Received: from malur.postgresql.org ([2a02:16a8:dc51::56]) by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.89) (envelope-from ) id 1fWFMO-0000Wi-Fw for pgsql-hackers@arkaria.postgresql.org; Fri, 22 Jun 2018 06:15:53 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1fWFML-0007rk-Ps for pgsql-hackers@arkaria.postgresql.org; Fri, 22 Jun 2018 06:15:49 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.89) (envelope-from ) id 1fWFMK-0007rS-0R for pgsql-hackers@lists.postgresql.org; Fri, 22 Jun 2018 06:15:49 +0000 Received: from out2-smtp.messagingengine.com ([66.111.4.26]) by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.89) (envelope-from ) id 1fWFME-0006zq-5c for pgsql-hackers@postgresql.org; Fri, 22 Jun 2018 06:15:47 +0000 Received: from compute4.internal (compute4.nyi.internal [10.202.2.44]) by mailout.nyi.internal (Postfix) with ESMTP id 857C422246 for ; Fri, 22 Jun 2018 02:15:39 -0400 (EDT) Received: from mailfrontend2 ([10.202.2.163]) by compute4.internal (MEProxy); Fri, 22 Jun 2018 02:15:39 -0400 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=paquier.xyz; h= content-type:date:from:message-id:mime-version:subject:to :x-me-sender:x-me-sender:x-sasl-enc; s=fm2; bh=+X4bLrXjqid+uGK7p WvxnAuBYWJt7t8fT5ZbYrEMbko=; b=oBCb/yh0ZjoaohUW6w8PbJ/2PQDHCxZdz jtF9Sr+NeuaRiYurBIoe3+gCWv5QSSak3sZC48Rjyx3KNmgpOWIANA8nu5NROlyr f1CvUC3nQRFfCoHB4v16bbH+bkj1b3jPBh7O6K/0JGljtQUfC05HLNkALl0hWURF LmQbd4JVFTWIZ0yuu1iAdR7jePaFUjVtZa18/0uGHWnLyPlIyq7FRa+RZXup6F4o JlHJAy7+/Q4wU+JUE02rxSC47B6MrSXGUTynMGHI0AkJkr8nJsMyIiFjktMw6thK 7+YoXbFEYrTq86r/8A1a3yhTc6NQ8MclBulmBjaHAOp1BJ5lHF8Cg== DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d= messagingengine.com; h=content-type:date:from:message-id :mime-version:subject:to:x-me-sender:x-me-sender:x-sasl-enc; s= fm3; bh=+X4bLrXjqid+uGK7pWvxnAuBYWJt7t8fT5ZbYrEMbko=; b=c+yUObOc 7Zmp/IN4OFVHC1QGtAzbMi/AfLErR44lfRxXTkSO/BzWqjTZ/d9tIapvet0TEk1S aiIgxWRGqslm799KEks3iQm+6DfIPhz28ZgDGyLNtRZHpZo6dPhdksONCcnrpUBz o13AKM96Seww8010useKH+aj+KROOk9+69Zyglm9yYQ0Od5xNBty0Za+PbXvAshc lcihyA2wN5nc5bgyd8q4o8kl+djnDDf18nFKOXMUvm4Tq0IzTmJpvakS9NpgNtET WU7g8EfKid13P+6c1ajMzVi7I8NS1ufXiC4zN29qikkiKrCSt2fSA4xaMaJWRxwk dTbLYX4NMx226Q== X-ME-Proxy: X-ME-Sender: Received: from paquier.xyz (c137162.net61215.cablenet.ne.jp [61.215.137.162]) by mail.messagingengine.com (Postfix) with ESMTPA id 65B2010324 for ; Fri, 22 Jun 2018 02:15:38 -0400 (EDT) Date: Fri, 22 Jun 2018 15:15:35 +0900 From: Michael Paquier To: Postgres hackers Subject: Incorrect errno used with %m for backend code Message-ID: <20180622061535.GD5215@paquier.xyz> MIME-Version: 1.0 Content-Type: multipart/signed; micalg=pgp-sha512; protocol="application/pgp-signature"; boundary="KJY2Ze80yH5MUxol" Content-Disposition: inline List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk --KJY2Ze80yH5MUxol Content-Type: multipart/mixed; boundary="mR8QP4gmHujQHb1c" Content-Disposition: inline --mR8QP4gmHujQHb1c Content-Type: text/plain; charset=us-ascii Content-Disposition: inline Content-Transfer-Encoding: quoted-printable Hi all, I have been reviewing the use of errno in the backend code when %m is used in the logs, and found more places than when I looked at improving the error messages for read() calls which bloat the errno value because of intermediate system calls. As the problem is separate and should be back-patched, I have preferred beginning a new thread. A couple of places use CloseTransientFile without bothering much that this can overwrite errno. I was tempted in keeping errno saved and kept if set to a non-zero value, but refrained from doing so as some callers may rely on the existing behavior, and the attached shows better the intention.=20 Attached is a patch with everything I have spotted. Any opinions or thoughts in getting this back-patched? Thanks, -- Michael --mR8QP4gmHujQHb1c Content-Type: text/x-diff; charset=us-ascii Content-Disposition: attachment; filename="errno-m-logs-v1.patch" Content-Transfer-Encoding: quoted-printable diff --git a/src/backend/access/transam/twophase.c b/src/backend/access/tra= nsam/twophase.c index 65194db70e..e5571a67d6 100644 --- a/src/backend/access/transam/twophase.c +++ b/src/backend/access/transam/twophase.c @@ -1241,12 +1241,17 @@ ReadTwoPhaseFile(TransactionId xid, bool give_warni= ngs) */ if (fstat(fd, &stat)) { + int save_errno =3D errno; + CloseTransientFile(fd); if (give_warnings) + { + errno =3D save_errno; ereport(WARNING, (errcode_for_file_access(), errmsg("could not stat two-phase state file \"%s\": %m", path))); + } return NULL; } =20 @@ -1274,13 +1279,18 @@ ReadTwoPhaseFile(TransactionId xid, bool give_warni= ngs) pgstat_report_wait_start(WAIT_EVENT_TWOPHASE_FILE_READ); if (read(fd, buf, stat.st_size) !=3D stat.st_size) { + int save_errno =3D errno; + pgstat_report_wait_end(); CloseTransientFile(fd); if (give_warnings) + { + errno =3D save_errno; ereport(WARNING, (errcode_for_file_access(), errmsg("could not read two-phase state file \"%s\": %m", path))); + } pfree(buf); return NULL; } @@ -1663,16 +1673,22 @@ RecreateTwoPhaseFile(TransactionId xid, void *conte= nt, int len) pgstat_report_wait_start(WAIT_EVENT_TWOPHASE_FILE_WRITE); if (write(fd, content, len) !=3D len) { + int save_errno =3D errno; + pgstat_report_wait_end(); CloseTransientFile(fd); + errno =3D save_errno; ereport(ERROR, (errcode_for_file_access(), errmsg("could not write two-phase state file: %m"))); } if (write(fd, &statefile_crc, sizeof(pg_crc32c)) !=3D sizeof(pg_crc32c)) { + int save_errno =3D errno; + pgstat_report_wait_end(); CloseTransientFile(fd); + errno =3D save_errno; ereport(ERROR, (errcode_for_file_access(), errmsg("could not write two-phase state file: %m"))); @@ -1686,7 +1702,10 @@ RecreateTwoPhaseFile(TransactionId xid, void *conten= t, int len) pgstat_report_wait_start(WAIT_EVENT_TWOPHASE_FILE_SYNC); if (pg_fsync(fd) !=3D 0) { + int save_errno =3D errno; + CloseTransientFile(fd); + errno =3D save_errno; ereport(ERROR, (errcode_for_file_access(), errmsg("could not fsync two-phase state file: %m"))); diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam= /xlog.c index adbd6a2126..1a419aa49b 100644 --- a/src/backend/access/transam/xlog.c +++ b/src/backend/access/transam/xlog.c @@ -3268,7 +3268,10 @@ XLogFileInit(XLogSegNo logsegno, bool *use_existent,= bool use_lock) pgstat_report_wait_start(WAIT_EVENT_WAL_INIT_SYNC); if (pg_fsync(fd) !=3D 0) { + int save_errno =3D errno; + close(fd); + errno =3D save_errno; ereport(ERROR, (errcode_for_file_access(), errmsg("could not fsync file \"%s\": %m", tmppath))); @@ -11675,8 +11678,10 @@ retry: if (lseek(readFile, (off_t) readOff, SEEK_SET) < 0) { char fname[MAXFNAMELEN]; + int save_errno =3D errno; =20 XLogFileName(fname, curFileTLI, readSegNo, wal_segment_size); + errno =3D save_errno; ereport(emode_for_corrupt_record(emode, targetPagePtr + reqLen), (errcode_for_file_access(), errmsg("could not seek in log segment %s to offset %u: %m", @@ -11688,9 +11693,11 @@ retry: if (read(readFile, readBuf, XLOG_BLCKSZ) !=3D XLOG_BLCKSZ) { char fname[MAXFNAMELEN]; + int save_errno =3D errno; =20 pgstat_report_wait_end(); XLogFileName(fname, curFileTLI, readSegNo, wal_segment_size); + errno =3D save_errno; ereport(emode_for_corrupt_record(emode, targetPagePtr + reqLen), (errcode_for_file_access(), errmsg("could not read from log segment %s, offset %u: %m", diff --git a/src/backend/access/transam/xlogutils.c b/src/backend/access/tr= ansam/xlogutils.c index 52fe55e2af..4ecdc9220f 100644 --- a/src/backend/access/transam/xlogutils.c +++ b/src/backend/access/transam/xlogutils.c @@ -718,9 +718,10 @@ XLogRead(char *buf, int segsize, TimeLineID tli, XLogR= ecPtr startptr, if (lseek(sendFile, (off_t) startoff, SEEK_SET) < 0) { char path[MAXPGPATH]; + int save_errno =3D errno; =20 XLogFilePath(path, tli, sendSegNo, segsize); - + errno =3D save_errno; ereport(ERROR, (errcode_for_file_access(), errmsg("could not seek in log segment %s to offset %u: %m", @@ -741,9 +742,10 @@ XLogRead(char *buf, int segsize, TimeLineID tli, XLogR= ecPtr startptr, if (readbytes <=3D 0) { char path[MAXPGPATH]; + int save_errno =3D errno; =20 XLogFilePath(path, tli, sendSegNo, segsize); - + errno =3D save_errno; ereport(ERROR, (errcode_for_file_access(), errmsg("could not read from log segment %s, offset %u, length %lu: %= m", diff --git a/src/backend/replication/basebackup.c b/src/backend/replication= /basebackup.c index 5688cbe2e9..3f1eae38a9 100644 --- a/src/backend/replication/basebackup.c +++ b/src/backend/replication/basebackup.c @@ -495,6 +495,8 @@ perform_base_backup(basebackup_options *opt) fp =3D AllocateFile(pathbuf, "rb"); if (fp =3D=3D NULL) { + int save_errno =3D errno; + /* * Most likely reason for this is that the file was already * removed by a checkpoint, so check for that to get a better @@ -502,6 +504,7 @@ perform_base_backup(basebackup_options *opt) */ CheckXLogRemoved(segno, tli); =20 + errno =3D save_errno; ereport(ERROR, (errcode_for_file_access(), errmsg("could not open file \"%s\": %m", pathbuf))); diff --git a/src/backend/replication/logical/origin.c b/src/backend/replica= tion/logical/origin.c index 963878a5d8..ddcff3b643 100644 --- a/src/backend/replication/logical/origin.c +++ b/src/backend/replication/logical/origin.c @@ -578,7 +578,10 @@ CheckPointReplicationOrigin(void) /* write magic */ if ((write(tmpfd, &magic, sizeof(magic))) !=3D sizeof(magic)) { + int save_errno =3D errno; + CloseTransientFile(tmpfd); + errno =3D save_errno; ereport(PANIC, (errcode_for_file_access(), errmsg("could not write to file \"%s\": %m", @@ -617,7 +620,10 @@ CheckPointReplicationOrigin(void) if ((write(tmpfd, &disk_state, sizeof(disk_state))) !=3D sizeof(disk_state)) { + int save_errno =3D errno; + CloseTransientFile(tmpfd); + errno =3D save_errno; ereport(PANIC, (errcode_for_file_access(), errmsg("could not write to file \"%s\": %m", @@ -633,7 +639,10 @@ CheckPointReplicationOrigin(void) FIN_CRC32C(crc); if ((write(tmpfd, &crc, sizeof(crc))) !=3D sizeof(crc)) { + int save_errno =3D errno; + CloseTransientFile(tmpfd); + errno =3D save_errno; ereport(PANIC, (errcode_for_file_access(), errmsg("could not write to file \"%s\": %m", diff --git a/src/backend/replication/logical/snapbuild.c b/src/backend/repl= ication/logical/snapbuild.c index 4123cdebcf..b0f82391b4 100644 --- a/src/backend/replication/logical/snapbuild.c +++ b/src/backend/replication/logical/snapbuild.c @@ -1605,7 +1605,10 @@ SnapBuildSerialize(SnapBuild *builder, XLogRecPtr ls= n) pgstat_report_wait_start(WAIT_EVENT_SNAPBUILD_WRITE); if ((write(fd, ondisk, needed_length)) !=3D needed_length) { + int save_errno =3D errno; + CloseTransientFile(fd); + errno =3D save_errno; ereport(ERROR, (errcode_for_file_access(), errmsg("could not write to file \"%s\": %m", tmppath))); @@ -1623,7 +1626,10 @@ SnapBuildSerialize(SnapBuild *builder, XLogRecPtr ls= n) pgstat_report_wait_start(WAIT_EVENT_SNAPBUILD_SYNC); if (pg_fsync(fd) !=3D 0) { + int save_errno =3D errno; + CloseTransientFile(fd); + errno =3D save_errno; ereport(ERROR, (errcode_for_file_access(), errmsg("could not fsync file \"%s\": %m", tmppath))); @@ -1708,7 +1714,10 @@ SnapBuildRestore(SnapBuild *builder, XLogRecPtr lsn) pgstat_report_wait_end(); if (readBytes !=3D SnapBuildOnDiskConstantSize) { + int save_errno =3D errno; + CloseTransientFile(fd); + errno =3D save_errno; ereport(ERROR, (errcode_for_file_access(), errmsg("could not read file \"%s\", read %d of %d: %m", @@ -1736,7 +1745,10 @@ SnapBuildRestore(SnapBuild *builder, XLogRecPtr lsn) pgstat_report_wait_end(); if (readBytes !=3D sizeof(SnapBuild)) { + int save_errno =3D errno; + CloseTransientFile(fd); + errno =3D save_errno; ereport(ERROR, (errcode_for_file_access(), errmsg("could not read file \"%s\", read %d of %d: %m", @@ -1753,7 +1765,10 @@ SnapBuildRestore(SnapBuild *builder, XLogRecPtr lsn) pgstat_report_wait_end(); if (readBytes !=3D sz) { + int save_errno =3D errno; + CloseTransientFile(fd); + errno =3D save_errno; ereport(ERROR, (errcode_for_file_access(), errmsg("could not read file \"%s\", read %d of %d: %m", @@ -1769,7 +1784,10 @@ SnapBuildRestore(SnapBuild *builder, XLogRecPtr lsn) pgstat_report_wait_end(); if (readBytes !=3D sz) { + int save_errno =3D errno; + CloseTransientFile(fd); + errno =3D save_errno; ereport(ERROR, (errcode_for_file_access(), errmsg("could not read file \"%s\", read %d of %d: %m", diff --git a/src/backend/replication/slot.c b/src/backend/replication/slot.c index e8b76b2f20..5b7116838f 100644 --- a/src/backend/replication/slot.c +++ b/src/backend/replication/slot.c @@ -1378,7 +1378,10 @@ RestoreSlotFromDisk(const char *name) pgstat_report_wait_start(WAIT_EVENT_REPLICATION_SLOT_RESTORE_SYNC); if (pg_fsync(fd) !=3D 0) { + int save_errno =3D errno; + CloseTransientFile(fd); + errno =3D save_errno; ereport(PANIC, (errcode_for_file_access(), errmsg("could not fsync file \"%s\": %m", --mR8QP4gmHujQHb1c-- --KJY2Ze80yH5MUxol Content-Type: application/pgp-signature; name="signature.asc" -----BEGIN PGP SIGNATURE----- iQIzBAABCgAdFiEEG72nH6vTowiyblFKnvQgOdbyQH0FAlsslAcACgkQnvQgOdby QH1nHg//de6xeO+9s2oq695V4hejIpnA8vshWlHb3ptFA1tXM8Y8N6GGqzqKl8Zp e1W8vx4XvkWsBVgKuVCF+0CZXl/qtNLPvj2DIF7aAhbr+XIh17olmLF7ZEiDdI9l GciJ3aPouf9ptP6k6IoyWQjHnpOf/eY6x/EsERSZuGNhn8YSnyYj40YjHNrv1Ume /Lph4+gik//pFl8ikbVwNryI/OzOK7ZrRRUtBsLN2g06GsBFdm3ZBJ0e6ijABLGi 361WgH/Jqhh5qUNBzVFdhGBNoRl3LmMHAoMN8IQH65U0oLlVN6h/wpY8ngqbvfFD MecoB7ZZNy0sWTkA9+qoNE45DSP6i21uJRezrsBrQrYTE1vDbuc1pde84g5nBuIE 5XbKubn3qX7L7qlE9omv2LzFWyV4QEAWVwTk4f5QjDSATXf6CmN/zfjO4P3GCDvz e1dJEWcaKoUpVRb4vZMTTKdqrixoVFGw+6aZkp+Tny9ub2KchaegUAm33ovukOrx X3yYADK2aOj3Be9GTx0jPqYc9vKxcw7fT2u8+V7vrD61rjeVO+1vBjIYHf9U8Di4 ykOVo7tfeKJ1LOBVqvaljIFZYdL5G8Lw5FXTc1XACFSLxeIsjzxp8UfEVJFQh5ur fwRwcHojZJJzxdcKtpALXx45wIELe5i4OWkaYV5MegTjac4a4SI= =yPBI -----END PGP SIGNATURE----- --KJY2Ze80yH5MUxol--