fix "Success" error messages
In a case of a corrupted database, I saw an error message like
Could not read from file ...: Success.
from the SLRU module. This is because it checks that it reads or writes
exactly BLCKSZ, and else goes to the error path. The attached patch
gives a different error message in this case.
Because of the structure of this code, we don't have the information to
do the usual "read %d of %zu", but at least this is better than
reporting a "success" error.
--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Attachments:
0001-Better-error-messages-for-short-reads-writes-in-SLRU.patchtext/plain; charset=UTF-8; name=0001-Better-error-messages-for-short-reads-writes-in-SLRU.patch; x-mac-creator=0; x-mac-type=0Download
From 680651938e30b5208a73b9d76813a5880af4ab54 Mon Sep 17 00:00:00 2001
From: Peter Eisentraut <peter@eisentraut.org>
Date: Tue, 18 Jun 2019 14:27:53 +0200
Subject: [PATCH 1/2] Better error messages for short reads/writes in SLRU
This avoids getting a
Could not read from file ...: Success.
for a short read or write (since errno is not set in that case).
Instead, report a more specific error messages.
---
src/backend/access/transam/slru.c | 12 ++++++++----
1 file changed, 8 insertions(+), 4 deletions(-)
diff --git a/src/backend/access/transam/slru.c b/src/backend/access/transam/slru.c
index 2dbc65b125..315c0612e6 100644
--- a/src/backend/access/transam/slru.c
+++ b/src/backend/access/transam/slru.c
@@ -923,15 +923,19 @@ SlruReportIOError(SlruCtl ctl, int pageno, TransactionId xid)
ereport(ERROR,
(errcode_for_file_access(),
errmsg("could not access status of transaction %u", xid),
- errdetail("Could not read from file \"%s\" at offset %u: %m.",
- path, offset)));
+ errno == 0
+ ? errdetail("Short read from file \"%s\" at offset %u.", path, offset)
+ : errdetail("Could not read from file \"%s\" at offset %u: %m.",
+ path, offset)));
break;
case SLRU_WRITE_FAILED:
ereport(ERROR,
(errcode_for_file_access(),
errmsg("could not access status of transaction %u", xid),
- errdetail("Could not write to file \"%s\" at offset %u: %m.",
- path, offset)));
+ errno == 0
+ ? errdetail("Short write to file \"%s\" at offset %u.", path, offset)
+ : errdetail("Could not write to file \"%s\" at offset %u: %m.",
+ path, offset)));
break;
case SLRU_FSYNC_FAILED:
ereport(data_sync_elevel(ERROR),
--
2.22.0
0002-Use-consistent-style-for-checking-return-from-system.patchtext/plain; charset=UTF-8; name=0002-Use-consistent-style-for-checking-return-from-system.patch; x-mac-creator=0; x-mac-type=0Download
From 9d6d381993701fc696466e822d58289c480c358f Mon Sep 17 00:00:00 2001
From: Peter Eisentraut <peter@eisentraut.org>
Date: Tue, 18 Jun 2019 14:29:31 +0200
Subject: [PATCH 2/2] Use consistent style for checking return from system
calls
Use
if (something() < 0)
error ...
instead of just
if (something)
error ...
The latter is not incorrect, but it's a bit confusing and not the
common style.
---
src/backend/access/transam/slru.c | 10 +++++-----
1 file changed, 5 insertions(+), 5 deletions(-)
diff --git a/src/backend/access/transam/slru.c b/src/backend/access/transam/slru.c
index 315c0612e6..dab5b6ffa0 100644
--- a/src/backend/access/transam/slru.c
+++ b/src/backend/access/transam/slru.c
@@ -697,7 +697,7 @@ SlruPhysicalReadPage(SlruCtl ctl, int pageno, int slotno)
}
pgstat_report_wait_end();
- if (CloseTransientFile(fd))
+ if (CloseTransientFile(fd) < 0)
{
slru_errcause = SLRU_CLOSE_FAILED;
slru_errno = errno;
@@ -869,7 +869,7 @@ SlruPhysicalWritePage(SlruCtl ctl, int pageno, int slotno, SlruFlush fdata)
if (!fdata)
{
pgstat_report_wait_start(WAIT_EVENT_SLRU_SYNC);
- if (ctl->do_fsync && pg_fsync(fd))
+ if (ctl->do_fsync && pg_fsync(fd) < 0)
{
pgstat_report_wait_end();
slru_errcause = SLRU_FSYNC_FAILED;
@@ -879,7 +879,7 @@ SlruPhysicalWritePage(SlruCtl ctl, int pageno, int slotno, SlruFlush fdata)
}
pgstat_report_wait_end();
- if (CloseTransientFile(fd))
+ if (CloseTransientFile(fd) < 0)
{
slru_errcause = SLRU_CLOSE_FAILED;
slru_errno = errno;
@@ -1150,7 +1150,7 @@ SimpleLruFlush(SlruCtl ctl, bool allow_redirtied)
for (i = 0; i < fdata.num_files; i++)
{
pgstat_report_wait_start(WAIT_EVENT_SLRU_FLUSH_SYNC);
- if (ctl->do_fsync && pg_fsync(fdata.fd[i]))
+ if (ctl->do_fsync && pg_fsync(fdata.fd[i]) < 0)
{
slru_errcause = SLRU_FSYNC_FAILED;
slru_errno = errno;
@@ -1159,7 +1159,7 @@ SimpleLruFlush(SlruCtl ctl, bool allow_redirtied)
}
pgstat_report_wait_end();
- if (CloseTransientFile(fdata.fd[i]))
+ if (CloseTransientFile(fdata.fd[i]) < 0)
{
slru_errcause = SLRU_CLOSE_FAILED;
slru_errno = errno;
--
2.22.0
On Tue, Jun 18, 2019 at 02:35:02PM +0200, Peter Eisentraut wrote:
--- a/src/backend/access/transam/slru.c +++ b/src/backend/access/transam/slru.c @@ -923,15 +923,19 @@ SlruReportIOError(SlruCtl ctl, int pageno, TransactionId xid) ereport(ERROR, (errcode_for_file_access(), errmsg("could not access status of transaction %u", xid), - errdetail("Could not read from file \"%s\" at offset %u: %m.", - path, offset))); + errno == 0 + ? errdetail("Short read from file \"%s\" at offset %u.", path, offset) + : errdetail("Could not read from file \"%s\" at offset %u: %m.", + path, offset)));
Perhaps using "Encountered partial read from file ..." would be better
suited for the error message.
break; case SLRU_WRITE_FAILED: ereport(ERROR, (errcode_for_file_access(), errmsg("could not access status of transaction %u", xid), - errdetail("Could not write to file \"%s\" at offset %u: %m.", - path, offset))); + errno == 0 + ? errdetail("Short write to file \"%s\" at offset %u.", path, offset) + : errdetail("Could not write to file \"%s\" at offset %u: %m.", + path, offset)));
Similarly, "Encountered partial write to file ..." would be better? Not
a 100% on using "Encountered" but "partial" seems to be the right word
to use here.
Do note that SlruPhysicalWritePage() will always set errno to ENOSPC if
errno was 0 during a write attempt, see [0]https://github.com/postgres/postgres/blob/master/src/backend/access/transam/slru.c#L854. Not sure this is a good
assumption to make since write(2) should return ENOSPC if the storage
medium is out of space [1]https://linux.die.net/man/2/write.
[0]: https://github.com/postgres/postgres/blob/master/src/backend/access/transam/slru.c#L854
https://github.com/postgres/postgres/blob/master/src/backend/access/transam/slru.c#L854
[1]: https://linux.die.net/man/2/write
--
Shawn Debnath
Amazon Web Services (AWS)
On Tue, Jun 18, 2019 at 09:13:19AM -0700, Shawn Debnath wrote:
case SLRU_WRITE_FAILED: ereport(ERROR, (errcode_for_file_access(), errmsg("could not access status of transaction %u", xid), - errdetail("Could not write to file \"%s\" at offset %u: %m.", - path, offset))); + errno == 0 + ? errdetail("Short write to file \"%s\" at offset %u.", path, offset) + : errdetail("Could not write to file \"%s\" at offset %u: %m.", + path, offset)));
There is no point to call errcode_for_file_access() if we know that
errno is 0. Not a big deal, still.. The last time I looked at that,
the best way I could think of would be to replace slru_errcause with a
proper error string generated at error time. Perhaps the partial
read/write case does not justify this extra facility. I don't know.
At least that would be more flexible.
Similarly, "Encountered partial write to file ..." would be better? Not
a 100% on using "Encountered" but "partial" seems to be the right word
to use here.
811b6e36 has done some work so as we have more consistency in the
error messages and I don't think we should introduce more flavors of
this stuff as that makes the life of translators harder.
- if (CloseTransientFile(fd))
+ if (CloseTransientFile(fd) < 0)
Some spots are missing:
$ git grep "CloseTransientFile" | grep "))" | wc -l
30
--
Michael
On 2019-06-19 04:51, Michael Paquier wrote:
On Tue, Jun 18, 2019 at 09:13:19AM -0700, Shawn Debnath wrote:
case SLRU_WRITE_FAILED: ereport(ERROR, (errcode_for_file_access(), errmsg("could not access status of transaction %u", xid), - errdetail("Could not write to file \"%s\" at offset %u: %m.", - path, offset))); + errno == 0 + ? errdetail("Short write to file \"%s\" at offset %u.", path, offset) + : errdetail("Could not write to file \"%s\" at offset %u: %m.", + path, offset)));There is no point to call errcode_for_file_access() if we know that
errno is 0. Not a big deal, still.. The last time I looked at that,
the best way I could think of would be to replace slru_errcause with a
proper error string generated at error time. Perhaps the partial
read/write case does not justify this extra facility. I don't know.
At least that would be more flexible.
Here is an updated patch set that rearranges this a bit according to
your suggestions, and also fixes some similar issues in pg_checksums.
--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Attachments:
v2-0001-Better-error-messages-for-short-reads-writes-in-S.patchtext/plain; charset=UTF-8; name=v2-0001-Better-error-messages-for-short-reads-writes-in-S.patch; x-mac-creator=0; x-mac-type=0Download
From d1d306f80c53a59b67823ae044bf85a2718ea94e Mon Sep 17 00:00:00 2001
From: Peter Eisentraut <peter@eisentraut.org>
Date: Mon, 26 Aug 2019 21:37:10 +0200
Subject: [PATCH v2 1/2] Better error messages for short reads/writes in SLRU
This avoids getting a
Could not read from file ...: Success.
for a short read or write (since errno is not set in that case).
Instead, report a more specific error messages.
---
src/backend/access/transam/slru.c | 31 +++++++++++++++++++++----------
1 file changed, 21 insertions(+), 10 deletions(-)
diff --git a/src/backend/access/transam/slru.c b/src/backend/access/transam/slru.c
index 0fbcb4e6fe..e38f9199dd 100644
--- a/src/backend/access/transam/slru.c
+++ b/src/backend/access/transam/slru.c
@@ -920,18 +920,29 @@ SlruReportIOError(SlruCtl ctl, int pageno, TransactionId xid)
path, offset)));
break;
case SLRU_READ_FAILED:
- ereport(ERROR,
- (errcode_for_file_access(),
- errmsg("could not access status of transaction %u", xid),
- errdetail("Could not read from file \"%s\" at offset %u: %m.",
- path, offset)));
+ if (errno)
+ ereport(ERROR,
+ (errcode_for_file_access(),
+ errmsg("could not access status of transaction %u", xid),
+ errdetail("Could not read from file \"%s\" at offset %u: %m.",
+ path, offset)));
+ else
+ ereport(ERROR,
+ (errmsg("could not access status of transaction %u", xid),
+ errdetail("Could not read from file \"%s\" at offset %u: read too few bytes.", path, offset)));
break;
case SLRU_WRITE_FAILED:
- ereport(ERROR,
- (errcode_for_file_access(),
- errmsg("could not access status of transaction %u", xid),
- errdetail("Could not write to file \"%s\" at offset %u: %m.",
- path, offset)));
+ if (errno)
+ ereport(ERROR,
+ (errcode_for_file_access(),
+ errmsg("could not access status of transaction %u", xid),
+ errdetail("Could not write to file \"%s\" at offset %u: %m.",
+ path, offset)));
+ else
+ ereport(ERROR,
+ (errmsg("could not access status of transaction %u", xid),
+ errdetail("Could not write to file \"%s\" at offset %u: wrote too few bytes.",
+ path, offset)));
break;
case SLRU_FSYNC_FAILED:
ereport(data_sync_elevel(ERROR),
base-commit: acb96eb7d294a003a9392cdd445630ef137d9918
--
2.22.0
v2-0002-pg_checksums-Handle-read-and-write-returns-correc.patchtext/plain; charset=UTF-8; name=v2-0002-pg_checksums-Handle-read-and-write-returns-correc.patch; x-mac-creator=0; x-mac-type=0Download
From 89fe3678ef9443fc56a8ebfc3657ad06f5585bf5 Mon Sep 17 00:00:00 2001
From: Peter Eisentraut <peter@eisentraut.org>
Date: Mon, 26 Aug 2019 21:37:50 +0200
Subject: [PATCH v2 2/2] pg_checksums: Handle read and write returns correctly
The read() return was not checking for errors, the write() return was
not checking for short writes.
---
src/bin/pg_checksums/pg_checksums.c | 21 +++++++++++++++++----
1 file changed, 17 insertions(+), 4 deletions(-)
diff --git a/src/bin/pg_checksums/pg_checksums.c b/src/bin/pg_checksums/pg_checksums.c
index 8c00ec9a3b..40619be0fa 100644
--- a/src/bin/pg_checksums/pg_checksums.c
+++ b/src/bin/pg_checksums/pg_checksums.c
@@ -196,7 +196,13 @@ scan_file(const char *fn, BlockNumber segmentno)
if (r == 0)
break;
- if (r != BLCKSZ)
+ else if (r < 0)
+ {
+ pg_log_error("could not read block %u in file \"%s\": %m",
+ blockno, fn);
+ exit(1);
+ }
+ else if (r != BLCKSZ)
{
pg_log_error("could not read block %u in file \"%s\": read %d of %d",
blockno, fn, r, BLCKSZ);
@@ -222,6 +228,8 @@ scan_file(const char *fn, BlockNumber segmentno)
}
else if (mode == PG_MODE_ENABLE)
{
+ int w;
+
/* Set checksum in page header */
header->pd_checksum = csum;
@@ -233,10 +241,15 @@ scan_file(const char *fn, BlockNumber segmentno)
}
/* Write block with checksum */
- if (write(f, buf.data, BLCKSZ) != BLCKSZ)
+ w = write(f, buf.data, BLCKSZ);
+ if (w != BLCKSZ)
{
- pg_log_error("could not write block %u in file \"%s\": %m",
- blockno, fn);
+ if (w < 0)
+ pg_log_error("could not write block %u in file \"%s\": %m",
+ blockno, fn);
+ else
+ pg_log_error("could not write block %u in file \"%s\": wrote %d of %d",
+ blockno, fn, w, BLCKSZ);
exit(1);
}
}
--
2.22.0
On Mon, Aug 26, 2019 at 09:40:23PM +0200, Peter Eisentraut wrote:
Here is an updated patch set that rearranges this a bit according to
your suggestions, and also fixes some similar issues in pg_checksums.
Thanks for the new patch, and you are right that pg_checksums has been
slacking here. There is the same issue with pg_verify_checksums in
11. Not sure that's worth a back-patch though. Those parts could
find their way to v12 easily.
- ereport(ERROR, - (errcode_for_file_access(), - errmsg("could not access status of transaction %u", xid), - errdetail("Could not read from file \"%s\" at offset %u: %m.", - path, offset))); + if (errno) + ereport(ERROR, + (errcode_for_file_access(), + errmsg("could not access status of transaction %u", xid), + errdetail("Could not read from file \"%s\" at offset %u: %m.", + path, offset))); + else + ereport(ERROR, + (errmsg("could not access status of transaction %u", xid), + errdetail("Could not read from file \"%s\" at offset %u: read too few bytes.", path, offset)));
Last time I worked on that, the following suggestion was made for
error messages with shorter reads or writes:
could not read file \"%s\": read %d of %zu
Still this is clearly an improvement and I that's not worth the extra
complication, so +1 for this way of doing things.
if (r == 0) break; - if (r != BLCKSZ) + else if (r < 0) + { + pg_log_error("could not read block %u in file \"%s\": %m", + blockno, fn); + exit(1); + } + else if (r != BLCKSZ) { pg_log_error("could not read block %u in file \"%s\": read %d of %d", blockno, fn, r, BLCKSZ);
Other code areas (xlog.c, pg_waldump.c, etc.) prefer doing it this
way, after checking the size read:
if (r != BLCKSZ)
{
if (r < 0)
pg_log_error("could not read blah: %m");
else
pg_log_error("could not read blah: read %d of %d")
}
/* Write block with checksum */ - if (write(f, buf.data, BLCKSZ) != BLCKSZ) + w = write(f, buf.data, BLCKSZ); + if (w != BLCKSZ) { - pg_log_error("could not write block %u in file \"%s\": %m", - blockno, fn); + if (w < 0) + pg_log_error("could not write block %u in file \"%s\": %m", + blockno, fn); + else + pg_log_error("could not write block %u in file \"%s\": wrote %d of %d", + blockno, fn, w, BLCKSZ); exit(1); } }
This is consistent.
--
Michael
On 2019-08-27 08:27, Michael Paquier wrote:
Thanks for the new patch, and you are right that pg_checksums has been
slacking here. There is the same issue with pg_verify_checksums in
11. Not sure that's worth a back-patch though. Those parts could
find their way to v12 easily.
Committed to master and PG12 with your suggested changes.
--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On Tue, Sep 3, 2019 at 08:38:22AM +0200, Peter Eisentraut wrote:
On 2019-08-27 08:27, Michael Paquier wrote:
Thanks for the new patch, and you are right that pg_checksums has been
slacking here. There is the same issue with pg_verify_checksums in
11. Not sure that's worth a back-patch though. Those parts could
find their way to v12 easily.Committed to master and PG12 with your suggested changes.
This "Success" has happened so many times I think we should tell people
to report any such error message as a bug by emitting a special error
message line.
--
Bruce Momjian <bruce@momjian.us> http://momjian.us
EnterpriseDB http://enterprisedb.com
+ As you are, so once was I. As I am, so you will be. +
+ Ancient Roman grave inscription +
Hello, pgsql-hackers
I'm gathering information about the following error.
FATAL: could not access status of transaction ..
DETAIL: Could not read from file (pg_clog/.... or pg_xact/....) ...: Success.
This error has caused the server to fail to start with recovery.
I got a report that it happend repeatedly at the newly generated
standby cluster. I gave them advice to comfirm the low level server
environment.
However, in addition to improving the message, should we retry to read
the rest of the data in the case reading too few bytes?
What about a limited number of retries instead of a complete loop?
---
Haruka Takatsuka / SRA OSS, Inc. Japan
On Fri, 27 Sep 2019 11:52:39 -0400
Bruce Momjian <bruce@momjian.us> wrote:
Show quoted text
On Tue, Sep 3, 2019 at 08:38:22AM +0200, Peter Eisentraut wrote:
On 2019-08-27 08:27, Michael Paquier wrote:
Thanks for the new patch, and you are right that pg_checksums has been
slacking here. There is the same issue with pg_verify_checksums in
11. Not sure that's worth a back-patch though. Those parts could
find their way to v12 easily.Committed to master and PG12 with your suggested changes.
This "Success" has happened so many times I think we should tell people
to report any such error message as a bug by emitting a special error
message line.--
Bruce Momjian <bruce@momjian.us> http://momjian.us
EnterpriseDB http://enterprisedb.com+ As you are, so once was I. As I am, so you will be. + + Ancient Roman grave inscription +
On 2019-11-21 02:42, TAKATSUKA Haruka wrote:
FATAL: could not access status of transaction ..
DETAIL: Could not read from file (pg_clog/.... or pg_xact/....) ...: Success.This error has caused the server to fail to start with recovery.
I got a report that it happend repeatedly at the newly generated
standby cluster. I gave them advice to comfirm the low level server
environment.However, in addition to improving the message, should we retry to read
the rest of the data in the case reading too few bytes?
What about a limited number of retries instead of a complete loop?
If we thought that would help, there are probably hundreds or more other
places where we read files that would need to be fixed up in the same
way. That doesn't seem reasonable.
Also, it is my understanding that short reads can in practice only
happen if the underlying storage is having a serious problem, so
retrying wouldn't actually help much.
--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On Thu, 21 Nov 2019 10:40:36 +0100
Peter Eisentraut <peter.eisentraut@2ndquadrant.com> wrote:
On 2019-11-21 02:42, TAKATSUKA Haruka wrote:
FATAL: could not access status of transaction ..
DETAIL: Could not read from file (pg_clog/.... or pg_xact/....) ...: Success.This error has caused the server to fail to start with recovery.
I got a report that it happend repeatedly at the newly generated
standby cluster. I gave them advice to comfirm the low level server
environment.However, in addition to improving the message, should we retry to read
the rest of the data in the case reading too few bytes?
What about a limited number of retries instead of a complete loop?If we thought that would help, there are probably hundreds or more other
places where we read files that would need to be fixed up in the same
way. That doesn't seem reasonable.Also, it is my understanding that short reads can in practice only
happen if the underlying storage is having a serious problem, so
retrying wouldn't actually help much.
OK, I understand.
In our case, the standby DB cluster space is on DRBD.
I will report the clear occurrence condition if it is found.
thanks,
Haruka Takatsuka