0s autopkgtest [19:41:36]: starting date and time: 2025-03-15 19:41:36+0000 0s autopkgtest [19:41:36]: git checkout: 325255d2 Merge branch 'pin-any-arch' into 'ubuntu/production' 0s autopkgtest [19:41:36]: host juju-7f2275-prod-proposed-migration-environment-15; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.a_s09aok/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-s390x --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-15@bos03-s390x-32.secgroup --name adt-plucky-s390x-vip-manager2-20250315-194136-juju-7f2275-prod-proposed-migration-environment-15-35799ac2-3283-4d5a-811e-f8e13e38aa6a --image adt/ubuntu-plucky-s390x-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-15 --net-id=net_prod-proposed-migration-s390x -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com,radosgw.ps5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 113s autopkgtest [19:43:29]: testbed dpkg architecture: s390x 113s autopkgtest [19:43:29]: testbed apt version: 2.9.33 114s autopkgtest [19:43:30]: @@@@@@@@@@@@@@@@@@@@ test bed setup 114s autopkgtest [19:43:30]: testbed release detected to be: None 114s autopkgtest [19:43:30]: updating testbed package index (apt update) 115s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [126 kB] 115s Hit:2 http://ftpmaster.internal/ubuntu plucky InRelease 115s Hit:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease 115s Hit:4 http://ftpmaster.internal/ubuntu plucky-security InRelease 115s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [45.1 kB] 115s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [14.5 kB] 115s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [369 kB] 115s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x Packages [77.3 kB] 115s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x c-n-f Metadata [1824 B] 115s Get:10 http://ftpmaster.internal/ubuntu plucky-proposed/restricted s390x c-n-f Metadata [116 B] 115s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/universe s390x Packages [314 kB] 116s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/universe s390x c-n-f Metadata [13.3 kB] 116s Get:13 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse s390x Packages [3532 B] 116s Get:14 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse s390x c-n-f Metadata [240 B] 116s Fetched 965 kB in 1s (960 kB/s) 116s Reading package lists... 117s + lsb_release --codename --short 117s + RELEASE=plucky 117s + cat 117s + [ plucky != trusty ] 117s + DEBIAN_FRONTEND=noninteractive eatmydata apt-get -y --allow-downgrades -o Dpkg::Options::=--force-confnew dist-upgrade 117s Reading package lists... 117s Building dependency tree... 117s Reading state information... 117s Calculating upgrade... 117s Calculating upgrade... 117s The following packages were automatically installed and are no longer required: 117s libnsl2 libpython3.12-minimal libpython3.12-stdlib libpython3.12t64 117s linux-headers-6.11.0-8 linux-headers-6.11.0-8-generic 117s linux-modules-6.11.0-8-generic linux-tools-6.11.0-8 117s linux-tools-6.11.0-8-generic 117s Use 'sudo apt autoremove' to remove them. 117s The following packages will be upgraded: 117s pinentry-curses python3-jinja2 strace 117s 3 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 117s Need to get 652 kB of archives. 117s After this operation, 27.6 kB of additional disk space will be used. 117s Get:1 http://ftpmaster.internal/ubuntu plucky/main s390x strace s390x 6.13+ds-1ubuntu1 [500 kB] 118s Get:2 http://ftpmaster.internal/ubuntu plucky/main s390x pinentry-curses s390x 1.3.1-2ubuntu3 [42.9 kB] 118s Get:3 http://ftpmaster.internal/ubuntu plucky/main s390x python3-jinja2 all 3.1.5-2ubuntu1 [109 kB] 118s Fetched 652 kB in 1s (808 kB/s) 118s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 81428 files and directories currently installed.) 118s Preparing to unpack .../strace_6.13+ds-1ubuntu1_s390x.deb ... 118s Unpacking strace (6.13+ds-1ubuntu1) over (6.11-0ubuntu1) ... 119s Preparing to unpack .../pinentry-curses_1.3.1-2ubuntu3_s390x.deb ... 119s Unpacking pinentry-curses (1.3.1-2ubuntu3) over (1.3.1-2ubuntu2) ... 119s Preparing to unpack .../python3-jinja2_3.1.5-2ubuntu1_all.deb ... 119s Unpacking python3-jinja2 (3.1.5-2ubuntu1) over (3.1.5-2) ... 119s Setting up pinentry-curses (1.3.1-2ubuntu3) ... 119s Setting up python3-jinja2 (3.1.5-2ubuntu1) ... 119s Setting up strace (6.13+ds-1ubuntu1) ... 119s Processing triggers for man-db (2.13.0-1) ... 119s + rm /etc/apt/preferences.d/force-downgrade-to-release.pref 119s + /usr/lib/apt/apt-helper analyze-pattern ?true 119s + uname -r 119s + sed s/\./\\./g 119s + running_kernel_pattern=^linux-.*6\.14\.0-10-generic.* 119s + apt list ?obsolete 119s + tail -n+2 119s + cut+ grep -v ^linux-.*6\.14\.0-10-generic.* 119s -d/ -f1 119s + obsolete_pkgs=linux-headers-6.11.0-8-generic 119s linux-headers-6.11.0-8 119s linux-modules-6.11.0-8-generic 119s linux-tools-6.11.0-8-generic 119s linux-tools-6.11.0-8 119s + DEBIAN_FRONTEND=noninteractive eatmydata apt-get -y purge --autoremove linux-headers-6.11.0-8-generic linux-headers-6.11.0-8 linux-modules-6.11.0-8-generic linux-tools-6.11.0-8-generic linux-tools-6.11.0-8 119s Reading package lists... 120s Building dependency tree... 120s Reading state information... 120s Solving dependencies... 120s The following packages will be REMOVED: 120s libnsl2* libpython3.12-minimal* libpython3.12-stdlib* libpython3.12t64* 120s linux-headers-6.11.0-8* linux-headers-6.11.0-8-generic* 120s linux-modules-6.11.0-8-generic* linux-tools-6.11.0-8* 120s linux-tools-6.11.0-8-generic* 120s 0 upgraded, 0 newly installed, 9 to remove and 5 not upgraded. 120s After this operation, 167 MB disk space will be freed. 120s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 81428 files and directories currently installed.) 120s Removing linux-tools-6.11.0-8-generic (6.11.0-8.8) ... 120s Removing linux-tools-6.11.0-8 (6.11.0-8.8) ... 120s Removing libpython3.12t64:s390x (3.12.9-1) ... 120s Removing libpython3.12-stdlib:s390x (3.12.9-1) ... 120s Removing libnsl2:s390x (1.3.0-3build3) ... 120s Removing libpython3.12-minimal:s390x (3.12.9-1) ... 120s Removing linux-headers-6.11.0-8-generic (6.11.0-8.8) ... 120s Removing linux-headers-6.11.0-8 (6.11.0-8.8) ... 121s Removing linux-modules-6.11.0-8-generic (6.11.0-8.8) ... 121s Processing triggers for libc-bin (2.41-1ubuntu1) ... 121s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 56328 files and directories currently installed.) 121s Purging configuration files for libpython3.12-minimal:s390x (3.12.9-1) ... 121s Purging configuration files for linux-modules-6.11.0-8-generic (6.11.0-8.8) ... 121s + grep -q trusty /etc/lsb-release 121s + [ ! -d /usr/share/doc/unattended-upgrades ] 121s + [ ! -d /usr/share/doc/lxd ] 121s + [ ! -d /usr/share/doc/lxd-client ] 121s + [ ! -d /usr/share/doc/snapd ] 121s + type iptables 121s + cat 121s + chmod 755 /etc/rc.local 121s + . /etc/rc.local 121s + iptables -w -t mangle -A FORWARD -p tcp --tcp-flags SYN,RST SYN -j TCPMSS --clamp-mss-to-pmtu 121s + iptables -A OUTPUT -d 10.255.255.1/32 -p tcp -j DROP 121s + iptables -A OUTPUT -d 10.255.255.2/32 -p tcp -j DROP 121s + uname -m 121s + [ s390x = ppc64le ] 121s + [ -d /run/systemd/system ] 121s + systemd-detect-virt --quiet --vm 121s + mkdir -p /etc/systemd/system/systemd-random-seed.service.d/ 121s + cat 121s + grep -q lz4 /etc/initramfs-tools/initramfs.conf 121s + echo COMPRESS=lz4 121s autopkgtest [19:43:37]: upgrading testbed (apt dist-upgrade and autopurge) 121s Reading package lists... 122s Building dependency tree... 122s Reading state information... 122s Calculating upgrade...Starting pkgProblemResolver with broken count: 0 122s Starting 2 pkgProblemResolver with broken count: 0 122s Done 122s Entering ResolveByKeep 122s 122s Calculating upgrade... 122s The following packages will be upgraded: 122s libc-bin libc-dev-bin libc6 libc6-dev locales 122s 5 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 122s Need to get 9512 kB of archives. 122s After this operation, 8192 B of additional disk space will be used. 122s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libc6-dev s390x 2.41-1ubuntu2 [1678 kB] 123s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libc-dev-bin s390x 2.41-1ubuntu2 [24.3 kB] 123s Get:3 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libc6 s390x 2.41-1ubuntu2 [2892 kB] 124s Get:4 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libc-bin s390x 2.41-1ubuntu2 [671 kB] 124s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x locales all 2.41-1ubuntu2 [4246 kB] 125s Preconfiguring packages ... 125s Fetched 9512 kB in 2s (4040 kB/s) 125s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 56326 files and directories currently installed.) 125s Preparing to unpack .../libc6-dev_2.41-1ubuntu2_s390x.deb ... 125s Unpacking libc6-dev:s390x (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 125s Preparing to unpack .../libc-dev-bin_2.41-1ubuntu2_s390x.deb ... 125s Unpacking libc-dev-bin (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 125s Preparing to unpack .../libc6_2.41-1ubuntu2_s390x.deb ... 125s Unpacking libc6:s390x (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 125s Setting up libc6:s390x (2.41-1ubuntu2) ... 125s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 56326 files and directories currently installed.) 125s Preparing to unpack .../libc-bin_2.41-1ubuntu2_s390x.deb ... 125s Unpacking libc-bin (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 125s Setting up libc-bin (2.41-1ubuntu2) ... 125s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 56326 files and directories currently installed.) 125s Preparing to unpack .../locales_2.41-1ubuntu2_all.deb ... 125s Unpacking locales (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 125s Setting up locales (2.41-1ubuntu2) ... 126s Generating locales (this might take a while)... 127s en_US.UTF-8... done 127s Generation complete. 127s Setting up libc-dev-bin (2.41-1ubuntu2) ... 127s Setting up libc6-dev:s390x (2.41-1ubuntu2) ... 127s Processing triggers for man-db (2.13.0-1) ... 127s Processing triggers for systemd (257.3-1ubuntu3) ... 128s Reading package lists... 128s Building dependency tree... 128s Reading state information... 128s Starting pkgProblemResolver with broken count: 0 128s Starting 2 pkgProblemResolver with broken count: 0 128s Done 129s Solving dependencies... 129s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 129s autopkgtest [19:43:45]: rebooting testbed after setup commands that affected boot 149s autopkgtest [19:44:05]: testbed running kernel: Linux 6.14.0-10-generic #10-Ubuntu SMP Wed Mar 12 14:53:49 UTC 2025 151s autopkgtest [19:44:07]: @@@@@@@@@@@@@@@@@@@@ apt-source vip-manager2 152s Get:1 http://ftpmaster.internal/ubuntu plucky/universe vip-manager2 3.0.0-2 (dsc) [2487 B] 152s Get:2 http://ftpmaster.internal/ubuntu plucky/universe vip-manager2 3.0.0-2 (tar) [46.4 kB] 152s Get:3 http://ftpmaster.internal/ubuntu plucky/universe vip-manager2 3.0.0-2 (diff) [9200 B] 153s gpgv: Signature made Mon Feb 3 15:49:05 2025 UTC 153s gpgv: using RSA key 5C48FE6157F49179597087C64C5A6BAB12D2A7AE 153s gpgv: Can't check signature: No public key 153s dpkg-source: warning: cannot verify inline signature for ./vip-manager2_3.0.0-2.dsc: no acceptable signature found 153s autopkgtest [19:44:09]: testing package vip-manager2 version 3.0.0-2 153s autopkgtest [19:44:09]: build not needed 153s autopkgtest [19:44:09]: test test: preparing testbed 154s Reading package lists... 154s Building dependency tree... 154s Reading state information... 154s Starting pkgProblemResolver with broken count: 0 154s Starting 2 pkgProblemResolver with broken count: 0 154s Done 154s The following NEW packages will be installed: 154s etcd-client etcd-server liblua5.4-0 ncat vip-manager2 154s 0 upgraded, 5 newly installed, 0 to remove and 0 not upgraded. 154s Need to get 21.9 MB of archives. 154s After this operation, 84.4 MB of additional disk space will be used. 154s Get:1 http://ftpmaster.internal/ubuntu plucky/universe s390x etcd-server s390x 3.5.16-4 [11.6 MB] 157s Get:2 http://ftpmaster.internal/ubuntu plucky/main s390x liblua5.4-0 s390x 5.4.7-1 [174 kB] 157s Get:3 http://ftpmaster.internal/ubuntu plucky/universe s390x ncat s390x 7.95+dfsg-2 [215 kB] 157s Get:4 http://ftpmaster.internal/ubuntu plucky/universe s390x vip-manager2 s390x 3.0.0-2 [4477 kB] 158s Get:5 http://ftpmaster.internal/ubuntu plucky/universe s390x etcd-client s390x 3.5.16-4 [5492 kB] 159s Fetched 21.9 MB in 4s (5080 kB/s) 159s Selecting previously unselected package etcd-server. 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 ... 56326 files and directories currently installed.) 159s Preparing to unpack .../etcd-server_3.5.16-4_s390x.deb ... 159s Unpacking etcd-server (3.5.16-4) ... 159s Selecting previously unselected package liblua5.4-0:s390x. 159s Preparing to unpack .../liblua5.4-0_5.4.7-1_s390x.deb ... 159s Unpacking liblua5.4-0:s390x (5.4.7-1) ... 159s Selecting previously unselected package ncat. 159s Preparing to unpack .../ncat_7.95+dfsg-2_s390x.deb ... 159s Unpacking ncat (7.95+dfsg-2) ... 159s Selecting previously unselected package vip-manager2. 159s Preparing to unpack .../vip-manager2_3.0.0-2_s390x.deb ... 159s Unpacking vip-manager2 (3.0.0-2) ... 159s Selecting previously unselected package etcd-client. 159s Preparing to unpack .../etcd-client_3.5.16-4_s390x.deb ... 159s Unpacking etcd-client (3.5.16-4) ... 159s Setting up vip-manager2 (3.0.0-2) ... 159s Created symlink '/etc/systemd/system/multi-user.target.wants/vip-manager.service' → '/usr/lib/systemd/system/vip-manager.service'. 160s Setting up etcd-client (3.5.16-4) ... 160s Setting up liblua5.4-0:s390x (5.4.7-1) ... 160s Setting up etcd-server (3.5.16-4) ... 160s info: Selecting UID from range 100 to 999 ... 160s 160s info: Selecting GID from range 100 to 999 ... 160s info: Adding system user `etcd' (UID 107) ... 160s info: Adding new group `etcd' (GID 110) ... 160s info: Adding new user `etcd' (UID 107) with group `etcd' ... 160s info: Creating home directory `/var/lib/etcd/' ... 160s Created symlink '/etc/systemd/system/etcd2.service' → '/usr/lib/systemd/system/etcd.service'. 160s Created symlink '/etc/systemd/system/multi-user.target.wants/etcd.service' → '/usr/lib/systemd/system/etcd.service'. 161s Setting up ncat (7.95+dfsg-2) ... 161s Processing triggers for man-db (2.13.0-1) ... 162s Processing triggers for libc-bin (2.41-1ubuntu2) ... 162s autopkgtest [19:44:18]: test test: [----------------------- 163s ○ etcd.service - etcd - highly-available key value store 163s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 163s Active: inactive (dead) since Sat 2025-03-15 19:45:44 UTC; 8ms ago 163s Duration: 1.908s 163s Invocation: 9b5ad4e98f0a4b62a5b316ceecd73482 163s Docs: https://etcd.io/docs 163s man:etcd 163s Process: 1505 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 163s Main PID: 1505 (code=killed, signal=TERM) 163s Mem peak: 8.3M 163s CPU: 30ms 163s 163s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"info","ts":"2025-03-15T19:45:44.679477Z","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"]} 163s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"warn","ts":"2025-03-15T19:45:44.680032Z","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"} 163s Mar 15 19:45:44 autopkgtest systemd[1]: Stopping etcd.service - etcd - highly-available key value store... 163s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"warn","ts":"2025-03-15T19:45:44.680192Z","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"} 163s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"info","ts":"2025-03-15T19:45:44.680215Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 163s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"info","ts":"2025-03-15T19:45:44.687231Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 163s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"info","ts":"2025-03-15T19:45:44.687301Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 163s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"info","ts":"2025-03-15T19:45:44.687312Z","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"]} 163s Mar 15 19:45:44 autopkgtest systemd[1]: etcd.service: Deactivated successfully. 163s Mar 15 19:45:44 autopkgtest systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 163s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 163s {"level":"warn","ts":"2025-03-15T19:45:44.736541Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_UNSUPPORTED_ARCH=s390x"} 163s {"level":"warn","ts":"2025-03-15T19:45:44.736604Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 163s {"level":"info","ts":"2025-03-15T19:45:44.736624Z","caller":"etcdmain/etcd.go:73","msg":"Running: ","args":["etcd"]} 163s {"level":"warn","ts":"2025-03-15T19:45:44.736640Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 163s {"level":"warn","ts":"2025-03-15T19:45:44.736660Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 163s {"level":"info","ts":"2025-03-15T19:45:44.736666Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 163s {"level":"info","ts":"2025-03-15T19:45:44.736993Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["http://localhost:2379"]} 163s {"level":"info","ts":"2025-03-15T19:45:44.737067Z","caller":"embed/etcd.go:311","msg":"starting an etcd server","etcd-version":"3.5.16","git-sha":"Not provided (use ./build instead of go build)","go-version":"go1.24.1","go-os":"linux","go-arch":"s390x","max-cpu-set":2,"max-cpu-available":2,"member-initialized":false,"name":"default","data-dir":"default.etcd","wal-dir":"","wal-dir-dedicated":"","member-dir":"default.etcd/member","force-new-cluster":false,"heartbeat-interval":"100ms","election-timeout":"1s","initial-election-tick-advance":true,"snapshot-count":100000,"max-wals":5,"max-snapshots":5,"snapshot-catchup-entries":5000,"initial-advertise-peer-urls":["http://localhost:2380"],"listen-peer-urls":["http://localhost:2380"],"advertise-client-urls":["http://localhost:2379"],"listen-client-urls":["http://localhost:2379"],"listen-metrics-urls":[],"cors":["*"],"host-whitelist":["*"],"initial-cluster":"default=http://localhost:2380","initial-cluster-state":"new","initial-cluster-token":"etcd-cluster","quota-backend-bytes":2147483648,"max-request-bytes":1572864,"max-concurrent-streams":4294967295,"pre-vote":true,"initial-corrupt-check":false,"corrupt-check-time-interval":"0s","compact-check-time-enabled":false,"compact-check-time-interval":"1m0s","auto-compaction-mode":"periodic","auto-compaction-retention":"0s","auto-compaction-interval":"0s","discovery-url":"","discovery-proxy":"","downgrade-check-interval":"5s"} 163s {"level":"info","ts":"2025-03-15T19:45:44.738854Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"1.617824ms"} 163s {"level":"info","ts":"2025-03-15T19:45:44.741968Z","caller":"etcdserver/raft.go:505","msg":"starting local member","local-member-id":"8e9e05c52164694d","cluster-id":"cdf818194e3a8c32"} 163s {"level":"info","ts":"2025-03-15T19:45:44.742002Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 163s {"level":"info","ts":"2025-03-15T19:45:44.742022Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 0"} 163s {"level":"info","ts":"2025-03-15T19:45:44.742031Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]"} 163s {"level":"info","ts":"2025-03-15T19:45:44.742039Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 1"} 163s {"level":"info","ts":"2025-03-15T19:45:44.742066Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 163s {"level":"warn","ts":"2025-03-15T19:45:44.743699Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 163s {"level":"info","ts":"2025-03-15T19:45:44.744569Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":1} 163s {"level":"info","ts":"2025-03-15T19:45:44.744888Z","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"} 163s {"level":"info","ts":"2025-03-15T19:45:44.745170Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 163s {"level":"info","ts":"2025-03-15T19:45:44.745248Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 163s {"level":"info","ts":"2025-03-15T19:45:44.746610Z","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":[]} 163s {"level":"info","ts":"2025-03-15T19:45:44.746665Z","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"} 163s {"level":"info","ts":"2025-03-15T19:45:44.746911Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 163s {"level":"info","ts":"2025-03-15T19:45:44.746936Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 163s {"level":"info","ts":"2025-03-15T19:45:44.746943Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 163s {"level":"info","ts":"2025-03-15T19:45:44.746972Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 163s {"level":"info","ts":"2025-03-15T19:45:44.746989Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 163s {"level":"info","ts":"2025-03-15T19:45:44.748268Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 163s {"level":"info","ts":"2025-03-15T19:45:44.748324Z","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"]} 163s {"level":"info","ts":"2025-03-15T19:45:45.342817Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 1"} 163s {"level":"info","ts":"2025-03-15T19:45:45.342921Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 1"} 163s {"level":"info","ts":"2025-03-15T19:45:45.343014Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 1"} 163s {"level":"info","ts":"2025-03-15T19:45:45.343032Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 2"} 163s {"level":"info","ts":"2025-03-15T19:45:45.343043Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 2"} 163s {"level":"info","ts":"2025-03-15T19:45:45.343054Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 2"} 163s {"level":"info","ts":"2025-03-15T19:45:45.343064Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 2"} 163s {"level":"info","ts":"2025-03-15T19:45:45.343581Z","caller":"etcdserver/server.go:2651","msg":"setting up initial cluster version using v2 API","cluster-version":"3.5"} 163s {"level":"info","ts":"2025-03-15T19:45:45.343864Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 163s {"level":"info","ts":"2025-03-15T19:45:45.343946Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 163s {"level":"info","ts":"2025-03-15T19:45:45.343943Z","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"} 163s {"level":"info","ts":"2025-03-15T19:45:45.343960Z","caller":"etcdserver/server.go:2675","msg":"cluster version is updated","cluster-version":"3.5"} 163s {"level":"info","ts":"2025-03-15T19:45:45.343979Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 163s {"level":"info","ts":"2025-03-15T19:45:45.344159Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 163s {"level":"info","ts":"2025-03-15T19:45:45.344174Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 163s {"level":"info","ts":"2025-03-15T19:45:45.344550Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 163s {"level":"info","ts":"2025-03-15T19:45:45.345069Z","caller":"embed/serve.go:188","msg":"serving client traffic insecurely; this is strongly discouraged!","traffic":"grpc+http","address":"127.0.0.1:2379"} 165s Ncat: Version 7.95 ( https://nmap.org/ncat ) 165s Ncat: Listening on 0.0.0.0:12345 165s 0 165s No dcs-endpoints specified, trying to use localhost with standard ports! 165s This is the config that will be used: 165s dcs-endpoints : [http://127.0.0.1:2379] 165s dcs-type : etcd 165s hostingtype : basic 165s interface : enc1 165s interval : 3000 165s ip : 10.0.2.123 165s manager-type : basic 165s netmask : 32 165s retry-after : 250 165s retry-num : 3 165s trigger-key : service/pgcluster/leader 165s trigger-value : autopkgtest 165s verbose : false 165s version : false 165s 2025-03-15T19:45:46.751Z INFO IP address 10.0.2.123/32 is down, must be down 165s 2025-03-15T19:45:46.751Z INFO Setting WATCH on service/pgcluster/leader 167s OK 167s 2025-03-15T19:45:48.762Z INFO Current leader from DCS: autopkgtest 167s 2025-03-15T19:45:48.762Z INFO IP address 10.0.2.123/32 is down, must be up 167s 2025-03-15T19:45:48.762Z INFO Configuring address 10.0.2.123/32 on enc1 167s 2025-03-15T19:45:48.764Z INFO Sent gratuitous ARP reply 167s 2025-03-15T19:45:48.764Z INFO Sent gratuitous ARP request 169s inet 10.0.2.123/32 scope global enc1 169s Ncat: Version 7.95 ( https://nmap.org/ncat ) 169s Ncat: Connection from 10.0.2.123:50646. 169s Ncat: Connected to 10.0.2.123:12345. 169s Ncat: 0 bytes sent, 0 bytes received in 0.02 seconds. 169s OK 169s 2025-03-15T19:45:50.803Z INFO Current leader from DCS: 0xGARBAGE 169s 2025-03-15T19:45:50.803Z INFO IP address 10.0.2.123/32 is up, must be down 169s 2025-03-15T19:45:50.803Z INFO Removing address 10.0.2.123/32 on enc1 171s Ncat: Version 7.95 ( https://nmap.org/ncat ) 171s Ncat: Connection refused. 171s ### You've reached the end of the script, all "tests" have successfully been passed! ### 171s {"level":"info","ts":"2025-03-15T19:45:52.839763Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 171s {"level":"info","ts":"2025-03-15T19:45:52.839845Z","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"]} 171s {"level":"warn","ts":"2025-03-15T19:45:52.839926Z","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"} 171s {"level":"warn","ts":"2025-03-15T19:45:52.840151Z","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"} 171s {"level":"info","ts":"2025-03-15T19:45:52.840180Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 171s {"level":"info","ts":"2025-03-15T19:45:52.841432Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 171s {"level":"info","ts":"2025-03-15T19:45:52.841575Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 171s {"level":"info","ts":"2025-03-15T19:45:52.841600Z","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"]} 171s autopkgtest [19:44:27]: test test: -----------------------] 172s autopkgtest [19:44:28]: test test: - - - - - - - - - - results - - - - - - - - - - 172s test PASS 172s autopkgtest [19:44:28]: test cacert-test: preparing testbed 172s Reading package lists... 172s Building dependency tree... 172s Reading state information... 172s Starting pkgProblemResolver with broken count: 0 172s Starting 2 pkgProblemResolver with broken count: 0 172s Done 173s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 173s autopkgtest [19:44:29]: test cacert-test: [----------------------- 174s ○ etcd.service - etcd - highly-available key value store 174s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 174s Active: inactive (dead) since Sat 2025-03-15 19:45:44 UTC; 11s ago 174s Duration: 1.908s 174s Invocation: 9b5ad4e98f0a4b62a5b316ceecd73482 174s Docs: https://etcd.io/docs 174s man:etcd 174s Process: 1505 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 174s Main PID: 1505 (code=killed, signal=TERM) 174s Mem peak: 8.3M 174s CPU: 30ms 174s 174s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"info","ts":"2025-03-15T19:45:44.679477Z","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"]} 174s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"warn","ts":"2025-03-15T19:45:44.680032Z","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"} 174s Mar 15 19:45:44 autopkgtest systemd[1]: Stopping etcd.service - etcd - highly-available key value store... 174s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"warn","ts":"2025-03-15T19:45:44.680192Z","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"} 174s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"info","ts":"2025-03-15T19:45:44.680215Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 174s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"info","ts":"2025-03-15T19:45:44.687231Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 174s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"info","ts":"2025-03-15T19:45:44.687301Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 174s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"info","ts":"2025-03-15T19:45:44.687312Z","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"]} 174s Mar 15 19:45:44 autopkgtest systemd[1]: etcd.service: Deactivated successfully. 174s Mar 15 19:45:44 autopkgtest systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 174s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 174s {"level":"warn","ts":"2025-03-15T19:45:56.006359Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_UNSUPPORTED_ARCH=s390x"} 174s {"level":"warn","ts":"2025-03-15T19:45:56.006482Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 174s {"level":"info","ts":"2025-03-15T19:45:56.006502Z","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"]} 174s {"level":"warn","ts":"2025-03-15T19:45:56.006523Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 174s {"level":"info","ts":"2025-03-15T19:45:56.006580Z","caller":"etcdmain/etcd.go:116","msg":"server has been already initialized","data-dir":"default.etcd","dir-type":"member"} 174s {"level":"warn","ts":"2025-03-15T19:45:56.006596Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 174s {"level":"info","ts":"2025-03-15T19:45:56.006603Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 174s {"level":"info","ts":"2025-03-15T19:45:56.007070Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["https://127.0.0.1:2379"]} 174s {"level":"info","ts":"2025-03-15T19:45:56.007137Z","caller":"embed/etcd.go:311","msg":"starting an etcd server","etcd-version":"3.5.16","git-sha":"Not provided (use ./build instead of go build)","go-version":"go1.24.1","go-os":"linux","go-arch":"s390x","max-cpu-set":2,"max-cpu-available":2,"member-initialized":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"} 174s {"level":"info","ts":"2025-03-15T19:45:56.013257Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"5.961415ms"} 174s {"level":"info","ts":"2025-03-15T19:45:56.013457Z","caller":"etcdserver/server.go:532","msg":"No snapshot found. Recovering WAL from scratch!"} 174s {"level":"info","ts":"2025-03-15T19:45:56.013823Z","caller":"etcdserver/raft.go:540","msg":"restarting local member","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","commit-index":7} 174s {"level":"info","ts":"2025-03-15T19:45:56.013876Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 174s {"level":"info","ts":"2025-03-15T19:45:56.013920Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 2"} 174s {"level":"info","ts":"2025-03-15T19:45:56.013997Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 2, commit: 7, applied: 0, lastindex: 7, lastterm: 2]"} 174s {"level":"warn","ts":"2025-03-15T19:45:56.014968Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 174s {"level":"info","ts":"2025-03-15T19:45:56.015785Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":3} 174s {"level":"info","ts":"2025-03-15T19:45:56.016136Z","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"} 174s {"level":"info","ts":"2025-03-15T19:45:56.016451Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 174s {"level":"info","ts":"2025-03-15T19:45:56.016569Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 174s {"level":"info","ts":"2025-03-15T19:45:56.016588Z","caller":"etcdserver/server.go:773","msg":"starting initial election tick advance","election-ticks":10} 174s {"level":"info","ts":"2025-03-15T19:45:56.016661Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 174s {"level":"info","ts":"2025-03-15T19:45:56.016688Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 174s {"level":"info","ts":"2025-03-15T19:45:56.016696Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 174s {"level":"info","ts":"2025-03-15T19:45:56.016856Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 174s {"level":"info","ts":"2025-03-15T19:45:56.016894Z","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"]} 174s {"level":"info","ts":"2025-03-15T19:45:56.016960Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 174s {"level":"info","ts":"2025-03-15T19:45:56.016981Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 174s {"level":"info","ts":"2025-03-15T19:45:56.018370Z","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":[]} 174s {"level":"warn","ts":"2025-03-15T19:45:56.018390Z","caller":"embed/etcd.go:742","msg":"Flag `enable-v2` is deprecated and will get removed in etcd 3.6."} 174s {"level":"info","ts":"2025-03-15T19:45:56.018747Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 174s {"level":"info","ts":"2025-03-15T19:45:56.018755Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 174s {"level":"info","ts":"2025-03-15T19:45:56.018813Z","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":[]} 176s {"level":"info","ts":"2025-03-15T19:44:32.160203Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 2"} 176s {"level":"info","ts":"2025-03-15T19:44:32.160314Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 2"} 176s {"level":"info","ts":"2025-03-15T19:44:32.160401Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 2"} 176s {"level":"info","ts":"2025-03-15T19:44:32.160419Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 3"} 176s {"level":"info","ts":"2025-03-15T19:44:32.160428Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 3"} 176s {"level":"info","ts":"2025-03-15T19:44:32.160458Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 3"} 176s {"level":"info","ts":"2025-03-15T19:44:32.160499Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 3"} 176s {"level":"info","ts":"2025-03-15T19:44:32.161617Z","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"} 176s {"level":"info","ts":"2025-03-15T19:44:32.161612Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 176s {"level":"info","ts":"2025-03-15T19:44:32.161884Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 176s {"level":"info","ts":"2025-03-15T19:44:32.161894Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 176s {"level":"info","ts":"2025-03-15T19:44:32.163577Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 176s {"level":"info","ts":"2025-03-15T19:44:32.165252Z","caller":"embed/serve.go:251","msg":"serving client traffic securely","traffic":"grpc+http","address":"127.0.0.1:2379"} 176s Ncat: Version 7.95 ( https://nmap.org/ncat ) 176s Ncat: Listening on 0.0.0.0:12345 176s 1 178s OK 180s inet 10.0.2.123/32 scope global enc1 180s Ncat: Version 7.95 ( https://nmap.org/ncat ) 180s Ncat: Connection from 10.0.2.123:50864. 180s Ncat: Connected to 10.0.2.123:12345. 180s Ncat: 0 bytes sent, 0 bytes received in 0.02 seconds. 180s ### You've reached the end of the script, all "tests" have successfully been passed! ### 180s {"level":"info","ts":"2025-03-15T19:44:36.563821Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 180s {"level":"info","ts":"2025-03-15T19:44:36.563872Z","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"]} 180s {"level":"warn","ts":"2025-03-15T19:44:36.563931Z","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"} 180s {"level":"warn","ts":"2025-03-15T19:44:36.564034Z","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"} 180s /tmp/autopkgtest.HCoL2A/wrapper.sh: Killing leaked background processes: 1867 180s PID TTY STAT TIME COMMAND 180s 1867 ? Sl 0:00 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 180s autopkgtest [19:44:36]: test cacert-test: -----------------------] 181s autopkgtest [19:44:37]: test cacert-test: - - - - - - - - - - results - - - - - - - - - - 181s cacert-test PASS 181s autopkgtest [19:44:37]: test clientcert-test: preparing testbed 181s Reading package lists... 182s Building dependency tree... 182s Reading state information... 182s Starting pkgProblemResolver with broken count: 0 182s Starting 2 pkgProblemResolver with broken count: 0 182s Done 182s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 183s autopkgtest [19:44:39]: test clientcert-test: [----------------------- 183s ○ etcd.service - etcd - highly-available key value store 183s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 183s Active: inactive (dead) since Sat 2025-03-15 19:45:44 UTC; 1min 5s left 183s Duration: 1.908s 183s Invocation: 9b5ad4e98f0a4b62a5b316ceecd73482 183s Docs: https://etcd.io/docs 183s man:etcd 183s Process: 1505 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 183s Main PID: 1505 (code=killed, signal=TERM) 183s Mem peak: 8.3M 183s CPU: 30ms 183s 183s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"info","ts":"2025-03-15T19:45:44.679477Z","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"]} 183s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"warn","ts":"2025-03-15T19:45:44.680032Z","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"} 183s Mar 15 19:45:44 autopkgtest systemd[1]: Stopping etcd.service - etcd - highly-available key value store... 183s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"warn","ts":"2025-03-15T19:45:44.680192Z","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"} 183s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"info","ts":"2025-03-15T19:45:44.680215Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 183s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"info","ts":"2025-03-15T19:45:44.687231Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 183s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"info","ts":"2025-03-15T19:45:44.687301Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 183s Mar 15 19:45:44 autopkgtest etcd[1505]: {"level":"info","ts":"2025-03-15T19:45:44.687312Z","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"]} 183s Mar 15 19:45:44 autopkgtest systemd[1]: etcd.service: Deactivated successfully. 183s Mar 15 19:45:44 autopkgtest systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 183s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 183s inet 10.0.2.123/32 scope global enc1 183s {"level":"warn","ts":"2025-03-15T19:44:39.688427Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_UNSUPPORTED_ARCH=s390x"} 183s {"level":"warn","ts":"2025-03-15T19:44:39.688542Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 183s {"level":"info","ts":"2025-03-15T19:44:39.688559Z","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"]} 183s {"level":"warn","ts":"2025-03-15T19:44:39.688582Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 183s {"level":"info","ts":"2025-03-15T19:44:39.688614Z","caller":"etcdmain/etcd.go:116","msg":"server has been already initialized","data-dir":"default.etcd","dir-type":"member"} 183s {"level":"warn","ts":"2025-03-15T19:44:39.688630Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 183s {"level":"info","ts":"2025-03-15T19:44:39.688638Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 183s {"level":"info","ts":"2025-03-15T19:44:39.688970Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["https://127.0.0.1:2379"]} 183s {"level":"info","ts":"2025-03-15T19:44:39.689028Z","caller":"embed/etcd.go:311","msg":"starting an etcd server","etcd-version":"3.5.16","git-sha":"Not provided (use ./build instead of go build)","go-version":"go1.24.1","go-os":"linux","go-arch":"s390x","max-cpu-set":2,"max-cpu-available":2,"member-initialized":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"} 183s {"level":"info","ts":"2025-03-15T19:44:39.689958Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"750.317µs"} 183s {"level":"info","ts":"2025-03-15T19:44:39.690100Z","caller":"etcdserver/server.go:532","msg":"No snapshot found. Recovering WAL from scratch!"} 183s {"level":"info","ts":"2025-03-15T19:44:39.690448Z","caller":"etcdserver/raft.go:540","msg":"restarting local member","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","commit-index":11} 183s {"level":"info","ts":"2025-03-15T19:44:39.690484Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 183s {"level":"info","ts":"2025-03-15T19:44:39.690521Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 3"} 183s {"level":"info","ts":"2025-03-15T19:44:39.690533Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 3, commit: 11, applied: 0, lastindex: 11, lastterm: 3]"} 183s {"level":"warn","ts":"2025-03-15T19:44:39.692061Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 183s {"level":"info","ts":"2025-03-15T19:44:39.692746Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":5} 183s {"level":"info","ts":"2025-03-15T19:44:39.693065Z","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"} 183s {"level":"info","ts":"2025-03-15T19:44:39.693343Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 183s {"level":"info","ts":"2025-03-15T19:44:39.693455Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 183s {"level":"info","ts":"2025-03-15T19:44:39.693493Z","caller":"etcdserver/server.go:773","msg":"starting initial election tick advance","election-ticks":10} 183s {"level":"info","ts":"2025-03-15T19:44:39.693604Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 183s {"level":"info","ts":"2025-03-15T19:44:39.693634Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 183s {"level":"info","ts":"2025-03-15T19:44:39.693647Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 183s {"level":"info","ts":"2025-03-15T19:44:39.693802Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 183s {"level":"info","ts":"2025-03-15T19:44:39.693842Z","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"]} 183s {"level":"info","ts":"2025-03-15T19:44:39.693906Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 183s {"level":"info","ts":"2025-03-15T19:44:39.693929Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 183s {"level":"info","ts":"2025-03-15T19:44:39.695828Z","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":[]} 183s {"level":"warn","ts":"2025-03-15T19:44:39.695881Z","caller":"embed/etcd.go:742","msg":"Flag `enable-v2` is deprecated and will get removed in etcd 3.6."} 183s {"level":"info","ts":"2025-03-15T19:44:39.696398Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 183s {"level":"info","ts":"2025-03-15T19:44:39.696429Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 183s {"level":"info","ts":"2025-03-15T19:44:39.696508Z","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":[]} 185s {"level":"info","ts":"2025-03-15T19:44:40.992021Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 3"} 185s {"level":"info","ts":"2025-03-15T19:44:40.992146Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 3"} 185s {"level":"info","ts":"2025-03-15T19:44:40.992214Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 3"} 185s {"level":"info","ts":"2025-03-15T19:44:40.992230Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 4"} 185s {"level":"info","ts":"2025-03-15T19:44:40.992236Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 4"} 185s {"level":"info","ts":"2025-03-15T19:44:40.992248Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 4"} 185s {"level":"info","ts":"2025-03-15T19:44:40.992256Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 4"} 185s {"level":"info","ts":"2025-03-15T19:44:40.994546Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 185s {"level":"info","ts":"2025-03-15T19:44:40.994558Z","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"} 185s {"level":"info","ts":"2025-03-15T19:44:40.994813Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 185s {"level":"info","ts":"2025-03-15T19:44:40.994848Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 185s {"level":"info","ts":"2025-03-15T19:44:40.996077Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 185s {"level":"info","ts":"2025-03-15T19:44:40.997470Z","caller":"embed/serve.go:251","msg":"serving client traffic securely","traffic":"grpc+http","address":"127.0.0.1:2379"} 185s Ncat: Version 7.95 ( https://nmap.org/ncat ) 185s Ncat: Listening on 0.0.0.0:12345 185s 1 187s OK 189s inet 10.0.2.123/32 scope global enc1 189s Ncat: Version 7.95 ( https://nmap.org/ncat ) 189s Ncat: Ncat: Connection from 10.0.2.123:43184. 189s Connected to 10.0.2.123:12345. 189s Ncat: 0 bytes sent, 0 bytes received in 0.02 seconds. 189s ### You've reached the end of the script, all "tests" have successfully been passed! ### 189s {"level":"info","ts":"2025-03-15T19:44:45.806665Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 189s {"level":"info","ts":"2025-03-15T19:44:45.806724Z","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"]} 189s {"level":"warn","ts":"2025-03-15T19:44:45.806779Z","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"} 189s {"level":"warn","ts":"2025-03-15T19:44:45.806805Z","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"} 189s {"level":"info","ts":"2025-03-15T19:44:45.807096Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 189s {"level":"info","ts":"2025-03-15T19:44:45.808705Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 189s {"level":"info","ts":"2025-03-15T19:44:45.808780Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 189s {"level":"info","ts":"2025-03-15T19:44:45.808797Z","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"]} 190s autopkgtest [19:44:46]: test clientcert-test: -----------------------] 190s clientcert-test PASS 190s autopkgtest [19:44:46]: test clientcert-test: - - - - - - - - - - results - - - - - - - - - - 191s autopkgtest [19:44:47]: @@@@@@@@@@@@@@@@@@@@ summary 191s test PASS 191s cacert-test PASS 191s clientcert-test PASS 196s nova [W] Using flock in prodstack6-s390x 196s Creating nova instance adt-plucky-s390x-vip-manager2-20250315-194136-juju-7f2275-prod-proposed-migration-environment-15-35799ac2-3283-4d5a-811e-f8e13e38aa6a from image adt/ubuntu-plucky-s390x-server-20250315.img (UUID 3d3557fa-fd0f-4bba-9b89-8d5964e09f61)... 196s nova [W] Timed out waiting for f842f4c3-28b7-4e96-8446-8bf0931de335 to get deleted.