0s autopkgtest [09:53:16]: starting date and time: 2025-01-06 09:53:16+0000 0s autopkgtest [09:53:16]: git checkout: 325255d2 Merge branch 'pin-any-arch' into 'ubuntu/production' 0s autopkgtest [09:53:16]: host juju-7f2275-prod-proposed-migration-environment-15; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.xmwz0mae/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:postgresql-17,src:icu --apt-upgrade pglogical --timeout-short=300 --timeout-copy=20000 --timeout-build=20000 '--env=ADT_TEST_TRIGGERS=postgresql-17/17.2-1build2 icu/76.1-1ubuntu1' -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-s390x --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-15@bos03-s390x-14.secgroup --name adt-plucky-s390x-pglogical-20250106-095315-juju-7f2275-prod-proposed-migration-environment-15-c3164b9a-cb72-45db-a675-cfa5ed558525 --image adt/ubuntu-plucky-s390x-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-15 --net-id=net_prod-proposed-migration-s390x -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com,radosgw.ps5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 80s autopkgtest [09:54:36]: testbed dpkg architecture: s390x 80s autopkgtest [09:54:36]: testbed apt version: 2.9.18 81s autopkgtest [09:54:37]: @@@@@@@@@@@@@@@@@@@@ test bed setup 81s autopkgtest [09:54:37]: testbed release detected to be: None 82s autopkgtest [09:54:38]: updating testbed package index (apt update) 82s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [73.9 kB] 82s Hit:2 http://ftpmaster.internal/ubuntu plucky InRelease 82s Hit:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease 82s Hit:4 http://ftpmaster.internal/ubuntu plucky-security InRelease 82s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [17.2 kB] 82s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [105 kB] 82s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [741 kB] 83s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/restricted Sources [9708 B] 83s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x Packages [173 kB] 83s Get:10 http://ftpmaster.internal/ubuntu plucky-proposed/restricted s390x Packages [756 B] 83s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/universe s390x Packages [765 kB] 83s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse s390x Packages [5928 B] 83s Fetched 1892 kB in 1s (2113 kB/s) 83s Reading package lists... 84s Reading package lists... 84s Building dependency tree... 84s Reading state information... 84s Calculating upgrade... 84s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 84s Reading package lists... 84s Building dependency tree... 84s Reading state information... 85s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 85s autopkgtest [09:54:41]: upgrading testbed (apt dist-upgrade and autopurge) 85s Reading package lists... 85s Building dependency tree... 85s Reading state information... 85s Calculating upgrade...Starting pkgProblemResolver with broken count: 0 85s Starting 2 pkgProblemResolver with broken count: 0 85s Done 85s Entering ResolveByKeep 85s 85s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 86s Reading package lists... 86s Building dependency tree... 86s Reading state information... 86s Starting pkgProblemResolver with broken count: 0 86s Starting 2 pkgProblemResolver with broken count: 0 86s Done 86s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 88s autopkgtest [09:54:44]: testbed running kernel: Linux 6.11.0-8-generic #8-Ubuntu SMP Mon Sep 16 12:49:35 UTC 2024 89s autopkgtest [09:54:45]: @@@@@@@@@@@@@@@@@@@@ apt-source pglogical 91s Get:1 http://ftpmaster.internal/ubuntu plucky/universe pglogical 2.4.4-1 (dsc) [2331 B] 91s Get:2 http://ftpmaster.internal/ubuntu plucky/universe pglogical 2.4.4-1 (tar) [281 kB] 91s Get:3 http://ftpmaster.internal/ubuntu plucky/universe pglogical 2.4.4-1 (diff) [180 kB] 91s gpgv: Signature made Wed Oct 18 08:27:21 2023 UTC 91s gpgv: using RSA key 5C48FE6157F49179597087C64C5A6BAB12D2A7AE 91s gpgv: Can't check signature: No public key 91s dpkg-source: warning: cannot verify inline signature for ./pglogical_2.4.4-1.dsc: no acceptable signature found 91s autopkgtest [09:54:47]: testing package pglogical version 2.4.4-1 91s autopkgtest [09:54:47]: build not needed 92s autopkgtest [09:54:48]: test prove: preparing testbed 92s Reading package lists... 92s Building dependency tree... 92s Reading state information... 93s Starting pkgProblemResolver with broken count: 0 93s Starting 2 pkgProblemResolver with broken count: 0 93s Done 93s The following NEW packages will be installed: 93s libio-pty-perl libipc-run-perl libjson-perl libpq5 93s libtap-parser-sourcehandler-pgtap-perl libxslt1.1 postgresql-16 93s postgresql-16-pglogical postgresql-client-16 postgresql-client-common 93s postgresql-common ssl-cert 93s 0 upgraded, 12 newly installed, 0 to remove and 0 not upgraded. 93s Need to get 18.8 MB of archives. 93s After this operation, 54.4 MB of additional disk space will be used. 93s Get:1 http://ftpmaster.internal/ubuntu plucky/main s390x libjson-perl all 4.10000-1 [81.9 kB] 93s Get:2 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-client-common all 262 [36.7 kB] 93s Get:3 http://ftpmaster.internal/ubuntu plucky/main s390x ssl-cert all 1.1.3ubuntu1 [18.7 kB] 93s Get:4 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-common all 262 [162 kB] 93s Get:5 http://ftpmaster.internal/ubuntu plucky/main s390x libio-pty-perl s390x 1:1.20-1build3 [31.6 kB] 93s Get:6 http://ftpmaster.internal/ubuntu plucky/main s390x libipc-run-perl all 20231003.0-2 [91.5 kB] 93s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libpq5 s390x 17.2-1build2 [146 kB] 93s Get:8 http://ftpmaster.internal/ubuntu plucky/main s390x libxslt1.1 s390x 1.1.39-0exp1ubuntu2 [169 kB] 93s Get:9 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-client-16 s390x 16.4-3 [1294 kB] 93s Get:10 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-16 s390x 16.4-3 [16.3 MB] 95s Get:11 http://ftpmaster.internal/ubuntu plucky/universe s390x postgresql-16-pglogical s390x 2.4.4-1 [483 kB] 95s Get:12 http://ftpmaster.internal/ubuntu plucky/universe s390x libtap-parser-sourcehandler-pgtap-perl all 3.36-2 [35.2 kB] 95s Preconfiguring packages ... 95s Fetched 18.8 MB in 2s (9179 kB/s) 95s Selecting previously unselected package libjson-perl. 95s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 55616 files and directories currently installed.) 95s Preparing to unpack .../00-libjson-perl_4.10000-1_all.deb ... 95s Unpacking libjson-perl (4.10000-1) ... 95s Selecting previously unselected package postgresql-client-common. 95s Preparing to unpack .../01-postgresql-client-common_262_all.deb ... 95s Unpacking postgresql-client-common (262) ... 95s Selecting previously unselected package ssl-cert. 95s Preparing to unpack .../02-ssl-cert_1.1.3ubuntu1_all.deb ... 95s Unpacking ssl-cert (1.1.3ubuntu1) ... 95s Selecting previously unselected package postgresql-common. 95s Preparing to unpack .../03-postgresql-common_262_all.deb ... 95s Adding 'diversion of /usr/bin/pg_config to /usr/bin/pg_config.libpq-dev by postgresql-common' 95s Unpacking postgresql-common (262) ... 95s Selecting previously unselected package libio-pty-perl. 95s Preparing to unpack .../04-libio-pty-perl_1%3a1.20-1build3_s390x.deb ... 95s Unpacking libio-pty-perl (1:1.20-1build3) ... 95s Selecting previously unselected package libipc-run-perl. 95s Preparing to unpack .../05-libipc-run-perl_20231003.0-2_all.deb ... 95s Unpacking libipc-run-perl (20231003.0-2) ... 95s Selecting previously unselected package libpq5:s390x. 95s Preparing to unpack .../06-libpq5_17.2-1build2_s390x.deb ... 95s Unpacking libpq5:s390x (17.2-1build2) ... 95s Selecting previously unselected package libxslt1.1:s390x. 95s Preparing to unpack .../07-libxslt1.1_1.1.39-0exp1ubuntu2_s390x.deb ... 95s Unpacking libxslt1.1:s390x (1.1.39-0exp1ubuntu2) ... 95s Selecting previously unselected package postgresql-client-16. 95s Preparing to unpack .../08-postgresql-client-16_16.4-3_s390x.deb ... 95s Unpacking postgresql-client-16 (16.4-3) ... 95s Selecting previously unselected package postgresql-16. 95s Preparing to unpack .../09-postgresql-16_16.4-3_s390x.deb ... 95s Unpacking postgresql-16 (16.4-3) ... 96s Selecting previously unselected package postgresql-16-pglogical. 96s Preparing to unpack .../10-postgresql-16-pglogical_2.4.4-1_s390x.deb ... 96s Unpacking postgresql-16-pglogical (2.4.4-1) ... 96s Selecting previously unselected package libtap-parser-sourcehandler-pgtap-perl. 96s Preparing to unpack .../11-libtap-parser-sourcehandler-pgtap-perl_3.36-2_all.deb ... 96s Unpacking libtap-parser-sourcehandler-pgtap-perl (3.36-2) ... 96s Setting up postgresql-client-common (262) ... 96s Setting up libtap-parser-sourcehandler-pgtap-perl (3.36-2) ... 96s Setting up libio-pty-perl (1:1.20-1build3) ... 96s Setting up libpq5:s390x (17.2-1build2) ... 96s Setting up ssl-cert (1.1.3ubuntu1) ... 96s Created symlink '/etc/systemd/system/multi-user.target.wants/ssl-cert.service' → '/usr/lib/systemd/system/ssl-cert.service'. 96s Setting up libipc-run-perl (20231003.0-2) ... 96s Setting up libjson-perl (4.10000-1) ... 96s Setting up libxslt1.1:s390x (1.1.39-0exp1ubuntu2) ... 96s Setting up postgresql-client-16 (16.4-3) ... 96s update-alternatives: using /usr/share/postgresql/16/man/man1/psql.1.gz to provide /usr/share/man/man1/psql.1.gz (psql.1.gz) in auto mode 96s Setting up postgresql-common (262) ... 97s Creating config file /etc/postgresql-common/createcluster.conf with new version 97s Building PostgreSQL dictionaries from installed myspell/hunspell packages... 97s Removing obsolete dictionary files: 97s Created symlink '/etc/systemd/system/multi-user.target.wants/postgresql.service' → '/usr/lib/systemd/system/postgresql.service'. 97s Setting up postgresql-16 (16.4-3) ... 97s Creating new PostgreSQL cluster 16/main ... 97s /usr/lib/postgresql/16/bin/initdb -D /var/lib/postgresql/16/main --auth-local peer --auth-host scram-sha-256 --no-instructions 98s The files belonging to this database system will be owned by user "postgres". 98s This user must also own the server process. 98s 98s The database cluster will be initialized with locale "C.UTF-8". 98s The default database encoding has accordingly been set to "UTF8". 98s The default text search configuration will be set to "english". 98s 98s Data page checksums are disabled. 98s 98s fixing permissions on existing directory /var/lib/postgresql/16/main ... ok 98s creating subdirectories ... ok 98s selecting dynamic shared memory implementation ... posix 98s selecting default max_connections ... 100 98s selecting default shared_buffers ... 128MB 98s selecting default time zone ... Etc/UTC 98s creating configuration files ... ok 98s running bootstrap script ... ok 98s performing post-bootstrap initialization ... ok 98s syncing data to disk ... ok 101s Setting up postgresql-16-pglogical (2.4.4-1) ... 101s Processing triggers for man-db (2.13.0-1) ... 102s Processing triggers for libc-bin (2.40-4ubuntu1) ... 103s autopkgtest [09:54:59]: test prove: [----------------------- 103s ### 16 ### 103s Skipping prove test on PG 16, test not compatible yet 103s cp: cannot stat '/tmp/regresscheck.BrW6bh/tmp_check/log/*': No such file or directory 103s autopkgtest [09:54:59]: test prove: -----------------------] 104s prove PASS 104s autopkgtest [09:55:00]: test prove: - - - - - - - - - - results - - - - - - - - - - 104s autopkgtest [09:55:00]: test regresscheck: preparing testbed 220s autopkgtest [09:56:56]: testbed dpkg architecture: s390x 220s autopkgtest [09:56:56]: testbed apt version: 2.9.18 220s autopkgtest [09:56:56]: @@@@@@@@@@@@@@@@@@@@ test bed setup 221s autopkgtest [09:56:57]: testbed release detected to be: plucky 221s autopkgtest [09:56:57]: updating testbed package index (apt update) 222s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [73.9 kB] 222s Hit:2 http://ftpmaster.internal/ubuntu plucky InRelease 222s Hit:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease 222s Hit:4 http://ftpmaster.internal/ubuntu plucky-security InRelease 222s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [17.2 kB] 222s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [741 kB] 222s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/restricted Sources [9708 B] 222s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [105 kB] 222s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x Packages [173 kB] 222s Get:10 http://ftpmaster.internal/ubuntu plucky-proposed/restricted s390x Packages [756 B] 222s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/universe s390x Packages [765 kB] 223s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse s390x Packages [5928 B] 223s Fetched 1892 kB in 1s (1423 kB/s) 223s Reading package lists... 224s Reading package lists... 224s Building dependency tree... 224s Reading state information... 224s Calculating upgrade... 224s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 224s Reading package lists... 225s Building dependency tree... 225s Reading state information... 225s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 225s autopkgtest [09:57:01]: upgrading testbed (apt dist-upgrade and autopurge) 225s Reading package lists... 225s Building dependency tree... 225s Reading state information... 225s Calculating upgrade...Starting pkgProblemResolver with broken count: 0 225s Starting 2 pkgProblemResolver with broken count: 0 225s Done 225s Entering ResolveByKeep 226s 226s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 226s Reading package lists... 226s Building dependency tree... 226s Reading state information... 226s Starting pkgProblemResolver with broken count: 0 226s Starting 2 pkgProblemResolver with broken count: 0 226s Done 226s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 229s Reading package lists... 229s Building dependency tree... 229s Reading state information... 229s Starting pkgProblemResolver with broken count: 0 229s Starting 2 pkgProblemResolver with broken count: 0 229s Done 229s The following NEW packages will be installed: 229s libjson-perl libpq5 libxslt1.1 postgresql-16 postgresql-16-pglogical 229s postgresql-client-16 postgresql-client-common postgresql-common ssl-cert 230s 0 upgraded, 9 newly installed, 0 to remove and 0 not upgraded. 230s Need to get 18.7 MB of archives. 230s After this operation, 54.0 MB of additional disk space will be used. 230s Get:1 http://ftpmaster.internal/ubuntu plucky/main s390x libjson-perl all 4.10000-1 [81.9 kB] 230s Get:2 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-client-common all 262 [36.7 kB] 230s Get:3 http://ftpmaster.internal/ubuntu plucky/main s390x ssl-cert all 1.1.3ubuntu1 [18.7 kB] 230s Get:4 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-common all 262 [162 kB] 230s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libpq5 s390x 17.2-1build2 [146 kB] 230s Get:6 http://ftpmaster.internal/ubuntu plucky/main s390x libxslt1.1 s390x 1.1.39-0exp1ubuntu2 [169 kB] 230s Get:7 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-client-16 s390x 16.4-3 [1294 kB] 230s Get:8 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-16 s390x 16.4-3 [16.3 MB] 234s Get:9 http://ftpmaster.internal/ubuntu plucky/universe s390x postgresql-16-pglogical s390x 2.4.4-1 [483 kB] 234s Preconfiguring packages ... 234s Fetched 18.7 MB in 4s (4351 kB/s) 234s Selecting previously unselected package libjson-perl. 234s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 55616 files and directories currently installed.) 234s Preparing to unpack .../0-libjson-perl_4.10000-1_all.deb ... 234s Unpacking libjson-perl (4.10000-1) ... 234s Selecting previously unselected package postgresql-client-common. 234s Preparing to unpack .../1-postgresql-client-common_262_all.deb ... 234s Unpacking postgresql-client-common (262) ... 234s Selecting previously unselected package ssl-cert. 234s Preparing to unpack .../2-ssl-cert_1.1.3ubuntu1_all.deb ... 234s Unpacking ssl-cert (1.1.3ubuntu1) ... 234s Selecting previously unselected package postgresql-common. 234s Preparing to unpack .../3-postgresql-common_262_all.deb ... 234s Adding 'diversion of /usr/bin/pg_config to /usr/bin/pg_config.libpq-dev by postgresql-common' 234s Unpacking postgresql-common (262) ... 234s Selecting previously unselected package libpq5:s390x. 234s Preparing to unpack .../4-libpq5_17.2-1build2_s390x.deb ... 234s Unpacking libpq5:s390x (17.2-1build2) ... 234s Selecting previously unselected package libxslt1.1:s390x. 234s Preparing to unpack .../5-libxslt1.1_1.1.39-0exp1ubuntu2_s390x.deb ... 234s Unpacking libxslt1.1:s390x (1.1.39-0exp1ubuntu2) ... 234s Selecting previously unselected package postgresql-client-16. 234s Preparing to unpack .../6-postgresql-client-16_16.4-3_s390x.deb ... 234s Unpacking postgresql-client-16 (16.4-3) ... 234s Selecting previously unselected package postgresql-16. 234s Preparing to unpack .../7-postgresql-16_16.4-3_s390x.deb ... 234s Unpacking postgresql-16 (16.4-3) ... 235s Selecting previously unselected package postgresql-16-pglogical. 235s Preparing to unpack .../8-postgresql-16-pglogical_2.4.4-1_s390x.deb ... 235s Unpacking postgresql-16-pglogical (2.4.4-1) ... 235s Setting up postgresql-client-common (262) ... 235s Setting up libpq5:s390x (17.2-1build2) ... 235s Setting up ssl-cert (1.1.3ubuntu1) ... 235s Created symlink '/etc/systemd/system/multi-user.target.wants/ssl-cert.service' → '/usr/lib/systemd/system/ssl-cert.service'. 235s Setting up libjson-perl (4.10000-1) ... 235s Setting up libxslt1.1:s390x (1.1.39-0exp1ubuntu2) ... 235s Setting up postgresql-client-16 (16.4-3) ... 235s update-alternatives: using /usr/share/postgresql/16/man/man1/psql.1.gz to provide /usr/share/man/man1/psql.1.gz (psql.1.gz) in auto mode 235s Setting up postgresql-common (262) ... 236s Creating config file /etc/postgresql-common/createcluster.conf with new version 236s Building PostgreSQL dictionaries from installed myspell/hunspell packages... 236s Removing obsolete dictionary files: 236s Created symlink '/etc/systemd/system/multi-user.target.wants/postgresql.service' → '/usr/lib/systemd/system/postgresql.service'. 236s Setting up postgresql-16 (16.4-3) ... 237s Creating new PostgreSQL cluster 16/main ... 237s /usr/lib/postgresql/16/bin/initdb -D /var/lib/postgresql/16/main --auth-local peer --auth-host scram-sha-256 --no-instructions 237s The files belonging to this database system will be owned by user "postgres". 237s This user must also own the server process. 237s 237s The database cluster will be initialized with locale "C.UTF-8". 237s The default database encoding has accordingly been set to "UTF8". 237s The default text search configuration will be set to "english". 237s 237s Data page checksums are disabled. 237s 237s fixing permissions on existing directory /var/lib/postgresql/16/main ... ok 237s creating subdirectories ... ok 237s selecting dynamic shared memory implementation ... posix 237s selecting default max_connections ... 100 237s selecting default shared_buffers ... 128MB 237s selecting default time zone ... Etc/UTC 237s creating configuration files ... ok 237s running bootstrap script ... ok 237s performing post-bootstrap initialization ... ok 237s syncing data to disk ... ok 240s Setting up postgresql-16-pglogical (2.4.4-1) ... 240s Processing triggers for man-db (2.13.0-1) ... 241s Processing triggers for libc-bin (2.40-4ubuntu1) ... 243s autopkgtest [09:57:19]: test regresscheck: [----------------------- 243s ### 16 ### 243s /bin/mkdir -p regression_output 243s echo "# +++ regress check in +++" && PATH="./tmp_install/usr/lib/postgresql/16/bin:/tmp/regresscheck.785HRR:$PATH" LD_LIBRARY_PATH="./tmp_install/usr/lib/s390x-linux-gnu" /usr/lib/postgresql/16/lib/pgxs/src/makefiles/../../src/test/regress/pg_regress --temp-instance=./tmp_check --inputdir=./ --bindir= \ 243s --temp-config ./regress-postgresql.conf \ 243s --temp-instance=./tmp_check \ 243s --outputdir=./regression_output \ 243s --create-role=logical \ 243s preseed infofuncs init_fail init preseed_check basic extended conflict_secondary_unique toasted replication_set matview bidirectional interfaces foreign_key functions copy triggers parallel row_filter att_list column_filter apply_delay node_origin_cascade drop 243s # +++ regress check in +++ 245s # using temp instance on port 61700 with PID 3689 245s ok 1 - preseed 84 ms 245s ok 2 - infofuncs 47 ms 245s not ok 3 - init_fail 83 ms 245s not ok 4 - init 273 ms 245s ok 5 - preseed_check 21 ms 255s ok 6 - basic 9097 ms 287s ok 7 - extended 32527 ms 288s ok 8 - conflict_secondary_unique 1025 ms 290s ok 9 - toasted 2035 ms 290s not ok 10 - replication_set 24 ms 293s ok 11 - matview 3046 ms 295s not ok 12 - bidirectional 2264 ms 296s not ok 13 - interfaces 342 ms 297s ok 14 - foreign_key 1024 ms 307s ok 15 - functions 10244 ms 307s ok 16 - copy 22 ms 311s ok 17 - triggers 4071 ms 314s not ok 18 - parallel 3264 ms 352s ok 19 - row_filter 37870 ms 353s ok 20 - att_list 1111 ms 355s ok 21 - column_filter 1248 ms 362s not ok 22 - apply_delay 7260 ms 365s not ok 23 - node_origin_cascade 3295 ms 366s ok 24 - drop 1051 ms 366s 1..24 366s # 8 of 24 tests failed. 366s # The differences that caused some tests to fail can be viewed in the file "/tmp/regresscheck.785HRR/regression_output/regression.diffs". 366s # A copy of the test summary that you see above is saved in the file "/tmp/regresscheck.785HRR/regression_output/regression.out". 366s make: *** [Makefile:143: regresscheck] Error 1 366s diff -U3 /tmp/regresscheck.785HRR/expected/init_fail.out /tmp/regresscheck.785HRR/regression_output/results/init_fail.out 366s --- /tmp/regresscheck.785HRR/expected/init_fail.out 2025-01-06 09:57:19.796406706 +0000 366s +++ /tmp/regresscheck.785HRR/regression_output/results/init_fail.out 2025-01-06 09:57:21.516406706 +0000 366s @@ -42,7 +42,7 @@ 366s SELECT * FROM pglogical.create_node(node_name := 'test_subscriber', dsn := (SELECT subscriber_dsn FROM pglogical_regress_variables()) || ' user=nonreplica'); 366s create_node 366s ------------- 366s - 1755434425 366s + 2095496919 366s (1 row) 366s 366s -- fail (can't connect to remote) 366s @@ -72,7 +72,7 @@ 366s SELECT * FROM pglogical.create_node(node_name := 'test_provider', dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=nonreplica'); 366s create_node 366s ------------- 366s - 2689511696 366s + 3385836371 366s (1 row) 366s 366s \c :subscriber_dsn 366s diff -U3 /tmp/regresscheck.785HRR/expected/init.out /tmp/regresscheck.785HRR/regression_output/results/init.out 366s --- /tmp/regresscheck.785HRR/expected/init.out 2025-01-06 09:57:19.796406706 +0000 366s +++ /tmp/regresscheck.785HRR/regression_output/results/init.out 2025-01-06 09:57:21.806406706 +0000 366s @@ -64,7 +64,7 @@ 366s SELECT * FROM pglogical.create_node(node_name := 'test_provider', dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=super'); 366s create_node 366s ------------- 366s - 2689511696 366s + 3385836371 366s (1 row) 366s 366s \c :subscriber_dsn 366s @@ -79,7 +79,7 @@ 366s SELECT * FROM pglogical.create_node(node_name := 'test_subscriber', dsn := (SELECT subscriber_dsn FROM pglogical_regress_variables()) || ' user=super'); 366s create_node 366s ------------- 366s - 1755434425 366s + 2095496919 366s (1 row) 366s 366s BEGIN; 366s @@ -90,7 +90,7 @@ 366s forward_origins := '{}'); 366s create_subscription 366s --------------------- 366s - 3848008564 366s + 2208722835 366s (1 row) 366s 366s /* 366s @@ -112,7 +112,7 @@ 366s SELECT sync_kind, sync_subid, sync_nspname, sync_relname, sync_status IN ('y', 'r') FROM pglogical.local_sync_status ORDER BY 2,3,4; 366s sync_kind | sync_subid | sync_nspname | sync_relname | ?column? 366s -----------+------------+--------------+--------------+---------- 366s - f | 3848008564 | | | t 366s + f | 2208722835 | | | t 366s (1 row) 366s 366s -- Make sure we see the slot and active connection 366s diff -U3 /tmp/regresscheck.785HRR/expected/replication_set.out /tmp/regresscheck.785HRR/regression_output/results/replication_set.out 366s --- /tmp/regresscheck.785HRR/expected/replication_set.out 2025-01-06 09:57:19.796406706 +0000 366s +++ /tmp/regresscheck.785HRR/regression_output/results/replication_set.out 2025-01-06 09:58:06.536121011 +0000 366s @@ -50,19 +50,19 @@ 366s SELECT * FROM pglogical.create_replication_set('repset_replicate_all'); 366s create_replication_set 366s ------------------------ 366s - 1767380104 366s + 3885206554 366s (1 row) 366s 366s SELECT * FROM pglogical.create_replication_set('repset_replicate_instrunc', replicate_update := false, replicate_delete := false); 366s create_replication_set 366s ------------------------ 366s - 348382733 366s + 4149578203 366s (1 row) 366s 366s SELECT * FROM pglogical.create_replication_set('repset_replicate_insupd', replicate_delete := false, replicate_truncate := false); 366s create_replication_set 366s ------------------------ 366s - 128878480 366s + 2580819485 366s (1 row) 366s 366s -- add tables 366s @@ -107,7 +107,7 @@ 366s SELECT * FROM pglogical.alter_replication_set('repset_replicate_insupd', replicate_truncate := true); 366s alter_replication_set 366s ----------------------- 366s - 128878480 366s + 2580819485 366s (1 row) 366s 366s -- fail again 366s @@ -226,8 +226,8 @@ 366s SELECT * FROM pglogical.replication_set; 366s set_id | set_nodeid | set_name | replicate_insert | replicate_update | replicate_delete | replicate_truncate 366s ------------+------------+---------------------+------------------+------------------+------------------+-------------------- 366s - 828867312 | 1755434425 | default | t | t | t | t 366s - 3318003856 | 1755434425 | default_insert_only | t | f | f | t 366s - 2796587818 | 1755434425 | ddl_sql | t | f | f | f 366s + 819356807 | 2095496919 | default | t | t | t | t 366s + 2454072499 | 2095496919 | default_insert_only | t | f | f | t 366s + 2627772969 | 2095496919 | ddl_sql | t | f | f | f 366s (3 rows) 366s 366s diff -U3 /tmp/regresscheck.785HRR/expected/bidirectional.out /tmp/regresscheck.785HRR/regression_output/results/bidirectional.out 366s --- /tmp/regresscheck.785HRR/expected/bidirectional.out 2025-01-06 09:57:19.796406706 +0000 366s +++ /tmp/regresscheck.785HRR/regression_output/results/bidirectional.out 2025-01-06 09:58:11.856115664 +0000 366s @@ -23,7 +23,7 @@ 366s forward_origins := '{}'); 366s create_subscription 366s --------------------- 366s - 4269973126 366s + 427419238 366s (1 row) 366s 366s BEGIN; 366s diff -U3 /tmp/regresscheck.785HRR/expected/interfaces.out /tmp/regresscheck.785HRR/regression_output/results/interfaces.out 366s --- /tmp/regresscheck.785HRR/expected/interfaces.out 2025-01-06 09:57:19.796406706 +0000 366s +++ /tmp/regresscheck.785HRR/regression_output/results/interfaces.out 2025-01-06 09:58:12.196115383 +0000 366s @@ -6,7 +6,7 @@ 366s SELECT * FROM pglogical.alter_node_add_interface('test_provider', 'super2', (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=super2'); 366s alter_node_add_interface 366s -------------------------- 366s - 3319308158 366s + 1597668009 366s (1 row) 366s 366s SELECT * FROM pglogical.alter_subscription_interface('test_subscription', 'super2'); 366s diff -U3 /tmp/regresscheck.785HRR/expected/parallel.out /tmp/regresscheck.785HRR/regression_output/results/parallel.out 366s --- /tmp/regresscheck.785HRR/expected/parallel.out 2025-01-06 09:57:19.796406706 +0000 366s +++ /tmp/regresscheck.785HRR/regression_output/results/parallel.out 2025-01-06 09:58:30.836122375 +0000 366s @@ -4,7 +4,7 @@ 366s SELECT * FROM pglogical.create_replication_set('parallel'); 366s create_replication_set 366s ------------------------ 366s - 3731651575 366s + 2651258374 366s (1 row) 366s 366s \c :subscriber_dsn 366s @@ -27,7 +27,7 @@ 366s ); 366s create_subscription 366s --------------------- 366s - 4051189029 366s + 3093400622 366s (1 row) 366s 366s BEGIN; 366s @@ -42,15 +42,15 @@ 366s SELECT sync_kind, sync_subid, sync_nspname, sync_relname, sync_status IN ('y', 'r') FROM pglogical.local_sync_status ORDER BY 2,3,4; 366s sync_kind | sync_subid | sync_nspname | sync_relname | ?column? 366s -----------+------------+--------------+--------------+---------- 366s - f | 3848008564 | | | t 366s - i | 4051189029 | | | t 366s + f | 2208722835 | | | t 366s + i | 3093400622 | | | t 366s (2 rows) 366s 366s SELECT * FROM pglogical.show_subscription_status(); 366s subscription_name | status | provider_node | provider_dsn | slot_name | replication_sets | forward_origins 366s ----------------------------+-------------+---------------+------------------------------+--------------------------------------------+---------------------------------------+----------------- 366s - test_subscription | replicating | test_provider | dbname=regression user=super | pgl_postgres_test_provider_test_sube55bf37 | {default,default_insert_only,ddl_sql} | 366s - test_subscription_parallel | replicating | test_provider | dbname=regression user=super | pgl_postgres_test_provider_test_subf1783d2 | {parallel} | 366s + test_subscription | replicating | test_provider | dbname=regression user=super | pgl_postgres_test_provider_test_sub83a66f9 | {default,default_insert_only,ddl_sql} | 366s + test_subscription_parallel | replicating | test_provider | dbname=regression user=super | pgl_postgres_test_provider_test_subb8618c2 | {parallel} | 366s (2 rows) 366s 366s -- Make sure we see the slot and active connection 366s diff -U3 /tmp/regresscheck.785HRR/expected/apply_delay.out /tmp/regresscheck.785HRR/regression_output/results/apply_delay.out 366s --- /tmp/regresscheck.785HRR/expected/apply_delay.out 2025-01-06 09:57:19.796406706 +0000 366s +++ /tmp/regresscheck.785HRR/regression_output/results/apply_delay.out 2025-01-06 09:59:18.336258112 +0000 366s @@ -13,7 +13,7 @@ 366s SELECT * FROM pglogical.create_replication_set('delay'); 366s create_replication_set 366s ------------------------ 366s - 3064111751 366s + 2893814808 366s (1 row) 366s 366s \c :subscriber_dsn 366s @@ -31,7 +31,7 @@ 366s ); 366s create_subscription 366s --------------------- 366s - 1550781037 366s + 2943762286 366s (1 row) 366s 366s BEGIN; 366s @@ -46,8 +46,8 @@ 366s SELECT sync_kind, sync_subid, sync_nspname, sync_relname, sync_status IN ('y', 'r') FROM pglogical.local_sync_status ORDER BY 2,3,4; 366s sync_kind | sync_subid | sync_nspname | sync_relname | ?column? 366s -----------+------------+--------------+--------------+---------- 366s - i | 1550781037 | | | t 366s - f | 3848008564 | | | t 366s + f | 2208722835 | | | t 366s + i | 2943762286 | | | t 366s (2 rows) 366s 366s SELECT status FROM pglogical.show_subscription_status() WHERE subscription_name = 'test_subscription_delay'; 366s diff -U3 /tmp/regresscheck.785HRR/expected/node_origin_cascade.out /tmp/regresscheck.785HRR/regression_output/results/node_origin_cascade.out 366s --- /tmp/regresscheck.785HRR/expected/node_origin_cascade.out 2025-01-06 09:57:19.796406706 +0000 366s +++ /tmp/regresscheck.785HRR/regression_output/results/node_origin_cascade.out 2025-01-06 09:59:21.626263091 +0000 366s @@ -31,7 +31,7 @@ 366s SELECT * FROM pglogical.create_node(node_name := 'test_orig_provider', dsn := (SELECT orig_provider_dsn FROM pglogical_regress_variables()) || ' user=super'); 366s create_node 366s ------------- 366s - 4029216451 366s + 3047209138 366s (1 row) 366s 366s \c :provider_dsn 366s @@ -45,7 +45,7 @@ 366s forward_origins := '{}'); 366s create_subscription 366s --------------------- 366s - 3575176667 366s + 1728723354 366s (1 row) 366s 366s COMMIT; 366s @@ -67,7 +67,7 @@ 366s SELECT sync_kind, sync_subid, sync_nspname, sync_relname, sync_status IN ('y', 'r') FROM pglogical.local_sync_status ORDER BY 2,3,4; 366s sync_kind | sync_subid | sync_nspname | sync_relname | ?column? 366s -----------+------------+--------------+--------------+---------- 366s - d | 3575176667 | | | t 366s + d | 1728723354 | | | t 366s (1 row) 366s 366s -- Make sure we see the slot and active connection 366s *** regression_output/log/initdb.log *** 366s Running in no-clean mode. Mistakes will not be cleaned up. 366s The files belonging to this database system will be owned by user "ubuntu". 366s This user must also own the server process. 366s 366s The database cluster will be initialized with this locale configuration: 366s provider: libc 366s LC_COLLATE: C.UTF-8 366s LC_CTYPE: C.UTF-8 366s LC_MESSAGES: C 366s LC_MONETARY: C.UTF-8 366s LC_NUMERIC: C.UTF-8 366s LC_TIME: C.UTF-8 366s The default database encoding has accordingly been set to "UTF8". 366s The default text search configuration will be set to "english". 366s 366s Data page checksums are disabled. 366s 366s creating directory /tmp/regresscheck.785HRR/tmp_check/data ... ok 366s creating subdirectories ... ok 366s selecting dynamic shared memory implementation ... posix 366s selecting default max_connections ... 100 366s selecting default shared_buffers ... 128MB 366s selecting default time zone ... Etc/UTC 366s creating configuration files ... ok 366s running bootstrap script ... ok 366s performing post-bootstrap initialization ... ok 366s 366s Sync to disk skipped. 366s The data directory might become corrupt if the operating system crashes. 366s 366s initdb: warning: enabling "trust" authentication for local connections 366s initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb. 366s 366s Success. You can now start the database server using: 366s 366s pg_ctl -D /tmp/regresscheck.785HRR/tmp_check/data -l logfile start 366s 366s *** regression_output/log/postmaster.log *** 366s [2025-01-06 09:57:20.282 UTC] [3689] [] LOG: starting PostgreSQL 16.4 (Ubuntu 16.4-3) on s390x-ibm-linux-gnu, compiled by gcc (Ubuntu 14.2.0-7ubuntu1) 14.2.0, 64-bit 366s [2025-01-06 09:57:20.282 UTC] [3689] [] LOG: listening on Unix socket "/tmp/pg_regress-Mj8rMG/.s.PGSQL.61700" 366s [2025-01-06 09:57:20.283 UTC] [3694] [] LOG: database system was shut down at 2025-01-06 09:57:20 UTC 366s [2025-01-06 09:57:20.286 UTC] [3689] [] LOG: database system is ready to accept connections 366s [2025-01-06 09:57:20.286 UTC] [3697] [] LOG: starting pglogical supervisor 366s [2025-01-06 09:57:20.289 UTC] [3699] [postgres] LOG: manager worker [3699] at slot 0 generation 1 detaching cleanly 366s [2025-01-06 09:57:20.293 UTC] [3700] [template1] LOG: manager worker [3700] at slot 0 generation 2 detaching cleanly 366s [2025-01-06 09:57:21.497 UTC] [3725] [postgres] ERROR: local pglogical node not found 366s [2025-01-06 09:57:21.497 UTC] [3725] [postgres] STATEMENT: SELECT * FROM pglogical.create_subscription( 366s subscription_name := 'test_subscription', 366s provider_dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=nonreplica', 366s forward_origins := '{}'); 366s [2025-01-06 09:57:21.499 UTC] [3727] [regression] FATAL: role "nonexisting" does not exist 366s [2025-01-06 09:57:21.499 UTC] [3726] [postgres] LOG: starting pglogical database manager for database postgres 366s [2025-01-06 09:57:21.499 UTC] [3725] [postgres] ERROR: could not connect to the postgresql server: FATAL: role "nonexisting" does not exist 366s 366s [2025-01-06 09:57:21.499 UTC] [3725] [postgres] CONTEXT: PL/pgSQL function inline_code_block line 9 at RAISE 366s [2025-01-06 09:57:21.499 UTC] [3725] [postgres] STATEMENT: DO $$ 366s BEGIN 366s SELECT * FROM pglogical.create_subscription( 366s subscription_name := 'test_subscription', 366s provider_dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=nonexisting', 366s forward_origins := '{}'); 366s EXCEPTION 366s WHEN OTHERS THEN 366s RAISE EXCEPTION '%:%', split_part(SQLERRM, ':', 1), (regexp_matches(SQLERRM, '^.*( FATAL:.*role.*)$'))[1]; 366s END; 366s $$; 366s [2025-01-06 09:57:21.501 UTC] [3728] [regression] ERROR: local pglogical node not found 366s [2025-01-06 09:57:21.501 UTC] [3728] [regression] STATEMENT: SELECT node_id, node_name, sysid, dbname, replication_sets FROM pglogical.pglogical_node_info() 366s [2025-01-06 09:57:21.501 UTC] [3725] [postgres] ERROR: could not fetch remote node info: ERROR: local pglogical node not found 366s 366s 366s [2025-01-06 09:57:21.501 UTC] [3725] [postgres] STATEMENT: SELECT * FROM pglogical.create_subscription( 366s subscription_name := 'test_subscription', 366s provider_dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=nonreplica', 366s forward_origins := '{}'); 366s [2025-01-06 09:57:21.506 UTC] [3730] [template1] LOG: manager worker [3730] at slot 1 generation 1 detaching cleanly 366s [2025-01-06 09:57:21.509 UTC] [3732] [regression] LOG: starting pglogical database manager for database regression 366s [2025-01-06 09:57:21.512 UTC] [3734] [regression] FATAL: permission denied to start WAL sender 366s [2025-01-06 09:57:21.512 UTC] [3734] [regression] DETAIL: Only roles with the REPLICATION attribute may start a WAL sender process. 366s [2025-01-06 09:57:21.513 UTC] [3731] [postgres] ERROR: could not connect to the postgresql server in replication mode 366s [2025-01-06 09:57:21.513 UTC] [3731] [postgres] CONTEXT: PL/pgSQL function inline_code_block line 9 at RAISE 366s [2025-01-06 09:57:21.513 UTC] [3731] [postgres] STATEMENT: DO $$ 366s BEGIN 366s SELECT * FROM pglogical.create_subscription( 366s subscription_name := 'test_subscription', 366s provider_dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=nonreplica', 366s forward_origins := '{}'); 366s EXCEPTION 366s WHEN OTHERS THEN 366s RAISE EXCEPTION '%', split_part(SQLERRM, ':', 1); 366s END; 366s $$; 366s [2025-01-06 09:57:21.514 UTC] [3726] [postgres] LOG: manager worker [3726] at slot 0 generation 3 detaching cleanly 366s [2025-01-06 09:57:21.516 UTC] [3735] [regression1] LOG: manager worker [3735] at slot 2 generation 1 detaching cleanly 366s [2025-01-06 09:57:21.523 UTC] [3737] [sourcedb] LOG: manager worker [3737] at slot 0 generation 4 detaching cleanly 366s [2025-01-06 09:57:21.525 UTC] [3732] [regression] LOG: manager worker [3732] at slot 1 generation 2 detaching cleanly 366s [2025-01-06 09:57:21.528 UTC] [3738] [postgres] LOG: manager worker [3738] at slot 0 generation 5 detaching cleanly 366s [2025-01-06 09:57:21.530 UTC] [3739] [template1] LOG: manager worker [3739] at slot 0 generation 6 detaching cleanly 366s [2025-01-06 09:57:21.532 UTC] [3740] [regression] LOG: manager worker [3740] at slot 0 generation 7 detaching cleanly 366s [2025-01-06 09:57:21.535 UTC] [3742] [regression1] LOG: manager worker [3742] at slot 0 generation 8 detaching cleanly 366s [2025-01-06 09:57:21.537 UTC] [3747] [sourcedb] LOG: manager worker [3747] at slot 0 generation 9 detaching cleanly 366s [2025-01-06 09:57:21.577 UTC] [3754] [postgres] LOG: manager worker [3754] at slot 0 generation 10 detaching cleanly 366s [2025-01-06 09:57:21.580 UTC] [3756] [template1] LOG: manager worker [3756] at slot 0 generation 11 detaching cleanly 366s [2025-01-06 09:57:21.582 UTC] [3757] [regression] LOG: starting pglogical database manager for database regression 366s [2025-01-06 09:57:21.591 UTC] [3758] [regression1] LOG: manager worker [3758] at slot 1 generation 3 detaching cleanly 366s [2025-01-06 09:57:21.594 UTC] [3759] [sourcedb] LOG: manager worker [3759] at slot 1 generation 4 detaching cleanly 366s [2025-01-06 09:57:21.601 UTC] [3763] [postgres] LOG: starting pglogical database manager for database postgres 366s [2025-01-06 09:57:21.602 UTC] [3764] [template1] LOG: manager worker [3764] at slot 3 generation 1 detaching cleanly 366s [2025-01-06 09:57:21.603 UTC] [3765] [postgres] LOG: starting apply for subscription test_subscription 366s [2025-01-06 09:57:21.605 UTC] [3767] [regression1] LOG: manager worker [3767] at slot 3 generation 2 detaching cleanly 366s [2025-01-06 09:57:21.607 UTC] [3768] [sourcedb] LOG: manager worker [3768] at slot 3 generation 3 detaching cleanly 366s [2025-01-06 09:57:21.611 UTC] [3769] [regression] LOG: logical decoding found consistent point at 0/2488518 366s [2025-01-06 09:57:21.611 UTC] [3769] [regression] DETAIL: There are no running transactions. 366s [2025-01-06 09:57:21.611 UTC] [3769] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL pglogical_output 366s [2025-01-06 09:57:21.611 UTC] [3769] [regression] LOG: exported logical decoding snapshot: "00000009-00000008-1" with 0 transaction IDs 366s [2025-01-06 09:57:21.611 UTC] [3769] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL pglogical_output 366s [2025-01-06 09:57:21.692 UTC] [3784] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9" 366s [2025-01-06 09:57:21.692 UTC] [3784] [regression] DETAIL: Streaming transactions committing after 0/2488550, reading WAL from 0/2488518. 366s [2025-01-06 09:57:21.692 UTC] [3784] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/2488550 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" '"default",default_insert_only,ddl_sql', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '3765') 366s [2025-01-06 09:57:21.692 UTC] [3784] [regression] LOG: logical decoding found consistent point at 0/2488518 366s [2025-01-06 09:57:21.692 UTC] [3784] [regression] DETAIL: There are no running transactions. 366s [2025-01-06 09:57:21.692 UTC] [3784] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/2488550 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" '"default",default_insert_only,ddl_sql', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '3765') 366s [2025-01-06 09:57:50.307 UTC] [3692] [] LOG: checkpoint starting: time 366s [2025-01-06 09:58:03.469 UTC] [3948] [regression] ERROR: duplicate key value violates unique constraint "secondary_unique_pred_b_idx" 366s [2025-01-06 09:58:03.469 UTC] [3948] [regression] DETAIL: Key (b)=(2) already exists. 366s [2025-01-06 09:58:03.469 UTC] [3948] [regression] STATEMENT: INSERT INTO secondary_unique_pred (a, b, check_unique) VALUES (5, 2, true); 366s [2025-01-06 09:58:06.537 UTC] [3966] [regression] ERROR: replication set nonexisting not found 366s [2025-01-06 09:58:06.537 UTC] [3966] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('nonexisting', 'test_publicschema'); 366s [2025-01-06 09:58:06.538 UTC] [3966] [regression] ERROR: UNLOGGED and TEMP tables cannot be replicated 366s [2025-01-06 09:58:06.538 UTC] [3966] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('repset_replicate_all', 'test_unlogged'); 366s [2025-01-06 09:58:06.538 UTC] [3966] [regression] ERROR: table test_nopkey cannot be added to replication set repset_replicate_all 366s [2025-01-06 09:58:06.538 UTC] [3966] [regression] DETAIL: table does not have PRIMARY KEY and given replication set is configured to replicate UPDATEs and/or DELETEs 366s [2025-01-06 09:58:06.538 UTC] [3966] [regression] HINT: Add a PRIMARY KEY to the table 366s [2025-01-06 09:58:06.538 UTC] [3966] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('repset_replicate_all', 'test_nopkey'); 366s [2025-01-06 09:58:06.538 UTC] [3966] [regression] ERROR: table test_nopkey cannot be added to replication set repset_replicate_insupd 366s [2025-01-06 09:58:06.538 UTC] [3966] [regression] DETAIL: table does not have PRIMARY KEY and given replication set is configured to replicate UPDATEs and/or DELETEs 366s [2025-01-06 09:58:06.538 UTC] [3966] [regression] HINT: Add a PRIMARY KEY to the table 366s [2025-01-06 09:58:06.538 UTC] [3966] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('repset_replicate_insupd', 'test_nopkey'); 366s [2025-01-06 09:58:06.538 UTC] [3966] [regression] ERROR: table test_nopkey cannot be added to replication set default 366s [2025-01-06 09:58:06.538 UTC] [3966] [regression] DETAIL: table does not have PRIMARY KEY and given replication set is configured to replicate UPDATEs and/or DELETEs 366s [2025-01-06 09:58:06.538 UTC] [3966] [regression] HINT: Add a PRIMARY KEY to the table 366s [2025-01-06 09:58:06.538 UTC] [3966] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_all_tables('default', '{public}'); 366s [2025-01-06 09:58:06.538 UTC] [3966] [regression] ERROR: replication set repset_replicate_instrunc cannot be altered to replicate UPDATEs or DELETEs because it contains tables without PRIMARY KEY 366s [2025-01-06 09:58:06.538 UTC] [3966] [regression] STATEMENT: SELECT * FROM pglogical.alter_replication_set('repset_replicate_instrunc', replicate_update := true); 366s [2025-01-06 09:58:06.539 UTC] [3966] [regression] ERROR: replication set repset_replicate_instrunc cannot be altered to replicate UPDATEs or DELETEs because it contains tables without PRIMARY KEY 366s [2025-01-06 09:58:06.539 UTC] [3966] [regression] STATEMENT: SELECT * FROM pglogical.alter_replication_set('repset_replicate_instrunc', replicate_delete := true); 366s [2025-01-06 09:58:06.539 UTC] [3966] [regression] ERROR: duplicate key value violates unique constraint "replication_set_table_pkey" 366s [2025-01-06 09:58:06.539 UTC] [3966] [regression] DETAIL: Key (set_id, set_reloid)=(3885206554, 17823) already exists. 366s [2025-01-06 09:58:06.539 UTC] [3966] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('repset_replicate_all', 'public.test_publicschema'); 366s [2025-01-06 09:58:06.540 UTC] [3966] [regression] ERROR: replication set name cannot be empty 366s [2025-01-06 09:58:06.540 UTC] [3966] [regression] STATEMENT: SELECT pglogical.create_replication_set(''); 366s [2025-01-06 09:58:06.540 UTC] [3966] [regression] ERROR: cannot drop table test_publicschema because other objects depend on it 366s [2025-01-06 09:58:06.540 UTC] [3966] [regression] DETAIL: table test_publicschema membership in replication set default_insert_only depends on table test_publicschema 366s table test_publicschema membership in replication set repset_replicate_all depends on table test_publicschema 366s [2025-01-06 09:58:06.540 UTC] [3966] [regression] HINT: Use DROP ... CASCADE to drop the dependent objects too. 366s [2025-01-06 09:58:06.540 UTC] [3966] [regression] STATEMENT: DROP TABLE public.test_publicschema; 366s [2025-01-06 09:58:06.541 UTC] [3966] [regression] ERROR: cannot drop table public.test_publicschema because other objects depend on it 366s [2025-01-06 09:58:06.541 UTC] [3966] [regression] DETAIL: table public.test_publicschema membership in replication set default_insert_only depends on table public.test_publicschema 366s table public.test_publicschema membership in replication set repset_replicate_all depends on table public.test_publicschema 366s [2025-01-06 09:58:06.541 UTC] [3966] [regression] HINT: Use DROP ... CASCADE to drop the dependent objects too. 366s [2025-01-06 09:58:06.541 UTC] [3966] [regression] CONTEXT: during execution of queued SQL statement: 366s DROP TABLE public.test_publicschema; 366s 366s [2025-01-06 09:58:06.541 UTC] [3966] [regression] STATEMENT: 366s DROP TABLE public.test_publicschema; 366s 366s [2025-01-06 09:58:09.619 UTC] [3988] [template1] LOG: manager worker [3988] at slot 3 generation 4 detaching cleanly 366s [2025-01-06 09:58:09.619 UTC] [3989] [regression] LOG: starting apply for subscription test_bidirectional 366s [2025-01-06 09:58:09.622 UTC] [3991] [regression1] LOG: manager worker [3991] at slot 3 generation 5 detaching cleanly 366s [2025-01-06 09:58:09.624 UTC] [3992] [postgres] LOG: logical decoding found consistent point at 0/26FD158 366s [2025-01-06 09:58:09.624 UTC] [3992] [postgres] DETAIL: There are no running transactions. 366s [2025-01-06 09:58:09.624 UTC] [3992] [postgres] STATEMENT: CREATE_REPLICATION_SLOT "pgl_regression_test_subscriber_test_bid1979e66" LOGICAL pglogical_output 366s [2025-01-06 09:58:09.624 UTC] [3992] [postgres] LOG: exported logical decoding snapshot: "0000000B-00000005-1" with 0 transaction IDs 366s [2025-01-06 09:58:09.624 UTC] [3992] [postgres] STATEMENT: CREATE_REPLICATION_SLOT "pgl_regression_test_subscriber_test_bid1979e66" LOGICAL pglogical_output 366s [2025-01-06 09:58:09.625 UTC] [3993] [sourcedb] LOG: manager worker [3993] at slot 3 generation 6 detaching cleanly 366s [2025-01-06 09:58:09.627 UTC] [3994] [postgres] LOG: starting logical decoding for slot "pgl_regression_test_subscriber_test_bid1979e66" 366s [2025-01-06 09:58:09.627 UTC] [3994] [postgres] DETAIL: Streaming transactions committing after 0/26FD190, reading WAL from 0/26FD158. 366s [2025-01-06 09:58:09.627 UTC] [3994] [postgres] STATEMENT: START_REPLICATION SLOT "pgl_regression_test_subscriber_test_bid1979e66" LOGICAL 0/26FD190 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" '"default",default_insert_only,ddl_sql', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '3989') 366s [2025-01-06 09:58:09.627 UTC] [3994] [postgres] LOG: logical decoding found consistent point at 0/26FD158 366s [2025-01-06 09:58:09.627 UTC] [3994] [postgres] DETAIL: There are no running transactions. 366s [2025-01-06 09:58:09.627 UTC] [3994] [postgres] STATEMENT: START_REPLICATION SLOT "pgl_regression_test_subscriber_test_bid1979e66" LOGICAL 0/26FD190 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" '"default",default_insert_only,ddl_sql', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '3989') 366s [2025-01-06 09:58:11.840 UTC] [3989] [regression] LOG: CONFLICT: remote UPDATE on relation public.basic_dml (local index basic_dml_pkey). Resolution: apply_remote. 366s [2025-01-06 09:58:11.840 UTC] [3989] [regression] DETAIL: existing local tuple {id[int4]:1 other[int4]:5 data[text]:foo something[interval]:00:01:00} xid=1055,origin=0,timestamp=2025-01-06 09:58:10.833337+00; remote tuple {id[int4]:1 other[int4]:1 data[text]:foo something[interval]:00:00:50} in xact origin=2,timestamp=2025-01-06 09:58:11.840251+00,commit_lsn=0/2716CF0 366s [2025-01-06 09:58:11.840 UTC] [3989] [regression] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/2716CF0, xid 1057 committed at 2025-01-06 09:58:11.840251+00 (action #2) from node replorigin 2 366s [2025-01-06 09:58:11.840 UTC] [3989] [regression] LOG: CONFLICT: remote UPDATE on relation public.basic_dml (local index basic_dml_pkey). Resolution: apply_remote. 366s [2025-01-06 09:58:11.840 UTC] [3989] [regression] DETAIL: existing local tuple {id[int4]:2 other[int4]:4 data[text]:bar something[interval]:84 days} xid=1055,origin=0,timestamp=2025-01-06 09:58:10.833337+00; remote tuple {id[int4]:2 other[int4]:2 data[text]:bar something[interval]:84 days -00:00:10} in xact origin=2,timestamp=2025-01-06 09:58:11.840251+00,commit_lsn=0/2716CF0 366s [2025-01-06 09:58:11.840 UTC] [3989] [regression] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/2716CF0, xid 1057 committed at 2025-01-06 09:58:11.840251+00 (action #3) from node replorigin 2 366s [2025-01-06 09:58:11.840 UTC] [3989] [regression] LOG: CONFLICT: remote UPDATE on relation public.basic_dml (local index basic_dml_pkey). Resolution: apply_remote. 366s [2025-01-06 09:58:11.840 UTC] [3989] [regression] DETAIL: existing local tuple {id[int4]:4 other[int4]:2 data[text]:qux something[interval]:8 mons 2 days} xid=1055,origin=0,timestamp=2025-01-06 09:58:10.833337+00; remote tuple {id[int4]:4 other[int4]:4 data[text]:qux something[interval]:8 mons 2 days 00:00:10} in xact origin=2,timestamp=2025-01-06 09:58:11.840412+00,commit_lsn=0/2716DD8 366s [2025-01-06 09:58:11.840 UTC] [3989] [regression] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/2716DD8, xid 1058 committed at 2025-01-06 09:58:11.840412+00 (action #2) from node replorigin 2 366s [2025-01-06 09:58:11.840 UTC] [3989] [regression] LOG: CONFLICT: remote UPDATE on relation public.basic_dml (local index basic_dml_pkey). Resolution: apply_remote. 366s [2025-01-06 09:58:11.840 UTC] [3989] [regression] DETAIL: existing local tuple {id[int4]:5 other[int4]:1 data[text]:(null) something[interval]:(null)} xid=1055,origin=0,timestamp=2025-01-06 09:58:10.833337+00; remote tuple {id[int4]:5 other[int4]:5 data[text]:(null) something[interval]:(null)} in xact origin=2,timestamp=2025-01-06 09:58:11.840412+00,commit_lsn=0/2716DD8 366s [2025-01-06 09:58:11.840 UTC] [3989] [regression] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/2716DD8, xid 1058 committed at 2025-01-06 09:58:11.840412+00 (action #3) from node replorigin 2 366s [2025-01-06 09:58:11.850 UTC] [3989] [regression] LOG: apply worker [3989] at slot 4 generation 1 detaching cleanly 366s [2025-01-06 09:58:11.856 UTC] [4001] [template1] LOG: manager worker [4001] at slot 3 generation 7 detaching cleanly 366s [2025-01-06 09:58:11.860 UTC] [4003] [regression1] LOG: manager worker [4003] at slot 3 generation 8 detaching cleanly 366s [2025-01-06 09:58:11.862 UTC] [4004] [sourcedb] LOG: manager worker [4004] at slot 3 generation 9 detaching cleanly 366s [2025-01-06 09:58:11.875 UTC] [3765] [postgres] LOG: apply worker [3765] at slot 2 generation 2 detaching cleanly 366s [2025-01-06 09:58:11.876 UTC] [4013] [template1] LOG: manager worker [4013] at slot 3 generation 10 detaching cleanly 366s [2025-01-06 09:58:11.879 UTC] [4014] [regression1] LOG: manager worker [4014] at slot 2 generation 3 detaching cleanly 366s [2025-01-06 09:58:11.880 UTC] [4015] [postgres] LOG: starting apply for subscription test_subscription 366s [2025-01-06 09:58:11.882 UTC] [4016] [sourcedb] LOG: manager worker [4016] at slot 3 generation 11 detaching cleanly 366s [2025-01-06 09:58:11.882 UTC] [4017] [regression] LOG: 0/2719F58 has been already streamed, forwarding to 0/271E620 366s [2025-01-06 09:58:11.882 UTC] [4017] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/2719F58 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" '"default",default_insert_only,ddl_sql', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '4015') 366s [2025-01-06 09:58:11.883 UTC] [4017] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9" 366s [2025-01-06 09:58:11.883 UTC] [4017] [regression] DETAIL: Streaming transactions committing after 0/271E620, reading WAL from 0/26FD158. 366s [2025-01-06 09:58:11.883 UTC] [4017] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/2719F58 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" '"default",default_insert_only,ddl_sql', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '4015') 366s [2025-01-06 09:58:11.883 UTC] [4017] [regression] LOG: logical decoding found consistent point at 0/26FD158 366s [2025-01-06 09:58:11.883 UTC] [4017] [regression] DETAIL: There are no running transactions. 366s [2025-01-06 09:58:11.883 UTC] [4017] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/2719F58 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" '"default",default_insert_only,ddl_sql', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '4015') 366s [2025-01-06 09:58:12.092 UTC] [4015] [postgres] LOG: apply worker [4015] at slot 2 generation 4 detaching cleanly 366s [2025-01-06 09:58:12.093 UTC] [4020] [template1] LOG: manager worker [4020] at slot 2 generation 5 detaching cleanly 366s [2025-01-06 09:58:12.094 UTC] [4021] [postgres] LOG: starting apply for subscription test_subscription 366s [2025-01-06 09:58:12.095 UTC] [4022] [regression1] LOG: manager worker [4022] at slot 3 generation 12 detaching cleanly 366s [2025-01-06 09:58:12.097 UTC] [4023] [regression] LOG: 0/2719F58 has been already streamed, forwarding to 0/271E9E0 366s [2025-01-06 09:58:12.097 UTC] [4023] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/2719F58 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" '"default",default_insert_only,ddl_sql', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '4021') 366s [2025-01-06 09:58:12.097 UTC] [4023] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9" 366s [2025-01-06 09:58:12.097 UTC] [4023] [regression] DETAIL: Streaming transactions committing after 0/271E9E0, reading WAL from 0/26FD158. 366s [2025-01-06 09:58:12.097 UTC] [4023] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/2719F58 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" '"default",default_insert_only,ddl_sql', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '4021') 366s [2025-01-06 09:58:12.097 UTC] [4023] [regression] LOG: logical decoding found consistent point at 0/26FD158 366s [2025-01-06 09:58:12.097 UTC] [4023] [regression] DETAIL: There are no running transactions. 366s [2025-01-06 09:58:12.097 UTC] [4023] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/2719F58 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" '"default",default_insert_only,ddl_sql', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '4021') 366s [2025-01-06 09:58:12.098 UTC] [4024] [sourcedb] LOG: manager worker [4024] at slot 3 generation 13 detaching cleanly 366s [2025-01-06 09:58:17.015 UTC] [3692] [] LOG: checkpoint complete: wrote 3158 buffers (19.3%); 0 WAL file(s) added, 0 removed, 1 recycled; write=26.707 s, sync=0.001 s, total=26.709 s; sync files=0, longest=0.000 s, average=0.000 s; distance=16910 kB, estimate=16910 kB; lsn=0/275BC08, redo lsn=0/2572C30 366s [2025-01-06 09:58:20.020 UTC] [3692] [] LOG: checkpoint starting: time 366s [2025-01-06 09:58:20.310 UTC] [4051] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_type" 366s avg read rate: 6.010 MB/s, avg write rate: 6.010 MB/s 366s buffer usage: 1072 hits, 10 misses, 10 dirtied 366s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s 366s [2025-01-06 09:58:20.316 UTC] [4051] [] LOG: automatic vacuum of table "postgres.pg_catalog.pg_attribute": index scans: 1 366s pages: 0 removed, 78 remain, 40 scanned (51.28% of total) 366s tuples: 808 removed, 3339 remain, 0 are dead but not yet removable 366s removable cutoff: 1117, which was 8 XIDs old when operation ended 366s new relfrozenxid: 789, which is 67 XIDs ahead of previous value 366s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 366s index scan needed: 20 pages from table (25.64% of total) had 913 dead item identifiers removed 366s index "pg_attribute_relid_attnam_index": pages: 21 in total, 2 newly deleted, 2 currently deleted, 0 reusable 366s index "pg_attribute_relid_attnum_index": pages: 14 in total, 1 newly deleted, 1 currently deleted, 0 reusable 366s avg read rate: 23.164 MB/s, avg write rate: 29.341 MB/s 366s buffer usage: 159 hits, 15 misses, 19 dirtied 366s WAL usage: 80 records, 34 full page images, 91127 bytes 366s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 366s [2025-01-06 09:58:20.327 UTC] [4051] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_attribute" 366s avg read rate: 18.229 MB/s, avg write rate: 5.208 MB/s 366s buffer usage: 549 hits, 28 misses, 8 dirtied 366s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s 366s [2025-01-06 09:58:20.328 UTC] [4051] [] LOG: automatic vacuum of table "postgres.pg_catalog.pg_class": index scans: 1 366s pages: 0 removed, 17 remain, 17 scanned (100.00% of total) 366s tuples: 74 removed, 455 remain, 1 are dead but not yet removable 366s removable cutoff: 1117, which was 9 XIDs old when operation ended 366s new relfrozenxid: 789, which is 67 XIDs ahead of previous value 366s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 366s index scan needed: 11 pages from table (64.71% of total) had 190 dead item identifiers removed 366s index "pg_class_oid_index": pages: 4 in total, 0 newly deleted, 0 currently deleted, 0 reusable 366s index "pg_class_relname_nsp_index": pages: 7 in total, 0 newly deleted, 0 currently deleted, 0 reusable 366s index "pg_class_tblspc_relfilenode_index": pages: 4 in total, 0 newly deleted, 0 currently deleted, 0 reusable 366s avg read rate: 0.000 MB/s, avg write rate: 172.516 MB/s 366s buffer usage: 99 hits, 0 misses, 7 dirtied 366s WAL usage: 38 records, 14 full page images, 61632 bytes 366s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 366s [2025-01-06 09:58:20.334 UTC] [4051] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_class" 366s avg read rate: 2.604 MB/s, avg write rate: 5.208 MB/s 366s buffer usage: 554 hits, 2 misses, 4 dirtied 366s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 366s [2025-01-06 09:58:20.338 UTC] [4051] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_constraint" 366s avg read rate: 5.859 MB/s, avg write rate: 5.859 MB/s 366s buffer usage: 555 hits, 3 misses, 3 dirtied 366s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 366s [2025-01-06 09:58:20.339 UTC] [4051] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_index" 366s avg read rate: 7.812 MB/s, avg write rate: 15.625 MB/s 366s buffer usage: 368 hits, 1 misses, 2 dirtied 366s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 366s [2025-01-06 09:58:20.339 UTC] [4051] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_trigger" 366s avg read rate: 0.000 MB/s, avg write rate: 7.812 MB/s 366s buffer usage: 252 hits, 0 misses, 1 dirtied 366s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 366s [2025-01-06 09:58:20.342 UTC] [4051] [] LOG: automatic vacuum of table "postgres.pg_catalog.pg_depend": index scans: 1 366s pages: 0 removed, 19 remain, 19 scanned (100.00% of total) 366s tuples: 440 removed, 1975 remain, 0 are dead but not yet removable 366s removable cutoff: 1117, which was 13 XIDs old when operation ended 366s new relfrozenxid: 789, which is 67 XIDs ahead of previous value 366s frozen: 3 pages from table (15.79% of total) had 135 tuples frozen 366s index scan needed: 8 pages from table (42.11% of total) had 622 dead item identifiers removed 366s index "pg_depend_depender_index": pages: 15 in total, 0 newly deleted, 0 currently deleted, 0 reusable 366s index "pg_depend_reference_index": pages: 10 in total, 0 newly deleted, 0 currently deleted, 0 reusable 366s avg read rate: 40.202 MB/s, avg write rate: 32.161 MB/s 366s buffer usage: 108 hits, 15 misses, 12 dirtied 366s WAL usage: 42 records, 20 full page images, 79459 bytes 366s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 366s [2025-01-06 09:58:20.346 UTC] [4051] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_depend" 366s avg read rate: 0.000 MB/s, avg write rate: 4.688 MB/s 366s buffer usage: 126 hits, 0 misses, 3 dirtied 366s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 366s [2025-01-06 09:58:22.324 UTC] [4021] [postgres] ERROR: null value in column "id2" of relation "not_nullcheck_tbl" violates not-null constraint 366s [2025-01-06 09:58:22.324 UTC] [4021] [postgres] DETAIL: Failing row contains (1, 1, name1, null). 366s [2025-01-06 09:58:22.324 UTC] [4021] [postgres] CONTEXT: apply INSERT from remote relation public.not_nullcheck_tbl in commit before 0/2827BF0, xid 1136 committed at 2025-01-06 09:58:22.324117+00 (action #2) from node replorigin 1 366s [2025-01-06 09:58:22.324 UTC] [4021] [postgres] LOG: apply worker [4021] at slot 2 generation 6 exiting with error 366s [2025-01-06 09:58:22.326 UTC] [4023] [regression] LOG: could not receive data from client: Connection reset by peer 366s [2025-01-06 09:58:22.326 UTC] [4023] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/2719F58 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" '"default",default_insert_only,ddl_sql', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '4021') 366s [2025-01-06 09:58:22.326 UTC] [4023] [regression] LOG: unexpected EOF on standby connection 366s [2025-01-06 09:58:22.326 UTC] [4023] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/2719F58 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" '"default",default_insert_only,ddl_sql', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '4021') 366s [2025-01-06 09:58:22.327 UTC] [3689] [] LOG: background worker "pglogical apply 5:2208722835" (PID 4021) exited with exit code 1 366s [2025-01-06 09:58:22.327 UTC] [4058] [postgres] ERROR: null value in column "id2" of relation "not_nullcheck_tbl" violates not-null constraint 366s [2025-01-06 09:58:22.327 UTC] [4058] [postgres] DETAIL: Failing row contains (3, 3, name3, null). 366s [2025-01-06 09:58:22.327 UTC] [4058] [postgres] STATEMENT: INSERT INTO public.not_nullcheck_tbl(id,id1,name) VALUES (3,3,'name3'); 366s [2025-01-06 09:58:22.329 UTC] [4059] [template1] LOG: manager worker [4059] at slot 3 generation 14 detaching cleanly 366s [2025-01-06 09:58:22.331 UTC] [4060] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9" 366s [2025-01-06 09:58:22.331 UTC] [4060] [regression] DETAIL: Streaming transactions committing after 0/2827B08, reading WAL from 0/2766B78. 366s [2025-01-06 09:58:22.331 UTC] [4060] [regression] STATEMENT: SELECT data::json->'action' as action, CASE WHEN data::json->>'action' IN ('I', 'D', 'U') THEN data END as data FROM pg_logical_slot_get_changes((SELECT slot_name FROM pg_replication_slots), NULL, 1, 'min_proto_version', '1', 'max_proto_version', '1', 'startup_params_format', '1', 'proto_format', 'json', 'pglogical.replication_set_names', 'default'); 366s [2025-01-06 09:58:22.332 UTC] [4060] [regression] LOG: logical decoding found consistent point at 0/2766B78 366s [2025-01-06 09:58:22.332 UTC] [4060] [regression] DETAIL: There are no running transactions. 366s [2025-01-06 09:58:22.332 UTC] [4060] [regression] STATEMENT: SELECT data::json->'action' as action, CASE WHEN data::json->>'action' IN ('I', 'D', 'U') THEN data END as data FROM pg_logical_slot_get_changes((SELECT slot_name FROM pg_replication_slots), NULL, 1, 'min_proto_version', '1', 'max_proto_version', '1', 'startup_params_format', '1', 'proto_format', 'json', 'pglogical.replication_set_names', 'default'); 366s [2025-01-06 09:58:22.333 UTC] [4061] [regression1] LOG: manager worker [4061] at slot 2 generation 7 detaching cleanly 366s [2025-01-06 09:58:22.333 UTC] [4060] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9" 366s [2025-01-06 09:58:22.333 UTC] [4060] [regression] DETAIL: Streaming transactions committing after 0/2827C20, reading WAL from 0/2766B78. 366s [2025-01-06 09:58:22.333 UTC] [4060] [regression] STATEMENT: SELECT data::json->'action' as action, CASE WHEN data::json->>'action' IN ('I', 'D', 'U') THEN data END as data FROM pg_logical_slot_get_changes((SELECT slot_name FROM pg_replication_slots), NULL, 1, 'min_proto_version', '1', 'max_proto_version', '1', 'startup_params_format', '1', 'proto_format', 'json', 'pglogical.replication_set_names', 'default'); 366s [2025-01-06 09:58:22.334 UTC] [4060] [regression] LOG: logical decoding found consistent point at 0/2766B78 366s [2025-01-06 09:58:22.334 UTC] [4060] [regression] DETAIL: There are no running transactions. 366s [2025-01-06 09:58:22.334 UTC] [4060] [regression] STATEMENT: SELECT data::json->'action' as action, CASE WHEN data::json->>'action' IN ('I', 'D', 'U') THEN data END as data FROM pg_logical_slot_get_changes((SELECT slot_name FROM pg_replication_slots), NULL, 1, 'min_proto_version', '1', 'max_proto_version', '1', 'startup_params_format', '1', 'proto_format', 'json', 'pglogical.replication_set_names', 'default'); 366s [2025-01-06 09:58:22.335 UTC] [4062] [sourcedb] LOG: manager worker [4062] at slot 2 generation 8 detaching cleanly 366s [2025-01-06 09:58:22.341 UTC] [4064] [template1] LOG: manager worker [4064] at slot 2 generation 9 detaching cleanly 366s [2025-01-06 09:58:22.343 UTC] [4066] [regression1] LOG: manager worker [4066] at slot 2 generation 10 detaching cleanly 366s [2025-01-06 09:58:22.343 UTC] [4065] [postgres] LOG: starting apply for subscription test_subscription 366s [2025-01-06 09:58:22.347 UTC] [4069] [sourcedb] LOG: manager worker [4069] at slot 2 generation 11 detaching cleanly 366s [2025-01-06 09:58:22.348 UTC] [4068] [regression] LOG: 0/280DBD0 has been already streamed, forwarding to 0/2827CD8 366s [2025-01-06 09:58:22.348 UTC] [4068] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/280DBD0 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" '"default",default_insert_only,ddl_sql', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '4065') 366s [2025-01-06 09:58:22.348 UTC] [4068] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9" 366s [2025-01-06 09:58:22.348 UTC] [4068] [regression] DETAIL: Streaming transactions committing after 0/2827CD8, reading WAL from 0/2766B78. 366s [2025-01-06 09:58:22.348 UTC] [4068] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/280DBD0 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" '"default",default_insert_only,ddl_sql', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '4065') 366s [2025-01-06 09:58:22.348 UTC] [4068] [regression] LOG: logical decoding found consistent point at 0/2766B78 366s [2025-01-06 09:58:22.348 UTC] [4068] [regression] DETAIL: There are no running transactions. 366s [2025-01-06 09:58:22.348 UTC] [4068] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/280DBD0 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" '"default",default_insert_only,ddl_sql', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '4065') 366s [2025-01-06 09:58:23.527 UTC] [4065] [postgres] WARNING: relcache reference leak: relation "test_trg_data" not closed 366s [2025-01-06 09:58:23.527 UTC] [4065] [postgres] CONTEXT: apply COMMIT in commit before 0/28A1300, xid 1175 committed at 2025-01-06 09:58:23.52653+00 (action #3) from node replorigin 1 366s [2025-01-06 09:58:23.527 UTC] [4065] [postgres] WARNING: relcache reference leak: relation "test_trg_data" not closed 366s [2025-01-06 09:58:23.527 UTC] [4065] [postgres] CONTEXT: apply COMMIT in commit before 0/28A1470, xid 1177 committed at 2025-01-06 09:58:23.526923+00 (action #4) from node replorigin 1 366s [2025-01-06 09:58:23.527 UTC] [4065] [postgres] WARNING: relcache reference leak: relation "test_trg_data" not closed 366s [2025-01-06 09:58:23.527 UTC] [4065] [postgres] CONTEXT: apply COMMIT in commit before 0/28A1470, xid 1177 committed at 2025-01-06 09:58:23.526923+00 (action #4) from node replorigin 1 366s [2025-01-06 09:58:23.527 UTC] [4065] [postgres] WARNING: relcache reference leak: relation "test_trg_data" not closed 366s [2025-01-06 09:58:23.527 UTC] [4065] [postgres] CONTEXT: apply COMMIT in commit before 0/28A1520, xid 1178 committed at 2025-01-06 09:58:23.527268+00 (action #4) from node replorigin 1 366s [2025-01-06 09:58:23.527 UTC] [4065] [postgres] WARNING: relcache reference leak: relation "test_trg_data" not closed 366s [2025-01-06 09:58:23.527 UTC] [4065] [postgres] CONTEXT: apply COMMIT in commit before 0/28A1520, xid 1178 committed at 2025-01-06 09:58:23.527268+00 (action #4) from node replorigin 1 366s [2025-01-06 09:58:27.595 UTC] [4105] [postgres] ERROR: existing subscription "test_subscription" to node "test_provider" already subscribes to replication set "default" 366s [2025-01-06 09:58:27.595 UTC] [4105] [postgres] STATEMENT: SELECT * FROM pglogical.create_subscription( 366s subscription_name := 'test_subscription_parallel', 366s provider_dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=super', 366s replication_sets := '{parallel,default}', 366s forward_origins := '{}', 366s synchronize_structure := false, 366s synchronize_data := false 366s ); 366s [2025-01-06 09:58:27.602 UTC] [4112] [postgres] LOG: starting apply for subscription test_subscription_parallel 366s [2025-01-06 09:58:27.603 UTC] [4113] [template1] LOG: manager worker [4113] at slot 4 generation 2 detaching cleanly 366s [2025-01-06 09:58:27.604 UTC] [4115] [regression1] LOG: manager worker [4115] at slot 5 generation 1 detaching cleanly 366s [2025-01-06 09:58:27.605 UTC] [4116] [sourcedb] LOG: manager worker [4116] at slot 4 generation 3 detaching cleanly 366s [2025-01-06 09:58:27.608 UTC] [4117] [regression] LOG: logical decoding found consistent point at 0/28C37D0 366s [2025-01-06 09:58:27.608 UTC] [4117] [regression] DETAIL: There are no running transactions. 366s [2025-01-06 09:58:27.608 UTC] [4117] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_subb8618c2" LOGICAL pglogical_output 366s [2025-01-06 09:58:27.609 UTC] [4117] [regression] LOG: exported logical decoding snapshot: "0000000B-00000018-1" with 0 transaction IDs 366s [2025-01-06 09:58:27.609 UTC] [4117] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_subb8618c2" LOGICAL pglogical_output 366s [2025-01-06 09:58:27.612 UTC] [4118] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_subb8618c2" 366s [2025-01-06 09:58:27.612 UTC] [4118] [regression] DETAIL: Streaming transactions committing after 0/28C3808, reading WAL from 0/28C37D0. 366s [2025-01-06 09:58:27.612 UTC] [4118] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_subb8618c2" LOGICAL 0/28C3808 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" 'parallel', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '4112') 366s [2025-01-06 09:58:27.612 UTC] [4118] [regression] LOG: logical decoding found consistent point at 0/28C37D0 366s [2025-01-06 09:58:27.612 UTC] [4118] [regression] DETAIL: There are no running transactions. 366s [2025-01-06 09:58:27.612 UTC] [4118] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_subb8618c2" LOGICAL 0/28C3808 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" 'parallel', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '4112') 366s [2025-01-06 09:58:29.826 UTC] [4112] [postgres] LOG: apply worker [4112] at slot 2 generation 12 detaching cleanly 366s [2025-01-06 09:58:30.830 UTC] [3763] [postgres] LOG: process 3763 still waiting for ShareUpdateExclusiveLock on relation 17336 of database 5 after 1001.866 ms 366s [2025-01-06 09:58:30.830 UTC] [3763] [postgres] DETAIL: Process holding the lock: 4120. Wait queue: 3763. 367s [2025-01-06 09:58:30.832 UTC] [3763] [postgres] LOG: process 3763 acquired ShareUpdateExclusiveLock on relation 17336 of database 5 after 1003.304 ms 367s [2025-01-06 09:58:30.833 UTC] [4122] [template1] LOG: manager worker [4122] at slot 2 generation 13 detaching cleanly 367s [2025-01-06 09:58:30.836 UTC] [4124] [regression1] LOG: manager worker [4124] at slot 2 generation 14 detaching cleanly 367s [2025-01-06 09:58:30.839 UTC] [4125] [sourcedb] LOG: manager worker [4125] at slot 2 generation 15 detaching cleanly 367s [2025-01-06 09:58:30.854 UTC] [4132] [regression] ERROR: cannot use subquery in check constraint 367s [2025-01-06 09:58:30.854 UTC] [4132] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', false, row_filter := '(SELECT count(*) FROM pg_class) > 1'); 367s [2025-01-06 09:58:30.855 UTC] [4132] [regression] ERROR: syntax error at or near "SELECT" 367s [2025-01-06 09:58:30.855 UTC] [4132] [regression] CONTEXT: invalid row_filter expression "SELECT true" 367s [2025-01-06 09:58:30.855 UTC] [4132] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', false, row_filter := 'SELECT true'); 367s [2025-01-06 09:58:30.855 UTC] [4132] [regression] ERROR: column "foobar" does not exist 367s [2025-01-06 09:58:30.855 UTC] [4132] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', false, row_filter := 'foobar'); 367s [2025-01-06 09:58:30.855 UTC] [4132] [regression] ERROR: argument of row_filter must be type boolean, not type text 367s [2025-01-06 09:58:30.855 UTC] [4132] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', false, row_filter := 'data'); 367s [2025-01-06 09:58:30.857 UTC] [4132] [regression] ERROR: cannot drop column data of table basic_dml because other objects depend on it 367s [2025-01-06 09:58:30.857 UTC] [4132] [regression] DETAIL: table basic_dml membership in replication set default depends on column data of table basic_dml 367s [2025-01-06 09:58:30.857 UTC] [4132] [regression] HINT: Use DROP ... CASCADE to drop the dependent objects too. 367s [2025-01-06 09:58:30.857 UTC] [4132] [regression] STATEMENT: ALTER TABLE basic_dml DROP COLUMN data; 367s [2025-01-06 09:58:30.857 UTC] [4133] [postgres] LOG: starting sync of table public.basic_dml for subscriber test_subscription 367s [2025-01-06 09:58:30.861 UTC] [4134] [regression] LOG: logical decoding found consistent point at 0/2905A18 367s [2025-01-06 09:58:30.861 UTC] [4134] [regression] DETAIL: There are no running transactions. 367s [2025-01-06 09:58:30.861 UTC] [4134] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" LOGICAL pglogical_output 367s [2025-01-06 09:58:30.861 UTC] [4134] [regression] LOG: exported logical decoding snapshot: "0000000A-00000020-1" with 0 transaction IDs 367s [2025-01-06 09:58:30.861 UTC] [4134] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" LOGICAL pglogical_output 367s [2025-01-06 09:58:31.870 UTC] [4139] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" 367s [2025-01-06 09:58:31.870 UTC] [4139] [regression] DETAIL: Streaming transactions committing after 0/2905A50, reading WAL from 0/2905A18. 367s [2025-01-06 09:58:31.870 UTC] [4139] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" LOGICAL 0/2905A50 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" 'all', "pglogical.replicate_only_table" 'public.basic_dml', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '4133') 367s [2025-01-06 09:58:31.870 UTC] [4139] [regression] LOG: logical decoding found consistent point at 0/2905A18 367s [2025-01-06 09:58:31.870 UTC] [4139] [regression] DETAIL: There are no running transactions. 367s [2025-01-06 09:58:31.870 UTC] [4139] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" LOGICAL 0/2905A50 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" 'all', "pglogical.replicate_only_table" 'public.basic_dml', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '4133') 367s [2025-01-06 09:58:44.695 UTC] [3692] [] LOG: checkpoint complete: wrote 234 buffers (1.4%); 0 WAL file(s) added, 0 removed, 0 recycled; write=24.673 s, sync=0.001 s, total=24.676 s; sync files=0, longest=0.000 s, average=0.000 s; distance=2001 kB, estimate=15419 kB; lsn=0/29062E0, redo lsn=0/2767230 367s [2025-01-06 09:58:56.312 UTC] [4142] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_type": index scans: 1 367s pages: 0 removed, 18 remain, 18 scanned (100.00% of total) 367s tuples: 71 removed, 639 remain, 0 are dead but not yet removable 367s removable cutoff: 1240, which was 4 XIDs old when operation ended 367s new relfrozenxid: 786, which is 64 XIDs ahead of previous value 367s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 367s index scan needed: 4 pages from table (22.22% of total) had 196 dead item identifiers removed 367s index "pg_type_oid_index": pages: 4 in total, 0 newly deleted, 0 currently deleted, 0 reusable 367s index "pg_type_typname_nsp_index": pages: 7 in total, 0 newly deleted, 0 currently deleted, 0 reusable 367s avg read rate: 0.000 MB/s, avg write rate: 44.423 MB/s 367s buffer usage: 80 hits, 0 misses, 15 dirtied 367s WAL usage: 20 records, 7 full page images, 36558 bytes 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:58:56.326 UTC] [4142] [] LOG: automatic analyze of table "regression.pg_catalog.pg_type" 367s avg read rate: 0.000 MB/s, avg write rate: 5.022 MB/s 367s buffer usage: 1096 hits, 0 misses, 9 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s 367s [2025-01-06 09:58:56.326 UTC] [4133] [postgres] LOG: pglogical sync finished processing; replayed to 0/291B4D8 of required 0/2906148 367s [2025-01-06 09:58:56.326 UTC] [4133] [postgres] CONTEXT: apply COMMIT in commit before 0/291B2A0, xid 1244 committed at 2025-01-06 09:58:56.326074+00 (action #2) from node replorigin 2 367s [2025-01-06 09:58:56.333 UTC] [4133] [postgres] LOG: finished sync of table public.basic_dml for subscriber test_subscription 367s [2025-01-06 09:58:56.333 UTC] [4133] [postgres] CONTEXT: apply COMMIT in commit before 0/291B2A0, xid 1244 committed at 2025-01-06 09:58:56.332781+00 (action #2) 367s [2025-01-06 09:58:56.333 UTC] [4133] [postgres] LOG: sync worker [4133] at slot 2 generation 16 detaching cleanly 367s [2025-01-06 09:58:56.339 UTC] [4142] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_attribute": index scans: 1 367s pages: 0 removed, 90 remain, 52 scanned (57.78% of total) 367s tuples: 940 removed, 3317 remain, 0 are dead but not yet removable 367s removable cutoff: 1240, which was 8 XIDs old when operation ended 367s new relfrozenxid: 786, which is 64 XIDs ahead of previous value 367s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 367s index scan needed: 33 pages from table (36.67% of total) had 1626 dead item identifiers removed 367s index "pg_attribute_relid_attnam_index": pages: 23 in total, 4 newly deleted, 4 currently deleted, 0 reusable 367s index "pg_attribute_relid_attnum_index": pages: 16 in total, 3 newly deleted, 3 currently deleted, 0 reusable 367s avg read rate: 0.000 MB/s, avg write rate: 30.028 MB/s 367s buffer usage: 243 hits, 0 misses, 52 dirtied 367s WAL usage: 123 records, 40 full page images, 97465 bytes 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s 367s [2025-01-06 09:58:56.351 UTC] [4142] [] LOG: automatic analyze of table "regression.pg_catalog.pg_attribute" 367s avg read rate: 0.000 MB/s, avg write rate: 5.409 MB/s 367s buffer usage: 569 hits, 0 misses, 9 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s 367s [2025-01-06 09:58:56.357 UTC] [4142] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_class": index scans: 1 367s pages: 0 removed, 20 remain, 20 scanned (100.00% of total) 367s tuples: 130 removed, 452 remain, 0 are dead but not yet removable 367s removable cutoff: 1244, which was 5 XIDs old when operation ended 367s new relfrozenxid: 786, which is 64 XIDs ahead of previous value 367s frozen: 1 pages from table (5.00% of total) had 19 tuples frozen 367s index scan needed: 15 pages from table (75.00% of total) had 345 dead item identifiers removed 367s index "pg_class_oid_index": pages: 4 in total, 0 newly deleted, 0 currently deleted, 0 reusable 367s index "pg_class_relname_nsp_index": pages: 7 in total, 0 newly deleted, 0 currently deleted, 0 reusable 367s index "pg_class_tblspc_relfilenode_index": pages: 4 in total, 0 newly deleted, 0 currently deleted, 0 reusable 367s avg read rate: 0.000 MB/s, avg write rate: 38.580 MB/s 367s buffer usage: 109 hits, 0 misses, 24 dirtied 367s WAL usage: 52 records, 15 full page images, 72019 bytes 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:58:56.362 UTC] [4142] [] LOG: automatic analyze of table "regression.pg_catalog.pg_class" 367s avg read rate: 0.000 MB/s, avg write rate: 6.510 MB/s 367s buffer usage: 563 hits, 0 misses, 5 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:58:56.362 UTC] [4142] [] LOG: automatic analyze of table "regression.pg_catalog.pg_attrdef" 367s avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s 367s buffer usage: 79 hits, 0 misses, 0 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:58:56.365 UTC] [4142] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_constraint": index scans: 1 367s pages: 0 removed, 6 remain, 6 scanned (100.00% of total) 367s tuples: 50 removed, 136 remain, 0 are dead but not yet removable 367s removable cutoff: 1244, which was 7 XIDs old when operation ended 367s new relfrozenxid: 786, which is 64 XIDs ahead of previous value 367s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 367s index scan needed: 4 pages from table (66.67% of total) had 105 dead item identifiers removed 367s index "pg_constraint_conparentid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 367s index "pg_constraint_conname_nsp_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 367s index "pg_constraint_conrelid_contypid_conname_index": pages: 4 in total, 0 newly deleted, 0 currently deleted, 0 reusable 367s index "pg_constraint_contypid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 367s index "pg_constraint_oid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 367s avg read rate: 0.000 MB/s, avg write rate: 32.380 MB/s 367s buffer usage: 111 hits, 0 misses, 11 dirtied 367s WAL usage: 23 records, 4 full page images, 20836 bytes 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:58:56.369 UTC] [4142] [] LOG: automatic analyze of table "regression.pg_catalog.pg_constraint" 367s avg read rate: 0.000 MB/s, avg write rate: 3.125 MB/s 367s buffer usage: 542 hits, 0 misses, 2 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:58:56.370 UTC] [4142] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_index": index scans: 1 367s pages: 0 removed, 6 remain, 6 scanned (100.00% of total) 367s tuples: 39 removed, 184 remain, 0 are dead but not yet removable 367s removable cutoff: 1244, which was 8 XIDs old when operation ended 367s new relfrozenxid: 786, which is 64 XIDs ahead of previous value 367s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 367s index scan needed: 6 pages from table (100.00% of total) had 129 dead item identifiers removed 367s index "pg_index_indrelid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 367s index "pg_index_indexrelid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 367s avg read rate: 0.000 MB/s, avg write rate: 615.157 MB/s 367s buffer usage: 39 hits, 0 misses, 10 dirtied 367s WAL usage: 19 records, 6 full page images, 43521 bytes 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:58:56.374 UTC] [4142] [] LOG: automatic analyze of table "regression.pg_catalog.pg_index" 367s avg read rate: 0.000 MB/s, avg write rate: 3.125 MB/s 367s buffer usage: 376 hits, 0 misses, 2 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:58:56.375 UTC] [4142] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_trigger": index scans: 1 367s pages: 0 removed, 2 remain, 2 scanned (100.00% of total) 367s tuples: 23 removed, 33 remain, 0 are dead but not yet removable 367s removable cutoff: 1244, which was 9 XIDs old when operation ended 367s new relfrozenxid: 786, which is 64 XIDs ahead of previous value 367s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 367s index scan needed: 2 pages from table (100.00% of total) had 135 dead item identifiers removed 367s index "pg_trigger_tgconstraint_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 367s index "pg_trigger_tgrelid_tgname_index": pages: 4 in total, 0 newly deleted, 0 currently deleted, 0 reusable 367s index "pg_trigger_oid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 367s avg read rate: 0.000 MB/s, avg write rate: 491.352 MB/s 367s buffer usage: 57 hits, 0 misses, 10 dirtied 367s WAL usage: 13 records, 4 full page images, 25536 bytes 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:58:56.378 UTC] [4142] [] LOG: automatic analyze of table "regression.pg_catalog.pg_trigger" 367s avg read rate: 0.000 MB/s, avg write rate: 1.953 MB/s 367s buffer usage: 230 hits, 0 misses, 1 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:58:56.386 UTC] [4142] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_depend": index scans: 1 367s pages: 0 removed, 24 remain, 24 scanned (100.00% of total) 367s tuples: 562 removed, 1972 remain, 0 are dead but not yet removable 367s removable cutoff: 1244, which was 10 XIDs old when operation ended 367s new relfrozenxid: 786, which is 64 XIDs ahead of previous value 367s frozen: 3 pages from table (12.50% of total) had 136 tuples frozen 367s index scan needed: 14 pages from table (58.33% of total) had 1395 dead item identifiers removed 367s index "pg_depend_depender_index": pages: 20 in total, 0 newly deleted, 0 currently deleted, 0 reusable 367s index "pg_depend_reference_index": pages: 14 in total, 1 newly deleted, 1 currently deleted, 0 reusable 367s avg read rate: 0.000 MB/s, avg write rate: 36.861 MB/s 367s buffer usage: 156 hits, 0 misses, 35 dirtied 367s WAL usage: 67 records, 20 full page images, 73414 bytes 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:58:56.391 UTC] [4142] [] LOG: automatic analyze of table "regression.pg_catalog.pg_depend" 367s avg read rate: 0.000 MB/s, avg write rate: 3.125 MB/s 367s buffer usage: 129 hits, 0 misses, 2 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:58:56.391 UTC] [4142] [] LOG: automatic analyze of table "regression.pg_catalog.pg_extension" 367s avg read rate: 0.000 MB/s, avg write rate: 7.812 MB/s 367s buffer usage: 119 hits, 0 misses, 1 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:58:56.391 UTC] [4142] [] LOG: automatic analyze of table "regression.pg_catalog.pg_sequence" 367s avg read rate: 0.000 MB/s, avg write rate: 15.625 MB/s 367s buffer usage: 145 hits, 0 misses, 2 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:58:56.391 UTC] [4142] [] LOG: automatic analyze of table "regression.pglogical.replication_set_table" 367s avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s 367s buffer usage: 115 hits, 0 misses, 0 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:58:56.392 UTC] [4142] [] LOG: automatic vacuum of table "regression.pglogical.depend": index scans: 0 367s pages: 0 removed, 1 remain, 1 scanned (100.00% of total) 367s tuples: 61 removed, 7 remain, 0 are dead but not yet removable 367s removable cutoff: 1244, which was 14 XIDs old when operation ended 367s new relfrozenxid: 1237, which is 450 XIDs ahead of previous value 367s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 367s index scan not needed: 1 pages from table (100.00% of total) had 61 dead item identifiers removed 367s avg read rate: 0.000 MB/s, avg write rate: 411.184 MB/s 367s buffer usage: 7 hits, 0 misses, 5 dirtied 367s WAL usage: 4 records, 1 full page images, 8840 bytes 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:58:56.392 UTC] [4142] [] LOG: automatic analyze of table "regression.pglogical.depend" 367s avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s 367s buffer usage: 63 hits, 0 misses, 0 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:58:58.540 UTC] [4065] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 367s [2025-01-06 09:58:58.540 UTC] [4065] [postgres] DETAIL: remote tuple {id[int4]:3 other[int4]:3 data[text]:baz3 SomeThing[interval]:2 years 01:00:00 insert_xid[int8]:1264 other2[text]:pr387 subonly[int4]:(null) subonly_def[int4]:(null) subonly_def_ts[timestamptz]:(null)} in xact origin=1,timestamp=2025-01-06 09:58:58.54026+00,commit_lsn=0/29A5BD0 367s [2025-01-06 09:58:58.540 UTC] [4065] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/29A5BD0, xid 1268 committed at 2025-01-06 09:58:58.54026+00 (action #3) from node replorigin 1 367s [2025-01-06 09:58:59.553 UTC] [4065] [postgres] LOG: CONFLICT: remote DELETE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 367s [2025-01-06 09:58:59.553 UTC] [4065] [postgres] DETAIL: remote tuple {id[int4]:3 other[int4]:(null) data[text]:(null) SomeThing[interval]:(null) insert_xid[int8]:(null) other2[text]:(null) subonly[int4]:(null) subonly_def[int4]:(null) subonly_def_ts[timestamptz]:(null)} in xact origin=1,timestamp=2025-01-06 09:58:59.553305+00,commit_lsn=0/29A63A0 367s [2025-01-06 09:58:59.553 UTC] [4065] [postgres] CONTEXT: apply (unknown action) from remote relation public.basic_dml in commit before 0/29A63A0, xid 1274 committed at 2025-01-06 09:58:59.553305+00 (action #2) from node replorigin 1 367s [2025-01-06 09:58:59.571 UTC] [4065] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 367s [2025-01-06 09:58:59.571 UTC] [4065] [postgres] DETAIL: remote tuple {id[int4]:6 other[int4]:100 data[text]:bar SomeThing[interval]:2 years 01:00:00 insert_xid[int8]:1284 other2[text]:pr387 subonly[int4]:(null) subonly_def[int4]:(null) subonly_def_ts[timestamptz]:(null)} in xact origin=1,timestamp=2025-01-06 09:58:59.570968+00,commit_lsn=0/29A6CE8 367s [2025-01-06 09:58:59.571 UTC] [4065] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/29A6CE8, xid 1285 committed at 2025-01-06 09:58:59.570968+00 (action #2) from node replorigin 1 367s [2025-01-06 09:58:59.571 UTC] [4065] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 367s [2025-01-06 09:58:59.571 UTC] [4065] [postgres] DETAIL: remote tuple {id[int4]:6 other[int4]:100 data[text]:abcd SomeThing[interval]:2 years 01:00:00 insert_xid[int8]:1284 other2[text]:pr387 subonly[int4]:(null) subonly_def[int4]:(null) subonly_def_ts[timestamptz]:(null)} in xact origin=1,timestamp=2025-01-06 09:58:59.571166+00,commit_lsn=0/29A6D88 367s [2025-01-06 09:58:59.571 UTC] [4065] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/29A6D88, xid 1286 committed at 2025-01-06 09:58:59.571166+00 (action #2) from node replorigin 1 367s [2025-01-06 09:59:02.611 UTC] [4163] [postgres] LOG: starting sync of table public.test_jsonb for subscriber test_subscription 367s [2025-01-06 09:59:02.616 UTC] [4164] [regression] LOG: logical decoding found consistent point at 0/29B3438 367s [2025-01-06 09:59:02.616 UTC] [4164] [regression] DETAIL: There are no running transactions. 367s [2025-01-06 09:59:02.616 UTC] [4164] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9_48bb0cb8" LOGICAL pglogical_output 367s [2025-01-06 09:59:02.616 UTC] [4164] [regression] LOG: exported logical decoding snapshot: "0000000A-00000028-1" with 0 transaction IDs 367s [2025-01-06 09:59:02.616 UTC] [4164] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9_48bb0cb8" LOGICAL pglogical_output 367s [2025-01-06 09:59:03.616 UTC] [4163] [postgres] LOG: finished sync of table public.test_jsonb for subscriber test_subscription 367s [2025-01-06 09:59:03.616 UTC] [4163] [postgres] LOG: sync worker [4163] at slot 2 generation 17 detaching cleanly 367s NOTICE: c_u: temp_owner, s_u: super 367s NOTICE: c_u: temp_owner, s_u: super 367s [2025-01-06 09:59:07.689 UTC] [4180] [regression] ERROR: set-returning functions are not allowed in check constraints 367s [2025-01-06 09:59:07.689 UTC] [4180] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', false, 367s row_filter := $rf$ (func_plpgsql_srf_retq(other)).result = 500 $rf$); 367s [2025-01-06 09:59:08.320 UTC] [4181] [] LOG: automatic analyze of table "template1.pg_catalog.pg_type" 367s avg read rate: 0.000 MB/s, avg write rate: 6.392 MB/s 367s buffer usage: 1078 hits, 0 misses, 9 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s 367s [2025-01-06 09:59:08.330 UTC] [4181] [] LOG: automatic analyze of table "template1.pg_catalog.pg_attribute" 367s avg read rate: 0.000 MB/s, avg write rate: 6.392 MB/s 367s buffer usage: 519 hits, 0 misses, 9 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s 367s [2025-01-06 09:59:08.330 UTC] [4181] [] LOG: automatic aggressive vacuum of table "template1.pg_catalog.pg_class": index scans: 0 367s pages: 0 removed, 14 remain, 14 scanned (100.00% of total) 367s tuples: 0 removed, 413 remain, 0 are dead but not yet removable 367s removable cutoff: 1298, which was 43 XIDs old when operation ended 367s new relfrozenxid: 1298, which is 576 XIDs ahead of previous value 367s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 367s index scan not needed: 0 pages from table (0.00% of total) had 0 dead item identifiers removed 367s avg read rate: 0.000 MB/s, avg write rate: 84.005 MB/s 367s buffer usage: 54 hits, 0 misses, 1 dirtied 367s WAL usage: 1 records, 1 full page images, 3097 bytes 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:59:08.335 UTC] [4181] [] LOG: automatic analyze of table "template1.pg_catalog.pg_class" 367s avg read rate: 0.000 MB/s, avg write rate: 9.766 MB/s 367s buffer usage: 537 hits, 0 misses, 5 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:59:08.338 UTC] [4181] [] LOG: automatic analyze of table "template1.pg_catalog.pg_constraint" 367s avg read rate: 0.000 MB/s, avg write rate: 5.859 MB/s 367s buffer usage: 555 hits, 0 misses, 3 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:59:08.338 UTC] [4181] [] LOG: automatic analyze of table "template1.pg_catalog.pg_rewrite" 367s avg read rate: 0.000 MB/s, avg write rate: 7.812 MB/s 367s buffer usage: 126 hits, 0 misses, 1 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:59:08.342 UTC] [4181] [] LOG: automatic analyze of table "template1.pg_catalog.pg_description" 367s avg read rate: 0.000 MB/s, avg write rate: 3.906 MB/s 367s buffer usage: 130 hits, 0 misses, 2 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:59:08.342 UTC] [4181] [] LOG: automatic aggressive vacuum of table "template1.pg_catalog.pg_depend": index scans: 0 367s pages: 0 removed, 13 remain, 13 scanned (100.00% of total) 367s tuples: 0 removed, 1704 remain, 0 are dead but not yet removable 367s removable cutoff: 1298, which was 47 XIDs old when operation ended 367s new relfrozenxid: 1298, which is 576 XIDs ahead of previous value 367s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 367s index scan not needed: 0 pages from table (0.00% of total) had 0 dead item identifiers removed 367s avg read rate: 0.000 MB/s, avg write rate: 49.446 MB/s 367s buffer usage: 71 hits, 0 misses, 1 dirtied 367s WAL usage: 1 records, 1 full page images, 7869 bytes 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:59:08.344 UTC] [4181] [] LOG: automatic analyze of table "template1.pg_catalog.pg_depend" 367s avg read rate: 0.000 MB/s, avg write rate: 11.719 MB/s 367s buffer usage: 107 hits, 0 misses, 3 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:59:08.344 UTC] [4181] [] LOG: automatic analyze of table "template1.pg_catalog.pg_ts_config_map" 367s avg read rate: 0.000 MB/s, avg write rate: 7.812 MB/s 367s buffer usage: 58 hits, 0 misses, 1 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:59:08.344 UTC] [4181] [] LOG: automatic analyze of table "template1.pg_catalog.pg_init_privs" 367s avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s 367s buffer usage: 85 hits, 0 misses, 0 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:59:08.345 UTC] [4181] [] LOG: automatic analyze of table "template1.pg_catalog.pg_collation" 367s avg read rate: 0.000 MB/s, avg write rate: 15.625 MB/s 367s buffer usage: 171 hits, 0 misses, 2 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:59:08.347 UTC] [4181] [] LOG: automatic analyze of table "template1.information_schema.sql_features" 367s avg read rate: 0.000 MB/s, avg write rate: 11.719 MB/s 367s buffer usage: 196 hits, 0 misses, 3 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:59:08.727 UTC] [4191] [regression] ERROR: REPLICA IDENTITY columns must be replicated 367s [2025-01-06 09:59:08.727 UTC] [4191] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', columns := '{ data, something}'); 367s [2025-01-06 09:59:09.815 UTC] [4065] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 367s [2025-01-06 09:59:09.815 UTC] [4065] [postgres] DETAIL: remote tuple {id[int4]:(null) data[text]:(null) something[interval]:00:59:50 subonly[int4]:(null) subonly_def[int4]:(null)} in xact origin=1,timestamp=2025-01-06 09:59:09.815685+00,commit_lsn=0/2A25E40 367s [2025-01-06 09:59:09.815 UTC] [4065] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/2A25E40, xid 1390 committed at 2025-01-06 09:59:09.815685+00 (action #2) from node replorigin 1 367s [2025-01-06 09:59:09.815 UTC] [4065] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 367s [2025-01-06 09:59:09.815 UTC] [4065] [postgres] DETAIL: remote tuple {id[int4]:(null) data[text]:(null) something[interval]:2 years -00:00:10 subonly[int4]:(null) subonly_def[int4]:(null)} in xact origin=1,timestamp=2025-01-06 09:59:09.815685+00,commit_lsn=0/2A25E40 367s [2025-01-06 09:59:09.815 UTC] [4065] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/2A25E40, xid 1390 committed at 2025-01-06 09:59:09.815685+00 (action #3) from node replorigin 1 367s [2025-01-06 09:59:09.815 UTC] [4065] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 367s [2025-01-06 09:59:09.815 UTC] [4065] [postgres] DETAIL: remote tuple {id[int4]:(null) data[text]:(null) something[interval]:00:02:50 subonly[int4]:(null) subonly_def[int4]:(null)} in xact origin=1,timestamp=2025-01-06 09:59:09.815685+00,commit_lsn=0/2A25E40 367s [2025-01-06 09:59:09.815 UTC] [4065] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/2A25E40, xid 1390 committed at 2025-01-06 09:59:09.815685+00 (action #4) from node replorigin 1 367s [2025-01-06 09:59:09.815 UTC] [4065] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 367s [2025-01-06 09:59:09.815 UTC] [4065] [postgres] DETAIL: remote tuple {id[int4]:(null) data[text]:(null) something[interval]:4 days -00:00:10 subonly[int4]:(null) subonly_def[int4]:(null)} in xact origin=1,timestamp=2025-01-06 09:59:09.815685+00,commit_lsn=0/2A25E40 367s [2025-01-06 09:59:09.815 UTC] [4065] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/2A25E40, xid 1390 committed at 2025-01-06 09:59:09.815685+00 (action #5) from node replorigin 1 367s [2025-01-06 09:59:09.815 UTC] [4065] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 367s [2025-01-06 09:59:09.815 UTC] [4065] [postgres] DETAIL: remote tuple {id[int4]:(null) data[text]:(null) something[interval]:00:00:50 subonly[int4]:(null) subonly_def[int4]:(null)} in xact origin=1,timestamp=2025-01-06 09:59:09.815685+00,commit_lsn=0/2A25E40 367s [2025-01-06 09:59:09.815 UTC] [4065] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/2A25E40, xid 1390 committed at 2025-01-06 09:59:09.815685+00 (action #6) from node replorigin 1 367s [2025-01-06 09:59:09.815 UTC] [4065] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 367s [2025-01-06 09:59:09.815 UTC] [4065] [postgres] DETAIL: remote tuple {id[int4]:(null) data[text]:(null) something[interval]:84 days -00:00:10 subonly[int4]:(null) subonly_def[int4]:(null)} in xact origin=1,timestamp=2025-01-06 09:59:09.815685+00,commit_lsn=0/2A25E40 367s [2025-01-06 09:59:09.815 UTC] [4065] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/2A25E40, xid 1390 committed at 2025-01-06 09:59:09.815685+00 (action #7) from node replorigin 1 367s [2025-01-06 09:59:09.851 UTC] [4222] [regression] ERROR: REPLICA IDENTITY columns must be replicated 367s [2025-01-06 09:59:09.851 UTC] [4222] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', synchronize_data := true, columns := '{data, something}'); 367s [2025-01-06 09:59:09.853 UTC] [4222] [regression] ERROR: table public.basic_dml does not have column nosuchcol 367s [2025-01-06 09:59:09.853 UTC] [4222] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', synchronize_data := true, columns := '{data, something, nosuchcol}'); 367s [2025-01-06 09:59:09.855 UTC] [4223] [postgres] LOG: starting sync of table public.basic_dml for subscriber test_subscription 367s [2025-01-06 09:59:09.859 UTC] [4224] [regression] LOG: logical decoding found consistent point at 0/2A390A0 367s [2025-01-06 09:59:09.859 UTC] [4224] [regression] DETAIL: There are no running transactions. 367s [2025-01-06 09:59:09.859 UTC] [4224] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" LOGICAL pglogical_output 367s [2025-01-06 09:59:09.859 UTC] [4224] [regression] LOG: exported logical decoding snapshot: "0000000A-0000002E-1" with 0 transaction IDs 367s [2025-01-06 09:59:09.859 UTC] [4224] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" LOGICAL pglogical_output 367s [2025-01-06 09:59:10.860 UTC] [4223] [postgres] LOG: finished sync of table public.basic_dml for subscriber test_subscription 367s [2025-01-06 09:59:10.860 UTC] [4223] [postgres] LOG: sync worker [4223] at slot 2 generation 18 detaching cleanly 367s [2025-01-06 09:59:11.070 UTC] [4230] [regression] ERROR: duplicate key value violates unique constraint "replication_set_table_pkey" 367s [2025-01-06 09:59:11.070 UTC] [4230] [regression] DETAIL: Key (set_id, set_reloid)=(1376784750, 18330) already exists. 367s [2025-01-06 09:59:11.070 UTC] [4230] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', synchronize_data := true); 367s [2025-01-06 09:59:11.072 UTC] [4230] [regression] ERROR: duplicate key value violates unique constraint "replication_set_table_pkey" 367s [2025-01-06 09:59:11.072 UTC] [4230] [regression] DETAIL: Key (set_id, set_reloid)=(1376784750, 18330) already exists. 367s [2025-01-06 09:59:11.072 UTC] [4230] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', synchronize_data := true, columns := '{id, data}'); 367s [2025-01-06 09:59:11.101 UTC] [4242] [postgres] LOG: starting apply for subscription test_subscription_delay 367s [2025-01-06 09:59:11.102 UTC] [4241] [template1] LOG: manager worker [4241] at slot 4 generation 4 detaching cleanly 367s [2025-01-06 09:59:11.105 UTC] [4244] [regression] LOG: logical decoding found consistent point at 0/2A44AD8 367s [2025-01-06 09:59:11.105 UTC] [4244] [regression] DETAIL: There are no running transactions. 367s [2025-01-06 09:59:11.105 UTC] [4244] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_subaf763f6" LOGICAL pglogical_output 367s [2025-01-06 09:59:11.105 UTC] [4244] [regression] LOG: exported logical decoding snapshot: "00000006-0000021D-1" with 0 transaction IDs 367s [2025-01-06 09:59:11.105 UTC] [4244] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_subaf763f6" LOGICAL pglogical_output 367s [2025-01-06 09:59:11.106 UTC] [4245] [regression1] LOG: manager worker [4245] at slot 4 generation 5 detaching cleanly 367s [2025-01-06 09:59:11.108 UTC] [4247] [sourcedb] LOG: manager worker [4247] at slot 4 generation 6 detaching cleanly 367s [2025-01-06 09:59:11.110 UTC] [4246] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_subaf763f6" 367s [2025-01-06 09:59:11.110 UTC] [4246] [regression] DETAIL: Streaming transactions committing after 0/2A44B10, reading WAL from 0/2A44AD8. 367s [2025-01-06 09:59:11.110 UTC] [4246] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_subaf763f6" LOGICAL 0/2A44B10 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" 'delay', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '4242') 367s [2025-01-06 09:59:11.110 UTC] [4246] [regression] LOG: logical decoding found consistent point at 0/2A44AD8 367s [2025-01-06 09:59:11.110 UTC] [4246] [regression] DETAIL: There are no running transactions. 367s [2025-01-06 09:59:11.110 UTC] [4246] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_subaf763f6" LOGICAL 0/2A44B10 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" 'delay', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '4242') 367s [2025-01-06 09:59:17.327 UTC] [4242] [postgres] LOG: apply worker [4242] at slot 2 generation 19 detaching cleanly 367s [2025-01-06 09:59:18.328 UTC] [3763] [postgres] LOG: process 3763 still waiting for ShareUpdateExclusiveLock on relation 17336 of database 5 after 1000.167 ms 367s [2025-01-06 09:59:18.328 UTC] [3763] [postgres] DETAIL: Process holding the lock: 4250. Wait queue: 3763. 367s [2025-01-06 09:59:18.332 UTC] [3763] [postgres] LOG: process 3763 acquired ShareUpdateExclusiveLock on relation 17336 of database 5 after 1003.306 ms 367s [2025-01-06 09:59:18.333 UTC] [4252] [template1] LOG: manager worker [4252] at slot 2 generation 20 detaching cleanly 367s [2025-01-06 09:59:18.336 UTC] [4254] [regression1] LOG: manager worker [4254] at slot 2 generation 21 detaching cleanly 367s [2025-01-06 09:59:18.338 UTC] [4255] [sourcedb] LOG: manager worker [4255] at slot 2 generation 22 detaching cleanly 367s [2025-01-06 09:59:18.373 UTC] [4264] [template1] LOG: manager worker [4264] at slot 2 generation 23 detaching cleanly 367s [2025-01-06 09:59:18.376 UTC] [4267] [regression1] LOG: manager worker [4267] at slot 2 generation 24 detaching cleanly 367s [2025-01-06 09:59:18.379 UTC] [4269] [sourcedb] LOG: starting pglogical database manager for database sourcedb 367s [2025-01-06 09:59:18.382 UTC] [4271] [regression] LOG: starting apply for subscription test_orig_subscription 367s [2025-01-06 09:59:18.386 UTC] [4273] [sourcedb] LOG: logical decoding found consistent point at 0/2B25F40 367s [2025-01-06 09:59:18.386 UTC] [4273] [sourcedb] DETAIL: There are no running transactions. 367s [2025-01-06 09:59:18.386 UTC] [4273] [sourcedb] STATEMENT: CREATE_REPLICATION_SLOT "pgl_regression_test_orib5a0b8b_test_ori670a399" LOGICAL pglogical_output 367s [2025-01-06 09:59:18.386 UTC] [4273] [sourcedb] LOG: exported logical decoding snapshot: "0000000C-00000014-1" with 0 transaction IDs 367s [2025-01-06 09:59:18.386 UTC] [4273] [sourcedb] STATEMENT: CREATE_REPLICATION_SLOT "pgl_regression_test_orib5a0b8b_test_ori670a399" LOGICAL pglogical_output 367s [2025-01-06 09:59:18.396 UTC] [4276] [sourcedb] LOG: starting logical decoding for slot "pgl_regression_test_orib5a0b8b_test_ori670a399" 367s [2025-01-06 09:59:18.396 UTC] [4276] [sourcedb] DETAIL: Streaming transactions committing after 0/2B25F78, reading WAL from 0/2B25F40. 367s [2025-01-06 09:59:18.396 UTC] [4276] [sourcedb] STATEMENT: START_REPLICATION SLOT "pgl_regression_test_orib5a0b8b_test_ori670a399" LOGICAL 0/2B25F78 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" '"default",default_insert_only,ddl_sql', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '4271') 367s [2025-01-06 09:59:18.396 UTC] [4276] [sourcedb] LOG: logical decoding found consistent point at 0/2B25F40 367s [2025-01-06 09:59:18.396 UTC] [4276] [sourcedb] DETAIL: There are no running transactions. 367s [2025-01-06 09:59:18.396 UTC] [4276] [sourcedb] STATEMENT: START_REPLICATION SLOT "pgl_regression_test_orib5a0b8b_test_ori670a399" LOGICAL 0/2B25F78 (expected_encoding 'UTF8', min_proto_version '1', max_proto_version '1', startup_params_format '1', "binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1', "binary.basetypes_major_version" '1600', "binary.sizeof_datum" '8', "binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '1', "binary.float4_byval" '0', "binary.float8_byval" '1', "binary.integer_datetimes" '0', "hooks.setup_function" 'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '', "pglogical.replication_set_names" '"default",default_insert_only,ddl_sql', "relmeta_cache_size" '-1', pg_version '160000', pglogical_version '2.4.4', pglogical_version_num '20404', pglogical_apply_pid '4271') 367s [2025-01-06 09:59:20.300 UTC] [4280] [] LOG: automatic vacuum of table "postgres.pg_catalog.pg_statistic": index scans: 1 367s pages: 0 removed, 26 remain, 26 scanned (100.00% of total) 367s tuples: 93 removed, 428 remain, 0 are dead but not yet removable 367s removable cutoff: 1441, which was 14 XIDs old when operation ended 367s new relfrozenxid: 1124, which is 402 XIDs ahead of previous value 367s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 367s index scan needed: 12 pages from table (46.15% of total) had 149 dead item identifiers removed 367s index "pg_statistic_relid_att_inh_index": pages: 5 in total, 0 newly deleted, 0 currently deleted, 0 reusable 367s avg read rate: 126.008 MB/s, avg write rate: 105.007 MB/s 367s buffer usage: 88 hits, 6 misses, 5 dirtied 367s WAL usage: 45 records, 1 full page images, 11934 bytes 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:59:20.303 UTC] [4280] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_attrdef" 367s avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s 367s buffer usage: 326 hits, 0 misses, 0 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:59:20.303 UTC] [4280] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_shdepend" 367s avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s 367s buffer usage: 213 hits, 0 misses, 0 dirtied 367s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 367s [2025-01-06 09:59:20.627 UTC] [4271] [regression] LOG: apply worker [4271] at slot 4 generation 7 detaching cleanly 367s [2025-01-06 09:59:20.717 UTC] [3692] [] LOG: checkpoint starting: time 367s [2025-01-06 09:59:21.628 UTC] [3757] [regression] LOG: process 3757 still waiting for ShareUpdateExclusiveLock on relation 17149 of database 16384 after 1000.109 ms 367s [2025-01-06 09:59:21.628 UTC] [3757] [regression] DETAIL: Process holding the lock: 4284. Wait queue: 3757. 367s [2025-01-06 09:59:21.631 UTC] [4286] [template1] LOG: manager worker [4286] at slot 4 generation 8 detaching cleanly 367s [2025-01-06 09:59:21.631 UTC] [3757] [regression] LOG: process 3757 acquired ShareUpdateExclusiveLock on relation 17149 of database 16384 after 1002.696 ms 367s [2025-01-06 09:59:21.633 UTC] [4288] [regression1] LOG: manager worker [4288] at slot 4 generation 9 detaching cleanly 367s [2025-01-06 09:59:21.636 UTC] [4289] [template1] LOG: manager worker [4289] at slot 4 generation 10 detaching cleanly 367s [2025-01-06 09:59:21.638 UTC] [4269] [sourcedb] LOG: manager worker [4269] at slot 2 generation 25 detaching cleanly 367s [2025-01-06 09:59:21.640 UTC] [4292] [regression1] LOG: manager worker [4292] at slot 2 generation 26 detaching cleanly 367s [2025-01-06 09:59:21.642 UTC] [4296] [sourcedb] LOG: starting pglogical database manager for database sourcedb 367s [2025-01-06 09:59:21.642 UTC] [4296] [sourcedb] LOG: manager worker [4296] at slot 2 generation 27 detaching cleanly 367s [2025-01-06 09:59:21.649 UTC] [4298] [regression] ERROR: cannot drop node "test_provider" because one or more replication slots for the node are still active 367s [2025-01-06 09:59:21.649 UTC] [4298] [regression] HINT: drop the subscriptions connected to the node first 367s [2025-01-06 09:59:21.649 UTC] [4298] [regression] STATEMENT: SELECT * FROM pglogical.drop_node(node_name := 'test_provider'); 367s [2025-01-06 09:59:21.656 UTC] [4065] [postgres] LOG: apply worker [4065] at slot 3 generation 15 detaching cleanly 367s [2025-01-06 09:59:22.658 UTC] [3763] [postgres] LOG: process 3763 still waiting for ShareUpdateExclusiveLock on relation 17336 of database 5 after 1000.243 ms 367s [2025-01-06 09:59:22.658 UTC] [3763] [postgres] DETAIL: Process holding the lock: 4299. Wait queue: 3763. 367s [2025-01-06 09:59:22.663 UTC] [4301] [template1] LOG: manager worker [4301] at slot 2 generation 28 detaching cleanly 367s [2025-01-06 09:59:22.663 UTC] [3763] [postgres] LOG: process 3763 acquired ShareUpdateExclusiveLock on relation 17336 of database 5 after 1005.585 ms 367s [2025-01-06 09:59:22.665 UTC] [3763] [postgres] LOG: manager worker [3763] at slot 1 generation 5 detaching cleanly 367s [2025-01-06 09:59:22.667 UTC] [4302] [regression1] LOG: manager worker [4302] at slot 2 generation 29 detaching cleanly 367s [2025-01-06 09:59:22.667 UTC] [4303] [sourcedb] LOG: starting pglogical database manager for database sourcedb 367s [2025-01-06 09:59:22.667 UTC] [4303] [sourcedb] LOG: manager worker [4303] at slot 3 generation 16 detaching cleanly 367s [2025-01-06 09:59:22.672 UTC] [3757] [regression] LOG: manager worker [3757] at slot 0 generation 12 detaching cleanly 367s [2025-01-06 09:59:22.675 UTC] [4307] [postgres] LOG: starting pglogical database manager for database postgres 367s [2025-01-06 09:59:22.675 UTC] [4307] [postgres] LOG: manager worker [4307] at slot 0 generation 13 detaching cleanly 367s [2025-01-06 09:59:22.678 UTC] [4309] [template1] LOG: manager worker [4309] at slot 0 generation 14 detaching cleanly 367s [2025-01-06 09:59:22.681 UTC] [4311] [regression] LOG: starting pglogical database manager for database regression 367s [2025-01-06 09:59:22.681 UTC] [4311] [regression] LOG: manager worker [4311] at slot 0 generation 15 detaching cleanly 367s [2025-01-06 09:59:22.684 UTC] [4313] [regression1] LOG: manager worker [4313] at slot 0 generation 16 detaching cleanly 367s [2025-01-06 09:59:22.686 UTC] [4315] [sourcedb] LOG: starting pglogical database manager for database sourcedb 367s [2025-01-06 09:59:22.686 UTC] [4315] [sourcedb] LOG: manager worker [4315] at slot 0 generation 17 detaching cleanly 367s [2025-01-06 09:59:22.694 UTC] [3689] [] LOG: received fast shutdown request 367s [2025-01-06 09:59:22.694 UTC] [3689] [] LOG: aborting any active transactions 367s [2025-01-06 09:59:22.695 UTC] [3689] [] LOG: background worker "logical replication launcher" (PID 3698) exited with exit code 1 367s [2025-01-06 09:59:22.703 UTC] [3692] [] LOG: checkpoint complete: wrote 640 buffers (3.9%); 0 WAL file(s) added, 0 removed, 0 recycled; write=1.985 s, sync=0.001 s, total=1.986 s; sync files=0, longest=0.000 s, average=0.000 s; distance=4016 kB, estimate=14279 kB; lsn=0/2B65858, redo lsn=0/2B535E8 367s [2025-01-06 09:59:22.703 UTC] [3692] [] LOG: shutting down 367s [2025-01-06 09:59:22.703 UTC] [3692] [] LOG: checkpoint starting: shutdown immediate 367s [2025-01-06 09:59:22.703 UTC] [3692] [] LOG: checkpoint complete: wrote 12 buffers (0.1%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s; distance=72 kB, estimate=12858 kB; lsn=0/2B658D0, redo lsn=0/2B658D0 367s [2025-01-06 09:59:22.711 UTC] [3689] [] LOG: database system is shut down 367s autopkgtest [09:59:23]: test regresscheck: -----------------------] 367s autopkgtest [09:59:23]: test regresscheck: - - - - - - - - - - results - - - - - - - - - - 367s regresscheck FLAKY non-zero exit status 1 368s autopkgtest [09:59:24]: @@@@@@@@@@@@@@@@@@@@ summary 368s prove PASS 368s regresscheck FLAKY non-zero exit status 1 386s nova [W] Using flock in prodstack6-s390x 386s Creating nova instance adt-plucky-s390x-pglogical-20250106-095315-juju-7f2275-prod-proposed-migration-environment-15-c3164b9a-cb72-45db-a675-cfa5ed558525 from image adt/ubuntu-plucky-s390x-server-20250106.img (UUID 5b452c36-3901-4afa-abc7-e21db541e94d)... 386s nova [W] Timed out waiting for 36e8bca5-59b3-4472-ad58-a963f5f31aba to get deleted. 386s nova [W] Using flock in prodstack6-s390x 386s Creating nova instance adt-plucky-s390x-pglogical-20250106-095315-juju-7f2275-prod-proposed-migration-environment-15-c3164b9a-cb72-45db-a675-cfa5ed558525 from image adt/ubuntu-plucky-s390x-server-20250106.img (UUID 5b452c36-3901-4afa-abc7-e21db541e94d)... 386s nova [W] Timed out waiting for 33e78ec2-3604-48ce-9bf7-55f42d7bd4be to get deleted.