0s autopkgtest [06:42:22]: starting date and time: 2025-02-22 06:42:22+0000 0s autopkgtest [06:42:22]: git checkout: 325255d2 Merge branch 'pin-any-arch' into 'ubuntu/production' 0s autopkgtest [06:42:22]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.huthut4w/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:postgresql-17 --apt-upgrade pglogical --timeout-short=300 --timeout-copy=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=postgresql-17/17.4-1 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-s390x --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos03-s390x-25.secgroup --name adt-plucky-s390x-pglogical-20250222-064222-juju-7f2275-prod-proposed-migration-environment-2-f07dcd74-686f-4946-a6ae-3b5fef36906a --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/ 59s autopkgtest [06:43:21]: testbed dpkg architecture: s390x 59s autopkgtest [06:43:21]: testbed apt version: 2.9.30ubuntu1 59s autopkgtest [06:43:21]: @@@@@@@@@@@@@@@@@@@@ test bed setup 60s autopkgtest [06:43:22]: testbed release detected to be: None 60s autopkgtest [06:43:22]: updating testbed package index (apt update) 61s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [110 kB] 61s Hit:2 http://ftpmaster.internal/ubuntu plucky InRelease 61s Hit:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease 61s Hit:4 http://ftpmaster.internal/ubuntu plucky-security InRelease 61s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [504 kB] 61s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/restricted Sources [3120 B] 61s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [80.9 kB] 61s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [13.5 kB] 61s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x Packages [125 kB] 61s Get:10 http://ftpmaster.internal/ubuntu plucky-proposed/restricted s390x Packages [760 B] 61s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/universe s390x Packages [424 kB] 61s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse s390x Packages [2816 B] 61s Fetched 1264 kB in 1s (1389 kB/s) 62s Reading package lists... 63s Reading package lists... 63s Building dependency tree... 63s Reading state information... 63s Calculating upgrade... 63s Calculating upgrade... 63s The following packages were automatically installed and are no longer required: 63s libnsl2 libpython3.12-minimal libpython3.12-stdlib libpython3.12t64 63s linux-headers-6.11.0-8 linux-headers-6.11.0-8-generic 63s linux-modules-6.11.0-8-generic linux-tools-6.11.0-8 63s linux-tools-6.11.0-8-generic 63s Use 'sudo apt autoremove' to remove them. 63s The following packages will be upgraded: 63s curl libcurl3t64-gnutls libcurl4t64 63s 3 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 63s Need to get 1041 kB of archives. 63s After this operation, 7168 B disk space will be freed. 63s Get:1 http://ftpmaster.internal/ubuntu plucky/main s390x curl s390x 8.12.1-2ubuntu1 [251 kB] 64s Get:2 http://ftpmaster.internal/ubuntu plucky/main s390x libcurl4t64 s390x 8.12.1-2ubuntu1 [397 kB] 64s Get:3 http://ftpmaster.internal/ubuntu plucky/main s390x libcurl3t64-gnutls s390x 8.12.1-2ubuntu1 [393 kB] 64s Fetched 1041 kB in 1s (1953 kB/s) 64s (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 ... 81030 files and directories currently installed.) 64s Preparing to unpack .../curl_8.12.1-2ubuntu1_s390x.deb ... 64s Unpacking curl (8.12.1-2ubuntu1) over (8.12.0+git20250209.89ed161+ds-1ubuntu1) ... 64s Preparing to unpack .../libcurl4t64_8.12.1-2ubuntu1_s390x.deb ... 64s Unpacking libcurl4t64:s390x (8.12.1-2ubuntu1) over (8.12.0+git20250209.89ed161+ds-1ubuntu1) ... 64s Preparing to unpack .../libcurl3t64-gnutls_8.12.1-2ubuntu1_s390x.deb ... 64s Unpacking libcurl3t64-gnutls:s390x (8.12.1-2ubuntu1) over (8.12.0+git20250209.89ed161+ds-1ubuntu1) ... 64s Setting up libcurl4t64:s390x (8.12.1-2ubuntu1) ... 64s Setting up libcurl3t64-gnutls:s390x (8.12.1-2ubuntu1) ... 64s Setting up curl (8.12.1-2ubuntu1) ... 64s Processing triggers for man-db (2.13.0-1) ... 64s Processing triggers for libc-bin (2.40-4ubuntu1) ... 65s Reading package lists... 65s Building dependency tree... 65s Reading state information... 65s Solving dependencies... 65s The following packages will be REMOVED: 65s libnsl2* libpython3.12-minimal* libpython3.12-stdlib* libpython3.12t64* 65s linux-headers-6.11.0-8* linux-headers-6.11.0-8-generic* 65s linux-modules-6.11.0-8-generic* linux-tools-6.11.0-8* 65s linux-tools-6.11.0-8-generic* 65s 0 upgraded, 0 newly installed, 9 to remove and 0 not upgraded. 65s After this operation, 167 MB disk space will be freed. 65s (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 ... 81030 files and directories currently installed.) 65s Removing linux-tools-6.11.0-8-generic (6.11.0-8.8) ... 65s Removing linux-tools-6.11.0-8 (6.11.0-8.8) ... 65s Removing libpython3.12t64:s390x (3.12.9-1) ... 65s Removing libpython3.12-stdlib:s390x (3.12.9-1) ... 65s Removing libnsl2:s390x (1.3.0-3build3) ... 65s Removing libpython3.12-minimal:s390x (3.12.9-1) ... 65s Removing linux-headers-6.11.0-8-generic (6.11.0-8.8) ... 65s Removing linux-headers-6.11.0-8 (6.11.0-8.8) ... 66s Removing linux-modules-6.11.0-8-generic (6.11.0-8.8) ... 66s Processing triggers for libc-bin (2.40-4ubuntu1) ... 66s (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 ... 55930 files and directories currently installed.) 66s Purging configuration files for libpython3.12-minimal:s390x (3.12.9-1) ... 66s Purging configuration files for linux-modules-6.11.0-8-generic (6.11.0-8.8) ... 66s autopkgtest [06:43:28]: upgrading testbed (apt dist-upgrade and autopurge) 66s Reading package lists... 67s Building dependency tree... 67s Reading state information... 67s Calculating upgrade...Starting pkgProblemResolver with broken count: 0 67s Starting 2 pkgProblemResolver with broken count: 0 67s Done 67s Entering ResolveByKeep 67s 67s Calculating upgrade... 67s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 67s Reading package lists... 67s Building dependency tree... 67s Reading state information... 68s Starting pkgProblemResolver with broken count: 0 68s Starting 2 pkgProblemResolver with broken count: 0 68s Done 68s Solving dependencies... 68s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 68s autopkgtest [06:43:30]: rebooting testbed after setup commands that affected boot 86s autopkgtest [06:43:48]: testbed running kernel: Linux 6.12.0-15-generic #15-Ubuntu SMP Tue Feb 4 15:05:57 UTC 2025 88s autopkgtest [06:43:50]: @@@@@@@@@@@@@@@@@@@@ apt-source pglogical 90s Get:1 http://ftpmaster.internal/ubuntu plucky/universe pglogical 2.4.5-1 (dsc) [2380 B] 90s Get:2 http://ftpmaster.internal/ubuntu plucky/universe pglogical 2.4.5-1 (tar) [283 kB] 90s Get:3 http://ftpmaster.internal/ubuntu plucky/universe pglogical 2.4.5-1 (diff) [180 kB] 90s gpgv: Signature made Tue Sep 24 14:05:34 2024 UTC 90s gpgv: using RSA key 5C48FE6157F49179597087C64C5A6BAB12D2A7AE 90s gpgv: Can't check signature: No public key 90s dpkg-source: warning: cannot verify inline signature for ./pglogical_2.4.5-1.dsc: no acceptable signature found 90s autopkgtest [06:43:52]: testing package pglogical version 2.4.5-1 91s autopkgtest [06:43:53]: build not needed 93s autopkgtest [06:43:55]: test prove: preparing testbed 93s Reading package lists... 93s Building dependency tree... 93s Reading state information... 93s Starting pkgProblemResolver with broken count: 0 93s Starting 2 pkgProblemResolver with broken count: 0 93s Done 93s The following NEW packages will be installed: 93s libio-pty-perl libipc-run-perl libjson-perl libllvm20 libpq5 93s libtap-parser-sourcehandler-pgtap-perl libxslt1.1 postgresql-17 93s postgresql-17-pglogical postgresql-client-17 postgresql-client-common 93s postgresql-common postgresql-common-dev ssl-cert 94s 0 upgraded, 14 newly installed, 0 to remove and 0 not upgraded. 94s Need to get 50.2 MB of archives. 94s After this operation, 214 MB of additional disk space will be used. 94s Get:1 http://ftpmaster.internal/ubuntu plucky/main s390x libjson-perl all 4.10000-1 [81.9 kB] 94s Get:2 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-client-common all 273 [47.5 kB] 94s Get:3 http://ftpmaster.internal/ubuntu plucky/main s390x libio-pty-perl s390x 1:1.20-1build3 [31.6 kB] 94s Get:4 http://ftpmaster.internal/ubuntu plucky/main s390x libipc-run-perl all 20231003.0-2 [91.5 kB] 94s Get:5 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-common-dev all 273 [72.9 kB] 94s Get:6 http://ftpmaster.internal/ubuntu plucky/main s390x ssl-cert all 1.1.3ubuntu1 [18.7 kB] 94s Get:7 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-common all 273 [101 kB] 94s Get:8 http://ftpmaster.internal/ubuntu plucky/main s390x libllvm20 s390x 1:20.1.0~+rc2-1~exp2ubuntu0.4 [31.3 MB] 98s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libpq5 s390x 17.4-1 [147 kB] 98s Get:10 http://ftpmaster.internal/ubuntu plucky/main s390x libxslt1.1 s390x 1.1.39-0exp1ubuntu2 [169 kB] 98s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x postgresql-client-17 s390x 17.4-1 [1367 kB] 98s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x postgresql-17 s390x 17.4-1 [16.3 MB] 98s Get:13 http://ftpmaster.internal/ubuntu plucky/universe s390x postgresql-17-pglogical s390x 2.4.5-1 [391 kB] 98s Get:14 http://ftpmaster.internal/ubuntu plucky/universe s390x libtap-parser-sourcehandler-pgtap-perl all 3.36-2 [35.2 kB] 98s Preconfiguring packages ... 98s Fetched 50.2 MB in 5s (10.6 MB/s) 98s Selecting previously unselected package libjson-perl. 99s (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 ... 55928 files and directories currently installed.) 99s Preparing to unpack .../00-libjson-perl_4.10000-1_all.deb ... 99s Unpacking libjson-perl (4.10000-1) ... 99s Selecting previously unselected package postgresql-client-common. 99s Preparing to unpack .../01-postgresql-client-common_273_all.deb ... 99s Unpacking postgresql-client-common (273) ... 99s Selecting previously unselected package libio-pty-perl. 99s Preparing to unpack .../02-libio-pty-perl_1%3a1.20-1build3_s390x.deb ... 99s Unpacking libio-pty-perl (1:1.20-1build3) ... 99s Selecting previously unselected package libipc-run-perl. 99s Preparing to unpack .../03-libipc-run-perl_20231003.0-2_all.deb ... 99s Unpacking libipc-run-perl (20231003.0-2) ... 99s Selecting previously unselected package postgresql-common-dev. 99s Preparing to unpack .../04-postgresql-common-dev_273_all.deb ... 99s Unpacking postgresql-common-dev (273) ... 99s Selecting previously unselected package ssl-cert. 99s Preparing to unpack .../05-ssl-cert_1.1.3ubuntu1_all.deb ... 99s Unpacking ssl-cert (1.1.3ubuntu1) ... 99s Selecting previously unselected package postgresql-common. 99s Preparing to unpack .../06-postgresql-common_273_all.deb ... 99s Adding 'diversion of /usr/bin/pg_config to /usr/bin/pg_config.libpq-dev by postgresql-common' 99s Unpacking postgresql-common (273) ... 99s Selecting previously unselected package libllvm20:s390x. 99s Preparing to unpack .../07-libllvm20_1%3a20.1.0~+rc2-1~exp2ubuntu0.4_s390x.deb ... 99s Unpacking libllvm20:s390x (1:20.1.0~+rc2-1~exp2ubuntu0.4) ... 99s Selecting previously unselected package libpq5:s390x. 99s Preparing to unpack .../08-libpq5_17.4-1_s390x.deb ... 99s Unpacking libpq5:s390x (17.4-1) ... 99s Selecting previously unselected package libxslt1.1:s390x. 99s Preparing to unpack .../09-libxslt1.1_1.1.39-0exp1ubuntu2_s390x.deb ... 99s Unpacking libxslt1.1:s390x (1.1.39-0exp1ubuntu2) ... 99s Selecting previously unselected package postgresql-client-17. 99s Preparing to unpack .../10-postgresql-client-17_17.4-1_s390x.deb ... 99s Unpacking postgresql-client-17 (17.4-1) ... 99s Selecting previously unselected package postgresql-17. 99s Preparing to unpack .../11-postgresql-17_17.4-1_s390x.deb ... 99s Unpacking postgresql-17 (17.4-1) ... 100s Selecting previously unselected package postgresql-17-pglogical. 100s Preparing to unpack .../12-postgresql-17-pglogical_2.4.5-1_s390x.deb ... 100s Unpacking postgresql-17-pglogical (2.4.5-1) ... 100s Selecting previously unselected package libtap-parser-sourcehandler-pgtap-perl. 100s Preparing to unpack .../13-libtap-parser-sourcehandler-pgtap-perl_3.36-2_all.deb ... 100s Unpacking libtap-parser-sourcehandler-pgtap-perl (3.36-2) ... 100s Setting up postgresql-client-common (273) ... 100s Setting up libtap-parser-sourcehandler-pgtap-perl (3.36-2) ... 100s Setting up libio-pty-perl (1:1.20-1build3) ... 100s Setting up libpq5:s390x (17.4-1) ... 100s Setting up ssl-cert (1.1.3ubuntu1) ... 100s Created symlink '/etc/systemd/system/multi-user.target.wants/ssl-cert.service' → '/usr/lib/systemd/system/ssl-cert.service'. 100s Setting up libllvm20:s390x (1:20.1.0~+rc2-1~exp2ubuntu0.4) ... 100s Setting up libipc-run-perl (20231003.0-2) ... 100s Setting up libjson-perl (4.10000-1) ... 100s Setting up libxslt1.1:s390x (1.1.39-0exp1ubuntu2) ... 100s Setting up postgresql-common-dev (273) ... 100s Setting up postgresql-client-17 (17.4-1) ... 100s 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 100s Setting up postgresql-common (273) ... 101s Creating config file /etc/postgresql-common/createcluster.conf with new version 101s Building PostgreSQL dictionaries from installed myspell/hunspell packages... 101s Removing obsolete dictionary files: 101s Created symlink '/etc/systemd/system/multi-user.target.wants/postgresql.service' → '/usr/lib/systemd/system/postgresql.service'. 101s Setting up postgresql-17 (17.4-1) ... 102s Creating new PostgreSQL cluster 17/main ... 102s /usr/lib/postgresql/17/bin/initdb -D /var/lib/postgresql/17/main --auth-local peer --auth-host scram-sha-256 --no-instructions 102s The files belonging to this database system will be owned by user "postgres". 102s This user must also own the server process. 102s 102s The database cluster will be initialized with locale "C.UTF-8". 102s The default database encoding has accordingly been set to "UTF8". 102s The default text search configuration will be set to "english". 102s 102s Data page checksums are disabled. 102s 102s fixing permissions on existing directory /var/lib/postgresql/17/main ... ok 102s creating subdirectories ... ok 102s selecting dynamic shared memory implementation ... posix 102s selecting default "max_connections" ... 100 102s selecting default "shared_buffers" ... 128MB 102s selecting default time zone ... Etc/UTC 102s creating configuration files ... ok 102s running bootstrap script ... ok 102s performing post-bootstrap initialization ... ok 102s syncing data to disk ... ok 105s Setting up postgresql-17-pglogical (2.4.5-1) ... 105s Processing triggers for man-db (2.13.0-1) ... 106s Processing triggers for libc-bin (2.40-4ubuntu1) ... 107s autopkgtest [06:44:09]: test prove: [----------------------- 107s ### 17 ### 107s Skipping prove test on PG 17, test not compatible yet 107s cp: cannot stat '/tmp/regresscheck.LxOAQZ/tmp_check/log/*': No such file or directory 108s autopkgtest [06:44:10]: test prove: -----------------------] 108s autopkgtest [06:44:10]: test prove: - - - - - - - - - - results - - - - - - - - - - 108s prove PASS 108s autopkgtest [06:44:10]: test regresscheck: preparing testbed 222s autopkgtest [06:46:04]: testbed dpkg architecture: s390x 223s autopkgtest [06:46:05]: testbed apt version: 2.9.30ubuntu1 223s autopkgtest [06:46:05]: @@@@@@@@@@@@@@@@@@@@ test bed setup 223s autopkgtest [06:46:05]: testbed release detected to be: plucky 224s autopkgtest [06:46:06]: updating testbed package index (apt update) 224s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [110 kB] 224s Hit:2 http://ftpmaster.internal/ubuntu plucky InRelease 224s Hit:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease 225s Hit:4 http://ftpmaster.internal/ubuntu plucky-security InRelease 225s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [13.5 kB] 225s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/restricted Sources [3120 B] 225s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [504 kB] 225s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [80.9 kB] 225s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x Packages [125 kB] 225s Get:10 http://ftpmaster.internal/ubuntu plucky-proposed/restricted s390x Packages [760 B] 225s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/universe s390x Packages [424 kB] 225s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse s390x Packages [2816 B] 225s Fetched 1264 kB in 1s (1308 kB/s) 226s Reading package lists... 226s Reading package lists... 226s Building dependency tree... 226s Reading state information... 226s Calculating upgrade... 226s Calculating upgrade... 227s The following packages were automatically installed and are no longer required: 227s libnsl2 libpython3.12-minimal libpython3.12-stdlib libpython3.12t64 227s linux-headers-6.11.0-8 linux-headers-6.11.0-8-generic 227s linux-modules-6.11.0-8-generic linux-tools-6.11.0-8 227s linux-tools-6.11.0-8-generic 227s Use 'sudo apt autoremove' to remove them. 227s The following packages will be upgraded: 227s curl libcurl3t64-gnutls libcurl4t64 227s 3 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 227s Need to get 1041 kB of archives. 227s After this operation, 7168 B disk space will be freed. 227s Get:1 http://ftpmaster.internal/ubuntu plucky/main s390x curl s390x 8.12.1-2ubuntu1 [251 kB] 227s Get:2 http://ftpmaster.internal/ubuntu plucky/main s390x libcurl4t64 s390x 8.12.1-2ubuntu1 [397 kB] 227s Get:3 http://ftpmaster.internal/ubuntu plucky/main s390x libcurl3t64-gnutls s390x 8.12.1-2ubuntu1 [393 kB] 227s Fetched 1041 kB in 1s (1731 kB/s) 228s (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 ... 81030 files and directories currently installed.) 228s Preparing to unpack .../curl_8.12.1-2ubuntu1_s390x.deb ... 228s Unpacking curl (8.12.1-2ubuntu1) over (8.12.0+git20250209.89ed161+ds-1ubuntu1) ... 228s Preparing to unpack .../libcurl4t64_8.12.1-2ubuntu1_s390x.deb ... 228s Unpacking libcurl4t64:s390x (8.12.1-2ubuntu1) over (8.12.0+git20250209.89ed161+ds-1ubuntu1) ... 228s Preparing to unpack .../libcurl3t64-gnutls_8.12.1-2ubuntu1_s390x.deb ... 228s Unpacking libcurl3t64-gnutls:s390x (8.12.1-2ubuntu1) over (8.12.0+git20250209.89ed161+ds-1ubuntu1) ... 228s Setting up libcurl4t64:s390x (8.12.1-2ubuntu1) ... 228s Setting up libcurl3t64-gnutls:s390x (8.12.1-2ubuntu1) ... 228s Setting up curl (8.12.1-2ubuntu1) ... 228s Processing triggers for man-db (2.13.0-1) ... 228s Processing triggers for libc-bin (2.40-4ubuntu1) ... 228s Reading package lists... 228s Building dependency tree... 228s Reading state information... 228s Solving dependencies... 228s The following packages will be REMOVED: 228s libnsl2* libpython3.12-minimal* libpython3.12-stdlib* libpython3.12t64* 228s linux-headers-6.11.0-8* linux-headers-6.11.0-8-generic* 228s linux-modules-6.11.0-8-generic* linux-tools-6.11.0-8* 228s linux-tools-6.11.0-8-generic* 229s 0 upgraded, 0 newly installed, 9 to remove and 0 not upgraded. 229s After this operation, 167 MB disk space will be freed. 229s (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 ... 81030 files and directories currently installed.) 229s Removing linux-tools-6.11.0-8-generic (6.11.0-8.8) ... 229s Removing linux-tools-6.11.0-8 (6.11.0-8.8) ... 229s Removing libpython3.12t64:s390x (3.12.9-1) ... 229s Removing libpython3.12-stdlib:s390x (3.12.9-1) ... 229s Removing libnsl2:s390x (1.3.0-3build3) ... 229s Removing libpython3.12-minimal:s390x (3.12.9-1) ... 229s Removing linux-headers-6.11.0-8-generic (6.11.0-8.8) ... 229s Removing linux-headers-6.11.0-8 (6.11.0-8.8) ... 230s Removing linux-modules-6.11.0-8-generic (6.11.0-8.8) ... 230s Processing triggers for libc-bin (2.40-4ubuntu1) ... 230s (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 ... 55930 files and directories currently installed.) 230s Purging configuration files for libpython3.12-minimal:s390x (3.12.9-1) ... 230s Purging configuration files for linux-modules-6.11.0-8-generic (6.11.0-8.8) ... 230s autopkgtest [06:46:12]: upgrading testbed (apt dist-upgrade and autopurge) 230s Reading package lists... 230s Building dependency tree... 230s Reading state information... 230s Calculating upgrade...Starting pkgProblemResolver with broken count: 0 230s Starting 2 pkgProblemResolver with broken count: 0 230s Done 231s Entering ResolveByKeep 231s 231s Calculating upgrade... 231s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 231s Reading package lists... 231s Building dependency tree... 231s Reading state information... 231s Starting pkgProblemResolver with broken count: 0 231s Starting 2 pkgProblemResolver with broken count: 0 231s Done 231s Solving dependencies... 231s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 232s autopkgtest [06:46:14]: rebooting testbed after setup commands that affected boot 257s Reading package lists... 257s Building dependency tree... 257s Reading state information... 257s Starting pkgProblemResolver with broken count: 0 257s Starting 2 pkgProblemResolver with broken count: 0 257s Done 257s The following NEW packages will be installed: 257s libio-pty-perl libipc-run-perl libjson-perl libllvm20 libpq5 libxslt1.1 257s postgresql-17 postgresql-17-pglogical postgresql-client-17 257s postgresql-client-common postgresql-common postgresql-common-dev ssl-cert 257s 0 upgraded, 13 newly installed, 0 to remove and 0 not upgraded. 257s Need to get 50.1 MB of archives. 257s After this operation, 214 MB of additional disk space will be used. 257s Get:1 http://ftpmaster.internal/ubuntu plucky/main s390x libjson-perl all 4.10000-1 [81.9 kB] 257s Get:2 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-client-common all 273 [47.5 kB] 257s Get:3 http://ftpmaster.internal/ubuntu plucky/main s390x libio-pty-perl s390x 1:1.20-1build3 [31.6 kB] 257s Get:4 http://ftpmaster.internal/ubuntu plucky/main s390x libipc-run-perl all 20231003.0-2 [91.5 kB] 257s Get:5 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-common-dev all 273 [72.9 kB] 257s Get:6 http://ftpmaster.internal/ubuntu plucky/main s390x ssl-cert all 1.1.3ubuntu1 [18.7 kB] 257s Get:7 http://ftpmaster.internal/ubuntu plucky/main s390x postgresql-common all 273 [101 kB] 257s Get:8 http://ftpmaster.internal/ubuntu plucky/main s390x libllvm20 s390x 1:20.1.0~+rc2-1~exp2ubuntu0.4 [31.3 MB] 260s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libpq5 s390x 17.4-1 [147 kB] 260s Get:10 http://ftpmaster.internal/ubuntu plucky/main s390x libxslt1.1 s390x 1.1.39-0exp1ubuntu2 [169 kB] 260s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x postgresql-client-17 s390x 17.4-1 [1367 kB] 260s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x postgresql-17 s390x 17.4-1 [16.3 MB] 261s Get:13 http://ftpmaster.internal/ubuntu plucky/universe s390x postgresql-17-pglogical s390x 2.4.5-1 [391 kB] 261s Preconfiguring packages ... 261s Fetched 50.1 MB in 4s (13.8 MB/s) 261s Selecting previously unselected package libjson-perl. 261s (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 ... 55928 files and directories currently installed.) 261s Preparing to unpack .../00-libjson-perl_4.10000-1_all.deb ... 261s Unpacking libjson-perl (4.10000-1) ... 261s Selecting previously unselected package postgresql-client-common. 261s Preparing to unpack .../01-postgresql-client-common_273_all.deb ... 261s Unpacking postgresql-client-common (273) ... 261s Selecting previously unselected package libio-pty-perl. 261s Preparing to unpack .../02-libio-pty-perl_1%3a1.20-1build3_s390x.deb ... 261s Unpacking libio-pty-perl (1:1.20-1build3) ... 261s Selecting previously unselected package libipc-run-perl. 261s Preparing to unpack .../03-libipc-run-perl_20231003.0-2_all.deb ... 261s Unpacking libipc-run-perl (20231003.0-2) ... 261s Selecting previously unselected package postgresql-common-dev. 261s Preparing to unpack .../04-postgresql-common-dev_273_all.deb ... 261s Unpacking postgresql-common-dev (273) ... 261s Selecting previously unselected package ssl-cert. 261s Preparing to unpack .../05-ssl-cert_1.1.3ubuntu1_all.deb ... 261s Unpacking ssl-cert (1.1.3ubuntu1) ... 261s Selecting previously unselected package postgresql-common. 261s Preparing to unpack .../06-postgresql-common_273_all.deb ... 261s Adding 'diversion of /usr/bin/pg_config to /usr/bin/pg_config.libpq-dev by postgresql-common' 261s Unpacking postgresql-common (273) ... 261s Selecting previously unselected package libllvm20:s390x. 261s Preparing to unpack .../07-libllvm20_1%3a20.1.0~+rc2-1~exp2ubuntu0.4_s390x.deb ... 261s Unpacking libllvm20:s390x (1:20.1.0~+rc2-1~exp2ubuntu0.4) ... 262s Selecting previously unselected package libpq5:s390x. 262s Preparing to unpack .../08-libpq5_17.4-1_s390x.deb ... 262s Unpacking libpq5:s390x (17.4-1) ... 262s Selecting previously unselected package libxslt1.1:s390x. 262s Preparing to unpack .../09-libxslt1.1_1.1.39-0exp1ubuntu2_s390x.deb ... 262s Unpacking libxslt1.1:s390x (1.1.39-0exp1ubuntu2) ... 262s Selecting previously unselected package postgresql-client-17. 262s Preparing to unpack .../10-postgresql-client-17_17.4-1_s390x.deb ... 262s Unpacking postgresql-client-17 (17.4-1) ... 262s Selecting previously unselected package postgresql-17. 262s Preparing to unpack .../11-postgresql-17_17.4-1_s390x.deb ... 262s Unpacking postgresql-17 (17.4-1) ... 262s Selecting previously unselected package postgresql-17-pglogical. 262s Preparing to unpack .../12-postgresql-17-pglogical_2.4.5-1_s390x.deb ... 262s Unpacking postgresql-17-pglogical (2.4.5-1) ... 262s Setting up postgresql-client-common (273) ... 262s Setting up libio-pty-perl (1:1.20-1build3) ... 262s Setting up libpq5:s390x (17.4-1) ... 262s Setting up ssl-cert (1.1.3ubuntu1) ... 262s Created symlink '/etc/systemd/system/multi-user.target.wants/ssl-cert.service' → '/usr/lib/systemd/system/ssl-cert.service'. 262s Setting up libllvm20:s390x (1:20.1.0~+rc2-1~exp2ubuntu0.4) ... 262s Setting up libipc-run-perl (20231003.0-2) ... 262s Setting up libjson-perl (4.10000-1) ... 262s Setting up libxslt1.1:s390x (1.1.39-0exp1ubuntu2) ... 262s Setting up postgresql-common-dev (273) ... 262s Setting up postgresql-client-17 (17.4-1) ... 263s 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 263s Setting up postgresql-common (273) ... 263s Creating config file /etc/postgresql-common/createcluster.conf with new version 263s Building PostgreSQL dictionaries from installed myspell/hunspell packages... 263s Removing obsolete dictionary files: 263s Created symlink '/etc/systemd/system/multi-user.target.wants/postgresql.service' → '/usr/lib/systemd/system/postgresql.service'. 264s Setting up postgresql-17 (17.4-1) ... 264s Creating new PostgreSQL cluster 17/main ... 264s /usr/lib/postgresql/17/bin/initdb -D /var/lib/postgresql/17/main --auth-local peer --auth-host scram-sha-256 --no-instructions 264s The files belonging to this database system will be owned by user "postgres". 264s This user must also own the server process. 264s 264s The database cluster will be initialized with locale "C.UTF-8". 264s The default database encoding has accordingly been set to "UTF8". 264s The default text search configuration will be set to "english". 264s 264s Data page checksums are disabled. 264s 264s fixing permissions on existing directory /var/lib/postgresql/17/main ... ok 264s creating subdirectories ... ok 264s selecting dynamic shared memory implementation ... posix 264s selecting default "max_connections" ... 100 264s selecting default "shared_buffers" ... 128MB 264s selecting default time zone ... Etc/UTC 264s creating configuration files ... ok 264s running bootstrap script ... ok 265s performing post-bootstrap initialization ... ok 265s syncing data to disk ... ok 267s Setting up postgresql-17-pglogical (2.4.5-1) ... 267s Processing triggers for man-db (2.13.0-1) ... 268s Processing triggers for libc-bin (2.40-4ubuntu1) ... 270s autopkgtest [06:46:52]: test regresscheck: [----------------------- 271s ### 17 ### 271s /bin/mkdir -p regression_output 271s 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' \ 271s --temp-config ./regress-postgresql.conf \ 271s --temp-instance=./tmp_check \ 271s --outputdir=./regression_output \ 271s --create-role=logical \ 271s 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 271s # +++ regress install-check in +++ 271s # initializing database system by running initdb 271s # using temp instance on port 55316 with PID 3407 271s ok 1 - preseed 59 ms 271s ok 2 - infofuncs 40 ms 271s not ok 3 - init_fail 73 ms 271s not ok 4 - init 263 ms 271s ok 5 - preseed_check 19 ms 279s ok 6 - basic 7084 ms 325s ok 7 - extended 46525 ms 326s ok 8 - conflict_secondary_unique 1024 ms 328s ok 9 - toasted 2031 ms 329s not ok 10 - replication_set 1027 ms 333s ok 11 - matview 4046 ms 337s not ok 12 - bidirectional 4261 ms 339s not ok 13 - interfaces 1119 ms 340s ok 14 - foreign_key 1022 ms 351s ok 15 - functions 11218 ms 352s ok 16 - copy 1022 ms 352s not ok 17 - sequence 14 ms 358s ok 18 - triggers 6072 ms 360s not ok 19 - parallel 2252 ms 441s not ok 20 - row_filter 81289 ms 447s ok 21 - att_list 5100 ms 449s ok 22 - column_filter 2041 ms 456s not ok 23 - apply_delay 7258 ms 458s not ok 24 - node_origin_cascade 2285 ms 459s ok 25 - drop 1046 ms 459s 1..25 459s # 10 of 25 tests failed. 459s # The differences that caused some tests to fail can be viewed in the file "/tmp/regresscheck.xnERvr/regression_output/regression.diffs". 459s # A copy of the test summary that you see above is saved in the file "/tmp/regresscheck.xnERvr/regression_output/regression.out". 459s make: *** [Makefile:146: regresscheck] Error 1 459s diff -U3 /tmp/regresscheck.xnERvr/expected/init_fail.out /tmp/regresscheck.xnERvr/regression_output/results/init_fail.out 459s --- /tmp/regresscheck.xnERvr/expected/init_fail.out 2025-02-22 06:48:18.613938846 +0000 459s +++ /tmp/regresscheck.xnERvr/regression_output/results/init_fail.out 2025-02-22 06:48:19.293938846 +0000 459s @@ -42,7 +42,7 @@ 459s SELECT * FROM pglogical.create_node(node_name := 'test_subscriber', dsn := (SELECT subscriber_dsn FROM pglogical_regress_variables()) || ' user=nonreplica'); 459s create_node 459s ------------- 459s - 1755434425 459s + 2095496919 459s (1 row) 459s 459s -- fail (can't connect to remote) 459s @@ -72,7 +72,7 @@ 459s SELECT * FROM pglogical.create_node(node_name := 'test_provider', dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=nonreplica'); 459s create_node 459s ------------- 459s - 2689511696 459s + 3385836371 459s (1 row) 459s 459s \c :subscriber_dsn 459s diff -U3 /tmp/regresscheck.xnERvr/expected/init.out /tmp/regresscheck.xnERvr/regression_output/results/init.out 459s --- /tmp/regresscheck.xnERvr/expected/init.out 2025-02-22 06:48:18.613938846 +0000 459s +++ /tmp/regresscheck.xnERvr/regression_output/results/init.out 2025-02-22 06:48:19.563938846 +0000 459s @@ -64,7 +64,7 @@ 459s SELECT * FROM pglogical.create_node(node_name := 'test_provider', dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=super'); 459s create_node 459s ------------- 459s - 2689511696 459s + 3385836371 459s (1 row) 459s 459s \c :subscriber_dsn 459s @@ -79,7 +79,7 @@ 459s SELECT * FROM pglogical.create_node(node_name := 'test_subscriber', dsn := (SELECT subscriber_dsn FROM pglogical_regress_variables()) || ' user=super'); 459s create_node 459s ------------- 459s - 1755434425 459s + 2095496919 459s (1 row) 459s 459s BEGIN; 459s @@ -90,7 +90,7 @@ 459s forward_origins := '{}'); 459s create_subscription 459s --------------------- 459s - 3848008564 459s + 2208722835 459s (1 row) 459s 459s /* 459s @@ -112,7 +112,7 @@ 459s SELECT sync_kind, sync_subid, sync_nspname, sync_relname, sync_status IN ('y', 'r') FROM pglogical.local_sync_status ORDER BY 2,3,4; 459s sync_kind | sync_subid | sync_nspname | sync_relname | ?column? 459s -----------+------------+--------------+--------------+---------- 459s - f | 3848008564 | | | t 459s + f | 2208722835 | | | t 459s (1 row) 459s 459s -- Make sure we see the slot and active connection 459s diff -U3 /tmp/regresscheck.xnERvr/expected/replication_set.out /tmp/regresscheck.xnERvr/regression_output/results/replication_set.out 459s --- /tmp/regresscheck.xnERvr/expected/replication_set.out 2025-02-22 06:48:18.613938846 +0000 459s +++ /tmp/regresscheck.xnERvr/regression_output/results/replication_set.out 2025-02-22 06:47:51.615842792 +0000 459s @@ -50,19 +50,19 @@ 459s SELECT * FROM pglogical.create_replication_set('repset_replicate_all'); 459s create_replication_set 459s ------------------------ 459s - 1767380104 459s + 3885206554 459s (1 row) 459s 459s SELECT * FROM pglogical.create_replication_set('repset_replicate_instrunc', replicate_update := false, replicate_delete := false); 459s create_replication_set 459s ------------------------ 459s - 348382733 459s + 4149578203 459s (1 row) 459s 459s SELECT * FROM pglogical.create_replication_set('repset_replicate_insupd', replicate_delete := false, replicate_truncate := false); 459s create_replication_set 459s ------------------------ 459s - 128878480 459s + 2580819485 459s (1 row) 459s 459s -- add tables 459s @@ -107,7 +107,7 @@ 459s SELECT * FROM pglogical.alter_replication_set('repset_replicate_insupd', replicate_truncate := true); 459s alter_replication_set 459s ----------------------- 459s - 128878480 459s + 2580819485 459s (1 row) 459s 459s -- fail again 459s @@ -226,8 +226,8 @@ 459s SELECT * FROM pglogical.replication_set; 459s set_id | set_nodeid | set_name | replicate_insert | replicate_update | replicate_delete | replicate_truncate 459s ------------+------------+---------------------+------------------+------------------+------------------+-------------------- 459s - 828867312 | 1755434425 | default | t | t | t | t 459s - 3318003856 | 1755434425 | default_insert_only | t | f | f | t 459s - 2796587818 | 1755434425 | ddl_sql | t | f | f | f 459s + 819356807 | 2095496919 | default | t | t | t | t 459s + 2454072499 | 2095496919 | default_insert_only | t | f | f | t 459s + 2627772969 | 2095496919 | ddl_sql | t | f | f | f 459s (3 rows) 459s 459s diff -U3 /tmp/regresscheck.xnERvr/expected/bidirectional.out /tmp/regresscheck.xnERvr/regression_output/results/bidirectional.out 459s --- /tmp/regresscheck.xnERvr/expected/bidirectional.out 2025-02-22 06:48:18.613938846 +0000 459s +++ /tmp/regresscheck.xnERvr/regression_output/results/bidirectional.out 2025-02-22 06:47:59.929527188 +0000 459s @@ -23,7 +23,7 @@ 459s forward_origins := '{}'); 459s create_subscription 459s --------------------- 459s - 4269973126 459s + 427419238 459s (1 row) 459s 459s BEGIN; 459s diff -U3 /tmp/regresscheck.xnERvr/expected/interfaces.out /tmp/regresscheck.xnERvr/regression_output/results/interfaces.out 459s --- /tmp/regresscheck.xnERvr/expected/interfaces.out 2025-02-22 06:48:18.613938846 +0000 459s +++ /tmp/regresscheck.xnERvr/regression_output/results/interfaces.out 2025-02-22 06:48:01.049778765 +0000 459s @@ -6,7 +6,7 @@ 459s SELECT * FROM pglogical.alter_node_add_interface('test_provider', 'super2', (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=super2'); 459s alter_node_add_interface 459s -------------------------- 459s - 3319308158 459s + 1597668009 459s (1 row) 459s 459s SELECT * FROM pglogical.alter_subscription_interface('test_subscription', 'super2'); 459s diff -U3 /tmp/regresscheck.xnERvr/expected/sequence.out /tmp/regresscheck.xnERvr/regression_output/results/sequence.out 459s --- /tmp/regresscheck.xnERvr/expected/sequence.out 2025-02-22 06:48:18.613938846 +0000 459s +++ /tmp/regresscheck.xnERvr/regression_output/results/sequence.out 2025-02-22 06:48:14.334792427 +0000 459s @@ -19,7 +19,7 @@ 459s SELECT * FROM pglogical.create_replication_set('stress_seq'); 459s create_replication_set 459s ------------------------ 459s - 2261733486 459s + 3511091149 459s (1 row) 459s 459s SELECT * FROM pglogical.replication_set_add_sequence('stress_seq', 'stress'); 459s diff -U3 /tmp/regresscheck.xnERvr/expected/parallel.out /tmp/regresscheck.xnERvr/regression_output/results/parallel.out 459s --- /tmp/regresscheck.xnERvr/expected/parallel.out 2025-02-22 06:48:18.613938846 +0000 459s +++ /tmp/regresscheck.xnERvr/regression_output/results/parallel.out 2025-02-22 06:48:22.667573320 +0000 459s @@ -4,7 +4,7 @@ 459s SELECT * FROM pglogical.create_replication_set('parallel'); 459s create_replication_set 459s ------------------------ 459s - 3731651575 459s + 2651258374 459s (1 row) 459s 459s \c :subscriber_dsn 459s @@ -27,7 +27,7 @@ 459s ); 459s create_subscription 459s --------------------- 459s - 4051189029 459s + 3093400622 459s (1 row) 459s 459s BEGIN; 459s @@ -42,15 +42,15 @@ 459s SELECT sync_kind, sync_subid, sync_nspname, sync_relname, sync_status IN ('y', 'r') FROM pglogical.local_sync_status ORDER BY 2,3,4; 459s sync_kind | sync_subid | sync_nspname | sync_relname | ?column? 459s -----------+------------+--------------+--------------+---------- 459s - f | 3848008564 | | | t 459s - i | 4051189029 | | | t 459s + f | 2208722835 | | | t 459s + i | 3093400622 | | | t 459s (2 rows) 459s 459s SELECT * FROM pglogical.show_subscription_status(); 459s subscription_name | status | provider_node | provider_dsn | slot_name | replication_sets | forward_origins 459s ----------------------------+-------------+---------------+------------------------------+--------------------------------------------+---------------------------------------+----------------- 459s - test_subscription | replicating | test_provider | dbname=regression user=super | pgl_postgres_test_provider_test_sube55bf37 | {default,default_insert_only,ddl_sql} | 459s - test_subscription_parallel | replicating | test_provider | dbname=regression user=super | pgl_postgres_test_provider_test_subf1783d2 | {parallel} | 459s + test_subscription | replicating | test_provider | dbname=regression user=super | pgl_postgres_test_provider_test_sub83a66f9 | {default,default_insert_only,ddl_sql} | 459s + test_subscription_parallel | replicating | test_provider | dbname=regression user=super | pgl_postgres_test_provider_test_subb8618c2 | {parallel} | 459s (2 rows) 459s 459s -- Make sure we see the slot and active connection 459s diff -U3 /tmp/regresscheck.xnERvr/expected/row_filter_1.out /tmp/regresscheck.xnERvr/regression_output/results/row_filter.out 459s --- /tmp/regresscheck.xnERvr/expected/row_filter_1.out 2025-02-22 06:48:18.613938846 +0000 459s +++ /tmp/regresscheck.xnERvr/regression_output/results/row_filter.out 2025-02-22 06:49:43.959042765 +0000 459s @@ -153,11 +153,7 @@ 459s BEGIN; 459s SET LOCAL statement_timeout = '60s'; 459s SELECT pglogical.wait_for_subscription_sync_complete('test_subscription'); 459s - wait_for_subscription_sync_complete 459s -------------------------------------- 459s - 459s -(1 row) 459s - 459s +ERROR: canceling statement due to statement timeout 459s COMMIT; 459s SELECT id, other, data, "SomeThing", other2 FROM basic_dml ORDER BY id; 459s id | other | data | SomeThing | other2 459s @@ -187,12 +183,15 @@ 459s 459s \c :subscriber_dsn 459s SELECT id, other, data, "SomeThing" FROM basic_dml ORDER BY id; 459s - id | other | data | SomeThing 459s -----+-------+------+----------------- 459s - 2 | 4 | bar | @ 84 days 459s - 4 | 2 | qux | @ 8 mons 2 days 459s - 5 | 1 | | 459s -(3 rows) 459s + id | other | data | SomeThing 459s +------+-------+------+----------------- 459s + 2 | 4 | bar | @ 84 days 459s + 4 | 2 | qux | @ 8 mons 2 days 459s + 5 | 1 | | 459s + 5000 | 1 | aaa | @ 1 hour 459s + 5002 | 3 | ccc | @ 3 mins 459s + 5003 | 4 | ddd | @ 4 days 459s +(6 rows) 459s 459s -- update one row 459s \c :provider_dsn 459s @@ -205,12 +204,15 @@ 459s 459s \c :subscriber_dsn 459s SELECT id, other, data, "SomeThing" FROM basic_dml ORDER BY id; 459s - id | other | data | SomeThing 459s -----+-------+------+----------- 459s - 2 | 4 | bar | @ 84 days 459s - 4 | 4 | | @ 3 days 459s - 5 | 1 | | 459s -(3 rows) 459s + id | other | data | SomeThing 459s +------+-------+------+----------- 459s + 2 | 4 | bar | @ 84 days 459s + 4 | 4 | | @ 3 days 459s + 5 | 1 | | 459s + 5000 | 1 | aaa | @ 1 hour 459s + 5002 | 3 | ccc | @ 3 mins 459s + 5003 | 4 | ddd | @ 4 days 459s +(6 rows) 459s 459s -- update multiple rows 459s \c :provider_dsn 459s @@ -223,12 +225,15 @@ 459s 459s \c :subscriber_dsn 459s SELECT id, other, data, "SomeThing" FROM basic_dml ORDER BY id; 459s - id | other | data | SomeThing 459s -----+-------+------+----------- 459s - 2 | 2 | bar2 | @ 84 days 459s - 4 | 4 | | @ 3 days 459s - 5 | 5 | | 459s -(3 rows) 459s + id | other | data | SomeThing 459s +------+-------+------+----------- 459s + 2 | 2 | bar2 | @ 84 days 459s + 4 | 4 | | @ 3 days 459s + 5 | 5 | | 459s + 5000 | 1 | aaa | @ 1 hour 459s + 5002 | 3 | ccc | @ 3 mins 459s + 5003 | 4 | ddd | @ 4 days 459s +(6 rows) 459s 459s \c :provider_dsn 459s UPDATE basic_dml SET other = id, "SomeThing" = "SomeThing" - '10 seconds'::interval WHERE id < 3; 459s @@ -257,14 +262,17 @@ 459s 459s \c :subscriber_dsn 459s SELECT id, other, data, "SomeThing", subonly, subonly_def FROM basic_dml ORDER BY id; 459s - id | other | data | SomeThing | subonly | subonly_def 459s -----+-------+--------+--------------------+---------+------------- 459s - 2 | 2 | bar2 | @ 84 days -10 secs | | 99 459s - 3 | 99 | bazbaz | @ 2 years 1 hour | | 99 459s - 4 | 4 | | @ 3 days 10 secs | | 99 459s - 5 | 5 | | | | 99 459s - 7 | 100 | bazbaz | @ 2 years 1 hour | | 99 459s -(5 rows) 459s + id | other | data | SomeThing | subonly | subonly_def 459s +------+-------+--------+--------------------+---------+------------- 459s + 2 | 2 | bar2 | @ 84 days -10 secs | | 99 459s + 3 | 99 | bazbaz | @ 2 years 1 hour | | 99 459s + 4 | 4 | | @ 3 days 10 secs | | 99 459s + 5 | 5 | | | | 99 459s + 7 | 100 | bazbaz | @ 2 years 1 hour | | 99 459s + 5000 | 1 | aaa | @ 1 hour | | 99 459s + 5002 | 3 | ccc | @ 3 mins | | 99 459s + 5003 | 4 | ddd | @ 4 days | | 99 459s +(8 rows) 459s 459s \c :provider_dsn 459s UPDATE basic_dml SET data = 'bar' WHERE id = 3; 459s @@ -292,13 +300,16 @@ 459s 459s \c :subscriber_dsn 459s SELECT id, other, data, "SomeThing", subonly, subonly_def FROM basic_dml ORDER BY id; 459s - id | other | data | SomeThing | subonly | subonly_def 459s -----+-------+------+--------------------+---------+------------- 459s - 2 | 2 | bar2 | @ 84 days -10 secs | | 99 459s - 3 | 99 | bar | @ 2 years 1 hour | | 99 459s - 4 | 4 | | @ 3 days 10 secs | | 99 459s - 5 | 5 | | | | 99 459s -(4 rows) 459s + id | other | data | SomeThing | subonly | subonly_def 459s +------+-------+------+--------------------+---------+------------- 459s + 2 | 2 | bar2 | @ 84 days -10 secs | | 99 459s + 3 | 99 | bar | @ 2 years 1 hour | | 99 459s + 4 | 4 | | @ 3 days 10 secs | | 99 459s + 5 | 5 | | | | 99 459s + 5000 | 1 | aaa | @ 1 hour | | 99 459s + 5002 | 3 | ccc | @ 3 mins | | 99 459s + 5003 | 4 | ddd | @ 4 days | | 99 459s +(7 rows) 459s 459s \c :provider_dsn 459s UPDATE basic_dml SET data = 'bar' WHERE id = 6; 459s @@ -313,13 +324,16 @@ 459s 459s \c :subscriber_dsn 459s SELECT id, other, data, "SomeThing" FROM basic_dml ORDER BY id; 459s - id | other | data | SomeThing 459s -----+-------+------+-------------------- 459s - 2 | 2 | bar2 | @ 84 days -10 secs 459s - 3 | 99 | bar | @ 2 years 1 hour 459s - 4 | 4 | | @ 3 days 10 secs 459s - 5 | 5 | | 459s -(4 rows) 459s + id | other | data | SomeThing 459s +------+-------+------+-------------------- 459s + 2 | 2 | bar2 | @ 84 days -10 secs 459s + 3 | 99 | bar | @ 2 years 1 hour 459s + 4 | 4 | | @ 3 days 10 secs 459s + 5 | 5 | | 459s + 5000 | 1 | aaa | @ 1 hour 459s + 5002 | 3 | ccc | @ 3 mins 459s + 5003 | 4 | ddd | @ 4 days 459s +(7 rows) 459s 459s -- transaction timestamp should be updated for each row (see #148) 459s SELECT count(DISTINCT subonly_def_ts) = count(DISTINCT insert_xid) FROM basic_dml; 459s @@ -339,11 +353,14 @@ 459s 459s \c :subscriber_dsn 459s SELECT id, other, data, "SomeThing" FROM basic_dml ORDER BY id; 459s - id | other | data | SomeThing 459s -----+-------+------+------------------ 459s - 4 | 4 | | @ 3 days 10 secs 459s - 5 | 5 | | 459s -(2 rows) 459s + id | other | data | SomeThing 459s +------+-------+------+------------------ 459s + 4 | 4 | | @ 3 days 10 secs 459s + 5 | 5 | | 459s + 5000 | 1 | aaa | @ 1 hour 459s + 5002 | 3 | ccc | @ 3 mins 459s + 5003 | 4 | ddd | @ 4 days 459s +(5 rows) 459s 459s -- truncate 459s \c :provider_dsn 459s diff -U3 /tmp/regresscheck.xnERvr/expected/apply_delay.out /tmp/regresscheck.xnERvr/regression_output/results/apply_delay.out 459s --- /tmp/regresscheck.xnERvr/expected/apply_delay.out 2025-02-22 06:48:18.613938846 +0000 459s +++ /tmp/regresscheck.xnERvr/regression_output/results/apply_delay.out 2025-02-22 06:49:58.352424639 +0000 459s @@ -13,7 +13,7 @@ 459s SELECT * FROM pglogical.create_replication_set('delay'); 459s create_replication_set 459s ------------------------ 459s - 3064111751 459s + 2893814808 459s (1 row) 459s 459s \c :subscriber_dsn 459s @@ -31,7 +31,7 @@ 459s ); 459s create_subscription 459s --------------------- 459s - 1550781037 459s + 2943762286 459s (1 row) 459s 459s BEGIN; 459s @@ -46,8 +46,8 @@ 459s SELECT sync_kind, sync_subid, sync_nspname, sync_relname, sync_status IN ('y', 'r') FROM pglogical.local_sync_status ORDER BY 2,3,4; 459s sync_kind | sync_subid | sync_nspname | sync_relname | ?column? 459s -----------+------------+--------------+--------------+---------- 459s - i | 1550781037 | | | t 459s - f | 3848008564 | | | t 459s + f | 2208722835 | | | t 459s + i | 2943762286 | | | t 459s (2 rows) 459s 459s SELECT status FROM pglogical.show_subscription_status() WHERE subscription_name = 'test_subscription_delay'; 459s diff -U3 /tmp/regresscheck.xnERvr/expected/node_origin_cascade.out /tmp/regresscheck.xnERvr/regression_output/results/node_origin_cascade.out 459s --- /tmp/regresscheck.xnERvr/expected/node_origin_cascade.out 2025-02-22 06:48:18.613938846 +0000 459s +++ /tmp/regresscheck.xnERvr/regression_output/results/node_origin_cascade.out 2025-02-22 06:50:00.642781179 +0000 459s @@ -31,7 +31,7 @@ 459s SELECT * FROM pglogical.create_node(node_name := 'test_orig_provider', dsn := (SELECT orig_provider_dsn FROM pglogical_regress_variables()) || ' user=super'); 459s create_node 459s ------------- 459s - 4029216451 459s + 3047209138 459s (1 row) 459s 459s \c :provider_dsn 459s @@ -45,7 +45,7 @@ 459s forward_origins := '{}'); 459s create_subscription 459s --------------------- 459s - 3575176667 459s + 1728723354 459s (1 row) 459s 459s COMMIT; 459s @@ -67,7 +67,7 @@ 459s SELECT sync_kind, sync_subid, sync_nspname, sync_relname, sync_status IN ('y', 'r') FROM pglogical.local_sync_status ORDER BY 2,3,4; 459s sync_kind | sync_subid | sync_nspname | sync_relname | ?column? 459s -----------+------------+--------------+--------------+---------- 459s - d | 3575176667 | | | t 459s + d | 1728723354 | | | t 459s (1 row) 459s 459s -- Make sure we see the slot and active connection 459s *** regression_output/log/initdb.log *** 459s Running in no-clean mode. Mistakes will not be cleaned up. 459s The files belonging to this database system will be owned by user "ubuntu". 459s This user must also own the server process. 459s 459s The database cluster will be initialized with this locale configuration: 459s locale provider: libc 459s LC_COLLATE: C.UTF-8 459s LC_CTYPE: C.UTF-8 459s LC_MESSAGES: C 459s LC_MONETARY: C.UTF-8 459s LC_NUMERIC: C.UTF-8 459s LC_TIME: C.UTF-8 459s The default database encoding has accordingly been set to "UTF8". 459s The default text search configuration will be set to "english". 459s 459s Data page checksums are disabled. 459s 459s creating directory /tmp/regresscheck.xnERvr/tmp_check/data ... ok 459s creating subdirectories ... ok 459s selecting dynamic shared memory implementation ... posix 459s selecting default "max_connections" ... 100 459s selecting default "shared_buffers" ... 128MB 459s selecting default time zone ... Etc/UTC 459s creating configuration files ... ok 459s running bootstrap script ... ok 459s performing post-bootstrap initialization ... ok 459s 459s Sync to disk skipped. 459s The data directory might become corrupt if the operating system crashes. 459s 459s initdb: warning: enabling "trust" authentication for local connections 459s 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. 459s 459s Success. You can now start the database server using: 459s 459s /usr/lib/postgresql/17/bin/pg_ctl -D /tmp/regresscheck.xnERvr/tmp_check/data -l logfile start 459s 459s *** regression_output/log/postmaster.log *** 459s [2025-02-22 06:48:19.074 UTC] [3407] [] 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 459s [2025-02-22 06:48:19.075 UTC] [3407] [] LOG: listening on Unix socket "/tmp/pg_regress-E210u4/.s.PGSQL.55316" 459s [2025-02-22 06:48:19.076 UTC] [3410] [] LOG: database system was shut down at 2025-02-22 06:48:19 UTC 459s [2025-02-22 06:48:19.078 UTC] [3407] [] LOG: database system is ready to accept connections 459s [2025-02-22 06:48:19.078 UTC] [3413] [] LOG: starting pglogical supervisor 459s [2025-02-22 06:48:19.083 UTC] [3416] [template1] LOG: manager worker [3416] at slot 1 generation 1 detaching cleanly 459s [2025-02-22 06:48:19.085 UTC] [3415] [postgres] LOG: manager worker [3415] at slot 0 generation 1 detaching cleanly 459s [2025-02-22 06:48:19.279 UTC] [3439] [postgres] ERROR: local pglogical node not found 459s [2025-02-22 06:48:19.279 UTC] [3439] [postgres] STATEMENT: SELECT * FROM pglogical.create_subscription( 459s subscription_name := 'test_subscription', 459s provider_dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=nonreplica', 459s forward_origins := '{}'); 459s [2025-02-22 06:48:19.281 UTC] [3440] [postgres] LOG: starting pglogical database manager for database postgres 459s [2025-02-22 06:48:19.281 UTC] [3441] [regression] FATAL: role "nonexisting" does not exist 459s [2025-02-22 06:48:19.282 UTC] [3442] [template1] LOG: manager worker [3442] at slot 1 generation 2 detaching cleanly 459s [2025-02-22 06:48:19.282 UTC] [3439] [postgres] ERROR: could not connect to the postgresql server: FATAL: role "nonexisting" does not exist 459s 459s [2025-02-22 06:48:19.282 UTC] [3439] [postgres] CONTEXT: PL/pgSQL function inline_code_block line 9 at RAISE 459s [2025-02-22 06:48:19.282 UTC] [3439] [postgres] STATEMENT: DO $$ 459s BEGIN 459s SELECT * FROM pglogical.create_subscription( 459s subscription_name := 'test_subscription', 459s provider_dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=nonexisting', 459s forward_origins := '{}'); 459s EXCEPTION 459s WHEN OTHERS THEN 459s RAISE EXCEPTION '%:%', split_part(SQLERRM, ':', 1), (regexp_matches(SQLERRM, '^.*( FATAL:.*role.*)$'))[1]; 459s END; 459s $$; 459s [2025-02-22 06:48:19.284 UTC] [3444] [regression] LOG: starting pglogical database manager for database regression 459s [2025-02-22 06:48:19.284 UTC] [3444] [regression] LOG: manager worker [3444] at slot 1 generation 3 detaching cleanly 459s [2025-02-22 06:48:19.284 UTC] [3443] [regression] ERROR: local pglogical node not found 459s [2025-02-22 06:48:19.284 UTC] [3443] [regression] STATEMENT: SELECT node_id, node_name, sysid, dbname, replication_sets FROM pglogical.pglogical_node_info() 459s [2025-02-22 06:48:19.284 UTC] [3439] [postgres] ERROR: could not fetch remote node info: ERROR: local pglogical node not found 459s 459s 459s [2025-02-22 06:48:19.284 UTC] [3439] [postgres] STATEMENT: SELECT * FROM pglogical.create_subscription( 459s subscription_name := 'test_subscription', 459s provider_dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=nonreplica', 459s forward_origins := '{}'); 459s [2025-02-22 06:48:19.286 UTC] [3446] [regression1] LOG: manager worker [3446] at slot 1 generation 4 detaching cleanly 459s [2025-02-22 06:48:19.288 UTC] [3447] [sourcedb] LOG: manager worker [3447] at slot 1 generation 5 detaching cleanly 459s [2025-02-22 06:48:19.290 UTC] [3449] [template1] LOG: manager worker [3449] at slot 1 generation 6 detaching cleanly 459s [2025-02-22 06:48:19.293 UTC] [3451] [regression] LOG: starting pglogical database manager for database regression 459s [2025-02-22 06:48:19.294 UTC] [3452] [regression] FATAL: permission denied to start WAL sender 459s [2025-02-22 06:48:19.294 UTC] [3452] [regression] DETAIL: Only roles with the REPLICATION attribute may start a WAL sender process. 459s [2025-02-22 06:48:19.294 UTC] [3448] [postgres] ERROR: could not connect to the postgresql server in replication mode 459s [2025-02-22 06:48:19.294 UTC] [3448] [postgres] CONTEXT: PL/pgSQL function inline_code_block line 9 at RAISE 459s [2025-02-22 06:48:19.294 UTC] [3448] [postgres] STATEMENT: DO $$ 459s BEGIN 459s SELECT * FROM pglogical.create_subscription( 459s subscription_name := 'test_subscription', 459s provider_dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=nonreplica', 459s forward_origins := '{}'); 459s EXCEPTION 459s WHEN OTHERS THEN 459s RAISE EXCEPTION '%', split_part(SQLERRM, ':', 1); 459s END; 459s $$; 459s [2025-02-22 06:48:19.296 UTC] [3453] [regression1] LOG: manager worker [3453] at slot 2 generation 1 detaching cleanly 459s [2025-02-22 06:48:19.296 UTC] [3440] [postgres] LOG: manager worker [3440] at slot 0 generation 2 detaching cleanly 459s [2025-02-22 06:48:19.298 UTC] [3454] [sourcedb] LOG: manager worker [3454] at slot 0 generation 3 detaching cleanly 459s [2025-02-22 06:48:19.307 UTC] [3456] [postgres] LOG: manager worker [3456] at slot 0 generation 4 detaching cleanly 459s [2025-02-22 06:48:19.309 UTC] [3457] [template1] LOG: manager worker [3457] at slot 0 generation 5 detaching cleanly 459s [2025-02-22 06:48:19.311 UTC] [3458] [regression1] LOG: manager worker [3458] at slot 0 generation 6 detaching cleanly 459s [2025-02-22 06:48:19.312 UTC] [3451] [regression] LOG: manager worker [3451] at slot 1 generation 7 detaching cleanly 459s [2025-02-22 06:48:19.314 UTC] [3459] [sourcedb] LOG: manager worker [3459] at slot 0 generation 7 detaching cleanly 459s [2025-02-22 06:48:19.351 UTC] [3471] [postgres] LOG: manager worker [3471] at slot 0 generation 8 detaching cleanly 459s [2025-02-22 06:48:19.352 UTC] [3473] [template1] LOG: manager worker [3473] at slot 1 generation 8 detaching cleanly 459s [2025-02-22 06:48:19.356 UTC] [3474] [regression] LOG: starting pglogical database manager for database regression 459s [2025-02-22 06:48:19.357 UTC] [3475] [regression1] LOG: manager worker [3475] at slot 1 generation 9 detaching cleanly 459s [2025-02-22 06:48:19.359 UTC] [3476] [sourcedb] LOG: manager worker [3476] at slot 1 generation 10 detaching cleanly 459s [2025-02-22 06:48:19.366 UTC] [3477] [postgres] LOG: starting pglogical database manager for database postgres 459s [2025-02-22 06:48:19.367 UTC] [3479] [template1] LOG: manager worker [3479] at slot 2 generation 2 detaching cleanly 459s [2025-02-22 06:48:19.370 UTC] [3482] [regression1] LOG: manager worker [3482] at slot 2 generation 3 detaching cleanly 459s [2025-02-22 06:48:19.373 UTC] [3483] [sourcedb] LOG: manager worker [3483] at slot 2 generation 4 detaching cleanly 459s [2025-02-22 06:48:19.374 UTC] [3484] [postgres] LOG: starting apply for subscription test_subscription 459s [2025-02-22 06:48:19.377 UTC] [3486] [regression] LOG: logical decoding found consistent point at 0/247FB98 459s [2025-02-22 06:48:19.377 UTC] [3486] [regression] DETAIL: There are no running transactions. 459s [2025-02-22 06:48:19.377 UTC] [3486] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL pglogical_output 459s [2025-02-22 06:48:19.377 UTC] [3486] [regression] LOG: exported logical decoding snapshot: "0000007F-00000002-1" with 0 transaction IDs 459s [2025-02-22 06:48:19.377 UTC] [3486] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL pglogical_output 459s [2025-02-22 06:48:19.443 UTC] [3501] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9" 459s [2025-02-22 06:48:19.443 UTC] [3501] [regression] DETAIL: Streaming transactions committing after 0/247FBD0, reading WAL from 0/247FB98. 459s [2025-02-22 06:48:19.443 UTC] [3501] [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 '3484') 459s [2025-02-22 06:48:19.443 UTC] [3501] [regression] LOG: logical decoding found consistent point at 0/247FB98 459s [2025-02-22 06:48:19.443 UTC] [3501] [regression] DETAIL: There are no running transactions. 459s [2025-02-22 06:48:19.443 UTC] [3501] [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 '3484') 459s [2025-02-22 06:48:26.702 UTC] [3540] [template1] LOG: manager worker [3540] at slot 2 generation 5 detaching cleanly 459s [2025-02-22 06:48:26.704 UTC] [3541] [regression1] LOG: manager worker [3541] at slot 2 generation 6 detaching cleanly 459s [2025-02-22 06:48:26.707 UTC] [3542] [sourcedb] LOG: manager worker [3542] at slot 2 generation 7 detaching cleanly 459s [2025-02-22 06:47:47.550 UTC] [3670] [regression] ERROR: duplicate key value violates unique constraint "secondary_unique_pred_b_idx" 459s [2025-02-22 06:47:47.550 UTC] [3670] [regression] DETAIL: Key (b)=(2) already exists. 459s [2025-02-22 06:47:47.550 UTC] [3670] [regression] STATEMENT: INSERT INTO secondary_unique_pred (a, b, check_unique) VALUES (5, 2, true); 459s [2025-02-22 06:47:51.614 UTC] [3688] [regression] ERROR: replication set nonexisting not found 459s [2025-02-22 06:47:51.614 UTC] [3688] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('nonexisting', 'test_publicschema'); 459s [2025-02-22 06:47:51.615 UTC] [3688] [regression] ERROR: UNLOGGED and TEMP tables cannot be replicated 459s [2025-02-22 06:47:51.615 UTC] [3688] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('repset_replicate_all', 'test_unlogged'); 459s [2025-02-22 06:47:51.615 UTC] [3688] [regression] ERROR: table test_nopkey cannot be added to replication set repset_replicate_all 459s [2025-02-22 06:47:51.615 UTC] [3688] [regression] DETAIL: table does not have PRIMARY KEY and given replication set is configured to replicate UPDATEs and/or DELETEs 459s [2025-02-22 06:47:51.615 UTC] [3688] [regression] HINT: Add a PRIMARY KEY to the table 459s [2025-02-22 06:47:51.615 UTC] [3688] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('repset_replicate_all', 'test_nopkey'); 459s [2025-02-22 06:47:51.616 UTC] [3688] [regression] ERROR: table test_nopkey cannot be added to replication set repset_replicate_insupd 459s [2025-02-22 06:47:51.616 UTC] [3688] [regression] DETAIL: table does not have PRIMARY KEY and given replication set is configured to replicate UPDATEs and/or DELETEs 459s [2025-02-22 06:47:51.616 UTC] [3688] [regression] HINT: Add a PRIMARY KEY to the table 459s [2025-02-22 06:47:51.616 UTC] [3688] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('repset_replicate_insupd', 'test_nopkey'); 459s [2025-02-22 06:47:51.616 UTC] [3688] [regression] ERROR: table test_nopkey cannot be added to replication set default 459s [2025-02-22 06:47:51.616 UTC] [3688] [regression] DETAIL: table does not have PRIMARY KEY and given replication set is configured to replicate UPDATEs and/or DELETEs 459s [2025-02-22 06:47:51.616 UTC] [3688] [regression] HINT: Add a PRIMARY KEY to the table 459s [2025-02-22 06:47:51.616 UTC] [3688] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_all_tables('default', '{public}'); 459s [2025-02-22 06:47:51.616 UTC] [3688] [regression] ERROR: replication set repset_replicate_instrunc cannot be altered to replicate UPDATEs or DELETEs because it contains tables without PRIMARY KEY 459s [2025-02-22 06:47:51.616 UTC] [3688] [regression] STATEMENT: SELECT * FROM pglogical.alter_replication_set('repset_replicate_instrunc', replicate_update := true); 459s [2025-02-22 06:47:51.616 UTC] [3688] [regression] ERROR: replication set repset_replicate_instrunc cannot be altered to replicate UPDATEs or DELETEs because it contains tables without PRIMARY KEY 459s [2025-02-22 06:47:51.616 UTC] [3688] [regression] STATEMENT: SELECT * FROM pglogical.alter_replication_set('repset_replicate_instrunc', replicate_delete := true); 459s [2025-02-22 06:47:51.616 UTC] [3688] [regression] ERROR: duplicate key value violates unique constraint "replication_set_table_pkey" 459s [2025-02-22 06:47:51.616 UTC] [3688] [regression] DETAIL: Key (set_id, set_reloid)=(3885206554, 17822) already exists. 459s [2025-02-22 06:47:51.616 UTC] [3688] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('repset_replicate_all', 'public.test_publicschema'); 459s [2025-02-22 06:47:51.617 UTC] [3688] [regression] ERROR: replication set name cannot be empty 459s [2025-02-22 06:47:51.617 UTC] [3688] [regression] STATEMENT: SELECT pglogical.create_replication_set(''); 459s [2025-02-22 06:47:51.618 UTC] [3688] [regression] ERROR: cannot drop table test_publicschema because other objects depend on it 459s [2025-02-22 06:47:51.618 UTC] [3688] [regression] DETAIL: table test_publicschema membership in replication set default_insert_only depends on table test_publicschema 459s table test_publicschema membership in replication set repset_replicate_all depends on table test_publicschema 459s [2025-02-22 06:47:51.618 UTC] [3688] [regression] HINT: Use DROP ... CASCADE to drop the dependent objects too. 459s [2025-02-22 06:47:51.618 UTC] [3688] [regression] STATEMENT: DROP TABLE public.test_publicschema; 459s [2025-02-22 06:47:51.618 UTC] [3688] [regression] ERROR: cannot drop table public.test_publicschema because other objects depend on it 459s [2025-02-22 06:47:51.618 UTC] [3688] [regression] DETAIL: table public.test_publicschema membership in replication set default_insert_only depends on table public.test_publicschema 459s table public.test_publicschema membership in replication set repset_replicate_all depends on table public.test_publicschema 459s [2025-02-22 06:47:51.618 UTC] [3688] [regression] HINT: Use DROP ... CASCADE to drop the dependent objects too. 459s [2025-02-22 06:47:51.618 UTC] [3688] [regression] CONTEXT: during execution of queued SQL statement: 459s DROP TABLE public.test_publicschema; 459s 459s [2025-02-22 06:47:51.618 UTC] [3688] [regression] STATEMENT: 459s DROP TABLE public.test_publicschema; 459s 459s [2025-02-22 06:47:55.695 UTC] [3710] [regression] LOG: starting apply for subscription test_bidirectional 459s [2025-02-22 06:47:55.695 UTC] [3711] [template1] LOG: manager worker [3711] at slot 4 generation 1 detaching cleanly 459s [2025-02-22 06:47:55.698 UTC] [3713] [regression1] LOG: manager worker [3713] at slot 4 generation 2 detaching cleanly 459s [2025-02-22 06:47:55.700 UTC] [3715] [sourcedb] LOG: manager worker [3715] at slot 4 generation 3 detaching cleanly 459s [2025-02-22 06:47:55.700 UTC] [3714] [postgres] LOG: logical decoding found consistent point at 0/26752F8 459s [2025-02-22 06:47:55.700 UTC] [3714] [postgres] DETAIL: There are no running transactions. 459s [2025-02-22 06:47:55.700 UTC] [3714] [postgres] STATEMENT: CREATE_REPLICATION_SLOT "pgl_regression_test_subscriber_test_bid1979e66" LOGICAL pglogical_output 459s [2025-02-22 06:47:55.700 UTC] [3714] [postgres] LOG: exported logical decoding snapshot: "00000082-00000002-1" with 0 transaction IDs 459s [2025-02-22 06:47:55.700 UTC] [3714] [postgres] STATEMENT: CREATE_REPLICATION_SLOT "pgl_regression_test_subscriber_test_bid1979e66" LOGICAL pglogical_output 459s [2025-02-22 06:47:55.702 UTC] [3716] [postgres] LOG: starting logical decoding for slot "pgl_regression_test_subscriber_test_bid1979e66" 459s [2025-02-22 06:47:55.702 UTC] [3716] [postgres] DETAIL: Streaming transactions committing after 0/2675330, reading WAL from 0/26752F8. 459s [2025-02-22 06:47:55.702 UTC] [3716] [postgres] STATEMENT: START_REPLICATION SLOT "pgl_regression_test_subscriber_test_bid1979e66" LOGICAL 0/2675330 (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 '3710') 459s [2025-02-22 06:47:55.702 UTC] [3716] [postgres] LOG: logical decoding found consistent point at 0/26752F8 459s [2025-02-22 06:47:55.702 UTC] [3716] [postgres] DETAIL: There are no running transactions. 459s [2025-02-22 06:47:55.702 UTC] [3716] [postgres] STATEMENT: START_REPLICATION SLOT "pgl_regression_test_subscriber_test_bid1979e66" LOGICAL 0/2675330 (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 '3710') 459s [2025-02-22 06:47:57.915 UTC] [3710] [regression] LOG: CONFLICT: remote UPDATE on relation public.basic_dml (local index basic_dml_pkey). Resolution: apply_remote. 459s [2025-02-22 06:47:57.915 UTC] [3710] [regression] DETAIL: existing local tuple {id[int4]:1 other[int4]:5 data[text]:foo something[interval]:00:01:00} xid=1063,origin=0,timestamp=2025-02-22 06:47:56.908373+00; remote tuple {id[int4]:1 other[int4]:1 data[text]:foo something[interval]:00:00:50} in xact origin=2,timestamp=2025-02-22 06:47:57.914598+00,commit_lsn=0/26862F8 459s [2025-02-22 06:47:57.915 UTC] [3710] [regression] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/26862F8, xid 1065 committed at 2025-02-22 06:47:57.914598+00 (action #2) from node replorigin 2 459s [2025-02-22 06:47:57.915 UTC] [3710] [regression] LOG: CONFLICT: remote UPDATE on relation public.basic_dml (local index basic_dml_pkey). Resolution: apply_remote. 459s [2025-02-22 06:47:57.915 UTC] [3710] [regression] DETAIL: existing local tuple {id[int4]:2 other[int4]:4 data[text]:bar something[interval]:84 days} xid=1063,origin=0,timestamp=2025-02-22 06:47:56.908373+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-02-22 06:47:57.914598+00,commit_lsn=0/26862F8 459s [2025-02-22 06:47:57.915 UTC] [3710] [regression] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/26862F8, xid 1065 committed at 2025-02-22 06:47:57.914598+00 (action #3) from node replorigin 2 459s [2025-02-22 06:47:57.915 UTC] [3710] [regression] LOG: CONFLICT: remote UPDATE on relation public.basic_dml (local index basic_dml_pkey). Resolution: apply_remote. 459s [2025-02-22 06:47:57.915 UTC] [3710] [regression] DETAIL: existing local tuple {id[int4]:4 other[int4]:2 data[text]:qux something[interval]:8 mons 2 days} xid=1063,origin=0,timestamp=2025-02-22 06:47:56.908373+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-02-22 06:47:57.914892+00,commit_lsn=0/26863E0 459s [2025-02-22 06:47:57.915 UTC] [3710] [regression] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/26863E0, xid 1066 committed at 2025-02-22 06:47:57.914892+00 (action #2) from node replorigin 2 459s [2025-02-22 06:47:57.915 UTC] [3710] [regression] LOG: CONFLICT: remote UPDATE on relation public.basic_dml (local index basic_dml_pkey). Resolution: apply_remote. 459s [2025-02-22 06:47:57.915 UTC] [3710] [regression] DETAIL: existing local tuple {id[int4]:5 other[int4]:1 data[text]:(null) something[interval]:(null)} xid=1063,origin=0,timestamp=2025-02-22 06:47:56.908373+00; remote tuple {id[int4]:5 other[int4]:5 data[text]:(null) something[interval]:(null)} in xact origin=2,timestamp=2025-02-22 06:47:57.914892+00,commit_lsn=0/26863E0 459s [2025-02-22 06:47:57.915 UTC] [3710] [regression] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/26863E0, xid 1066 committed at 2025-02-22 06:47:57.914892+00 (action #3) from node replorigin 2 459s [2025-02-22 06:47:58.926 UTC] [3710] [regression] LOG: apply worker [3710] at slot 2 generation 8 detaching cleanly 459s [2025-02-22 06:47:59.928 UTC] [3474] [regression] LOG: process 3474 still waiting for ShareUpdateExclusiveLock on relation 17149 of database 16384 after 1000.087 ms 459s [2025-02-22 06:47:59.928 UTC] [3474] [regression] DETAIL: Process holding the lock: 3721. Wait queue: 3474. 459s [2025-02-22 06:47:59.930 UTC] [3474] [regression] LOG: process 3474 acquired ShareUpdateExclusiveLock on relation 17149 of database 16384 after 1002.446 ms 459s [2025-02-22 06:47:59.932 UTC] [3724] [regression1] LOG: manager worker [3724] at slot 4 generation 4 detaching cleanly 459s [2025-02-22 06:47:59.932 UTC] [3723] [template1] LOG: manager worker [3723] at slot 2 generation 9 detaching cleanly 459s [2025-02-22 06:47:59.934 UTC] [3725] [sourcedb] LOG: manager worker [3725] at slot 5 generation 1 detaching cleanly 459s [2025-02-22 06:47:59.949 UTC] [3484] [postgres] LOG: apply worker [3484] at slot 3 generation 1 detaching cleanly 459s [2025-02-22 06:47:59.952 UTC] [3736] [template1] LOG: manager worker [3736] at slot 2 generation 10 detaching cleanly 459s [2025-02-22 06:47:59.952 UTC] [3735] [postgres] LOG: starting apply for subscription test_subscription 459s [2025-02-22 06:47:59.954 UTC] [3738] [regression1] LOG: manager worker [3738] at slot 2 generation 11 detaching cleanly 459s [2025-02-22 06:47:59.955 UTC] [3739] [sourcedb] LOG: manager worker [3739] at slot 4 generation 5 detaching cleanly 459s [2025-02-22 06:47:59.955 UTC] [3737] [regression] LOG: 0/2689508 has been already streamed, forwarding to 0/268CB30 459s [2025-02-22 06:47:59.955 UTC] [3737] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/2689508 (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 '3735') 459s [2025-02-22 06:47:59.956 UTC] [3737] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9" 459s [2025-02-22 06:47:59.956 UTC] [3737] [regression] DETAIL: Streaming transactions committing after 0/268CB30, reading WAL from 0/26752F8. 459s [2025-02-22 06:47:59.956 UTC] [3737] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/2689508 (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 '3735') 459s [2025-02-22 06:47:59.956 UTC] [3737] [regression] LOG: logical decoding found consistent point at 0/26752F8 459s [2025-02-22 06:47:59.956 UTC] [3737] [regression] DETAIL: There are no running transactions. 459s [2025-02-22 06:47:59.956 UTC] [3737] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/2689508 (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 '3735') 459s [2025-02-22 06:48:00.954 UTC] [3742] [template1] LOG: manager worker [3742] at slot 2 generation 12 detaching cleanly 459s [2025-02-22 06:48:00.956 UTC] [3735] [postgres] LOG: apply worker [3735] at slot 3 generation 2 detaching cleanly 459s [2025-02-22 06:48:00.956 UTC] [3743] [regression1] LOG: manager worker [3743] at slot 2 generation 13 detaching cleanly 459s [2025-02-22 06:48:00.958 UTC] [3744] [postgres] LOG: starting apply for subscription test_subscription 459s [2025-02-22 06:48:00.958 UTC] [3745] [sourcedb] LOG: manager worker [3745] at slot 3 generation 3 detaching cleanly 459s [2025-02-22 06:48:00.960 UTC] [3746] [regression] LOG: 0/2689508 has been already streamed, forwarding to 0/268CCA0 459s [2025-02-22 06:48:00.960 UTC] [3746] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/2689508 (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 '3744') 459s [2025-02-22 06:48:00.960 UTC] [3746] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9" 459s [2025-02-22 06:48:00.960 UTC] [3746] [regression] DETAIL: Streaming transactions committing after 0/268CCA0, reading WAL from 0/26752F8. 459s [2025-02-22 06:48:00.960 UTC] [3746] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/2689508 (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 '3744') 459s [2025-02-22 06:48:00.960 UTC] [3746] [regression] LOG: logical decoding found consistent point at 0/26752F8 459s [2025-02-22 06:48:00.960 UTC] [3746] [regression] DETAIL: There are no running transactions. 459s [2025-02-22 06:48:00.960 UTC] [3746] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/2689508 (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 '3744') 459s [2025-02-22 06:48:11.158 UTC] [3744] [postgres] ERROR: null value in column "id2" of relation "not_nullcheck_tbl" violates not-null constraint 459s [2025-02-22 06:48:11.158 UTC] [3744] [postgres] DETAIL: Failing row contains (1, 1, name1, null). 459s [2025-02-22 06:48:11.158 UTC] [3744] [postgres] CONTEXT: apply INSERT from remote relation public.not_nullcheck_tbl in commit before 0/26CD638, xid 1137 committed at 2025-02-22 06:48:11.158114+00 (action #2) from node replorigin 1 459s [2025-02-22 06:48:11.158 UTC] [3744] [postgres] LOG: apply worker [3744] at slot 2 generation 14 exiting with error 459s [2025-02-22 06:48:11.159 UTC] [3746] [regression] LOG: unexpected EOF on standby connection 459s [2025-02-22 06:48:11.159 UTC] [3746] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/2689508 (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 '3744') 459s [2025-02-22 06:48:11.159 UTC] [3407] [] LOG: background worker "pglogical apply 5:2208722835" (PID 3744) exited with exit code 1 459s [2025-02-22 06:48:11.162 UTC] [3778] [postgres] ERROR: null value in column "id2" of relation "not_nullcheck_tbl" violates not-null constraint 459s [2025-02-22 06:48:11.162 UTC] [3778] [postgres] DETAIL: Failing row contains (3, 3, name3, null). 459s [2025-02-22 06:48:11.162 UTC] [3778] [postgres] STATEMENT: INSERT INTO public.not_nullcheck_tbl(id,id1,name) VALUES (3,3,'name3'); 459s [2025-02-22 06:48:11.164 UTC] [3779] [template1] LOG: manager worker [3779] at slot 2 generation 15 detaching cleanly 459s [2025-02-22 06:48:11.166 UTC] [3781] [regression1] LOG: manager worker [3781] at slot 2 generation 16 detaching cleanly 459s [2025-02-22 06:48:11.166 UTC] [3780] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9" 459s [2025-02-22 06:48:11.166 UTC] [3780] [regression] DETAIL: Streaming transactions committing after 0/26CD550, reading WAL from 0/26752F8. 459s [2025-02-22 06:48:11.166 UTC] [3780] [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'); 459s [2025-02-22 06:48:11.166 UTC] [3780] [regression] LOG: logical decoding found consistent point at 0/26752F8 459s [2025-02-22 06:48:11.166 UTC] [3780] [regression] DETAIL: There are no running transactions. 459s [2025-02-22 06:48:11.166 UTC] [3780] [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'); 459s [2025-02-22 06:48:11.168 UTC] [3782] [sourcedb] LOG: manager worker [3782] at slot 2 generation 17 detaching cleanly 459s [2025-02-22 06:48:11.168 UTC] [3780] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9" 459s [2025-02-22 06:48:11.168 UTC] [3780] [regression] DETAIL: Streaming transactions committing after 0/26CD668, reading WAL from 0/26752F8. 459s [2025-02-22 06:48:11.168 UTC] [3780] [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'); 459s [2025-02-22 06:48:11.168 UTC] [3780] [regression] LOG: logical decoding found consistent point at 0/26752F8 459s [2025-02-22 06:48:11.168 UTC] [3780] [regression] DETAIL: There are no running transactions. 459s [2025-02-22 06:48:11.168 UTC] [3780] [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'); 459s [2025-02-22 06:48:11.173 UTC] [3784] [template1] LOG: manager worker [3784] at slot 2 generation 18 detaching cleanly 459s [2025-02-22 06:48:11.175 UTC] [3785] [postgres] LOG: starting apply for subscription test_subscription 459s [2025-02-22 06:48:11.175 UTC] [3786] [regression1] LOG: manager worker [3786] at slot 2 generation 19 detaching cleanly 459s [2025-02-22 06:48:11.177 UTC] [3789] [sourcedb] LOG: manager worker [3789] at slot 2 generation 20 detaching cleanly 459s [2025-02-22 06:48:11.179 UTC] [3788] [regression] LOG: 0/26C80D8 has been already streamed, forwarding to 0/26CD720 459s [2025-02-22 06:48:11.179 UTC] [3788] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/26C80D8 (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 '3785') 459s [2025-02-22 06:48:11.179 UTC] [3788] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9" 459s [2025-02-22 06:48:11.179 UTC] [3788] [regression] DETAIL: Streaming transactions committing after 0/26CD720, reading WAL from 0/26752F8. 459s [2025-02-22 06:48:11.179 UTC] [3788] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/26C80D8 (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 '3785') 459s [2025-02-22 06:48:11.179 UTC] [3788] [regression] LOG: logical decoding found consistent point at 0/26752F8 459s [2025-02-22 06:48:11.179 UTC] [3788] [regression] DETAIL: There are no running transactions. 459s [2025-02-22 06:48:11.179 UTC] [3788] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9" LOGICAL 0/26C80D8 (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 '3785') 459s [2025-02-22 06:48:16.375 UTC] [3785] [postgres] WARNING: resource was not closed: relation "test_trg_data" 459s [2025-02-22 06:48:16.375 UTC] [3785] [postgres] CONTEXT: apply COMMIT in commit before 0/2746960, xid 1182 committed at 2025-02-22 06:48:16.374087+00 (action #3) from node replorigin 1 459s [2025-02-22 06:48:16.375 UTC] [3785] [postgres] WARNING: resource was not closed: relation "test_trg_data" 459s [2025-02-22 06:48:16.375 UTC] [3785] [postgres] CONTEXT: apply COMMIT in commit before 0/2746A40, xid 1183 committed at 2025-02-22 06:48:16.374224+00 (action #4) from node replorigin 1 459s [2025-02-22 06:48:16.375 UTC] [3785] [postgres] WARNING: resource was not closed: relation "test_trg_data" 459s [2025-02-22 06:48:16.375 UTC] [3785] [postgres] CONTEXT: apply COMMIT in commit before 0/2746A40, xid 1183 committed at 2025-02-22 06:48:16.374224+00 (action #4) from node replorigin 1 459s [2025-02-22 06:48:16.375 UTC] [3785] [postgres] WARNING: resource was not closed: relation "test_trg_data" 459s [2025-02-22 06:48:16.375 UTC] [3785] [postgres] CONTEXT: apply COMMIT in commit before 0/2746B80, xid 1185 committed at 2025-02-22 06:48:16.374259+00 (action #4) from node replorigin 1 459s [2025-02-22 06:48:16.375 UTC] [3785] [postgres] WARNING: resource was not closed: relation "test_trg_data" 459s [2025-02-22 06:48:16.375 UTC] [3785] [postgres] CONTEXT: apply COMMIT in commit before 0/2746B80, xid 1185 committed at 2025-02-22 06:48:16.374259+00 (action #4) from node replorigin 1 459s [2025-02-22 06:48:20.434 UTC] [3831] [postgres] ERROR: existing subscription "test_subscription" to node "test_provider" already subscribes to replication set "default" 459s [2025-02-22 06:48:20.434 UTC] [3831] [postgres] STATEMENT: SELECT * FROM pglogical.create_subscription( 459s subscription_name := 'test_subscription_parallel', 459s provider_dsn := (SELECT provider_dsn FROM pglogical_regress_variables()) || ' user=super', 459s replication_sets := '{parallel,default}', 459s forward_origins := '{}', 459s synchronize_structure := false, 459s synchronize_data := false 459s ); 459s [2025-02-22 06:48:20.441 UTC] [3838] [template1] LOG: manager worker [3838] at slot 4 generation 6 detaching cleanly 459s [2025-02-22 06:48:20.442 UTC] [3839] [postgres] LOG: starting apply for subscription test_subscription_parallel 459s [2025-02-22 06:48:20.443 UTC] [3841] [regression1] LOG: manager worker [3841] at slot 4 generation 7 detaching cleanly 459s [2025-02-22 06:48:20.445 UTC] [3842] [regression] LOG: logical decoding found consistent point at 0/2767F20 459s [2025-02-22 06:48:20.445 UTC] [3842] [regression] DETAIL: There are no running transactions. 459s [2025-02-22 06:48:20.445 UTC] [3842] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_subb8618c2" LOGICAL pglogical_output 459s [2025-02-22 06:48:20.445 UTC] [3842] [regression] LOG: exported logical decoding snapshot: "00000089-00000002-1" with 0 transaction IDs 459s [2025-02-22 06:48:20.445 UTC] [3842] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_subb8618c2" LOGICAL pglogical_output 459s [2025-02-22 06:48:20.445 UTC] [3843] [sourcedb] LOG: manager worker [3843] at slot 4 generation 8 detaching cleanly 459s [2025-02-22 06:48:20.448 UTC] [3844] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_subb8618c2" 459s [2025-02-22 06:48:20.448 UTC] [3844] [regression] DETAIL: Streaming transactions committing after 0/2767F58, reading WAL from 0/2767F20. 459s [2025-02-22 06:48:20.448 UTC] [3844] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_subb8618c2" LOGICAL 0/2767F58 (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 '3839') 459s [2025-02-22 06:48:20.448 UTC] [3844] [regression] LOG: logical decoding found consistent point at 0/2767F20 459s [2025-02-22 06:48:20.448 UTC] [3844] [regression] DETAIL: There are no running transactions. 459s [2025-02-22 06:48:20.448 UTC] [3844] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_subb8618c2" LOGICAL 0/2767F58 (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 '3839') 459s [2025-02-22 06:48:22.661 UTC] [3839] [postgres] LOG: apply worker [3839] at slot 2 generation 21 detaching cleanly 459s [2025-02-22 06:48:22.666 UTC] [3848] [template1] LOG: manager worker [3848] at slot 2 generation 22 detaching cleanly 459s [2025-02-22 06:48:22.668 UTC] [3850] [regression1] LOG: manager worker [3850] at slot 2 generation 23 detaching cleanly 459s [2025-02-22 06:48:22.670 UTC] [3851] [sourcedb] LOG: manager worker [3851] at slot 2 generation 24 detaching cleanly 459s [2025-02-22 06:48:22.683 UTC] [3858] [regression] ERROR: cannot use subquery in check constraint 459s [2025-02-22 06:48:22.683 UTC] [3858] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', false, row_filter := '(SELECT count(*) FROM pg_class) > 1'); 459s [2025-02-22 06:48:22.683 UTC] [3858] [regression] ERROR: syntax error at or near "SELECT" 459s [2025-02-22 06:48:22.683 UTC] [3858] [regression] CONTEXT: invalid row_filter expression "SELECT true" 459s [2025-02-22 06:48:22.683 UTC] [3858] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', false, row_filter := 'SELECT true'); 459s [2025-02-22 06:48:22.683 UTC] [3858] [regression] ERROR: column "foobar" does not exist 459s [2025-02-22 06:48:22.683 UTC] [3858] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', false, row_filter := 'foobar'); 459s [2025-02-22 06:48:22.684 UTC] [3858] [regression] ERROR: argument of row_filter must be type boolean, not type text 459s [2025-02-22 06:48:22.684 UTC] [3858] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', false, row_filter := 'data'); 459s [2025-02-22 06:48:22.686 UTC] [3859] [postgres] LOG: starting sync of table public.basic_dml for subscriber test_subscription 459s [2025-02-22 06:48:22.686 UTC] [3858] [regression] ERROR: cannot drop column data of table basic_dml because other objects depend on it 459s [2025-02-22 06:48:22.686 UTC] [3858] [regression] DETAIL: table basic_dml membership in replication set default depends on column data of table basic_dml 459s [2025-02-22 06:48:22.686 UTC] [3858] [regression] HINT: Use DROP ... CASCADE to drop the dependent objects too. 459s [2025-02-22 06:48:22.686 UTC] [3858] [regression] STATEMENT: ALTER TABLE basic_dml DROP COLUMN data; 459s [2025-02-22 06:48:22.689 UTC] [3860] [regression] LOG: logical decoding found consistent point at 0/27A47B8 459s [2025-02-22 06:48:22.689 UTC] [3860] [regression] DETAIL: There are no running transactions. 459s [2025-02-22 06:48:22.689 UTC] [3860] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" LOGICAL pglogical_output 459s [2025-02-22 06:48:22.689 UTC] [3860] [regression] LOG: exported logical decoding snapshot: "0000008B-00000002-1" with 0 transaction IDs 459s [2025-02-22 06:48:22.689 UTC] [3860] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" LOGICAL pglogical_output 459s [2025-02-22 06:48:22.696 UTC] [3864] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" 459s [2025-02-22 06:48:22.696 UTC] [3864] [regression] DETAIL: Streaming transactions committing after 0/27A47F0, reading WAL from 0/27A47B8. 459s [2025-02-22 06:48:22.696 UTC] [3864] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" LOGICAL 0/27A47F0 (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 '3859') 459s [2025-02-22 06:48:22.696 UTC] [3864] [regression] LOG: logical decoding found consistent point at 0/27A47B8 459s [2025-02-22 06:48:22.696 UTC] [3864] [regression] DETAIL: There are no running transactions. 459s [2025-02-22 06:48:22.696 UTC] [3864] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" LOGICAL 0/27A47F0 (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 '3859') 459s [2025-02-22 06:48:49.515 UTC] [3408] [] LOG: checkpoint starting: time 459s [2025-02-22 06:49:16.004 UTC] [3408] [] LOG: checkpoint complete: wrote 3265 buffers (19.9%); 0 WAL file(s) added, 0 removed, 1 recycled; write=26.486 s, sync=0.001 s, total=26.489 s; sync files=0, longest=0.000 s, average=0.000 s; distance=19170 kB, estimate=19170 kB; lsn=0/27A5038, redo lsn=0/27A4FA8 459s [2025-02-22 06:49:19.149 UTC] [3867] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_type" 459s avg read rate: 7.102 MB/s, avg write rate: 9.233 MB/s 459s buffer usage: 1070 hits, 10 misses, 13 dirtied 459s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s 459s [2025-02-22 06:49:19.159 UTC] [3867] [] LOG: automatic vacuum of table "postgres.pg_catalog.pg_attribute": index scans: 1 459s pages: 0 removed, 79 remain, 42 scanned (53.16% of total) 459s tuples: 1153 removed, 3308 remain, 0 are dead but not yet removable 459s removable cutoff: 1247, which was 5 XIDs old when operation ended 459s new relfrozenxid: 797, which is 67 XIDs ahead of previous value 459s frozen: 1 pages from table (1.27% of total) had 33 tuples frozen 459s index scan needed: 24 pages from table (30.38% of total) had 1209 dead item identifiers removed 459s index "pg_attribute_relid_attnam_index": pages: 21 in total, 3 newly deleted, 3 currently deleted, 0 reusable 459s index "pg_attribute_relid_attnum_index": pages: 15 in total, 2 newly deleted, 2 currently deleted, 0 reusable 459s avg read rate: 11.757 MB/s, avg write rate: 38.630 MB/s 459s buffer usage: 184 hits, 14 misses, 46 dirtied 459s WAL usage: 98 records, 39 full page images, 91411 bytes 459s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 459s [2025-02-22 06:49:19.173 UTC] [3867] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_attribute" 459s avg read rate: 10.603 MB/s, avg write rate: 5.022 MB/s 459s buffer usage: 561 hits, 19 misses, 9 dirtied 459s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s 459s [2025-02-22 06:49:19.176 UTC] [3867] [] LOG: automatic vacuum of table "postgres.pg_catalog.pg_class": index scans: 1 459s pages: 0 removed, 18 remain, 18 scanned (100.00% of total) 459s tuples: 59 removed, 453 remain, 0 are dead but not yet removable 459s removable cutoff: 1247, which was 6 XIDs old when operation ended 459s new relfrozenxid: 797, which is 67 XIDs ahead of previous value 459s frozen: 1 pages from table (5.56% of total) had 5 tuples frozen 459s index scan needed: 12 pages from table (66.67% of total) had 242 dead item identifiers removed 459s index "pg_class_oid_index": pages: 4 in total, 0 newly deleted, 0 currently deleted, 0 reusable 459s index "pg_class_relname_nsp_index": pages: 7 in total, 0 newly deleted, 0 currently deleted, 0 reusable 459s index "pg_class_tblspc_relfilenode_index": pages: 4 in total, 0 newly deleted, 0 currently deleted, 0 reusable 459s avg read rate: 0.000 MB/s, avg write rate: 53.662 MB/s 459s buffer usage: 102 hits, 0 misses, 17 dirtied 459s WAL usage: 39 records, 14 full page images, 60704 bytes 459s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 459s [2025-02-22 06:49:19.182 UTC] [3867] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_class" 459s avg read rate: 3.348 MB/s, avg write rate: 6.696 MB/s 459s buffer usage: 550 hits, 3 misses, 6 dirtied 459s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 459s [2025-02-22 06:49:19.187 UTC] [3867] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_constraint" 459s avg read rate: 1.562 MB/s, avg write rate: 4.688 MB/s 459s buffer usage: 548 hits, 1 misses, 3 dirtied 459s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 459s [2025-02-22 06:49:19.190 UTC] [3867] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_index" 459s avg read rate: 2.604 MB/s, avg write rate: 7.812 MB/s 459s buffer usage: 366 hits, 1 misses, 3 dirtied 459s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 459s [2025-02-22 06:49:19.191 UTC] [3867] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_trigger" 459s avg read rate: 0.000 MB/s, avg write rate: 15.625 MB/s 459s buffer usage: 251 hits, 0 misses, 2 dirtied 459s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 459s [2025-02-22 06:49:19.195 UTC] [3867] [] LOG: automatic vacuum of table "postgres.pg_catalog.pg_depend": index scans: 1 459s pages: 0 removed, 21 remain, 21 scanned (100.00% of total) 459s tuples: 474 removed, 1992 remain, 0 are dead but not yet removable 459s removable cutoff: 1247, which was 10 XIDs old when operation ended 459s new relfrozenxid: 797, which is 67 XIDs ahead of previous value 459s frozen: 3 pages from table (14.29% of total) had 147 tuples frozen 459s index scan needed: 10 pages from table (47.62% of total) had 784 dead item identifiers removed 459s index "pg_depend_depender_index": pages: 15 in total, 0 newly deleted, 0 currently deleted, 0 reusable 459s index "pg_depend_reference_index": pages: 11 in total, 0 newly deleted, 0 currently deleted, 0 reusable 459s avg read rate: 25.631 MB/s, avg write rate: 41.650 MB/s 459s buffer usage: 114 hits, 16 misses, 26 dirtied 459s WAL usage: 45 records, 22 full page images, 77058 bytes 459s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 459s [2025-02-22 06:49:19.201 UTC] [3867] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_depend" 459s avg read rate: 0.000 MB/s, avg write rate: 2.604 MB/s 459s buffer usage: 129 hits, 0 misses, 2 dirtied 459s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 459s [2025-02-22 06:49:20.009 UTC] [3408] [] LOG: checkpoint starting: time 459s [2025-02-22 06:49:23.691 UTC] [3865] [postgres] ERROR: canceling statement due to statement timeout 459s [2025-02-22 06:49:23.691 UTC] [3865] [postgres] STATEMENT: SELECT pglogical.wait_for_subscription_sync_complete('test_subscription'); 459s [2025-02-22 06:49:23.699 UTC] [3859] [postgres] LOG: pglogical sync finished processing; replayed to 0/2831CA0 of required 0/27A4E48 459s [2025-02-22 06:49:23.699 UTC] [3859] [postgres] CONTEXT: apply COMMIT in commit before 0/2831B30, xid 1261 committed at 2025-02-22 06:49:23.698876+00 (action #2) from node replorigin 2 459s [2025-02-22 06:49:23.702 UTC] [3859] [postgres] LOG: finished sync of table public.basic_dml for subscriber test_subscription 459s [2025-02-22 06:49:23.702 UTC] [3859] [postgres] CONTEXT: apply COMMIT in commit before 0/2831B30, xid 1261 committed at 2025-02-22 06:49:23.702044+00 (action #2) 459s [2025-02-22 06:49:23.702 UTC] [3859] [postgres] LOG: sync worker [3859] at slot 2 generation 25 detaching cleanly 459s [2025-02-22 06:49:25.717 UTC] [3785] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 459s [2025-02-22 06:49:25.717 UTC] [3785] [postgres] DETAIL: remote tuple {id[int4]:3 other[int4]:3 data[text]:baz3 SomeThing[interval]:2 years 01:00:00 insert_xid[int8]:1263 other2[text]:pr387 subonly[int4]:(null) subonly_def[int4]:(null) subonly_def_ts[timestamptz]:(null)} in xact origin=1,timestamp=2025-02-22 06:49:25.717326+00,commit_lsn=0/2834740 459s [2025-02-22 06:49:25.717 UTC] [3785] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/2834740, xid 1270 committed at 2025-02-22 06:49:25.717326+00 (action #3) from node replorigin 1 459s [2025-02-22 06:49:26.727 UTC] [3785] [postgres] LOG: CONFLICT: remote DELETE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 459s [2025-02-22 06:49:26.727 UTC] [3785] [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-02-22 06:49:26.726985+00,commit_lsn=0/2834EF8 459s [2025-02-22 06:49:26.727 UTC] [3785] [postgres] CONTEXT: apply (unknown action) from remote relation public.basic_dml in commit before 0/2834EF8, xid 1276 committed at 2025-02-22 06:49:26.726985+00 (action #2) from node replorigin 1 459s [2025-02-22 06:49:26.741 UTC] [3785] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 459s [2025-02-22 06:49:26.741 UTC] [3785] [postgres] DETAIL: remote tuple {id[int4]:6 other[int4]:100 data[text]:bar SomeThing[interval]:2 years 01:00:00 insert_xid[int8]:1286 other2[text]:pr387 subonly[int4]:(null) subonly_def[int4]:(null) subonly_def_ts[timestamptz]:(null)} in xact origin=1,timestamp=2025-02-22 06:49:26.741645+00,commit_lsn=0/2835840 459s [2025-02-22 06:49:26.741 UTC] [3785] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/2835840, xid 1287 committed at 2025-02-22 06:49:26.741645+00 (action #2) from node replorigin 1 459s [2025-02-22 06:49:26.741 UTC] [3785] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 459s [2025-02-22 06:49:26.741 UTC] [3785] [postgres] DETAIL: remote tuple {id[int4]:6 other[int4]:100 data[text]:abcd SomeThing[interval]:2 years 01:00:00 insert_xid[int8]:1286 other2[text]:pr387 subonly[int4]:(null) subonly_def[int4]:(null) subonly_def_ts[timestamptz]:(null)} in xact origin=1,timestamp=2025-02-22 06:49:26.74177+00,commit_lsn=0/28358E0 459s [2025-02-22 06:49:26.741 UTC] [3785] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/28358E0, xid 1288 committed at 2025-02-22 06:49:26.74177+00 (action #2) from node replorigin 1 459s [2025-02-22 06:49:29.776 UTC] [3888] [postgres] LOG: starting sync of table public.test_jsonb for subscriber test_subscription 459s [2025-02-22 06:49:29.780 UTC] [3889] [regression] LOG: logical decoding found consistent point at 0/28830A0 459s [2025-02-22 06:49:29.780 UTC] [3889] [regression] DETAIL: There are no running transactions. 459s [2025-02-22 06:49:29.780 UTC] [3889] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9_48bb0cb8" LOGICAL pglogical_output 459s [2025-02-22 06:49:29.780 UTC] [3889] [regression] LOG: exported logical decoding snapshot: "0000008D-00000002-1" with 0 transaction IDs 459s [2025-02-22 06:49:29.780 UTC] [3889] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9_48bb0cb8" LOGICAL pglogical_output 459s [2025-02-22 06:49:29.789 UTC] [3893] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_sub83a66f9_48bb0cb8" 459s [2025-02-22 06:49:29.789 UTC] [3893] [regression] DETAIL: Streaming transactions committing after 0/28830D8, reading WAL from 0/28830A0. 459s [2025-02-22 06:49:29.789 UTC] [3893] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9_48bb0cb8" LOGICAL 0/28830D8 (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.test_jsonb', "relmeta_cache_size" '-1', pg_version '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3888') 459s [2025-02-22 06:49:29.789 UTC] [3893] [regression] LOG: logical decoding found consistent point at 0/28830A0 459s [2025-02-22 06:49:29.789 UTC] [3893] [regression] DETAIL: There are no running transactions. 459s [2025-02-22 06:49:29.789 UTC] [3893] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_sub83a66f9_48bb0cb8" LOGICAL 0/28830D8 (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.test_jsonb', "relmeta_cache_size" '-1', pg_version '170000', pglogical_version '2.4.5', pglogical_version_num '20405', pglogical_apply_pid '3888') 459s [2025-02-22 06:49:31.155 UTC] [3895] [] LOG: automatic vacuum of table "postgres.pg_catalog.pg_statistic": index scans: 1 459s pages: 0 removed, 26 remain, 26 scanned (100.00% of total) 459s tuples: 149 removed, 429 remain, 0 are dead but not yet removable 459s removable cutoff: 1300, which was 4 XIDs old when operation ended 459s new relfrozenxid: 1251, which is 521 XIDs ahead of previous value 459s frozen: 5 pages from table (19.23% of total) had 11 tuples frozen 459s index scan needed: 11 pages from table (42.31% of total) had 145 dead item identifiers removed 459s index "pg_statistic_relid_att_inh_index": pages: 5 in total, 0 newly deleted, 0 currently deleted, 0 reusable 459s avg read rate: 12.771 MB/s, avg write rate: 36.716 MB/s 459s buffer usage: 87 hits, 8 misses, 23 dirtied 459s WAL usage: 45 records, 16 full page images, 67577 bytes 459s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 459s [2025-02-22 06:49:31.158 UTC] [3895] [] LOG: automatic analyze of table "postgres.pg_catalog.pg_attrdef" 459s avg read rate: 0.000 MB/s, avg write rate: 2.604 MB/s 459s buffer usage: 322 hits, 0 misses, 1 dirtied 459s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 459s [2025-02-22 06:49:31.158 UTC] [3895] [] LOG: automatic vacuum of table "postgres.pg_catalog.pg_index": index scans: 1 459s pages: 0 removed, 6 remain, 6 scanned (100.00% of total) 459s tuples: 4 removed, 185 remain, 0 are dead but not yet removable 459s removable cutoff: 1300, which was 5 XIDs old when operation ended 459s new relfrozenxid: 797, which is 67 XIDs ahead of previous value 459s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 459s index scan needed: 6 pages from table (100.00% of total) had 91 dead item identifiers removed 459s index "pg_index_indrelid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 459s index "pg_index_indexrelid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 459s avg read rate: 0.000 MB/s, avg write rate: 574.449 MB/s 459s buffer usage: 40 hits, 0 misses, 10 dirtied 459s WAL usage: 18 records, 7 full page images, 50473 bytes 459s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 459s [2025-02-22 06:49:32.934 UTC] [3408] [] LOG: checkpoint complete: wrote 135 buffers (0.8%); 0 WAL file(s) added, 0 removed, 0 recycled; write=12.925 s, sync=0.001 s, total=12.925 s; sync files=0, longest=0.000 s, average=0.000 s; distance=489 kB, estimate=17302 kB; lsn=0/28A2930, redo lsn=0/281F5B0 459s [2025-02-22 06:49:40.904 UTC] [3888] [postgres] LOG: pglogical sync finished processing; replayed to 0/28A2DF0 of required 0/28838B0 459s [2025-02-22 06:49:40.904 UTC] [3888] [postgres] CONTEXT: apply COMMIT in commit before 0/28A2DA8, xid 1305 committed at 2025-02-22 06:49:40.903664+00 (action #2) from node replorigin 2 459s [2025-02-22 06:49:40.909 UTC] [3888] [postgres] LOG: finished sync of table public.test_jsonb for subscriber test_subscription 459s [2025-02-22 06:49:40.909 UTC] [3888] [postgres] CONTEXT: apply COMMIT in commit before 0/28A2DA8, xid 1305 committed at 2025-02-22 06:49:40.909103+00 (action #2) 459s [2025-02-22 06:49:40.909 UTC] [3888] [postgres] LOG: sync worker [3888] at slot 2 generation 26 detaching cleanly 459s NOTICE: c_u: temp_owner, s_u: super 459s NOTICE: c_u: temp_owner, s_u: super 459s [2025-02-22 06:49:42.946 UTC] [3907] [regression] ERROR: set-returning functions are not allowed in check constraints 459s [2025-02-22 06:49:42.946 UTC] [3907] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', false, 459s row_filter := $rf$ (func_plpgsql_srf_retq(other)).result = 500 $rf$); 459s [2025-02-22 06:49:43.160 UTC] [3908] [] LOG: automatic analyze of table "template1.pg_catalog.pg_type" 459s avg read rate: 0.000 MB/s, avg write rate: 6.392 MB/s 459s buffer usage: 1078 hits, 0 misses, 9 dirtied 459s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s 459s [2025-02-22 06:49:43.170 UTC] [3908] [] LOG: automatic analyze of table "template1.pg_catalog.pg_attribute" 459s avg read rate: 0.000 MB/s, avg write rate: 7.031 MB/s 459s buffer usage: 520 hits, 0 misses, 9 dirtied 459s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 459s [2025-02-22 06:49:43.170 UTC] [3908] [] LOG: automatic aggressive vacuum of table "template1.pg_catalog.pg_class": index scans: 0 459s pages: 0 removed, 14 remain, 14 scanned (100.00% of total) 459s tuples: 0 removed, 415 remain, 0 are dead but not yet removable 459s removable cutoff: 1318, which was 26 XIDs old when operation ended 460s new relfrozenxid: 1318, which is 588 XIDs ahead of previous value 460s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 460s index scan not needed: 0 pages from table (0.00% of total) had 0 dead item identifiers removed 460s avg read rate: 0.000 MB/s, avg write rate: 101.461 MB/s 460s buffer usage: 57 hits, 0 misses, 1 dirtied 460s WAL usage: 1 records, 1 full page images, 2641 bytes 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:43.175 UTC] [3908] [] LOG: automatic analyze of table "template1.pg_catalog.pg_class" 460s avg read rate: 0.000 MB/s, avg write rate: 9.375 MB/s 460s buffer usage: 531 hits, 0 misses, 6 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:43.180 UTC] [3908] [] LOG: automatic analyze of table "template1.pg_catalog.pg_constraint" 460s avg read rate: 0.000 MB/s, avg write rate: 6.250 MB/s 460s buffer usage: 565 hits, 0 misses, 4 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:43.180 UTC] [3908] [] LOG: automatic analyze of table "template1.pg_catalog.pg_rewrite" 460s avg read rate: 0.000 MB/s, avg write rate: 7.812 MB/s 460s buffer usage: 130 hits, 0 misses, 1 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:43.184 UTC] [3908] [] LOG: automatic analyze of table "template1.pg_catalog.pg_description" 460s avg read rate: 0.000 MB/s, avg write rate: 1.953 MB/s 460s buffer usage: 131 hits, 0 misses, 1 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:43.184 UTC] [3908] [] LOG: automatic aggressive vacuum of table "template1.pg_catalog.pg_depend": index scans: 0 460s pages: 0 removed, 13 remain, 13 scanned (100.00% of total) 460s tuples: 0 removed, 1709 remain, 0 are dead but not yet removable 460s removable cutoff: 1318, which was 30 XIDs old when operation ended 460s new relfrozenxid: 1318, which is 588 XIDs ahead of previous value 460s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 460s index scan not needed: 0 pages from table (0.00% of total) had 0 dead item identifiers removed 460s avg read rate: 0.000 MB/s, avg write rate: 53.879 MB/s 460s buffer usage: 73 hits, 0 misses, 1 dirtied 460s WAL usage: 1 records, 1 full page images, 7869 bytes 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:43.186 UTC] [3908] [] LOG: automatic analyze of table "template1.pg_catalog.pg_depend" 460s avg read rate: 0.000 MB/s, avg write rate: 7.812 MB/s 460s buffer usage: 109 hits, 0 misses, 2 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:43.186 UTC] [3908] [] LOG: automatic analyze of table "template1.pg_catalog.pg_ts_config_map" 460s avg read rate: 0.000 MB/s, avg write rate: 7.812 MB/s 460s buffer usage: 61 hits, 0 misses, 1 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:43.186 UTC] [3908] [] LOG: automatic analyze of table "template1.pg_catalog.pg_init_privs" 460s avg read rate: 0.000 MB/s, avg write rate: 7.812 MB/s 460s buffer usage: 89 hits, 0 misses, 1 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:43.188 UTC] [3908] [] LOG: automatic analyze of table "template1.pg_catalog.pg_collation" 460s avg read rate: 0.000 MB/s, avg write rate: 7.812 MB/s 460s buffer usage: 169 hits, 0 misses, 2 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:43.189 UTC] [3908] [] LOG: automatic analyze of table "template1.information_schema.sql_features" 460s avg read rate: 0.000 MB/s, avg write rate: 19.531 MB/s 460s buffer usage: 204 hits, 0 misses, 5 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:43.975 UTC] [3922] [regression] ERROR: REPLICA IDENTITY columns must be replicated 460s [2025-02-22 06:49:43.975 UTC] [3922] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', columns := '{ data, something}'); 460s [2025-02-22 06:49:49.059 UTC] [3785] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 460s [2025-02-22 06:49:49.059 UTC] [3785] [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-02-22 06:49:49.059597+00,commit_lsn=0/292ADE0 460s [2025-02-22 06:49:49.059 UTC] [3785] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/292ADE0, xid 1392 committed at 2025-02-22 06:49:49.059597+00 (action #2) from node replorigin 1 460s [2025-02-22 06:49:49.059 UTC] [3785] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 460s [2025-02-22 06:49:49.059 UTC] [3785] [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-02-22 06:49:49.059597+00,commit_lsn=0/292ADE0 460s [2025-02-22 06:49:49.059 UTC] [3785] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/292ADE0, xid 1392 committed at 2025-02-22 06:49:49.059597+00 (action #3) from node replorigin 1 460s [2025-02-22 06:49:49.059 UTC] [3785] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 460s [2025-02-22 06:49:49.059 UTC] [3785] [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-02-22 06:49:49.059597+00,commit_lsn=0/292ADE0 460s [2025-02-22 06:49:49.059 UTC] [3785] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/292ADE0, xid 1392 committed at 2025-02-22 06:49:49.059597+00 (action #4) from node replorigin 1 460s [2025-02-22 06:49:49.059 UTC] [3785] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 460s [2025-02-22 06:49:49.059 UTC] [3785] [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-02-22 06:49:49.059597+00,commit_lsn=0/292ADE0 460s [2025-02-22 06:49:49.059 UTC] [3785] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/292ADE0, xid 1392 committed at 2025-02-22 06:49:49.059597+00 (action #5) from node replorigin 1 460s [2025-02-22 06:49:49.059 UTC] [3785] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 460s [2025-02-22 06:49:49.059 UTC] [3785] [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-02-22 06:49:49.059597+00,commit_lsn=0/292ADE0 460s [2025-02-22 06:49:49.059 UTC] [3785] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/292ADE0, xid 1392 committed at 2025-02-22 06:49:49.059597+00 (action #6) from node replorigin 1 460s [2025-02-22 06:49:49.059 UTC] [3785] [postgres] LOG: CONFLICT: remote UPDATE on relation public.basic_dml replica identity index basic_dml_pkey (tuple not found). Resolution: skip. 460s [2025-02-22 06:49:49.059 UTC] [3785] [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-02-22 06:49:49.059597+00,commit_lsn=0/292ADE0 460s [2025-02-22 06:49:49.059 UTC] [3785] [postgres] CONTEXT: apply UPDATE from remote relation public.basic_dml in commit before 0/292ADE0, xid 1392 committed at 2025-02-22 06:49:49.059597+00 (action #7) from node replorigin 1 460s [2025-02-22 06:49:49.087 UTC] [3953] [regression] ERROR: REPLICA IDENTITY columns must be replicated 460s [2025-02-22 06:49:49.087 UTC] [3953] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', synchronize_data := true, columns := '{data, something}'); 460s [2025-02-22 06:49:49.088 UTC] [3953] [regression] ERROR: table public.basic_dml does not have column nosuchcol 460s [2025-02-22 06:49:49.088 UTC] [3953] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', synchronize_data := true, columns := '{data, something, nosuchcol}'); 460s [2025-02-22 06:49:49.091 UTC] [3954] [postgres] LOG: starting sync of table public.basic_dml for subscriber test_subscription 460s [2025-02-22 06:49:49.094 UTC] [3955] [regression] LOG: logical decoding found consistent point at 0/29422B8 460s [2025-02-22 06:49:49.094 UTC] [3955] [regression] DETAIL: There are no running transactions. 460s [2025-02-22 06:49:49.094 UTC] [3955] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" LOGICAL pglogical_output 460s [2025-02-22 06:49:49.094 UTC] [3955] [regression] LOG: exported logical decoding snapshot: "0000008F-00000002-1" with 0 transaction IDs 460s [2025-02-22 06:49:49.094 UTC] [3955] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_sub83a66f9_40ac3386" LOGICAL pglogical_output 460s [2025-02-22 06:49:49.951 UTC] [3408] [] LOG: checkpoint starting: time 460s [2025-02-22 06:49:50.094 UTC] [3954] [postgres] LOG: finished sync of table public.basic_dml for subscriber test_subscription 460s [2025-02-22 06:49:50.094 UTC] [3954] [postgres] LOG: sync worker [3954] at slot 2 generation 27 detaching cleanly 460s [2025-02-22 06:49:50.100 UTC] [3961] [regression] ERROR: duplicate key value violates unique constraint "replication_set_table_pkey" 460s [2025-02-22 06:49:50.100 UTC] [3961] [regression] DETAIL: Key (set_id, set_reloid)=(1376784750, 18336) already exists. 460s [2025-02-22 06:49:50.100 UTC] [3961] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', synchronize_data := true); 460s [2025-02-22 06:49:50.101 UTC] [3961] [regression] ERROR: duplicate key value violates unique constraint "replication_set_table_pkey" 460s [2025-02-22 06:49:50.101 UTC] [3961] [regression] DETAIL: Key (set_id, set_reloid)=(1376784750, 18336) already exists. 460s [2025-02-22 06:49:50.101 UTC] [3961] [regression] STATEMENT: SELECT * FROM pglogical.replication_set_add_table('default', 'basic_dml', synchronize_data := true, columns := '{id, data}'); 460s [2025-02-22 06:49:51.131 UTC] [3973] [postgres] LOG: starting apply for subscription test_subscription_delay 460s [2025-02-22 06:49:51.132 UTC] [3972] [template1] LOG: manager worker [3972] at slot 4 generation 9 detaching cleanly 460s [2025-02-22 06:49:51.132 UTC] [3974] [regression1] LOG: manager worker [3974] at slot 5 generation 2 detaching cleanly 460s [2025-02-22 06:49:51.134 UTC] [3976] [sourcedb] LOG: manager worker [3976] at slot 4 generation 10 detaching cleanly 460s [2025-02-22 06:49:51.136 UTC] [3977] [regression] LOG: logical decoding found consistent point at 0/2974CD0 460s [2025-02-22 06:49:51.136 UTC] [3977] [regression] DETAIL: There are no running transactions. 460s [2025-02-22 06:49:51.136 UTC] [3977] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_subaf763f6" LOGICAL pglogical_output 460s [2025-02-22 06:49:51.136 UTC] [3977] [regression] LOG: exported logical decoding snapshot: "0000007D-00000003-1" with 0 transaction IDs 460s [2025-02-22 06:49:51.136 UTC] [3977] [regression] STATEMENT: CREATE_REPLICATION_SLOT "pgl_postgres_test_provider_test_subaf763f6" LOGICAL pglogical_output 460s [2025-02-22 06:49:51.140 UTC] [3978] [regression] LOG: starting logical decoding for slot "pgl_postgres_test_provider_test_subaf763f6" 460s [2025-02-22 06:49:51.140 UTC] [3978] [regression] DETAIL: Streaming transactions committing after 0/2974D08, reading WAL from 0/2974CD0. 460s [2025-02-22 06:49:51.140 UTC] [3978] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_subaf763f6" LOGICAL 0/2974D08 (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 '3973') 460s [2025-02-22 06:49:51.140 UTC] [3978] [regression] LOG: logical decoding found consistent point at 0/2974CD0 460s [2025-02-22 06:49:51.140 UTC] [3978] [regression] DETAIL: There are no running transactions. 460s [2025-02-22 06:49:51.140 UTC] [3978] [regression] STATEMENT: START_REPLICATION SLOT "pgl_postgres_test_provider_test_subaf763f6" LOGICAL 0/2974D08 (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 '3973') 460s [2025-02-22 06:49:55.146 UTC] [3980] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_type": index scans: 1 460s pages: 0 removed, 18 remain, 18 scanned (100.00% of total) 460s tuples: 63 removed, 645 remain, 0 are dead but not yet removable 460s removable cutoff: 1422, which was 8 XIDs old when operation ended 460s new relfrozenxid: 794, which is 64 XIDs ahead of previous value 460s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 460s index scan needed: 4 pages from table (22.22% of total) had 206 dead item identifiers removed 460s index "pg_type_oid_index": pages: 5 in total, 0 newly deleted, 0 currently deleted, 0 reusable 460s index "pg_type_typname_nsp_index": pages: 8 in total, 0 newly deleted, 0 currently deleted, 0 reusable 460s avg read rate: 0.000 MB/s, avg write rate: 34.877 MB/s 460s buffer usage: 83 hits, 0 misses, 11 dirtied 460s WAL usage: 21 records, 9 full page images, 46672 bytes 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.157 UTC] [3980] [] LOG: automatic analyze of table "regression.pg_catalog.pg_type" 460s avg read rate: 0.000 MB/s, avg write rate: 7.812 MB/s 460s buffer usage: 1105 hits, 0 misses, 12 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s 460s [2025-02-22 06:49:55.170 UTC] [3980] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_attribute": index scans: 1 460s pages: 0 removed, 87 remain, 50 scanned (57.47% of total) 460s tuples: 1065 removed, 3338 remain, 1 are dead but not yet removable 460s removable cutoff: 1422, which was 9 XIDs old when operation ended 460s new relfrozenxid: 794, which is 64 XIDs ahead of previous value 460s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 460s index scan needed: 33 pages from table (37.93% of total) had 1773 dead item identifiers removed 460s index "pg_attribute_relid_attnam_index": pages: 22 in total, 3 newly deleted, 3 currently deleted, 0 reusable 460s index "pg_attribute_relid_attnum_index": pages: 16 in total, 2 newly deleted, 2 currently deleted, 0 reusable 460s avg read rate: 0.000 MB/s, avg write rate: 34.291 MB/s 460s buffer usage: 225 hits, 0 misses, 52 dirtied 460s WAL usage: 115 records, 46 full page images, 96441 bytes 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s 460s [2025-02-22 06:49:55.182 UTC] [3980] [] LOG: automatic analyze of table "regression.pg_catalog.pg_attribute" 460s avg read rate: 0.000 MB/s, avg write rate: 5.409 MB/s 460s buffer usage: 568 hits, 0 misses, 9 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s 460s [2025-02-22 06:49:55.187 UTC] [3980] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_class": index scans: 1 460s pages: 0 removed, 21 remain, 21 scanned (100.00% of total) 460s tuples: 79 removed, 462 remain, 3 are dead but not yet removable 460s removable cutoff: 1422, which was 10 XIDs old when operation ended 460s new relfrozenxid: 794, which is 64 XIDs ahead of previous value 460s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 460s index scan needed: 16 pages from table (76.19% of total) had 382 dead item identifiers removed 460s index "pg_class_oid_index": pages: 4 in total, 0 newly deleted, 0 currently deleted, 0 reusable 460s index "pg_class_relname_nsp_index": pages: 7 in total, 0 newly deleted, 0 currently deleted, 0 reusable 460s index "pg_class_tblspc_relfilenode_index": pages: 4 in total, 0 newly deleted, 0 currently deleted, 0 reusable 460s avg read rate: 0.000 MB/s, avg write rate: 34.492 MB/s 460s buffer usage: 112 hits, 0 misses, 20 dirtied 460s WAL usage: 47 records, 17 full page images, 75509 bytes 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.192 UTC] [3980] [] LOG: automatic analyze of table "regression.pg_catalog.pg_class" 460s avg read rate: 0.000 MB/s, avg write rate: 5.208 MB/s 460s buffer usage: 556 hits, 0 misses, 4 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.193 UTC] [3980] [] LOG: automatic analyze of table "regression.pg_catalog.pg_attrdef" 460s avg read rate: 0.000 MB/s, avg write rate: 7.812 MB/s 460s buffer usage: 79 hits, 0 misses, 1 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.195 UTC] [3980] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_constraint": index scans: 1 460s pages: 0 removed, 5 remain, 5 scanned (100.00% of total) 460s tuples: 27 removed, 137 remain, 0 are dead but not yet removable 460s removable cutoff: 1422, which was 12 XIDs old when operation ended 460s new relfrozenxid: 794, which is 64 XIDs ahead of previous value 460s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 460s index scan needed: 3 pages from table (60.00% of total) had 109 dead item identifiers removed 460s index "pg_constraint_conparentid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 460s index "pg_constraint_conname_nsp_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 460s index "pg_constraint_conrelid_contypid_conname_index": pages: 4 in total, 0 newly deleted, 0 currently deleted, 0 reusable 460s index "pg_constraint_contypid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 460s index "pg_constraint_oid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 460s avg read rate: 0.000 MB/s, avg write rate: 28.935 MB/s 460s buffer usage: 106 hits, 0 misses, 9 dirtied 460s WAL usage: 19 records, 4 full page images, 26265 bytes 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.200 UTC] [3980] [] LOG: automatic analyze of table "regression.pg_catalog.pg_constraint" 460s avg read rate: 0.000 MB/s, avg write rate: 1.562 MB/s 460s buffer usage: 534 hits, 0 misses, 1 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.200 UTC] [3980] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_index": index scans: 1 460s pages: 0 removed, 6 remain, 6 scanned (100.00% of total) 460s tuples: 14 removed, 186 remain, 0 are dead but not yet removable 460s removable cutoff: 1422, which was 13 XIDs old when operation ended 460s new relfrozenxid: 794, which is 64 XIDs ahead of previous value 460s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 460s index scan needed: 6 pages from table (100.00% of total) had 138 dead item identifiers removed 460s index "pg_index_indrelid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 460s index "pg_index_indexrelid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 460s avg read rate: 0.000 MB/s, avg write rate: 685.307 MB/s 460s buffer usage: 40 hits, 0 misses, 10 dirtied 460s WAL usage: 18 records, 6 full page images, 43470 bytes 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.206 UTC] [3980] [] LOG: automatic analyze of table "regression.pg_catalog.pg_index" 460s avg read rate: 0.000 MB/s, avg write rate: 2.604 MB/s 460s buffer usage: 375 hits, 0 misses, 2 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.206 UTC] [3980] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_trigger": index scans: 1 460s pages: 0 removed, 2 remain, 2 scanned (100.00% of total) 460s tuples: 28 removed, 33 remain, 0 are dead but not yet removable 460s removable cutoff: 1422, which was 14 XIDs old when operation ended 460s new relfrozenxid: 794, which is 64 XIDs ahead of previous value 460s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 460s index scan needed: 2 pages from table (100.00% of total) had 139 dead item identifiers removed 460s index "pg_trigger_tgconstraint_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 460s index "pg_trigger_tgrelid_tgname_index": pages: 4 in total, 0 newly deleted, 0 currently deleted, 0 reusable 460s index "pg_trigger_oid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 460s avg read rate: 0.000 MB/s, avg write rate: 321.691 MB/s 460s buffer usage: 57 hits, 0 misses, 7 dirtied 460s WAL usage: 12 records, 4 full page images, 25522 bytes 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.209 UTC] [3980] [] LOG: automatic analyze of table "regression.pg_catalog.pg_trigger" 460s avg read rate: 0.000 MB/s, avg write rate: 1.953 MB/s 460s buffer usage: 233 hits, 0 misses, 1 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.217 UTC] [3980] [] LOG: automatic vacuum of table "regression.pg_catalog.pg_depend": index scans: 1 460s pages: 0 removed, 27 remain, 27 scanned (100.00% of total) 460s tuples: 702 removed, 2007 remain, 0 are dead but not yet removable 460s removable cutoff: 1422, which was 15 XIDs old when operation ended 460s new relfrozenxid: 794, which is 64 XIDs ahead of previous value 460s frozen: 4 pages from table (14.81% of total) had 176 tuples frozen 460s index scan needed: 16 pages from table (59.26% of total) had 1556 dead item identifiers removed 460s index "pg_depend_depender_index": pages: 20 in total, 2 newly deleted, 2 currently deleted, 0 reusable 460s index "pg_depend_reference_index": pages: 14 in total, 1 newly deleted, 1 currently deleted, 0 reusable 460s avg read rate: 0.000 MB/s, avg write rate: 35.576 MB/s 460s buffer usage: 179 hits, 0 misses, 35 dirtied 460s WAL usage: 71 records, 30 full page images, 90772 bytes 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.222 UTC] [3980] [] LOG: automatic analyze of table "regression.pg_catalog.pg_depend" 460s avg read rate: 0.000 MB/s, avg write rate: 1.562 MB/s 460s buffer usage: 133 hits, 0 misses, 1 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.222 UTC] [3980] [] LOG: automatic analyze of table "regression.pg_catalog.pg_shdepend" 460s avg read rate: 0.000 MB/s, avg write rate: 15.625 MB/s 460s buffer usage: 108 hits, 0 misses, 2 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.222 UTC] [3980] [] LOG: automatic analyze of table "regression.pg_catalog.pg_extension" 460s avg read rate: 0.000 MB/s, avg write rate: 15.625 MB/s 460s buffer usage: 128 hits, 0 misses, 2 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.222 UTC] [3980] [] LOG: automatic analyze of table "regression.pg_catalog.pg_sequence" 460s avg read rate: 0.000 MB/s, avg write rate: 7.812 MB/s 460s buffer usage: 133 hits, 0 misses, 1 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.222 UTC] [3980] [] LOG: automatic vacuum of table "regression.pglogical.sequence_state": index scans: 1 460s pages: 0 removed, 3 remain, 3 scanned (100.00% of total) 460s tuples: 31 removed, 1 remain, 0 are dead but not yet removable 460s removable cutoff: 1422, which was 19 XIDs old when operation ended 460s new relfrozenxid: 1422, which is 627 XIDs ahead of previous value 460s frozen: 1 pages from table (33.33% of total) had 1 tuples frozen 460s index scan needed: 2 pages from table (66.67% of total) had 2 dead item identifiers removed 460s index "sequence_state_pkey": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 460s avg read rate: 0.000 MB/s, avg write rate: 791.139 MB/s 460s buffer usage: 35 hits, 0 misses, 8 dirtied 460s WAL usage: 9 records, 5 full page images, 9325 bytes 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.225 UTC] [3980] [] LOG: automatic analyze of table "regression.pglogical.sequence_state" 460s avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s 460s buffer usage: 49 hits, 0 misses, 0 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.230 UTC] [3980] [] LOG: automatic analyze of table "regression.pglogical.queue" 460s avg read rate: 0.000 MB/s, avg write rate: 15.625 MB/s 460s buffer usage: 212 hits, 0 misses, 12 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.230 UTC] [3980] [] LOG: automatic vacuum of table "regression.pglogical.replication_set_table": index scans: 1 460s pages: 0 removed, 1 remain, 1 scanned (100.00% of total) 460s tuples: 12 removed, 1 remain, 0 are dead but not yet removable 460s removable cutoff: 1422, which was 21 XIDs old when operation ended 460s new relfrozenxid: 1422, which is 628 XIDs ahead of previous value 460s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 460s index scan needed: 1 pages from table (100.00% of total) had 57 dead item identifiers removed 460s index "replication_set_table_pkey": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable 460s avg read rate: 0.000 MB/s, avg write rate: 203.804 MB/s 460s buffer usage: 31 hits, 0 misses, 3 dirtied 460s WAL usage: 5 records, 0 full page images, 825 bytes 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.230 UTC] [3980] [] LOG: automatic analyze of table "regression.pglogical.replication_set_table" 460s avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s 460s buffer usage: 109 hits, 0 misses, 0 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.231 UTC] [3980] [] LOG: automatic vacuum of table "regression.pglogical.depend": index scans: 0 460s pages: 0 removed, 1 remain, 1 scanned (100.00% of total) 460s tuples: 101 removed, 2 remain, 0 are dead but not yet removable 460s removable cutoff: 1422, which was 22 XIDs old when operation ended 460s new relfrozenxid: 1170, which is 375 XIDs ahead of previous value 460s frozen: 0 pages from table (0.00% of total) had 0 tuples frozen 460s index scan not needed: 0 pages from table (0.00% of total) had 0 dead item identifiers removed 460s avg read rate: 0.000 MB/s, avg write rate: 300.481 MB/s 460s buffer usage: 9 hits, 0 misses, 3 dirtied 460s WAL usage: 2 records, 0 full page images, 493 bytes 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:55.231 UTC] [3980] [] LOG: automatic analyze of table "regression.pglogical.depend" 460s avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s 460s buffer usage: 66 hits, 0 misses, 0 dirtied 460s system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 460s [2025-02-22 06:49:57.354 UTC] [3973] [postgres] LOG: apply worker [3973] at slot 2 generation 28 detaching cleanly 460s [2025-02-22 06:49:58.356 UTC] [3477] [postgres] LOG: process 3477 still waiting for ShareUpdateExclusiveLock on relation 17336 of database 5 after 1000.064 ms 460s [2025-02-22 06:49:58.356 UTC] [3477] [postgres] DETAIL: Process holding the lock: 3981. Wait queue: 3477. 460s [2025-02-22 06:49:58.362 UTC] [3477] [postgres] LOG: process 3477 acquired ShareUpdateExclusiveLock on relation 17336 of database 5 after 1005.462 ms 460s [2025-02-22 06:49:58.363 UTC] [3983] [template1] LOG: manager worker [3983] at slot 2 generation 29 detaching cleanly 460s [2025-02-22 06:49:58.366 UTC] [3985] [regression1] LOG: manager worker [3985] at slot 2 generation 30 detaching cleanly 460s [2025-02-22 06:49:58.370 UTC] [3986] [sourcedb] LOG: manager worker [3986] at slot 2 generation 31 detaching cleanly 460s [2025-02-22 06:49:58.402 UTC] [3996] [template1] LOG: manager worker [3996] at slot 2 generation 32 detaching cleanly 460s [2025-02-22 06:49:58.406 UTC] [3999] [sourcedb] LOG: starting pglogical database manager for database sourcedb 460s [2025-02-22 06:49:58.406 UTC] [3998] [regression1] LOG: manager worker [3998] at slot 2 generation 33 detaching cleanly 460s [2025-02-22 06:49:58.410 UTC] [4002] [template1] LOG: manager worker [4002] at slot 5 generation 3 detaching cleanly 460s [2025-02-22 06:49:58.411 UTC] [4003] [regression] LOG: starting apply for subscription test_orig_subscription 460s [2025-02-22 06:49:58.412 UTC] [4004] [regression1] LOG: manager worker [4004] at slot 5 generation 4 detaching cleanly 460s [2025-02-22 06:49:58.414 UTC] [4006] [sourcedb] LOG: logical decoding found consistent point at 0/2B39B90 460s [2025-02-22 06:49:58.414 UTC] [4006] [sourcedb] DETAIL: There are no running transactions. 460s [2025-02-22 06:49:58.414 UTC] [4006] [sourcedb] STATEMENT: CREATE_REPLICATION_SLOT "pgl_regression_test_orib5a0b8b_test_ori670a399" LOGICAL pglogical_output 460s [2025-02-22 06:49:58.414 UTC] [4006] [sourcedb] LOG: exported logical decoding snapshot: "00000081-00000003-1" with 0 transaction IDs 460s [2025-02-22 06:49:58.414 UTC] [4006] [sourcedb] STATEMENT: CREATE_REPLICATION_SLOT "pgl_regression_test_orib5a0b8b_test_ori670a399" LOGICAL pglogical_output 460s [2025-02-22 06:49:58.424 UTC] [4009] [sourcedb] LOG: starting logical decoding for slot "pgl_regression_test_orib5a0b8b_test_ori670a399" 460s [2025-02-22 06:49:58.424 UTC] [4009] [sourcedb] DETAIL: Streaming transactions committing after 0/2B39BC8, reading WAL from 0/2B39B90. 460s [2025-02-22 06:49:58.424 UTC] [4009] [sourcedb] STATEMENT: START_REPLICATION SLOT "pgl_regression_test_orib5a0b8b_test_ori670a399" LOGICAL 0/2B39BC8 (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 '4003') 460s [2025-02-22 06:49:58.424 UTC] [4009] [sourcedb] LOG: logical decoding found consistent point at 0/2B39B90 460s [2025-02-22 06:49:58.424 UTC] [4009] [sourcedb] DETAIL: There are no running transactions. 460s [2025-02-22 06:49:58.424 UTC] [4009] [sourcedb] STATEMENT: START_REPLICATION SLOT "pgl_regression_test_orib5a0b8b_test_ori670a399" LOGICAL 0/2B39BC8 (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 '4003') 460s [2025-02-22 06:50:00.645 UTC] [4003] [regression] LOG: apply worker [4003] at slot 2 generation 34 detaching cleanly 460s [2025-02-22 06:50:00.650 UTC] [4018] [template1] LOG: manager worker [4018] at slot 2 generation 35 detaching cleanly 460s [2025-02-22 06:50:00.652 UTC] [4020] [regression1] LOG: manager worker [4020] at slot 2 generation 36 detaching cleanly 460s [2025-02-22 06:50:00.653 UTC] [3999] [sourcedb] LOG: manager worker [3999] at slot 4 generation 11 detaching cleanly 460s [2025-02-22 06:50:00.654 UTC] [4021] [template1] LOG: manager worker [4021] at slot 2 generation 37 detaching cleanly 460s [2025-02-22 06:50:00.656 UTC] [4022] [regression1] LOG: manager worker [4022] at slot 2 generation 38 detaching cleanly 460s [2025-02-22 06:50:00.658 UTC] [4024] [sourcedb] LOG: starting pglogical database manager for database sourcedb 460s [2025-02-22 06:50:00.658 UTC] [4024] [sourcedb] LOG: manager worker [4024] at slot 2 generation 39 detaching cleanly 460s [2025-02-22 06:50:00.666 UTC] [4030] [regression] ERROR: cannot drop node "test_provider" because one or more replication slots for the node are still active 460s [2025-02-22 06:50:00.666 UTC] [4030] [regression] HINT: drop the subscriptions connected to the node first 460s [2025-02-22 06:50:00.666 UTC] [4030] [regression] STATEMENT: SELECT * FROM pglogical.drop_node(node_name := 'test_provider'); 460s [2025-02-22 06:50:00.671 UTC] [3785] [postgres] LOG: apply worker [3785] at slot 3 generation 4 detaching cleanly 460s [2025-02-22 06:50:01.672 UTC] [3477] [postgres] LOG: process 3477 still waiting for ShareUpdateExclusiveLock on relation 17336 of database 5 after 1000.071 ms 460s [2025-02-22 06:50:01.672 UTC] [3477] [postgres] DETAIL: Process holding the lock: 4031. Wait queue: 3477. 460s [2025-02-22 06:50:01.676 UTC] [3477] [postgres] LOG: process 3477 acquired ShareUpdateExclusiveLock on relation 17336 of database 5 after 1003.437 ms 460s [2025-02-22 06:50:01.677 UTC] [4033] [template1] LOG: manager worker [4033] at slot 2 generation 40 detaching cleanly 460s [2025-02-22 06:50:01.678 UTC] [3477] [postgres] LOG: manager worker [3477] at slot 1 generation 11 detaching cleanly 460s [2025-02-22 06:50:01.680 UTC] [4035] [regression1] LOG: manager worker [4035] at slot 1 generation 12 detaching cleanly 460s [2025-02-22 06:50:01.682 UTC] [3474] [regression] LOG: manager worker [3474] at slot 0 generation 9 detaching cleanly 460s [2025-02-22 06:50:01.682 UTC] [4036] [sourcedb] LOG: starting pglogical database manager for database sourcedb 460s [2025-02-22 06:50:01.683 UTC] [4036] [sourcedb] LOG: manager worker [4036] at slot 1 generation 13 detaching cleanly 460s [2025-02-22 06:50:01.684 UTC] [4037] [postgres] LOG: starting pglogical database manager for database postgres 460s [2025-02-22 06:50:01.685 UTC] [4037] [postgres] LOG: manager worker [4037] at slot 0 generation 10 detaching cleanly 460s [2025-02-22 06:50:01.686 UTC] [4038] [template1] LOG: manager worker [4038] at slot 0 generation 11 detaching cleanly 460s [2025-02-22 06:50:01.689 UTC] [4040] [regression] LOG: starting pglogical database manager for database regression 460s [2025-02-22 06:50:01.689 UTC] [4040] [regression] LOG: manager worker [4040] at slot 0 generation 12 detaching cleanly 460s [2025-02-22 06:50:01.692 UTC] [4043] [regression1] LOG: manager worker [4043] at slot 0 generation 13 detaching cleanly 460s [2025-02-22 06:50:01.694 UTC] [4045] [sourcedb] LOG: starting pglogical database manager for database sourcedb 460s [2025-02-22 06:50:01.695 UTC] [4045] [sourcedb] LOG: manager worker [4045] at slot 0 generation 14 detaching cleanly 460s [2025-02-22 06:50:01.706 UTC] [3407] [] LOG: received fast shutdown request 460s [2025-02-22 06:50:01.706 UTC] [3407] [] LOG: aborting any active transactions 460s [2025-02-22 06:50:01.708 UTC] [3407] [] LOG: background worker "logical replication launcher" (PID 3414) exited with exit code 1 460s [2025-02-22 06:50:01.711 UTC] [3408] [] LOG: checkpoint complete: wrote 208 buffers (1.3%); 0 WAL file(s) added, 0 removed, 0 recycled; write=11.759 s, sync=0.001 s, total=11.760 s; sync files=0, longest=0.000 s, average=0.000 s; distance=1165 kB, estimate=15688 kB; lsn=0/2B6F4C8, redo lsn=0/29429C8 460s [2025-02-22 06:50:01.711 UTC] [3408] [] LOG: shutting down 460s [2025-02-22 06:50:01.711 UTC] [3408] [] LOG: checkpoint starting: shutdown immediate 460s [2025-02-22 06:50:01.714 UTC] [3408] [] LOG: checkpoint complete: wrote 451 buffers (2.8%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.003 s, sync=0.001 s, total=0.003 s; sync files=0, longest=0.000 s, average=0.000 s; distance=2226 kB, estimate=14342 kB; lsn=0/2B6F540, redo lsn=0/2B6F540 460s [2025-02-22 06:50:01.721 UTC] [3407] [] LOG: database system is shut down 460s autopkgtest [06:50:02]: test regresscheck: -----------------------] 460s autopkgtest [06:50:02]: test regresscheck: - - - - - - - - - - results - - - - - - - - - - 460s regresscheck FLAKY non-zero exit status 1 461s autopkgtest [06:50:03]: @@@@@@@@@@@@@@@@@@@@ summary 461s prove PASS 461s regresscheck FLAKY non-zero exit status 1 466s nova [W] Using flock in prodstack6-s390x 466s Creating nova instance adt-plucky-s390x-pglogical-20250222-064222-juju-7f2275-prod-proposed-migration-environment-2-f07dcd74-686f-4946-a6ae-3b5fef36906a from image adt/ubuntu-plucky-s390x-server-20250222.img (UUID ae633cda-0dee-481c-9805-d0ef3f3b5166)... 466s nova [W] Timed out waiting for d9336c78-02bf-42d2-9628-b2068645d097 to get deleted. 466s nova [W] Using flock in prodstack6-s390x 466s Creating nova instance adt-plucky-s390x-pglogical-20250222-064222-juju-7f2275-prod-proposed-migration-environment-2-f07dcd74-686f-4946-a6ae-3b5fef36906a from image adt/ubuntu-plucky-s390x-server-20250222.img (UUID ae633cda-0dee-481c-9805-d0ef3f3b5166)... 466s nova [W] Timed out waiting for b2a2053e-060f-4a38-aeeb-0a4bbdec8db0 to get deleted.