Assertion failure in walreceiver

I tried to set up a simple master/slave setup and immediately ran into
this assertion failure. The slave is just a cold copy of the database
immediately after initdb. The first WAL segment hasn't been archived
yet. It sees that the first archive fail hasn't been archived yet,
starts up walreceiver but it looks like the start point hasn't been
initialized yet because it hasn't processed any checkpoint WAL records
yet.

$ /usr/local/pgsql/bin/postgres -D /var/tmp/pg85/s/
LOG: database system was shut down at 2010-02-23 14:30:08 GMT
cp: cannot stat `/var/tmp/pg85/w/000000010000000000000000': No such
file or directory
TRAP: FailedAssertion("!(startpoint.xlogid != 0 || startpoint.xrecoff
!= 0)", File: "libpqwalreceiver.c", Line: 87)
LOG: WAL receiver process (PID 3536) was terminated by signal 6: Aborted
LOG: terminating any other active server processes
LOG: startup process (PID 3534) exited with exit code 2
LOG: aborting startup due to startup process failure

--
greg

Did anyone see this? This seems like a pretty grave problem in
streaming replication.

On Tue, Feb 23, 2010 at 2:46 PM, Greg Stark <stark(at)mit(dot)edu> wrote:
> I tried to set up a simple master/slave setup and immediately ran into
> this assertion failure. The slave is just a cold copy of the database
> immediately after initdb. The first WAL segment hasn't been archived
> yet. It sees that the first archive fail hasn't been archived yet,
> starts up walreceiver but it looks like the start point hasn't been
> initialized yet because it hasn't processed any checkpoint WAL records
> yet.
>
> $ /usr/local/pgsql/bin/postgres -D /var/tmp/pg85/s/
> LOG:  database system was shut down at 2010-02-23 14:30:08 GMT
> cp: cannot stat `/var/tmp/pg85/w/000000010000000000000000': No such
> file or directory
> TRAP: FailedAssertion("!(startpoint.xlogid != 0 || startpoint.xrecoff
> != 0)", File: "libpqwalreceiver.c", Line: 87)
> LOG:  WAL receiver process (PID 3536) was terminated by signal 6: Aborted
> LOG:  terminating any other active server processes
> LOG:  startup process (PID 3534) exited with exit code 2
> LOG:  aborting startup due to startup process failure
>
>
> --
> greg
>

--
greg

Greg Stark wrote:
> I tried to set up a simple master/slave setup and immediately ran into
> this assertion failure. The slave is just a cold copy of the database
> immediately after initdb. The first WAL segment hasn't been archived
> yet. It sees that the first archive fail hasn't been archived yet,
> starts up walreceiver but it looks like the start point hasn't been
> initialized yet because it hasn't processed any checkpoint WAL records
> yet.
>
> $ /usr/local/pgsql/bin/postgres -D /var/tmp/pg85/s/
> LOG: database system was shut down at 2010-02-23 14:30:08 GMT
> cp: cannot stat `/var/tmp/pg85/w/000000010000000000000000': No such
> file or directory
> TRAP: FailedAssertion("!(startpoint.xlogid != 0 || startpoint.xrecoff
> != 0)", File: "libpqwalreceiver.c", Line: 87)
> LOG: WAL receiver process (PID 3536) was terminated by signal 6: Aborted
> LOG: terminating any other active server processes
> LOG: startup process (PID 3534) exited with exit code 2
> LOG: aborting startup due to startup process failure

Hmm, interesting corner case. That assertion is checking that the
streaming starting point is initialized correctly, but 0/0 is actually a
valid value when you start streaming from the very first WAL segment.

I guess we can just remove the assertion. If an incorrect zero value
finds its way there due to some bug, nothing particularly bad will
happen; you'll just get an error because the WAL segment most likely
doesn't exist in the primary anymore.

--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com

On Thu, Feb 25, 2010 at 5:29 AM, Heikki Linnakangas
<heikki(dot)linnakangas(at)enterprisedb(dot)com> wrote:
> Hmm, interesting corner case. That assertion is checking that the
> streaming starting point is initialized correctly, but 0/0 is actually a
> valid value when you start streaming from the very first WAL segment.
>
> I guess we can just remove the assertion. If an incorrect zero value
> finds its way there due to some bug, nothing particularly bad will
> happen; you'll just get an error because the WAL segment most likely
> doesn't exist in the primary anymore.

And we need to remove the following code from XLogSend(). This code is
useless now since the initial CopyData message is guaranteed to arrive
at the primary before doing XLogSend().

> /*
> * Invalid position means that we have not yet received the initial
> * CopyData message from the slave that indicates where to start the
> * streaming.
> */
> if (sentPtr.xlogid == 0 &&
> sentPtr.xrecoff == 0)
> return true;

I have one question. Do we support starting an archive recovery and
standby server from a cold backup (not a base backup taken by online
backup)? Though I think they would work and be very useful, I'm not
sure they are safe.

Regards,

--
Fujii Masao
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

Fujii Masao wrote:
> And we need to remove the following code from XLogSend(). This code is
> useless now since the initial CopyData message is guaranteed to arrive
> at the primary before doing XLogSend().
>
>> /*
>> * Invalid position means that we have not yet received the initial
>> * CopyData message from the slave that indicates where to start the
>> * streaming.
>> */
>> if (sentPtr.xlogid == 0 &&
>> sentPtr.xrecoff == 0)
>> return true;

Yeah, good catch.

Committed removal of that and the assertion. You still can't use a copy
of the data directory taken right after initdb, because the initial
checkpoint record has the flag set indicating that archiving is not
enabled. While we're at it, the error message doesn't seem right:

FATAL: recovery connections cannot start because the
recovery_connections parameter is disabled on the WAL source server

recovery_connections is on by default, the real problem is that
archive_command and max_wal_senders are disabled.

> I have one question. Do we support starting an archive recovery and
> standby server from a cold backup (not a base backup taken by online
> backup)? Though I think they would work and be very useful, I'm not
> sure they are safe.

I don't see why not. We support that in PITR, streaming replication is
just another way of getting the logs to the server.

--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com

On Thu, Feb 25, 2010 at 4:31 PM, Heikki Linnakangas
<heikki(dot)linnakangas(at)enterprisedb(dot)com> wrote:
>> I have one question. Do we support starting an archive recovery and
>> standby server from a cold backup (not a base backup taken by online
>> backup)? Though I think they would work and be very useful, I'm not
>> sure they are safe.
>
> I don't see why not. We support that in PITR, streaming replication is
> just another way of getting the logs to the server.

I thought that because, AFAIK, there is no document about initial startup
of PITR from a cold backup. But I'd be happy if it's supported. After
failover happens, previous primary server might be able to become standby
from its old data without taking a new backup from new primary.

Regards,

--
Fujii Masao
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

On Thu, Feb 25, 2010 at 7:31 AM, Heikki Linnakangas
<heikki(dot)linnakangas(at)enterprisedb(dot)com> wrote:
> Committed removal of that and the assertion. You still can't use a copy
> of the data directory taken right after initdb, because the initial
> checkpoint record has the flag set indicating that archiving is not
> enabled. While we're at it, the error message doesn't seem right:
>
> FATAL:  recovery connections cannot start because the
> recovery_connections parameter is disabled on the WAL source server
>
> recovery_connections is on by default, the real problem is that
> archive_command and max_wal_senders are disabled.

Perhaps we need to put these flags in a record on startup. If they're
not set on the checkpoint you start at you check if the next record is
a shutdown and it starts up with the flags set.

I'm not sure that's exactly right as I've never looked at the wal
sequence on shutdown and startup. But it seems like a problem if you
want to start replication, find that archive_mode needs to be set so
you restart your database with it set but then still can't start up
the slave until a checkpoint happens on the master.

--
greg

On Thu, Feb 25, 2010 at 7:31 AM, Heikki Linnakangas
<heikki(dot)linnakangas(at)enterprisedb(dot)com> wrote:
> While we're at it, the error message doesn't seem right:
>
> FATAL:  recovery connections cannot start because the
> recovery_connections parameter is disabled on the WAL source server
>
> recovery_connections is on by default, the real problem is that
> archive_command and max_wal_senders are disabled.

So do I understand this right, if you have archive_mode disabled and
try to start a slave you get this error. Then when you shut down your
master and set archive_mode on and bring it up and try again you'll
*still* get this message because the last checkpoint will be the final
shutdown checkpoint where archive_mode was still disabled?

--
greg

Greg Stark wrote:
> So do I understand this right, if you have archive_mode disabled and
> try to start a slave you get this error. Then when you shut down your
> master and set archive_mode on and bring it up and try again you'll
> *still* get this message because the last checkpoint will be the final
> shutdown checkpoint where archive_mode was still disabled?

Right.

--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com

Greg Stark wrote:
> On Thu, Feb 25, 2010 at 7:31 AM, Heikki Linnakangas
> <heikki(dot)linnakangas(at)enterprisedb(dot)com> wrote:
>> Committed removal of that and the assertion. You still can't use a copy
>> of the data directory taken right after initdb, because the initial
>> checkpoint record has the flag set indicating that archiving is not
>> enabled. While we're at it, the error message doesn't seem right:
>>
>> FATAL: recovery connections cannot start because the
>> recovery_connections parameter is disabled on the WAL source server
>>
>> recovery_connections is on by default, the real problem is that
>> archive_command and max_wal_senders are disabled.
>
> Perhaps we need to put these flags in a record on startup. If they're
> not set on the checkpoint you start at you check if the next record is
> a shutdown and it starts up with the flags set.

Seems reasonable, though if you're unlucky the startup record goes into
the next WAL segment, which might not exist on the standby yet. So I
don't think you can "peek ahead" to see if the record exists, but you
could downgrade the fatal error to a warning, and refrain from opening
for read-only connections until you see the startup record.

--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com