Re: BUG #16154: pg_ctl restart with a logfile fails sometimes (on Windows)

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

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);
 }
 
 /*

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);