Received: from malur.postgresql.org ([2a02:16a8:dc51::56]) by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.89) (envelope-from ) id 1g9vQw-0000LF-Hp for pgsql-admin@arkaria.postgresql.org; Tue, 09 Oct 2018 17:04:34 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1g9vQs-0006ZG-OQ for pgsql-admin@arkaria.postgresql.org; Tue, 09 Oct 2018 17:04:30 +0000 Received: from makus.postgresql.org ([2001:4800:1501:1::229]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.89) (envelope-from ) id 1g9vQs-0006Xg-5S for pgsql-admin@lists.postgresql.org; Tue, 09 Oct 2018 17:04:30 +0000 Received: from mail-lf1-x143.google.com ([2a00:1450:4864:20::143]) by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1g9vQo-000264-GO for pgsql-admin@postgresql.org; Tue, 09 Oct 2018 17:04:28 +0000 Received: by mail-lf1-x143.google.com with SMTP id w21-v6so1812620lff.6 for ; Tue, 09 Oct 2018 10:04:26 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:references:in-reply-to:from:date:message-id:subject:to; bh=YdO5E6imkZwpTWQegGeATLKHJBwJuDwuEjNOI3rr3Og=; b=LU2bQ4zlRZ40yIaEjtagqyFStYf0RymofPcFJtCe7Z6ou91oMez7wfQf9do/C8VOtC LALXMQk4Dx4PLMq1cucbbGzI1GPkaJI5+eyMZQKBhXUyNycCLbFW1pienp4H2xzjyydO YAOrsocF6CTdNWbKQ3fXolB0nLI3xTa8zGyo1KHk4rkRZmdmx6giN0XPRAib+MiCK8Df XaJ8T6yWii9YQzNqFT0dP8NggBegN50KKhVOLPF9j7p9xi1NBSImFEUC8hxZQeCtO6yw T3RXy1NKbinuFdOqXFekiTKMm+/rHp4/vPH/fcHvTcMxOWq0fU4B5nd1mmCCcJgZIySz 9W7Q== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to; bh=YdO5E6imkZwpTWQegGeATLKHJBwJuDwuEjNOI3rr3Og=; b=paWJLdhNcp9WRSAAFDmLDcgk4zsfT2vCrrW6gG11pABLG0mP7pSUddBZdWqnYJTlvp /503529X5s84bJGzc4Q8dNQZKolvE/kpgEE1Se6bNAvzxqkOj9MhcV5HxdzFnEOhTe9g nbnHs5OfBo+H3wPNU8YzT0OpML7IFFaiePVBgDw+vQFBN0kZc+AA2f1QeNc2d63ICV7a qOteuSvZ+HXtWtWztwRZQ/K3DfOrgrVcYWVoONA76Uu1Ojzl632lYhMhSP79y7xE9dwv zKqgwQRIxRWYuTQBtN4d6qSGbyM1gNMDu6pyfeNu03EXKAwdp4TMOKmelLw20TQucmps vIAw== X-Gm-Message-State: ABuFfoiiaoQEWgjziHtEbyPiQCqpfJHrADaysJt5EEhUdhk5i6z8rC4V CKJ9bpUk66wWr7428YyNUi7925xc97t1uTNZjepnLIcA X-Google-Smtp-Source: ACcGV637TXn2sVoFl4t/wOLtki29+B8t4k1EZxdcQuiaztPwKBkwJ46XsS804VvxBmnP/0sqwC+YnjTUhvkt5FsU0/U= X-Received: by 2002:a19:a7c1:: with SMTP id q184-v6mr15985579lfe.37.1539104664463; Tue, 09 Oct 2018 10:04:24 -0700 (PDT) MIME-Version: 1.0 References: In-Reply-To: From: Mike Broers Date: Tue, 9 Oct 2018 12:04:12 -0500 Message-ID: Subject: Re: root cause of corruption in hot standby To: rui@crazybean.net, pgsql-admin@postgresql.org Content-Type: multipart/alternative; boundary="000000000000cc2f810577ceba58" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk --000000000000cc2f810577ceba58 Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable Ok so I have checksum errors in this replica AGAIN. To remind the list of the scenario: primary 9.5.14 db centos 7.4 ext4 filesystem on vmware in colo hosting environment with ssd san one replica in same colo with same os configuration on hyper-v vm on the same san starts reporting checksum error second replica with same os configuration in AWS does not have this problem. both are connected directly to primary as hot standbys using streaming replication, with a restore command and rsynced archivelogs if streaming falls behind primary xlog. This occurred during times of relatively low activity on the primary, I verified in the log that streaming replication is connected and it isnt happening during the application of an rsync'ed transaction log. Previously it was thought that maybe i was rsyncing transaction logs as they were being written and this was the cause. Im doubting that now and Ive changed the rsync command to base its list on a find with -mmin +10 to avoid rsyncing files unless their mtime is older than 10 minutes. The last time this happened I ran chkdsk (no errors) and even reformatted the volumes. Is there any extensive testing I can do to verify the memory isnt the problem or some other tests to try to determine root cause? Its a hyper-v vm so Im not sure how the virtual hardware abstraction is playing a role. My next step is going to be destroying and recreating the vm, but Im going to have a hard time being confident in the replica environment if I have no idea what is causing this. Many other VMs share the hyperv environment, no other hosts have complained about this kind of problem. Thanks for reading, any guidance is appreciated. On Thu, Sep 20, 2018 at 3:17 PM Mike Broers wrote: > Strange to finally hit the race condition after using this approach for s= o > long on so many different databases but I can accept my understanding was > flawed. Im trying to decide a path to fix this going forward. > > If I switch to using a script to archive, and have the local copy as well > as the rsync in the script, then Im assuming that would be the best way a= s > postgres is only rsyncing AFTER the file has been fully written? > > Something akin to: > archive_command =3D 'cp "%p" /mnt/backup/pgsql/9.5/archive"%f" && rsync -= a > "%p" postgres@destination_host:/mnt/backup/pgsql/archive/"%f"' > > I dont really like the idea of archive_command needing an rsync to succee= d > to rotate through pg_xlogs but perhaps I can wire that in a bash script s= o > it exits with 0 but notifies me in some other way or something.. > > Thanks for commenting Rui! > > On Thu, Sep 20, 2018 at 2:00 PM Rui DeSousa wrote: > >> Hi Mike, >> >> Using rsync on an active file will lead to a =E2=80=9Ccorrupted=E2=80=9D= file; which is >> normal; however, there is a race condition with rsync and the filesystem >> metadata. This means on subsequent rsync runs the file may not get rsyn= c=E2=80=99d >> when it really should. That is what the -c =E2=80=9Cchecksum" option i= n rsync is >> for; it will checksum the files to determine if it needs to be rsync'd a= nd >> not only rely on filesystem metadata. >> >> Using the -c option should fix your issue; however, I don=E2=80=99t thin= k you >> really want to use it as that would cause a lot of unnecessary I/O to >> compare all the already archived files. A better approach would be to >> archive the file with a temporary name and when it=E2=80=99s fully archi= ved rename >> it to the final name. >> >> What are you using for archiving, a script or just copy? >> >> >> >> On Sep 20, 2018, at 11:13 AM, Mike Broers wrote: >> >> I ran fsck and reran mkfs.ext4 in case there was something wrong with th= e >> underlying file systems, reran a pg_basebackup and got the same problem. >> It seems to be choking up on an archived wal that was rsync'ed during a >> time of a nightly vacuum. >> >> 2018-09-20 09:48:22 CDT [21017]: [5305-1] user=3D,db=3D LOG: restored l= og >> file "0000000100007D260000000E" from archive >> 2018-09-20 09:48:22 CDT [21017]: [5306-1] user=3D,db=3D LOG: incorrect >> resource manager data checksum in record at 7D26/EC04550 >> 2018-09-20 09:48:22 CDT [28296]: [1-1] user=3D,db=3D LOG: started strea= ming >> WAL from primary at 7D26/E000000 on timeline 1 >> 2018-09-20 09:48:22 CDT [28296]: [2-1] user=3D,db=3D FATAL: could not >> receive data from WAL stream: ERROR: requested WAL segment >> 0000000100007D260000000E has already been removed >> >> I dont know if this is a good test but I attempted to diff the file from >> primary and the file that got rsynced and they 'differ' >> >> -bash-4.2$ diff 0000000100007D260000000E 0000000100007D260000000E.sch1-d= b8 >> >> Binary files 0000000100007D260000000E and >> 0000000100007D260000000E.sch1-db8 differ >> >> It seems like my archived wal rsync strategy is flawed? Im just running = a >> cron to rsync from the primary server to the replica every 15 minutes. >> >> rsync -az -B 16384 --rsh=3Dssh ${PGPRIMARYHOST}/archive ${PGBACKUP}/arch= ive >> >> Although its strange to me if its rsyncing a file before writes complete >> why are they the same size? >> >> -rw------- 1 postgres postgres 16777216 Sep 20 03:57 >> 0000000100007D260000000E >> -bash-4.2$ ls -l 0000000100007D260000000E.sch1-db8 >> -rw------- 1 postgres postgres 16777216 Sep 20 10:05 >> 0000000100007D260000000E.sch1-db8 >> >> I will RTD on how it is advised to copy the wals and see if I am missing >> something obvious, but any help is always appreciated :) >> >> Mike >> >> >> >> On Wed, Sep 19, 2018 at 9:14 AM Mike Broers wrote: >> >>> A fresh replica using pg_basebackup on the same system generated simila= r >>> errors:. >>> >>> cp: cannot stat =E2=80=98/mnt/backup/pgsql/9.5/archive/00000002.history= =E2=80=99: No >>> such file or directory >>> 2018-09-19 08:36:23 CDT [57006]: [179-1] user=3D,db=3D LOG: restored l= og >>> file "0000000100007CFC00000040" from archive >>> 2018-09-19 08:36:23 CDT [57006]: [180-1] user=3D,db=3D LOG: incorrect >>> resource manager data checksum in record at 7CFC/405ED198 >>> >>> I am going to run file system checks now.. Maybe the backup volume the >>> archived wals get rsync'ed to has problems and is corrupting on the >>> replay? No checksum alerts on primary or an additional replica.. >>> >>> If I can supply additional info that would help get some advice please >>> let me know. >>> >>> Postgres 9.5.14, CentOS 7, ext4 filesystem, hyper-v VM >>> >>> On Mon, Sep 10, 2018 at 8:40 AM Mike Broers wrote: >>> >>>> Well I've verified my primary backups are working, and think my plan i= s >>>> to patch to 9.5.14, reprime a replica in the same environment and see = how >>>> it goes unless someone has an idea of something to check on the host t= o >>>> avoid future corruption... >>>> >>>> >>>> >>>> >>>> >>>> On Thu, Sep 6, 2018 at 12:28 PM Mike Broers wrote: >>>> >>>>> So I have discovered corruption in a postgres 9.5.12 read replica, ya= y >>>>> checksums! >>>>> >>>>> 2018-09-06 12:00:53 CDT [1563]: [4-1] user=3Dpostgres,db=3Dproduction >>>>> WARNING: page verification failed, calculated checksum 3482 but expe= cted >>>>> 32232 >>>>> >>>>> 2018-09-06 12:00:53 CDT [1563]: [5-1] user=3Dpostgres,db=3Dproduction >>>>> ERROR: invalid page in block 15962 of relation base/16384/464832386 >>>>> >>>>> The rest of the log is clean and just has usual monitoring queries as >>>>> this isnt a heavily used db. >>>>> >>>>> This corruption isnt occurring on the primary or a second replica, so >>>>> I'm not freaking out exactly, but Im not sure how I can further diagn= ose >>>>> what the root cause of the corruption might be. >>>>> >>>>> There were no power outages. This is a streaming hot standby replica >>>>> that looks like it was connected fine to its primary xlog at the time= , and >>>>> not falling back on rsync'ed WALS or anything. We run off an SSD SAN= that >>>>> is allocated using LVM and I've noticed documentation that states tha= t can >>>>> be problematic, but I'm unclear on how to diagnose what might have be= en the >>>>> root cause and now I'm somewhat uncomfortable with this environments >>>>> reliability in general. >>>>> >>>>> Does anyone have advice for what to check further to determine a >>>>> possible root cause? This is a CentOS 7 vm running on Hyper-V. >>>>> >>>>> Thanks for any assistance, greatly appreciated! >>>>> Mike >>>>> >>>>> >> --000000000000cc2f810577ceba58 Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
Ok so I have checksum errors in this replica AGAIN.
To remind the list of the scenario:
primary 9.5.14 d= b centos 7.4 ext4 filesystem on vmware in colo hosting environment with ssd= san
one replica in same colo with same os configuration on hyper= -v vm on the same san starts reporting checksum error
second repl= ica with same os configuration in AWS does not have this problem.=C2=A0 bot= h are connected directly to primary as hot standbys using streaming replica= tion, with a restore command and rsynced archivelogs if streaming falls beh= ind primary xlog.

This occurred during times of re= latively low activity on the primary, I verified in the log that streaming = replication is connected and it isnt happening during the application of an= rsync'ed transaction log.=C2=A0 Previously it was thought that maybe i= was rsyncing transaction logs as they were being written and this was the = cause.=C2=A0 Im doubting that now and Ive changed the rsync command to base= its list on a find with=C2=A0=C2=A0= -mmin +10=C2=A0to avoid rs= yncing files unless their mtime is older than 10 minutes.

The last time this happened I ran chkdsk (no errors) and even refor= matted the volumes.=C2=A0 Is there any extensive testing I can do to verify= the memory isnt the problem or some other tests to try to determine root c= ause?=C2=A0 Its a hyper-v vm so Im not sure how the virtual hardware abstra= ction is playing a role. My next step is going to be destroying and recreat= ing the vm, but Im going to have a hard time being confident in the replica= environment if I have no idea what is causing this.

Many other VMs share the hyperv environment, no other hosts have complai= ned about this kind of problem.

Thanks for reading= , any guidance is appreciated.



=


= On Thu, Sep 20, 2018 at 3:17 PM Mike Broers <mbroers@gmail.com> wrote:
Strange to finally hit the race condition after us= ing this approach for so long on so many different databases but I can acce= pt my understanding was flawed.=C2=A0 Im trying to decide a path to fix thi= s going forward.

If I switch to using a script to archiv= e, and have the local copy as well as the rsync in the script, then Im assu= ming that would be the best way as postgres is only rsyncing AFTER the file= has been fully written?

Something akin to:
<= div>archive_command =3D 'cp "%p" /mnt/backup/pgsql/9.5/archiv= e"%f" && rsync -a "%p" postgres@destination_hos= t:/mnt/backup/pgsql/archive/"%f"'=C2=A0 =C2=A0

=
I dont really like the idea of archive_command needing an rsync = to succeed to rotate through pg_xlogs but perhaps I can wire that in a bash= script so it exits with 0 but notifies me in some other way or something..=

Thanks for commenting Rui!

On Thu, Sep 20, 2018 at 2:00 PM Rui De= Sousa <rui@crazyb= ean.net> wrote:
Hi Mike,
=
Using rsync on an active file will lead to a =E2=80=9Ccorrupte= d=E2=80=9D file; which is normal; however, there is a race condition with r= sync and the filesystem metadata.=C2=A0 This means on subsequent rsync runs= the file may not get rsync=E2=80=99d when it really should.=C2=A0 That is = what the -c =C2=A0=E2=80=9Cchecksum" option in rsync is for; it will c= hecksum the files to determine if it needs to be rsync'd and not only r= ely on filesystem metadata.

Using the -c option= should fix your issue; however, I don=E2=80=99t think you really want to u= se it as that would cause a lot of unnecessary I/O to compare all the alrea= dy archived files.=C2=A0 A better approach would be to archive the file wit= h a temporary name and when it=E2=80=99s fully archived rename it to the fi= nal name.

What are you using for archiving, a scri= pt or just copy?



On Sep 20, 2018, at 11:13 AM, Mike Broers <mbroers@gmail.com> w= rote:

I ran fsck and re= ran mkfs.ext4 in case there was something wrong with the underlying file sy= stems, reran a pg_basebackup and got the same problem.=C2=A0 It seems to be= choking up on an archived wal that was rsync'ed during a time of a nig= htly vacuum.

2018-09-20 09:48:22 CDT [21017]: [5305= -1] user=3D,db=3D LOG:=C2=A0 restored log file "0000000100007D26000000= 0E" from archive
2018-09-20 09:48:22 CDT [21017]: [5306-1] u= ser=3D,db=3D LOG:=C2=A0 incorrect resource manager data checksum in record = at 7D26/EC04550
2018-09-20 09:48:22 CDT [28296]: [1-1] user=3D,db= =3D LOG:=C2=A0 started streaming WAL from primary at 7D26/E000000 on timeli= ne 1
2018-09-20 09:48:22 CDT [28296]: [2-1] user=3D,db=3D FATAL:= =C2=A0 could not receive data from WAL stream: ERROR:=C2=A0 requested WAL s= egment 0000000100007D260000000E has already been removed

I dont know if this is a good test but I attempted to diff the file = from primary and the file that got rsynced and they 'differ'
<= div>
-bash-4.2$ diff 0000000= 100007D260000000E 0000000100007D260000000E.sch1-db8=C2=A0
Binary files 0000000100007D= 260000000E and 0000000100007D260000000E.sch1-db8 differ
<= div>
It seems like my archived wal rsync strategy is fl= awed? Im just running a cron to rsync from the primary server to the replic= a every 15 minutes.=C2=A0=C2=A0

rsync -az -B 16384 --rsh=3Dssh ${PGPRIMARYHOST}/archive ${PG= BACKUP}/archive

Although its strange = to me if its rsyncing a file before writes complete why are they the same s= ize?=C2=A0=C2=A0

-rw------- 1 postgres postgres 1= 6777216 Sep 20 03:57 0000000100007D260000000E
-bash-4.2$ ls -l 0000000100007D260000000E.sch1-db8
On Wed, Sep 19, 2018 at 9:14 AM Mike Broers <mbroers@gmail.com> wrote:
A fres= h replica using pg_basebackup on the same system generated similar errors:.=

cp: cannot stat =E2=80=98/mnt/backup/pgsql/9.5/arc= hive/00000002.history=E2=80=99: No such file or directory
2018-09= -19 08:36:23 CDT [57006]: [179-1] user=3D,db=3D LOG:=C2=A0 restored log fil= e "0000000100007CFC00000040" from archive
2018-09-19 08= :36:23 CDT [57006]: [180-1] user=3D,db=3D LOG:=C2=A0 incorrect resource man= ager data checksum in record at 7CFC/405ED198

I am going to run file system checks now.. Maybe the backup volume the ar= chived wals get rsync'ed to has problems and is corrupting on the repla= y?=C2=A0 No checksum alerts on primary or an additional replica..

If I can supply additional info that would help get some ad= vice please let me know.=C2=A0=C2=A0

Postgres 9.5.= 14, CentOS 7, ext4 filesystem, hyper-v VM

On Mon, Sep 10, 2018 at 8:40 AM Mike Broe= rs <mbroers@gmail= .com> wrote:
Well I've verified my primary backups are working, and think my plan = is to patch to 9.5.14, reprime a replica in the same environment and see ho= w it goes unless someone has an idea of something to check on the host to a= void future corruption...





On Thu, Sep= 6, 2018 at 12:28 PM Mike Broers <mbroers@gmail.com> wrote:
So I have discovered corru= ption in a postgres 9.5.12 read replica, yay checksums!

=
2018-09-06 12:00:53 CDT [1563]: [4-1] user=3Dpostgres,db=3Dproduction = WARNING:=C2=A0 page verification failed, calculated checksum 3482 but expec= ted 32232

2018-09-06 12:00:53 CDT [1563]: [5-1] us= er=3Dpostgres,db=3Dproduction ERROR:=C2=A0 invalid page in block 15962 of r= elation base/16384/464832386

The rest of the= log is clean and just has usual monitoring queries as this isnt a heavily = used db.

This corruption isnt occurring on the pri= mary or a second replica, so I'm not freaking out exactly, but Im not s= ure how I can further diagnose what the root cause of the corruption might = be.=C2=A0

There were no power outages.=C2=A0 This = is a streaming hot standby replica that looks like it was connected fine to= its primary xlog at the time, and not falling back on rsync'ed WALS or= anything.=C2=A0 We run off an SSD SAN that is allocated using LVM and I= 9;ve noticed documentation that states that can be problematic, but I'm= unclear on how to diagnose what might have been the root cause and now I&#= 39;m somewhat uncomfortable with this environments reliability in general.= =C2=A0=C2=A0

Does anyone have advice for what to c= heck further to determine a possible root cause?=C2=A0 This is a CentOS 7 v= m running on Hyper-V.=C2=A0=C2=A0

Thanks for any a= ssistance, greatly appreciated!
Mike


--000000000000cc2f810577ceba58--