Обсуждение: BUG #15804: Assertion failure when using logging_collector with EXEC_BACKEND

The following bug has been logged on the website:

Bug reference:      15804
Logged by:          Yulian Khodorkovskiy
Email address:      yuli.khodorkovskiy@crunchydata.com
PostgreSQL version: Unsupported/Unknown
Operating system:   Centos 7.4
Description:

The following assertion fails when compiling postgres 12 on Linux (centos
7.4) with EXEC_BACKEND and logging_collector enabled:

    `Assert(UsedShmemSegAddr != NULL);` in `PGSharedMemoryNoReAttach()`

Commit 57431a911d3a650451d198846ad3194900666152 appears to have introduced
this regression by moving SysLogger_Start() before reset_shared() is called
and shared memory is initialized.

For what it's worth, Windows 10/jacana (and maybe other windows builds) on
the build farm does not use logging_collector, which is perhaps why this
regression was not caught.

Yuli

> On May 14, 2019, at 2:28 PM, PG Bug reporting form <noreply@postgresql.org> wrote:
>
> The following bug has been logged on the website:
>
> Bug reference:      15804
> Logged by:          Yulian Khodorkovskiy
> Email address:      yuli.khodorkovskiy@crunchydata.com
> PostgreSQL version: Unsupported/Unknown
> Operating system:   Centos 7.4
> Description:
>
> The following assertion fails when compiling postgres 12 on Linux (centos
> 7.4) with EXEC_BACKEND and logging_collector enabled:
>
>    `Assert(UsedShmemSegAddr != NULL);` in `PGSharedMemoryNoReAttach()`
>
> Commit 57431a911d3a650451d198846ad3194900666152 appears to have introduced
> this regression by moving SysLogger_Start() before reset_shared() is called
> and shared memory is initialized.
>
> For what it's worth, Windows 10/jacana (and maybe other windows builds) on
> the build farm does not use logging_collector, which is perhaps why this
> regression was not caught.
>
> Yuli
>

Attached is a patch that fixes the issue in the bug report.

Yuli Khodorkovskiy <yuli.khodorkovskiy@crunchydata.com> writes:
> Attached is a patch that fixes the issue in the bug report.

I do not think this is a very good way to fix it (even assuming
that it works, which I'm unsure of --- in particular, doing this
would alter the order of changes to postmaster.pid, possibly
breaking pg_ctl or other tools that look at that file).  The whole
point of commit 57431a911 was to switch to log-collector logging
before we've done anything very interesting, and that would surely
include shmem setup.  I'm a bit surprised actually that Peter
didn't move the SysLogger_Start call even further up; in principle
it ought to be safe to do it as soon as we have the data directory
lock file.

It might be better to give up the assertion in PGSharedMemoryNoReAttach,
and just make it work more like PGSharedMemoryDetach, ie "detach if
UsedShmemSegAddr is set, else do nothing".  I don't remember for sure,
but if we do that, there might be no functional difference anymore
between those two functions, in which case we might as well merge 'em.

            regards, tom lane

I wrote:
> It might be better to give up the assertion in PGSharedMemoryNoReAttach,
> and just make it work more like PGSharedMemoryDetach, ie "detach if
> UsedShmemSegAddr is set, else do nothing".  I don't remember for sure,
> but if we do that, there might be no functional difference anymore
> between those two functions, in which case we might as well merge 'em.

Apropos of this: I notice that commit 57431a911 is already relying
on PGSharedMemoryDetach to do the "right thing" here, because that
gets called in the non-EXEC_BACKEND code path, cf SysLogger_Start:

            /* Drop our connection to postmaster's shared memory, as well */
            dsm_detach_all();
            PGSharedMemoryDetach();

I'm also not too happy that this comment doesn't mention the fact that
we'd (now) only be attached to shmem in the case of a postmaster restart.

BTW, it looks to me like dsm_detach_all doesn't get called anywhere in
the EXEC_BACKEND case, which seems like a separate bug.

            regards, tom lane

On Tue, May 14, 2019 at 03:52:04PM -0400, Tom Lane wrote:
> It might be better to give up the assertion in PGSharedMemoryNoReAttach,
> and just make it work more like PGSharedMemoryDetach, ie "detach if
> UsedShmemSegAddr is set, else do nothing".  I don't remember for sure,
> but if we do that, there might be no functional difference anymore
> between those two functions, in which case we might as well merge 'em.

It would be nice to fix that before beta1 is out, or we are going to
get complaints :(

So what about dropping PGSharedMemoryNoReAttach() completely and using
(or abusing of?) the detach routine so as we rely on its no-op
behavior when a subprocess is not attached yet to a shared memory
segment.  On Windows, the sub-processes calling NoReAttach don't map
to a segment per the comments in the code, and I can indeed see some
"could not map" LOG messages coming from these in the logs if
enforcing the use of the detach routine in postmaster.c.  It could
actually be an advantage to unmap using UnmapViewOfFile() so as a
subsequent call of ReAttach does not finish by mapping an extra time.
We may consider lowering the LOG messages to DEBUG1, or extend the
detach routine so as we control the level of logs with an elevel to
avoid sparse LOG messages when unmapping from shared segments where we
know it would fail.

I have been playing with the attached using EXEC_BACKEND on Linux and
some Windows builds FWIW.  Thoughts?
--
Michael

Michael Paquier <michael@paquier.xyz> writes:
> On Tue, May 14, 2019 at 03:52:04PM -0400, Tom Lane wrote:
>> It might be better to give up the assertion in PGSharedMemoryNoReAttach,
>> and just make it work more like PGSharedMemoryDetach, ie "detach if
>> UsedShmemSegAddr is set, else do nothing".  I don't remember for sure,
>> but if we do that, there might be no functional difference anymore
>> between those two functions, in which case we might as well merge 'em.

> It would be nice to fix that before beta1 is out, or we are going to
> get complaints :(

Agreed, that's why I put it on the open items list ;-)

> So what about dropping PGSharedMemoryNoReAttach() completely and using
> (or abusing of?) the detach routine so as we rely on its no-op
> behavior when a subprocess is not attached yet to a shared memory
> segment.  On Windows, the sub-processes calling NoReAttach don't map
> to a segment per the comments in the code, and I can indeed see some
> "could not map" LOG messages coming from these in the logs if
> enforcing the use of the detach routine in postmaster.c.  It could
> actually be an advantage to unmap using UnmapViewOfFile() so as a
> subsequent call of ReAttach does not finish by mapping an extra time.
> We may consider lowering the LOG messages to DEBUG1, or extend the
> detach routine so as we control the level of logs with an elevel to
> avoid sparse LOG messages when unmapping from shared segments where we
> know it would fail.

Hm.  I don't much like ignoring errors, which is what that would
amount to.  It seems like in win32_shmem.c, PGSharedMemoryNoReAttach
is already more or less right: resetting UsedShmemSegAddr to NULL and
then calling PGSharedMemoryDetach is exactly what to do.  It just needs
to lose the no-longer-correct assertions.  Maybe sysv_shmem.c's version
should look the same?

The real point of PGSharedMemoryNoReAttach, now that I think about it,
is that it's dealing with a case where we passed down UsedShmemSegAddr
via the BackendParameters mechanism, but we know that the segment is
not really attached (because of exec()).  This is different from the
API expectations of PGSharedMemoryDetach, which thinks that non-nullness
of UsedShmemSegAddr corresponds to whether the segment is attached or
not.  So we can't unify those functions without breaking things, or
at least losing the ability to distinguish errors from not-errors.

BTW, another thing I think is worth looking into is exactly why the
buildfarm failed to detect this problem.  According to the code
coverage report,

https://coverage.postgresql.org/src/backend/postmaster/syslogger.c.gcov.html

we *are* exercising the syslogger at some point during a standard
test run.  Perhaps the Windows animals don't run whatever test
case that is?

            regards, tom lane

On Wed, May 15, 2019 at 10:39:49AM -0400, Tom Lane wrote:
> Hm.  I don't much like ignoring errors, which is what that would
> amount to.  It seems like in win32_shmem.c, PGSharedMemoryNoReAttach
> is already more or less right: resetting UsedShmemSegAddr to NULL and
> then calling PGSharedMemoryDetach is exactly what to do.  It just needs
> to lose the no-longer-correct assertions.  Maybe sysv_shmem.c's version
> should look the same?
>
> The real point of PGSharedMemoryNoReAttach, now that I think about it,
> is that it's dealing with a case where we passed down UsedShmemSegAddr
> via the BackendParameters mechanism, but we know that the segment is
> not really attached (because of exec()).  This is different from the
> API expectations of PGSharedMemoryDetach, which thinks that non-nullness
> of UsedShmemSegAddr corresponds to whether the segment is attached or
> not.  So we can't unify those functions without breaking things, or
> at least losing the ability to distinguish errors from not-errors.

My thoughts were to switch the LOG to DEBUG1 for the code paths where
we do not expect a failure, which is the code path from the
postmaster, so that actually comes closer to your upthread suggestion
of merging both functions.  The only thing which changes is that we
would call UnmapViewOfFile(), and fail silently.  We don't generate an
ERROR now for the existing code, just a LOG.  So there is no actual
hard failure now?  Anyway, you are right that it is no time to
redesign this interface with the current timing.

Using vcregress check with logging_collector and assertions enabled
is enough to see the failures on Windows, but the assertions actually
triggered are not the same ones as the EXEC_BACKEND case with sysv
because it's actually the three assertions in
pgwin32_ReserveSharedMemoryRegion() which blow up, not the ones in
PGSharedMemoryNoReAttach() which is able to handle its own.  Removing
some assertions are per the attached avoids problems.  I am able to
pass check with the logging collector enabled on Windows.

> BTW, another thing I think is worth looking into is exactly why the
> buildfarm failed to detect this problem.  According to the code
> coverage report,
>
> https://coverage.postgresql.org/src/backend/postmaster/syslogger.c.gcov.html
>
> we *are* exercising the syslogger at some point during a standard
> test run.  Perhaps the Windows animals don't run whatever test
> case that is?

Now from what I can see from the related buildfarm members:
- culicidae uses EXEC_BACKEND on Linux and has assertions, but not
logging_collector.
- dory, hamerkop, woodloose and bowerbird test on Windows with MSVC,
have assertions enabled, but not logging_collector.
- jacana tests on Windows with mingw, has assertions, but it does not
enforce logging_collector.
The Windows animals do not run bincheck.

So my bet is that the coverage is from pg_ctl/t/004_logrotate.pl,
which is a test skipped on Windows.  culicidae runs that, so the fact
that the failure got undetected is actually a bit of a mystery because
this uses sysv_shmem.c.

Except culicidae, I am seeing no members using EXEC_BACKEND which
enable the syslogger and use TAP tests :(
--
Michael

On Thu, May 16, 2019 at 10:38:08AM +0900, Michael Paquier wrote:
> So my bet is that the coverage is from pg_ctl/t/004_logrotate.pl,
> which is a test skipped on Windows.  culicidae runs that, so the fact
> that the failure got undetected is actually a bit of a mystery because
> this uses sysv_shmem.c.
>
> Except culicidae, I am seeing no members using EXEC_BACKEND which
> enable the syslogger and use TAP tests :(

Oh, actually culicidae catches the failure, but that's burried in the
logs, and I am not able to catch up that on my machine in the TAP
tests:
TRAP: FailedAssertion("!(UsedShmemSegAddr != ((void *)0))", File:
"pg_shmem.c", Line: 848)
https://buildfarm.postgresql.org/cgi-bin/show_stage_log.pl?nm=culicidae&dt=2019-05-16%2000%3A30%3A04&stg=pg_ctl-check

We definitely need to improve that.

Also, I am noticing another consequence as the handling of backend
variable files also suffers consequences:
could not open backend variables file
"pgsql_tmp/pgsql_tmp.backend_var.21912.1": No such file or directory

So it seems that reverting 57431a91 is an option on the table?
Opinions?
--
Michael

Hi,

On 2019-05-16 11:19:03 +0900, Michael Paquier wrote:
> So it seems that reverting 57431a91 is an option on the table?
> Opinions?

Seems a bit early to go that way. Given that this bug was reported
yesterday, and that there's reasonable sketches how to fix this, I'm not
clear why reverting would already be on the table?

Greetings,

Andres Freund

Michael Paquier <michael@paquier.xyz> writes:
> Also, I am noticing another consequence as the handling of backend
> variable files also suffers consequences:
> could not open backend variables file
> "pgsql_tmp/pgsql_tmp.backend_var.21912.1": No such file or directory

Um ... where/how are you seeing that?

            regards, tom lane

On Wed, May 15, 2019 at 11:32:38PM -0400, Tom Lane wrote:
> Michael Paquier <michael@paquier.xyz> writes:
> > Also, I am noticing another consequence as the handling of backend
> > variable files also suffers consequences:
> > could not open backend variables file
> > "pgsql_tmp/pgsql_tmp.backend_var.21912.1": No such file or directory
>
> Um ... where/how are you seeing that?

On HEAD with EXEC_BACKEND, just like that:
$ cd src/bin/pg_ctl && PROVE_TESTS=t/004_logrotate.pl make check
$ cat tmp_check/log/004_logrotate_primary.log
2019-05-16 12:44:03.427 JST [26433] LOG:  redirecting log output to
logging collector process
2019-05-16 12:44:03.427 JST [26433] HINT:  Future log output will
appear in directory "log".
could not open backend variables file
"pgsql_tmp/pgsql_tmp.backend_var.26433.1": No such file or directory

The test is able to pass, but we have a race condition between the
moment the backend file gets saved and the moment we allow it to be
read.   I have not spent much time checking the stack between
InitializeMaxBackends() and RemovePgTempFiles() in postmaster.c, but
57431a9 triggers the failure.
--
Michael

On Thu, May 16, 2019 at 12:56:17PM +0900, Michael Paquier wrote:
> The test is able to pass, but we have a race condition between the
> moment the backend file gets saved and the moment we allow it to be
> read.   I have not spent much time checking the stack between
> InitializeMaxBackends() and RemovePgTempFiles() in postmaster.c, but
> 57431a9 triggers the failure.

Oh, I think I got it.  The issue is that we call RemovePgTempFiles()
after starting the syslogger.  This cannot be run with other processes
running in parallel, and with EXEC_BACKEND there is the extra case
where we have a pgsql_tmp/ at the root of the data folder, so the
syslogger complains on that.  By making RemovePgTempFiles() happen
before starting the syslogger, then the test complains again about the
assertion without my previous patch applied of course.  With the patch
applied, I get no complains.
--
Michael

Michael Paquier <michael@paquier.xyz> writes:
> On Thu, May 16, 2019 at 12:56:17PM +0900, Michael Paquier wrote:
>> The test is able to pass, but we have a race condition between the
>> moment the backend file gets saved and the moment we allow it to be
>> read.   I have not spent much time checking the stack between
>> InitializeMaxBackends() and RemovePgTempFiles() in postmaster.c, but
>> 57431a9 triggers the failure.

> Oh, I think I got it.  The issue is that we call RemovePgTempFiles()
> after starting the syslogger.  This cannot be run with other processes
> running in parallel, and with EXEC_BACKEND there is the extra case
> where we have a pgsql_tmp/ at the root of the data folder, so the
> syslogger complains on that.  By making RemovePgTempFiles() happen
> before starting the syslogger, then the test complains again about the
> assertion without my previous patch applied of course.  With the patch
> applied, I get no complains.

Hm, should we separate the cleanup of the root pgsql_tmp/ from the rest of
what RemovePgTempFiles does?  I'm still feeling like we should be trying
to launch the syslogger as soon as possible.

            regards, tom lane

On Thu, May 16, 2019 at 12:51:34AM -0400, Tom Lane wrote:
> Hm, should we separate the cleanup of the root pgsql_tmp/ from the rest of
> what RemovePgTempFiles does?  I'm still feeling like we should be trying
> to launch the syslogger as soon as possible.

Indeed, this should be safe, the syslogger is not going to touch any
of the other temp files anyway.  If we begin to do that, we had better
update the comments at the top of RemovePgTempFiles()'s call, and
expose RemovePgTempFilesInDir().

Anyway, I have to admit that I am not really enthusiastic about
relaxing the assertions for the win32 and the sysv interfaces, and do
that inconsistently on top of it.

As far as my first investigations have gone, assertions in
pgwin32_ReserveSharedMemoryRegion() and
PGSharedMemoryReAttach():sysv_shmem.c would need relaxing, but we rely
on that since a7e5878, which is quite some time ago.  And, actually,
the failure for pgwin32_ReserveSharedMemoryRegion() should never
happen at all, because we need to call reset_shared() before starting
the syslogger as well, no?  If we want to be able to log the creation
socket messages with the logging collector, it seems to me that we
would need first to remove the dependency with the port number in
PGSharedMemoryCreate() to find a free IPC key.  Thoughts?
--
Michael

On Thu, May 16, 2019 at 03:06:28PM +0900, Michael Paquier wrote:
> As far as my first investigations have gone, assertions in
> pgwin32_ReserveSharedMemoryRegion() and
> PGSharedMemoryReAttach():sysv_shmem.c would need relaxing, but we rely
> on that since a7e5878, which is quite some time ago.  And, actually,
> the failure for pgwin32_ReserveSharedMemoryRegion() should never
> happen at all, because we need to call reset_shared() before starting
> the syslogger as well, no?

Trying to avoid calling pgwin32_ReserveSharedMemoryRegion() for
processes which are never going to connect to shared memory is
actually an interesting option, because this way there is no need to
relax the assertions it includes, and there is no point in reserving a
shared memory area if it is never going to use it.  This would not
cause a process trying to reattach to cause conflicts as well, which
is why we pre-allocate the region in the first place.

So, I have been hacking my way through this idea, and finished with
the attached.  I have added the changes to src/tools/msvc/ and
postgresql.conf.sample (enabling logging_collector by default) to test
the viability of the change, and after fixing the first assertion
issues and the second one with the temporary files, I have bumped into
a third issue causing recovery/t/017_shm.pl to remain stuck on Linux
with -DEXEC_BACKEND as the syslogger keeps starting and stopping, as
it enters.  This gets masked because of the temporary file issues
and/or the assertion problems.

This may sound rough, but based on the timing and the time I can spend
on that, I really think that we should revert 57431a9, as this has not
been completely thought through for EXEC_BACKEND, and the patch I am
attaching is a set of rough counter-measures which keep piling up,
giving a result I am not comfortable with at all.  I am not sure that
I could actually go to the bottom of it without reworking the way we
attach, detach and reattach to shared memory a process, particularly
on Windows where we don't actually need to allocate a region for a
process we know will never use shared memory (right?).  And this is no
time to do so for v12.  Last year I did the same kind of mistake by
underestimating the Windows-related stuff for v11 just before a
release which has resulted in an urgent revert as of df8b5f3.  I don't
want to do the same mistake again.
--
Michael

Hi,

Peter, it'd be really good if you could chime in here PDQ.


On 2019-05-17 13:25:36 +0900, Michael Paquier wrote:
> This may sound rough, but based on the timing and the time I can spend
> on that, I really think that we should revert 57431a9, as this has not
> been completely thought through for EXEC_BACKEND, and the patch I am
> attaching is a set of rough counter-measures which keep piling up,
> giving a result I am not comfortable with at all.  I am not sure that
> I could actually go to the bottom of it without reworking the way we
> attach, detach and reattach to shared memory a process, particularly
> on Windows where we don't actually need to allocate a region for a
> process we know will never use shared memory (right?).  And this is no
> time to do so for v12.

I'm not sure I see this as sufficient reason to revert.


> Last year I did the same kind of mistake by
> underestimating the Windows-related stuff for v11 just before a
> release which has resulted in an urgent revert as of df8b5f3.  I don't
> want to do the same mistake again.

I don't think a windows-only patch is the same thing as a feature, one
that makes debugging easier to boot, that's applicable to all platforms.



> diff --git a/src/tools/msvc/config_default.pl b/src/tools/msvc/config_default.pl
> index d7a9fc5039..de070e26e5 100644
> --- a/src/tools/msvc/config_default.pl
> +++ b/src/tools/msvc/config_default.pl
> @@ -3,7 +3,7 @@ use strict;
>  use warnings;
>
>  our $config = {
> -    asserts => 0,    # --enable-cassert
> +    asserts => 1,    # --enable-cassert
>           # float4byval=>1,         # --disable-float4-byval, on by default
>
>      # float8byval=> $platformbits == 64, # --disable-float8-byval,
> @@ -17,7 +17,7 @@ our $config = {
>      gss       => undef,    # --with-gssapi=<path>
>      icu       => undef,    # --with-icu=<path>
>      nls       => undef,    # --enable-nls=<path>
> -    tap_tests => undef,    # --enable-tap-tests
> +    tap_tests => 1,    # --enable-tap-tests
>      tcl       => undef,    # --with-tcl=<path>
>      perl      => undef,    # --with-perl
>      python    => undef,    # --with-python=<path>

Hm? Is this to coerce cfbot?

Greetings,

Andres Freund

On Fri, May 17, 2019 at 01:24:43PM -0700, Andres Freund wrote:
> I don't think a windows-only patch is the same thing as a feature, one
> that makes debugging easier to boot, that's applicable to all
> platforms.

We are discussing here a set of problems which breaks the logging
collector to work on Windows, requiring mostly a Windows patch.  And I
am not much willing to mess up with the area of shared memory handling
on Windows a couple of days before a beta.

>> diff --git a/src/tools/msvc/config_default.pl b/src/tools/msvc/config_default.pl
>> @@ -17,7 +17,7 @@ our $config = {
>>      gss       => undef,    # --with-gssapi=<path>
>>      icu       => undef,    # --with-icu=<path>
>>      nls       => undef,    # --enable-nls=<path>
>> -    tap_tests => undef,    # --enable-tap-tests
>> +    tap_tests => 1,    # --enable-tap-tests
>>      tcl       => undef,    # --with-tcl=<path>
>>      perl      => undef,    # --with-perl
>>      python    => undef,    # --with-python=<path>
>
> Hm? Is this to coerce cfbot?

This is part of the patch only because it has proved to be useful for
testing with MSVC on my VMs.  I am not suggesting to add that in this
patch if this gets merged into HEAD.  It is actually a good idea to
enforce that sometimes for the cfbot..  I'll remember your suggestion
for future patches.
--
Michael

Michael Paquier <michael@paquier.xyz> writes:
> On Fri, May 17, 2019 at 01:24:43PM -0700, Andres Freund wrote:
>> I don't think a windows-only patch is the same thing as a feature, one
>> that makes debugging easier to boot, that's applicable to all
>> platforms.

> We are discussing here a set of problems which breaks the logging
> collector to work on Windows, requiring mostly a Windows patch.  And I
> am not much willing to mess up with the area of shared memory handling
> on Windows a couple of days before a beta.

Yeah.  I started digging around this finally, and I agree that the
Windows side of it is a mess --- in particular, on Windows
internal_forkexec() calls pgwin32_ReserveSharedMemoryRegion, which
means we have a hard-wired assumption there that no postmaster child
process is launched till after shared memory exists.  EXEC_BACKEND
on Unix will not reproduce that.

At this point I agree with Michael that reverting 57431a911 is the most
prudent thing to do for beta1.  While it's probably not *that* hard to
fix, it will require Windows-specific testing.  Moreover, the fact that
there are race conditions involved means that one person's testing might
not catch everything.  So I do not think we have enough time to get a
trustworthy fix in place by Monday.  And we do have other things to
worry about.

(I'm also getting annoyed that Peter, as the original author of this
commit, isn't doing anything about the issue.)

I wouldn't be totally opposed to un-reverting after beta1, if a
better-tested patch emerges.  But we don't have such a patch today
and I don't see how we'll get there this weekend.

            regards, tom lane

[ some notes for whoever tries to fix this in the future ]

Michael Paquier <michael@paquier.xyz> writes:
> Trying to avoid calling pgwin32_ReserveSharedMemoryRegion() for
> processes which are never going to connect to shared memory is
> actually an interesting option, because this way there is no need to
> relax the assertions it includes,

Yeah, I'd come to the same conclusion while thinking about this,
but I don't think you're going about it in quite the right way.

In the first place, it's a mistake to try to drive the what-to-do-about-
shared-memory decision strictly off the type of the subprocess.  In the
case of the syslogger, in particular, we have not only the initial launch
to think about but also a possible relaunch if the first syslogger child
crashes.  In that scenario there *would* be shared memory to detach from.

So the sketch that's emerging in my mind is

1. The postmaster should have its own state variable, say
"static bool shared_memory_exists", which it sets at the appropriate
time.  (We could rely on testing UsedShmemSegAddr for that, but I don't
think that'd be good design; UsedShmemSegAddr is really private state of
the particular shmem implementation.)  Since internal_forkexec is
inside postmaster.c and runs in the postmaster process, it could just
test that state variable directly to see if it needs to call
pgwin32_ReserveSharedMemoryRegion.

2. I think we'd be well advised to get rid of the process-type-specific
tests in SubPostmasterMain, too.  The idea in my mind is to have the
postmaster pass down an additional switch explicitly saying what to do
about shared memory, so that what SubPostmasterMain does is roughly

    if (strcmp(argv[2], "--reattach") == 0)
        PGSharedMemoryReAttach();
    else if (strcmp(argv[2], "--noreattach") == 0)
        PGSharedMemoryNoReAttach();
    else
        /* do nothing, shared memory does not exist yet */ ;

Then the problem for the syslogger is solved by passing --noreattach
or not depending on whether shared_memory_exists is true yet.

I've not worked that out in any detail; getting the switches included
properly might be too much of a pain for this to be an improvement.
But for sure I don't want there to be multiple copies of that list of
which subprocess types use shared memory.

A variant idea is to include shared_memory_exists in what's passed down
by the BackendParameters mechanism, and then subprocesses can adjust
their behavior for themselves.

In any case, the thrust of all of this is that we shouldn't touch any
of the assertions in the shmem support files; rather, the way to fix
it is to improve the logic in postmaster.c so that we don't call those
functions at all in child processes that are launched before shmem
exists.

            regards, tom lane

On Sat, May 18, 2019 at 12:18:28PM -0400, Tom Lane wrote:
> At this point I agree with Michael that reverting 57431a911 is the most
> prudent thing to do for beta1.  While it's probably not *that* hard to
> fix, it will require Windows-specific testing.  Moreover, the fact that
> there are race conditions involved means that one person's testing might
> not catch everything.  So I do not think we have enough time to get a
> trustworthy fix in place by Monday.  And we do have other things to
> worry about.

Thanks for confirming.  There is little time for doing the revert, and
it would have been nice seeing comments from Peter.  Anyway, I should
be able to do that myself in 24 hours or so after coming back in
front of my desk so as the buildfarm can have a couple of cycles for
its work.  If you prefer doing that yourself, that's of course fine by
me.

> I wouldn't be totally opposed to un-reverting after beta1, if a
> better-tested patch emerges.  But we don't have such a patch today
> and I don't see how we'll get there this weekend.

Possible.  My recommendation is to keep this as potential v13 work and
focus on v12 stability.  I have no doubt that after beta1 emerges we
will get enough reports to work on.
--
Michael

Hi,

On 2019-05-18 12:18:28 -0400, Tom Lane wrote:
> At this point I agree with Michael that reverting 57431a911 is the most
> prudent thing to do for beta1.

Seems reasonable at this point in time :(.  A bit annoyed that
longer-existing crappyness around the windows port affects a relatively
platform independent patch this much.


> (I'm also getting annoyed that Peter, as the original author of this
> commit, isn't doing anything about the issue.)

Yea, I'm confused / annoyed about that too.


> I wouldn't be totally opposed to un-reverting after beta1, if a
> better-tested patch emerges.  But we don't have such a patch today
> and I don't see how we'll get there this weekend.

Right. I think if somebody puts some elbow grease into that that'd be a
reasonable course. But so far Peter's not showing up, so ...


Greetings,

Andres Freund

Michael Paquier <michael@paquier.xyz> writes:
> Thanks for confirming.  There is little time for doing the revert, and
> it would have been nice seeing comments from Peter.  Anyway, I should
> be able to do that myself in 24 hours or so after coming back in
> front of my desk so as the buildfarm can have a couple of cycles for
> its work.  If you prefer doing that yourself, that's of course fine by
> me.

I'm going to push this revert in a few minutes (as soon as I get done
with local sanity testing).  At this point, an extra 8 or 10 hours
makes a significant difference in how many of the slower buildfarm
critters will have reported in by Monday.

            regards, tom lane

I went back to take a closer look at why the existing regression tests
failed to detect this problem.  As Michael already noted,
src/bin/pg_ctl/t/004_logrotate.pl does try to exercise the logging
collector, and we do have a couple of Windows machines that run the
TAP tests, so how'd it escape notice?

The answer indeed seems to be that it *was* noticed, but Andrew failed
to realize what he was seeing:

Author: Andrew Dunstan <andrew@dunslane.net>
Branch: master [d611175e5] 2019-03-03 18:19:44 -0500

    Don't do pg_ctl logrotate test on Windows
    
    The test crashes and burns quite badly, for some reason, but even if it
    didn't it wouldn't work, since Windows doesn't let you rename a file
    held by a running process.

But even when we do run it, it fails to detect any problem, because
it's only testing for the existence of a log file not whether anything
ever gets written into it.  As it happens, SysLogger_Start() creates
the initial log file right in the postmaster (to validate the logging
parameters), so as 004_logrotate.pl is constituted it fails to prove
that the syslogger process got launched at all.  That's why it
"passes" even when the syslogger is crashing instantly on launch.

Given the current unpleasantness, I think it's quite important that
we fix 004_logrotate.pl so that it (a) poses an end-to-end test
and (b) works on Windows.  I think (a) could be managed by having
the test execute guaranteed-to-fail SQL commands ("select 1/0" or
the like) and making it look into the log file to verify that the
expected error messages appear there.  (b) is a little harder in
view of Andrew's point that we can't just summarily rename or unlink
the log file.  But I don't much like using a fixed log file name
in the test anyway.  I propose that we let it use the default logfile
pattern (postgresql-%Y-%m-%d_%H%M%S.log), and that we just sleep for a
couple of seconds before requesting rotation, and that we verify that
the file name actually changed.  We can avoid difficult issues of
guessing what file name got used by having the test script look into
"current_logfiles" to get the name --- which is another feature that
there's exactly zero test coverage of right now, so that seems like
a win all around.

Thoughts, better ideas?

            regards, tom lane

On 5/19/19 12:09 PM, Tom Lane wrote:
> I went back to take a closer look at why the existing regression tests
> failed to detect this problem.  As Michael already noted,
> src/bin/pg_ctl/t/004_logrotate.pl does try to exercise the logging
> collector, and we do have a couple of Windows machines that run the
> TAP tests, so how'd it escape notice?
>
> The answer indeed seems to be that it *was* noticed, but Andrew failed
> to realize what he was seeing:
>
> Author: Andrew Dunstan <andrew@dunslane.net>
> Branch: master [d611175e5] 2019-03-03 18:19:44 -0500
>
>     Don't do pg_ctl logrotate test on Windows
>
>     The test crashes and burns quite badly, for some reason, but even if it
>     didn't it wouldn't work, since Windows doesn't let you rename a file
>     held by a running process.
>
> But even when we do run it, it fails to detect any problem, because
> it's only testing for the existence of a log file not whether anything
> ever gets written into it.  As it happens, SysLogger_Start() creates
> the initial log file right in the postmaster (to validate the logging
> parameters), so as 004_logrotate.pl is constituted it fails to prove
> that the syslogger process got launched at all.  That's why it
> "passes" even when the syslogger is crashing instantly on launch.
>
> Given the current unpleasantness, I think it's quite important that
> we fix 004_logrotate.pl so that it (a) poses an end-to-end test
> and (b) works on Windows.  I think (a) could be managed by having
> the test execute guaranteed-to-fail SQL commands ("select 1/0" or
> the like) and making it look into the log file to verify that the
> expected error messages appear there.  (b) is a little harder in
> view of Andrew's point that we can't just summarily rename or unlink
> the log file.  But I don't much like using a fixed log file name
> in the test anyway.  I propose that we let it use the default logfile
> pattern (postgresql-%Y-%m-%d_%H%M%S.log), and that we just sleep for a
> couple of seconds before requesting rotation, and that we verify that
> the file name actually changed.  We can avoid difficult issues of
> guessing what file name got used by having the test script look into
> "current_logfiles" to get the name --- which is another feature that
> there's exactly zero test coverage of right now, so that seems like
> a win all around.
>



Worth a try.


cheers


andrew



--
Andrew Dunstan                https://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Andrew Dunstan <andrew.dunstan@2ndquadrant.com> writes:
> On 5/19/19 12:09 PM, Tom Lane wrote:
>> Given the current unpleasantness, I think it's quite important that
>> we fix 004_logrotate.pl so that it (a) poses an end-to-end test
>> and (b) works on Windows.  I think (a) could be managed by having
>> the test execute guaranteed-to-fail SQL commands ("select 1/0" or
>> the like) and making it look into the log file to verify that the
>> expected error messages appear there.  (b) is a little harder in
>> view of Andrew's point that we can't just summarily rename or unlink
>> the log file.  But I don't much like using a fixed log file name
>> in the test anyway.  I propose that we let it use the default logfile
>> pattern (postgresql-%Y-%m-%d_%H%M%S.log), and that we just sleep for a
>> couple of seconds before requesting rotation, and that we verify that
>> the file name actually changed.  We can avoid difficult issues of
>> guessing what file name got used by having the test script look into
>> "current_logfiles" to get the name --- which is another feature that
>> there's exactly zero test coverage of right now, so that seems like
>> a win all around.

> Worth a try.

Done.  I went ahead and pushed it, but if the buildfarm shows any
sign of unhappiness I'll just revert it.

            regards, tom lane

On Sun, May 19, 2019 at 11:05:22AM -0400, Tom Lane wrote:
> I'm going to push this revert in a few minutes (as soon as I get done
> with local sanity testing).  At this point, an extra 8 or 10 hours
> makes a significant difference in how many of the slower buildfarm
> critters will have reported in by Monday.

Thanks for doing that before I was able to come back, the reverted
version looks fine to me.
--
Michael

On Sun, May 19, 2019 at 02:19:40PM -0400, Tom Lane wrote:
> Done.  I went ahead and pushed it, but if the buildfarm shows any
> sign of unhappiness I'll just revert it.

I have not tested on Windows this one, but on Linux with EXEC_BACKEND
the test is still not able to detect correctly the failures of the
syslogger if one reverts 8334515 to re-enable the early syslogger
startup, so that's a bit disappointing, and on the contrary
culicidae's run frequency and its detection of the problem are good :(

The trick is that the postmaster does not complain on that as we are
still in early stages of initialization.  Still it can be found in
the logs redirected to stderr.

I got some ideas on how to improve the detection unfortunately I think
that these are rather fragile as the syslogger keeps restarting:
- Switch all the assertions in *_shmem.c to elog(FATAL) or just
elog(PANIC) to ease their detection in the logs.
- Track for any FATAL or PANIC, or even assertions failures in the log
files generated at early stages when starting the server.
- Have a GUC switch to never restart the syslogger in case of a
failure, still at realy stages we'll run into issues because the GUC
configuration may not be loaded?

Tracking the syslogger via pg_stat_activity is not an option either as
we don't want to connect it to shared memory by design.  We cannot
either increase read_backend_variables(), as all its errors go to
stderr.

Ideas are welcome.
--
Michael

On Sat, May 18, 2019 at 01:07:15PM -0400, Tom Lane wrote:
> I've not worked that out in any detail; getting the switches included
> properly might be too much of a pain for this to be an improvement.
> But for sure I don't want there to be multiple copies of that list of
> which subprocess types use shared memory.

Getting rid of the process list dependency would be nice.

> A variant idea is to include shared_memory_exists in what's passed down
> by the BackendParameters mechanism, and then subprocesses can adjust
> their behavior for themselves.

I actually got to think about having extra switches to control the
re-attachment of sub-processes when thinking about a solution, and I
agree that it would be much cleaner.  The idea about using backend
parameters is interesting (I haven't considered it), though I feel
that this could introduce race conditions as the process startup
scheduling can cause tricky issues on Windows, so I think that this
would make the system less robust.  Using a state specific to the
postmaster for the decision-making ensures a single entry point.

> In any case, the thrust of all of this is that we shouldn't touch any
> of the assertions in the shmem support files; rather, the way to fix
> it is to improve the logic in postmaster.c so that we don't call those
> functions at all in child processes that are launched before shmem
> exists.

I certainly agree with that.  Those assertions are here to stay.
--
Michael

Michael Paquier <michael@paquier.xyz> writes:
> I have not tested on Windows this one, but on Linux with EXEC_BACKEND
> the test is still not able to detect correctly the failures of the
> syslogger if one reverts 8334515 to re-enable the early syslogger
> startup, so that's a bit disappointing,

[ pokes at that... ]  Hah, it proves the syslogger restart logic
works anyway.  Because when we restart the crashed syslogger,
we're doing so after shmem exists, so the asserts don't fire.


However, I had a sudden realization about this, which is that
we need to think harder about the question of how the startup
sequence interlocks with the possibility of a pre-existing
postmaster or orphan backends.  There's code down inside
CreateDataDirLockFile that attempts to detect a pre-existing
postmaster, but if the postmaster died leaving orphan backends,
that interlock will not detect them.  Where we will notice
surviving backends is where we look for a pre-existing shared
memory segment, which is down inside reset_shared.

And: we really should not do anything much to the data directory
until we know that no such old processes remain.  Otherwise we
risk problems such as deleting active temp files.

This line of thought suggests that trying to fix things so that
we can launch child processes before creating shared memory
is the wrong thing, because it seriously risks creating problems
in the leftover-child-processes scenario.

This means that the change that 57431a911 wanted to make is only
going to be safe if we're willing to re-order things so that the
startup sequence is

    * create datadir lock file
    * create shmem
    * launch syslogger
    * create sockets

Historically we've opened the sockets before making shmem.  I'm
not sure offhand if there's any compelling reason for that order
... but if there is, getting 57431a911 to work is a whole lot
trickier than we've been thinking.

            regards, tom lane

I wrote:
> This line of thought suggests that trying to fix things so that
> we can launch child processes before creating shared memory
> is the wrong thing, because it seriously risks creating problems
> in the leftover-child-processes scenario.

> This means that the change that 57431a911 wanted to make is only
> going to be safe if we're willing to re-order things so that the
> startup sequence is

>     * create datadir lock file
>     * create shmem
>     * launch syslogger
>     * create sockets

In other words, the right way to think about this is less "move
syslogger launch to earlier" and more "move port opening to later".

I did some cursory testing of that idea with the attached patch,
which simply relocates the port opening logic to below where
syslogger start is (though "git diff" insists on presenting it
differently :-().  I also moved and recommented the emission
of the "starting ..." log entry.  It works under EXEC_BACKEND,
but I'm not fool enough to believe that that proves it works
under Windows :-(.

One issue with this is that we can't be sure we have sole control
of the postmaster port number at the time we create shmem.
Hence, to avoid undesirable conflicts of shmem, we should change
things to base the shmem key on the datadir's ID not the port
number, as was already speculated about in
https://postgr.es/m/16908.1557521200@sss.pgh.pa.us

Also, this will change the order in which entries get made into
postmaster.pid.  I think that's OK, but we'll need to take a
close look at pg_ctl to be sure it isn't making any invalid
assumptions.

Another point is that we want to be sure this doesn't change
the order in which lockfiles are released at shutdown.  That
seems OK (I confirmed by strace'ing that the postmaster's
final syscalls are still done in the same order) but it could
use some additional eyeballs on it.

There may be some other reorderings that would be a good idea.
In particular I'm thinking that the CreateOptsFile call should
be pushed down, so that it doesn't get written until we know
that the port number is OK.

            regards, tom lane

diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index f2c99e6..5ec63aa 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -993,7 +993,140 @@ PostmasterMain(int argc, char *argv[])
      */
     InitializeMaxBackends();

-    /* Report server startup in log */
+    /*
+     * Set up shared memory and semaphores.
+     */
+    reset_shared(PostPortNumber);
+
+    /*
+     * Estimate number of openable files.  This must happen after setting up
+     * semaphores, because on some platforms semaphores count as open files.
+     */
+    set_max_safe_fds();
+
+    /*
+     * Set reference point for stack-depth checking.
+     */
+    set_stack_base();
+
+    /*
+     * Initialize pipe (or process handle on Windows) that allows children to
+     * wake up from sleep on postmaster death.
+     */
+    InitPostmasterDeathWatchHandle();
+
+#ifdef WIN32
+
+    /*
+     * Initialize I/O completion port used to deliver list of dead children.
+     */
+    win32ChildQueue = CreateIoCompletionPort(INVALID_HANDLE_VALUE, NULL, 0, 1);
+    if (win32ChildQueue == NULL)
+        ereport(FATAL,
+                (errmsg("could not create I/O completion port for child queue")));
+#endif
+
+    /*
+     * Record postmaster options.  We delay this till now to avoid recording
+     * bogus options (eg, NBuffers too high for available memory).
+     */
+    if (!CreateOptsFile(argc, argv, my_exec_path))
+        ExitPostmaster(1);
+
+#ifdef EXEC_BACKEND
+    /* Write out nondefault GUC settings for child processes to use */
+    write_nondefault_variables(PGC_POSTMASTER);
+#endif
+
+    /*
+     * Write the external PID file if requested
+     */
+    if (external_pid_file)
+    {
+        FILE       *fpidfile = fopen(external_pid_file, "w");
+
+        if (fpidfile)
+        {
+            fprintf(fpidfile, "%d\n", MyProcPid);
+            fclose(fpidfile);
+
+            /* Make PID file world readable */
+            if (chmod(external_pid_file, S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH) != 0)
+                write_stderr("%s: could not change permissions of external PID file \"%s\": %s\n",
+                             progname, external_pid_file, strerror(errno));
+        }
+        else
+            write_stderr("%s: could not write external PID file \"%s\": %s\n",
+                         progname, external_pid_file, strerror(errno));
+
+        on_proc_exit(unlink_external_pid_file, 0);
+    }
+
+    /*
+     * Remove old temporary files.  At this point there can be no other
+     * Postgres processes running in this directory, so this should be safe.
+     */
+    RemovePgTempFiles();
+
+    /*
+     * Forcibly remove the files signaling a standby promotion request.
+     * Otherwise, the existence of those files triggers a promotion too early,
+     * whether a user wants that or not.
+     *
+     * This removal of files is usually unnecessary because they can exist
+     * only during a few moments during a standby promotion. However there is
+     * a race condition: if pg_ctl promote is executed and creates the files
+     * during a promotion, the files can stay around even after the server is
+     * brought up to new master. Then, if new standby starts by using the
+     * backup taken from that master, the files can exist at the server
+     * startup and should be removed in order to avoid an unexpected
+     * promotion.
+     *
+     * Note that promotion signal files need to be removed before the startup
+     * process is invoked. Because, after that, they can be used by
+     * postmaster's SIGUSR1 signal handler.
+     */
+    RemovePromoteSignalFiles();
+
+    /* Do the same for logrotate signal file */
+    RemoveLogrotateSignalFiles();
+
+    /* Remove any outdated file holding the current log filenames. */
+    if (unlink(LOG_METAINFO_DATAFILE) < 0 && errno != ENOENT)
+        ereport(LOG,
+                (errcode_for_file_access(),
+                 errmsg("could not remove file \"%s\": %m",
+                        LOG_METAINFO_DATAFILE)));
+
+    /*
+     * If enabled, start up syslogger collection subprocess
+     */
+    SysLoggerPID = SysLogger_Start();
+
+    /*
+     * Reset whereToSendOutput from DestDebug (its starting state) to
+     * DestNone. This stops ereport from sending log messages to stderr unless
+     * Log_destination permits.  We don't do this until the postmaster is
+     * fully launched, since startup failures may as well be reported to
+     * stderr.
+     *
+     * If we are in fact disabling logging to stderr, first emit a log message
+     * saying so, to provide a breadcrumb trail for users who may not remember
+     * that their logging is configured to go somewhere else.
+     */
+    if (!(Log_destination & LOG_DESTINATION_STDERR))
+        ereport(LOG,
+                (errmsg("ending log output to stderr"),
+                 errhint("Future log output will go to log destination \"%s\".",
+                         Log_destination_string)));
+
+    whereToSendOutput = DestNone;
+
+    /*
+     * Report server startup in log.  While we could emit this much earlier,
+     * it seems best to do so after starting the log collector, if we intend
+     * to use one.
+     */
     ereport(LOG,
             (errmsg("starting %s", PG_VERSION_STR)));

@@ -1173,135 +1306,6 @@ PostmasterMain(int argc, char *argv[])
         AddToDataDirLockFile(LOCK_FILE_LINE_LISTEN_ADDR, "");

     /*
-     * Set up shared memory and semaphores.
-     */
-    reset_shared(PostPortNumber);
-
-    /*
-     * Estimate number of openable files.  This must happen after setting up
-     * semaphores, because on some platforms semaphores count as open files.
-     */
-    set_max_safe_fds();
-
-    /*
-     * Set reference point for stack-depth checking.
-     */
-    set_stack_base();
-
-    /*
-     * Initialize pipe (or process handle on Windows) that allows children to
-     * wake up from sleep on postmaster death.
-     */
-    InitPostmasterDeathWatchHandle();
-
-#ifdef WIN32
-
-    /*
-     * Initialize I/O completion port used to deliver list of dead children.
-     */
-    win32ChildQueue = CreateIoCompletionPort(INVALID_HANDLE_VALUE, NULL, 0, 1);
-    if (win32ChildQueue == NULL)
-        ereport(FATAL,
-                (errmsg("could not create I/O completion port for child queue")));
-#endif
-
-    /*
-     * Record postmaster options.  We delay this till now to avoid recording
-     * bogus options (eg, NBuffers too high for available memory).
-     */
-    if (!CreateOptsFile(argc, argv, my_exec_path))
-        ExitPostmaster(1);
-
-#ifdef EXEC_BACKEND
-    /* Write out nondefault GUC settings for child processes to use */
-    write_nondefault_variables(PGC_POSTMASTER);
-#endif
-
-    /*
-     * Write the external PID file if requested
-     */
-    if (external_pid_file)
-    {
-        FILE       *fpidfile = fopen(external_pid_file, "w");
-
-        if (fpidfile)
-        {
-            fprintf(fpidfile, "%d\n", MyProcPid);
-            fclose(fpidfile);
-
-            /* Make PID file world readable */
-            if (chmod(external_pid_file, S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH) != 0)
-                write_stderr("%s: could not change permissions of external PID file \"%s\": %s\n",
-                             progname, external_pid_file, strerror(errno));
-        }
-        else
-            write_stderr("%s: could not write external PID file \"%s\": %s\n",
-                         progname, external_pid_file, strerror(errno));
-
-        on_proc_exit(unlink_external_pid_file, 0);
-    }
-
-    /*
-     * Remove old temporary files.  At this point there can be no other
-     * Postgres processes running in this directory, so this should be safe.
-     */
-    RemovePgTempFiles();
-
-    /*
-     * Forcibly remove the files signaling a standby promotion request.
-     * Otherwise, the existence of those files triggers a promotion too early,
-     * whether a user wants that or not.
-     *
-     * This removal of files is usually unnecessary because they can exist
-     * only during a few moments during a standby promotion. However there is
-     * a race condition: if pg_ctl promote is executed and creates the files
-     * during a promotion, the files can stay around even after the server is
-     * brought up to new master. Then, if new standby starts by using the
-     * backup taken from that master, the files can exist at the server
-     * startup and should be removed in order to avoid an unexpected
-     * promotion.
-     *
-     * Note that promotion signal files need to be removed before the startup
-     * process is invoked. Because, after that, they can be used by
-     * postmaster's SIGUSR1 signal handler.
-     */
-    RemovePromoteSignalFiles();
-
-    /* Do the same for logrotate signal file */
-    RemoveLogrotateSignalFiles();
-
-    /* Remove any outdated file holding the current log filenames. */
-    if (unlink(LOG_METAINFO_DATAFILE) < 0 && errno != ENOENT)
-        ereport(LOG,
-                (errcode_for_file_access(),
-                 errmsg("could not remove file \"%s\": %m",
-                        LOG_METAINFO_DATAFILE)));
-
-    /*
-     * If enabled, start up syslogger collection subprocess
-     */
-    SysLoggerPID = SysLogger_Start();
-
-    /*
-     * Reset whereToSendOutput from DestDebug (its starting state) to
-     * DestNone. This stops ereport from sending log messages to stderr unless
-     * Log_destination permits.  We don't do this until the postmaster is
-     * fully launched, since startup failures may as well be reported to
-     * stderr.
-     *
-     * If we are in fact disabling logging to stderr, first emit a log message
-     * saying so, to provide a breadcrumb trail for users who may not remember
-     * that their logging is configured to go somewhere else.
-     */
-    if (!(Log_destination & LOG_DESTINATION_STDERR))
-        ereport(LOG,
-                (errmsg("ending log output to stderr"),
-                 errhint("Future log output will go to log destination \"%s\".",
-                         Log_destination_string)));
-
-    whereToSendOutput = DestNone;
-
-    /*
      * Initialize stats collection subsystem (this does NOT start the
      * collector process!)
      */

On Mon, May 20, 2019 at 11:01:05AM -0400, Tom Lane wrote:
> In other words, the right way to think about this is less "move
> syslogger launch to earlier" and more "move port opening to later".

> I did some cursory testing of that idea with the attached patch,
> which simply relocates the port opening logic to below where
> syslogger start is (though "git diff" insists on presenting it
> differently :-().  I also moved and recommented the emission
> of the "starting ..." log entry.  It works under EXEC_BACKEND,
> but I'm not fool enough to believe that that proves it works
> under Windows :-(.

I can see what you have done, no worries.

> One issue with this is that we can't be sure we have sole control
> of the postmaster port number at the time we create shmem.

Couldn't that also be a problem for some users?  This means that
there is a window where the port won't be opened but the external PID
file can be found.  Some tools could be broken as an effect of that.

> Hence, to avoid undesirable conflicts of shmem, we should change
> things to base the shmem key on the datadir's ID not the port
> number, as was already speculated about in
> https://postgr.es/m/16908.1557521200@sss.pgh.pa.us

This would be actually nice to change as you suggest.

> Another point is that we want to be sure this doesn't change
> the order in which lockfiles are released at shutdown.  That
> seems OK (I confirmed by strace'ing that the postmaster's
> final syscalls are still done in the same order) but it could
> use some additional eyeballs on it.
>
> There may be some other reorderings that would be a good idea.
> In particular I'm thinking that the CreateOptsFile call should
> be pushed down, so that it doesn't get written until we know
> that the port number is OK.

Is this thread a good place to discuss all those changes by the way?
After all the recent activity in this area, a new thread and a
discussion for v13 would be I think appropriate.  I would rather not
play with the devil for v12.
--
Michael

On 2019-05-19 04:10, Andres Freund wrote:
>> (I'm also getting annoyed that Peter, as the original author of this
>> commit, isn't doing anything about the issue.)
> 
> Yea, I'm confused / annoyed about that too.

I was traveling, and the subject line didn't yell "problem with beta1".

>> I wouldn't be totally opposed to un-reverting after beta1, if a
>> better-tested patch emerges.  But we don't have such a patch today
>> and I don't see how we'll get there this weekend.
> 
> Right. I think if somebody puts some elbow grease into that that'd be a
> reasonable course. But so far Peter's not showing up, so ...

After rereading the entire discussion, I don't have much enthusiasm for
trying to fix this for PG12.  It's worth trying again in the future.

-- 
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Peter Eisentraut <peter.eisentraut@2ndquadrant.com> writes:
> After rereading the entire discussion, I don't have much enthusiasm for
> trying to fix this for PG12.  It's worth trying again in the future.

Fair enough.  I stuck my patch into the CF app[1] so we don't forget.

            regards, tom lane

[1] https://commitfest.postgresql.org/23/2126/

I wrote:
> In other words, the right way to think about this is less "move
> syslogger launch to earlier" and more "move port opening to later".

> I did some cursory testing of that idea with the attached patch,
> which simply relocates the port opening logic to below where
> syslogger start is (though "git diff" insists on presenting it
> differently :-().  I also moved and recommented the emission
> of the "starting ..." log entry.

The cfbot noticed that this required a minor rebase over 7de19fbc0,
so here is one.

> One issue with this is that we can't be sure we have sole control
> of the postmaster port number at the time we create shmem.
> Hence, to avoid undesirable conflicts of shmem, we should change
> things to base the shmem key on the datadir's ID not the port
> number, as was already speculated about in
> https://postgr.es/m/16908.1557521200@sss.pgh.pa.us

That's now been committed (7de19fbc0), so it's not holding back
this patch anymore.

> Also, this will change the order in which entries get made into
> postmaster.pid.  I think that's OK, but we'll need to take a
> close look at pg_ctl to be sure it isn't making any invalid
> assumptions.

I took a look around and couldn't find any such problems.
pg_ctl, in particular, doesn't care about the order in which
these lines get added.  I did add a comment to pidfile.h
warning people against making new assumptions in this area.

> There may be some other reorderings that would be a good idea.
> In particular I'm thinking that the CreateOptsFile call should
> be pushed down, so that it doesn't get written until we know
> that the port number is OK.

I did that here, too.

I think this probably is committable now, though of course it'd
be good for somebody to review it (and maybe test on Windows
before it hits the buildfarm?)

            regards, tom lane

diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index a5446d5..6941159 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -993,7 +993,133 @@ PostmasterMain(int argc, char *argv[])
      */
     InitializeMaxBackends();

-    /* Report server startup in log */
+    /*
+     * Set up shared memory and semaphores.
+     */
+    reset_shared();
+
+    /*
+     * Estimate number of openable files.  This must happen after setting up
+     * semaphores, because on some platforms semaphores count as open files.
+     */
+    set_max_safe_fds();
+
+    /*
+     * Set reference point for stack-depth checking.
+     */
+    set_stack_base();
+
+    /*
+     * Initialize pipe (or process handle on Windows) that allows children to
+     * wake up from sleep on postmaster death.
+     */
+    InitPostmasterDeathWatchHandle();
+
+#ifdef WIN32
+
+    /*
+     * Initialize I/O completion port used to deliver list of dead children.
+     */
+    win32ChildQueue = CreateIoCompletionPort(INVALID_HANDLE_VALUE, NULL, 0, 1);
+    if (win32ChildQueue == NULL)
+        ereport(FATAL,
+                (errmsg("could not create I/O completion port for child queue")));
+#endif
+
+#ifdef EXEC_BACKEND
+    /* Write out nondefault GUC settings for child processes to use */
+    write_nondefault_variables(PGC_POSTMASTER);
+#endif
+
+    /*
+     * Write the external PID file if requested
+     */
+    if (external_pid_file)
+    {
+        FILE       *fpidfile = fopen(external_pid_file, "w");
+
+        if (fpidfile)
+        {
+            fprintf(fpidfile, "%d\n", MyProcPid);
+            fclose(fpidfile);
+
+            /* Make PID file world readable */
+            if (chmod(external_pid_file, S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH) != 0)
+                write_stderr("%s: could not change permissions of external PID file \"%s\": %s\n",
+                             progname, external_pid_file, strerror(errno));
+        }
+        else
+            write_stderr("%s: could not write external PID file \"%s\": %s\n",
+                         progname, external_pid_file, strerror(errno));
+
+        on_proc_exit(unlink_external_pid_file, 0);
+    }
+
+    /*
+     * Remove old temporary files.  At this point there can be no other
+     * Postgres processes running in this directory, so this should be safe.
+     */
+    RemovePgTempFiles();
+
+    /*
+     * Forcibly remove the files signaling a standby promotion request.
+     * Otherwise, the existence of those files triggers a promotion too early,
+     * whether a user wants that or not.
+     *
+     * This removal of files is usually unnecessary because they can exist
+     * only during a few moments during a standby promotion. However there is
+     * a race condition: if pg_ctl promote is executed and creates the files
+     * during a promotion, the files can stay around even after the server is
+     * brought up to new master. Then, if new standby starts by using the
+     * backup taken from that master, the files can exist at the server
+     * startup and should be removed in order to avoid an unexpected
+     * promotion.
+     *
+     * Note that promotion signal files need to be removed before the startup
+     * process is invoked. Because, after that, they can be used by
+     * postmaster's SIGUSR1 signal handler.
+     */
+    RemovePromoteSignalFiles();
+
+    /* Do the same for logrotate signal file */
+    RemoveLogrotateSignalFiles();
+
+    /* Remove any outdated file holding the current log filenames. */
+    if (unlink(LOG_METAINFO_DATAFILE) < 0 && errno != ENOENT)
+        ereport(LOG,
+                (errcode_for_file_access(),
+                 errmsg("could not remove file \"%s\": %m",
+                        LOG_METAINFO_DATAFILE)));
+
+    /*
+     * If enabled, start up syslogger collection subprocess
+     */
+    SysLoggerPID = SysLogger_Start();
+
+    /*
+     * Reset whereToSendOutput from DestDebug (its starting state) to
+     * DestNone. This stops ereport from sending log messages to stderr unless
+     * Log_destination permits.  We don't do this until the postmaster is
+     * fully launched, since startup failures may as well be reported to
+     * stderr.
+     *
+     * If we are in fact disabling logging to stderr, first emit a log message
+     * saying so, to provide a breadcrumb trail for users who may not remember
+     * that their logging is configured to go somewhere else.
+     */
+    if (!(Log_destination & LOG_DESTINATION_STDERR))
+        ereport(LOG,
+                (errmsg("ending log output to stderr"),
+                 errhint("Future log output will go to log destination \"%s\".",
+                         Log_destination_string)));
+
+    whereToSendOutput = DestNone;
+
+    /*
+     * Report server startup in log.  While we could emit this much earlier,
+     * it seems best to do so after starting the log collector, if we intend
+     * to use one.
+     */
     ereport(LOG,
             (errmsg("starting %s", PG_VERSION_STR)));

@@ -1173,134 +1299,12 @@ PostmasterMain(int argc, char *argv[])
         AddToDataDirLockFile(LOCK_FILE_LINE_LISTEN_ADDR, "");

     /*
-     * Set up shared memory and semaphores.
-     */
-    reset_shared();
-
-    /*
-     * Estimate number of openable files.  This must happen after setting up
-     * semaphores, because on some platforms semaphores count as open files.
-     */
-    set_max_safe_fds();
-
-    /*
-     * Set reference point for stack-depth checking.
-     */
-    set_stack_base();
-
-    /*
-     * Initialize pipe (or process handle on Windows) that allows children to
-     * wake up from sleep on postmaster death.
-     */
-    InitPostmasterDeathWatchHandle();
-
-#ifdef WIN32
-
-    /*
-     * Initialize I/O completion port used to deliver list of dead children.
-     */
-    win32ChildQueue = CreateIoCompletionPort(INVALID_HANDLE_VALUE, NULL, 0, 1);
-    if (win32ChildQueue == NULL)
-        ereport(FATAL,
-                (errmsg("could not create I/O completion port for child queue")));
-#endif
-
-    /*
      * Record postmaster options.  We delay this till now to avoid recording
-     * bogus options (eg, NBuffers too high for available memory).
+     * bogus options (eg, unusable port number).
      */
     if (!CreateOptsFile(argc, argv, my_exec_path))
         ExitPostmaster(1);

-#ifdef EXEC_BACKEND
-    /* Write out nondefault GUC settings for child processes to use */
-    write_nondefault_variables(PGC_POSTMASTER);
-#endif
-
-    /*
-     * Write the external PID file if requested
-     */
-    if (external_pid_file)
-    {
-        FILE       *fpidfile = fopen(external_pid_file, "w");
-
-        if (fpidfile)
-        {
-            fprintf(fpidfile, "%d\n", MyProcPid);
-            fclose(fpidfile);
-
-            /* Make PID file world readable */
-            if (chmod(external_pid_file, S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH) != 0)
-                write_stderr("%s: could not change permissions of external PID file \"%s\": %s\n",
-                             progname, external_pid_file, strerror(errno));
-        }
-        else
-            write_stderr("%s: could not write external PID file \"%s\": %s\n",
-                         progname, external_pid_file, strerror(errno));
-
-        on_proc_exit(unlink_external_pid_file, 0);
-    }
-
-    /*
-     * Remove old temporary files.  At this point there can be no other
-     * Postgres processes running in this directory, so this should be safe.
-     */
-    RemovePgTempFiles();
-
-    /*
-     * Forcibly remove the files signaling a standby promotion request.
-     * Otherwise, the existence of those files triggers a promotion too early,
-     * whether a user wants that or not.
-     *
-     * This removal of files is usually unnecessary because they can exist
-     * only during a few moments during a standby promotion. However there is
-     * a race condition: if pg_ctl promote is executed and creates the files
-     * during a promotion, the files can stay around even after the server is
-     * brought up to new master. Then, if new standby starts by using the
-     * backup taken from that master, the files can exist at the server
-     * startup and should be removed in order to avoid an unexpected
-     * promotion.
-     *
-     * Note that promotion signal files need to be removed before the startup
-     * process is invoked. Because, after that, they can be used by
-     * postmaster's SIGUSR1 signal handler.
-     */
-    RemovePromoteSignalFiles();
-
-    /* Do the same for logrotate signal file */
-    RemoveLogrotateSignalFiles();
-
-    /* Remove any outdated file holding the current log filenames. */
-    if (unlink(LOG_METAINFO_DATAFILE) < 0 && errno != ENOENT)
-        ereport(LOG,
-                (errcode_for_file_access(),
-                 errmsg("could not remove file \"%s\": %m",
-                        LOG_METAINFO_DATAFILE)));
-
-    /*
-     * If enabled, start up syslogger collection subprocess
-     */
-    SysLoggerPID = SysLogger_Start();
-
-    /*
-     * Reset whereToSendOutput from DestDebug (its starting state) to
-     * DestNone. This stops ereport from sending log messages to stderr unless
-     * Log_destination permits.  We don't do this until the postmaster is
-     * fully launched, since startup failures may as well be reported to
-     * stderr.
-     *
-     * If we are in fact disabling logging to stderr, first emit a log message
-     * saying so, to provide a breadcrumb trail for users who may not remember
-     * that their logging is configured to go somewhere else.
-     */
-    if (!(Log_destination & LOG_DESTINATION_STDERR))
-        ereport(LOG,
-                (errmsg("ending log output to stderr"),
-                 errhint("Future log output will go to log destination \"%s\".",
-                         Log_destination_string)));
-
-    whereToSendOutput = DestNone;
-
     /*
      * Initialize stats collection subsystem (this does NOT start the
      * collector process!)
diff --git a/src/include/utils/pidfile.h b/src/include/utils/pidfile.h
index b2dcca6..21e7ccf 100644
--- a/src/include/utils/pidfile.h
+++ b/src/include/utils/pidfile.h
@@ -28,7 +28,8 @@
  *
  * Lines 6 and up are added via AddToDataDirLockFile() after initial file
  * creation; also, line 5 is initially empty and is changed after the first
- * Unix socket is opened.
+ * Unix socket is opened.  Onlookers should not assume that lines 4 and up
+ * are filled in any particular order.
  *
  * Socket lock file(s), if used, have the same contents as lines 1-5, with
  * line 5 being their own directory.

On Mon, Sep 09, 2019 at 03:35:23PM -0400, Tom Lane wrote:
> I think this probably is committable now, though of course it'd
> be good for somebody to review it (and maybe test on Windows
> before it hits the buildfarm?)

I have looked at the patch and tested it a bit on Windows with MSVC
(TAP, bincheck, etc.), and the logic looks fine.  Thanks.

Do we need to worry about the port being opened after the external PID
file is written though?  With some imagination it is possible to
imagine that some folks rely on the external PID file to be present
before attempting to access Postgres when not using pg_ctl.  Still, I
would discard that as postmaster.pid gets written before opening the
port already.
--
Michael

Michael Paquier <michael@paquier.xyz> writes:
> Do we need to worry about the port being opened after the external PID
> file is written though?  With some imagination it is possible to
> imagine that some folks rely on the external PID file to be present
> before attempting to access Postgres when not using pg_ctl.  Still, I
> would discard that as postmaster.pid gets written before opening the
> port already.

Hm, that's a good point.  Extending my comment upthread, the existing
code sequence is

    * create datadir lock file
    * create sockets
    * create shmem
    * create external PID file, if requested
    * launch syslogger

which this patch proposes to rearrange to

    * create datadir lock file
    * create shmem
    * create external PID file, if requested
    * launch syslogger
    * create sockets

As far as the datadir lock file is concerned, it's there first in any case.
You could imagine some external code that expects that the socket-related
lines in postmaster.pid will be filled before the shmem key line is,
in which case this patch would break it.  But it's hard to see exactly
what such an expectation would consist of.  There isn't really any
good reason for external code to look at the shmem key line at all.

But the external PID file is a different story.  I can believe that
something might be expecting the sockets to be open before we create
that file --- and since we're not using that file for an interlock,
there's no reason to be in a hurry to create it.  I think it'd make
sense to move that step further down, so it's still done after the
create-sockets step.

            regards, tom lane

On Tue, Sep 10, 2019 at 01:28:51AM -0400, Tom Lane wrote:
> But the external PID file is a different story.  I can believe that
> something might be expecting the sockets to be open before we create
> that file --- and since we're not using that file for an interlock,
> there's no reason to be in a hurry to create it.  I think it'd make
> sense to move that step further down, so it's still done after the
> create-sockets step.

That's the actual take here.  We cannot assume that nobody is relying
on that.  If they do, it could be tricky to rework this logic.  Moving
the external file write a bit later does not sound like a bad thing in
itself to keep more consistency with the past.
--
Michael

Michael Paquier <michael@paquier.xyz> writes:
> On Tue, Sep 10, 2019 at 01:28:51AM -0400, Tom Lane wrote:
>> But the external PID file is a different story.  I can believe that
>> something might be expecting the sockets to be open before we create
>> that file --- and since we're not using that file for an interlock,
>> there's no reason to be in a hurry to create it.  I think it'd make
>> sense to move that step further down, so it's still done after the
>> create-sockets step.

> That's the actual take here.  We cannot assume that nobody is relying
> on that.  If they do, it could be tricky to rework this logic.  Moving
> the external file write a bit later does not sound like a bad thing in
> itself to keep more consistency with the past.

Here's a version that does it like that.  After studying things a bit,
it seemed like a good idea to also move RemovePgTempFiles() down,
so that that possibly-slow step still occurs after making the external
PID file.  Everything else that we've moved to before that step
should be reasonably quick.

            regards, tom lane

diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index a5446d5..bf4376c 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -993,7 +993,103 @@ PostmasterMain(int argc, char *argv[])
      */
     InitializeMaxBackends();

-    /* Report server startup in log */
+    /*
+     * Set up shared memory and semaphores.
+     */
+    reset_shared();
+
+    /*
+     * Estimate number of openable files.  This must happen after setting up
+     * semaphores, because on some platforms semaphores count as open files.
+     */
+    set_max_safe_fds();
+
+    /*
+     * Set reference point for stack-depth checking.
+     */
+    set_stack_base();
+
+    /*
+     * Initialize pipe (or process handle on Windows) that allows children to
+     * wake up from sleep on postmaster death.
+     */
+    InitPostmasterDeathWatchHandle();
+
+#ifdef WIN32
+
+    /*
+     * Initialize I/O completion port used to deliver list of dead children.
+     */
+    win32ChildQueue = CreateIoCompletionPort(INVALID_HANDLE_VALUE, NULL, 0, 1);
+    if (win32ChildQueue == NULL)
+        ereport(FATAL,
+                (errmsg("could not create I/O completion port for child queue")));
+#endif
+
+#ifdef EXEC_BACKEND
+    /* Write out nondefault GUC settings for child processes to use */
+    write_nondefault_variables(PGC_POSTMASTER);
+#endif
+
+    /*
+     * Forcibly remove the files signaling a standby promotion request.
+     * Otherwise, the existence of those files triggers a promotion too early,
+     * whether a user wants that or not.
+     *
+     * This removal of files is usually unnecessary because they can exist
+     * only during a few moments during a standby promotion. However there is
+     * a race condition: if pg_ctl promote is executed and creates the files
+     * during a promotion, the files can stay around even after the server is
+     * brought up to new master. Then, if new standby starts by using the
+     * backup taken from that master, the files can exist at the server
+     * startup and should be removed in order to avoid an unexpected
+     * promotion.
+     *
+     * Note that promotion signal files need to be removed before the startup
+     * process is invoked. Because, after that, they can be used by
+     * postmaster's SIGUSR1 signal handler.
+     */
+    RemovePromoteSignalFiles();
+
+    /* Do the same for logrotate signal file */
+    RemoveLogrotateSignalFiles();
+
+    /* Remove any outdated file holding the current log filenames. */
+    if (unlink(LOG_METAINFO_DATAFILE) < 0 && errno != ENOENT)
+        ereport(LOG,
+                (errcode_for_file_access(),
+                 errmsg("could not remove file \"%s\": %m",
+                        LOG_METAINFO_DATAFILE)));
+
+    /*
+     * If enabled, start up syslogger collection subprocess
+     */
+    SysLoggerPID = SysLogger_Start();
+
+    /*
+     * Reset whereToSendOutput from DestDebug (its starting state) to
+     * DestNone. This stops ereport from sending log messages to stderr unless
+     * Log_destination permits.  We don't do this until the postmaster is
+     * fully launched, since startup failures may as well be reported to
+     * stderr.
+     *
+     * If we are in fact disabling logging to stderr, first emit a log message
+     * saying so, to provide a breadcrumb trail for users who may not remember
+     * that their logging is configured to go somewhere else.
+     */
+    if (!(Log_destination & LOG_DESTINATION_STDERR))
+        ereport(LOG,
+                (errmsg("ending log output to stderr"),
+                 errhint("Future log output will go to log destination \"%s\".",
+                         Log_destination_string)));
+
+    whereToSendOutput = DestNone;
+
+    /*
+     * Report server startup in log.  While we could emit this much earlier,
+     * it seems best to do so after starting the log collector, if we intend
+     * to use one.
+     */
     ereport(LOG,
             (errmsg("starting %s", PG_VERSION_STR)));

@@ -1173,50 +1269,12 @@ PostmasterMain(int argc, char *argv[])
         AddToDataDirLockFile(LOCK_FILE_LINE_LISTEN_ADDR, "");

     /*
-     * Set up shared memory and semaphores.
-     */
-    reset_shared();
-
-    /*
-     * Estimate number of openable files.  This must happen after setting up
-     * semaphores, because on some platforms semaphores count as open files.
-     */
-    set_max_safe_fds();
-
-    /*
-     * Set reference point for stack-depth checking.
-     */
-    set_stack_base();
-
-    /*
-     * Initialize pipe (or process handle on Windows) that allows children to
-     * wake up from sleep on postmaster death.
-     */
-    InitPostmasterDeathWatchHandle();
-
-#ifdef WIN32
-
-    /*
-     * Initialize I/O completion port used to deliver list of dead children.
-     */
-    win32ChildQueue = CreateIoCompletionPort(INVALID_HANDLE_VALUE, NULL, 0, 1);
-    if (win32ChildQueue == NULL)
-        ereport(FATAL,
-                (errmsg("could not create I/O completion port for child queue")));
-#endif
-
-    /*
      * Record postmaster options.  We delay this till now to avoid recording
-     * bogus options (eg, NBuffers too high for available memory).
+     * bogus options (eg, unusable port number).
      */
     if (!CreateOptsFile(argc, argv, my_exec_path))
         ExitPostmaster(1);

-#ifdef EXEC_BACKEND
-    /* Write out nondefault GUC settings for child processes to use */
-    write_nondefault_variables(PGC_POSTMASTER);
-#endif
-
     /*
      * Write the external PID file if requested
      */
@@ -1248,60 +1306,6 @@ PostmasterMain(int argc, char *argv[])
     RemovePgTempFiles();

     /*
-     * Forcibly remove the files signaling a standby promotion request.
-     * Otherwise, the existence of those files triggers a promotion too early,
-     * whether a user wants that or not.
-     *
-     * This removal of files is usually unnecessary because they can exist
-     * only during a few moments during a standby promotion. However there is
-     * a race condition: if pg_ctl promote is executed and creates the files
-     * during a promotion, the files can stay around even after the server is
-     * brought up to new master. Then, if new standby starts by using the
-     * backup taken from that master, the files can exist at the server
-     * startup and should be removed in order to avoid an unexpected
-     * promotion.
-     *
-     * Note that promotion signal files need to be removed before the startup
-     * process is invoked. Because, after that, they can be used by
-     * postmaster's SIGUSR1 signal handler.
-     */
-    RemovePromoteSignalFiles();
-
-    /* Do the same for logrotate signal file */
-    RemoveLogrotateSignalFiles();
-
-    /* Remove any outdated file holding the current log filenames. */
-    if (unlink(LOG_METAINFO_DATAFILE) < 0 && errno != ENOENT)
-        ereport(LOG,
-                (errcode_for_file_access(),
-                 errmsg("could not remove file \"%s\": %m",
-                        LOG_METAINFO_DATAFILE)));
-
-    /*
-     * If enabled, start up syslogger collection subprocess
-     */
-    SysLoggerPID = SysLogger_Start();
-
-    /*
-     * Reset whereToSendOutput from DestDebug (its starting state) to
-     * DestNone. This stops ereport from sending log messages to stderr unless
-     * Log_destination permits.  We don't do this until the postmaster is
-     * fully launched, since startup failures may as well be reported to
-     * stderr.
-     *
-     * If we are in fact disabling logging to stderr, first emit a log message
-     * saying so, to provide a breadcrumb trail for users who may not remember
-     * that their logging is configured to go somewhere else.
-     */
-    if (!(Log_destination & LOG_DESTINATION_STDERR))
-        ereport(LOG,
-                (errmsg("ending log output to stderr"),
-                 errhint("Future log output will go to log destination \"%s\".",
-                         Log_destination_string)));
-
-    whereToSendOutput = DestNone;
-
-    /*
      * Initialize stats collection subsystem (this does NOT start the
      * collector process!)
      */
diff --git a/src/include/utils/pidfile.h b/src/include/utils/pidfile.h
index b2dcca6..21e7ccf 100644
--- a/src/include/utils/pidfile.h
+++ b/src/include/utils/pidfile.h
@@ -28,7 +28,8 @@
  *
  * Lines 6 and up are added via AddToDataDirLockFile() after initial file
  * creation; also, line 5 is initially empty and is changed after the first
- * Unix socket is opened.
+ * Unix socket is opened.  Onlookers should not assume that lines 4 and up
+ * are filled in any particular order.
  *
  * Socket lock file(s), if used, have the same contents as lines 1-5, with
  * line 5 being their own directory.

On Tue, Sep 10, 2019 at 10:58:52AM -0400, Tom Lane wrote:
> Here's a version that does it like that.  After studying things a bit,
> it seemed like a good idea to also move RemovePgTempFiles() down,
> so that that possibly-slow step still occurs after making the external
> PID file.  Everything else that we've moved to before that step
> should be reasonably quick.

Good point.  Nothing more to add with this version.  Thanks for
caring.
--
Michael

Michael Paquier <michael@paquier.xyz> writes:
> On Tue, Sep 10, 2019 at 10:58:52AM -0400, Tom Lane wrote:
>> Here's a version that does it like that.  After studying things a bit,
>> it seemed like a good idea to also move RemovePgTempFiles() down,
>> so that that possibly-slow step still occurs after making the external
>> PID file.  Everything else that we've moved to before that step
>> should be reasonably quick.

> Good point.  Nothing more to add with this version.  Thanks for
> caring.

I did one final round of testing and noted that in a Linux EXEC_BACKEND
build, this last change causes the race condition that was noted upthread:
RemovePgTempFiles could remove the parameter file that the syslogger
process is supposed to consume.  So I split off the clearing of that
subdirectory as we'd discussed, and pushed it.  Thanks for reviewing!

            regards, tom lane