0s autopkgtest [11:07:07]: starting date and time: 2025-03-15 11:07:07+0000 0s autopkgtest [11:07:07]: git checkout: 325255d2 Merge branch 'pin-any-arch' into 'ubuntu/production' 0s autopkgtest [11:07:07]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.kvgbgxk1/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:glibc --apt-upgrade pglogical --timeout-short=300 --timeout-copy=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=glibc/2.41-1ubuntu2 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-s390x --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos03-s390x-8.secgroup --name adt-plucky-s390x-pglogical-20250315-110707-juju-7f2275-prod-proposed-migration-environment-2-da236843-81c8-400b-87e4-7ffa43ca1dc9 --image adt/ubuntu-plucky-s390x-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-2 --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/ 145s autopkgtest [11:09:32]: testbed dpkg architecture: s390x 145s autopkgtest [11:09:32]: testbed apt version: 2.9.33 145s autopkgtest [11:09:32]: @@@@@@@@@@@@@@@@@@@@ test bed setup 146s autopkgtest [11:09:33]: testbed release detected to be: None 146s autopkgtest [11:09:33]: updating testbed package index (apt update) 147s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [126 kB] 147s Hit:2 http://ftpmaster.internal/ubuntu plucky InRelease 147s Hit:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease 147s Hit:4 http://ftpmaster.internal/ubuntu plucky-security InRelease 147s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [15.8 kB] 147s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [46.2 kB] 147s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [410 kB] 148s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x Packages [80.7 kB] 148s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x c-n-f Metadata [1852 B] 148s Get:10 http://ftpmaster.internal/ubuntu plucky-proposed/restricted s390x c-n-f Metadata [116 B] 148s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/universe s390x Packages [335 kB] 148s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/universe s390x c-n-f Metadata [14.4 kB] 148s Get:13 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse s390x Packages [3776 B] 148s Get:14 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse s390x c-n-f Metadata [328 B] 149s Fetched 1034 kB in 2s (602 kB/s) 149s Reading package lists... 150s Reading package lists... 150s Building dependency tree... 150s Reading state information... 150s Calculating upgrade... 150s Calculating upgrade... 150s The following packages were automatically installed and are no longer required: 150s libnsl2 libpython3.12-minimal libpython3.12-stdlib libpython3.12t64 150s linux-headers-6.11.0-8 linux-headers-6.11.0-8-generic 150s linux-modules-6.11.0-8-generic linux-tools-6.11.0-8 150s linux-tools-6.11.0-8-generic 150s Use 'sudo apt autoremove' to remove them. 150s The following packages will be upgraded: 150s python3-jinja2 strace 150s 2 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 150s Need to get 609 kB of archives. 150s After this operation, 27.6 kB of additional disk space will be used. 150s Get:1 http://ftpmaster.internal/ubuntu plucky/main s390x strace s390x 6.13+ds-1ubuntu1 [500 kB] 151s Get:2 http://ftpmaster.internal/ubuntu plucky/main s390x python3-jinja2 all 3.1.5-2ubuntu1 [109 kB] 151s Fetched 609 kB in 1s (622 kB/s) 152s (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 ... 81428 files and directories currently installed.) 152s Preparing to unpack .../strace_6.13+ds-1ubuntu1_s390x.deb ... 152s Unpacking strace (6.13+ds-1ubuntu1) over (6.11-0ubuntu1) ... 152s Preparing to unpack .../python3-jinja2_3.1.5-2ubuntu1_all.deb ... 152s Unpacking python3-jinja2 (3.1.5-2ubuntu1) over (3.1.5-2) ... 152s Setting up python3-jinja2 (3.1.5-2ubuntu1) ... 152s Setting up strace (6.13+ds-1ubuntu1) ... 152s Processing triggers for man-db (2.13.0-1) ... 152s Reading package lists... 152s Building dependency tree... 152s Reading state information... 153s Solving dependencies... 153s The following packages will be REMOVED: 153s libnsl2* libpython3.12-minimal* libpython3.12-stdlib* libpython3.12t64* 153s linux-headers-6.11.0-8* linux-headers-6.11.0-8-generic* 153s linux-modules-6.11.0-8-generic* linux-tools-6.11.0-8* 153s linux-tools-6.11.0-8-generic* 153s 0 upgraded, 0 newly installed, 9 to remove and 5 not upgraded. 153s After this operation, 167 MB disk space will be freed. 153s (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 ... 81428 files and directories currently installed.) 153s Removing linux-tools-6.11.0-8-generic (6.11.0-8.8) ... 153s Removing linux-tools-6.11.0-8 (6.11.0-8.8) ... 153s Removing libpython3.12t64:s390x (3.12.9-1) ... 153s Removing libpython3.12-stdlib:s390x (3.12.9-1) ... 153s Removing libnsl2:s390x (1.3.0-3build3) ... 153s Removing libpython3.12-minimal:s390x (3.12.9-1) ... 153s Removing linux-headers-6.11.0-8-generic (6.11.0-8.8) ... 153s Removing linux-headers-6.11.0-8 (6.11.0-8.8) ... 154s Removing linux-modules-6.11.0-8-generic (6.11.0-8.8) ... 154s Processing triggers for libc-bin (2.41-1ubuntu1) ... 154s (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 ... 56328 files and directories currently installed.) 154s Purging configuration files for libpython3.12-minimal:s390x (3.12.9-1) ... 154s Purging configuration files for linux-modules-6.11.0-8-generic (6.11.0-8.8) ... 154s autopkgtest [11:09:41]: upgrading testbed (apt dist-upgrade and autopurge) 154s Reading package lists... 154s Building dependency tree... 154s Reading state information... 155s Calculating upgrade...Starting pkgProblemResolver with broken count: 0 155s Starting 2 pkgProblemResolver with broken count: 0 155s Done 155s Entering ResolveByKeep 155s 155s Calculating upgrade... 155s The following packages will be upgraded: 155s libc-bin libc-dev-bin libc6 libc6-dev locales 155s 5 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 155s Need to get 9512 kB of archives. 155s After this operation, 8192 B of additional disk space will be used. 155s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libc6-dev s390x 2.41-1ubuntu2 [1678 kB] 158s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libc-dev-bin s390x 2.41-1ubuntu2 [24.3 kB] 158s Get:3 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libc6 s390x 2.41-1ubuntu2 [2892 kB] 161s Get:4 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libc-bin s390x 2.41-1ubuntu2 [671 kB] 161s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x locales all 2.41-1ubuntu2 [4246 kB] 166s Preconfiguring packages ... 166s Fetched 9512 kB in 11s (874 kB/s) 166s (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 ... 56326 files and directories currently installed.) 166s Preparing to unpack .../libc6-dev_2.41-1ubuntu2_s390x.deb ... 166s Unpacking libc6-dev:s390x (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 166s Preparing to unpack .../libc-dev-bin_2.41-1ubuntu2_s390x.deb ... 166s Unpacking libc-dev-bin (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 166s Preparing to unpack .../libc6_2.41-1ubuntu2_s390x.deb ... 167s Unpacking libc6:s390x (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 167s Setting up libc6:s390x (2.41-1ubuntu2) ... 167s (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 ... 56326 files and directories currently installed.) 167s Preparing to unpack .../libc-bin_2.41-1ubuntu2_s390x.deb ... 167s Unpacking libc-bin (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 167s Setting up libc-bin (2.41-1ubuntu2) ... 167s (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 ... 56326 files and directories currently installed.) 167s Preparing to unpack .../locales_2.41-1ubuntu2_all.deb ... 167s Unpacking locales (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 167s Setting up locales (2.41-1ubuntu2) ... 167s Generating locales (this might take a while)... 168s en_US.UTF-8... done 168s Generation complete. 168s Setting up libc-dev-bin (2.41-1ubuntu2) ... 168s Setting up libc6-dev:s390x (2.41-1ubuntu2) ... 168s Processing triggers for man-db (2.13.0-1) ... 169s Processing triggers for systemd (257.3-1ubuntu3) ... 170s Reading package lists... 170s Building dependency tree... 170s Reading state information... 170s Starting pkgProblemResolver with broken count: 0 170s Starting 2 pkgProblemResolver with broken count: 0 170s Done 170s Solving dependencies... 170s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 170s autopkgtest [11:09:57]: rebooting testbed after setup commands that affected boot 189s autopkgtest [11:10:16]: testbed running kernel: Linux 6.14.0-10-generic #10-Ubuntu SMP Wed Mar 12 14:53:49 UTC 2025 192s autopkgtest [11:10:19]: @@@@@@@@@@@@@@@@@@@@ apt-source pglogical 194s Get:1 http://ftpmaster.internal/ubuntu plucky/universe pglogical 2.4.5-1 (dsc) [2380 B] 194s Get:2 http://ftpmaster.internal/ubuntu plucky/universe pglogical 2.4.5-1 (tar) [283 kB] 194s Get:3 http://ftpmaster.internal/ubuntu plucky/universe pglogical 2.4.5-1 (diff) [180 kB] 194s gpgv: Signature made Tue Sep 24 14:05:34 2024 UTC 194s gpgv: using RSA key 5C48FE6157F49179597087C64C5A6BAB12D2A7AE 194s gpgv: Can't check signature: No public key 194s dpkg-source: warning: cannot verify inline signature for ./pglogical_2.4.5-1.dsc: no acceptable signature found 194s autopkgtest [11:10:21]: testing package pglogical version 2.4.5-1 195s autopkgtest [11:10:22]: build not needed 197s autopkgtest [11:10:24]: test prove: preparing testbed 197s Reading package lists... 197s Building dependency tree... 197s Reading state information... 197s Starting pkgProblemResolver with broken count: 0 197s Starting 2 pkgProblemResolver with broken count: 0 197s Done 197s The following NEW packages will be installed: 197s libio-pty-perl libipc-run-perl libjson-perl libllvm20 libpq5 197s libtap-parser-sourcehandler-pgtap-perl libxslt1.1 postgresql-17 197s postgresql-17-pglogical postgresql-client-17 postgresql-client-common 197s postgresql-common postgresql-common-dev ssl-cert 198s 0 upgraded, 14 newly installed, 0 to remove and 0 not upgraded. 198s Need to get 50.2 MB of archives. 198s After this operation, 214 MB of additional disk space will be used. 198s Get:1 http://ftpmaster.internal/ubuntu plucky/main s390x libjson-perl all 4.10000-1 [81.9 kB] 198s Get:2 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-client-common all 274 [47.6 kB] 198s Get:3 http://ftpmaster.internal/ubuntu plucky/main s390x libio-pty-perl s390x 1:1.20-1build3 [31.6 kB] 198s Get:4 http://ftpmaster.internal/ubuntu plucky/main s390x libipc-run-perl all 20231003.0-2 [91.5 kB] 198s Get:5 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-common-dev all 274 [73.0 kB] 198s Get:6 http://ftpmaster.internal/ubuntu plucky/main s390x ssl-cert all 1.1.3ubuntu1 [18.7 kB] 198s Get:7 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-common all 274 [101 kB] 198s Get:8 http://ftpmaster.internal/ubuntu plucky/main s390x libllvm20 s390x 1:20.1.0~+rc2-1~exp2ubuntu0.4 [31.3 MB] 235s Get:9 http://ftpmaster.internal/ubuntu plucky/main s390x libpq5 s390x 17.4-1 [147 kB] 235s Get:10 http://ftpmaster.internal/ubuntu plucky/main s390x libxslt1.1 s390x 1.1.39-0exp1ubuntu2 [169 kB] 235s Get:11 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-client-17 s390x 17.4-1 [1367 kB] 237s Get:12 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-17 s390x 17.4-1 [16.3 MB] 255s Get:13 http://ftpmaster.internal/ubuntu plucky/universe s390x postgresql-17-pglogical s390x 2.4.5-1 [391 kB] 255s Get:14 http://ftpmaster.internal/ubuntu plucky/universe s390x libtap-parser-sourcehandler-pgtap-perl all 3.36-2 [35.2 kB] 255s Preconfiguring packages ... 255s Fetched 50.2 MB in 58s (871 kB/s) 255s Selecting previously unselected package libjson-perl. 255s (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 ... 56326 files and directories currently installed.) 255s Preparing to unpack .../00-libjson-perl_4.10000-1_all.deb ... 255s Unpacking libjson-perl (4.10000-1) ... 255s Selecting previously unselected package postgresql-client-common. 255s Preparing to unpack .../01-postgresql-client-common_274_all.deb ... 255s Unpacking postgresql-client-common (274) ... 255s Selecting previously unselected package libio-pty-perl. 255s Preparing to unpack .../02-libio-pty-perl_1%3a1.20-1build3_s390x.deb ... 255s Unpacking libio-pty-perl (1:1.20-1build3) ... 255s Selecting previously unselected package libipc-run-perl. 255s Preparing to unpack .../03-libipc-run-perl_20231003.0-2_all.deb ... 255s Unpacking libipc-run-perl (20231003.0-2) ... 255s Selecting previously unselected package postgresql-common-dev. 255s Preparing to unpack .../04-postgresql-common-dev_274_all.deb ... 255s Unpacking postgresql-common-dev (274) ... 255s Selecting previously unselected package ssl-cert. 255s Preparing to unpack .../05-ssl-cert_1.1.3ubuntu1_all.deb ... 255s Unpacking ssl-cert (1.1.3ubuntu1) ... 255s Selecting previously unselected package postgresql-common. 255s Preparing to unpack .../06-postgresql-common_274_all.deb ... 255s Adding 'diversion of /usr/bin/pg_config to /usr/bin/pg_config.libpq-dev by postgresql-common' 255s Unpacking postgresql-common (274) ... 255s Selecting previously unselected package libllvm20:s390x. 255s Preparing to unpack .../07-libllvm20_1%3a20.1.0~+rc2-1~exp2ubuntu0.4_s390x.deb ... 255s Unpacking libllvm20:s390x (1:20.1.0~+rc2-1~exp2ubuntu0.4) ... 256s Selecting previously unselected package libpq5:s390x. 256s Preparing to unpack .../08-libpq5_17.4-1_s390x.deb ... 256s Unpacking libpq5:s390x (17.4-1) ... 256s Selecting previously unselected package libxslt1.1:s390x. 256s Preparing to unpack .../09-libxslt1.1_1.1.39-0exp1ubuntu2_s390x.deb ... 256s Unpacking libxslt1.1:s390x (1.1.39-0exp1ubuntu2) ... 256s Selecting previously unselected package postgresql-client-17. 256s Preparing to unpack .../10-postgresql-client-17_17.4-1_s390x.deb ... 256s Unpacking postgresql-client-17 (17.4-1) ... 256s Selecting previously unselected package postgresql-17. 256s Preparing to unpack .../11-postgresql-17_17.4-1_s390x.deb ... 256s Unpacking postgresql-17 (17.4-1) ... 256s Selecting previously unselected package postgresql-17-pglogical. 256s Preparing to unpack .../12-postgresql-17-pglogical_2.4.5-1_s390x.deb ... 256s Unpacking postgresql-17-pglogical (2.4.5-1) ... 256s Selecting previously unselected package libtap-parser-sourcehandler-pgtap-perl. 256s Preparing to unpack .../13-libtap-parser-sourcehandler-pgtap-perl_3.36-2_all.deb ... 256s Unpacking libtap-parser-sourcehandler-pgtap-perl (3.36-2) ... 256s Setting up postgresql-client-common (274) ... 256s Setting up libtap-parser-sourcehandler-pgtap-perl (3.36-2) ... 256s Setting up libio-pty-perl (1:1.20-1build3) ... 256s Setting up libpq5:s390x (17.4-1) ... 256s Setting up ssl-cert (1.1.3ubuntu1) ... 257s Created symlink '/etc/systemd/system/multi-user.target.wants/ssl-cert.service' → '/usr/lib/systemd/system/ssl-cert.service'. 257s Setting up libllvm20:s390x (1:20.1.0~+rc2-1~exp2ubuntu0.4) ... 257s Setting up libipc-run-perl (20231003.0-2) ... 257s Setting up libjson-perl (4.10000-1) ... 257s Setting up libxslt1.1:s390x (1.1.39-0exp1ubuntu2) ... 257s Setting up postgresql-common-dev (274) ... 257s Setting up postgresql-client-17 (17.4-1) ... 257s update-alternatives: using /usr/share/postgresql/17/man/man1/psql.1.gz to provide /usr/share/man/man1/psql.1.gz (psql.1.gz) in auto mode 257s Setting up postgresql-common (274) ... 257s Creating config file /etc/postgresql-common/createcluster.conf with new version 257s Building PostgreSQL dictionaries from installed myspell/hunspell packages... 257s Removing obsolete dictionary files: 258s Created symlink '/etc/systemd/system/multi-user.target.wants/postgresql.service' → '/usr/lib/systemd/system/postgresql.service'. 258s Setting up postgresql-17 (17.4-1) ... 259s Creating new PostgreSQL cluster 17/main ... 259s /usr/lib/postgresql/17/bin/initdb -D /var/lib/postgresql/17/main --auth-local peer --auth-host scram-sha-256 --no-instructions 259s The files belonging to this database system will be owned by user "postgres". 259s This user must also own the server process. 259s 259s The database cluster will be initialized with locale "C.UTF-8". 259s The default database encoding has accordingly been set to "UTF8". 259s The default text search configuration will be set to "english". 259s 259s Data page checksums are disabled. 259s 259s fixing permissions on existing directory /var/lib/postgresql/17/main ... ok 259s creating subdirectories ... ok 259s selecting dynamic shared memory implementation ... posix 259s selecting default "max_connections" ... 100 259s selecting default "shared_buffers" ... 128MB 259s selecting default time zone ... Etc/UTC 259s creating configuration files ... ok 259s running bootstrap script ... ok 259s performing post-bootstrap initialization ... ok 259s syncing data to disk ... ok 262s Setting up postgresql-17-pglogical (2.4.5-1) ... 262s Processing triggers for man-db (2.13.0-1) ... 263s Processing triggers for libc-bin (2.41-1ubuntu2) ... 264s autopkgtest [11:11:31]: test prove: [----------------------- 264s ### 17 ### 264s Skipping prove test on PG 17, test not compatible yet 264s cp: cannot stat '/tmp/regresscheck.dzG9yy/tmp_check/log/*': No such file or directory 264s autopkgtest [11:11:31]: test prove: -----------------------] 265s prove PASS 265s autopkgtest [11:11:32]: test prove: - - - - - - - - - - results - - - - - - - - - - 265s autopkgtest [11:11:32]: test regresscheck: preparing testbed 385s autopkgtest [11:13:32]: testbed dpkg architecture: s390x 385s autopkgtest [11:13:32]: testbed apt version: 2.9.33 386s autopkgtest [11:13:33]: @@@@@@@@@@@@@@@@@@@@ test bed setup 386s autopkgtest [11:13:33]: testbed release detected to be: plucky 387s autopkgtest [11:13:34]: updating testbed package index (apt update) 387s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [126 kB] 387s Hit:2 http://ftpmaster.internal/ubuntu plucky InRelease 387s Hit:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease 387s Hit:4 http://ftpmaster.internal/ubuntu plucky-security InRelease 387s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [15.8 kB] 387s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [410 kB] 388s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [46.2 kB] 388s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x Packages [80.7 kB] 388s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x c-n-f Metadata [1852 B] 388s Get:10 http://ftpmaster.internal/ubuntu plucky-proposed/restricted s390x c-n-f Metadata [116 B] 388s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/universe s390x Packages [335 kB] 388s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/universe s390x c-n-f Metadata [14.4 kB] 388s Get:13 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse s390x Packages [3776 B] 388s Get:14 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse s390x c-n-f Metadata [328 B] 388s Fetched 1034 kB in 1s (754 kB/s) 389s Reading package lists... 389s Reading package lists... 390s Building dependency tree... 390s Reading state information... 390s Calculating upgrade... 390s Calculating upgrade... 390s The following packages were automatically installed and are no longer required: 390s libnsl2 libpython3.12-minimal libpython3.12-stdlib libpython3.12t64 390s linux-headers-6.11.0-8 linux-headers-6.11.0-8-generic 390s linux-modules-6.11.0-8-generic linux-tools-6.11.0-8 390s linux-tools-6.11.0-8-generic 390s Use 'sudo apt autoremove' to remove them. 390s The following packages will be upgraded: 390s python3-jinja2 strace 390s 2 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 390s Need to get 609 kB of archives. 390s After this operation, 27.6 kB of additional disk space will be used. 390s Get:1 http://ftpmaster.internal/ubuntu plucky/main s390x strace s390x 6.13+ds-1ubuntu1 [500 kB] 391s Get:2 http://ftpmaster.internal/ubuntu plucky/main s390x python3-jinja2 all 3.1.5-2ubuntu1 [109 kB] 391s Fetched 609 kB in 1s (757 kB/s) 391s (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 ... 81428 files and directories currently installed.) 391s Preparing to unpack .../strace_6.13+ds-1ubuntu1_s390x.deb ... 391s Unpacking strace (6.13+ds-1ubuntu1) over (6.11-0ubuntu1) ... 391s Preparing to unpack .../python3-jinja2_3.1.5-2ubuntu1_all.deb ... 391s Unpacking python3-jinja2 (3.1.5-2ubuntu1) over (3.1.5-2) ... 391s Setting up python3-jinja2 (3.1.5-2ubuntu1) ... 391s Setting up strace (6.13+ds-1ubuntu1) ... 391s Processing triggers for man-db (2.13.0-1) ... 392s Reading package lists... 392s Building dependency tree... 392s Reading state information... 392s Solving dependencies... 392s The following packages will be REMOVED: 392s libnsl2* libpython3.12-minimal* libpython3.12-stdlib* libpython3.12t64* 392s linux-headers-6.11.0-8* linux-headers-6.11.0-8-generic* 392s linux-modules-6.11.0-8-generic* linux-tools-6.11.0-8* 392s linux-tools-6.11.0-8-generic* 392s 0 upgraded, 0 newly installed, 9 to remove and 5 not upgraded. 392s After this operation, 167 MB disk space will be freed. 392s (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 ... 81428 files and directories currently installed.) 392s Removing linux-tools-6.11.0-8-generic (6.11.0-8.8) ... 392s Removing linux-tools-6.11.0-8 (6.11.0-8.8) ... 392s Removing libpython3.12t64:s390x (3.12.9-1) ... 392s Removing libpython3.12-stdlib:s390x (3.12.9-1) ... 392s Removing libnsl2:s390x (1.3.0-3build3) ... 392s Removing libpython3.12-minimal:s390x (3.12.9-1) ... 392s Removing linux-headers-6.11.0-8-generic (6.11.0-8.8) ... 393s Removing linux-headers-6.11.0-8 (6.11.0-8.8) ... 393s Removing linux-modules-6.11.0-8-generic (6.11.0-8.8) ... 394s Processing triggers for libc-bin (2.41-1ubuntu1) ... 394s (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 ... 56328 files and directories currently installed.) 394s Purging configuration files for libpython3.12-minimal:s390x (3.12.9-1) ... 394s Purging configuration files for linux-modules-6.11.0-8-generic (6.11.0-8.8) ... 394s autopkgtest [11:13:41]: upgrading testbed (apt dist-upgrade and autopurge) 394s Reading package lists... 394s Building dependency tree... 394s Reading state information... 394s Calculating upgrade...Starting pkgProblemResolver with broken count: 0 394s Starting 2 pkgProblemResolver with broken count: 0 394s Done 394s Entering ResolveByKeep 395s 395s Calculating upgrade... 395s The following packages will be upgraded: 395s libc-bin libc-dev-bin libc6 libc6-dev locales 395s 5 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 395s Need to get 9512 kB of archives. 395s After this operation, 8192 B of additional disk space will be used. 395s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libc6-dev s390x 2.41-1ubuntu2 [1678 kB] 396s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libc-dev-bin s390x 2.41-1ubuntu2 [24.3 kB] 396s Get:3 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libc6 s390x 2.41-1ubuntu2 [2892 kB] 398s Get:4 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libc-bin s390x 2.41-1ubuntu2 [671 kB] 398s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x locales all 2.41-1ubuntu2 [4246 kB] 400s Preconfiguring packages ... 400s Fetched 9512 kB in 5s (1844 kB/s) 400s (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 ... 56326 files and directories currently installed.) 400s Preparing to unpack .../libc6-dev_2.41-1ubuntu2_s390x.deb ... 400s Unpacking libc6-dev:s390x (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 400s Preparing to unpack .../libc-dev-bin_2.41-1ubuntu2_s390x.deb ... 400s Unpacking libc-dev-bin (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 400s Preparing to unpack .../libc6_2.41-1ubuntu2_s390x.deb ... 400s Unpacking libc6:s390x (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 400s Setting up libc6:s390x (2.41-1ubuntu2) ... 401s (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 ... 56326 files and directories currently installed.) 401s Preparing to unpack .../libc-bin_2.41-1ubuntu2_s390x.deb ... 401s Unpacking libc-bin (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 401s Setting up libc-bin (2.41-1ubuntu2) ... 401s (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 ... 56326 files and directories currently installed.) 401s Preparing to unpack .../locales_2.41-1ubuntu2_all.deb ... 401s Unpacking locales (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 401s Setting up locales (2.41-1ubuntu2) ... 401s Generating locales (this might take a while)... 402s en_US.UTF-8... done 402s Generation complete. 402s Setting up libc-dev-bin (2.41-1ubuntu2) ... 402s Setting up libc6-dev:s390x (2.41-1ubuntu2) ... 402s Processing triggers for man-db (2.13.0-1) ... 403s Processing triggers for systemd (257.3-1ubuntu3) ... 404s Reading package lists... 404s Building dependency tree... 404s Reading state information... 404s Starting pkgProblemResolver with broken count: 0 404s Starting 2 pkgProblemResolver with broken count: 0 404s Done 404s Solving dependencies... 404s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 404s autopkgtest [11:13:51]: rebooting testbed after setup commands that affected boot 427s Reading package lists... 427s Building dependency tree... 427s Reading state information... 427s Starting pkgProblemResolver with broken count: 0 427s Starting 2 pkgProblemResolver with broken count: 0 427s Done 427s The following NEW packages will be installed: 427s libio-pty-perl libipc-run-perl libjson-perl libllvm20 libpq5 libxslt1.1 427s postgresql-17 postgresql-17-pglogical postgresql-client-17 427s postgresql-client-common postgresql-common postgresql-common-dev ssl-cert 427s 0 upgraded, 13 newly installed, 0 to remove and 0 not upgraded. 427s Need to get 50.1 MB of archives. 427s After this operation, 214 MB of additional disk space will be used. 427s Get:1 http://ftpmaster.internal/ubuntu plucky/main s390x libjson-perl all 4.10000-1 [81.9 kB] 427s Get:2 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-client-common all 274 [47.6 kB] 427s Get:3 http://ftpmaster.internal/ubuntu plucky/main s390x libio-pty-perl s390x 1:1.20-1build3 [31.6 kB] 427s Get:4 http://ftpmaster.internal/ubuntu plucky/main s390x libipc-run-perl all 20231003.0-2 [91.5 kB] 428s Get:5 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-common-dev all 274 [73.0 kB] 428s Get:6 http://ftpmaster.internal/ubuntu plucky/main s390x ssl-cert all 1.1.3ubuntu1 [18.7 kB] 428s Get:7 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-common all 274 [101 kB] 428s Get:8 http://ftpmaster.internal/ubuntu plucky/main s390x libllvm20 s390x 1:20.1.0~+rc2-1~exp2ubuntu0.4 [31.3 MB] 462s Get:9 http://ftpmaster.internal/ubuntu plucky/main s390x libpq5 s390x 17.4-1 [147 kB] 463s Get:10 http://ftpmaster.internal/ubuntu plucky/main s390x libxslt1.1 s390x 1.1.39-0exp1ubuntu2 [169 kB] 463s Get:11 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-client-17 s390x 17.4-1 [1367 kB] 464s Get:12 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-17 s390x 17.4-1 [16.3 MB] 484s Get:13 http://ftpmaster.internal/ubuntu plucky/universe s390x postgresql-17-pglogical s390x 2.4.5-1 [391 kB] 484s Preconfiguring packages ... 484s Fetched 50.1 MB in 57s (878 kB/s) 484s Selecting previously unselected package libjson-perl. 484s (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 ... 56326 files and directories currently installed.) 484s Preparing to unpack .../00-libjson-perl_4.10000-1_all.deb ... 484s Unpacking libjson-perl (4.10000-1) ... 485s Selecting previously unselected package postgresql-client-common. 485s Preparing to unpack .../01-postgresql-client-common_274_all.deb ... 485s Unpacking postgresql-client-common (274) ... 485s Selecting previously unselected package libio-pty-perl. 485s Preparing to unpack .../02-libio-pty-perl_1%3a1.20-1build3_s390x.deb ... 485s Unpacking libio-pty-perl (1:1.20-1build3) ... 485s Selecting previously unselected package libipc-run-perl. 485s Preparing to unpack .../03-libipc-run-perl_20231003.0-2_all.deb ... 485s Unpacking libipc-run-perl (20231003.0-2) ... 485s Selecting previously unselected package postgresql-common-dev. 485s Preparing to unpack .../04-postgresql-common-dev_274_all.deb ... 485s Unpacking postgresql-common-dev (274) ... 485s Selecting previously unselected package ssl-cert. 485s Preparing to unpack .../05-ssl-cert_1.1.3ubuntu1_all.deb ... 485s Unpacking ssl-cert (1.1.3ubuntu1) ... 485s Selecting previously unselected package postgresql-common. 485s Preparing to unpack .../06-postgresql-common_274_all.deb ... 485s Adding 'diversion of /usr/bin/pg_config to /usr/bin/pg_config.libpq-dev by postgresql-common' 485s Unpacking postgresql-common (274) ... 485s Selecting previously unselected package libllvm20:s390x. 485s Preparing to unpack .../07-libllvm20_1%3a20.1.0~+rc2-1~exp2ubuntu0.4_s390x.deb ... 485s Unpacking libllvm20:s390x (1:20.1.0~+rc2-1~exp2ubuntu0.4) ... 485s Selecting previously unselected package libpq5:s390x. 485s Preparing to unpack .../08-libpq5_17.4-1_s390x.deb ... 485s Unpacking libpq5:s390x (17.4-1) ... 485s Selecting previously unselected package libxslt1.1:s390x. 485s Preparing to unpack .../09-libxslt1.1_1.1.39-0exp1ubuntu2_s390x.deb ... 485s Unpacking libxslt1.1:s390x (1.1.39-0exp1ubuntu2) ... 485s Selecting previously unselected package postgresql-client-17. 485s Preparing to unpack .../10-postgresql-client-17_17.4-1_s390x.deb ... 485s Unpacking postgresql-client-17 (17.4-1) ... 485s Selecting previously unselected package postgresql-17. 485s Preparing to unpack .../11-postgresql-17_17.4-1_s390x.deb ... 485s Unpacking postgresql-17 (17.4-1) ... 485s Selecting previously unselected package postgresql-17-pglogical. 485s Preparing to unpack .../12-postgresql-17-pglogical_2.4.5-1_s390x.deb ... 485s Unpacking postgresql-17-pglogical (2.4.5-1) ... 485s Setting up postgresql-client-common (274) ... 485s Setting up libio-pty-perl (1:1.20-1build3) ... 485s Setting up libpq5:s390x (17.4-1) ... 485s Setting up ssl-cert (1.1.3ubuntu1) ... 486s Created symlink '/etc/systemd/system/multi-user.target.wants/ssl-cert.service' → '/usr/lib/systemd/system/ssl-cert.service'. 486s Setting up libllvm20:s390x (1:20.1.0~+rc2-1~exp2ubuntu0.4) ... 486s Setting up libipc-run-perl (20231003.0-2) ... 486s Setting up libjson-perl (4.10000-1) ... 486s Setting up libxslt1.1:s390x (1.1.39-0exp1ubuntu2) ... 486s Setting up postgresql-common-dev (274) ... 486s Setting up postgresql-client-17 (17.4-1) ... 486s update-alternatives: using /usr/share/postgresql/17/man/man1/psql.1.gz to provide /usr/share/man/man1/psql.1.gz (psql.1.gz) in auto mode 486s Setting up postgresql-common (274) ... 487s Creating config file /etc/postgresql-common/createcluster.conf with new version 487s Building PostgreSQL dictionaries from installed myspell/hunspell packages... 487s Removing obsolete dictionary files: 487s Created symlink '/etc/systemd/system/multi-user.target.wants/postgresql.service' → '/usr/lib/systemd/system/postgresql.service'. 487s Setting up postgresql-17 (17.4-1) ... 488s Creating new PostgreSQL cluster 17/main ... 488s /usr/lib/postgresql/17/bin/initdb -D /var/lib/postgresql/17/main --auth-local peer --auth-host scram-sha-256 --no-instructions 488s The files belonging to this database system will be owned by user "postgres". 488s This user must also own the server process. 488s 488s The database cluster will be initialized with locale "C.UTF-8". 488s The default database encoding has accordingly been set to "UTF8". 488s The default text search configuration will be set to "english". 488s 488s Data page checksums are disabled. 488s 488s fixing permissions on existing directory /var/lib/postgresql/17/main ... ok 488s creating subdirectories ... ok 488s selecting dynamic shared memory implementation ... posix 488s selecting default "max_connections" ... 100 488s selecting default "shared_buffers" ... 128MB 488s selecting default time zone ... Etc/UTC 488s creating configuration files ... ok 488s running bootstrap script ... ok 488s performing post-bootstrap initialization ... ok 488s syncing data to disk ... ok 491s Setting up postgresql-17-pglogical (2.4.5-1) ... 491s Processing triggers for man-db (2.13.0-1) ... 492s Processing triggers for libc-bin (2.41-1ubuntu2) ... 496s autopkgtest [11:15:23]: test regresscheck: [----------------------- 496s ### 17 ### 496s /bin/mkdir -p regression_output 496s echo "# +++ regress install-check in +++" && /usr/lib/postgresql/17/lib/pgxs/src/makefiles/../../src/test/regress/pg_regress --inputdir=./ --bindir='/usr/lib/postgresql/17/bin' \ 496s --temp-config ./regress-postgresql.conf \ 496s --temp-instance=./tmp_check \ 496s --outputdir=./regression_output \ 496s --create-role=logical \ 496s preseed infofuncs init_fail init preseed_check basic extended conflict_secondary_unique toasted replication_set matview bidirectional interfaces foreign_key functions copy sequence triggers parallel row_filter att_list column_filter apply_delay node_origin_cascade drop 496s # +++ regress install-check in +++ 496s # initializing database system by running initdb 497s # using temp instance on port 55316 with PID 3417 497s ok 1 - preseed 69 ms 497s ok 2 - infofuncs 40 ms 497s not ok 3 - init_fail 85 ms 497s not ok 4 - init 268 ms 497s ok 5 - preseed_check 19 ms 506s ok 6 - basic 9091 ms 558s ok 7 - extended 51569 ms 558s ok 8 - conflict_secondary_unique 22 ms 561s ok 9 - toasted 3036 ms 561s not ok 10 - replication_set 29 ms 565s ok 11 - matview 4048 ms 569s not ok 12 - bidirectional 4262 ms 570s not ok 13 - interfaces 1131 ms 572s ok 14 - foreign_key 2022 ms 579s ok 15 - functions 7122 ms 580s ok 16 - copy 1020 ms 580s not ok 17 - sequence 16 ms 586s ok 18 - triggers 6083 ms 590s not ok 19 - parallel 3258 ms 599s ok 20 - row_filter 9080 ms 603s ok 21 - att_list 4109 ms 605s ok 22 - column_filter 2244 ms 611s not ok 23 - apply_delay 6266 ms 615s not ok 24 - node_origin_cascade 3295 ms 616s ok 25 - drop 1043 ms 616s 1..25 616s diff -U3 /tmp/regresscheck.yhGUBn/expected/init_fail.out /tmp/regresscheck.yhGUBn/regression_output/results/init_fail.out 616s --- /tmp/regresscheck.yhGUBn/expected/init_fail.out 2025-03-15 11:15:23.523757404 +0000 616s +++ /tmp/regresscheck.yhGUBn/regression_output/results/init_fail.out 2025-03-15 11:15:24.213239149 +0000 616s @@ -42,7 +42,7 @@ 616s SELECT * FROM pglogical.create_node(node_name := 'test_subscriber', dsn := (SELECT subscriber_dsn FROM pglogical_regress_variables()) || ' user=nonreplica'); 616s create_node 616s ------------- 616s - 1755434425 616s + 2095496919 616s (1 row) 616s 616s -- fail (can't connect to remote) 616s @@ -72,7 +72,7 @@ 616s SELECT * FROM pglogical.create_node(node_name := 'test_provider', dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=nonreplica'); 616s create_node 616s ------------- 616s - 2689511696 616s + 3385836371 616s (1 row) 616s 616s \c :subscriber_dsn 616s diff -U3 /tmp/regresscheck.yhGUBn/expected/init.out /tmp/regresscheck.yhGUBn/regression_output/results/init.out 616s --- /tmp/regresscheck.yhGUBn/expected/init.out 2025-03-15 11:15:23.523607573 +0000 616s +++ /tmp/regresscheck.yhGUBn/regression_output/results/init.out 2025-03-15 11:15:24.493237709 +0000 616s @@ -64,7 +64,7 @@ 616s SELECT * FROM pglogical.create_node(node_name := 'test_provider', dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=super'); 616s create_node 616s ------------- 616s - 2689511696 616s + 3385836371 616s (1 row) 616s 616s \c :subscriber_dsn 616s @@ -79,7 +79,7 @@ 616s SELECT * FROM pglogical.create_node(node_name := 'test_subscriber', dsn := (SELECT subscriber_dsn FROM pglogical_regress_variables()) || ' user=super'); 616s create_node 616s ------------- 616s - 1755434425 616s + 2095496919 616s (1 row) 616s 616s BEGIN; 616s @@ -90,7 +90,7 @@ 616s forward_origins := '{}'); 616s create_subscription 616s --------------------- 616s - 3848008564 616s + 2208722835 616s (1 row) 616s 616s /* 616s @@ -112,7 +112,7 @@ 616s SELECT sync_kind, sync_subid, sync_nspname, sync_relname, sync_status IN ('y', 'r') FROM pglogical.local_sync_status ORDER BY 2,3,4; 616s sync_kind | sync_subid | sync_nspname | sync_relname | ?column? 616s -----------+------------+--------------+--------------+---------- 616s - f | 3848008564 | | | t 616s + f | 2208722835 | | | t 616s (1 row) 616s 616s -- Make sure we see the slot and active connection 616s diff -U3 /tmp/regresscheck.yhGUBn/expected/replication_set.out /tmp/regresscheck.yhGUBn/regression_output/results/replication_set.out 616s --- /tmp/regresscheck.yhGUBn/expected/replication_set.out 2025-03-15 11:15:23.523560050 +0000 616s +++ /tmp/regresscheck.yhGUBn/regression_output/results/replication_set.out 2025-03-15 11:16:28.272262947 +0000 616s @@ -50,19 +50,19 @@ 616s SELECT * FROM pglogical.create_replication_set('repset_replicate_all'); 616s create_replication_set 616s ------------------------ 616s - 1767380104 616s + 3885206554 616s (1 row) 616s 616s SELECT * FROM pglogical.create_replication_set('repset_replicate_instrunc', replicate_update := false, replicate_delete := false); 616s create_replication_set 616s ------------------------ 616s - 348382733 616s + 4149578203 616s (1 row) 616s 616s SELECT * FROM pglogical.create_replication_set('repset_replicate_insupd', replicate_delete := false, replicate_truncate := false); 616s create_replication_set 616s ------------------------ 616s - 128878480 616s + 2580819485 616s (1 row) 616s 616s -- add tables 616s @@ -107,7 +107,7 @@ 616s SELECT * FROM pglogical.alter_replication_set('repset_replicate_insupd', replicate_truncate := true); 616s alter_replication_set 616s ----------------------- 616s - 128878480 616s + 2580819485 616s (1 row) 616s 616s -- fail again 616s @@ -226,8 +226,8 @@ 616s SELECT * FROM pglogical.replication_set; 616s set_id | set_nodeid | set_name | replicate_insert | replicate_update | replicate_delete | replicate_truncate 616s ------------+------------+---------------------+------------------+------------------+------------------+-------------------- 616s - 828867312 | 1755434425 | default | t | t | t | t 616s - 3318003856 | 1755434425 | default_insert_only | t | f | f | t 616s - 2796587818 | 1755434425 | ddl_sql | t | f | f | f 616s + 819356807 | 2095496919 | default | t | t | t | t 616s + 2454072499 | 2095496919 | default_insert_only | t | f | f | t 616s + 2627772969 | 2095496919 | ddl_sql | t | f | f | f 616s (3 rows) 616s 616s diff -U3 /tmp/regresscheck.yhGUBn/expected/bidirectional.out /tmp/regresscheck.yhGUBn/regression_output/results/bidirectional.out 616s --- /tmp/regresscheck.yhGUBn/expected/bidirectional.out 2025-03-15 11:15:23.524181705 +0000 616s +++ /tmp/regresscheck.yhGUBn/regression_output/results/bidirectional.out 2025-03-15 11:16:36.583984447 +0000 616s @@ -23,7 +23,7 @@ 616s forward_origins := '{}'); 616s create_subscription 616s --------------------- 616s - 4269973126 616s + 427419238 616s (1 row) 616s 616s BEGIN; 616s diff -U3 /tmp/regresscheck.yhGUBn/expected/interfaces.out /tmp/regresscheck.yhGUBn/regression_output/results/interfaces.out 616s --- /tmp/regresscheck.yhGUBn/expected/interfaces.out 2025-03-15 11:15:23.523785576 +0000 616s +++ /tmp/regresscheck.yhGUBn/regression_output/results/interfaces.out 2025-03-15 11:16:37.717691712 +0000 616s @@ -6,7 +6,7 @@ 616s SELECT * FROM pglogical.alter_node_add_interface('test_provider', 'super2', (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=super2'); 616s alter_node_add_interface 616s -------------------------- 616s - 3319308158 616s + 1597668009 616s (1 row) 616s 616s SELECT * FROM pglogical.alter_subscription_interface('test_subscription', 'super2'); 616s diff -U3 /tmp/regresscheck.yhGUBn/expected/sequence.out /tmp/regresscheck.yhGUBn/regression_output/results/sequence.out 616s --- /tmp/regresscheck.yhGUBn/expected/sequence.out 2025-03-15 11:15:23.524063468 +0000 616s +++ /tmp/regresscheck.yhGUBn/regression_output/results/sequence.out 2025-03-15 11:16:47.907816202 +0000 616s @@ -19,7 +19,7 @@ 616s SELECT * FROM pglogical.create_replication_set('stress_seq'); 616s create_replication_set 616s ------------------------ 616s - 2261733486 616s + 3511091149 616s (1 row) 616s 616s SELECT * FROM pglogical.replication_set_add_sequence('stress_seq', 'stress'); 616s diff -U3 /tmp/regresscheck.yhGUBn/expected/parallel.out /tmp/regresscheck.yhGUBn/regression_output/results/parallel.out 616s --- /tmp/regresscheck.yhGUBn/expected/parallel.out 2025-03-15 11:15:23.523593110 +0000 616s +++ /tmp/regresscheck.yhGUBn/regression_output/results/parallel.out 2025-03-15 11:16:57.248447175 +0000 616s @@ -4,7 +4,7 @@ 616s SELECT * FROM pglogical.create_replication_set('parallel'); 616s create_replication_set 616s ------------------------ 616s - 3731651575 616s + 2651258374 616s (1 row) 616s 616s \c :subscriber_dsn 616s @@ -27,7 +27,7 @@ 616s ); 616s create_subscription 616s --------------------- 616s - 4051189029 616s + 3093400622 616s (1 row) 616s 616s BEGIN; 616s @@ -42,15 +42,15 @@ 616s SELECT sync_kind, sync_subid, sync_nspname, sync_relname, sync_status IN ('y', 'r') FROM pglogical.local_sync_status ORDER BY 2,3,4; 616s sync_kind | sync_subid | sync_nspname | sync_relname | ?column? 616s -----------+------------+--------------+--------------+---------- 616s - f | 3848008564 | | | t 616s - i | 4051189029 | | | t 616s + f | 2208722835 | | | t 616s + i | 3093400622 | | | t 616s (2 rows) 616s 616s SELECT * FROM pglogical.show_subscription_status(); 616s subscription_name | status | provider_node | provider_dsn | slot_name | replication_sets | forward_origins 616s ----------------------------+-------------+---------------+------------------------------+--------------------------------------------+---------------------------------------+----------------- 616s - test_subscription | replicating | test_provider | dbname=regression user=super | pgl_postgres_test_provider_test_sube55bf37 | {default,default_insert_only,ddl_sql} | 616s - test_subscription_parallel | replicating | test_provider | dbname=regression user=super | pgl_postgres_test_provider_test_subf1783d2 | {parallel} | 616s + test_subscription | replicating | test_provider | dbname=regression user=super | pgl_postgres_test_provider_test_sub83a66f9 | {default,default_insert_only,ddl_sql} | 616s + test_subscription_parallel | replicating | test_provider | dbname=regression user=super | pgl_postgres_test_provider_test_subb8618c2 | {parallel} | 616s (2 rows) 616s 616s -- Make sure we see the slot and active connection 616s diff -U3 /tmp/regresscheck.yhGUBn/expected/apply_delay.out /tmp/regresscheck.yhGUBn/regression_output/results/apply_delay.out 616s --- /tmp/regresscheck.yhGUBn/expected/apply_delay.out 2025-03-15 11:15:23.524079278 +0000 616s +++ /tmp/regresscheck.yhGUBn/regression_output/results/apply_delay.out 2025-03-15 11:17:18.958561443 +0000 616s @@ -13,7 +13,7 @@ 616s SELECT * FROM pglogical.create_replication_set('delay'); 616s create_replication_set 616s ------------------------ 616s - 3064111751 616s + 2893814808 616s (1 row) 616s 616s \c :subscriber_dsn 616s @@ -31,7 +31,7 @@ 616s ); 616s create_subscription 616s --------------------- 616s - 1550781037 616s + 2943762286 616s (1 row) 616s 616s BEGIN; 616s @@ -46,8 +46,8 @@ 616s SELECT sync_kind, sync_subid, sync_nspname, sync_relname, sync_status IN ('y', 'r') FROM pglogical.local_sync_status ORDER BY 2,3,4; 616s sync_kind | sync_subid | sync_nspname | sync_relname | ?column? 616s -----------+------------+--------------+--------------+---------- 616s - i | 1550781037 | | | t 616s - f | 3848008564 | | | t 616s + f | 2208722835 | | | t 616s + i | 2943762286 | | | t 616s (2 rows) 616s 616s SELECT status FROM pglogical.show_subscription_status() WHERE subscription_name = 'test_subscription_delay'; 616s diff -U3 /tmp/regresscheck.yhGUBn/expected/node_origin_cascade.out /tmp/regresscheck.yhGUBn/regression_output/results/node_origin_cascade.out 616s --- /tmp/regresscheck.yhGUBn/expected/node_origin_cascade.out 2025-03-15 11:15:23.523770761 +0000 616s +++ /tmp/regresscheck.yhGUBn/regression_output/results/node_origin_cascade.out 2025-03-15 11:17:22.261511464 +0000 616s @@ -31,7 +31,7 @@ 616s SELECT * FROM pglogical.create_node(node_name := 'test_orig_provider', dsn := (SELECT orig_provider_dsn FROM pglogical_regress_variables()) || ' user=super'); 616s create_node 616s ------------- 616s - 4029216451 616s + 3047209138 616s (1 row) 616s 616s \c :provider_dsn 616s @@ -45,7 +45,7 @@ 616s forward_origins := '{}'); 616s create_subscription 616s --------------------- 616s - 3575176667 616s + 1728723354 616s (1 row) 616s 616s COMMIT; 616s @@ -67,7 +67,7 @@ 616s SELECT sync_kind, sync_subid, sync_nspname, sync_relname, sync_status IN ('y', 'r') FROM pglogical.local_sync_status ORDER BY 2,3,4; 616s sync_kind | sync_subid | sync_nspname | sync_relname | ?column? 616s -----------+------------+--------------+--------------+---------- 616s - d | 3575176667 | | | t 616s + d | 1728723354 | | | t 616s (1 row) 616s 616s -- Make sure we see the slot and active connection 616s *** regression_output/log/initdb.log *** 616s # 9 of 25 tests failed. 616s # The differences that caused some tests to fail can be viewed in the file "/tmp/regresscheck.yhGUBn/regression_output/regression.diffs". 616s # A copy of the test summary that you see above is saved in the file "/tmp/regresscheck.yhGUBn/regression_output/regression.out". 616s make: *** [Makefile:146: regresscheck] Error 1 616s Running in no-clean mode. Mistakes will not be cleaned up. 616s The files belonging to this database system will be owned by user "ubuntu". 616s This user must also own the server process. 616s 616s The database cluster will be initialized with this locale configuration: 616s locale provider: libc 616s LC_COLLATE: C.UTF-8 616s LC_CTYPE: C.UTF-8 616s LC_MESSAGES: C 616s LC_MONETARY: C.UTF-8 616s LC_NUMERIC: C.UTF-8 616s LC_TIME: C.UTF-8 616s The default database encoding has accordingly been set to "UTF8". 616s The default text search configuration will be set to "english". 616s 616s Data page checksums are disabled. 616s 616s creating directory /tmp/regresscheck.yhGUBn/tmp_check/data ... ok 616s creating subdirectories ... ok 616s selecting dynamic shared memory implementation ... posix 616s selecting default "max_connections" ... 100 616s selecting default "shared_buffers" ... 128MB 616s selecting default time zone ... Etc/UTC 616s creating configuration files ... ok 616s running bootstrap script ... ok 616s performing post-bootstrap initialization ... ok 616s 616s Sync to disk skipped. 616s The data directory might become corrupt if the operating system crashes. 616s 616s initdb: warning: enabling "trust" authentication for local connections 616s 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. 616s 616s Success. You can now start the database server using: 616s 616s /usr/lib/postgresql/17/bin/pg_ctl -D /tmp/regresscheck.yhGUBn/tmp_check/data -l logfile start 616s 616s *** regression_output/log/postmaster.log *** 616s [2025-03-15 11:15:23.968 UTC] [3417] [] LOG: starting PostgreSQL 17.4 (Ubuntu 17.4-1) on s390x-ibm-linux-gnu, compiled by gcc (Ubuntu 14.2.0-17ubuntu3) 14.2.0, 64-bit 616s [2025-03-15 11:15:23.968 UTC] [3417] [] LOG: listening on Unix socket "/tmp/pg_regress-hGCOHF/.s.PGSQL.55316" 616s [2025-03-15 11:15:23.970 UTC] [3420] [] LOG: database system was shut down at 2025-03-15 11:15:23 UTC 616s [2025-03-15 11:15:23.972 UTC] [3417] [] LOG: database system is ready to accept connections 616s [2025-03-15 11:15:23.972 UTC] [3423] [] LOG: starting pglogical supervisor 616s [2025-03-15 11:15:23.975 UTC] [3425] [postgres] LOG: manager worker [3425] at slot 0 generation 1 detaching cleanly 616s [2025-03-15 11:15:23.979 UTC] [3426] [template1] LOG: manager worker [3426] at slot 0 generation 2 detaching cleanly 616s [2025-03-15 11:15:24.187 UTC] [3449] [postgres] ERROR: local pglogical node not found 616s [2025-03-15 11:15:24.187 UTC] [3449] [postgres] STATEMENT: SELECT * FROM pglogical.create_subscription( 616s subscription_name := 'test_subscription', 616s provider_dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=nonreplica', 616s forward_origins := '{}'); 616s [2025-03-15 11:15:24.189 UTC] [3450] [postgres] LOG: starting pglogical database manager for database postgres 616s [2025-03-15 11:15:24.190 UTC] [3451] [regression] FATAL: role "nonexisting" does not exist 616s [2025-03-15 11:15:24.190 UTC] [3449] [postgres] ERROR: could not connect to the postgresql server: FATAL: role "nonexisting" does not exist 616s 616s [2025-03-15 11:15:24.190 UTC] [3449] [postgres] CONTEXT: PL/pgSQL function inline_code_block line 9 at RAISE 616s [2025-03-15 11:15:24.190 UTC] [3449] [postgres] STATEMENT: DO $$ 616s BEGIN 616s SELECT * FROM pglogical.create_subscription( 616s subscription_name := 'test_subscription', 616s provider_dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=nonexisting', 616s forward_origins := '{}'); 616s EXCEPTION 616s WHEN OTHERS THEN 616s RAISE EXCEPTION '%:%', split_part(SQLERRM, ':', 1), (regexp_matches(SQLERRM, '^.*( FATAL:.*role.*)$'))[1]; 616s END; 616s $$; 616s [2025-03-15 11:15:24.190 UTC] [3452] [template1] LOG: manager worker [3452] at slot 1 generation 1 detaching cleanly 616s [2025-03-15 11:15:24.193 UTC] [3454] [regression] LOG: starting pglogical database manager for database regression 616s [2025-03-15 11:15:24.194 UTC] [3454] [regression] LOG: manager worker [3454] at slot 1 generation 2 detaching cleanly 616s [2025-03-15 11:15:24.194 UTC] [3453] [regression] ERROR: local pglogical node not found 616s [2025-03-15 11:15:24.194 UTC] [3453] [regression] STATEMENT: SELECT node_id, node_name, sysid, dbname, replication_sets FROM pglogical.pglogical_node_info() 616s [2025-03-15 11:15:24.194 UTC] [3449] [postgres] ERROR: could not fetch remote node info: ERROR: local pglogical node not found 616s 616s 616s [2025-03-15 11:15:24.194 UTC] [3449] [postgres] STATEMENT: SELECT * FROM pglogical.create_subscription( 616s subscription_name := 'test_subscription', 616s provider_dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=nonreplica', 616s forward_origins := '{}'); 616s [2025-03-15 11:15:24.198 UTC] [3456] [regression1] LOG: manager worker [3456] at slot 1 generation 3 detaching cleanly 616s [2025-03-15 11:15:24.203 UTC] [3458] [sourcedb] LOG: manager worker [3458] at slot 1 generation 4 detaching cleanly 616s [2025-03-15 11:15:24.205 UTC] [3460] [regression] FATAL: permission denied to start WAL sender 616s [2025-03-15 11:15:24.205 UTC] [3460] [regression] DETAIL: Only roles with the REPLICATION attribute may start a WAL sender process. 616s [2025-03-15 11:15:24.205 UTC] [3461] [template1] LOG: manager worker [3461] at slot 1 generation 5 detaching cleanly 616s [2025-03-15 11:15:24.206 UTC] [3457] [postgres] ERROR: could not connect to the postgresql server in replication mode 616s [2025-03-15 11:15:24.206 UTC] [3457] [postgres] CONTEXT: PL/pgSQL function inline_code_block line 9 at RAISE 616s [2025-03-15 11:15:24.206 UTC] [3457] [postgres] STATEMENT: DO $$ 616s BEGIN 616s SELECT * FROM pglogical.create_subscription( 616s subscription_name := 'test_subscription', 616s provider_dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=nonreplica', 616s forward_origins := '{}'); 616s EXCEPTION 616s WHEN OTHERS THEN 616s RAISE EXCEPTION '%', split_part(SQLERRM, ':', 1); 616s END; 616s $$; 616s [2025-03-15 11:15:24.208 UTC] [3450] [postgres] LOG: manager worker [3450] at slot 0 generation 3 detaching cleanly 616s [2025-03-15 11:15:24.210 UTC] [3462] [regression] LOG: starting pglogical database manager for database regression 616s [2025-03-15 11:15:24.212 UTC] [3463] [regression1] LOG: manager worker [3463] at slot 1 generation 6 detaching cleanly 616s [2025-03-15 11:15:24.214 UTC] [3464] [sourcedb] LOG: manager worker [3464] at slot 1 generation 7 detaching cleanly 616s [2025-03-15 11:15:24.222 UTC] [3466] [postgres] LOG: manager worker [3466] at slot 1 generation 8 detaching cleanly 616s [2025-03-15 11:15:24.225 UTC] [3467] [template1] LOG: manager worker [3467] at slot 1 generation 9 detaching cleanly 616s [2025-03-15 11:15:24.228 UTC] [3468] [regression1] LOG: manager worker [3468] at slot 1 generation 10 detaching cleanly 616s [2025-03-15 11:15:24.229 UTC] [3462] [regression] LOG: manager worker [3462] at slot 0 generation 4 detaching cleanly 616s [2025-03-15 11:15:24.232 UTC] [3469] [sourcedb] LOG: manager worker [3469] at slot 0 generation 5 detaching cleanly 616s [2025-03-15 11:15:24.272 UTC] [3481] [postgres] LOG: manager worker [3481] at slot 0 generation 6 detaching cleanly 616s [2025-03-15 11:15:24.276 UTC] [3483] [template1] LOG: manager worker [3483] at slot 0 generation 7 detaching cleanly 616s [2025-03-15 11:15:24.278 UTC] [3484] [regression] LOG: starting pglogical database manager for database regression 616s [2025-03-15 11:15:24.289 UTC] [3485] [regression1] LOG: manager worker [3485] at slot 1 generation 11 detaching cleanly 616s [2025-03-15 11:15:24.292 UTC] [3487] [sourcedb] LOG: manager worker [3487] at slot 1 generation 12 detaching cleanly 616s [2025-03-15 11:15:24.297 UTC] [3490] [postgres] LOG: starting pglogical database manager for database postgres 616s [2025-03-15 11:15:24.298 UTC] [3491] [postgres] LOG: starting apply for subscription test_subscription 616s [2025-03-15 11:15:24.301 UTC] [3493] [regression] LOG: logical decoding found consistent point at 0/247FB98 616s [2025-03-15 11:15:24.301 UTC] [3493] [regression] DETAIL: There are no running transactions. 616s [2025-03-15 11:15:24.301 UTC] [3493] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL pglogical_output 616s [2025-03-15 11:15:24.301 UTC] [3493] [regression] LOG: exported logical decoding snapshot: "0000007F-00000002-1" with 0 transaction IDs 616s [2025-03-15 11:15:24.301 UTC] [3493] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL pglogical_output 616s [2025-03-15 11:15:24.370 UTC] [3508] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9" 616s [2025-03-15 11:15:24.370 UTC] [3508] [regression] DETAIL: Streaming transactions committing after 0/247FBD0, reading WAL from 0/247FB98. 616s [2025-03-15 11:15:24.370 UTC] [3508] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/247FBD0 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3491') 616s [2025-03-15 11:15:24.370 UTC] [3508] [regression] LOG: logical decoding found consistent point at 0/247FB98 616s [2025-03-15 11:15:24.370 UTC] [3508] [regression] DETAIL: There are no running transactions. 616s [2025-03-15 11:15:24.370 UTC] [3508] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/247FBD0 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3491') 616s [2025-03-15 11:15:25.299 UTC] [3524] [template1] LOG: manager worker [3524] at slot 3 generation 1 detaching cleanly 616s [2025-03-15 11:15:25.302 UTC] [3525] [regression1] LOG: manager worker [3525] at slot 3 generation 2 detaching cleanly 616s [2025-03-15 11:15:25.304 UTC] [3526] [sourcedb] LOG: manager worker [3526] at slot 3 generation 3 detaching cleanly 616s [2025-03-15 11:15:53.994 UTC] [3418] [] LOG: checkpoint starting: time 616s [2025-03-15 11:16:20.089 UTC] [3418] [] LOG: checkpoint complete: wrote 3231 buffers (19.7%); 0 WAL file(s) added, 0 removed, 1 recycled; write=26.093 s, sync=0.001 s, total=26.095 s; sync files=0, longest=0.000 s, average=0.000 s; distance=16883 kB, estimate=16883 kB; lsn=0/256F220, redo lsn=0/2569350 616s [2025-03-15 11:16:23.093 UTC] [3418] [] LOG: checkpoint starting: time 616s [2025-03-15 11:16:23.796 UTC] [3418] [] LOG: checkpoint complete: wrote 9 buffers (0.1%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.703 s, sync=0.001 s, total=0.704 s; sync files=0, longest=0.000 s, average=0.000 s; distance=27 kB, estimate=15197 kB; lsn=0/25709F0, redo lsn=0/256FFB0 616s [2025-03-15 11:16:23.996 UTC] [3670] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_attribute" 616s avg read rate: 9.375 MB/s, avg write rate: 10.156 MB/s 616s buffer usage: 1067 hits, 24 misses, 26 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s 616s [2025-03-15 11:16:24.002 UTC] [3670] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_class" 616s avg read rate: 3.906 MB/s, avg write rate: 10.417 MB/s 616s buffer usage: 623 hits, 3 misses, 8 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:16:24.006 UTC] [3670] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_constraint" 616s avg read rate: 4.688 MB/s, avg write rate: 9.375 MB/s 616s buffer usage: 553 hits, 3 misses, 6 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:16:24.007 UTC] [3670] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_trigger" 616s avg read rate: 7.812 MB/s, avg write rate: 7.812 MB/s 616s buffer usage: 286 hits, 1 misses, 1 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:16:24.011 UTC] [3670] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_depend" 616s avg read rate: 15.625 MB/s, avg write rate: 17.188 MB/s 616s buffer usage: 139 hits, 10 misses, 11 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:16:25.197 UTC] [3680] [regression] ERROR: duplicate key value violates unique constraint "secondary_unique_pred_b_idx" 616s [2025-03-15 11:16:25.197 UTC] [3680] [regression] DETAIL: Key (b)=(2) already exists. 616s [2025-03-15 11:16:25.197 UTC] [3680] [regression] STATEMENT: INSERT INTO secondary_unique_pred (a, b, check_unique) VALUES (5, 2, true); 616s [2025-03-15 11:16:28.264 UTC] [3698] [regression] ERROR: replication set nonexisting not found 616s [2025-03-15 11:16:28.264 UTC] [3698] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('nonexisting', 'test_publicschema'); 616s [2025-03-15 11:16:28.266 UTC] [3698] [regression] ERROR: UNLOGGED and TEMP tables cannot be replicated 616s [2025-03-15 11:16:28.266 UTC] [3698] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('repset_replicate_all', 'test_unlogged'); 616s [2025-03-15 11:16:28.266 UTC] [3698] [regression] ERROR: table test_nopkey cannot be added to replication set repset_replicate_all 616s [2025-03-15 11:16:28.266 UTC] [3698] [regression] DETAIL: table does not have PRIMARY KEY and given replication set is configured to replicate UPDATEs and/or DELETEs 616s [2025-03-15 11:16:28.266 UTC] [3698] [regression] HINT: Add a PRIMARY KEY to the table 616s [2025-03-15 11:16:28.266 UTC] [3698] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('repset_replicate_all', 'test_nopkey'); 616s [2025-03-15 11:16:28.266 UTC] [3698] [regression] ERROR: table test_nopkey cannot be added to replication set repset_replicate_insupd 616s [2025-03-15 11:16:28.266 UTC] [3698] [regression] DETAIL: table does not have PRIMARY KEY and given replication set is configured to replicate UPDATEs and/or DELETEs 616s [2025-03-15 11:16:28.266 UTC] [3698] [regression] HINT: Add a PRIMARY KEY to the table 616s [2025-03-15 11:16:28.266 UTC] [3698] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('repset_replicate_insupd', 'test_nopkey'); 616s [2025-03-15 11:16:28.266 UTC] [3698] [regression] ERROR: table test_nopkey cannot be added to replication set default 616s [2025-03-15 11:16:28.266 UTC] [3698] [regression] DETAIL: table does not have PRIMARY KEY and given replication set is configured to replicate UPDATEs and/or DELETEs 616s [2025-03-15 11:16:28.266 UTC] [3698] [regression] HINT: Add a PRIMARY KEY to the table 616s [2025-03-15 11:16:28.266 UTC] [3698] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_all_tables('default', '{public}'); 616s [2025-03-15 11:16:28.267 UTC] [3698] [regression] ERROR: replication set repset_replicate_instrunc cannot be altered to replicate UPDATEs or DELETEs because it contains tables without PRIMARY KEY 616s [2025-03-15 11:16:28.267 UTC] [3698] [regression] STATEMENT: SELECT * FROM pglogical.alter_replication_set('repset_replicate_instrunc', replicate_update := true); 616s [2025-03-15 11:16:28.267 UTC] [3698] [regression] ERROR: replication set repset_replicate_instrunc cannot be altered to replicate UPDATEs or DELETEs because it contains tables without PRIMARY KEY 616s [2025-03-15 11:16:28.267 UTC] [3698] [regression] STATEMENT: SELECT * FROM pglogical.alter_replication_set('repset_replicate_instrunc', replicate_delete := true); 616s [2025-03-15 11:16:28.267 UTC] [3698] [regression] ERROR: duplicate key value violates unique constraint "replication_set_table_pkey" 616s [2025-03-15 11:16:28.267 UTC] [3698] [regression] DETAIL: Key (set_id, set_reloid)=(3885206554, 17823) already exists. 616s [2025-03-15 11:16:28.267 UTC] [3698] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('repset_replicate_all', 'public.test_publicschema'); 616s [2025-03-15 11:16:28.268 UTC] [3698] [regression] ERROR: replication set name cannot be empty 616s [2025-03-15 11:16:28.268 UTC] [3698] [regression] STATEMENT: SELECT pglogical.create_replication_set(''); 616s [2025-03-15 11:16:28.269 UTC] [3698] [regression] ERROR: cannot drop table test_publicschema because other objects depend on it 616s [2025-03-15 11:16:28.269 UTC] [3698] [regression] DETAIL: table test_publicschema membership in replication set default_insert_only depends on table test_publicschema 616s table test_publicschema membership in replication set repset_replicate_all depends on table test_publicschema 616s [2025-03-15 11:16:28.269 UTC] [3698] [regression] HINT: Use DROP ... CASCADE to drop the dependent objects too. 616s [2025-03-15 11:16:28.269 UTC] [3698] [regression] STATEMENT: DROP TABLE public.test_publicschema; 616s [2025-03-15 11:16:28.270 UTC] [3698] [regression] ERROR: cannot drop table public.test_publicschema because other objects depend on it 616s [2025-03-15 11:16:28.270 UTC] [3698] [regression] DETAIL: table public.test_publicschema membership in replication set default_insert_only depends on table public.test_publicschema 616s table public.test_publicschema membership in replication set repset_replicate_all depends on table public.test_publicschema 616s [2025-03-15 11:16:28.270 UTC] [3698] [regression] HINT: Use DROP ... CASCADE to drop the dependent objects too. 616s [2025-03-15 11:16:28.270 UTC] [3698] [regression] CONTEXT: during execution of queued SQL statement: 616s DROP TABLE public.test_publicschema; 616s 616s [2025-03-15 11:16:28.270 UTC] [3698] [regression] STATEMENT: 616s DROP TABLE public.test_publicschema; 616s 616s [2025-03-15 11:16:32.347 UTC] [3721] [template1] LOG: manager worker [3721] at slot 3 generation 4 detaching cleanly 616s [2025-03-15 11:16:32.347 UTC] [3720] [regression] LOG: starting apply for subscription test_bidirectional 616s [2025-03-15 11:16:32.350 UTC] [3723] [regression1] LOG: manager worker [3723] at slot 3 generation 5 detaching cleanly 616s [2025-03-15 11:16:32.351 UTC] [3724] [postgres] LOG: logical decoding found consistent point at 0/2730470 616s [2025-03-15 11:16:32.351 UTC] [3724] [postgres] DETAIL: There are no running transactions. 616s [2025-03-15 11:16:32.351 UTC] [3724] [postgres] STATEMENT: CREATE_REPLICATION_SLOT "pgl_regression_test_subscriber_test_bid1979e66" LOGICAL pglogical_output 616s [2025-03-15 11:16:32.351 UTC] [3724] [postgres] LOG: exported logical decoding snapshot: "00000082-00000002-1" with 0 transaction IDs 616s [2025-03-15 11:16:32.351 UTC] [3724] [postgres] STATEMENT: CREATE_REPLICATION_SLOT "pgl_regression_test_subscriber_test_bid1979e66" LOGICAL pglogical_output 616s [2025-03-15 11:16:32.352 UTC] [3725] [sourcedb] LOG: manager worker [3725] at slot 3 generation 6 detaching cleanly 616s [2025-03-15 11:16:32.356 UTC] [3726] [postgres] LOG: starting logical decoding for slot "pgl_regression_test_subscriber_test_bid1979e66" 616s [2025-03-15 11:16:32.356 UTC] [3726] [postgres] DETAIL: Streaming transactions committing after 0/27304A8, reading WAL from 0/2730470. 616s [2025-03-15 11:16:32.356 UTC] [3726] [postgres] STATEMENT: START_REPLICATION SLOT "pgl_regression_test_subscriber_test_bid1979e66" LOGICAL 0/27304A8 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3720') 616s [2025-03-15 11:16:32.356 UTC] [3726] [postgres] LOG: logical decoding found consistent point at 0/2730470 616s [2025-03-15 11:16:32.356 UTC] [3726] [postgres] DETAIL: There are no running transactions. 616s [2025-03-15 11:16:32.356 UTC] [3726] [postgres] STATEMENT: START_REPLICATION SLOT "pgl_regression_test_subscriber_test_bid1979e66" LOGICAL 0/27304A8 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3720') 616s [2025-03-15 11:16:34.567 UTC] [3720] [regression] LOG: CONFLICT: remote UPDATE on relation public.basic_dml (local index basic_dml_pkey). Resolution: apply_remote. 616s [2025-03-15 11:16:34.567 UTC] [3720] [regression] DETAIL: existing local tuple {id[int4]:1 other[int4]:5 data[text]:foo something[interval]:00:01:00} xid=1068,origin=0,timestamp=2025-03-15 11:16:33.560724+00; remote tuple {id[int4]:1 other[int4]:1 data[text]:foo something[interval]:00:00:50} in xact origin=2,timestamp=2025-03-15 11:16:34.567137+00,commit_lsn=0/274AA90 616s [2025-03-15 11:16:34.567 UTC] [3720] [regression] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/274AA90, xid 1070 committed at 2025-03-15 11:16:34.567137+00 (action #2) from node replorigin 2 616s [2025-03-15 11:16:34.567 UTC] [3720] [regression] LOG: CONFLICT: remote UPDATE on relation public.basic_dml (local index basic_dml_pkey). Resolution: apply_remote. 616s [2025-03-15 11:16:34.567 UTC] [3720] [regression] DETAIL: existing local tuple {id[int4]:2 other[int4]:4 data[text]:bar something[interval]:84 days} xid=1068,origin=0,timestamp=2025-03-15 11:16:33.560724+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-03-15 11:16:34.567137+00,commit_lsn=0/274AA90 616s [2025-03-15 11:16:34.567 UTC] [3720] [regression] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/274AA90, xid 1070 committed at 2025-03-15 11:16:34.567137+00 (action #3) from node replorigin 2 616s [2025-03-15 11:16:34.567 UTC] [3720] [regression] LOG: CONFLICT: remote UPDATE on relation public.basic_dml (local index basic_dml_pkey). Resolution: apply_remote. 616s [2025-03-15 11:16:34.567 UTC] [3720] [regression] DETAIL: existing local tuple {id[int4]:4 other[int4]:2 data[text]:qux something[interval]:8 mons 2 days} xid=1068,origin=0,timestamp=2025-03-15 11:16:33.560724+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-03-15 11:16:34.567442+00,commit_lsn=0/274AB78 616s [2025-03-15 11:16:34.567 UTC] [3720] [regression] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/274AB78, xid 1071 committed at 2025-03-15 11:16:34.567442+00 (action #2) from node replorigin 2 616s [2025-03-15 11:16:34.567 UTC] [3720] [regression] LOG: CONFLICT: remote UPDATE on relation public.basic_dml (local index basic_dml_pkey). Resolution: apply_remote. 616s [2025-03-15 11:16:34.567 UTC] [3720] [regression] DETAIL: existing local tuple {id[int4]:5 other[int4]:1 data[text]:(null) something[interval]:(null)} xid=1068,origin=0,timestamp=2025-03-15 11:16:33.560724+00; remote tuple {id[int4]:5 other[int4]:5 data[text]:(null) something[interval]:(null)} in xact origin=2,timestamp=2025-03-15 11:16:34.567442+00,commit_lsn=0/274AB78 616s [2025-03-15 11:16:34.567 UTC] [3720] [regression] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/274AB78, xid 1071 committed at 2025-03-15 11:16:34.567442+00 (action #3) from node replorigin 2 616s [2025-03-15 11:16:35.579 UTC] [3720] [regression] LOG: apply worker [3720] at slot 4 generation 1 detaching cleanly 616s [2025-03-15 11:16:36.581 UTC] [3484] [regression] LOG: process 3484 still waiting for ShareUpdateExclusiveLock on relation 17149 of database 16384 after 1000.592 ms 616s [2025-03-15 11:16:36.581 UTC] [3484] [regression] DETAIL: Process holding the lock: 3731. Wait queue: 3484. 616s [2025-03-15 11:16:36.584 UTC] [3484] [regression] LOG: process 3484 still waiting for ShareUpdateExclusiveLock on relation 17149 of database 16384 after 1003.780 ms 616s [2025-03-15 11:16:36.584 UTC] [3484] [regression] DETAIL: Process holding the lock: 3731. Wait queue: 3484. 616s [2025-03-15 11:16:36.584 UTC] [3484] [regression] LOG: process 3484 acquired ShareUpdateExclusiveLock on relation 17149 of database 16384 after 1003.802 ms 616s [2025-03-15 11:16:36.587 UTC] [3735] [template1] LOG: manager worker [3735] at slot 3 generation 7 detaching cleanly 616s [2025-03-15 11:16:36.589 UTC] [3736] [regression1] LOG: manager worker [3736] at slot 3 generation 8 detaching cleanly 616s [2025-03-15 11:16:36.593 UTC] [3739] [sourcedb] LOG: manager worker [3739] at slot 3 generation 9 detaching cleanly 616s [2025-03-15 11:16:36.607 UTC] [3491] [postgres] LOG: apply worker [3491] at slot 2 generation 1 detaching cleanly 616s [2025-03-15 11:16:36.608 UTC] [3746] [template1] LOG: manager worker [3746] at slot 3 generation 10 detaching cleanly 616s [2025-03-15 11:16:36.611 UTC] [3747] [postgres] LOG: starting apply for subscription test_subscription 616s [2025-03-15 11:16:36.612 UTC] [3749] [regression] LOG: 0/274DCF0 has been already streamed, forwarding to 0/2752908 616s [2025-03-15 11:16:36.612 UTC] [3749] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/274DCF0 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3747') 616s [2025-03-15 11:16:36.612 UTC] [3748] [regression1] LOG: manager worker [3748] at slot 2 generation 2 detaching cleanly 616s [2025-03-15 11:16:36.612 UTC] [3749] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9" 616s [2025-03-15 11:16:36.612 UTC] [3749] [regression] DETAIL: Streaming transactions committing after 0/2752908, reading WAL from 0/2730470. 616s [2025-03-15 11:16:36.612 UTC] [3749] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/274DCF0 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3747') 616s [2025-03-15 11:16:36.612 UTC] [3749] [regression] LOG: logical decoding found consistent point at 0/2730470 616s [2025-03-15 11:16:36.612 UTC] [3749] [regression] DETAIL: There are no running transactions. 616s [2025-03-15 11:16:36.612 UTC] [3749] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/274DCF0 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3747') 616s [2025-03-15 11:16:36.613 UTC] [3750] [sourcedb] LOG: manager worker [3750] at slot 4 generation 2 detaching cleanly 616s [2025-03-15 11:16:37.614 UTC] [3747] [postgres] LOG: apply worker [3747] at slot 3 generation 11 detaching cleanly 616s [2025-03-15 11:16:37.616 UTC] [3753] [template1] LOG: manager worker [3753] at slot 2 generation 3 detaching cleanly 616s [2025-03-15 11:16:37.616 UTC] [3754] [regression1] LOG: manager worker [3754] at slot 3 generation 12 detaching cleanly 616s [2025-03-15 11:16:37.618 UTC] [3755] [postgres] LOG: starting apply for subscription test_subscription 616s [2025-03-15 11:16:37.619 UTC] [3757] [sourcedb] LOG: manager worker [3757] at slot 3 generation 13 detaching cleanly 616s [2025-03-15 11:16:37.620 UTC] [3756] [regression] LOG: 0/274DCF0 has been already streamed, forwarding to 0/2752908 616s [2025-03-15 11:16:37.620 UTC] [3756] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/274DCF0 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3755') 616s [2025-03-15 11:16:37.620 UTC] [3756] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9" 616s [2025-03-15 11:16:37.620 UTC] [3756] [regression] DETAIL: Streaming transactions committing after 0/2752908, reading WAL from 0/2730470. 616s [2025-03-15 11:16:37.620 UTC] [3756] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/274DCF0 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3755') 616s [2025-03-15 11:16:37.620 UTC] [3756] [regression] LOG: logical decoding found consistent point at 0/2730470 616s [2025-03-15 11:16:37.620 UTC] [3756] [regression] DETAIL: There are no running transactions. 616s [2025-03-15 11:16:37.620 UTC] [3756] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/274DCF0 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3755') 616s [2025-03-15 11:16:45.833 UTC] [3755] [postgres] ERROR: null value in column "id2" of relation "not_nullcheck_tbl" violates not-null constraint 616s [2025-03-15 11:16:45.833 UTC] [3755] [postgres] DETAIL: Failing row contains (1, 1, name1, null). 616s [2025-03-15 11:16:45.833 UTC] [3755] [postgres] CONTEXT: apply INSERT from remote relation public.not_nullcheck_tbl in commit before 0/27A41C0, xid 1142 committed at 2025-03-15 11:16:45.833541+00 (action #2) from node replorigin 1 616s [2025-03-15 11:16:45.833 UTC] [3755] [postgres] LOG: apply worker [3755] at slot 2 generation 4 exiting with error 616s [2025-03-15 11:16:45.835 UTC] [3756] [regression] LOG: could not send data to client: Broken pipe 616s [2025-03-15 11:16:45.835 UTC] [3756] [regression] CONTEXT: slot "pgl_postgres_test_provider_test_sub83a66f9", output plugin "pglogical_output", in the commit callback, associated LSN 0/27A41C0 616s [2025-03-15 11:16:45.835 UTC] [3756] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/274DCF0 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3755') 616s [2025-03-15 11:16:45.835 UTC] [3417] [] LOG: background worker "pglogical apply 5:2208722835" (PID 3755) exited with exit code 1 616s [2025-03-15 11:16:45.835 UTC] [3789] [postgres] ERROR: null value in column "id2" of relation "not_nullcheck_tbl" violates not-null constraint 616s [2025-03-15 11:16:45.835 UTC] [3789] [postgres] DETAIL: Failing row contains (3, 3, name3, null). 616s [2025-03-15 11:16:45.835 UTC] [3789] [postgres] STATEMENT: INSERT INTO public.not_nullcheck_tbl(id,id1,name) VALUES (3,3,'name3'); 616s [2025-03-15 11:16:45.837 UTC] [3790] [template1] LOG: manager worker [3790] at slot 3 generation 14 detaching cleanly 616s [2025-03-15 11:16:45.841 UTC] [3791] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9" 616s [2025-03-15 11:16:45.841 UTC] [3791] [regression] DETAIL: Streaming transactions committing after 0/27A40D8, reading WAL from 0/2765BA0. 616s [2025-03-15 11:16:45.841 UTC] [3791] [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'); 616s [2025-03-15 11:16:45.841 UTC] [3791] [regression] LOG: logical decoding found consistent point at 0/2765BA0 616s [2025-03-15 11:16:45.841 UTC] [3791] [regression] DETAIL: There are no running transactions. 616s [2025-03-15 11:16:45.841 UTC] [3791] [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'); 616s [2025-03-15 11:16:45.841 UTC] [3792] [regression1] LOG: manager worker [3792] at slot 2 generation 5 detaching cleanly 616s [2025-03-15 11:16:45.843 UTC] [3791] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9" 616s [2025-03-15 11:16:45.843 UTC] [3791] [regression] DETAIL: Streaming transactions committing after 0/27A41F0, reading WAL from 0/2765BA0. 616s [2025-03-15 11:16:45.843 UTC] [3791] [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'); 616s [2025-03-15 11:16:45.843 UTC] [3791] [regression] LOG: logical decoding found consistent point at 0/2765BA0 616s [2025-03-15 11:16:45.843 UTC] [3791] [regression] DETAIL: There are no running transactions. 616s [2025-03-15 11:16:45.843 UTC] [3791] [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'); 616s [2025-03-15 11:16:45.843 UTC] [3793] [sourcedb] LOG: manager worker [3793] at slot 2 generation 6 detaching cleanly 616s [2025-03-15 11:16:45.847 UTC] [3796] [postgres] LOG: starting apply for subscription test_subscription 616s [2025-03-15 11:16:45.847 UTC] [3795] [template1] LOG: manager worker [3795] at slot 3 generation 15 detaching cleanly 616s [2025-03-15 11:16:45.849 UTC] [3799] [regression1] LOG: manager worker [3799] at slot 3 generation 16 detaching cleanly 616s [2025-03-15 11:16:45.850 UTC] [3798] [regression] LOG: 0/279EC48 has been already streamed, forwarding to 0/27A42A8 616s [2025-03-15 11:16:45.850 UTC] [3798] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/279EC48 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3796') 616s [2025-03-15 11:16:45.850 UTC] [3798] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9" 616s [2025-03-15 11:16:45.850 UTC] [3798] [regression] DETAIL: Streaming transactions committing after 0/27A42A8, reading WAL from 0/2765BA0. 616s [2025-03-15 11:16:45.850 UTC] [3798] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/279EC48 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3796') 616s [2025-03-15 11:16:45.850 UTC] [3798] [regression] LOG: logical decoding found consistent point at 0/2765BA0 616s [2025-03-15 11:16:45.850 UTC] [3798] [regression] DETAIL: There are no running transactions. 616s [2025-03-15 11:16:45.850 UTC] [3798] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/279EC48 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3796') 616s [2025-03-15 11:16:45.853 UTC] [3800] [sourcedb] LOG: manager worker [3800] at slot 3 generation 17 detaching cleanly 616s [2025-03-15 11:16:48.087 UTC] [3825] [] LOG: automatic analyze of table "template1.pg_catalog.pg_type" 616s avg read rate: 0.000 MB/s, avg write rate: 6.392 MB/s 616s buffer usage: 1078 hits, 0 misses, 9 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s 616s [2025-03-15 11:16:48.097 UTC] [3825] [] LOG: automatic analyze of table "template1.pg_catalog.pg_attribute" 616s avg read rate: 0.000 MB/s, avg write rate: 7.031 MB/s 616s buffer usage: 520 hits, 0 misses, 9 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:16:48.097 UTC] [3825] [] LOG: automatic aggressive vacuum of table "template1.pg_catalog.pg_class": index scans: 0 616s pages: 0 removed, 14 remain, 14 scanned (100.00% of total) 616s tuples: 0 removed, 415 remain, 0 are dead but not yet removable 616s removable cutoff: 1098, which was 85 XIDs old when operation ended 616s new relfrozenxid: 1098, which is 368 XIDs ahead of previous value 616s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 616s index scan not needed: 0 pages from table (0.00% of total) had 0 dead item identifiers removed 616s avg read rate: 0.000 MB/s, avg write rate: 101.461 MB/s 616s buffer usage: 57 hits, 0 misses, 1 dirtied 616s WAL usage: 1 records, 1 full page images, 2641 bytes 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:16:48.102 UTC] [3825] [] LOG: automatic analyze of table "template1.pg_catalog.pg_class" 616s avg read rate: 0.000 MB/s, avg write rate: 9.375 MB/s 616s buffer usage: 531 hits, 0 misses, 6 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:16:48.106 UTC] [3825] [] LOG: automatic analyze of table "template1.pg_catalog.pg_constraint" 616s avg read rate: 0.000 MB/s, avg write rate: 6.250 MB/s 616s buffer usage: 565 hits, 0 misses, 4 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:16:48.106 UTC] [3825] [] LOG: automatic analyze of table "template1.pg_catalog.pg_rewrite" 616s avg read rate: 0.000 MB/s, avg write rate: 7.812 MB/s 616s buffer usage: 130 hits, 0 misses, 1 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:16:48.110 UTC] [3825] [] LOG: automatic analyze of table "template1.pg_catalog.pg_description" 616s avg read rate: 0.000 MB/s, avg write rate: 1.953 MB/s 616s buffer usage: 131 hits, 0 misses, 1 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:16:48.110 UTC] [3825] [] LOG: automatic aggressive vacuum of table "template1.pg_catalog.pg_depend": index scans: 0 616s pages: 0 removed, 13 remain, 13 scanned (100.00% of total) 616s tuples: 0 removed, 1709 remain, 0 are dead but not yet removable 616s removable cutoff: 1098, which was 89 XIDs old when operation ended 616s new relfrozenxid: 1098, which is 368 XIDs ahead of previous value 616s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 616s index scan not needed: 0 pages from table (0.00% of total) had 0 dead item identifiers removed 616s avg read rate: 0.000 MB/s, avg write rate: 52.787 MB/s 616s buffer usage: 73 hits, 0 misses, 1 dirtied 616s WAL usage: 1 records, 1 full page images, 7869 bytes 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:16:48.112 UTC] [3825] [] LOG: automatic analyze of table "template1.pg_catalog.pg_depend" 616s avg read rate: 0.000 MB/s, avg write rate: 7.812 MB/s 616s buffer usage: 109 hits, 0 misses, 2 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:16:48.112 UTC] [3825] [] LOG: automatic analyze of table "template1.pg_catalog.pg_ts_config_map" 616s avg read rate: 0.000 MB/s, avg write rate: 7.812 MB/s 616s buffer usage: 61 hits, 0 misses, 1 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:16:48.112 UTC] [3825] [] LOG: automatic analyze of table "template1.pg_catalog.pg_init_privs" 616s avg read rate: 0.000 MB/s, avg write rate: 7.812 MB/s 616s buffer usage: 89 hits, 0 misses, 1 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:16:48.114 UTC] [3825] [] LOG: automatic analyze of table "template1.pg_catalog.pg_collation" 616s avg read rate: 0.000 MB/s, avg write rate: 7.812 MB/s 616s buffer usage: 169 hits, 0 misses, 2 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:16:48.115 UTC] [3825] [] LOG: automatic analyze of table "template1.information_schema.sql_features" 616s avg read rate: 0.000 MB/s, avg write rate: 19.531 MB/s 616s buffer usage: 204 hits, 0 misses, 5 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:16:49.947 UTC] [3796] [postgres] WARNING: resource was not closed: relation "test_trg_data" 616s [2025-03-15 11:16:49.947 UTC] [3796] [postgres] CONTEXT: apply COMMIT in commit before 0/2876A18, xid 1198 committed at 2025-03-15 11:16:49.946406+00 (action #3) from node replorigin 1 616s [2025-03-15 11:16:49.947 UTC] [3796] [postgres] WARNING: resource was not closed: relation "test_trg_data" 616s [2025-03-15 11:16:49.947 UTC] [3796] [postgres] CONTEXT: apply COMMIT in commit before 0/2876AF8, xid 1199 committed at 2025-03-15 11:16:49.946575+00 (action #4) from node replorigin 1 616s [2025-03-15 11:16:49.947 UTC] [3796] [postgres] WARNING: resource was not closed: relation "test_trg_data" 616s [2025-03-15 11:16:49.947 UTC] [3796] [postgres] CONTEXT: apply COMMIT in commit before 0/2876AF8, xid 1199 committed at 2025-03-15 11:16:49.946575+00 (action #4) from node replorigin 1 616s [2025-03-15 11:16:49.947 UTC] [3796] [postgres] WARNING: resource was not closed: relation "test_trg_data" 616s [2025-03-15 11:16:49.947 UTC] [3796] [postgres] CONTEXT: apply COMMIT in commit before 0/2876C38, xid 1201 committed at 2025-03-15 11:16:49.947533+00 (action #4) from node replorigin 1 616s [2025-03-15 11:16:49.947 UTC] [3796] [postgres] WARNING: resource was not closed: relation "test_trg_data" 616s [2025-03-15 11:16:49.947 UTC] [3796] [postgres] CONTEXT: apply COMMIT in commit before 0/2876C38, xid 1201 committed at 2025-03-15 11:16:49.947533+00 (action #4) from node replorigin 1 616s [2025-03-15 11:16:53.827 UTC] [3418] [] LOG: checkpoint starting: time 616s [2025-03-15 11:16:54.015 UTC] [3843] [postgres] ERROR: existing subscription "test_subscription" to node "test_provider" already subscribes to replication set "default" 616s [2025-03-15 11:16:54.015 UTC] [3843] [postgres] STATEMENT: SELECT * FROM pglogical.create_subscription( 616s subscription_name := 'test_subscription_parallel', 616s provider_dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=super', 616s replication_sets := '{parallel,default}', 616s forward_origins := '{}', 616s synchronize_structure := false, 616s synchronize_data := false 616s ); 616s [2025-03-15 11:16:54.024 UTC] [3851] [postgres] LOG: starting apply for subscription test_subscription_parallel 616s [2025-03-15 11:16:54.025 UTC] [3850] [template1] LOG: manager worker [3850] at slot 4 generation 3 detaching cleanly 616s [2025-03-15 11:16:54.028 UTC] [3853] [regression] LOG: logical decoding found consistent point at 0/28C4370 616s [2025-03-15 11:16:54.028 UTC] [3853] [regression] DETAIL: There are no running transactions. 616s [2025-03-15 11:16:54.028 UTC] [3853] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_subb8618c2" LOGICAL pglogical_output 616s [2025-03-15 11:16:54.028 UTC] [3853] [regression] LOG: exported logical decoding snapshot: "00000089-00000002-1" with 0 transaction IDs 616s [2025-03-15 11:16:54.028 UTC] [3853] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_subb8618c2" LOGICAL pglogical_output 616s [2025-03-15 11:16:54.028 UTC] [3854] [regression1] LOG: manager worker [3854] at slot 4 generation 4 detaching cleanly 616s [2025-03-15 11:16:54.031 UTC] [3855] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_subb8618c2" 616s [2025-03-15 11:16:54.031 UTC] [3855] [regression] DETAIL: Streaming transactions committing after 0/28C43A8, reading WAL from 0/28C4370. 616s [2025-03-15 11:16:54.031 UTC] [3855] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_subb8618c2" LOGICAL 0/28C43A8 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3851') 616s [2025-03-15 11:16:54.031 UTC] [3855] [regression] LOG: logical decoding found consistent point at 0/28C4370 616s [2025-03-15 11:16:54.031 UTC] [3855] [regression] DETAIL: There are no running transactions. 616s [2025-03-15 11:16:54.031 UTC] [3855] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_subb8618c2" LOGICAL 0/28C43A8 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3851') 616s [2025-03-15 11:16:54.031 UTC] [3856] [sourcedb] LOG: manager worker [3856] at slot 4 generation 5 detaching cleanly 616s [2025-03-15 11:16:56.243 UTC] [3851] [postgres] LOG: apply worker [3851] at slot 3 generation 18 detaching cleanly 616s [2025-03-15 11:16:57.245 UTC] [3490] [postgres] LOG: process 3490 still waiting for ShareUpdateExclusiveLock on relation 17336 of database 5 after 1000.485 ms 616s [2025-03-15 11:16:57.245 UTC] [3490] [postgres] DETAIL: Process holding the lock: 3858. Wait queue: 3490. 616s [2025-03-15 11:16:57.248 UTC] [3490] [postgres] LOG: process 3490 still waiting for ShareUpdateExclusiveLock on relation 17336 of database 5 after 1003.932 ms 616s [2025-03-15 11:16:57.248 UTC] [3490] [postgres] DETAIL: Process holding the lock: 3858. Wait queue: 3490. 616s [2025-03-15 11:16:57.248 UTC] [3490] [postgres] LOG: process 3490 acquired ShareUpdateExclusiveLock on relation 17336 of database 5 after 1004.072 ms 616s [2025-03-15 11:16:57.250 UTC] [3860] [template1] LOG: manager worker [3860] at slot 3 generation 19 detaching cleanly 616s [2025-03-15 11:16:57.252 UTC] [3862] [regression1] LOG: manager worker [3862] at slot 4 generation 6 detaching cleanly 616s [2025-03-15 11:16:57.254 UTC] [3863] [sourcedb] LOG: manager worker [3863] at slot 3 generation 20 detaching cleanly 616s [2025-03-15 11:16:57.271 UTC] [3870] [regression] ERROR: cannot use subquery in check constraint 616s [2025-03-15 11:16:57.271 UTC] [3870] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', false, row_filter := '(SELECT count(*) FROM pg_class) > 1'); 616s [2025-03-15 11:16:57.271 UTC] [3870] [regression] ERROR: syntax error at or near "SELECT" 616s [2025-03-15 11:16:57.271 UTC] [3870] [regression] CONTEXT: invalid row_filter expression "SELECT true" 616s [2025-03-15 11:16:57.271 UTC] [3870] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', false, row_filter := 'SELECT true'); 616s [2025-03-15 11:16:57.271 UTC] [3870] [regression] ERROR: column "foobar" does not exist 616s [2025-03-15 11:16:57.271 UTC] [3870] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', false, row_filter := 'foobar'); 616s [2025-03-15 11:16:57.271 UTC] [3870] [regression] ERROR: argument of row_filter must be type boolean, not type text 616s [2025-03-15 11:16:57.271 UTC] [3870] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', false, row_filter := 'data'); 616s [2025-03-15 11:16:57.274 UTC] [3871] [postgres] LOG: starting sync of table public.basic_dml for subscriber test_subscription 616s [2025-03-15 11:16:57.274 UTC] [3870] [regression] ERROR: cannot drop column data of table basic_dml because other objects depend on it 616s [2025-03-15 11:16:57.274 UTC] [3870] [regression] DETAIL: table basic_dml membership in replication set default depends on column data of table basic_dml 616s [2025-03-15 11:16:57.274 UTC] [3870] [regression] HINT: Use DROP ... CASCADE to drop the dependent objects too. 616s [2025-03-15 11:16:57.274 UTC] [3870] [regression] STATEMENT: ALTER TABLE basic_dml DROP COLUMN data; 616s [2025-03-15 11:16:57.277 UTC] [3872] [regression] LOG: logical decoding found consistent point at 0/2946478 616s [2025-03-15 11:16:57.277 UTC] [3872] [regression] DETAIL: There are no running transactions. 616s [2025-03-15 11:16:57.277 UTC] [3872] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" LOGICAL pglogical_output 616s [2025-03-15 11:16:57.277 UTC] [3872] [regression] LOG: exported logical decoding snapshot: "0000008B-00000002-1" with 0 transaction IDs 616s [2025-03-15 11:16:57.277 UTC] [3872] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" LOGICAL pglogical_output 616s [2025-03-15 11:16:57.285 UTC] [3876] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" 616s [2025-03-15 11:16:57.285 UTC] [3876] [regression] DETAIL: Streaming transactions committing after 0/29464B0, reading WAL from 0/2946478. 616s [2025-03-15 11:16:57.285 UTC] [3876] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" LOGICAL 0/29464B0 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3871') 616s [2025-03-15 11:16:57.285 UTC] [3876] [regression] LOG: logical decoding found consistent point at 0/2946478 616s [2025-03-15 11:16:57.285 UTC] [3876] [regression] DETAIL: There are no running transactions. 616s [2025-03-15 11:16:57.285 UTC] [3876] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" LOGICAL 0/29464B0 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3871') 616s [2025-03-15 11:16:59.980 UTC] [3878] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_type": index scans: 1 616s pages: 0 removed, 18 remain, 18 scanned (100.00% of total) 616s tuples: 55 removed, 643 remain, 0 are dead but not yet removable 616s removable cutoff: 1263, which was 4 XIDs old when operation ended 616s new relfrozenxid: 794, which is 64 XIDs ahead of previous value 616s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 616s index scan needed: 4 pages from table (22.22% of total) had 198 dead item identifiers removed 616s index "pg_type_oid_index": pages: 4 in total, 0 newly deleted, 0 currently deleted, 0 reusable 616s index "pg_type_typname_nsp_index": pages: 7 in total, 0 newly deleted, 0 currently deleted, 0 reusable 616s avg read rate: 0.000 MB/s, avg write rate: 223.214 MB/s 616s buffer usage: 81 hits, 0 misses, 9 dirtied 616s WAL usage: 20 records, 9 full page images, 47787 bytes 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:16:59.992 UTC] [3878] [] LOG: automatic analyze of table "regression.pg_catalog.pg_type" 616s avg read rate: 0.000 MB/s, avg write rate: 6.510 MB/s 616s buffer usage: 1105 hits, 0 misses, 10 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s 616s [2025-03-15 11:16:59.992 UTC] [3871] [postgres] LOG: pglogical sync finished processing; replayed to 0/2964F08 of required 0/2946B08 616s [2025-03-15 11:16:59.992 UTC] [3871] [postgres] CONTEXT: apply COMMIT in commit before 0/2964CD0, xid 1267 committed at 2025-03-15 11:16:59.992058+00 (action #2) from node replorigin 2 616s [2025-03-15 11:16:59.999 UTC] [3871] [postgres] LOG: finished sync of table public.basic_dml for subscriber test_subscription 616s [2025-03-15 11:16:59.999 UTC] [3871] [postgres] CONTEXT: apply COMMIT in commit before 0/2964CD0, xid 1267 committed at 2025-03-15 11:16:59.999001+00 (action #2) 616s [2025-03-15 11:16:59.999 UTC] [3871] [postgres] LOG: sync worker [3871] at slot 3 generation 21 detaching cleanly 616s [2025-03-15 11:17:00.002 UTC] [3878] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_attribute": index scans: 1 616s pages: 0 removed, 85 remain, 48 scanned (56.47% of total) 616s tuples: 952 removed, 3319 remain, 0 are dead but not yet removable 616s removable cutoff: 1263, which was 8 XIDs old when operation ended 616s new relfrozenxid: 794, which is 64 XIDs ahead of previous value 616s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 616s index scan needed: 31 pages from table (36.47% of total) had 1650 dead item identifiers removed 616s index "pg_attribute_relid_attnam_index": pages: 22 in total, 3 newly deleted, 3 currently deleted, 0 reusable 616s index "pg_attribute_relid_attnum_index": pages: 16 in total, 2 newly deleted, 2 currently deleted, 0 reusable 616s avg read rate: 0.000 MB/s, avg write rate: 32.040 MB/s 616s buffer usage: 219 hits, 0 misses, 43 dirtied 616s WAL usage: 111 records, 41 full page images, 86053 bytes 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s 616s [2025-03-15 11:17:00.015 UTC] [3878] [] LOG: automatic analyze of table "regression.pg_catalog.pg_attribute" 616s avg read rate: 0.000 MB/s, avg write rate: 4.808 MB/s 616s buffer usage: 566 hits, 0 misses, 8 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s 616s [2025-03-15 11:17:00.020 UTC] [3878] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_class": index scans: 1 616s pages: 0 removed, 21 remain, 21 scanned (100.00% of total) 616s tuples: 157 removed, 455 remain, 0 are dead but not yet removable 616s removable cutoff: 1263, which was 9 XIDs old when operation ended 616s new relfrozenxid: 794, which is 64 XIDs ahead of previous value 616s frozen: 1 pages from table (4.76% of total) had 5 tuples frozen 616s index scan needed: 16 pages from table (76.19% of total) had 347 dead item identifiers removed 616s index "pg_class_oid_index": pages: 4 in total, 0 newly deleted, 0 currently deleted, 0 reusable 616s index "pg_class_relname_nsp_index": pages: 7 in total, 0 newly deleted, 0 currently deleted, 0 reusable 616s index "pg_class_tblspc_relfilenode_index": pages: 4 in total, 0 newly deleted, 0 currently deleted, 0 reusable 616s avg read rate: 0.000 MB/s, avg write rate: 30.571 MB/s 616s buffer usage: 112 hits, 0 misses, 18 dirtied 616s WAL usage: 51 records, 17 full page images, 78782 bytes 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:00.025 UTC] [3878] [] LOG: automatic analyze of table "regression.pg_catalog.pg_class" 616s avg read rate: 0.000 MB/s, avg write rate: 5.208 MB/s 616s buffer usage: 556 hits, 0 misses, 4 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:00.026 UTC] [3878] [] LOG: automatic analyze of table "regression.pg_catalog.pg_attrdef" 616s avg read rate: 0.000 MB/s, avg write rate: 7.812 MB/s 616s buffer usage: 79 hits, 0 misses, 1 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:00.026 UTC] [3878] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_constraint": index scans: 1 616s pages: 0 removed, 5 remain, 5 scanned (100.00% of total) 616s tuples: 23 removed, 136 remain, 0 are dead but not yet removable 616s removable cutoff: 1263, which was 11 XIDs old when operation ended 616s new relfrozenxid: 794, which is 64 XIDs ahead of previous value 616s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 616s index scan needed: 3 pages from table (60.00% of total) had 105 dead item identifiers removed 616s index "pg_constraint_conparentid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 616s index "pg_constraint_conname_nsp_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 616s index "pg_constraint_conrelid_contypid_conname_index": pages: 4 in total, 0 newly deleted, 0 currently deleted, 0 reusable 616s index "pg_constraint_contypid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 616s index "pg_constraint_oid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 616s avg read rate: 0.000 MB/s, avg write rate: 325.521 MB/s 616s buffer usage: 106 hits, 0 misses, 8 dirtied 616s WAL usage: 20 records, 4 full page images, 26266 bytes 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:00.033 UTC] [3878] [] LOG: automatic analyze of table "regression.pg_catalog.pg_constraint" 616s avg read rate: 0.000 MB/s, avg write rate: 1.116 MB/s 616s buffer usage: 534 hits, 0 misses, 1 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:00.033 UTC] [3878] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_index": index scans: 1 616s pages: 0 removed, 6 remain, 6 scanned (100.00% of total) 616s tuples: 40 removed, 184 remain, 0 are dead but not yet removable 616s removable cutoff: 1263, which was 12 XIDs old when operation ended 616s new relfrozenxid: 794, which is 64 XIDs ahead of previous value 616s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 616s index scan needed: 6 pages from table (100.00% of total) had 130 dead item identifiers removed 616s index "pg_index_indrelid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 616s index "pg_index_indexrelid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 616s avg read rate: 0.000 MB/s, avg write rate: 387.397 MB/s 616s buffer usage: 40 hits, 0 misses, 6 dirtied 616s WAL usage: 19 records, 6 full page images, 43529 bytes 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:00.037 UTC] [3878] [] LOG: automatic analyze of table "regression.pg_catalog.pg_index" 616s avg read rate: 0.000 MB/s, avg write rate: 3.125 MB/s 616s buffer usage: 375 hits, 0 misses, 2 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:00.038 UTC] [3878] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_trigger": index scans: 1 616s pages: 0 removed, 2 remain, 2 scanned (100.00% of total) 616s tuples: 23 removed, 33 remain, 0 are dead but not yet removable 616s removable cutoff: 1263, which was 13 XIDs old when operation ended 616s new relfrozenxid: 794, which is 64 XIDs ahead of previous value 616s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 616s index scan needed: 2 pages from table (100.00% of total) had 135 dead item identifiers removed 616s index "pg_trigger_tgconstraint_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 616s index "pg_trigger_tgrelid_tgname_index": pages: 4 in total, 0 newly deleted, 0 currently deleted, 0 reusable 616s index "pg_trigger_oid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 616s avg read rate: 0.000 MB/s, avg write rate: 174.581 MB/s 616s buffer usage: 57 hits, 0 misses, 4 dirtied 616s WAL usage: 13 records, 4 full page images, 25537 bytes 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:00.041 UTC] [3878] [] LOG: automatic analyze of table "regression.pg_catalog.pg_trigger" 616s avg read rate: 0.000 MB/s, avg write rate: 1.953 MB/s 616s buffer usage: 231 hits, 0 misses, 1 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:00.046 UTC] [3878] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_depend": index scans: 1 616s pages: 0 removed, 26 remain, 26 scanned (100.00% of total) 616s tuples: 721 removed, 2004 remain, 0 are dead but not yet removable 616s removable cutoff: 1263, which was 14 XIDs old when operation ended 616s new relfrozenxid: 794, which is 64 XIDs ahead of previous value 616s frozen: 3 pages from table (11.54% of total) had 173 tuples frozen 616s index scan needed: 16 pages from table (61.54% of total) had 1483 dead item identifiers removed 616s index "pg_depend_depender_index": pages: 20 in total, 2 newly deleted, 2 currently deleted, 0 reusable 616s index "pg_depend_reference_index": pages: 14 in total, 1 newly deleted, 1 currently deleted, 0 reusable 616s avg read rate: 0.000 MB/s, avg write rate: 31.973 MB/s 616s buffer usage: 177 hits, 0 misses, 20 dirtied 616s WAL usage: 73 records, 28 full page images, 84473 bytes 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:00.050 UTC] [3878] [] LOG: automatic analyze of table "regression.pg_catalog.pg_depend" 616s avg read rate: 0.000 MB/s, avg write rate: 1.562 MB/s 616s buffer usage: 132 hits, 0 misses, 1 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:00.050 UTC] [3878] [] LOG: automatic analyze of table "regression.pg_catalog.pg_extension" 616s avg read rate: 0.000 MB/s, avg write rate: 23.438 MB/s 616s buffer usage: 130 hits, 0 misses, 3 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:00.050 UTC] [3878] [] LOG: automatic analyze of table "regression.pg_catalog.pg_sequence" 616s avg read rate: 0.000 MB/s, avg write rate: 7.812 MB/s 616s buffer usage: 133 hits, 0 misses, 1 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:00.051 UTC] [3878] [] LOG: automatic vacuum of table "regression.pglogical.sequence_state": index scans: 1 616s pages: 0 removed, 3 remain, 3 scanned (100.00% of total) 616s tuples: 31 removed, 1 remain, 0 are dead but not yet removable 616s removable cutoff: 1263, which was 17 XIDs old when operation ended 616s new relfrozenxid: 1263, which is 468 XIDs ahead of previous value 616s frozen: 1 pages from table (33.33% of total) had 1 tuples frozen 616s index scan needed: 2 pages from table (66.67% of total) had 2 dead item identifiers removed 616s index "sequence_state_pkey": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 616s avg read rate: 0.000 MB/s, avg write rate: 385.802 MB/s 616s buffer usage: 35 hits, 0 misses, 4 dirtied 616s WAL usage: 9 records, 3 full page images, 9267 bytes 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:00.051 UTC] [3878] [] LOG: automatic analyze of table "regression.pglogical.sequence_state" 616s avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s 616s buffer usage: 49 hits, 0 misses, 0 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:00.051 UTC] [3878] [] LOG: automatic analyze of table "regression.pglogical.queue" 616s avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s 616s buffer usage: 212 hits, 0 misses, 0 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:00.052 UTC] [3878] [] LOG: automatic analyze of table "regression.pglogical.replication_set_table" 616s avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s 616s buffer usage: 116 hits, 0 misses, 0 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:00.052 UTC] [3878] [] LOG: automatic vacuum of table "regression.pglogical.depend": index scans: 0 616s pages: 0 removed, 1 remain, 1 scanned (100.00% of total) 616s tuples: 61 removed, 8 remain, 0 are dead but not yet removable 616s removable cutoff: 1263, which was 20 XIDs old when operation ended 616s new relfrozenxid: 1175, which is 380 XIDs ahead of previous value 616s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 616s index scan not needed: 0 pages from table (0.00% of total) had 0 dead item identifiers removed 616s avg read rate: 0.000 MB/s, avg write rate: 351.124 MB/s 616s buffer usage: 9 hits, 0 misses, 4 dirtied 616s WAL usage: 3 records, 1 full page images, 8669 bytes 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:00.052 UTC] [3878] [] LOG: automatic analyze of table "regression.pglogical.depend" 616s avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s 616s buffer usage: 66 hits, 0 misses, 0 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:01.103 UTC] [3796] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 616s [2025-03-15 11:17:01.103 UTC] [3796] [postgres] DETAIL: remote tuple {id[int4]:3 other[int4]:3 data[text]:baz3 SomeThing[interval]:2 years 01:00:00 insert_xid[int8]:1289 other2[text]:pr387 subonly[int4]:(null) subonly_def[int4]:(null) subonly_def_ts[timestamptz]:(null)} in xact origin=1,timestamp=2025-03-15 11:17:01.103243+00,commit_lsn=0/29EFCA0 616s [2025-03-15 11:17:01.103 UTC] [3796] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/29EFCA0, xid 1293 committed at 2025-03-15 11:17:01.103243+00 (action #3) from node replorigin 1 616s [2025-03-15 11:17:02.113 UTC] [3796] [postgres] LOG: CONFLICT: remote DELETE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 616s [2025-03-15 11:17:02.113 UTC] [3796] [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-03-15 11:17:02.113219+00,commit_lsn=0/29F02F0 616s [2025-03-15 11:17:02.113 UTC] [3796] [postgres] CONTEXT: apply (unknown action) from remote relation public.basic_dml in commit before 0/29F02F0, xid 1298 committed at 2025-03-15 11:17:02.113219+00 (action #2) from node replorigin 1 616s [2025-03-15 11:17:02.126 UTC] [3796] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 616s [2025-03-15 11:17:02.126 UTC] [3796] [postgres] DETAIL: remote tuple {id[int4]:6 other[int4]:100 data[text]:bar SomeThing[interval]:2 years 01:00:00 insert_xid[int8]:1309 other2[text]:pr387 subonly[int4]:(null) subonly_def[int4]:(null) subonly_def_ts[timestamptz]:(null)} in xact origin=1,timestamp=2025-03-15 11:17:02.126213+00,commit_lsn=0/29F0DB8 616s [2025-03-15 11:17:02.126 UTC] [3796] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/29F0DB8, xid 1310 committed at 2025-03-15 11:17:02.126213+00 (action #2) from node replorigin 1 616s [2025-03-15 11:17:02.126 UTC] [3796] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 616s [2025-03-15 11:17:02.126 UTC] [3796] [postgres] DETAIL: remote tuple {id[int4]:6 other[int4]:100 data[text]:abcd SomeThing[interval]:2 years 01:00:00 insert_xid[int8]:1309 other2[text]:pr387 subonly[int4]:(null) subonly_def[int4]:(null) subonly_def_ts[timestamptz]:(null)} in xact origin=1,timestamp=2025-03-15 11:17:02.126284+00,commit_lsn=0/29F0E58 616s [2025-03-15 11:17:02.126 UTC] [3796] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/29F0E58, xid 1311 committed at 2025-03-15 11:17:02.126284+00 (action #2) from node replorigin 1 616s [2025-03-15 11:17:04.162 UTC] [3902] [postgres] LOG: starting sync of table public.test_jsonb for subscriber test_subscription 616s [2025-03-15 11:17:04.166 UTC] [3903] [regression] LOG: logical decoding found consistent point at 0/2A00718 616s [2025-03-15 11:17:04.166 UTC] [3903] [regression] DETAIL: There are no running transactions. 616s [2025-03-15 11:17:04.166 UTC] [3903] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9_48bb0cb8" LOGICAL pglogical_output 616s [2025-03-15 11:17:04.166 UTC] [3903] [regression] LOG: exported logical decoding snapshot: "0000008D-00000002-1" with 0 transaction IDs 616s [2025-03-15 11:17:04.166 UTC] [3903] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9_48bb0cb8" LOGICAL pglogical_output 616s [2025-03-15 11:17:05.167 UTC] [3902] [postgres] LOG: finished sync of table public.test_jsonb for subscriber test_subscription 616s [2025-03-15 11:17:05.168 UTC] [3902] [postgres] LOG: sync worker [3902] at slot 3 generation 22 detaching cleanly 616s NOTICE: c_u: temp_owner, s_u: super 616s NOTICE: c_u: temp_owner, s_u: super 616s [2025-03-15 11:17:06.324 UTC] [3919] [regression] ERROR: set-returning functions are not allowed in check constraints 616s [2025-03-15 11:17:06.324 UTC] [3919] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', false, 616s row_filter := $rf$ (func_plpgsql_srf_retq(other)).result = 500 $rf$); 616s [2025-03-15 11:17:06.354 UTC] [3929] [regression] ERROR: REPLICA IDENTITY columns must be replicated 616s [2025-03-15 11:17:06.354 UTC] [3929] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', columns := '{ data, something}'); 616s [2025-03-15 11:17:10.444 UTC] [3796] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 616s [2025-03-15 11:17:10.444 UTC] [3796] [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-03-15 11:17:10.444706+00,commit_lsn=0/2A307D0 616s [2025-03-15 11:17:10.444 UTC] [3796] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/2A307D0, xid 1404 committed at 2025-03-15 11:17:10.444706+00 (action #2) from node replorigin 1 616s [2025-03-15 11:17:10.444 UTC] [3796] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 616s [2025-03-15 11:17:10.444 UTC] [3796] [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-03-15 11:17:10.444706+00,commit_lsn=0/2A307D0 616s [2025-03-15 11:17:10.444 UTC] [3796] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/2A307D0, xid 1404 committed at 2025-03-15 11:17:10.444706+00 (action #3) from node replorigin 1 616s [2025-03-15 11:17:10.444 UTC] [3796] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 616s [2025-03-15 11:17:10.444 UTC] [3796] [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-03-15 11:17:10.444706+00,commit_lsn=0/2A307D0 616s [2025-03-15 11:17:10.444 UTC] [3796] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/2A307D0, xid 1404 committed at 2025-03-15 11:17:10.444706+00 (action #4) from node replorigin 1 616s [2025-03-15 11:17:10.444 UTC] [3796] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 616s [2025-03-15 11:17:10.444 UTC] [3796] [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-03-15 11:17:10.444706+00,commit_lsn=0/2A307D0 616s [2025-03-15 11:17:10.444 UTC] [3796] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/2A307D0, xid 1404 committed at 2025-03-15 11:17:10.444706+00 (action #5) from node replorigin 1 616s [2025-03-15 11:17:10.444 UTC] [3796] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 616s [2025-03-15 11:17:10.444 UTC] [3796] [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-03-15 11:17:10.444706+00,commit_lsn=0/2A307D0 616s [2025-03-15 11:17:10.444 UTC] [3796] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/2A307D0, xid 1404 committed at 2025-03-15 11:17:10.444706+00 (action #6) from node replorigin 1 616s [2025-03-15 11:17:10.444 UTC] [3796] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 616s [2025-03-15 11:17:10.444 UTC] [3796] [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-03-15 11:17:10.444706+00,commit_lsn=0/2A307D0 616s [2025-03-15 11:17:10.444 UTC] [3796] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/2A307D0, xid 1404 committed at 2025-03-15 11:17:10.444706+00 (action #7) from node replorigin 1 616s [2025-03-15 11:17:10.474 UTC] [3960] [regression] ERROR: REPLICA IDENTITY columns must be replicated 616s [2025-03-15 11:17:10.474 UTC] [3960] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', synchronize_data := true, columns := '{data, something}'); 616s [2025-03-15 11:17:10.476 UTC] [3960] [regression] ERROR: table public.basic_dml does not have column nosuchcol 616s [2025-03-15 11:17:10.476 UTC] [3960] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', synchronize_data := true, columns := '{data, something, nosuchcol}'); 616s [2025-03-15 11:17:10.478 UTC] [3961] [postgres] LOG: starting sync of table public.basic_dml for subscriber test_subscription 616s [2025-03-15 11:17:10.482 UTC] [3962] [regression] LOG: logical decoding found consistent point at 0/2A49368 616s [2025-03-15 11:17:10.482 UTC] [3962] [regression] DETAIL: There are no running transactions. 616s [2025-03-15 11:17:10.482 UTC] [3962] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" LOGICAL pglogical_output 616s [2025-03-15 11:17:10.482 UTC] [3962] [regression] LOG: exported logical decoding snapshot: "0000008E-00000002-1" with 0 transaction IDs 616s [2025-03-15 11:17:10.482 UTC] [3962] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" LOGICAL pglogical_output 616s [2025-03-15 11:17:11.484 UTC] [3961] [postgres] LOG: finished sync of table public.basic_dml for subscriber test_subscription 616s [2025-03-15 11:17:11.484 UTC] [3961] [postgres] LOG: sync worker [3961] at slot 3 generation 23 detaching cleanly 616s [2025-03-15 11:17:11.690 UTC] [3968] [regression] ERROR: duplicate key value violates unique constraint "replication_set_table_pkey" 616s [2025-03-15 11:17:11.690 UTC] [3968] [regression] DETAIL: Key (set_id, set_reloid)=(1376784750, 18341) already exists. 616s [2025-03-15 11:17:11.690 UTC] [3968] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', synchronize_data := true); 616s [2025-03-15 11:17:11.692 UTC] [3968] [regression] ERROR: duplicate key value violates unique constraint "replication_set_table_pkey" 616s [2025-03-15 11:17:11.692 UTC] [3968] [regression] DETAIL: Key (set_id, set_reloid)=(1376784750, 18341) already exists. 616s [2025-03-15 11:17:11.692 UTC] [3968] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', synchronize_data := true, columns := '{id, data}'); 616s [2025-03-15 11:17:11.991 UTC] [3969] [] LOG: automatic analyze of table "regression1.pg_catalog.pg_shdepend" 616s avg read rate: 0.000 MB/s, avg write rate: 9.766 MB/s 616s buffer usage: 308 hits, 0 misses, 5 dirtied 616s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 616s [2025-03-15 11:17:12.724 UTC] [3980] [template1] LOG: manager worker [3980] at slot 3 generation 24 detaching cleanly 616s [2025-03-15 11:17:12.724 UTC] [3981] [postgres] LOG: starting apply for subscription test_subscription_delay 616s [2025-03-15 11:17:12.726 UTC] [3983] [regression1] LOG: manager worker [3983] at slot 3 generation 25 detaching cleanly 616s [2025-03-15 11:17:12.728 UTC] [3984] [regression] LOG: logical decoding found consistent point at 0/2A5F108 616s [2025-03-15 11:17:12.728 UTC] [3984] [regression] DETAIL: There are no running transactions. 616s [2025-03-15 11:17:12.728 UTC] [3984] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_subaf763f6" LOGICAL pglogical_output 616s [2025-03-15 11:17:12.728 UTC] [3984] [regression] LOG: exported logical decoding snapshot: "00000090-00000002-1" with 0 transaction IDs 616s [2025-03-15 11:17:12.728 UTC] [3984] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_subaf763f6" LOGICAL pglogical_output 616s [2025-03-15 11:17:12.728 UTC] [3985] [sourcedb] LOG: manager worker [3985] at slot 3 generation 26 detaching cleanly 616s [2025-03-15 11:17:12.732 UTC] [3986] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_subaf763f6" 616s [2025-03-15 11:17:12.732 UTC] [3986] [regression] DETAIL: Streaming transactions committing after 0/2A5F140, reading WAL from 0/2A5F108. 616s [2025-03-15 11:17:12.732 UTC] [3986] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_subaf763f6" LOGICAL 0/2A5F140 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3981') 616s [2025-03-15 11:17:12.732 UTC] [3986] [regression] LOG: logical decoding found consistent point at 0/2A5F108 616s [2025-03-15 11:17:12.732 UTC] [3986] [regression] DETAIL: There are no running transactions. 616s [2025-03-15 11:17:12.732 UTC] [3986] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_subaf763f6" LOGICAL 0/2A5F140 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3981') 616s [2025-03-15 11:17:18.953 UTC] [3981] [postgres] LOG: apply worker [3981] at slot 4 generation 7 detaching cleanly 616s [2025-03-15 11:17:18.958 UTC] [3991] [template1] LOG: manager worker [3991] at slot 3 generation 27 detaching cleanly 616s [2025-03-15 11:17:18.959 UTC] [3992] [regression1] LOG: manager worker [3992] at slot 4 generation 8 detaching cleanly 616s [2025-03-15 11:17:18.961 UTC] [3994] [sourcedb] LOG: manager worker [3994] at slot 3 generation 28 detaching cleanly 616s [2025-03-15 11:17:19.004 UTC] [4003] [template1] LOG: manager worker [4003] at slot 3 generation 29 detaching cleanly 616s [2025-03-15 11:17:19.008 UTC] [4006] [regression1] LOG: manager worker [4006] at slot 3 generation 30 detaching cleanly 616s [2025-03-15 11:17:19.010 UTC] [4008] [sourcedb] LOG: starting pglogical database manager for database sourcedb 616s [2025-03-15 11:17:19.016 UTC] [4010] [regression] LOG: starting apply for subscription test_orig_subscription 616s [2025-03-15 11:17:19.019 UTC] [4012] [sourcedb] LOG: logical decoding found consistent point at 0/2B390F8 616s [2025-03-15 11:17:19.019 UTC] [4012] [sourcedb] DETAIL: There are no running transactions. 616s [2025-03-15 11:17:19.019 UTC] [4012] [sourcedb] STATEMENT: CREATE_REPLICATION_SLOT "pgl_regression_test_orib5a0b8b_test_ori670a399" LOGICAL pglogical_output 616s [2025-03-15 11:17:19.019 UTC] [4012] [sourcedb] LOG: exported logical decoding snapshot: "0000007F-00000004-1" with 0 transaction IDs 616s [2025-03-15 11:17:19.019 UTC] [4012] [sourcedb] STATEMENT: CREATE_REPLICATION_SLOT "pgl_regression_test_orib5a0b8b_test_ori670a399" LOGICAL pglogical_output 616s [2025-03-15 11:17:19.029 UTC] [4015] [sourcedb] LOG: starting logical decoding for slot "pgl_regression_test_orib5a0b8b_test_ori670a399" 616s [2025-03-15 11:17:19.029 UTC] [4015] [sourcedb] DETAIL: Streaming transactions committing after 0/2B39130, reading WAL from 0/2B390F8. 616s [2025-03-15 11:17:19.029 UTC] [4015] [sourcedb] STATEMENT: START_REPLICATION SLOT "pgl_regression_test_orib5a0b8b_test_ori670a399" LOGICAL 0/2B39130 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '4010') 616s [2025-03-15 11:17:19.029 UTC] [4015] [sourcedb] LOG: logical decoding found consistent point at 0/2B390F8 616s [2025-03-15 11:17:19.029 UTC] [4015] [sourcedb] DETAIL: There are no running transactions. 616s [2025-03-15 11:17:19.029 UTC] [4015] [sourcedb] STATEMENT: START_REPLICATION SLOT "pgl_regression_test_orib5a0b8b_test_ori670a399" LOGICAL 0/2B39130 (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" '1700', "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 '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '4010') 616s [2025-03-15 11:17:20.098 UTC] [3418] [] LOG: checkpoint complete: wrote 387 buffers (2.4%); 0 WAL file(s) added, 0 removed, 0 recycled; write=26.269 s, sync=0.001 s, total=26.272 s; sync files=0, longest=0.000 s, average=0.000 s; distance=3190 kB, estimate=13997 kB; lsn=0/2B485D8, redo lsn=0/288D898 616s [2025-03-15 11:17:21.254 UTC] [4010] [regression] LOG: apply worker [4010] at slot 4 generation 9 detaching cleanly 616s [2025-03-15 11:17:22.255 UTC] [3484] [regression] LOG: process 3484 still waiting for ShareUpdateExclusiveLock on relation 17149 of database 16384 after 1000.107 ms 616s [2025-03-15 11:17:22.255 UTC] [3484] [regression] DETAIL: Process holding the lock: 4022. Wait queue: 3484. 616s [2025-03-15 11:17:22.258 UTC] [3484] [regression] LOG: process 3484 still waiting for ShareUpdateExclusiveLock on relation 17149 of database 16384 after 1003.239 ms 616s [2025-03-15 11:17:22.258 UTC] [3484] [regression] DETAIL: Process holding the lock: 4022. Wait queue: 3484. 616s [2025-03-15 11:17:22.259 UTC] [4024] [template1] LOG: manager worker [4024] at slot 4 generation 10 detaching cleanly 616s [2025-03-15 11:17:22.260 UTC] [3484] [regression] LOG: process 3484 acquired ShareUpdateExclusiveLock on relation 17149 of database 16384 after 1004.525 ms 616s [2025-03-15 11:17:22.262 UTC] [4026] [regression1] LOG: manager worker [4026] at slot 4 generation 11 detaching cleanly 616s [2025-03-15 11:17:22.264 UTC] [4027] [template1] LOG: manager worker [4027] at slot 4 generation 12 detaching cleanly 616s [2025-03-15 11:17:22.266 UTC] [4029] [regression1] LOG: manager worker [4029] at slot 4 generation 13 detaching cleanly 616s [2025-03-15 11:17:22.268 UTC] [4008] [sourcedb] LOG: manager worker [4008] at slot 3 generation 31 detaching cleanly 616s [2025-03-15 11:17:22.270 UTC] [4034] [sourcedb] LOG: starting pglogical database manager for database sourcedb 616s [2025-03-15 11:17:22.270 UTC] [4034] [sourcedb] LOG: manager worker [4034] at slot 3 generation 32 detaching cleanly 616s [2025-03-15 11:17:22.276 UTC] [4036] [regression] ERROR: cannot drop node "test_provider" because one or more replication slots for the node are still active 616s [2025-03-15 11:17:22.276 UTC] [4036] [regression] HINT: drop the subscriptions connected to the node first 616s [2025-03-15 11:17:22.276 UTC] [4036] [regression] STATEMENT: SELECT * FROM pglogical.drop_node(node_name := 'test_provider'); 616s [2025-03-15 11:17:22.281 UTC] [3796] [postgres] LOG: apply worker [3796] at slot 2 generation 7 detaching cleanly 616s [2025-03-15 11:17:23.101 UTC] [3418] [] LOG: checkpoint starting: time 616s [2025-03-15 11:17:23.283 UTC] [3490] [postgres] LOG: process 3490 still waiting for ShareUpdateExclusiveLock on relation 17336 of database 5 after 1000.057 ms 616s [2025-03-15 11:17:23.283 UTC] [3490] [postgres] DETAIL: Process holding the lock: 4037. Wait queue: 3490. 616s [2025-03-15 11:17:23.286 UTC] [3490] [postgres] LOG: process 3490 acquired ShareUpdateExclusiveLock on relation 17336 of database 5 after 1003.194 ms 616s [2025-03-15 11:17:23.287 UTC] [4039] [template1] LOG: manager worker [4039] at slot 2 generation 8 detaching cleanly 616s [2025-03-15 11:17:23.287 UTC] [3490] [postgres] LOG: manager worker [3490] at slot 1 generation 13 detaching cleanly 616s [2025-03-15 11:17:23.292 UTC] [3484] [regression] LOG: manager worker [3484] at slot 0 generation 8 detaching cleanly 616s [2025-03-15 11:17:23.294 UTC] [4041] [regression1] LOG: manager worker [4041] at slot 1 generation 14 detaching cleanly 616s [2025-03-15 11:17:23.294 UTC] [4042] [sourcedb] LOG: starting pglogical database manager for database sourcedb 616s [2025-03-15 11:17:23.294 UTC] [4042] [sourcedb] LOG: manager worker [4042] at slot 2 generation 9 detaching cleanly 616s [2025-03-15 11:17:23.313 UTC] [3417] [] LOG: received fast shutdown request 616s [2025-03-15 11:17:23.313 UTC] [3417] [] LOG: aborting any active transactions 616s [2025-03-15 11:17:23.315 UTC] [3417] [] LOG: background worker "logical replication launcher" (PID 3424) exited with exit code 1 616s [2025-03-15 11:17:23.320 UTC] [3418] [] LOG: checkpoint complete: wrote 473 buffers (2.9%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.217 s, sync=0.001 s, total=0.219 s; sync files=0, longest=0.000 s, average=0.000 s; distance=2903 kB, estimate=12887 kB; lsn=0/2B739E8, redo lsn=0/2B63518 616s [2025-03-15 11:17:23.320 UTC] [3418] [] LOG: shutting down 616s [2025-03-15 11:17:23.320 UTC] [3418] [] LOG: checkpoint starting: shutdown immediate 616s [2025-03-15 11:17:23.321 UTC] [3418] [] LOG: checkpoint complete: wrote 13 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=65 kB, estimate=11605 kB; lsn=0/2B73A60, redo lsn=0/2B73A60 616s [2025-03-15 11:17:23.327 UTC] [3417] [] LOG: database system is shut down 616s autopkgtest [11:17:23]: test regresscheck: -----------------------] 617s regresscheck FLAKY non-zero exit status 1 617s autopkgtest [11:17:24]: test regresscheck: - - - - - - - - - - results - - - - - - - - - - 617s autopkgtest [11:17:24]: @@@@@@@@@@@@@@@@@@@@ summary 617s prove PASS 617s regresscheck FLAKY non-zero exit status 1 623s nova [W] Using flock in prodstack6-s390x 623s Creating nova instance adt-plucky-s390x-pglogical-20250315-110707-juju-7f2275-prod-proposed-migration-environment-2-da236843-81c8-400b-87e4-7ffa43ca1dc9 from image adt/ubuntu-plucky-s390x-server-20250315.img (UUID 3d3557fa-fd0f-4bba-9b89-8d5964e09f61)... 623s nova [W] Timed out waiting for 4c584dc3-488c-41fa-ab04-4154bd664960 to get deleted. 623s nova [W] Using flock in prodstack6-s390x 623s Creating nova instance adt-plucky-s390x-pglogical-20250315-110707-juju-7f2275-prod-proposed-migration-environment-2-da236843-81c8-400b-87e4-7ffa43ca1dc9 from image adt/ubuntu-plucky-s390x-server-20250315.img (UUID 3d3557fa-fd0f-4bba-9b89-8d5964e09f61)... 623s nova [W] Timed out waiting for 7d2e9f23-e9c1-424e-80a9-85a10fbc231b to get deleted.