Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1gyZ0m-0001Cr-4a for pgsql-admin@arkaria.postgresql.org; Tue, 26 Feb 2019 09:26:52 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1gyZ0j-00007b-2m for pgsql-admin@arkaria.postgresql.org; Tue, 26 Feb 2019 09:26:49 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1gyZ0i-000058-Ex for pgsql-admin@lists.postgresql.org; Tue, 26 Feb 2019 09:26:48 +0000 Received: from mail-vk1-xa34.google.com ([2607:f8b0:4864:20::a34]) by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1gyZ0a-0007ig-J6 for pgsql-admin@postgresql.org; Tue, 26 Feb 2019 09:26:46 +0000 Received: by mail-vk1-xa34.google.com with SMTP id e131so2808812vkf.10 for ; Tue, 26 Feb 2019 01:26:40 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=avast.com; s=google; h=from:mime-version:thread-index:date:message-id:subject:to:cc; bh=ETKJLYDG9PU3kVGs9OwSjoBEYBrS/6WYgYNfqOt43DA=; b=e1Bh0CldWLEunVDn+s2ERUu5NzdE2MVtgodIP1/wF7gWdiyqUJoIC2vQ0ar4/Wq3p3 vkTEus1nGpQLhNcep4DfilI7k4d4Jsv6E1RLDVaq6rdoYBxPcbwWSEtkJjtnO+f8zbOP goBsHwp/5Yz8KBORu4j6s27Hew12ci3/9KWGU= X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:mime-version:thread-index:date:message-id :subject:to:cc; bh=ETKJLYDG9PU3kVGs9OwSjoBEYBrS/6WYgYNfqOt43DA=; b=O5WF+yRfS4OYYjtu4sT3LC/w3614ObOfC6XP/cy4DcqE2/CCf2z9ht0bm3GEETS2Qu iRltarwujgvndnIW8e3nowcVVb9dvao+keWJg6WXUSqTLvlyhiUZEo/EqzOowXtF2OJc eSLLe+tnsiWKRY60pzLQoKyv8j3QR0gVNrsIsKknyAOSPdBsT9sRHCZq6eEv03q4mpLf BrRoUysliyymcVaGtg+glrbiYG+wwqwWi+luobq56k29fqL/IlXI6Z1StaMdJ80Qqxj4 M3lmjDiYzk8npcbUCatbmw9WpUVgQUTec9aiRrhFAbcb/VwEZpEmA/+RtTsJTbwMHzy3 v8ug== X-Gm-Message-State: AHQUAuYFBqQI1M1e+nFE+PRNA+ZY0hs8Oc/ZwoU3gppE6QeEMewSLpUu +hsm+vJ32pxxZB3T3SlOcP1OvVpvvOHMJdq1CmFKENTK X-Google-Smtp-Source: AHgI3IYzkEUVs8lyFDdCJC8kyG6Jv62qZ4fRXkHbNxRQyiLvqvE82d7oYJbidsVM5VhFSysedRMMZ55+5FFpYJb0LHI= X-Received: by 2002:a1f:1144:: with SMTP id 65mr11779646vkr.39.1551173198599; Tue, 26 Feb 2019 01:26:38 -0800 (PST) From: =?UTF-8?B?VG9tw6HFoSBVa28=?= MIME-Version: 1.0 X-Mailer: Microsoft Outlook 16.0 Thread-Index: AdTNsQd0bJsd/jUsQFiPTla8QhBxcA== Date: Tue, 26 Feb 2019 10:26:37 +0100 Message-ID: <238227add62b080920c485b04ed4c341@mail.gmail.com> Subject: streaming vs wal shipping issue To: pgsql-admin@postgresql.org Cc: =?UTF-8?Q?Petr_Nov=C3=A1k?= Content-Type: multipart/alternative; boundary="0000000000007d7b0a0582c8a73b" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk --0000000000007d7b0a0582c8a73b Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable Hi all, We have recently found weird issue with WAL being still present after recovery (In fact, they are never deleted), this problem is on several version (starting from 9.4 up to 9.6, possibly later). Our setup is this: - Master in one DC, with wal shipping to different storage/server o Wal shipping via archive_command (pigz and scp - and we check return codes J ) - Several replicas in different DCs, configured use streaming replication as well as wal restore from that storage with archive_mode =3D 'on' o snippet of recovery.conf: standby_mode =3D 'on' primary_conninfo =3D 'host=3DXY port=3D5432 user=3DAAA password=3DPASSWORD sslmode=3Dverify-full' restore_command =3D '~/bin/wal_handler.sh -r -h REMOTE_STORAGE -f %f -p %p = -d LOCATION_ON_REMOTE_STORAGE' This custom script does this: [ -f =E2=80=9CPARAM_P/PARAM_F " ] && { echo "Logfile PARAM_P/PARAM_F alre= ady exists"; } echo "Restoring xlog PARAM_F " scp -i $SshKey -o PasswordAuthentication=3Dno -o StrictHostKeyChecking=3D= no REMOTE_STORAGE:LOCATION_ON_REMOTE_STORAGE/PARAM_F.gz PARAM_P [ $? =3D=3D 0 ] || { echo "Failed to retrieve log PARAM_F from REMOTE_STORAGE" && exit 1; } unpigz -f PARAM_P/PARAM_F.gz [ $? =3D=3D 0 ] || { echo "Failed to unpack log to PARAM_P/PARAM_F.gz" && exit 1; } When our master became under some massive DML workload (daily bases) some of replicas stops using streaming replication and switch to wal restore (so far good). Message in logs: 2019-02-25 23:10:03.087 CET, pid: 2100971, client: , db: , usr: ; LOG: recovery restart point at CEA9/3007188 2019-02-25 23:10:03.087 CET, pid: 2100971, client: , db: , usr: ; DETAIL: last completed transaction was at log time 2019-02-25 22:27:14.059533+01 2019-02-25 23:10:36.829 CET, pid: 2100971, client: , db: , usr: ; LOG: restartpoint starting: xlog 2019-02-25 23:10:47.832 CET, pid: 2100974, client: , db: , usr: ; FATAL: could not receive data from WAL stream: ERROR: requested WAL segment 000000020000CEA90000008A has already been removed But once they start restoring wals, they never deletes afterwards. We=E2=80= =99ve discovered when there is restore point, it creates next wal segment in sequence (in pg_xlog dir), which is immediately overwritten by restore. With overwrite enabled logs are full of: Restoring xlog 000000020000CE3900000029 Restoring xlog 000000020000CE390000002A Restoring xlog 000000020000CE390000002B Restoring xlog 000000020000CE390000002C Restoring xlog 000000020000CE390000002D Restoring xlog 000000020000CE390000002E And once if catches up: scp: /LOCATION_ON_REMOTE_STORAGE/000000020000CE8B00000017.gz: No such file or directory Failed to retrieve log 000000020000CE8B00000017 from REMOTE_STORAGE 2019-02-25 09:09:28.490 CET, pid: 2090891, client: , db: , usr: ; LOG: started streaming WAL from primary at CE8B/17000000 on timeline 2 When we disabled overriding of WALs during restore we git this error messag= e 2019-02-25 23:10:03.086 CET, pid: 2100971, client: , db: , usr: ; LOG: restartpoint complete: wrote 142421 buffers (18.1%); 0 transaction log file(s) added, 68 removed, 0 recycled; write=3D24.086 s, sync=3D0.022 s, total=3D24.424 s; sync files=3D74, longest=3D0.005 s, average=3D0.000 s; distance=3D1114130 kB, estimate=3D1114148 kB 2019-02-25 23:10:03.087 CET, pid: 2100971, client: , db: , usr: ; LOG: recovery restart point at CEA9/3007188 2019-02-25 23:10:03.087 CET, pid: 2100971, client: , db: , usr: ; DETAIL: last completed transaction was at log time 2019-02-25 22:27:14.059533+01 2019-02-25 23:10:36.829 CET, pid: 2100971, client: , db: , usr: ; LOG: restartpoint starting: xlog Logfile pg_xlog/000000020000CEA90000008A already exists Restoring xlog 000000020000CEA90000008A unpigz: abort: write error on pg_xlog/000000020000CEA90000008A (Inappropriate ioctl for device) Which means, wal file is present in this xlog directory Thanks for any advice --0000000000007d7b0a0582c8a73b Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable <= div class=3D"WordSection1">

Hi all,

=C2=A0

We have recently found weird issu= e with WAL being still present after recovery (In fact, they are never dele= ted), this problem is on several version (starting from 9.4 up to 9.6, poss= ibly later).

Our setup is this:

-=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Master in one DC, with wal shipping to different storage/server

o=C2=A0=C2=A0 Wal shipping via archive_command (pigz and scp=C2=A0 - and we check ret= urn codes J )

-=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 Several replicas in different DCs, configured use streaming replication = as well as wal restore from that storage with archive_mode =3D 'on'=

o<= span style=3D"font:7.0pt "Times New Roman"">=C2=A0=C2=A0 <= /span>snippet of recovery.conf:

standby_mode =3D 'on'

primary_conninfo =3D 'host=3DXY port=3D5432 user=3DAAA password= =3DPASSWORD sslmode=3Dverify-full'

restore_command =3D '~= /bin/wal_handler.sh -r -h REMOTE_STORAGE -f %f -p %p -d LOCATION_ON_REMOTE_= STORAGE'

=C2=A0

This custom script does this:

=C2=A0 [ -f =E2=80=9CPARAM_P/PARAM_F &= quot; ] && { echo "Logfile PARAM_P/PARAM_F already exists"= ;; }

=C2=A0 echo "Restoring xlog PARAM_F "

= =C2=A0 scp -i $SshKey -o PasswordAuthentication=3Dno -o StrictHostKeyChecki= ng=3Dno REMOTE_STORAGE:LOCATION_ON_REMOTE_STORAGE/PARAM_F.gz PARAM_P=

=C2=A0 [ $? =3D=3D 0 ] || { echo "Failed to retrieve log PARAM_F f= rom REMOTE_STORAGE" && exit 1; }

=C2=A0 unpigz -f PA= RAM_P/PARAM_F.gz

=C2=A0 [ $? =3D=3D 0 ] || { echo "Failed to= unpack log to PARAM_P/PARAM_F.gz" && exit 1; }

=C2=A0

When our master became = under some massive DML workload (daily bases) some of replicas stops using = streaming replication and switch to wal restore (so far good). Message in l= ogs:

=C2=A0

2019-02-25 23:10:03.087 CET, pid: = 2100971, client: , db: , usr: ; LOG:=C2=A0 recovery restart point at CEA9/3= 007188

2019-02-25 23:10:03.087 CET, pid: 2100971, client: , db: ,= usr: ; DETAIL:=C2=A0 last completed transaction was at log time 2019-02-25= 22:27:14.059533+01

2019-02-25 23:10:36.829 CET, pid: 2100971, cl= ient: , db: , usr: ; LOG:=C2=A0 restartpoint starting: xlog

2019-= 02-25 23:10:47.832 CET, pid: 2100974, client: , db: , usr: ; FATAL:=C2=A0 c= ould not receive data from WAL stream: ERROR:=C2=A0 requested WAL segment 0= 00000020000CEA90000008A has already been removed

=C2=A0

But once they start restoring wals,= they never deletes afterwards. We=E2=80=99ve discovered when there is rest= ore point, it creates next wal segment in sequence (in pg_xlog dir), which = is immediately overwritten by restore.

With over= write enabled logs are full of:

Restoring xlog 000000020000CE3900000029<= /span>

Restoring xlog 000000020000CE390000002A

Restoring xlog = 000000020000CE390000002B

Restoring xlog 000000020000CE390000002C<= /span>

Restoring xlog 000000020000CE390000002D

Restoring xlog = 000000020000CE390000002E

And once if catches up:

scp: /LOCATION_ON_REMOTE_STORAGE/000000020000CE8B00000017.gz: No suc= h file or directory

Failed to retrieve log 000000020000CE8B000000= 17 from REMOTE_STORAGE

2019-02-25 09:09:28.490 CET, pid: 2090891,= client: , db: , usr: ; LOG:=C2=A0 started streaming WAL from primary at CE= 8B/17000000 on timeline 2

=C2=A0

When we disabled overriding of WALs during restore we git = this error message

2019-02-25 23:10:03.086 CET, pid: 2100971, client: , = db: , usr: ; LOG:=C2=A0 restartpoint complete: wrote 142421 buffers (18.1%)= ; 0 transaction log file(s) added, 68 removed, 0 recycled; write=3D24.086 s= , sync=3D0.022 s, total=3D24.424 s; sync files=3D74, longest=3D0.005 s, ave= rage=3D0.000 s; distance=3D1114130 kB, estimate=3D1114148 kB

2019= -02-25 23:10:03.087 CET, pid: 2100971, client: , db: , usr: ; LOG:=C2=A0 re= covery restart point at CEA9/3007188

2019-02-25 23:10:03.087 CET,= pid: 2100971, client: , db: , usr: ; DETAIL:=C2=A0 last completed transact= ion was at log time 2019-02-25 22:27:14.059533+01

2019-02-25 23:1= 0:36.829 CET, pid: 2100971, client: , db: , usr: ; LOG:=C2=A0 restartpoint = starting: xlog

Logfile pg_xlog/000000020000CEA90000008A already e= xists

Restoring xlog 000000020000CEA90000008A

unpigz: = abort: write error on pg_xlog/000000020000CEA90000008A (Inappropriate ioctl= for device)

Which means, wal file is pres= ent in this xlog directory

=C2=A0

Thanks for any advice

=C2=A0

=C2=A0

=C2=A0

=C2=A0

--0000000000007d7b0a0582c8a73b--