Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1Wrci2-0002TQ-BH for pgsql-admin@arkaria.postgresql.org; Tue, 03 Jun 2014 00:36:10 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.80) (envelope-from ) id 1Wrci1-0008DO-Qr for pgsql-admin@arkaria.postgresql.org; Tue, 03 Jun 2014 00:36:09 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.2:DHE_RSA_AES_256_CBC_SHA256:256) (Exim 4.80) (envelope-from ) id 1Wrchz-0008D7-Kz for pgsql-admin@postgresql.org; Tue, 03 Jun 2014 00:36:07 +0000 Received: from mail.journyx.com ([209.163.206.41] helo=mail.int.journyx.com) by magus.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1Wrcho-0004uk-Rs for pgsql-admin@postgresql.org; Tue, 03 Jun 2014 00:36:05 +0000 Received: from localhost (localhost [127.0.0.1]) by mail.int.journyx.com (Postfix) with ESMTP id C41A230008A for ; Mon, 2 Jun 2014 19:35:53 -0500 (CDT) Received: from mail.int.journyx.com ([127.0.0.1]) by localhost (mail.int.journyx.com [127.0.0.1]) (amavisd-new, port 10032) with ESMTP id 47o2eFVJGhzf; Mon, 2 Jun 2014 19:35:43 -0500 (CDT) Received: from localhost (localhost [127.0.0.1]) by mail.int.journyx.com (Postfix) with ESMTP id 9267B300079; Mon, 2 Jun 2014 19:35:43 -0500 (CDT) X-Virus-Scanned: amavisd-new at mail.int.journyx.com Received: from mail.int.journyx.com ([127.0.0.1]) by localhost (mail.int.journyx.com [127.0.0.1]) (amavisd-new, port 10026) with ESMTP id anfL20hZvY-p; Mon, 2 Jun 2014 19:35:43 -0500 (CDT) Received: from mail.int.journyx.com (zimbra.int.journyx.com [192.168.100.5]) by mail.int.journyx.com (Postfix) with ESMTP id 46EBA300077; Mon, 2 Jun 2014 19:35:43 -0500 (CDT) Date: Mon, 2 Jun 2014 19:35:43 -0500 (CDT) From: Scott Whitney Reply-To: Scott Whitney To: Scott Whitney Cc: postgres admin Message-ID: <196857337.1802139.1401755743114.JavaMail.zimbra@mail.int.journyx.com> In-Reply-To: <1909414898.1801998.1401752951465.JavaMail.zimbra@mail.int.journyx.com> References: <1909414898.1801998.1401752951465.JavaMail.zimbra@mail.int.journyx.com> Subject: Re: Failing replication MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="----=_Part_1802138_216715007.1401755743112" X-Originating-IP: [192.168.100.1] X-Mailer: Zimbra 8.0.6_GA_5922 (ZimbraWebClient - GC35 (Win)/8.0.6_GA_5922) Thread-Topic: Failing replication Thread-Index: AVd0YC83JzJEJkFsainVUVvfRJwu1MT6kXmH X-Pg-Spam-Score: -2.5 (--) List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-admin Precedence: bulk Sender: pgsql-admin-owner@postgresql.org ------=_Part_1802138_216715007.1401755743112 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit rsync has completed. Cascading (#3 -> #1 via #2) is up and running again. Log as of now: LOG: consistent recovery state reached at 31C/1C979FD8 LOG: database system is ready to accept read only connections LOG: record with zero length at 31C/1CCDF680 LOG: streaming replication successfully connected to primary === me....it's working 7:29 pm === scott again...restarting pg -> db01 at 6/2/14 7:33 just to see what happens. LOG: database system was shut down in recovery at 2014-06-02 19:34:07 CDT LOG: entering standby mode LOG: redo starts at 31C/1F443578 LOG: consistent recovery state reached at 31C/20278980 LOG: record with incorrect prev-link 319/60278768 at 31C/20278980 LOG: database system is ready to accept read only connections LOG: streaming replication successfully connected to primary ----- Original Message ----- > So, I have 3 servers: > 1) Production. > 2) "Production" training server. Replicates #1. At same data center. 2 > postmasters on separate ports. > 3) Internal "production" server. 3 postmasters on separate ports. Replicates > #2 and #1 (both from #2). > This has happened to me several times in the past few weeks. > From #3: > LOG: entering standby mode > LOG: redo starts at 31B/FDFFC0D8 > WARNING: page 7843 of relation base/25999670/33421425 is uninitialized > PANIC: WAL contains references to invalid pages > LOG: startup process (PID 4580) was terminated by signal 6: Aborted > LOG: terminating any other active server processes > === > here is me restarting...adding this since there are no timestamps in this > log... > === > LOG: database system was interrupted while in recovery at log time 2014-06-02 > 17:31:05 CDT > HINT: If this has occurred more than once some data might be corrupted and > you might need to choose an earlier recovery target. > LOG: entering standby mode > LOG: redo starts at 31B/FDFFC0D8 > WARNING: page 7843 of relation base/25999670/33421425 is uninitialized > PANIC: WAL contains references to invalid pages > LOG: startup process (PID 4838) was terminated by signal 6: Aborted > LOG: terminating any other active server processes > There is no activity in #2's pg_log postgresql-Mon.log file consummate to > this event. > I have wal segments keeping 1,000. I have pg_xlog files dated yesterday. > This happened earlier today as well. It happened twice last week. > The "warning page" stuff is different from the pg_controldata stuff earlier > today. > Here is pg_controldata from server 3 wrt server 1 replication. > pg_control version number: 922 > Catalog version number: 201204301 > Database system identifier: 5868266298097360799 > Database cluster state: in archive recovery > pg_control last modified: Mon Jun 2 18:42:18 2014 > Latest checkpoint location: 31B/FE08DB50 > Prior checkpoint location: 31B/FE08DB50 > Latest checkpoint's REDO location: 31B/FDFFC0D8 > Latest checkpoint's TimeLineID: 1 > Latest checkpoint's full_page_writes: on > Latest checkpoint's NextXID: 0/441709396 > Latest checkpoint's NextOID: 33432042 > Latest checkpoint's NextMultiXactId: 28077 > Latest checkpoint's NextMultiOffset: 57507 > Latest checkpoint's oldestXID: 241800232 > Latest checkpoint's oldestXID's DB: 16573 > Latest checkpoint's oldestActiveXID: 441709396 > Time of latest checkpoint: Mon Jun 2 17:31:05 2014 > Minimum recovery ending location: 31C/4E1C18 > Backup start location: 0/0 > Backup end location: 0/0 > End-of-backup record required: no > Current wal_level setting: hot_standby > Current max_connections setting: 4000 > Current max_prepared_xacts setting: 0 > Current max_locks_per_xact setting: 64 > Maximum data alignment: 8 > Database block size: 8192 > Blocks per segment of large relation: 131072 > WAL block size: 8192 > Bytes per WAL segment: 16777216 > Maximum length of identifiers: 64 > Maximum columns in an index: 32 > Maximum size of a TOAST chunk: 1996 > Date/time type storage: 64-bit integers > Float4 argument passing: by value > Float8 argument passing: by value > I have to redo the base backup and bring it back up again, so the rest of the > stuff is about to be rsycnhed awak, but it has now failed twice today. It > might well, again. > What more should I provide to try to find a solution? > Server 2 -> 1 replication has no issues. > Server 3 -> 2 (replicating server 1) is the one that's failing. > 65Mbps line between them. > PG 9.28 across the board on Centos 6.5 64bit all across. ------=_Part_1802138_216715007.1401755743112 Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: quoted-printable
rsync has completed. Cascading (= #3 -> #1 via #2) is up and running again.

Log a= s of now:

LOG: consistent recovery state reached at 31C/1C979FD8LOG: database system is ready to accept read only connections
LOG: reco= rd with zero length at 31C/1CCDF680
LOG: streaming replication successfu= lly connected to primary

=3D=3D=3D me....it's working 7:29 pm
=3D=3D=3D scott again...= restarting pg -> db01 at 6/2/14 7:33 just to see what happens.

LOG: database system was shut down in recovery at 2014-06-02 19:3= 4:07 CDT



So, I h= ave 3 servers:

1) Production.
2) "Produc= tion" training server. Replicates #1. At same data center. 2 postmasters on= separate ports.
3) Internal "production" server. 3 postmasters o= n separate ports. Replicates #2 and #1 (both from #2). 

=
This has happened to me several times in the past few weeks.

From  #3:

LO= G: entering standby mode
LOG: redo starts at 31B/FDFFC0D8
WARNING: pa= ge 7843 of relation base/25999670/33421425 is uninitialized
PANIC: WAL c= ontains references to invalid pages
LOG: startup process (PID 4580) was = terminated by signal 6: Aborted
LOG: terminating any other active server= processes


= =3D=3D=3D

here is me restarting...adding this = since there are no timestamps in this log...

= =3D=3D=3D


LOG: database system was interru= pted while in recovery at log time 2014-06-02 17:31:05 CDT
HINT: If this= has occurred more than once some data might be corrupted and you might nee= d to choose an earlier recovery target.
LOG: entering standby mode
LO= G: redo starts at 31B/FDFFC0D8
WARNING: page 7843 of relation base/25999= 670/33421425 is uninitialized
PANIC: WAL contains references to invalid = pages
LOG: startup process (PID 4838) was terminated by signal 6: Aborte= d
LOG: terminating any other active server processes



There is no activity in #2's pg_log 

I have wal segments keeping 1,= 000. I have pg_xlog files dated yesterday.


This happened earlier today as well. It= happened twice last week.


The "warning page" stuff is different from the pg_con= troldata stuff earlier today.


Here is pg_controldata from server 3 wrt server 1 re= plication.


pg_control version number: 922
= Catalog version number: 201204301
Database system identifier: 5868266298= 097360799
Database cluster state: in archive recovery
pg_control last= modified: Mon Jun 2 18:42:18 2014
Latest checkpoint location: 31B/FE08D= B50
Prior checkpoint location: 31B/FE08DB50
Latest checkpoint's REDO = location: 31B/FDFFC0D8
Latest checkpoint's TimeLineID: 1
Latest check= point's full_page_writes: on
Latest checkpoint's NextXID: 0/441709396Latest checkpoint's NextOID: 33432042
Latest checkpoint's NextMultiXact= Id: 28077
Latest checkpoint's NextMultiOffset: 57507
Latest checkpoin= t's oldestXID: 241800232
Latest checkpoint's oldestXID's DB: 16573
La= test checkpoint's oldestActiveXID: 441709396
Time of latest checkpoint: = Mon Jun 2 17:31:05 2014
Minimum recovery ending location: 31C/4E1C18
= Backup start location: 0/0
Backup end location: 0/0
End-of-backup rec= ord required: no
Current wal_level setting: hot_standby
Current max_c= onnections setting: 4000
Current max_prepared_xacts setting: 0
Curren= t max_locks_per_xact setting: 64
Maximum data alignment: 8
Database b= lock size: 8192
Blocks per segment of large relation: 131072
WAL bloc= k size: 8192
Bytes per WAL segment: 16777216
Maximum length of identi= fiers: 64
Maximum columns in an index: 32
Maximum size of a TOAST chu= nk: 1996
Date/time type storage: 64-bit integers
Float4 argument pass= ing: by value
Float8 argument passing: by value


I have to redo the base backup and b= ring it back up again, so the rest of the stuff is about to be rsycnhed awa= k, but it has now failed twice today. It might well, again.


What more should I provide = to try to find a solution?


Server 2 -> 1 replication has no issues.

Server 3 -> 2 (replicating server 1) is the one that's fail= ing.

65Mbps line between them.


PG 9.28 across the board on= Centos 6.5 64bit all across.





------=_Part_1802138_216715007.1401755743112--