Обсуждение: Hot Standby Not So Hot Anymore

On Mon, Nov 5, 2012 at 7:40 PM, Ian Harding <harding.ian@gmail.com> wrote:
> I had a 9.0.8 hot standby setup, one master, two slaves, working great.
> Then, I tried to re-initialize by making a base backup, the way I've done it
> many times before, but for some reason I can't get the standby to accept
> connections.  I copied the postgresql.conf and recorvery.conf out of the
> way, cleaned the data directory and extracted the backup files, then
> replaced the conf files.  Everything works perfectly, but I keep getting
> :FATAL:  the database system is starting up
>
> I know I'm an idiot and that I did something wrong but I can't find it.
>
> [root@db03 data]# grep standby postgresql.conf
> wal_level = hot_standby            # minimal, archive, or hot_standby
> hot_standby = on        # "on" allows queries during recovery
> max_standby_archive_delay = -1    # max delay before canceling queries
> max_standby_streaming_delay = -1    # max delay before canceling queries
>
> [root@db03 data]# grep standby recovery.conf
> # Specifies whether to start the server as a standby. In streaming
> replication,
> standby_mode          = 'on'
> # Specifies a connection string which is used for the standby server to
> connect
>
> [root@db03 data]# ps aux | grep stream
> postgres 62127  0.1  0.0 34554356 3724 ?       Ss   16:22   0:16 postgres:
> wal receiver process   streaming BA7/12B87818
>
>
> [root@db03 data]# ps aux | grep startup
> postgres 62122  0.5  0.9 34545900 1223708 ?    Ss   16:22   1:03 postgres:
> startup process   recovering 0000000100000BA700000012
>
> Any suggestions appreciated!!!

What's your log have to say?

On Mon, Nov 5, 2012 at 7:49 PM, Ian Harding <harding.ian@gmail.com> wrote:
>
>
> On Mon, Nov 5, 2012 at 7:46 PM, Lonni J Friedman <netllama@gmail.com> wrote:
>>
>> On Mon, Nov 5, 2012 at 7:40 PM, Ian Harding <harding.ian@gmail.com> wrote:
>> > I had a 9.0.8 hot standby setup, one master, two slaves, working great.
>> > Then, I tried to re-initialize by making a base backup, the way I've
>> > done it
>> > many times before, but for some reason I can't get the standby to accept
>> > connections.  I copied the postgresql.conf and recorvery.conf out of the
>> > way, cleaned the data directory and extracted the backup files, then
>> > replaced the conf files.  Everything works perfectly, but I keep getting
>> > :FATAL:  the database system is starting up
>> >
>> > I know I'm an idiot and that I did something wrong but I can't find it.
>> >
>> > [root@db03 data]# grep standby postgresql.conf
>> > wal_level = hot_standby            # minimal, archive, or hot_standby
>> > hot_standby = on        # "on" allows queries during recovery
>> > max_standby_archive_delay = -1    # max delay before canceling queries
>> > max_standby_streaming_delay = -1    # max delay before canceling queries
>> >
>> > [root@db03 data]# grep standby recovery.conf
>> > # Specifies whether to start the server as a standby. In streaming
>> > replication,
>> > standby_mode          = 'on'
>> > # Specifies a connection string which is used for the standby server to
>> > connect
>> >
>> > [root@db03 data]# ps aux | grep stream
>> > postgres 62127  0.1  0.0 34554356 3724 ?       Ss   16:22   0:16
>> > postgres:
>> > wal receiver process   streaming BA7/12B87818
>> >
>> >
>> > [root@db03 data]# ps aux | grep startup
>> > postgres 62122  0.5  0.9 34545900 1223708 ?    Ss   16:22   1:03
>> > postgres:
>> > startup process   recovering 0000000100000BA700000012
>> >
>> > Any suggestions appreciated!!!
>>
>> What's your log have to say?
>
>
> It says everything is happy as normal...
>
> 2012-11-05 16:22:38.744 PST -  :LOG:  database system was shut down in
> recovery at 2012-11-05 16:22:33 PST
> 2012-11-05 16:22:38.745 PST -  :LOG:  entering standby mode
> 2012-11-05 16:22:38.746 PST -  :LOG:  redo starts at BA5/F96F86A8
> 2012-11-05 16:22:38.762 PST - postgres :FATAL:  the database system is
> starting up
> 2012-11-05 16:22:39.764 PST - postgres :FATAL:  the database system is
> starting up
> 2012-11-05 16:22:40.766 PST - postgres :FATAL:  the database system is
> starting up
> 2012-11-05 16:22:41.200 PST -  :LOG:  invalid record length at BA6/6DCBA48
> 2012-11-05 16:22:41.206 PST -  :LOG:  streaming replication successfully
> connected to primary
>
>
> This is after I stopped and restarted... after that just more failed
> connection attempts.

Are you sure that its not still recovering?  In other words, when you
look at the 'ps' output do the 'wal receiver process' and 'recovering'
entries change?

On Mon, Nov 5, 2012 at 8:13 PM, Ian Harding <harding.ian@gmail.com> wrote:
>
>
>
> On Mon, Nov 5, 2012 at 7:57 PM, Lonni J Friedman <netllama@gmail.com> wrote:
>>
>> On Mon, Nov 5, 2012 at 7:49 PM, Ian Harding <harding.ian@gmail.com> wrote:
>> >
>> >
>> > On Mon, Nov 5, 2012 at 7:46 PM, Lonni J Friedman <netllama@gmail.com>
>> > wrote:
>> >>
>> >> On Mon, Nov 5, 2012 at 7:40 PM, Ian Harding <harding.ian@gmail.com>
>> >> wrote:
>> >> > I had a 9.0.8 hot standby setup, one master, two slaves, working
>> >> > great.
>> >> > Then, I tried to re-initialize by making a base backup, the way I've
>> >> > done it
>> >> > many times before, but for some reason I can't get the standby to
>> >> > accept
>> >> > connections.  I copied the postgresql.conf and recorvery.conf out of
>> >> > the
>> >> > way, cleaned the data directory and extracted the backup files, then
>> >> > replaced the conf files.  Everything works perfectly, but I keep
>> >> > getting
>> >> > :FATAL:  the database system is starting up
>> >> >
>> >> > I know I'm an idiot and that I did something wrong but I can't find
>> >> > it.
>> >> >
>> >> > [root@db03 data]# grep standby postgresql.conf
>> >> > wal_level = hot_standby            # minimal, archive, or hot_standby
>> >> > hot_standby = on        # "on" allows queries during recovery
>> >> > max_standby_archive_delay = -1    # max delay before canceling
>> >> > queries
>> >> > max_standby_streaming_delay = -1    # max delay before canceling
>> >> > queries
>> >> >
>> >> > [root@db03 data]# grep standby recovery.conf
>> >> > # Specifies whether to start the server as a standby. In streaming
>> >> > replication,
>> >> > standby_mode          = 'on'
>> >> > # Specifies a connection string which is used for the standby server
>> >> > to
>> >> > connect
>> >> >
>> >> > [root@db03 data]# ps aux | grep stream
>> >> > postgres 62127  0.1  0.0 34554356 3724 ?       Ss   16:22   0:16
>> >> > postgres:
>> >> > wal receiver process   streaming BA7/12B87818
>> >> >
>> >> >
>> >> > [root@db03 data]# ps aux | grep startup
>> >> > postgres 62122  0.5  0.9 34545900 1223708 ?    Ss   16:22   1:03
>> >> > postgres:
>> >> > startup process   recovering 0000000100000BA700000012
>> >> >
>> >> > Any suggestions appreciated!!!
>> >>
>> >> What's your log have to say?
>> >
>> >
>> > It says everything is happy as normal...
>> >
>> > 2012-11-05 16:22:38.744 PST -  :LOG:  database system was shut down in
>> > recovery at 2012-11-05 16:22:33 PST
>> > 2012-11-05 16:22:38.745 PST -  :LOG:  entering standby mode
>> > 2012-11-05 16:22:38.746 PST -  :LOG:  redo starts at BA5/F96F86A8
>> > 2012-11-05 16:22:38.762 PST - postgres :FATAL:  the database system is
>> > starting up
>> > 2012-11-05 16:22:39.764 PST - postgres :FATAL:  the database system is
>> > starting up
>> > 2012-11-05 16:22:40.766 PST - postgres :FATAL:  the database system is
>> > starting up
>> > 2012-11-05 16:22:41.200 PST -  :LOG:  invalid record length at
>> > BA6/6DCBA48
>> > 2012-11-05 16:22:41.206 PST -  :LOG:  streaming replication successfully
>> > connected to primary
>> >
>> >
>> > This is after I stopped and restarted... after that just more failed
>> > connection attempts.
>>
>> Are you sure that its not still recovering?  In other words, when you
>> look at the 'ps' output do the 'wal receiver process' and 'recovering'
>> entries change?
>
>
> Yeah, it's still recovering.  In normal operation it keeps right on
> recovering, it's just that it used to accept read-only connections...

Is the 2nd slave also experiencing this problem?  If not, is it
further ahead than the bad one?

On Mon, Nov 5, 2012 at 8:31 PM, Ian Harding <harding.ian@gmail.com> wrote:
>
>
>
> On Mon, Nov 5, 2012 at 8:15 PM, Lonni J Friedman <netllama@gmail.com> wrote:
>>
>> On Mon, Nov 5, 2012 at 8:13 PM, Ian Harding <harding.ian@gmail.com> wrote:
>> >
>> >
>> >
>> > On Mon, Nov 5, 2012 at 7:57 PM, Lonni J Friedman <netllama@gmail.com>
>> > wrote:
>> >>
>> >> On Mon, Nov 5, 2012 at 7:49 PM, Ian Harding <harding.ian@gmail.com>
>> >> wrote:
>> >> >
>> >> >
>> >> > On Mon, Nov 5, 2012 at 7:46 PM, Lonni J Friedman <netllama@gmail.com>
>> >> > wrote:
>> >> >>
>> >> >> On Mon, Nov 5, 2012 at 7:40 PM, Ian Harding <harding.ian@gmail.com>
>> >> >> wrote:
>> >> >> > I had a 9.0.8 hot standby setup, one master, two slaves, working
>> >> >> > great.
>> >> >> > Then, I tried to re-initialize by making a base backup, the way
>> >> >> > I've
>> >> >> > done it
>> >> >> > many times before, but for some reason I can't get the standby to
>> >> >> > accept
>> >> >> > connections.  I copied the postgresql.conf and recorvery.conf out
>> >> >> > of
>> >> >> > the
>> >> >> > way, cleaned the data directory and extracted the backup files,
>> >> >> > then
>> >> >> > replaced the conf files.  Everything works perfectly, but I keep
>> >> >> > getting
>> >> >> > :FATAL:  the database system is starting up
>> >> >> >
>> >> >> > I know I'm an idiot and that I did something wrong but I can't
>> >> >> > find
>> >> >> > it.
>> >> >> >
>> >> >> > [root@db03 data]# grep standby postgresql.conf
>> >> >> > wal_level = hot_standby            # minimal, archive, or
>> >> >> > hot_standby
>> >> >> > hot_standby = on        # "on" allows queries during recovery
>> >> >> > max_standby_archive_delay = -1    # max delay before canceling
>> >> >> > queries
>> >> >> > max_standby_streaming_delay = -1    # max delay before canceling
>> >> >> > queries
>> >> >> >
>> >> >> > [root@db03 data]# grep standby recovery.conf
>> >> >> > # Specifies whether to start the server as a standby. In streaming
>> >> >> > replication,
>> >> >> > standby_mode          = 'on'
>> >> >> > # Specifies a connection string which is used for the standby
>> >> >> > server
>> >> >> > to
>> >> >> > connect
>> >> >> >
>> >> >> > [root@db03 data]# ps aux | grep stream
>> >> >> > postgres 62127  0.1  0.0 34554356 3724 ?       Ss   16:22   0:16
>> >> >> > postgres:
>> >> >> > wal receiver process   streaming BA7/12B87818
>> >> >> >
>> >> >> >
>> >> >> > [root@db03 data]# ps aux | grep startup
>> >> >> > postgres 62122  0.5  0.9 34545900 1223708 ?    Ss   16:22   1:03
>> >> >> > postgres:
>> >> >> > startup process   recovering 0000000100000BA700000012
>> >> >> >
>> >> >> > Any suggestions appreciated!!!
>> >> >>
>> >> >> What's your log have to say?
>> >> >
>> >> >
>> >> > It says everything is happy as normal...
>> >> >
>> >> > 2012-11-05 16:22:38.744 PST -  :LOG:  database system was shut down
>> >> > in
>> >> > recovery at 2012-11-05 16:22:33 PST
>> >> > 2012-11-05 16:22:38.745 PST -  :LOG:  entering standby mode
>> >> > 2012-11-05 16:22:38.746 PST -  :LOG:  redo starts at BA5/F96F86A8
>> >> > 2012-11-05 16:22:38.762 PST - postgres :FATAL:  the database system
>> >> > is
>> >> > starting up
>> >> > 2012-11-05 16:22:39.764 PST - postgres :FATAL:  the database system
>> >> > is
>> >> > starting up
>> >> > 2012-11-05 16:22:40.766 PST - postgres :FATAL:  the database system
>> >> > is
>> >> > starting up
>> >> > 2012-11-05 16:22:41.200 PST -  :LOG:  invalid record length at
>> >> > BA6/6DCBA48
>> >> > 2012-11-05 16:22:41.206 PST -  :LOG:  streaming replication
>> >> > successfully
>> >> > connected to primary
>> >> >
>> >> >
>> >> > This is after I stopped and restarted... after that just more failed
>> >> > connection attempts.
>> >>
>> >> Are you sure that its not still recovering?  In other words, when you
>> >> look at the 'ps' output do the 'wal receiver process' and 'recovering'
>> >> entries change?
>> >
>> >
>> > Yeah, it's still recovering.  In normal operation it keeps right on
>> > recovering, it's just that it used to accept read-only connections...
>>
>> Is the 2nd slave also experiencing this problem?  If not, is it
>> further ahead than the bad one?
>
>
> Everything looks fine (forgot to cc the list...)
>
>
> [root@db0 ~]# ps aux | grep stream
> postgres 45267  0.0  0.0 34546456 3036 ?       Ss   16:22   0:14 postgres:
> wal sender process postgres 192.168.4.4(55925) streaming BA7/5FC1BFD8
> postgres 54247  0.0  0.0 34546456 3036 ?       Ss   18:15   0:07 postgres:
> wal sender process postgres 192.168.4.3(57482) streaming BA7/5FC1BFD8
>

Right, but what I meant was, are both slaves experiencing the same
problem, or just 1?  Did you use the same base backup on both of them,
or did you generate a different one for each slave?

Ian Harding wrote:
> On Mon, Nov 5, 2012 at 7:46 PM, Lonni J Friedman <netllama@gmail.com> wrote:
> It says everything is happy as normal...
>
> 2012-11-05 16:22:41.200 PST -  :LOG:  invalid record length at BA6/6DCBA48

What does this log line mean?  Is that "happy as normal"? -- Darren Duncan

Darren Duncan wrote:
> Ian Harding wrote:

>> It says everything is happy as normal...
>>
>> 2012-11-05 16:22:41.200 PST - :LOG: invalid record length at BA6/6DCBA48
>
> What does this log line mean? Is that "happy as normal"?

Note that the message level is LOG, not WARNING or ERROR or anything
more severe. It found the end of the valid WAL stream in WAL files it
was provided, and it's telling you how it decided it was at the end.

One thing I don't think you've really described is how you took your
base backup. You did follow all the instructions, like using
pg_start_backup() and pg_stop_backup(), excluding the pg_xlog
directory contents, and excluding the postmaster.pid file, right? If
you missed some details there you might see odd behavior.

-Kevin