Unexpected "shared memory block is still in use"

Just now, while running a parallel check-world on HEAD according to the
same script I've been using for quite some time, one of the TAP tests
died during initdb:

selecting dynamic shared memory implementation ... posix
selecting default max_connections ... 100
selecting default shared_buffers ... 128MB
selecting default timezone ... America/New_York
creating configuration files ... ok
running bootstrap script ... ok
performing post-bootstrap initialization ... 2019-05-08 13:59:19.963 EDT [18351] FATAL: pre-existing shared memory block (key 5440004, ID 1734475802) is still in use
2019-05-08 13:59:19.963 EDT [18351] HINT: Terminate any old server processes associated with data directory "/home/postgres/pgsql/src/test/subscription/tmp_check/t_004_sync_publisher_data/pgdata".
child process exited with exit code 1
initdb: removing data directory "/home/postgres/pgsql/src/test/subscription/tmp_check/t_004_sync_publisher_data/pgdata"
Bail out! system initdb failed

I have never seen this happen before in the TAP tests.

I think the odds are very high that this implies something wrong with
commit c09850992.

My immediate guess after eyeballing that patch quickly is that it was
not a good idea to redefine the rules used by bootstrap/standalone
backends. In particular, it seems somewhat plausible that the bootstrap
process hadn't yet completely died when the standalone backend for the
post-bootstrap phase came along and decided there was a conflict (which
it never would have before).

regards, tom lane

On Wed, May 08, 2019 at 02:32:46PM -0400, Tom Lane wrote:
> Just now, while running a parallel check-world on HEAD according to the
> same script I've been using for quite some time, one of the TAP tests
> died during initdb:
>
> selecting dynamic shared memory implementation ... posix
> selecting default max_connections ... 100
> selecting default shared_buffers ... 128MB
> selecting default timezone ... America/New_York
> creating configuration files ... ok
> running bootstrap script ... ok
> performing post-bootstrap initialization ... 2019-05-08 13:59:19.963 EDT [18351] FATAL: pre-existing shared memory block (key 5440004, ID 1734475802) is still in use
> 2019-05-08 13:59:19.963 EDT [18351] HINT: Terminate any old server processes associated with data directory "/home/postgres/pgsql/src/test/subscription/tmp_check/t_004_sync_publisher_data/pgdata".
> child process exited with exit code 1
> initdb: removing data directory "/home/postgres/pgsql/src/test/subscription/tmp_check/t_004_sync_publisher_data/pgdata"
> Bail out! system initdb failed
>
> I have never seen this happen before in the TAP tests.
>
> I think the odds are very high that this implies something wrong with
> commit c09850992.

The odds are very high that you would not have gotten that error before that
commit. But if the cause matches your guess, it's not something wrong with
the commit ...

> My immediate guess after eyeballing that patch quickly is that it was
> not a good idea to redefine the rules used by bootstrap/standalone
> backends. In particular, it seems somewhat plausible that the bootstrap
> process hadn't yet completely died when the standalone backend for the
> post-bootstrap phase came along and decided there was a conflict (which
> it never would have before).

If so, I would sure try to fix the initdb sequence to not let that happen. I
would not trust such a conflict to be harmless.

What OS, OS version, and filesystem?

At Wed, 8 May 2019 22:54:14 -0700, Noah Misch <noah(at)leadboat(dot)com> wrote in <20190509055414(dot)GB1066859(at)rfd(dot)leadboat(dot)com>
> On Wed, May 08, 2019 at 02:32:46PM -0400, Tom Lane wrote:
> > Just now, while running a parallel check-world on HEAD according to the
> > same script I've been using for quite some time, one of the TAP tests
> > died during initdb:
> >
> > selecting dynamic shared memory implementation ... posix
> > selecting default max_connections ... 100
> > selecting default shared_buffers ... 128MB
> > selecting default timezone ... America/New_York
> > creating configuration files ... ok
> > running bootstrap script ... ok
> > performing post-bootstrap initialization ... 2019-05-08 13:59:19.963 EDT [18351] FATAL: pre-existing shared memory block (key 5440004, ID 1734475802) is still in use
> > 2019-05-08 13:59:19.963 EDT [18351] HINT: Terminate any old server processes associated with data directory "/home/postgres/pgsql/src/test/subscription/tmp_check/t_004_sync_publisher_data/pgdata".
> > child process exited with exit code 1
> > initdb: removing data directory "/home/postgres/pgsql/src/test/subscription/tmp_check/t_004_sync_publisher_data/pgdata"
> > Bail out! system initdb failed
> >
> > I have never seen this happen before in the TAP tests.
> >
> > I think the odds are very high that this implies something wrong with
> > commit c09850992.
>
> The odds are very high that you would not have gotten that error before that
> commit. But if the cause matches your guess, it's not something wrong with
> the commit ...
>
> > My immediate guess after eyeballing that patch quickly is that it was
> > not a good idea to redefine the rules used by bootstrap/standalone
> > backends. In particular, it seems somewhat plausible that the bootstrap
> > process hadn't yet completely died when the standalone backend for the
> > post-bootstrap phase came along and decided there was a conflict (which
> > it never would have before).
>
> If so, I would sure try to fix the initdb sequence to not let that happen. I
> would not trust such a conflict to be harmless.
>
> What OS, OS version, and filesystem?

PGSharedMemoryCreate shows the error in SHMSTATE_ANALYSYS_FAILURE
case. PGSharedMemoryAttach returns the code when, for example,
shmat failed with ENOMEM. I'm afraid that the message is not
shown from SHMSTATE_ATTACHED..

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center

Noah Misch <noah(at)leadboat(dot)com> writes:
> On Wed, May 08, 2019 at 02:32:46PM -0400, Tom Lane wrote:
>> Just now, while running a parallel check-world on HEAD according to the
>> same script I've been using for quite some time, one of the TAP tests
>> died during initdb:
>> performing post-bootstrap initialization ... 2019-05-08 13:59:19.963 EDT [18351] FATAL: pre-existing shared memory block (key 5440004, ID 1734475802) is still in use

> The odds are very high that you would not have gotten that error before that
> commit. But if the cause matches your guess, it's not something wrong with
> the commit ...

Fair point.

> What OS, OS version, and filesystem?

Up-to-date RHEL6 (kernel 2.6.32-754.12.1.el6.x86_64), ext4 over LVM
on spinning rust with an LSI MegaRAID controller in front of it.

Since complaining, I've done half a dozen more parallel check-worlds
without issue, so the error was and still is rare. This matches the
fact that we've not seen it in the buildfarm :-(.

regards, tom lane

I wrote:
> Noah Misch <noah(at)leadboat(dot)com> writes:
>> The odds are very high that you would not have gotten that error before that
>> commit. But if the cause matches your guess, it's not something wrong with
>> the commit ...

> Fair point.

After more study and testing, I no longer believe my original thought
about a bootstrap-to-standalone-backend race condition. The bootstrap
process definitely kills its SysV shmem segment before exiting.

However, I have a new theory, after noticing that c09850992 moved the
check for shm_nattch == 0. Previously, if a shmem segment had zero attach
count, it was unconditionally considered not-a-threat. Now, we'll try
shmat() anyway, and if that fails for any reason other than EACCES, we say
SHMSTATE_ANALYSIS_FAILURE which leads to the described error report.
So I suspect that what we hit was a race condition whereby some other
parallel test was using the same shmem ID and we managed to see its
segment successfully in shmctl but then it was gone by the time we did
shmat. This leads me to think that EINVAL and EIDRM failures from
shmat had better be considered SHMSTATE_ENOENT not
SHMSTATE_ANALYSIS_FAILURE.

In principle this is a longstanding race condition, but I wonder
whether we made it more probable by moving the shm_nattch check.

regards, tom lane

I wrote:
> However, I have a new theory, after noticing that c09850992 moved the
> check for shm_nattch == 0. Previously, if a shmem segment had zero attach
> count, it was unconditionally considered not-a-threat. Now, we'll try
> shmat() anyway, and if that fails for any reason other than EACCES, we say
> SHMSTATE_ANALYSIS_FAILURE which leads to the described error report.
> So I suspect that what we hit was a race condition whereby some other
> parallel test was using the same shmem ID and we managed to see its
> segment successfully in shmctl but then it was gone by the time we did
> shmat. This leads me to think that EINVAL and EIDRM failures from
> shmat had better be considered SHMSTATE_ENOENT not
> SHMSTATE_ANALYSIS_FAILURE.
> In principle this is a longstanding race condition, but I wonder
> whether we made it more probable by moving the shm_nattch check.

Hah --- this is a real race condition, and I can demonstrate it very
easily by inserting a sleep right there, as in the attached
for-testing-only patch.

The particular parallelism level I use is

make -s check-world -j4 PROVE_FLAGS='-j4 --quiet --nocolor --nocount'

on a dual-socket 4-cores-per-socket Xeon machine. With that command and
this patch, I frequently get multiple failures per run, and they all
report either EINVAL or EIDRM.

The patch generally reports that nattch had been 1, so my thought that
that change might've made it worse seems unfounded. But we have
absolutely got a hittable race condition here. The real fix should
be on the order of

if (errno == EACCES)
return SHMSTATE_FOREIGN;
+ else if (errno == EINVAL || errno == EIDRM)
+ return SHMSTATE_ENOENT;
else
return SHMSTATE_ANALYSIS_FAILURE;

(plus comments of course).

regards, tom lane

On Thu, May 09, 2019 at 06:47:58PM -0400, Tom Lane wrote:
> I wrote:
> > However, I have a new theory, after noticing that c09850992 moved the
> > check for shm_nattch == 0. Previously, if a shmem segment had zero attach
> > count, it was unconditionally considered not-a-threat. Now, we'll try
> > shmat() anyway, and if that fails for any reason other than EACCES, we say
> > SHMSTATE_ANALYSIS_FAILURE which leads to the described error report.
> > So I suspect that what we hit was a race condition whereby some other
> > parallel test was using the same shmem ID and we managed to see its
> > segment successfully in shmctl but then it was gone by the time we did
> > shmat. This leads me to think that EINVAL and EIDRM failures from
> > shmat had better be considered SHMSTATE_ENOENT not
> > SHMSTATE_ANALYSIS_FAILURE.
> > In principle this is a longstanding race condition, but I wonder
> > whether we made it more probable by moving the shm_nattch check.
>
> Hah --- this is a real race condition, and I can demonstrate it very
> easily by inserting a sleep right there, as in the attached
> for-testing-only patch.
>
> The particular parallelism level I use is
>
> make -s check-world -j4 PROVE_FLAGS='-j4 --quiet --nocolor --nocount'
>
> on a dual-socket 4-cores-per-socket Xeon machine. With that command and
> this patch, I frequently get multiple failures per run, and they all
> report either EINVAL or EIDRM.
>
> The patch generally reports that nattch had been 1, so my thought that
> that change might've made it worse seems unfounded. But we have
> absolutely got a hittable race condition here. The real fix should
> be on the order of
>
> if (errno == EACCES)
> return SHMSTATE_FOREIGN;
> + else if (errno == EINVAL || errno == EIDRM)
> + return SHMSTATE_ENOENT;
> else
> return SHMSTATE_ANALYSIS_FAILURE;
>
> (plus comments of course).

Looks good. That is basically a defect in commit c09850992; the race passed
from irrelevance to relevance when that commit subjected more segments to the
test. Thanks for diagnosing it.

Noah Misch <noah(at)leadboat(dot)com> writes:
> Looks good. That is basically a defect in commit c09850992; the race passed
> from irrelevance to relevance when that commit subjected more segments to the
> test. Thanks for diagnosing it.

The bug's far older than that, surely, since before c09850992 we treated
*any* shmat failure as meaning we'd better fail. I think you're right
that c09850992 might've made it slightly more probable, but most likely
the bottom line here is just that we haven't been doing parallel
check-worlds a lot until relatively recently. The buildfarm would be
kind of unlikely to hit this I think --- AFAIK it doesn't launch multiple
postmasters using the same port number concurrently. But parallel
invocation of TAP test scripts makes the hazard real.

Will go fix/backpatch in a minute.

regards, tom lane

I wrote:
> Will go fix/backpatch in a minute.

Done now, but while thinking more about the issue, I had an idea: why is
it that we base the shmem key on the postmaster's port number, and not
on the data directory's inode number? Using the port number not only
increases the risk of collisions (though admittedly only in testing
situations), but it *decreases* our ability to detect real conflicts.
Consider case where DBA wants to change the installation's port number,
and he edits postgresql.conf, but then uses "kill -9 && rm postmaster.pid"
rather than some saner way of stopping the old postmaster. When he
starts the new one, it won't detect any remaining children of the old
postmaster because it'll be looking in the wrong range of shmem keys.
It seems like something tied to the data directory's identity would
be much more trustworthy.

I think the reason for doing it this way originally was to allow
one to identify which shmem segment is which in "ipcs -m" output.
But that was back when having to clean up shmem segments manually
was still a common task. It's been a long time since I can remember
needing to figure out which was which.

regards, tom lane

On Fri, May 10, 2019 at 04:46:40PM -0400, Tom Lane wrote:
> I wrote:
> > Will go fix/backpatch in a minute.
>
> Done now, but while thinking more about the issue, I had an idea: why is
> it that we base the shmem key on the postmaster's port number, and not
> on the data directory's inode number? Using the port number not only
> increases the risk of collisions (though admittedly only in testing
> situations), but it *decreases* our ability to detect real conflicts.
> Consider case where DBA wants to change the installation's port number,
> and he edits postgresql.conf, but then uses "kill -9 && rm postmaster.pid"
> rather than some saner way of stopping the old postmaster. When he
> starts the new one, it won't detect any remaining children of the old
> postmaster because it'll be looking in the wrong range of shmem keys.
> It seems like something tied to the data directory's identity would
> be much more trustworthy.

Good point. Since we now ignore (SHMSTATE_FOREIGN) any segment that bears
(st_dev,st_ino) not matching $PGDATA, the change you describe couldn't make us
fail to detect a real conflict or miss a cleanup opportunity. It would reduce
the ability to test sysv_shmem.c; I suppose one could add a debug GUC to
override the start of the key space.

> I think the reason for doing it this way originally was to allow
> one to identify which shmem segment is which in "ipcs -m" output.
> But that was back when having to clean up shmem segments manually
> was still a common task. It's been a long time since I can remember
> needing to figure out which was which.

I don't see that presenting a problem these days, agreed.

Noah Misch <noah(at)leadboat(dot)com> writes:
> On Fri, May 10, 2019 at 04:46:40PM -0400, Tom Lane wrote:
>> Done now, but while thinking more about the issue, I had an idea: why is
>> it that we base the shmem key on the postmaster's port number, and not
>> on the data directory's inode number? Using the port number not only
>> increases the risk of collisions (though admittedly only in testing
>> situations), but it *decreases* our ability to detect real conflicts.
>> Consider case where DBA wants to change the installation's port number,
>> and he edits postgresql.conf, but then uses "kill -9 && rm postmaster.pid"
>> rather than some saner way of stopping the old postmaster. When he
>> starts the new one, it won't detect any remaining children of the old
>> postmaster because it'll be looking in the wrong range of shmem keys.
>> It seems like something tied to the data directory's identity would
>> be much more trustworthy.

> Good point. Since we now ignore (SHMSTATE_FOREIGN) any segment that bears
> (st_dev,st_ino) not matching $PGDATA, the change you describe couldn't make us
> fail to detect a real conflict or miss a cleanup opportunity. It would reduce
> the ability to test sysv_shmem.c; I suppose one could add a debug GUC to
> override the start of the key space.

Attached is a draft patch to change both shmem and sema key selection
to be based on data directory inode rather than port.

I considered using "st_ino ^ st_dev", or some such, but decided that
that would largely just make it harder to manually correlate IPC
keys with running postmasters. It's generally easy to find out the
data directory inode number with "ls", but the extra work to find out
and XOR in the device number is not so easy, and it's not clear what
it'd buy us in typical scenarios.

The Windows code seems fine as-is: it's already using data directory
name, not port, to set up shmem, and it doesn't need anything for
semaphores.

I'm not quite sure what's going on in src/test/recovery/t/017_shm.pl.
As expected, the test for port number non-collision no longer sees
a failure. After fixing that, the test passes, but it takes a
ridiculously long time (minutes); apparently each postmaster start/stop
cycle takes much longer than it ought to. I suppose this patch is
breaking its assumptions, but I've not studied it. We'd have to do
something about that before this would be committable.

I'll add this to the next commitfest.

regards, tom lane

On 2019-08-14 01:22, Tom Lane wrote:
> Attached is a draft patch to change both shmem and sema key selection
> to be based on data directory inode rather than port.
>
> I considered using "st_ino ^ st_dev", or some such, but decided that
> that would largely just make it harder to manually correlate IPC
> keys with running postmasters. It's generally easy to find out the
> data directory inode number with "ls", but the extra work to find out
> and XOR in the device number is not so easy, and it's not clear what
> it'd buy us in typical scenarios.

For the POSIX APIs where the numbers are just converted to a string, why
not use both -- or forget about the inodes and use the actual data
directory string.

For the SYSV APIs, the scenario that came to my mind is if someone
starts a bunch of servers each on their own mount, it could happen that
the inodes of the data directories are very similar.

There is also the issue that AFAICT the key_t in the SYSV APIs is always
32-bit whereas inodes are 64-bit. Probably not a big deal, but it might
prevent an exact one-to-one mapping.

Of course, ftok() is also available here as an existing solution.

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

Peter Eisentraut <peter(dot)eisentraut(at)2ndquadrant(dot)com> writes:
> On 2019-08-14 01:22, Tom Lane wrote:
>> Attached is a draft patch to change both shmem and sema key selection
>> to be based on data directory inode rather than port.

> For the POSIX APIs where the numbers are just converted to a string, why
> not use both -- or forget about the inodes and use the actual data
> directory string.

Considering that we still need an operation equivalent to "nextSemKey++"
(in case of a key collision), I'm not really sure how working with strings
rather than ints would make life better.

> For the SYSV APIs, the scenario that came to my mind is if someone
> starts a bunch of servers each on their own mount, it could happen that
> the inodes of the data directories are very similar.

Sure. That's why I didn't throw away any of the duplicate-key-handling
logic, and why we're still checking for st_dev match when inspecting
particular shmem blocks. (It also seems likely that somebody
who's doing that would be using similar pathnames on the different
mounts, so that string-based approaches wouldn't exactly be free of
collision problems either.)

> There is also the issue that AFAICT the key_t in the SYSV APIs is always
> 32-bit whereas inodes are 64-bit. Probably not a big deal, but it might
> prevent an exact one-to-one mapping.

True, although the width of inode numbers is probably pretty platform-
and filesystem-dependent. We could consider trying some more complicated
mapping like xor'ing high and low halves, but I don't entirely see what
it buys us.

> Of course, ftok() is also available here as an existing solution.

I looked at that briefly, but I don't really see what it'd buy us either,
except for opacity which doesn't seem useful. The Linux man page pretty
much says in so many words that it's a wrapper for st_ino and st_dev;
and how does it help us if other platforms do it differently?

(Actually, if Linux does it the way the man page suggests, it'd really
be a net negative, because there'd only be 24 bits of key variation
not 32.)

regards, tom lane

I agree with this patch and the reasons for it.

A related point, perhaps we should change the key printed into
postmaster.pid to be in hexadecimal format ("0x08x") so that it matches
what ipcs prints.

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

Peter Eisentraut <peter(dot)eisentraut(at)2ndquadrant(dot)com> writes:
> I agree with this patch and the reasons for it.

OK, thanks for reviewing.

> A related point, perhaps we should change the key printed into
> postmaster.pid to be in hexadecimal format ("0x08x") so that it matches
> what ipcs prints.

Hmm, that depends on whose ipcs you use :-(. A quick survey
of my machines says it's

key shmid

Linux: hex decimal
FreeBSD: decimal decimal
NetBSD: decimal decimal
OpenBSD: decimal decimal
macOS: hex decimal
HPUX: hex (not printed)

There's certainly room to argue that hex+decimal is most popular,
but I'm not sure that that outweighs possible compatibility issues
from changing postmaster.pid contents. (Admittedly, it's not real
clear that anything would be paying attention to the shmem key,
so maybe there's no compatibility issue.)

If we did want to assume that we could change postmaster.pid,
it might be best to print the key both ways?

regards, tom lane

I wrote:
> Attached is a draft patch to change both shmem and sema key selection
> to be based on data directory inode rather than port.
> ...
> I'm not quite sure what's going on in src/test/recovery/t/017_shm.pl.
> As expected, the test for port number non-collision no longer sees
> a failure. After fixing that, the test passes, but it takes a
> ridiculously long time (minutes); apparently each postmaster start/stop
> cycle takes much longer than it ought to. I suppose this patch is
> breaking its assumptions, but I've not studied it.

After looking closer, the problem is pretty obvious: the initial
loop is trying to create a cluster whose shmem key matches its
port-number-based expectation. With this code, that will never
happen except by unlikely accident, so it wastes time with repeated
initdb/start/stop attempts. After 100 tries it gives up and presses
on with the test, resulting in the apparent pass with long runtime.

I now understand the point you made upthread that this test could
only be preserved if we invent some way to force the choice of shmem
key. While it wouldn't be hard to do that (say, invent a magic
environment variable), I really don't want to do so. In the field,
such a behavior would have no positive use, and it could destroy our
newly-improved guarantees about detecting conflicting old processes.

However, there's another way to skin this cat. We can have the
Perl test script create a conflicting shmem segment directly,
as in the attached second-draft patch. I simplified the test
script quite a bit, since I don't see any particular value in
creating more than one test postmaster with this approach.

This still isn't committable as-is, since the test will just curl up
and die on machines lacking IPC::SharedMem. (It could be rewritten
to rely only on the lower-level IPC::SysV module, but I doubt that's
worth the trouble, since either way it'd fail on Windows.) I'm not
sure whether we should just not bother to run the test at all, or
if we should run it but skip the IPC-related parts; and my Perl-fu
isn't really up to implementing either behavior.

Another thing that might be interesting is to do more than just create
the conflicting segment, ie, try to put some data into it that would
fool the postmaster. I'm not excited about that at all, but maybe
someone else is?

The attached patch is identical to the previous one except for the
changes in src/test/recovery/t/017_shm.pl.

regards, tom lane

I wrote:
> This still isn't committable as-is, since the test will just curl up
> and die on machines lacking IPC::SharedMem.

After a bit of research, here's a version that takes a stab at fixing
that. There may be cleaner ways to do it, but this successfully skips
the test if it can't import the needed IPC modules.

This also fixes a problem that the previous script had with leaking
a shmem segment. That's due to something that could be considered
a pre-existing bug, which is that if we use shmem key X+1, and the
postmaster crashes, and the next start is able to get shmem key X,
we don't clean up the shmem segment at X+1. In principle, we could
note from the contents of postmaster.pid that X+1 was used before and
try to remove it. In practice, I doubt this is worth worrying about
given how small the shmem segments are now, and the very low probability
of key collisions in the new regime. Anyway it would be material for
a different patch.

I think this could be considered committable, but if anyone wants to
improve the test script, step right up.

regards, tom lane

On 2019-09-04 16:59, Tom Lane wrote:
>> A related point, perhaps we should change the key printed into
>> postmaster.pid to be in hexadecimal format ("0x08x") so that it matches
>> what ipcs prints.
> Hmm, that depends on whose ipcs you use :-(. A quick survey
> of my machines says it's
>
> key shmid
>
> Linux: hex decimal
> FreeBSD: decimal decimal
> NetBSD: decimal decimal
> OpenBSD: decimal decimal
> macOS: hex decimal
> HPUX: hex (not printed)
>
> There's certainly room to argue that hex+decimal is most popular,
> but I'm not sure that that outweighs possible compatibility issues
> from changing postmaster.pid contents. (Admittedly, it's not real
> clear that anything would be paying attention to the shmem key,
> so maybe there's no compatibility issue.)

Let's just leave it decimal then. At least then it's easier to compare
it to ls -i output.

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