0s autopkgtest [17:20:18]: starting date and time: 2025-03-15 17:20:18+0000 0s autopkgtest [17:20:18]: git checkout: 325255d2 Merge branch 'pin-any-arch' into 'ubuntu/production' 0s autopkgtest [17:20:18]: host juju-7f2275-prod-proposed-migration-environment-20; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.0qwbgcir/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 --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-20@bos03-arm64-35.secgroup --name adt-plucky-arm64-vip-manager-20250315-172018-juju-7f2275-prod-proposed-migration-environment-20-5b565166-02d3-4097-9a6b-cf843fe5ac1e --image adt/ubuntu-plucky-arm64-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-20 --net-id=net_prod-proposed-migration -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/ 142s autopkgtest [17:22:40]: testbed dpkg architecture: arm64 142s autopkgtest [17:22:40]: testbed apt version: 2.9.33 143s autopkgtest [17:22:41]: @@@@@@@@@@@@@@@@@@@@ test bed setup 143s autopkgtest [17:22:41]: testbed release detected to be: None 144s autopkgtest [17:22:42]: updating testbed package index (apt update) 144s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [126 kB] 144s Hit:2 http://ftpmaster.internal/ubuntu plucky InRelease 144s Hit:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease 144s Hit:4 http://ftpmaster.internal/ubuntu plucky-security InRelease 145s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [15.8 kB] 145s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [379 kB] 145s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [99.7 kB] 145s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 Packages [111 kB] 145s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 c-n-f Metadata [1856 B] 145s Get:10 http://ftpmaster.internal/ubuntu plucky-proposed/restricted arm64 c-n-f Metadata [116 B] 145s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/universe arm64 Packages [324 kB] 146s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/universe arm64 c-n-f Metadata [14.7 kB] 146s Get:13 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse arm64 Packages [4948 B] 146s Get:14 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse arm64 c-n-f Metadata [268 B] 146s Fetched 1078 kB in 2s (577 kB/s) 148s Reading package lists... 149s Reading package lists... 149s Building dependency tree... 149s Reading state information... 151s Calculating upgrade... 151s Calculating upgrade... 151s The following packages will be upgraded: 151s pinentry-curses python3-jinja2 strace 151s 3 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 151s Need to get 647 kB of archives. 151s After this operation, 11.3 kB of additional disk space will be used. 151s Get:1 http://ftpmaster.internal/ubuntu plucky/main arm64 strace arm64 6.13+ds-1ubuntu1 [499 kB] 152s Get:2 http://ftpmaster.internal/ubuntu plucky/main arm64 pinentry-curses arm64 1.3.1-2ubuntu3 [39.2 kB] 152s Get:3 http://ftpmaster.internal/ubuntu plucky/main arm64 python3-jinja2 all 3.1.5-2ubuntu1 [109 kB] 153s Fetched 647 kB in 1s (615 kB/s) 153s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 117701 files and directories currently installed.) 153s Preparing to unpack .../strace_6.13+ds-1ubuntu1_arm64.deb ... 153s Unpacking strace (6.13+ds-1ubuntu1) over (6.11-0ubuntu1) ... 153s Preparing to unpack .../pinentry-curses_1.3.1-2ubuntu3_arm64.deb ... 153s Unpacking pinentry-curses (1.3.1-2ubuntu3) over (1.3.1-2ubuntu2) ... 153s Preparing to unpack .../python3-jinja2_3.1.5-2ubuntu1_all.deb ... 153s Unpacking python3-jinja2 (3.1.5-2ubuntu1) over (3.1.5-2) ... 153s Setting up pinentry-curses (1.3.1-2ubuntu3) ... 153s Setting up python3-jinja2 (3.1.5-2ubuntu1) ... 154s Setting up strace (6.13+ds-1ubuntu1) ... 154s Processing triggers for man-db (2.13.0-1) ... 154s Reading package lists... 154s Building dependency tree... 154s Reading state information... 155s Solving dependencies... 155s The following packages will be REMOVED: 155s libnsl2* libpython3.12-minimal* libpython3.12-stdlib* libpython3.12t64* 155s libunwind8* linux-headers-6.11.0-8* linux-headers-6.11.0-8-generic* 155s linux-image-6.11.0-8-generic* linux-modules-6.11.0-8-generic* 155s linux-tools-6.11.0-8* linux-tools-6.11.0-8-generic* 156s 0 upgraded, 0 newly installed, 11 to remove and 5 not upgraded. 156s After this operation, 267 MB disk space will be freed. 156s (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 ... 117701 files and directories currently installed.) 156s Removing linux-tools-6.11.0-8-generic (6.11.0-8.8) ... 156s Removing linux-tools-6.11.0-8 (6.11.0-8.8) ... 156s Removing libpython3.12t64:arm64 (3.12.9-1) ... 156s Removing libpython3.12-stdlib:arm64 (3.12.9-1) ... 156s Removing libnsl2:arm64 (1.3.0-3build3) ... 156s Removing libpython3.12-minimal:arm64 (3.12.9-1) ... 156s Removing libunwind8:arm64 (1.6.2-3.1) ... 156s Removing linux-headers-6.11.0-8-generic (6.11.0-8.8) ... 156s Removing linux-headers-6.11.0-8 (6.11.0-8.8) ... 158s Removing linux-image-6.11.0-8-generic (6.11.0-8.8) ... 158s I: /boot/vmlinuz.old is now a symlink to vmlinuz-6.14.0-10-generic 158s I: /boot/initrd.img.old is now a symlink to initrd.img-6.14.0-10-generic 158s /etc/kernel/postrm.d/initramfs-tools: 158s update-initramfs: Deleting /boot/initrd.img-6.11.0-8-generic 158s /etc/kernel/postrm.d/zz-flash-kernel: 158s flash-kernel: Kernel 6.11.0-8-generic has been removed. 158s flash-kernel: A higher version (6.14.0-10-generic) is still installed, no reflashing required. 158s /etc/kernel/postrm.d/zz-update-grub: 158s Sourcing file `/etc/default/grub' 158s Sourcing file `/etc/default/grub.d/50-cloudimg-settings.cfg' 158s Generating grub configuration file ... 159s Found linux image: /boot/vmlinuz-6.14.0-10-generic 159s Found initrd image: /boot/initrd.img-6.14.0-10-generic 159s Warning: os-prober will not be executed to detect other bootable partitions. 159s Systems on them will not be added to the GRUB boot configuration. 159s Check GRUB_DISABLE_OS_PROBER documentation entry. 159s Adding boot menu entry for UEFI Firmware Settings ... 159s done 159s Removing linux-modules-6.11.0-8-generic (6.11.0-8.8) ... 159s Processing triggers for libc-bin (2.41-1ubuntu1) ... 159s (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 ... 81650 files and directories currently installed.) 159s Purging configuration files for linux-image-6.11.0-8-generic (6.11.0-8.8) ... 159s Purging configuration files for libpython3.12-minimal:arm64 (3.12.9-1) ... 159s Purging configuration files for linux-modules-6.11.0-8-generic (6.11.0-8.8) ... 160s autopkgtest [17:22:58]: upgrading testbed (apt dist-upgrade and autopurge) 160s Reading package lists... 160s Building dependency tree... 160s Reading state information... 161s Calculating upgrade...Starting pkgProblemResolver with broken count: 0 161s Starting 2 pkgProblemResolver with broken count: 0 161s Done 162s Entering ResolveByKeep 162s 162s Calculating upgrade... 162s The following packages will be upgraded: 162s libc-bin libc-dev-bin libc6 libc6-dev locales 162s 5 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 162s Need to get 9530 kB of archives. 162s After this operation, 0 B of additional disk space will be used. 162s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 libc6-dev arm64 2.41-1ubuntu2 [1750 kB] 164s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 libc-dev-bin arm64 2.41-1ubuntu2 [24.0 kB] 164s Get:3 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 libc6 arm64 2.41-1ubuntu2 [2910 kB] 167s Get:4 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 libc-bin arm64 2.41-1ubuntu2 [600 kB] 168s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 locales all 2.41-1ubuntu2 [4246 kB] 172s Preconfiguring packages ... 172s Fetched 9530 kB in 10s (998 kB/s) 172s (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 ... 81647 files and directories currently installed.) 172s Preparing to unpack .../libc6-dev_2.41-1ubuntu2_arm64.deb ... 172s Unpacking libc6-dev:arm64 (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 172s Preparing to unpack .../libc-dev-bin_2.41-1ubuntu2_arm64.deb ... 172s Unpacking libc-dev-bin (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 172s Preparing to unpack .../libc6_2.41-1ubuntu2_arm64.deb ... 173s Unpacking libc6:arm64 (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 173s Setting up libc6:arm64 (2.41-1ubuntu2) ... 173s (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 ... 81647 files and directories currently installed.) 173s Preparing to unpack .../libc-bin_2.41-1ubuntu2_arm64.deb ... 173s Unpacking libc-bin (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 173s Setting up libc-bin (2.41-1ubuntu2) ... 173s (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 ... 81647 files and directories currently installed.) 173s Preparing to unpack .../locales_2.41-1ubuntu2_all.deb ... 173s Unpacking locales (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 173s Setting up locales (2.41-1ubuntu2) ... 174s Generating locales (this might take a while)... 176s en_US.UTF-8... done 176s Generation complete. 176s Setting up libc-dev-bin (2.41-1ubuntu2) ... 176s Setting up libc6-dev:arm64 (2.41-1ubuntu2) ... 176s Processing triggers for man-db (2.13.0-1) ... 177s Processing triggers for systemd (257.3-1ubuntu3) ... 178s Reading package lists... 178s Building dependency tree... 178s Reading state information... 178s Starting pkgProblemResolver with broken count: 0 178s Starting 2 pkgProblemResolver with broken count: 0 178s Done 179s Solving dependencies... 179s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 179s autopkgtest [17:23:17]: rebooting testbed after setup commands that affected boot 202s autopkgtest [17:23:40]: testbed running kernel: Linux 6.14.0-10-generic #10-Ubuntu SMP PREEMPT_DYNAMIC Wed Mar 12 15:45:31 UTC 2025 205s autopkgtest [17:23:43]: @@@@@@@@@@@@@@@@@@@@ apt-source vip-manager 207s Get:1 http://ftpmaster.internal/ubuntu plucky/universe vip-manager 1.0.2-9 (dsc) [2473 B] 207s Get:2 http://ftpmaster.internal/ubuntu plucky/universe vip-manager 1.0.2-9 (tar) [69.9 kB] 207s Get:3 http://ftpmaster.internal/ubuntu plucky/universe vip-manager 1.0.2-9 (diff) [9432 B] 207s gpgv: Signature made Fri Aug 23 16:57:11 2024 UTC 207s gpgv: using RSA key 5C48FE6157F49179597087C64C5A6BAB12D2A7AE 207s gpgv: Can't check signature: No public key 207s dpkg-source: warning: cannot verify inline signature for ./vip-manager_1.0.2-9.dsc: no acceptable signature found 207s autopkgtest [17:23:45]: testing package vip-manager version 1.0.2-9 207s autopkgtest [17:23:45]: build not needed 208s autopkgtest [17:23:46]: test test: preparing testbed 208s Reading package lists... 208s Building dependency tree... 208s Reading state information... 209s Starting pkgProblemResolver with broken count: 0 209s Starting 2 pkgProblemResolver with broken count: 0 209s Done 209s The following NEW packages will be installed: 209s etcd-server liblua5.4-0 ncat vip-manager 210s 0 upgraded, 4 newly installed, 0 to remove and 0 not upgraded. 210s Need to get 13.9 MB of archives. 210s After this operation, 49.4 MB of additional disk space will be used. 210s Get:1 http://ftpmaster.internal/ubuntu plucky/universe arm64 etcd-server arm64 3.5.16-4 [11.1 MB] 220s Get:2 http://ftpmaster.internal/ubuntu plucky/main arm64 liblua5.4-0 arm64 5.4.7-1 [158 kB] 220s Get:3 http://ftpmaster.internal/ubuntu plucky/universe arm64 ncat arm64 7.95+dfsg-2 [213 kB] 221s Get:4 http://ftpmaster.internal/ubuntu plucky/universe arm64 vip-manager arm64 1.0.2-9 [2454 kB] 223s Fetched 13.9 MB in 14s (1026 kB/s) 223s Selecting previously unselected package etcd-server. 224s (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 ... 81647 files and directories currently installed.) 224s Preparing to unpack .../etcd-server_3.5.16-4_arm64.deb ... 224s Unpacking etcd-server (3.5.16-4) ... 224s Selecting previously unselected package liblua5.4-0:arm64. 224s Preparing to unpack .../liblua5.4-0_5.4.7-1_arm64.deb ... 224s Unpacking liblua5.4-0:arm64 (5.4.7-1) ... 224s Selecting previously unselected package ncat. 224s Preparing to unpack .../ncat_7.95+dfsg-2_arm64.deb ... 224s Unpacking ncat (7.95+dfsg-2) ... 224s Selecting previously unselected package vip-manager. 224s Preparing to unpack .../vip-manager_1.0.2-9_arm64.deb ... 224s Unpacking vip-manager (1.0.2-9) ... 224s Setting up liblua5.4-0:arm64 (5.4.7-1) ... 224s Setting up etcd-server (3.5.16-4) ... 224s info: Selecting UID from range 100 to 999 ... 224s 224s info: Selecting GID from range 100 to 999 ... 224s info: Adding system user `etcd' (UID 107) ... 224s info: Adding new group `etcd' (GID 108) ... 224s info: Adding new user `etcd' (UID 107) with group `etcd' ... 224s info: Creating home directory `/var/lib/etcd/' ... 224s Created symlink '/etc/systemd/system/etcd2.service' → '/usr/lib/systemd/system/etcd.service'. 224s Created symlink '/etc/systemd/system/multi-user.target.wants/etcd.service' → '/usr/lib/systemd/system/etcd.service'. 225s Setting up vip-manager (1.0.2-9) ... 225s Created symlink '/etc/systemd/system/multi-user.target.wants/vip-manager.service' → '/usr/lib/systemd/system/vip-manager.service'. 225s Setting up ncat (7.95+dfsg-2) ... 225s Processing triggers for man-db (2.13.0-1) ... 226s Processing triggers for libc-bin (2.41-1ubuntu2) ... 227s autopkgtest [17:24:05]: test test: [----------------------- 228s ○ etcd.service - etcd - highly-available key value store 228s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 228s Active: inactive (dead) since Sat 2025-03-15 17:24:06 UTC; 21ms ago 228s Duration: 2.998s 228s Invocation: ce4a4c26dbe24a5db10e460fe69ce116 228s Docs: https://etcd.io/docs 228s man:etcd 228s Process: 1384 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 228s Main PID: 1384 (code=killed, signal=TERM) 228s Mem peak: 8.4M 228s CPU: 109ms 228s 228s Mar 15 17:24:06 autopkgtest etcd[1384]: {"level":"info","ts":"2025-03-15T17:24:06.113019Z","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"]} 228s Mar 15 17:24:06 autopkgtest etcd[1384]: {"level":"warn","ts":"2025-03-15T17:24:06.113124Z","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"} 228s Mar 15 17:24:06 autopkgtest etcd[1384]: {"level":"warn","ts":"2025-03-15T17:24:06.113273Z","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"} 228s Mar 15 17:24:06 autopkgtest etcd[1384]: {"level":"info","ts":"2025-03-15T17:24:06.113351Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 228s Mar 15 17:24:06 autopkgtest systemd[1]: Stopping etcd.service - etcd - highly-available key value store... 228s Mar 15 17:24:06 autopkgtest etcd[1384]: {"level":"info","ts":"2025-03-15T17:24:06.117514Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 228s Mar 15 17:24:06 autopkgtest etcd[1384]: {"level":"info","ts":"2025-03-15T17:24:06.117813Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 228s Mar 15 17:24:06 autopkgtest etcd[1384]: {"level":"info","ts":"2025-03-15T17:24:06.117826Z","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"]} 228s Mar 15 17:24:06 autopkgtest systemd[1]: etcd.service: Deactivated successfully. 228s Mar 15 17:24:06 autopkgtest systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 228s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 228s {"level":"warn","ts":"2025-03-15T17:24:06.210570Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_UNSUPPORTED_ARCH=arm64"} 228s {"level":"warn","ts":"2025-03-15T17:24:06.210781Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 228s {"level":"info","ts":"2025-03-15T17:24:06.210818Z","caller":"etcdmain/etcd.go:73","msg":"Running: ","args":["etcd","--enable-v2"]} 228s {"level":"warn","ts":"2025-03-15T17:24:06.210843Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 228s {"level":"warn","ts":"2025-03-15T17:24:06.210874Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 228s {"level":"info","ts":"2025-03-15T17:24:06.210891Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 228s {"level":"info","ts":"2025-03-15T17:24:06.211320Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["http://localhost:2379"]} 228s {"level":"info","ts":"2025-03-15T17:24:06.211549Z","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":"arm64","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"} 228s {"level":"info","ts":"2025-03-15T17:24:06.217473Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"5.578397ms"} 228s {"level":"info","ts":"2025-03-15T17:24:06.230667Z","caller":"etcdserver/raft.go:505","msg":"starting local member","local-member-id":"8e9e05c52164694d","cluster-id":"cdf818194e3a8c32"} 228s {"level":"info","ts":"2025-03-15T17:24:06.230788Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 228s {"level":"info","ts":"2025-03-15T17:24:06.230849Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 0"} 228s {"level":"info","ts":"2025-03-15T17:24:06.230862Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]"} 228s {"level":"info","ts":"2025-03-15T17:24:06.230875Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 1"} 228s {"level":"info","ts":"2025-03-15T17:24:06.230919Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 228s {"level":"warn","ts":"2025-03-15T17:24:06.239364Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 228s {"level":"info","ts":"2025-03-15T17:24:06.241353Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":1} 228s {"level":"info","ts":"2025-03-15T17:24:06.242676Z","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"} 228s {"level":"info","ts":"2025-03-15T17:24:06.243673Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 228s {"level":"info","ts":"2025-03-15T17:24:06.243823Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 228s {"level":"info","ts":"2025-03-15T17:24:06.244743Z","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"} 228s {"level":"info","ts":"2025-03-15T17:24:06.244937Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 228s {"level":"info","ts":"2025-03-15T17:24:06.245011Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 228s {"level":"info","ts":"2025-03-15T17:24:06.245051Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 228s {"level":"info","ts":"2025-03-15T17:24:06.245832Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 228s {"level":"info","ts":"2025-03-15T17:24:06.247244Z","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"]} 228s {"level":"warn","ts":"2025-03-15T17:24:06.247260Z","caller":"embed/etcd.go:742","msg":"Flag `enable-v2` is deprecated and will get removed in etcd 3.6."} 228s {"level":"info","ts":"2025-03-15T17:24:06.247446Z","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":[]} 228s {"level":"info","ts":"2025-03-15T17:24:06.247505Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 228s {"level":"info","ts":"2025-03-15T17:24:06.247520Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 229s {"level":"info","ts":"2025-03-15T17:24:07.132173Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 1"} 229s {"level":"info","ts":"2025-03-15T17:24:07.132545Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 1"} 229s {"level":"info","ts":"2025-03-15T17:24:07.132589Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 1"} 229s {"level":"info","ts":"2025-03-15T17:24:07.132602Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 2"} 229s {"level":"info","ts":"2025-03-15T17:24:07.132636Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 2"} 229s {"level":"info","ts":"2025-03-15T17:24:07.132646Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 2"} 229s {"level":"info","ts":"2025-03-15T17:24:07.132669Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 2"} 229s {"level":"info","ts":"2025-03-15T17:24:07.133692Z","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"} 229s {"level":"info","ts":"2025-03-15T17:24:07.133774Z","caller":"etcdserver/server.go:2651","msg":"setting up initial cluster version using v2 API","cluster-version":"3.5"} 229s {"level":"info","ts":"2025-03-15T17:24:07.134137Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 229s {"level":"info","ts":"2025-03-15T17:24:07.134177Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 229s {"level":"info","ts":"2025-03-15T17:24:07.133800Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 229s {"level":"info","ts":"2025-03-15T17:24:07.134713Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 229s {"level":"info","ts":"2025-03-15T17:24:07.134804Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 229s {"level":"info","ts":"2025-03-15T17:24:07.134952Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 229s {"level":"info","ts":"2025-03-15T17:24:07.134981Z","caller":"etcdserver/server.go:2675","msg":"cluster version is updated","cluster-version":"3.5"} 229s {"level":"info","ts":"2025-03-15T17:24:07.135034Z","caller":"embed/serve.go:188","msg":"serving client traffic insecurely; this is strongly discouraged!","traffic":"grpc+http","address":"127.0.0.1:2379"} 230s Ncat: Version 7.95 ( https://nmap.org/ncat ) 230s Ncat: Listening on 0.0.0.0:12345 230s {"errorCode":100,"message":"Key not found","cause":"/service","index":3} 230s 2025/03/15 17:24:08 No dcs-endpoints specified, trying to use localhost with standard ports! 230s dcs-endpoints : [http://127.0.0.1:2379] 230s dcs-type : etcd 230s hostingtype : basic 230s interface : enp1s0 230s interval : 1000 230s ip : 10.0.2.123 230s manager-type : basic 230s netmask : 32 230s retry-after : 250 230s retry-num : 3 230s trigger-key : service/pgcluster/leader 230s trigger-value : autopkgtest 230s verbose : false 230s version : false 230s 2025/03/15 17:24:08 This is the config that will be used: 230s 2025/03/15 17:24:08 IP address 10.0.2.123/32 state is false, desired false 230s 2025/03/15 17:24:08 etcd error: 100: Key not found (/service) [3] 231s 2025/03/15 17:24:09 etcd error: 100: Key not found (/service) [3] 232s 2025/03/15 17:24:10 IP address 10.0.2.123/32 state is false, desired true 232s 2025/03/15 17:24:10 Configuring address 10.0.2.123/32 on enp1s0 232s { 232s "action": "set", 232s "node": { 232s "key": "/service/pgcluster/leader", 232s "value": "autopkgtest", 232s "modifiedIndex": 4, 232s "createdIndex": 4 232s } 232s } 232s 2025/03/15 17:24:10 Sent gratuitous ARP reply 232s 2025/03/15 17:24:10 Sent gratuitous ARP request 232s 2025/03/15 17:24:10 IP address 10.0.2.123/32 state is true, desired true 234s inet 10.0.2.123/32 scope global enp1s0 234s Ncat: Version 7.95 ( https://nmap.org/ncat ) 234s Ncat: Ncat: Connection from 10.0.2.123:43776. 234s Connected to 10.0.2.123:12345. 234s Ncat: 0 bytes sent, 0 bytes received in 0.03 seconds. 234s { 234s "action": "set", 234s "node": { 234s "key": "/service/pgcluster/leader", 234s "value": "0xGARBAGE", 234s "modifiedIndex": 5, 234s "createdIndex": 5 234s }, 234s "prevNode": { 234s "key": "/service/pgcluster/leader", 234s "value": "autopkgtest", 234s "modifiedIndex": 4, 234s "createdIndex": 4 234s } 234s } 235s 2025/03/15 17:24:13 IP address 10.0.2.123/32 state is true, desired false 235s 2025/03/15 17:24:13 Removing address 10.0.2.123/32 on enp1s0 235s 2025/03/15 17:24:13 IP address 10.0.2.123/32 state is false, desired false 236s Ncat: Version 7.95 ( https://nmap.org/ncat ) 236s Ncat: Connection refused. 236s ### You've reached the end of the script, all "tests" have successfully been passed! ### 236s {"level":"info","ts":"2025-03-15T17:24:14.339761Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 236s {"level":"info","ts":"2025-03-15T17:24:14.339925Z","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"]} 236s {"level":"warn","ts":"2025-03-15T17:24:14.340114Z","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"} 236s {"level":"warn","ts":"2025-03-15T17:24:14.340293Z","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"} 236s {"level":"info","ts":"2025-03-15T17:24:14.340314Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 236s {"level":"info","ts":"2025-03-15T17:24:14.343288Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 236s {"level":"info","ts":"2025-03-15T17:24:14.343632Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 236s {"level":"info","ts":"2025-03-15T17:24:14.343747Z","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"]} 236s autopkgtest [17:24:14]: test test: -----------------------] 237s autopkgtest [17:24:15]: test test: - - - - - - - - - - results - - - - - - - - - - 237s test PASS 237s autopkgtest [17:24:15]: @@@@@@@@@@@@@@@@@@@@ summary 237s test PASS 254s nova [W] Using flock in prodstack6-arm64 254s Creating nova instance adt-plucky-arm64-vip-manager-20250315-172018-juju-7f2275-prod-proposed-migration-environment-20-5b565166-02d3-4097-9a6b-cf843fe5ac1e from image adt/ubuntu-plucky-arm64-server-20250315.img (UUID bd6e766c-b51f-4b53-86d6-23aa4d18f524)... 254s nova [W] Timed out waiting for 19dfcb55-3d21-4b7b-b442-ac6f5a4df2fb to get deleted.