2s autopkgtest [17:20:51]: starting date and time: 2025-03-15 17:20:51+0000 2s autopkgtest [17:20:51]: git checkout: 325255d2 Merge branch 'pin-any-arch' into 'ubuntu/production' 2s autopkgtest [17:20:51]: host juju-7f2275-prod-proposed-migration-environment-15; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.nws369rp/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:glibc --apt-upgrade vip-manager2 --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-15@bos03-arm64-20.secgroup --name adt-plucky-arm64-vip-manager2-20250315-172048-juju-7f2275-prod-proposed-migration-environment-15-ab3e22dc-fa41-42d0-82e0-6693deef060f --image adt/ubuntu-plucky-arm64-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-15 --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/ 168s autopkgtest [17:23:37]: testbed dpkg architecture: arm64 168s autopkgtest [17:23:37]: testbed apt version: 2.9.33 169s autopkgtest [17:23:38]: @@@@@@@@@@@@@@@@@@@@ test bed setup 169s autopkgtest [17:23:38]: testbed release detected to be: None 170s autopkgtest [17:23:39]: updating testbed package index (apt update) 170s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [126 kB] 170s Hit:2 http://ftpmaster.internal/ubuntu plucky InRelease 171s Hit:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease 171s Hit:4 http://ftpmaster.internal/ubuntu plucky-security InRelease 171s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [99.7 kB] 171s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [15.8 kB] 171s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [379 kB] 171s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 Packages [111 kB] 171s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 c-n-f Metadata [1856 B] 171s Get:10 http://ftpmaster.internal/ubuntu plucky-proposed/restricted arm64 c-n-f Metadata [116 B] 171s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/universe arm64 Packages [324 kB] 172s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/universe arm64 c-n-f Metadata [14.7 kB] 172s Get:13 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse arm64 Packages [4948 B] 172s Get:14 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse arm64 c-n-f Metadata [268 B] 172s Fetched 1078 kB in 2s (676 kB/s) 173s Reading package lists... 173s + lsb_release --codename --short 173s + RELEASE=plucky 173s + cat 173s + [ plucky != trusty ] 173s + DEBIAN_FRONTEND=noninteractive eatmydata apt-get -y --allow-downgrades -o Dpkg::Options::=--force-confnew dist-upgrade 173s Reading package lists... 174s Building dependency tree... 174s Reading state information... 174s Calculating upgrade... 174s Calculating upgrade... 175s The following packages will be upgraded: 175s pinentry-curses python3-jinja2 strace 175s 3 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 175s Need to get 647 kB of archives. 175s After this operation, 11.3 kB of additional disk space will be used. 175s Get:1 http://ftpmaster.internal/ubuntu plucky/main arm64 strace arm64 6.13+ds-1ubuntu1 [499 kB] 176s Get:2 http://ftpmaster.internal/ubuntu plucky/main arm64 pinentry-curses arm64 1.3.1-2ubuntu3 [39.2 kB] 176s Get:3 http://ftpmaster.internal/ubuntu plucky/main arm64 python3-jinja2 all 3.1.5-2ubuntu1 [109 kB] 176s Fetched 647 kB in 1s (682 kB/s) 177s (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.) 177s Preparing to unpack .../strace_6.13+ds-1ubuntu1_arm64.deb ... 177s Unpacking strace (6.13+ds-1ubuntu1) over (6.11-0ubuntu1) ... 177s Preparing to unpack .../pinentry-curses_1.3.1-2ubuntu3_arm64.deb ... 177s Unpacking pinentry-curses (1.3.1-2ubuntu3) over (1.3.1-2ubuntu2) ... 177s Preparing to unpack .../python3-jinja2_3.1.5-2ubuntu1_all.deb ... 177s Unpacking python3-jinja2 (3.1.5-2ubuntu1) over (3.1.5-2) ... 177s Setting up pinentry-curses (1.3.1-2ubuntu3) ... 177s Setting up python3-jinja2 (3.1.5-2ubuntu1) ... 177s Setting up strace (6.13+ds-1ubuntu1) ... 177s Processing triggers for man-db (2.13.0-1) ... 178s + rm /etc/apt/preferences.d/force-downgrade-to-release.pref 178s + /usr/lib/apt/apt-helper analyze-pattern ?true 178s + uname -r 178s + sed s/\./\\./g 178s + running_kernel_pattern=^linux-.*6\.14\.0-10-generic.* 178s + apt list ?obsolete 178s + tail -n+2 178s + cut -d/ -f1 178s + grep -v ^linux-.*6\.14\.0-10-generic.* 178s + obsolete_pkgs=linux-headers-6.11.0-8-generic 178s linux-headers-6.11.0-8 178s linux-image-6.11.0-8-generic 178s linux-modules-6.11.0-8-generic 178s linux-tools-6.11.0-8-generic 178s linux-tools-6.11.0-8 178s + DEBIAN_FRONTEND=noninteractive eatmydata apt-get -y purge --autoremove linux-headers-6.11.0-8-generic linux-headers-6.11.0-8 linux-image-6.11.0-8-generic linux-modules-6.11.0-8-generic linux-tools-6.11.0-8-generic linux-tools-6.11.0-8 178s Reading package lists... 179s Building dependency tree... 179s Reading state information... 179s Solving dependencies... 179s The following packages will be REMOVED: 179s libnsl2* libpython3.12-minimal* libpython3.12-stdlib* libpython3.12t64* 179s libunwind8* linux-headers-6.11.0-8* linux-headers-6.11.0-8-generic* 179s linux-image-6.11.0-8-generic* linux-modules-6.11.0-8-generic* 179s linux-tools-6.11.0-8* linux-tools-6.11.0-8-generic* 180s 0 upgraded, 0 newly installed, 11 to remove and 5 not upgraded. 180s After this operation, 267 MB disk space will be freed. 180s (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.) 180s Removing linux-tools-6.11.0-8-generic (6.11.0-8.8) ... 180s Removing linux-tools-6.11.0-8 (6.11.0-8.8) ... 180s Removing libpython3.12t64:arm64 (3.12.9-1) ... 180s Removing libpython3.12-stdlib:arm64 (3.12.9-1) ... 180s Removing libnsl2:arm64 (1.3.0-3build3) ... 180s Removing libpython3.12-minimal:arm64 (3.12.9-1) ... 180s Removing libunwind8:arm64 (1.6.2-3.1) ... 180s Removing linux-headers-6.11.0-8-generic (6.11.0-8.8) ... 181s Removing linux-headers-6.11.0-8 (6.11.0-8.8) ... 182s Removing linux-image-6.11.0-8-generic (6.11.0-8.8) ... 182s I: /boot/vmlinuz.old is now a symlink to vmlinuz-6.14.0-10-generic 182s I: /boot/initrd.img.old is now a symlink to initrd.img-6.14.0-10-generic 182s /etc/kernel/postrm.d/initramfs-tools: 182s update-initramfs: Deleting /boot/initrd.img-6.11.0-8-generic 183s /etc/kernel/postrm.d/zz-flash-kernel: 183s flash-kernel: Kernel 6.11.0-8-generic has been removed. 183s flash-kernel: A higher version (6.14.0-10-generic) is still installed, no reflashing required. 183s /etc/kernel/postrm.d/zz-update-grub: 183s Sourcing file `/etc/default/grub' 183s Sourcing file `/etc/default/grub.d/50-cloudimg-settings.cfg' 183s Generating grub configuration file ... 183s Found linux image: /boot/vmlinuz-6.14.0-10-generic 183s Found initrd image: /boot/initrd.img-6.14.0-10-generic 183s Warning: os-prober will not be executed to detect other bootable partitions. 183s Systems on them will not be added to the GRUB boot configuration. 183s Check GRUB_DISABLE_OS_PROBER documentation entry. 183s Adding boot menu entry for UEFI Firmware Settings ... 183s done 183s Removing linux-modules-6.11.0-8-generic (6.11.0-8.8) ... 184s Processing triggers for libc-bin (2.41-1ubuntu1) ... 184s (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.) 184s Purging configuration files for linux-image-6.11.0-8-generic (6.11.0-8.8) ... 184s Purging configuration files for libpython3.12-minimal:arm64 (3.12.9-1) ... 184s Purging configuration files for linux-modules-6.11.0-8-generic (6.11.0-8.8) ... 184s + grep -q trusty /etc/lsb-release 184s + [ ! -d /usr/share/doc/unattended-upgrades ] 184s + [ ! -d /usr/share/doc/lxd ] 184s + [ ! -d /usr/share/doc/lxd-client ] 184s + [ ! -d /usr/share/doc/snapd ] 184s + type iptables 184s + cat 184s + chmod 755 /etc/rc.local 184s + . /etc/rc.local 184s + iptables -w -t mangle -A FORWARD -p tcp --tcp-flags SYN,RST SYN -j TCPMSS --clamp-mss-to-pmtu 184s + iptables -A OUTPUT -d 10.255.255.1/32 -p tcp -j DROP 184s + iptables -A OUTPUT -d 10.255.255.2/32 -p tcp -j DROP 184s + uname -m 184s + [ aarch64 = ppc64le ] 184s + [ -d /run/systemd/system ] 184s + systemd-detect-virt --quiet --vm 184s + mkdir -p /etc/systemd/system/systemd-random-seed.service.d/ 184s + cat 184s + grep -q lz4 /etc/initramfs-tools/initramfs.conf 184s + echo COMPRESS=lz4 184s autopkgtest [17:23:53]: upgrading testbed (apt dist-upgrade and autopurge) 184s Reading package lists... 185s Building dependency tree... 185s Reading state information... 185s Calculating upgrade...Starting pkgProblemResolver with broken count: 0 185s Starting 2 pkgProblemResolver with broken count: 0 185s Done 186s Entering ResolveByKeep 186s 186s Calculating upgrade... 187s The following packages will be upgraded: 187s libc-bin libc-dev-bin libc6 libc6-dev locales 187s 5 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 187s Need to get 9530 kB of archives. 187s After this operation, 0 B of additional disk space will be used. 187s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 libc6-dev arm64 2.41-1ubuntu2 [1750 kB] 189s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 libc-dev-bin arm64 2.41-1ubuntu2 [24.0 kB] 189s Get:3 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 libc6 arm64 2.41-1ubuntu2 [2910 kB] 192s Get:4 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 libc-bin arm64 2.41-1ubuntu2 [600 kB] 192s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 locales all 2.41-1ubuntu2 [4246 kB] 197s Preconfiguring packages ... 197s Fetched 9530 kB in 10s (953 kB/s) 197s (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.) 197s Preparing to unpack .../libc6-dev_2.41-1ubuntu2_arm64.deb ... 197s Unpacking libc6-dev:arm64 (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 198s Preparing to unpack .../libc-dev-bin_2.41-1ubuntu2_arm64.deb ... 198s Unpacking libc-dev-bin (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 198s Preparing to unpack .../libc6_2.41-1ubuntu2_arm64.deb ... 198s Unpacking libc6:arm64 (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 198s Setting up libc6:arm64 (2.41-1ubuntu2) ... 198s (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.) 198s Preparing to unpack .../libc-bin_2.41-1ubuntu2_arm64.deb ... 198s Unpacking libc-bin (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 198s Setting up libc-bin (2.41-1ubuntu2) ... 198s (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.) 198s Preparing to unpack .../locales_2.41-1ubuntu2_all.deb ... 198s Unpacking locales (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 199s Setting up locales (2.41-1ubuntu2) ... 199s Generating locales (this might take a while)... 201s en_US.UTF-8... done 201s Generation complete. 201s Setting up libc-dev-bin (2.41-1ubuntu2) ... 202s Setting up libc6-dev:arm64 (2.41-1ubuntu2) ... 202s Processing triggers for man-db (2.13.0-1) ... 203s Processing triggers for systemd (257.3-1ubuntu3) ... 203s Reading package lists... 204s Building dependency tree... 204s Reading state information... 204s Starting pkgProblemResolver with broken count: 0 204s Starting 2 pkgProblemResolver with broken count: 0 204s Done 205s Solving dependencies... 205s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 205s autopkgtest [17:24:14]: rebooting testbed after setup commands that affected boot 230s autopkgtest [17:24:39]: testbed running kernel: Linux 6.14.0-10-generic #10-Ubuntu SMP PREEMPT_DYNAMIC Wed Mar 12 15:45:31 UTC 2025 233s autopkgtest [17:24:42]: @@@@@@@@@@@@@@@@@@@@ apt-source vip-manager2 236s Get:1 http://ftpmaster.internal/ubuntu plucky/universe vip-manager2 3.0.0-2 (dsc) [2487 B] 236s Get:2 http://ftpmaster.internal/ubuntu plucky/universe vip-manager2 3.0.0-2 (tar) [46.4 kB] 236s Get:3 http://ftpmaster.internal/ubuntu plucky/universe vip-manager2 3.0.0-2 (diff) [9200 B] 236s gpgv: Signature made Mon Feb 3 15:49:05 2025 UTC 236s gpgv: using RSA key 5C48FE6157F49179597087C64C5A6BAB12D2A7AE 236s gpgv: Can't check signature: No public key 236s dpkg-source: warning: cannot verify inline signature for ./vip-manager2_3.0.0-2.dsc: no acceptable signature found 236s autopkgtest [17:24:45]: testing package vip-manager2 version 3.0.0-2 237s autopkgtest [17:24:46]: build not needed 238s autopkgtest [17:24:47]: test test: preparing testbed 238s Reading package lists... 238s Building dependency tree... 238s Reading state information... 239s Starting pkgProblemResolver with broken count: 0 239s Starting 2 pkgProblemResolver with broken count: 0 239s Done 240s The following NEW packages will be installed: 240s etcd-client etcd-server liblua5.4-0 ncat vip-manager2 240s 0 upgraded, 5 newly installed, 0 to remove and 0 not upgraded. 240s Need to get 21.1 MB of archives. 240s After this operation, 76.4 MB of additional disk space will be used. 240s Get:1 http://ftpmaster.internal/ubuntu plucky/universe arm64 etcd-server arm64 3.5.16-4 [11.1 MB] 251s Get:2 http://ftpmaster.internal/ubuntu plucky/main arm64 liblua5.4-0 arm64 5.4.7-1 [158 kB] 251s Get:3 http://ftpmaster.internal/ubuntu plucky/universe arm64 ncat arm64 7.95+dfsg-2 [213 kB] 251s Get:4 http://ftpmaster.internal/ubuntu plucky/universe arm64 vip-manager2 arm64 3.0.0-2 [4310 kB] 256s Get:5 http://ftpmaster.internal/ubuntu plucky/universe arm64 etcd-client arm64 3.5.16-4 [5272 kB] 261s Fetched 21.1 MB in 21s (993 kB/s) 261s Selecting previously unselected package etcd-server. 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 ... 81647 files and directories currently installed.) 261s Preparing to unpack .../etcd-server_3.5.16-4_arm64.deb ... 261s Unpacking etcd-server (3.5.16-4) ... 262s Selecting previously unselected package liblua5.4-0:arm64. 262s Preparing to unpack .../liblua5.4-0_5.4.7-1_arm64.deb ... 262s Unpacking liblua5.4-0:arm64 (5.4.7-1) ... 262s Selecting previously unselected package ncat. 262s Preparing to unpack .../ncat_7.95+dfsg-2_arm64.deb ... 262s Unpacking ncat (7.95+dfsg-2) ... 262s Selecting previously unselected package vip-manager2. 262s Preparing to unpack .../vip-manager2_3.0.0-2_arm64.deb ... 262s Unpacking vip-manager2 (3.0.0-2) ... 262s Selecting previously unselected package etcd-client. 262s Preparing to unpack .../etcd-client_3.5.16-4_arm64.deb ... 262s Unpacking etcd-client (3.5.16-4) ... 262s Setting up vip-manager2 (3.0.0-2) ... 262s Created symlink '/etc/systemd/system/multi-user.target.wants/vip-manager.service' → '/usr/lib/systemd/system/vip-manager.service'. 263s Setting up etcd-client (3.5.16-4) ... 263s Setting up liblua5.4-0:arm64 (5.4.7-1) ... 263s Setting up etcd-server (3.5.16-4) ... 263s info: Selecting UID from range 100 to 999 ... 263s 263s info: Selecting GID from range 100 to 999 ... 263s info: Adding system user `etcd' (UID 107) ... 263s info: Adding new group `etcd' (GID 108) ... 263s info: Adding new user `etcd' (UID 107) with group `etcd' ... 263s info: Creating home directory `/var/lib/etcd/' ... 263s Created symlink '/etc/systemd/system/etcd2.service' → '/usr/lib/systemd/system/etcd.service'. 263s Created symlink '/etc/systemd/system/multi-user.target.wants/etcd.service' → '/usr/lib/systemd/system/etcd.service'. 264s Setting up ncat (7.95+dfsg-2) ... 264s Processing triggers for man-db (2.13.0-1) ... 265s Processing triggers for libc-bin (2.41-1ubuntu2) ... 266s autopkgtest [17:25:15]: test test: [----------------------- 267s ○ etcd.service - etcd - highly-available key value store 267s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 267s Active: inactive (dead) since Sat 2025-03-15 17:25:16 UTC; 14ms ago 267s Duration: 2.983s 267s Invocation: 9151423ed7cf4c4fa5ba80cb75b4ba13 267s Docs: https://etcd.io/docs 267s man:etcd 267s Process: 1486 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 267s Main PID: 1486 (code=killed, signal=TERM) 267s Mem peak: 8.8M 267s CPU: 132ms 267s 267s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"info","ts":"2025-03-15T17:25:16.472102Z","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"]} 267s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"warn","ts":"2025-03-15T17:25:16.472215Z","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"} 267s Mar 15 17:25:16 autopkgtest systemd[1]: Stopping etcd.service - etcd - highly-available key value store... 267s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"warn","ts":"2025-03-15T17:25:16.473176Z","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"} 267s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"info","ts":"2025-03-15T17:25:16.473285Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 267s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"info","ts":"2025-03-15T17:25:16.476957Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 267s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"info","ts":"2025-03-15T17:25:16.477444Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 267s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"info","ts":"2025-03-15T17:25:16.477479Z","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"]} 267s Mar 15 17:25:16 autopkgtest systemd[1]: etcd.service: Deactivated successfully. 267s Mar 15 17:25:16 autopkgtest systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 267s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 267s {"level":"warn","ts":"2025-03-15T17:25:16.561360Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_UNSUPPORTED_ARCH=arm64"} 267s {"level":"warn","ts":"2025-03-15T17:25:16.561587Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 267s {"level":"info","ts":"2025-03-15T17:25:16.561630Z","caller":"etcdmain/etcd.go:73","msg":"Running: ","args":["etcd"]} 267s {"level":"warn","ts":"2025-03-15T17:25:16.561663Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 267s {"level":"warn","ts":"2025-03-15T17:25:16.561697Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 267s {"level":"info","ts":"2025-03-15T17:25:16.561706Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 267s {"level":"info","ts":"2025-03-15T17:25:16.562107Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["http://localhost:2379"]} 267s {"level":"info","ts":"2025-03-15T17:25:16.562292Z","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"} 267s {"level":"info","ts":"2025-03-15T17:25:16.567058Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"4.37816ms"} 267s {"level":"info","ts":"2025-03-15T17:25:16.578300Z","caller":"etcdserver/raft.go:505","msg":"starting local member","local-member-id":"8e9e05c52164694d","cluster-id":"cdf818194e3a8c32"} 267s {"level":"info","ts":"2025-03-15T17:25:16.578408Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 267s {"level":"info","ts":"2025-03-15T17:25:16.578454Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 0"} 267s {"level":"info","ts":"2025-03-15T17:25:16.578464Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]"} 267s {"level":"info","ts":"2025-03-15T17:25:16.578477Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 1"} 267s {"level":"info","ts":"2025-03-15T17:25:16.578506Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 267s {"level":"warn","ts":"2025-03-15T17:25:16.585111Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 267s {"level":"info","ts":"2025-03-15T17:25:16.588120Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":1} 267s {"level":"info","ts":"2025-03-15T17:25:16.589357Z","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"} 267s {"level":"info","ts":"2025-03-15T17:25:16.590758Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 267s {"level":"info","ts":"2025-03-15T17:25:16.590950Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 267s {"level":"info","ts":"2025-03-15T17:25:16.591571Z","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"} 267s {"level":"info","ts":"2025-03-15T17:25:16.591775Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 267s {"level":"info","ts":"2025-03-15T17:25:16.591850Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 267s {"level":"info","ts":"2025-03-15T17:25:16.591890Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 267s {"level":"info","ts":"2025-03-15T17:25:16.592120Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 267s {"level":"info","ts":"2025-03-15T17:25:16.593681Z","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"]} 267s {"level":"info","ts":"2025-03-15T17:25:16.594329Z","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":[]} 267s {"level":"info","ts":"2025-03-15T17:25:16.594372Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 267s {"level":"info","ts":"2025-03-15T17:25:16.594475Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 267s {"level":"info","ts":"2025-03-15T17:25:16.779627Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 1"} 267s {"level":"info","ts":"2025-03-15T17:25:16.779678Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 1"} 267s {"level":"info","ts":"2025-03-15T17:25:16.779698Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 1"} 267s {"level":"info","ts":"2025-03-15T17:25:16.779711Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 2"} 267s {"level":"info","ts":"2025-03-15T17:25:16.779740Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 2"} 267s {"level":"info","ts":"2025-03-15T17:25:16.779748Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 2"} 267s {"level":"info","ts":"2025-03-15T17:25:16.779755Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 2"} 267s {"level":"info","ts":"2025-03-15T17:25:16.780722Z","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"} 267s {"level":"info","ts":"2025-03-15T17:25:16.780774Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 267s {"level":"info","ts":"2025-03-15T17:25:16.780954Z","caller":"etcdserver/server.go:2651","msg":"setting up initial cluster version using v2 API","cluster-version":"3.5"} 267s {"level":"info","ts":"2025-03-15T17:25:16.781794Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 267s {"level":"info","ts":"2025-03-15T17:25:16.782586Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 267s {"level":"info","ts":"2025-03-15T17:25:16.782630Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 267s {"level":"info","ts":"2025-03-15T17:25:16.782693Z","caller":"embed/serve.go:188","msg":"serving client traffic insecurely; this is strongly discouraged!","traffic":"grpc+http","address":"127.0.0.1:2379"} 267s {"level":"info","ts":"2025-03-15T17:25:16.781878Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 267s {"level":"info","ts":"2025-03-15T17:25:16.783123Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 267s {"level":"info","ts":"2025-03-15T17:25:16.783163Z","caller":"etcdserver/server.go:2675","msg":"cluster version is updated","cluster-version":"3.5"} 269s Ncat: Version 7.95 ( https://nmap.org/ncat ) 269s Ncat: Listening on 0.0.0.0:12345 269s 0 269s No dcs-endpoints specified, trying to use localhost with standard ports! 269s This is the config that will be used: 269s dcs-endpoints : [http://127.0.0.1:2379] 269s dcs-type : etcd 269s hostingtype : basic 269s interface : enp1s0 269s interval : 3000 269s ip : 10.0.2.123 269s manager-type : basic 269s netmask : 32 269s retry-after : 250 269s retry-num : 3 269s trigger-key : service/pgcluster/leader 269s trigger-value : autopkgtest 269s verbose : false 269s version : false 269s 2025-03-15T17:25:18.625Z INFO IP address 10.0.2.123/32 is down, must be down 269s 2025-03-15T17:25:18.626Z INFO Setting WATCH on service/pgcluster/leader 271s 2025-03-15T17:25:20.634Z INFO Current leader from DCS: autopkgtest 271s 2025-03-15T17:25:20.635Z INFO IP address 10.0.2.123/32 is down, must be up 271s 2025-03-15T17:25:20.635Z INFO Configuring address 10.0.2.123/32 on enp1s0 271s OK 271s 2025-03-15T17:25:20.639Z INFO Sent gratuitous ARP reply 271s 2025-03-15T17:25:20.639Z INFO Sent gratuitous ARP request 273s inet 10.0.2.123/32 scope global enp1s0 273s Ncat: Version 7.95 ( https://nmap.org/ncat ) 273s Ncat: Connected to 10.0.2.123:12345. 273s Ncat: 0 bytes sent, 0 bytes received in 0.03 seconds. 273s Ncat: Connection from 10.0.2.123:48930. 273s OK 273s 2025-03-15T17:25:22.706Z INFO Current leader from DCS: 0xGARBAGE 273s 2025-03-15T17:25:22.706Z INFO IP address 10.0.2.123/32 is up, must be down 273s 2025-03-15T17:25:22.706Z INFO Removing address 10.0.2.123/32 on enp1s0 275s Ncat: Version 7.95 ( https://nmap.org/ncat ) 275s Ncat: Connection refused. 275s ### You've reached the end of the script, all "tests" have successfully been passed! ### 275s {"level":"info","ts":"2025-03-15T17:25:24.790013Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 275s {"level":"info","ts":"2025-03-15T17:25:24.790167Z","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"]} 275s {"level":"warn","ts":"2025-03-15T17:25:24.790411Z","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"} 275s {"level":"warn","ts":"2025-03-15T17:25:24.790960Z","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"} 275s {"level":"info","ts":"2025-03-15T17:25:24.791046Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 275s {"level":"info","ts":"2025-03-15T17:25:24.796189Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 275s {"level":"info","ts":"2025-03-15T17:25:24.797033Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 275s {"level":"info","ts":"2025-03-15T17:25:24.797217Z","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"]} 276s autopkgtest [17:25:25]: test test: -----------------------] 276s test PASS 276s autopkgtest [17:25:25]: test test: - - - - - - - - - - results - - - - - - - - - - 277s autopkgtest [17:25:26]: test cacert-test: preparing testbed 277s Reading package lists... 277s Building dependency tree... 277s Reading state information... 278s Starting pkgProblemResolver with broken count: 0 278s Starting 2 pkgProblemResolver with broken count: 0 278s Done 278s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 279s autopkgtest [17:25:28]: test cacert-test: [----------------------- 280s ○ etcd.service - etcd - highly-available key value store 280s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 280s Active: inactive (dead) since Sat 2025-03-15 17:25:16 UTC; 13s ago 280s Duration: 2.983s 280s Invocation: 9151423ed7cf4c4fa5ba80cb75b4ba13 280s Docs: https://etcd.io/docs 280s man:etcd 280s Process: 1486 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 280s Main PID: 1486 (code=killed, signal=TERM) 280s Mem peak: 8.8M 280s CPU: 132ms 280s 280s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"info","ts":"2025-03-15T17:25:16.472102Z","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"]} 280s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"warn","ts":"2025-03-15T17:25:16.472215Z","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"} 280s Mar 15 17:25:16 autopkgtest systemd[1]: Stopping etcd.service - etcd - highly-available key value store... 280s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"warn","ts":"2025-03-15T17:25:16.473176Z","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"} 280s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"info","ts":"2025-03-15T17:25:16.473285Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 280s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"info","ts":"2025-03-15T17:25:16.476957Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 280s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"info","ts":"2025-03-15T17:25:16.477444Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 280s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"info","ts":"2025-03-15T17:25:16.477479Z","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"]} 280s Mar 15 17:25:16 autopkgtest systemd[1]: etcd.service: Deactivated successfully. 280s Mar 15 17:25:16 autopkgtest systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 280s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 280s {"level":"warn","ts":"2025-03-15T17:25:29.669223Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_UNSUPPORTED_ARCH=arm64"} 280s {"level":"warn","ts":"2025-03-15T17:25:29.669509Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 280s {"level":"info","ts":"2025-03-15T17:25:29.669554Z","caller":"etcdmain/etcd.go:73","msg":"Running: ","args":["etcd","--enable-v2","--cert-file=test/certs/etcd_server.crt","--key-file=test/certs/etcd_server.key","--listen-client-urls","https://127.0.0.1:2379","--advertise-client-urls","https://127.0.0.1:2379"]} 280s {"level":"warn","ts":"2025-03-15T17:25:29.669581Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 280s {"level":"info","ts":"2025-03-15T17:25:29.669637Z","caller":"etcdmain/etcd.go:116","msg":"server has been already initialized","data-dir":"default.etcd","dir-type":"member"} 280s {"level":"warn","ts":"2025-03-15T17:25:29.669654Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 280s {"level":"info","ts":"2025-03-15T17:25:29.669667Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 280s {"level":"info","ts":"2025-03-15T17:25:29.670065Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["https://127.0.0.1:2379"]} 280s {"level":"info","ts":"2025-03-15T17:25:29.670166Z","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":true,"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":["https://127.0.0.1:2379"],"listen-client-urls":["https://127.0.0.1:2379"],"listen-metrics-urls":[],"cors":["*"],"host-whitelist":["*"],"initial-cluster":"","initial-cluster-state":"new","initial-cluster-token":"","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"} 280s {"level":"info","ts":"2025-03-15T17:25:29.676573Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"6.21ms"} 280s {"level":"info","ts":"2025-03-15T17:25:29.676902Z","caller":"etcdserver/server.go:532","msg":"No snapshot found. Recovering WAL from scratch!"} 280s {"level":"info","ts":"2025-03-15T17:25:29.677501Z","caller":"etcdserver/raft.go:540","msg":"restarting local member","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","commit-index":7} 280s {"level":"info","ts":"2025-03-15T17:25:29.677598Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 280s {"level":"info","ts":"2025-03-15T17:25:29.677645Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 2"} 280s {"level":"info","ts":"2025-03-15T17:25:29.677662Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 2, commit: 7, applied: 0, lastindex: 7, lastterm: 2]"} 280s {"level":"warn","ts":"2025-03-15T17:25:29.679260Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 280s {"level":"info","ts":"2025-03-15T17:25:29.680715Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":3} 280s {"level":"info","ts":"2025-03-15T17:25:29.682616Z","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"} 280s {"level":"info","ts":"2025-03-15T17:25:29.683756Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 280s {"level":"info","ts":"2025-03-15T17:25:29.683843Z","caller":"etcdserver/server.go:773","msg":"starting initial election tick advance","election-ticks":10} 280s {"level":"info","ts":"2025-03-15T17:25:29.683946Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 280s {"level":"info","ts":"2025-03-15T17:25:29.684120Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 280s {"level":"info","ts":"2025-03-15T17:25:29.684187Z","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"]} 280s {"level":"info","ts":"2025-03-15T17:25:29.684275Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 280s {"level":"info","ts":"2025-03-15T17:25:29.684301Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 280s {"level":"info","ts":"2025-03-15T17:25:29.684389Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 280s {"level":"info","ts":"2025-03-15T17:25:29.684418Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 280s {"level":"info","ts":"2025-03-15T17:25:29.684431Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 280s {"level":"info","ts":"2025-03-15T17:25:29.686883Z","caller":"embed/etcd.go:729","msg":"starting with client TLS","tls-info":"cert = test/certs/etcd_server.crt, key = test/certs/etcd_server.key, client-cert=, client-key=, trusted-ca = , client-cert-auth = false, crl-file = ","cipher-suites":[]} 280s {"level":"warn","ts":"2025-03-15T17:25:29.687016Z","caller":"embed/etcd.go:742","msg":"Flag `enable-v2` is deprecated and will get removed in etcd 3.6."} 280s {"level":"info","ts":"2025-03-15T17:25:29.687075Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 280s {"level":"info","ts":"2025-03-15T17:25:29.687101Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 280s {"level":"info","ts":"2025-03-15T17:25:29.687215Z","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":["https://127.0.0.1:2379"],"listen-client-urls":["https://127.0.0.1:2379"],"listen-metrics-urls":[]} 282s {"level":"info","ts":"2025-03-15T17:25:31.579088Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 2"} 282s {"level":"info","ts":"2025-03-15T17:25:31.579139Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 2"} 282s {"level":"info","ts":"2025-03-15T17:25:31.579181Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 2"} 282s {"level":"info","ts":"2025-03-15T17:25:31.579192Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 3"} 282s {"level":"info","ts":"2025-03-15T17:25:31.579226Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 3"} 282s {"level":"info","ts":"2025-03-15T17:25:31.579235Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 3"} 282s {"level":"info","ts":"2025-03-15T17:25:31.579241Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 3"} 282s {"level":"info","ts":"2025-03-15T17:25:31.583980Z","caller":"etcdserver/server.go:2140","msg":"published local member to cluster through raft","local-member-id":"8e9e05c52164694d","local-member-attributes":"{Name:default ClientURLs:[https://127.0.0.1:2379]}","request-path":"/0/members/8e9e05c52164694d/attributes","cluster-id":"cdf818194e3a8c32","publish-timeout":"7s"} 282s {"level":"info","ts":"2025-03-15T17:25:31.583992Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 282s {"level":"info","ts":"2025-03-15T17:25:31.584697Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 282s {"level":"info","ts":"2025-03-15T17:25:31.584735Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 282s {"level":"info","ts":"2025-03-15T17:25:31.585335Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 282s {"level":"info","ts":"2025-03-15T17:25:31.586623Z","caller":"embed/serve.go:251","msg":"serving client traffic securely","traffic":"grpc+http","address":"127.0.0.1:2379"} 282s Ncat: Version 7.95 ( https://nmap.org/ncat ) 282s Ncat: Listening on 0.0.0.0:12345 282s 1 284s OK 286s inet 10.0.2.123/32 scope global enp1s0 286s Ncat: Version 7.95 ( https://nmap.org/ncat ) 286s ### You've reached the end of the script, all "tests" have successfully been passed! ### 286s Ncat: Connected to 10.0.2.123:12345. 286s Ncat: 0 bytes sent, 0 bytes received in 0.02 seconds. 286s Ncat: Connection from 10.0.2.123:53206. 286s {"level":"info","ts":"2025-03-15T17:25:35.811225Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 286s {"level":"info","ts":"2025-03-15T17:25:35.811433Z","caller":"embed/etcd.go:378","msg":"closing etcd server","name":"default","data-dir":"default.etcd","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["https://127.0.0.1:2379"]} 286s {"level":"warn","ts":"2025-03-15T17:25:35.811649Z","caller":"embed/serve.go:213","msg":"stopping secure grpc server due to error","error":"accept tcp 127.0.0.1:2379: use of closed network connection"} 286s {"level":"warn","ts":"2025-03-15T17:25:35.811938Z","caller":"embed/serve.go:215","msg":"stopped secure grpc server due to error","error":"accept tcp 127.0.0.1:2379: use of closed network connection"} 286s {"level":"info","ts":"2025-03-15T17:25:35.814006Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 286s {"level":"info","ts":"2025-03-15T17:25:35.820607Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 286s {"level":"info","ts":"2025-03-15T17:25:35.820920Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 286s {"level":"info","ts":"2025-03-15T17:25:35.820991Z","caller":"embed/etcd.go:380","msg":"closed etcd server","name":"default","data-dir":"default.etcd","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["https://127.0.0.1:2379"]} 287s autopkgtest [17:25:36]: test cacert-test: -----------------------] 287s autopkgtest [17:25:36]: test cacert-test: - - - - - - - - - - results - - - - - - - - - - 287s cacert-test PASS 288s autopkgtest [17:25:37]: test clientcert-test: preparing testbed 288s Reading package lists... 288s Building dependency tree... 288s Reading state information... 288s Starting pkgProblemResolver with broken count: 0 289s Starting 2 pkgProblemResolver with broken count: 0 289s Done 289s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 291s autopkgtest [17:25:40]: test clientcert-test: [----------------------- 292s ○ etcd.service - etcd - highly-available key value store 292s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 292s Active: inactive (dead) since Sat 2025-03-15 17:25:16 UTC; 24s ago 292s Duration: 2.983s 292s Invocation: 9151423ed7cf4c4fa5ba80cb75b4ba13 292s Docs: https://etcd.io/docs 292s man:etcd 292s Process: 1486 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 292s Main PID: 1486 (code=killed, signal=TERM) 292s Mem peak: 8.8M 292s CPU: 132ms 292s 292s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"info","ts":"2025-03-15T17:25:16.472102Z","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"]} 292s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"warn","ts":"2025-03-15T17:25:16.472215Z","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"} 292s Mar 15 17:25:16 autopkgtest systemd[1]: Stopping etcd.service - etcd - highly-available key value store... 292s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"warn","ts":"2025-03-15T17:25:16.473176Z","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"} 292s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"info","ts":"2025-03-15T17:25:16.473285Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 292s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"info","ts":"2025-03-15T17:25:16.476957Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 292s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"info","ts":"2025-03-15T17:25:16.477444Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 292s Mar 15 17:25:16 autopkgtest etcd[1486]: {"level":"info","ts":"2025-03-15T17:25:16.477479Z","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"]} 292s Mar 15 17:25:16 autopkgtest systemd[1]: etcd.service: Deactivated successfully. 292s Mar 15 17:25:16 autopkgtest systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 292s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 292s inet 10.0.2.123/32 scope global enp1s0 292s {"level":"warn","ts":"2025-03-15T17:25:41.386659Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_UNSUPPORTED_ARCH=arm64"} 292s {"level":"warn","ts":"2025-03-15T17:25:41.386873Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 292s {"level":"info","ts":"2025-03-15T17:25:41.386898Z","caller":"etcdmain/etcd.go:73","msg":"Running: ","args":["etcd","--enable-v2","--cert-file=test/certs/etcd_server.crt","--key-file=test/certs/etcd_server.key","--listen-client-urls","https://127.0.0.1:2379","--advertise-client-urls","https://127.0.0.1:2379"]} 292s {"level":"warn","ts":"2025-03-15T17:25:41.386925Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 292s {"level":"info","ts":"2025-03-15T17:25:41.386985Z","caller":"etcdmain/etcd.go:116","msg":"server has been already initialized","data-dir":"default.etcd","dir-type":"member"} 292s {"level":"warn","ts":"2025-03-15T17:25:41.387004Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 292s {"level":"info","ts":"2025-03-15T17:25:41.387012Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 292s {"level":"info","ts":"2025-03-15T17:25:41.387640Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["https://127.0.0.1:2379"]} 292s {"level":"info","ts":"2025-03-15T17:25:41.387766Z","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":true,"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":["https://127.0.0.1:2379"],"listen-client-urls":["https://127.0.0.1:2379"],"listen-metrics-urls":[],"cors":["*"],"host-whitelist":["*"],"initial-cluster":"","initial-cluster-state":"new","initial-cluster-token":"","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"} 292s {"level":"info","ts":"2025-03-15T17:25:41.389223Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"1.210184ms"} 292s {"level":"info","ts":"2025-03-15T17:25:41.389510Z","caller":"etcdserver/server.go:532","msg":"No snapshot found. Recovering WAL from scratch!"} 292s {"level":"info","ts":"2025-03-15T17:25:41.390021Z","caller":"etcdserver/raft.go:540","msg":"restarting local member","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","commit-index":11} 292s {"level":"info","ts":"2025-03-15T17:25:41.390327Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 292s {"level":"info","ts":"2025-03-15T17:25:41.390465Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 3"} 292s {"level":"info","ts":"2025-03-15T17:25:41.390497Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 3, commit: 11, applied: 0, lastindex: 11, lastterm: 3]"} 292s {"level":"warn","ts":"2025-03-15T17:25:41.393419Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 292s {"level":"info","ts":"2025-03-15T17:25:41.395113Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":5} 292s {"level":"info","ts":"2025-03-15T17:25:41.396511Z","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"} 292s {"level":"info","ts":"2025-03-15T17:25:41.397760Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 292s {"level":"info","ts":"2025-03-15T17:25:41.398008Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 292s {"level":"info","ts":"2025-03-15T17:25:41.398143Z","caller":"etcdserver/server.go:773","msg":"starting initial election tick advance","election-ticks":10} 292s {"level":"info","ts":"2025-03-15T17:25:41.398254Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 292s {"level":"info","ts":"2025-03-15T17:25:41.398287Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 292s {"level":"info","ts":"2025-03-15T17:25:41.398294Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 292s {"level":"info","ts":"2025-03-15T17:25:41.398652Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 292s {"level":"info","ts":"2025-03-15T17:25:41.398706Z","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"]} 292s {"level":"info","ts":"2025-03-15T17:25:41.398788Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 292s {"level":"info","ts":"2025-03-15T17:25:41.398811Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 292s {"level":"info","ts":"2025-03-15T17:25:41.401062Z","caller":"embed/etcd.go:729","msg":"starting with client TLS","tls-info":"cert = test/certs/etcd_server.crt, key = test/certs/etcd_server.key, client-cert=, client-key=, trusted-ca = , client-cert-auth = false, crl-file = ","cipher-suites":[]} 292s {"level":"warn","ts":"2025-03-15T17:25:41.401162Z","caller":"embed/etcd.go:742","msg":"Flag `enable-v2` is deprecated and will get removed in etcd 3.6."} 292s {"level":"info","ts":"2025-03-15T17:25:41.401227Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 292s {"level":"info","ts":"2025-03-15T17:25:41.401260Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 292s {"level":"info","ts":"2025-03-15T17:25:41.401290Z","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":["https://127.0.0.1:2379"],"listen-client-urls":["https://127.0.0.1:2379"],"listen-metrics-urls":[]} 294s {"level":"info","ts":"2025-03-15T17:25:43.090755Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 3"} 294s {"level":"info","ts":"2025-03-15T17:25:43.090879Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 3"} 294s {"level":"info","ts":"2025-03-15T17:25:43.090912Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 3"} 294s {"level":"info","ts":"2025-03-15T17:25:43.090952Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 4"} 294s {"level":"info","ts":"2025-03-15T17:25:43.091026Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 4"} 294s {"level":"info","ts":"2025-03-15T17:25:43.091056Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 4"} 294s {"level":"info","ts":"2025-03-15T17:25:43.091076Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 4"} 294s {"level":"info","ts":"2025-03-15T17:25:43.095822Z","caller":"etcdserver/server.go:2140","msg":"published local member to cluster through raft","local-member-id":"8e9e05c52164694d","local-member-attributes":"{Name:default ClientURLs:[https://127.0.0.1:2379]}","request-path":"/0/members/8e9e05c52164694d/attributes","cluster-id":"cdf818194e3a8c32","publish-timeout":"7s"} 294s {"level":"info","ts":"2025-03-15T17:25:43.095848Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 294s {"level":"info","ts":"2025-03-15T17:25:43.096100Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 294s {"level":"info","ts":"2025-03-15T17:25:43.096127Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 294s {"level":"info","ts":"2025-03-15T17:25:43.097279Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 294s {"level":"info","ts":"2025-03-15T17:25:43.098457Z","caller":"embed/serve.go:251","msg":"serving client traffic securely","traffic":"grpc+http","address":"127.0.0.1:2379"} 294s Ncat: Version 7.95 ( https://nmap.org/ncat ) 294s Ncat: Listening on 0.0.0.0:12345 294s 1 296s OK 298s inet 10.0.2.123/32 scope global enp1s0 298s Ncat: Version 7.95 ( https://nmap.org/ncat ) 298s Ncat: Ncat: Connected to 10.0.2.123:12345. 298s Connection from 10.0.2.123:37376Ncat: . 298s 0 bytes sent, 0 bytes received in 0.03 seconds. 298s ### You've reached the end of the script, all "tests" have successfully been passed! ### 298s {"level":"info","ts":"2025-03-15T17:25:47.538504Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 298s {"level":"info","ts":"2025-03-15T17:25:47.538589Z","caller":"embed/etcd.go:378","msg":"closing etcd server","name":"default","data-dir":"default.etcd","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["https://127.0.0.1:2379"]} 298s {"level":"warn","ts":"2025-03-15T17:25:47.538684Z","caller":"embed/serve.go:213","msg":"stopping secure grpc server due to error","error":"accept tcp 127.0.0.1:2379: use of closed network connection"} 298s {"level":"warn","ts":"2025-03-15T17:25:47.538907Z","caller":"embed/serve.go:215","msg":"stopped secure grpc server due to error","error":"accept tcp 127.0.0.1:2379: use of closed network connection"} 298s {"level":"info","ts":"2025-03-15T17:25:47.539986Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 298s {"level":"info","ts":"2025-03-15T17:25:47.544320Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 298s {"level":"info","ts":"2025-03-15T17:25:47.544492Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 298s {"level":"info","ts":"2025-03-15T17:25:47.544504Z","caller":"embed/etcd.go:380","msg":"closed etcd server","name":"default","data-dir":"default.etcd","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["https://127.0.0.1:2379"]} 298s autopkgtest [17:25:47]: test clientcert-test: -----------------------] 299s autopkgtest [17:25:48]: test clientcert-test: - - - - - - - - - - results - - - - - - - - - - 299s clientcert-test PASS 299s autopkgtest [17:25:48]: @@@@@@@@@@@@@@@@@@@@ summary 299s test PASS 299s cacert-test PASS 299s clientcert-test PASS 323s nova [W] Using flock in prodstack6-arm64 323s flock: timeout while waiting to get lock 323s Creating nova instance adt-plucky-arm64-vip-manager2-20250315-172048-juju-7f2275-prod-proposed-migration-environment-15-ab3e22dc-fa41-42d0-82e0-6693deef060f from image adt/ubuntu-plucky-arm64-server-20250315.img (UUID bd6e766c-b51f-4b53-86d6-23aa4d18f524)... 323s nova [W] Timed out waiting for 495cbd07-ed2f-4018-a1ec-30f55e867e33 to get deleted.