0s autopkgtest [19:41:31]: starting date and time: 2025-03-15 19:41:31+0000 0s autopkgtest [19:41:31]: git checkout: 325255d2 Merge branch 'pin-any-arch' into 'ubuntu/production' 0s autopkgtest [19:41:31]: host juju-7f2275-prod-proposed-migration-environment-20; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.7z8_5xbp/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:glibc --apt-upgrade vip-manager --timeout-short=300 --timeout-copy=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=glibc/2.41-1ubuntu2 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-s390x --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-20@bos03-s390x-18.secgroup --name adt-plucky-s390x-vip-manager-20250315-194130-juju-7f2275-prod-proposed-migration-environment-20-097dba5f-20db-460c-b3a2-4e9dbd9f8186 --image adt/ubuntu-plucky-s390x-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-20 --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/ 113s autopkgtest [19:43:24]: testbed dpkg architecture: s390x 113s autopkgtest [19:43:24]: testbed apt version: 2.9.33 114s autopkgtest [19:43:25]: @@@@@@@@@@@@@@@@@@@@ test bed setup 114s autopkgtest [19:43:25]: testbed release detected to be: None 115s autopkgtest [19:43:26]: updating testbed package index (apt update) 115s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [126 kB] 115s Hit:2 http://ftpmaster.internal/ubuntu plucky InRelease 115s Hit:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease 115s Hit:4 http://ftpmaster.internal/ubuntu plucky-security InRelease 115s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [369 kB] 116s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [14.5 kB] 116s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [45.1 kB] 116s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x Packages [77.3 kB] 116s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x c-n-f Metadata [1824 B] 116s Get:10 http://ftpmaster.internal/ubuntu plucky-proposed/restricted s390x c-n-f Metadata [116 B] 116s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/universe s390x Packages [314 kB] 116s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/universe s390x c-n-f Metadata [13.3 kB] 116s Get:13 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse s390x Packages [3532 B] 116s Get:14 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse s390x c-n-f Metadata [240 B] 116s Fetched 965 kB in 1s (1068 kB/s) 116s Reading package lists... 117s Reading package lists... 117s Building dependency tree... 117s Reading state information... 117s Calculating upgrade... 117s Calculating upgrade... 117s The following packages were automatically installed and are no longer required: 117s libnsl2 libpython3.12-minimal libpython3.12-stdlib libpython3.12t64 117s linux-headers-6.11.0-8 linux-headers-6.11.0-8-generic 117s linux-modules-6.11.0-8-generic linux-tools-6.11.0-8 117s linux-tools-6.11.0-8-generic 117s Use 'sudo apt autoremove' to remove them. 117s The following packages will be upgraded: 117s pinentry-curses python3-jinja2 strace 118s 3 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 118s Need to get 652 kB of archives. 118s After this operation, 27.6 kB of additional disk space will be used. 118s Get:1 http://ftpmaster.internal/ubuntu plucky/main s390x strace s390x 6.13+ds-1ubuntu1 [500 kB] 118s Get:2 http://ftpmaster.internal/ubuntu plucky/main s390x pinentry-curses s390x 1.3.1-2ubuntu3 [42.9 kB] 118s Get:3 http://ftpmaster.internal/ubuntu plucky/main s390x python3-jinja2 all 3.1.5-2ubuntu1 [109 kB] 118s Fetched 652 kB in 1s (982 kB/s) 118s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 81428 files and directories currently installed.) 118s Preparing to unpack .../strace_6.13+ds-1ubuntu1_s390x.deb ... 118s Unpacking strace (6.13+ds-1ubuntu1) over (6.11-0ubuntu1) ... 118s Preparing to unpack .../pinentry-curses_1.3.1-2ubuntu3_s390x.deb ... 118s Unpacking pinentry-curses (1.3.1-2ubuntu3) over (1.3.1-2ubuntu2) ... 118s Preparing to unpack .../python3-jinja2_3.1.5-2ubuntu1_all.deb ... 118s Unpacking python3-jinja2 (3.1.5-2ubuntu1) over (3.1.5-2) ... 118s Setting up pinentry-curses (1.3.1-2ubuntu3) ... 119s Setting up python3-jinja2 (3.1.5-2ubuntu1) ... 119s Setting up strace (6.13+ds-1ubuntu1) ... 119s Processing triggers for man-db (2.13.0-1) ... 119s Reading package lists... 119s Building dependency tree... 119s Reading state information... 119s Solving dependencies... 120s The following packages will be REMOVED: 120s libnsl2* libpython3.12-minimal* libpython3.12-stdlib* libpython3.12t64* 120s linux-headers-6.11.0-8* linux-headers-6.11.0-8-generic* 120s linux-modules-6.11.0-8-generic* linux-tools-6.11.0-8* 120s linux-tools-6.11.0-8-generic* 120s 0 upgraded, 0 newly installed, 9 to remove and 5 not upgraded. 120s After this operation, 167 MB disk space will be freed. 120s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 81428 files and directories currently installed.) 120s Removing linux-tools-6.11.0-8-generic (6.11.0-8.8) ... 120s Removing linux-tools-6.11.0-8 (6.11.0-8.8) ... 120s Removing libpython3.12t64:s390x (3.12.9-1) ... 120s Removing libpython3.12-stdlib:s390x (3.12.9-1) ... 120s Removing libnsl2:s390x (1.3.0-3build3) ... 120s Removing libpython3.12-minimal:s390x (3.12.9-1) ... 120s Removing linux-headers-6.11.0-8-generic (6.11.0-8.8) ... 120s Removing linux-headers-6.11.0-8 (6.11.0-8.8) ... 121s Removing linux-modules-6.11.0-8-generic (6.11.0-8.8) ... 121s Processing triggers for libc-bin (2.41-1ubuntu1) ... 121s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 56328 files and directories currently installed.) 121s Purging configuration files for libpython3.12-minimal:s390x (3.12.9-1) ... 121s Purging configuration files for linux-modules-6.11.0-8-generic (6.11.0-8.8) ... 121s autopkgtest [19:43:32]: upgrading testbed (apt dist-upgrade and autopurge) 121s Reading package lists... 121s Building dependency tree... 121s Reading state information... 122s Calculating upgrade...Starting pkgProblemResolver with broken count: 0 122s Starting 2 pkgProblemResolver with broken count: 0 122s Done 122s Entering ResolveByKeep 122s 122s Calculating upgrade... 122s The following packages will be upgraded: 122s libc-bin libc-dev-bin libc6 libc6-dev locales 122s 5 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 122s Need to get 9512 kB of archives. 122s After this operation, 8192 B of additional disk space will be used. 122s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libc6-dev s390x 2.41-1ubuntu2 [1678 kB] 123s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libc-dev-bin s390x 2.41-1ubuntu2 [24.3 kB] 123s Get:3 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libc6 s390x 2.41-1ubuntu2 [2892 kB] 123s Get:4 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libc-bin s390x 2.41-1ubuntu2 [671 kB] 124s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x locales all 2.41-1ubuntu2 [4246 kB] 125s Preconfiguring packages ... 125s Fetched 9512 kB in 2s (4290 kB/s) 125s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 56326 files and directories currently installed.) 125s Preparing to unpack .../libc6-dev_2.41-1ubuntu2_s390x.deb ... 125s Unpacking libc6-dev:s390x (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 125s Preparing to unpack .../libc-dev-bin_2.41-1ubuntu2_s390x.deb ... 125s Unpacking libc-dev-bin (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 125s Preparing to unpack .../libc6_2.41-1ubuntu2_s390x.deb ... 125s Unpacking libc6:s390x (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 125s Setting up libc6:s390x (2.41-1ubuntu2) ... 125s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 56326 files and directories currently installed.) 125s Preparing to unpack .../libc-bin_2.41-1ubuntu2_s390x.deb ... 125s Unpacking libc-bin (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 125s Setting up libc-bin (2.41-1ubuntu2) ... 125s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 56326 files and directories currently installed.) 125s Preparing to unpack .../locales_2.41-1ubuntu2_all.deb ... 125s Unpacking locales (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 125s Setting up locales (2.41-1ubuntu2) ... 125s Generating locales (this might take a while)... 126s en_US.UTF-8... done 126s Generation complete. 126s Setting up libc-dev-bin (2.41-1ubuntu2) ... 126s Setting up libc6-dev:s390x (2.41-1ubuntu2) ... 126s Processing triggers for man-db (2.13.0-1) ... 127s Processing triggers for systemd (257.3-1ubuntu3) ... 128s Reading package lists... 128s Building dependency tree... 128s Reading state information... 128s Starting pkgProblemResolver with broken count: 0 128s Starting 2 pkgProblemResolver with broken count: 0 128s Done 128s Solving dependencies... 128s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 128s autopkgtest [19:43:39]: rebooting testbed after setup commands that affected boot 148s autopkgtest [19:43:59]: testbed running kernel: Linux 6.14.0-10-generic #10-Ubuntu SMP Wed Mar 12 14:53:49 UTC 2025 150s autopkgtest [19:44:01]: @@@@@@@@@@@@@@@@@@@@ apt-source vip-manager 151s Get:1 http://ftpmaster.internal/ubuntu plucky/universe vip-manager 1.0.2-9 (dsc) [2473 B] 151s Get:2 http://ftpmaster.internal/ubuntu plucky/universe vip-manager 1.0.2-9 (tar) [69.9 kB] 151s Get:3 http://ftpmaster.internal/ubuntu plucky/universe vip-manager 1.0.2-9 (diff) [9432 B] 151s gpgv: Signature made Fri Aug 23 16:57:11 2024 UTC 151s gpgv: using RSA key 5C48FE6157F49179597087C64C5A6BAB12D2A7AE 151s gpgv: Can't check signature: No public key 151s dpkg-source: warning: cannot verify inline signature for ./vip-manager_1.0.2-9.dsc: no acceptable signature found 152s autopkgtest [19:44:03]: testing package vip-manager version 1.0.2-9 152s autopkgtest [19:44:03]: build not needed 152s autopkgtest [19:44:03]: test test: preparing testbed 152s Reading package lists... 153s Building dependency tree... 153s Reading state information... 153s Starting pkgProblemResolver with broken count: 0 153s Starting 2 pkgProblemResolver with broken count: 0 153s Done 153s The following NEW packages will be installed: 153s etcd-server liblua5.4-0 ncat vip-manager 153s 0 upgraded, 4 newly installed, 0 to remove and 0 not upgraded. 153s Need to get 14.5 MB of archives. 153s After this operation, 54.5 MB of additional disk space will be used. 153s Get:1 http://ftpmaster.internal/ubuntu plucky/universe s390x etcd-server s390x 3.5.16-4 [11.6 MB] 156s Get:2 http://ftpmaster.internal/ubuntu plucky/main s390x liblua5.4-0 s390x 5.4.7-1 [174 kB] 156s Get:3 http://ftpmaster.internal/ubuntu plucky/universe s390x ncat s390x 7.95+dfsg-2 [215 kB] 156s Get:4 http://ftpmaster.internal/ubuntu plucky/universe s390x vip-manager s390x 1.0.2-9 [2552 kB] 157s Fetched 14.5 MB in 4s (3451 kB/s) 157s Selecting previously unselected package etcd-server. 157s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 56326 files and directories currently installed.) 157s Preparing to unpack .../etcd-server_3.5.16-4_s390x.deb ... 157s Unpacking etcd-server (3.5.16-4) ... 158s Selecting previously unselected package liblua5.4-0:s390x. 158s Preparing to unpack .../liblua5.4-0_5.4.7-1_s390x.deb ... 158s Unpacking liblua5.4-0:s390x (5.4.7-1) ... 158s Selecting previously unselected package ncat. 158s Preparing to unpack .../ncat_7.95+dfsg-2_s390x.deb ... 158s Unpacking ncat (7.95+dfsg-2) ... 158s Selecting previously unselected package vip-manager. 158s Preparing to unpack .../vip-manager_1.0.2-9_s390x.deb ... 158s Unpacking vip-manager (1.0.2-9) ... 158s Setting up liblua5.4-0:s390x (5.4.7-1) ... 158s Setting up etcd-server (3.5.16-4) ... 158s info: Selecting UID from range 100 to 999 ... 158s 158s info: Selecting GID from range 100 to 999 ... 158s info: Adding system user `etcd' (UID 107) ... 158s info: Adding new group `etcd' (GID 110) ... 158s info: Adding new user `etcd' (UID 107) with group `etcd' ... 158s info: Creating home directory `/var/lib/etcd/' ... 158s Created symlink '/etc/systemd/system/etcd2.service' → '/usr/lib/systemd/system/etcd.service'. 158s Created symlink '/etc/systemd/system/multi-user.target.wants/etcd.service' → '/usr/lib/systemd/system/etcd.service'. 158s Setting up vip-manager (1.0.2-9) ... 159s Created symlink '/etc/systemd/system/multi-user.target.wants/vip-manager.service' → '/usr/lib/systemd/system/vip-manager.service'. 159s Setting up ncat (7.95+dfsg-2) ... 159s Processing triggers for man-db (2.13.0-1) ... 159s Processing triggers for libc-bin (2.41-1ubuntu2) ... 160s autopkgtest [19:44:11]: test test: [----------------------- 161s ○ etcd.service - etcd - highly-available key value store 161s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 161s Active: inactive (dead) since Sat 2025-03-15 19:45:37 UTC; 8ms ago 161s Duration: 2.282s 161s Invocation: 2dddd0550e214efab988d4be7f5493da 161s Docs: https://etcd.io/docs 161s man:etcd 161s Process: 1423 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 161s Main PID: 1423 (code=killed, signal=TERM) 161s Mem peak: 8.3M 161s CPU: 29ms 161s 161s Mar 15 19:45:37 autopkgtest etcd[1423]: {"level":"info","ts":"2025-03-15T19:45:37.713384Z","caller":"embed/etcd.go:378","msg":"closing etcd server","name":"autopkgtest","data-dir":"/var/lib/etcd/default","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["http://localhost:2379"]} 161s Mar 15 19:45:37 autopkgtest etcd[1423]: {"level":"warn","ts":"2025-03-15T19:45:37.713543Z","caller":"embed/serve.go:161","msg":"stopping insecure grpc server due to error","error":"accept tcp 127.0.0.1:2379: use of closed network connection"} 161s Mar 15 19:45:37 autopkgtest etcd[1423]: {"level":"warn","ts":"2025-03-15T19:45:37.713808Z","caller":"embed/serve.go:163","msg":"stopped insecure grpc server due to error","error":"accept tcp 127.0.0.1:2379: use of closed network connection"} 161s Mar 15 19:45:37 autopkgtest etcd[1423]: {"level":"info","ts":"2025-03-15T19:45:37.713846Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 161s Mar 15 19:45:37 autopkgtest systemd[1]: Stopping etcd.service - etcd - highly-available key value store... 161s Mar 15 19:45:37 autopkgtest etcd[1423]: {"level":"info","ts":"2025-03-15T19:45:37.714929Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 161s Mar 15 19:45:37 autopkgtest etcd[1423]: {"level":"info","ts":"2025-03-15T19:45:37.715000Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 161s Mar 15 19:45:37 autopkgtest etcd[1423]: {"level":"info","ts":"2025-03-15T19:45:37.715025Z","caller":"embed/etcd.go:380","msg":"closed etcd server","name":"autopkgtest","data-dir":"/var/lib/etcd/default","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["http://localhost:2379"]} 161s Mar 15 19:45:37 autopkgtest systemd[1]: etcd.service: Deactivated successfully. 161s Mar 15 19:45:37 autopkgtest systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 161s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 161s {"level":"warn","ts":"2025-03-15T19:45:37.765596Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_UNSUPPORTED_ARCH=s390x"} 161s {"level":"warn","ts":"2025-03-15T19:45:37.765685Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 161s {"level":"info","ts":"2025-03-15T19:45:37.765699Z","caller":"etcdmain/etcd.go:73","msg":"Running: ","args":["etcd","--enable-v2"]} 161s {"level":"warn","ts":"2025-03-15T19:45:37.765712Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 161s {"level":"warn","ts":"2025-03-15T19:45:37.765727Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 161s {"level":"info","ts":"2025-03-15T19:45:37.765738Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 161s {"level":"info","ts":"2025-03-15T19:45:37.766119Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["http://localhost:2379"]} 161s {"level":"info","ts":"2025-03-15T19:45:37.766225Z","caller":"embed/etcd.go:311","msg":"starting an etcd server","etcd-version":"3.5.16","git-sha":"Not provided (use ./build instead of go build)","go-version":"go1.24.1","go-os":"linux","go-arch":"s390x","max-cpu-set":2,"max-cpu-available":2,"member-initialized":false,"name":"default","data-dir":"default.etcd","wal-dir":"","wal-dir-dedicated":"","member-dir":"default.etcd/member","force-new-cluster":false,"heartbeat-interval":"100ms","election-timeout":"1s","initial-election-tick-advance":true,"snapshot-count":100000,"max-wals":5,"max-snapshots":5,"snapshot-catchup-entries":5000,"initial-advertise-peer-urls":["http://localhost:2380"],"listen-peer-urls":["http://localhost:2380"],"advertise-client-urls":["http://localhost:2379"],"listen-client-urls":["http://localhost:2379"],"listen-metrics-urls":[],"cors":["*"],"host-whitelist":["*"],"initial-cluster":"default=http://localhost:2380","initial-cluster-state":"new","initial-cluster-token":"etcd-cluster","quota-backend-bytes":2147483648,"max-request-bytes":1572864,"max-concurrent-streams":4294967295,"pre-vote":true,"initial-corrupt-check":false,"corrupt-check-time-interval":"0s","compact-check-time-enabled":false,"compact-check-time-interval":"1m0s","auto-compaction-mode":"periodic","auto-compaction-retention":"0s","auto-compaction-interval":"0s","discovery-url":"","discovery-proxy":"","downgrade-check-interval":"5s"} 161s {"level":"info","ts":"2025-03-15T19:45:37.768339Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"1.910619ms"} 161s {"level":"info","ts":"2025-03-15T19:45:37.772036Z","caller":"etcdserver/raft.go:505","msg":"starting local member","local-member-id":"8e9e05c52164694d","cluster-id":"cdf818194e3a8c32"} 161s {"level":"info","ts":"2025-03-15T19:45:37.772111Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 161s {"level":"info","ts":"2025-03-15T19:45:37.772138Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 0"} 161s {"level":"info","ts":"2025-03-15T19:45:37.772170Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]"} 161s {"level":"info","ts":"2025-03-15T19:45:37.772215Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 1"} 161s {"level":"info","ts":"2025-03-15T19:45:37.772259Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 161s {"level":"warn","ts":"2025-03-15T19:45:37.773581Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 161s {"level":"info","ts":"2025-03-15T19:45:37.774657Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":1} 161s {"level":"info","ts":"2025-03-15T19:45:37.775122Z","caller":"etcdserver/quota.go:94","msg":"enabled backend quota with default value","quota-name":"v3-applier","quota-size-bytes":2147483648,"quota-size":"2.1 GB"} 161s {"level":"info","ts":"2025-03-15T19:45:37.775478Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 161s {"level":"info","ts":"2025-03-15T19:45:37.775565Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 161s {"level":"info","ts":"2025-03-15T19:45:37.775831Z","caller":"etcdserver/server.go:757","msg":"started as single-node; fast-forwarding election ticks","local-member-id":"8e9e05c52164694d","forward-ticks":9,"forward-duration":"900ms","election-ticks":10,"election-timeout":"1s"} 161s {"level":"info","ts":"2025-03-15T19:45:37.775970Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 161s {"level":"info","ts":"2025-03-15T19:45:37.776006Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 161s {"level":"info","ts":"2025-03-15T19:45:37.776023Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 161s {"level":"info","ts":"2025-03-15T19:45:37.776170Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 161s {"level":"info","ts":"2025-03-15T19:45:37.776232Z","caller":"membership/cluster.go:421","msg":"added member","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","added-peer-id":"8e9e05c52164694d","added-peer-peer-urls":["http://localhost:2380"]} 161s {"level":"warn","ts":"2025-03-15T19:45:37.778392Z","caller":"embed/etcd.go:742","msg":"Flag `enable-v2` is deprecated and will get removed in etcd 3.6."} 161s {"level":"info","ts":"2025-03-15T19:45:37.778512Z","caller":"embed/etcd.go:280","msg":"now serving peer/client/metrics","local-member-id":"8e9e05c52164694d","initial-advertise-peer-urls":["http://localhost:2380"],"listen-peer-urls":["http://localhost:2380"],"advertise-client-urls":["http://localhost:2379"],"listen-client-urls":["http://localhost:2379"],"listen-metrics-urls":[]} 161s {"level":"info","ts":"2025-03-15T19:45:37.778549Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 161s {"level":"info","ts":"2025-03-15T19:45:37.778564Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 161s {"level":"info","ts":"2025-03-15T19:45:38.272402Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 1"} 161s {"level":"info","ts":"2025-03-15T19:45:38.272491Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 1"} 161s {"level":"info","ts":"2025-03-15T19:45:38.272545Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 1"} 161s {"level":"info","ts":"2025-03-15T19:45:38.272561Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 2"} 161s {"level":"info","ts":"2025-03-15T19:45:38.272566Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 2"} 161s {"level":"info","ts":"2025-03-15T19:45:38.272576Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 2"} 161s {"level":"info","ts":"2025-03-15T19:45:38.272583Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 2"} 161s {"level":"info","ts":"2025-03-15T19:45:38.273135Z","caller":"etcdserver/server.go:2140","msg":"published local member to cluster through raft","local-member-id":"8e9e05c52164694d","local-member-attributes":"{Name:default ClientURLs:[http://localhost:2379]}","request-path":"/0/members/8e9e05c52164694d/attributes","cluster-id":"cdf818194e3a8c32","publish-timeout":"7s"} 161s {"level":"info","ts":"2025-03-15T19:45:38.273143Z","caller":"etcdserver/server.go:2651","msg":"setting up initial cluster version using v2 API","cluster-version":"3.5"} 161s {"level":"info","ts":"2025-03-15T19:45:38.273329Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 161s {"level":"info","ts":"2025-03-15T19:45:38.273475Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 161s {"level":"info","ts":"2025-03-15T19:45:38.273486Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 161s {"level":"info","ts":"2025-03-15T19:45:38.273498Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 161s {"level":"info","ts":"2025-03-15T19:45:38.273529Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 161s {"level":"info","ts":"2025-03-15T19:45:38.273544Z","caller":"etcdserver/server.go:2675","msg":"cluster version is updated","cluster-version":"3.5"} 161s {"level":"info","ts":"2025-03-15T19:45:38.273887Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 161s {"level":"info","ts":"2025-03-15T19:45:38.274308Z","caller":"embed/serve.go:188","msg":"serving client traffic insecurely; this is strongly discouraged!","traffic":"grpc+http","address":"127.0.0.1:2379"} 163s Ncat: Version 7.95 ( https://nmap.org/ncat ) 163s Ncat: Listening on 0.0.0.0:12345 163s {"errorCode":100,"message":"Key not found","cause":"/service","index":3} 163s 2025/03/15 19:45:39 No dcs-endpoints specified, trying to use localhost with standard ports! 163s 2025/03/15 19:45:39 This is the config that will be used: 163s 2025/03/15 19:45:39 IP address 10.0.2.123/32 state is false, desired false 163s 2025/03/15 19:45:39 etcd error: 100: Key not found (/service) [3] 163s dcs-endpoints : [http://127.0.0.1:2379] 163s dcs-type : etcd 163s hostingtype : basic 163s interface : enc1 163s interval : 1000 163s ip : 10.0.2.123 163s manager-type : basic 163s netmask : 32 163s retry-after : 250 163s retry-num : 3 163s trigger-key : service/pgcluster/leader 163s trigger-value : autopkgtest 163s verbose : false 163s version : false 164s 2025/03/15 19:45:40 etcd error: 100: Key not found (/service) [3] 166s 2025/03/15 19:45:41 etcd error: 100: Key not found (/service) [3] 166s { 166s "action": "set", 166s "node": { 166s "key": "/service/pgcluster/leader", 166s "value": "autopkgtest", 166s "modifiedIndex": 4, 166s "createdIndex": 4 166s } 166s } 166s 2025/03/15 19:45:42 IP address 10.0.2.123/32 state is false, desired true 166s 2025/03/15 19:45:42 Configuring address 10.0.2.123/32 on enc1 166s 2025/03/15 19:45:42 Sent gratuitous ARP reply 166s 2025/03/15 19:45:42 Sent gratuitous ARP request 166s 2025/03/15 19:45:42 IP address 10.0.2.123/32 state is true, desired true 167s inet 10.0.2.123/32 scope global enc1 167s Ncat: Version 7.95 ( https://nmap.org/ncat ) 167s Ncat: Connected to 10.0.2.123:12345. 167s Ncat: Ncat: 0 bytes sent, 0 bytes received in 0.02 seconds. 167s Connection from 10.0.2.123:53276. 167s { 167s "action": "set", 167s "node": { 167s "key": "/service/pgcluster/leader", 167s "value": "0xGARBAGE", 167s "modifiedIndex": 5, 167s "createdIndex": 5 167s }, 167s "prevNode": { 167s "key": "/service/pgcluster/leader", 167s "value": "autopkgtest", 167s "modifiedIndex": 4, 167s "createdIndex": 4 167s } 167s } 168s 2025/03/15 19:45:44 IP address 10.0.2.123/32 state is true, desired false 168s 2025/03/15 19:45:44 Removing address 10.0.2.123/32 on enc1 168s 2025/03/15 19:45:44 IP address 10.0.2.123/32 state is false, desired false 169s Ncat: Version 7.95 ( https://nmap.org/ncat ) 169s Ncat: Connection refused. 169s ### You've reached the end of the script, all "tests" have successfully been passed! ### 169s {"level":"info","ts":"2025-03-15T19:45:45.857212Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 169s {"level":"info","ts":"2025-03-15T19:45:45.857294Z","caller":"embed/etcd.go:378","msg":"closing etcd server","name":"default","data-dir":"default.etcd","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["http://localhost:2379"]} 169s {"level":"warn","ts":"2025-03-15T19:45:45.857378Z","caller":"embed/serve.go:161","msg":"stopping insecure grpc server due to error","error":"accept tcp 127.0.0.1:2379: use of closed network connection"} 169s {"level":"warn","ts":"2025-03-15T19:45:45.857582Z","caller":"embed/serve.go:163","msg":"stopped insecure grpc server due to error","error":"accept tcp 127.0.0.1:2379: use of closed network connection"} 169s {"level":"info","ts":"2025-03-15T19:45:45.857618Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 169s {"level":"info","ts":"2025-03-15T19:45:45.858582Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 169s {"level":"info","ts":"2025-03-15T19:45:45.858653Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 169s {"level":"info","ts":"2025-03-15T19:45:45.858684Z","caller":"embed/etcd.go:380","msg":"closed etcd server","name":"default","data-dir":"default.etcd","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["http://localhost:2379"]} 169s autopkgtest [19:44:20]: test test: -----------------------] 170s autopkgtest [19:44:21]: test test: - - - - - - - - - - results - - - - - - - - - - 170s test PASS 170s autopkgtest [19:44:21]: @@@@@@@@@@@@@@@@@@@@ summary 170s test PASS 187s nova [W] Using flock in prodstack6-s390x 187s Creating nova instance adt-plucky-s390x-vip-manager-20250315-194130-juju-7f2275-prod-proposed-migration-environment-20-097dba5f-20db-460c-b3a2-4e9dbd9f8186 from image adt/ubuntu-plucky-s390x-server-20250315.img (UUID 3d3557fa-fd0f-4bba-9b89-8d5964e09f61)... 187s nova [W] Timed out waiting for fab1915d-760d-4b12-967b-e2af762bd91b to get deleted.