Subject: Re: BUG #16154: pg_ctl restart with a logfile fails sometimes (on
 Windows)
To: pgsql-bugs@lists.postgresql.org
References: <16154-1ccf0b537b24d5e0@postgresql.org>
From: Alexander Lakhin <exclusion@gmail.com>
Message-ID: <e5179494-715e-f8a3-266b-0cf52adac8f4@gmail.com>
Date: Fri, 6 Dec 2019 11:00:01 +0300
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:60.0) Gecko/20100101
 Thunderbird/60.7.2
MIME-Version: 1.0
In-Reply-To: <16154-1ccf0b537b24d5e0@postgresql.org>
Content-Type: multipart/mixed;
 boundary="------------C9227EE100DB1B730994A475"
Content-Language: en-US
Precedence: bulk

This is a multi-part message in MIME format.
--------------C9227EE100DB1B730994A475
Content-Type: multipart/alternative;
 boundary="------------E676E5EB66EA9606DD0ACF69"


--------------E676E5EB66EA9606DD0ACF69
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit

06.12.2019 10:00, PG Bug reporting form wrote:
> When performing regression tests on Windows intermittent failures are
> observed, e.g. in src/bin/pg_basebackup test:
> vcregress taptest src/bin/pg_basebackup
> ...
> t/010_pg_basebackup.pl ... 10/106 Bailout called.  Further testing stopped: 
> system pg_ctl failed
> FAILED--Further testing stopped: system pg_ctl failed
>
>
> waiting for server to start....The process cannot access the file because it
> is being used by another process.
>  stopped waiting
> pg_ctl: could not start server
>
> The issue is caused by sporadic "pg_ctl ... restart -l logfile" failures.

To reproduce this issue reliably I propose the simple demo patch
(delay_after_unlink_pid p, li { white-space: pre-wrap;).
With the delay added the "pg_ctl ... restart -l logfile" command (and
"vcregress taptest src/bin/pg_basebackup") fails always.
Error message is not very informational, but debugging shows that the
file in question is the log file, specified when running the command:
"C:\Windows\system32\cmd.exe" /C
""C:/src/postgresql/tmp_install/bin/postgres.exe" -D
"C:/src/postgresql/src/bin/pg_basebackup/tmp_check/t_010_pg_basebackup_main_data/pgdata"
--cluster-name=main < "nul" >>
"/C:/src/postgresql/src/bin/pg_basebackup/tmp_check/log/010_pg_basebackup_main.log/"
2>&1"

If this file is still opened by the previous server shell (it can happen
when the previous server instance has unlinked it's pid file, but it's
CMD shell is still running), the next CMD start fails with the
aforementioned error message.

To fix this issue I propose the attached patch
(fix_logfile_sharing_violation ).
With the patch, pg_ctl will wait for the log file to become available
(for 30 seconds). And if the file still could not be opened (it can be
reproduced with a larger delay in the demo patch), you'll get more
meaningful message:
/pg_ctl: could not access log file
"C:/src/postgresql/src/bin/pg_basebackup/tmp_check/log/010_pg_basebackup_main.log":
Permission denied/

Best regards,
Alexander

--------------E676E5EB66EA9606DD0ACF69
Content-Type: text/html; charset=utf-8
Content-Transfer-Encoding: 7bit

<html>
  <head>
    <meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
  </head>
  <body text="#000000" bgcolor="#FFFFFF">
    <div class="moz-cite-prefix">06.12.2019 10:00, PG Bug reporting form
      wrote:
    </div>
    <blockquote type="cite"
      cite="mid:%3C16154-1ccf0b537b24d5e0@postgresql.org%3E">
      <pre class="moz-quote-pre" wrap="">When performing regression tests on Windows intermittent failures are
observed, e.g. in src/bin/pg_basebackup test:
vcregress taptest src/bin/pg_basebackup
...
t/010_pg_basebackup.pl ... 10/106 Bailout called.  Further testing stopped: 
system pg_ctl failed
FAILED--Further testing stopped: system pg_ctl failed


waiting for server to start....The process cannot access the file because it
is being used by another process.
 stopped waiting
pg_ctl: could not start server

The issue is caused by sporadic "pg_ctl ... restart -l logfile" failures.
</pre>
    </blockquote>
    <br>
    To reproduce this issue reliably I propose the simple demo patch
    (delay_after_unlink_pid
    p, li { white-space: pre-wrap;).<br>
    With the delay added the "pg_ctl ... restart -l logfile" command
    (and "vcregress taptest src/bin/pg_basebackup") fails always.<br>
    Error message is not very informational, but debugging shows that
    the file in question is the log file, specified when running the
    command:<br>
    "C:\Windows\system32\cmd.exe" /C
    ""C:/src/postgresql/tmp_install/bin/postgres.exe" -D
"C:/src/postgresql/src/bin/pg_basebackup/tmp_check/t_010_pg_basebackup_main_data/pgdata"
    --cluster-name=main &lt; "nul" &gt;&gt; "<i>C:/src/postgresql/src/bin/pg_basebackup/tmp_check/log/010_pg_basebackup_main.log</i>"
    2&gt;&amp;1"<br>
    <br>
    If this file is still opened by the previous server shell (it can
    happen when the previous server instance has unlinked it's pid file,
    but it's CMD shell is still running), the next CMD start fails with
    the aforementioned error message.<br>
    <br>
    To fix this issue I propose the attached patch
    (fix_logfile_sharing_violation
    <style type="text/css">
p, li { white-space: pre-wrap; }</style>).<br>
    With the patch, pg_ctl will wait for the log file to become
    available (for 30 seconds). And if the file still could not be
    opened (it can be reproduced with a larger delay in the demo patch),
    you'll get more meaningful message:<br>
    <i>pg_ctl: could not access log file
"C:/src/postgresql/src/bin/pg_basebackup/tmp_check/log/010_pg_basebackup_main.log":
      Permission denied</i><br>
    <br>
    Best regards,<br>
    Alexander<br>
  </body>
</html>

--------------E676E5EB66EA9606DD0ACF69--

--------------C9227EE100DB1B730994A475
Content-Type: text/x-patch;
 name="delay_after_unlink_pid.patch"
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment;
 filename="delay_after_unlink_pid.patch"

diff --git a/src/backend/utils/init/miscinit.c b/src/backend/utils/init/miscinit.c
index 83c9514856..130d666f33 100644
--- a/src/backend/utils/init/miscinit.c
+++ b/src/backend/utils/init/miscinit.c
@@ -858,6 +858,7 @@ UnlinkLockFiles(int status, Datum arg)
 	 */
 	ereport(IsPostmasterEnvironment ? LOG : NOTICE,
 			(errmsg("database system is shut down")));
+	pg_usleep(1000000L);
 }
 
 /*

--------------C9227EE100DB1B730994A475
Content-Type: text/x-patch;
 name="fix_logfile_sharing_violation.patch"
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment;
 filename="fix_logfile_sharing_violation.patch"

diff --git a/src/bin/pg_ctl/pg_ctl.c b/src/bin/pg_ctl/pg_ctl.c
index 65f9fb4c0a..9bc44b2de4 100644
--- a/src/bin/pg_ctl/pg_ctl.c
+++ b/src/bin/pg_ctl/pg_ctl.c
@@ -519,8 +519,21 @@ start_postmaster(void)
 		comspec = "CMD";
 
 	if (log_file != NULL)
+	{
+		/* Check the log file availability to prevent CMD.EXE failing with
+		 * ERROR_SHARING_VIOLATION, e.g. when the log file is still opened
+		 * by the previous server shell.
+		 */
+		FILE *fd = fopen(log_file, "w+");
+		if (!fd) {
+			write_stderr(_("%s: could not access log file \"%s\": %s\n"),
+						 progname, log_file, strerror(errno));
+			exit(1);
+		}
+		fclose(fd);
 		snprintf(cmd, MAXPGPATH, "\"%s\" /C \"\"%s\" %s%s < \"%s\" >> \"%s\" 2>&1\"",
 				 comspec, exec_path, pgdata_opt, post_opts, DEVNULL, log_file);
+	}
 	else
 		snprintf(cmd, MAXPGPATH, "\"%s\" /C \"\"%s\" %s%s < \"%s\" 2>&1\"",
 				 comspec, exec_path, pgdata_opt, post_opts, DEVNULL);

--------------C9227EE100DB1B730994A475--