0s autopkgtest [01:13:37]: starting date and time: 2024-11-02 01:13:37+0000 0s autopkgtest [01:13:37]: git checkout: 6f3be7a8 Fix armhf LXD image generation for plucky 0s autopkgtest [01:13:37]: host juju-7f2275-prod-proposed-migration-environment-14; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.1c5neipu/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:etcd,src:golang-opentelemetry-contrib,src:golang-opentelemetry-otel,src:golang-opentelemetry-proto --apt-upgrade vip-manager2 --timeout-short=300 --timeout-copy=20000 --timeout-build=20000 '--env=ADT_TEST_TRIGGERS=etcd/3.5.16-3 golang-opentelemetry-contrib/0.56.0-4 golang-opentelemetry-otel/1.31.0-3 golang-opentelemetry-proto/1.3.1-2' -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-14@bos03-arm64-17.secgroup --name adt-plucky-arm64-vip-manager2-20241102-011337-juju-7f2275-prod-proposed-migration-environment-14-b8bc0304-8ddc-43fb-ba1a-2ca187314f47 --image adt/ubuntu-plucky-arm64-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-14 --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'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 67s autopkgtest [01:14:44]: testbed dpkg architecture: arm64 67s autopkgtest [01:14:44]: testbed apt version: 2.9.8 67s autopkgtest [01:14:44]: @@@@@@@@@@@@@@@@@@@@ test bed setup 68s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [73.9 kB] 69s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [41.0 kB] 69s Get:3 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [175 kB] 69s Get:4 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [2625 kB] 69s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/restricted Sources [7016 B] 69s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 Packages [230 kB] 69s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/restricted arm64 Packages [50.3 kB] 69s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/universe arm64 Packages [1923 kB] 69s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse arm64 Packages [34.6 kB] 70s Fetched 5160 kB in 1s (3832 kB/s) 70s Reading package lists... 73s Reading package lists... 73s Building dependency tree... 73s Reading state information... 74s Calculating upgrade... 75s The following packages will be upgraded: 75s libblockdev-crypto3 libblockdev-fs3 libblockdev-loop3 libblockdev-mdraid3 75s libblockdev-nvme3 libblockdev-part3 libblockdev-swap3 libblockdev-utils3 75s libblockdev3 libevdev2 libftdi1-2 libinih1 libpipeline1 nano 75s python3-lazr.uri 75s 15 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 75s Need to get 594 kB of archives. 75s After this operation, 19.5 kB of additional disk space will be used. 75s Get:1 http://ftpmaster.internal/ubuntu plucky/main arm64 libevdev2 arm64 1.13.3+dfsg-1 [36.0 kB] 75s Get:2 http://ftpmaster.internal/ubuntu plucky/main arm64 libpipeline1 arm64 1.5.8-1 [30.6 kB] 75s Get:3 http://ftpmaster.internal/ubuntu plucky/main arm64 nano arm64 8.2-1 [289 kB] 76s Get:4 http://ftpmaster.internal/ubuntu plucky/main arm64 libblockdev-utils3 arm64 3.2.0-2 [18.8 kB] 76s Get:5 http://ftpmaster.internal/ubuntu plucky/main arm64 libblockdev-crypto3 arm64 3.2.0-2 [22.6 kB] 76s Get:6 http://ftpmaster.internal/ubuntu plucky/main arm64 libblockdev-fs3 arm64 3.2.0-2 [35.8 kB] 76s Get:7 http://ftpmaster.internal/ubuntu plucky/main arm64 libblockdev-loop3 arm64 3.2.0-2 [7276 B] 76s Get:8 http://ftpmaster.internal/ubuntu plucky/main arm64 libblockdev-mdraid3 arm64 3.2.0-2 [12.8 kB] 76s Get:9 http://ftpmaster.internal/ubuntu plucky/main arm64 libblockdev-nvme3 arm64 3.2.0-2 [17.2 kB] 76s Get:10 http://ftpmaster.internal/ubuntu plucky/main arm64 libblockdev-part3 arm64 3.2.0-2 [14.9 kB] 76s Get:11 http://ftpmaster.internal/ubuntu plucky/main arm64 libblockdev-swap3 arm64 3.2.0-2 [7832 B] 76s Get:12 http://ftpmaster.internal/ubuntu plucky/main arm64 libblockdev3 arm64 3.2.0-2 [52.4 kB] 76s Get:13 http://ftpmaster.internal/ubuntu plucky/main arm64 libftdi1-2 arm64 1.5-7 [28.4 kB] 76s Get:14 http://ftpmaster.internal/ubuntu plucky/main arm64 libinih1 arm64 58-1ubuntu1 [7412 B] 76s Get:15 http://ftpmaster.internal/ubuntu plucky/main arm64 python3-lazr.uri all 1.0.6-4 [13.6 kB] 76s Fetched 594 kB in 1s (1052 kB/s) 77s (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 ... 79705 files and directories currently installed.) 77s Preparing to unpack .../00-libevdev2_1.13.3+dfsg-1_arm64.deb ... 77s Unpacking libevdev2:arm64 (1.13.3+dfsg-1) over (1.13.2+dfsg-1) ... 77s Preparing to unpack .../01-libpipeline1_1.5.8-1_arm64.deb ... 77s Unpacking libpipeline1:arm64 (1.5.8-1) over (1.5.7-2) ... 77s Preparing to unpack .../02-nano_8.2-1_arm64.deb ... 77s Unpacking nano (8.2-1) over (8.1-1) ... 77s Preparing to unpack .../03-libblockdev-utils3_3.2.0-2_arm64.deb ... 77s Unpacking libblockdev-utils3:arm64 (3.2.0-2) over (3.1.1-2) ... 77s Preparing to unpack .../04-libblockdev-crypto3_3.2.0-2_arm64.deb ... 77s Unpacking libblockdev-crypto3:arm64 (3.2.0-2) over (3.1.1-2) ... 77s Preparing to unpack .../05-libblockdev-fs3_3.2.0-2_arm64.deb ... 77s Unpacking libblockdev-fs3:arm64 (3.2.0-2) over (3.1.1-2) ... 77s Preparing to unpack .../06-libblockdev-loop3_3.2.0-2_arm64.deb ... 77s Unpacking libblockdev-loop3:arm64 (3.2.0-2) over (3.1.1-2) ... 77s Preparing to unpack .../07-libblockdev-mdraid3_3.2.0-2_arm64.deb ... 77s Unpacking libblockdev-mdraid3:arm64 (3.2.0-2) over (3.1.1-2) ... 77s Preparing to unpack .../08-libblockdev-nvme3_3.2.0-2_arm64.deb ... 77s Unpacking libblockdev-nvme3:arm64 (3.2.0-2) over (3.1.1-2) ... 77s Preparing to unpack .../09-libblockdev-part3_3.2.0-2_arm64.deb ... 77s Unpacking libblockdev-part3:arm64 (3.2.0-2) over (3.1.1-2) ... 77s Preparing to unpack .../10-libblockdev-swap3_3.2.0-2_arm64.deb ... 77s Unpacking libblockdev-swap3:arm64 (3.2.0-2) over (3.1.1-2) ... 77s Preparing to unpack .../11-libblockdev3_3.2.0-2_arm64.deb ... 77s Unpacking libblockdev3:arm64 (3.2.0-2) over (3.1.1-2) ... 77s Preparing to unpack .../12-libftdi1-2_1.5-7_arm64.deb ... 77s Unpacking libftdi1-2:arm64 (1.5-7) over (1.5-6build5) ... 78s Preparing to unpack .../13-libinih1_58-1ubuntu1_arm64.deb ... 78s Unpacking libinih1:arm64 (58-1ubuntu1) over (55-1ubuntu2) ... 78s Preparing to unpack .../14-python3-lazr.uri_1.0.6-4_all.deb ... 78s Unpacking python3-lazr.uri (1.0.6-4) over (1.0.6-3) ... 78s Setting up libpipeline1:arm64 (1.5.8-1) ... 78s Setting up libinih1:arm64 (58-1ubuntu1) ... 78s Setting up python3-lazr.uri (1.0.6-4) ... 78s Setting up libftdi1-2:arm64 (1.5-7) ... 78s Setting up libblockdev-utils3:arm64 (3.2.0-2) ... 78s Setting up libblockdev-nvme3:arm64 (3.2.0-2) ... 78s Setting up nano (8.2-1) ... 78s Setting up libblockdev-fs3:arm64 (3.2.0-2) ... 78s Setting up libevdev2:arm64 (1.13.3+dfsg-1) ... 78s Setting up libblockdev-mdraid3:arm64 (3.2.0-2) ... 78s Setting up libblockdev-crypto3:arm64 (3.2.0-2) ... 78s Setting up libblockdev-swap3:arm64 (3.2.0-2) ... 78s Setting up libblockdev-loop3:arm64 (3.2.0-2) ... 78s Setting up libblockdev3:arm64 (3.2.0-2) ... 78s Installing new version of config file /etc/libblockdev/3/conf.d/00-default.cfg ... 78s Setting up libblockdev-part3:arm64 (3.2.0-2) ... 78s Processing triggers for libc-bin (2.40-1ubuntu3) ... 78s Processing triggers for man-db (2.12.1-3) ... 79s Processing triggers for install-info (7.1.1-1) ... 80s Reading package lists... 80s Building dependency tree... 80s Reading state information... 81s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 82s Hit:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease 82s Hit:2 http://ftpmaster.internal/ubuntu plucky InRelease 82s Hit:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease 82s Hit:4 http://ftpmaster.internal/ubuntu plucky-security InRelease 84s Reading package lists... 84s Reading package lists... 85s Building dependency tree... 85s Reading state information... 86s Calculating upgrade... 87s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 87s Reading package lists... 88s Building dependency tree... 88s Reading state information... 89s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 92s autopkgtest [01:15:09]: testbed running kernel: Linux 6.11.0-8-generic #8-Ubuntu SMP PREEMPT_DYNAMIC Mon Sep 16 14:19:41 UTC 2024 93s autopkgtest [01:15:10]: @@@@@@@@@@@@@@@@@@@@ apt-source vip-manager2 94s Get:1 http://ftpmaster.internal/ubuntu plucky/universe vip-manager2 2.5.0-1 (dsc) [2487 B] 94s Get:2 http://ftpmaster.internal/ubuntu plucky/universe vip-manager2 2.5.0-1 (tar) [45.4 kB] 94s Get:3 http://ftpmaster.internal/ubuntu plucky/universe vip-manager2 2.5.0-1 (diff) [8284 B] 95s gpgv: Signature made Fri May 17 08:39:51 2024 UTC 95s gpgv: using RSA key 5C48FE6157F49179597087C64C5A6BAB12D2A7AE 95s gpgv: Can't check signature: No public key 95s dpkg-source: warning: cannot verify inline signature for ./vip-manager2_2.5.0-1.dsc: no acceptable signature found 95s autopkgtest [01:15:12]: testing package vip-manager2 version 2.5.0-1 95s autopkgtest [01:15:12]: build not needed 96s autopkgtest [01:15:13]: test test: preparing testbed 97s Reading package lists... 98s Building dependency tree... 98s Reading state information... 99s Starting pkgProblemResolver with broken count: 0 99s Starting 2 pkgProblemResolver with broken count: 0 99s Done 100s The following additional packages will be installed: 100s etcd-client etcd-server liblua5.4-0 ncat vip-manager2 100s The following NEW packages will be installed: 100s autopkgtest-satdep etcd-client etcd-server liblua5.4-0 ncat vip-manager2 100s 0 upgraded, 6 newly installed, 0 to remove and 0 not upgraded. 100s Need to get 19.8 MB/19.8 MB of archives. 100s After this operation, 71.4 MB of additional disk space will be used. 100s Get:1 /tmp/autopkgtest.iAUUFr/1-autopkgtest-satdep.deb autopkgtest-satdep arm64 0 [736 B] 100s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/universe arm64 etcd-server arm64 3.5.16-3 [10.7 MB] 101s Get:3 http://ftpmaster.internal/ubuntu plucky/main arm64 liblua5.4-0 arm64 5.4.6-3build2 [158 kB] 101s Get:4 http://ftpmaster.internal/ubuntu plucky/universe arm64 ncat arm64 7.94+git20230807.3be01efb1+dfsg-4 [212 kB] 101s Get:5 http://ftpmaster.internal/ubuntu plucky/universe arm64 vip-manager2 arm64 2.5.0-1 [3574 kB] 101s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/universe arm64 etcd-client arm64 3.5.16-3 [5086 kB] 102s Fetched 19.8 MB in 1s (14.7 MB/s) 102s Selecting previously unselected package etcd-server. 102s (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 ... 79705 files and directories currently installed.) 102s Preparing to unpack .../0-etcd-server_3.5.16-3_arm64.deb ... 102s Unpacking etcd-server (3.5.16-3) ... 103s Selecting previously unselected package liblua5.4-0:arm64. 103s Preparing to unpack .../1-liblua5.4-0_5.4.6-3build2_arm64.deb ... 103s Unpacking liblua5.4-0:arm64 (5.4.6-3build2) ... 103s Selecting previously unselected package ncat. 103s Preparing to unpack .../2-ncat_7.94+git20230807.3be01efb1+dfsg-4_arm64.deb ... 103s Unpacking ncat (7.94+git20230807.3be01efb1+dfsg-4) ... 103s Selecting previously unselected package vip-manager2. 103s Preparing to unpack .../3-vip-manager2_2.5.0-1_arm64.deb ... 103s Unpacking vip-manager2 (2.5.0-1) ... 103s Selecting previously unselected package etcd-client. 103s Preparing to unpack .../4-etcd-client_3.5.16-3_arm64.deb ... 103s Unpacking etcd-client (3.5.16-3) ... 103s Selecting previously unselected package autopkgtest-satdep. 103s Preparing to unpack .../5-1-autopkgtest-satdep.deb ... 103s Unpacking autopkgtest-satdep (0) ... 103s Setting up vip-manager2 (2.5.0-1) ... 103s Created symlink '/etc/systemd/system/multi-user.target.wants/vip-manager.service' → '/usr/lib/systemd/system/vip-manager.service'. 104s Setting up etcd-client (3.5.16-3) ... 104s Setting up liblua5.4-0:arm64 (5.4.6-3build2) ... 104s Setting up etcd-server (3.5.16-3) ... 104s info: Selecting UID from range 100 to 999 ... 104s 104s info: Selecting GID from range 100 to 999 ... 104s info: Adding system user `etcd' (UID 107) ... 104s info: Adding new group `etcd' (GID 108) ... 104s info: Adding new user `etcd' (UID 107) with group `etcd' ... 104s info: Creating home directory `/var/lib/etcd/' ... 105s Created symlink '/etc/systemd/system/etcd2.service' → '/usr/lib/systemd/system/etcd.service'. 105s Created symlink '/etc/systemd/system/multi-user.target.wants/etcd.service' → '/usr/lib/systemd/system/etcd.service'. 106s Setting up ncat (7.94+git20230807.3be01efb1+dfsg-4) ... 106s Setting up autopkgtest-satdep (0) ... 106s Processing triggers for man-db (2.12.1-3) ... 106s Processing triggers for libc-bin (2.40-1ubuntu3) ... 110s (Reading database ... 79750 files and directories currently installed.) 110s Removing autopkgtest-satdep (0) ... 110s autopkgtest [01:15:27]: test test: [----------------------- 111s ○ etcd.service - etcd - highly-available key value store 111s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 111s Active: inactive (dead) since Sat 2024-11-02 01:15:28 UTC; 14ms ago 111s Duration: 5.476s 111s Invocation: 58804457331b46fc95c0f2fbfcd98f76 111s Docs: https://etcd.io/docs 111s man:etcd 111s Process: 2454 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 111s Main PID: 2454 (code=killed, signal=TERM) 111s Mem peak: 7.2M 111s CPU: 164ms 111s 111s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"info","ts":"2024-11-02T01:15:28.665471Z","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"]} 111s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"warn","ts":"2024-11-02T01:15:28.665597Z","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"} 111s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"warn","ts":"2024-11-02T01:15:28.666157Z","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"} 111s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"info","ts":"2024-11-02T01:15:28.666193Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 111s Nov 02 01:15:28 autopkgtest systemd[1]: Stopping etcd.service - etcd - highly-available key value store... 111s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"info","ts":"2024-11-02T01:15:28.671231Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 111s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"info","ts":"2024-11-02T01:15:28.671428Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 111s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"info","ts":"2024-11-02T01:15:28.671441Z","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"]} 111s Nov 02 01:15:28 autopkgtest systemd[1]: etcd.service: Deactivated successfully. 111s Nov 02 01:15:28 autopkgtest systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 111s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 111s {"level":"warn","ts":"2024-11-02T01:15:28.771420Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_UNSUPPORTED_ARCH=arm64"} 111s {"level":"warn","ts":"2024-11-02T01:15:28.771656Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 111s {"level":"info","ts":"2024-11-02T01:15:28.771690Z","caller":"etcdmain/etcd.go:73","msg":"Running: ","args":["etcd"]} 111s {"level":"warn","ts":"2024-11-02T01:15:28.771714Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 111s {"level":"warn","ts":"2024-11-02T01:15:28.771745Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 111s {"level":"info","ts":"2024-11-02T01:15:28.771754Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 111s {"level":"info","ts":"2024-11-02T01:15:28.772347Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["http://localhost:2379"]} 111s {"level":"info","ts":"2024-11-02T01:15:28.772653Z","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.23.2","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"} 111s {"level":"info","ts":"2024-11-02T01:15:28.778994Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"5.925176ms"} 111s {"level":"info","ts":"2024-11-02T01:15:28.786876Z","caller":"etcdserver/raft.go:505","msg":"starting local member","local-member-id":"8e9e05c52164694d","cluster-id":"cdf818194e3a8c32"} 111s {"level":"info","ts":"2024-11-02T01:15:28.787012Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 111s {"level":"info","ts":"2024-11-02T01:15:28.787049Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 0"} 111s {"level":"info","ts":"2024-11-02T01:15:28.787059Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]"} 111s {"level":"info","ts":"2024-11-02T01:15:28.787070Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 1"} 111s {"level":"info","ts":"2024-11-02T01:15:28.787105Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 111s {"level":"warn","ts":"2024-11-02T01:15:28.796233Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 111s {"level":"info","ts":"2024-11-02T01:15:28.797872Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":1} 111s {"level":"info","ts":"2024-11-02T01:15:28.799193Z","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"} 111s {"level":"info","ts":"2024-11-02T01:15:28.800600Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 111s {"level":"info","ts":"2024-11-02T01:15:28.800784Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 111s {"level":"info","ts":"2024-11-02T01:15:28.801543Z","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"} 111s {"level":"info","ts":"2024-11-02T01:15:28.801723Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 111s {"level":"info","ts":"2024-11-02T01:15:28.801760Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 111s {"level":"info","ts":"2024-11-02T01:15:28.801767Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 111s {"level":"info","ts":"2024-11-02T01:15:28.802744Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 111s {"level":"info","ts":"2024-11-02T01:15:28.803411Z","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"]} 111s {"level":"info","ts":"2024-11-02T01:15:28.805315Z","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":[]} 111s {"level":"info","ts":"2024-11-02T01:15:28.805399Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 111s {"level":"info","ts":"2024-11-02T01:15:28.805414Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 112s {"level":"info","ts":"2024-11-02T01:15:29.287679Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 1"} 112s {"level":"info","ts":"2024-11-02T01:15:29.287736Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 1"} 112s {"level":"info","ts":"2024-11-02T01:15:29.287756Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 1"} 112s {"level":"info","ts":"2024-11-02T01:15:29.287770Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 2"} 112s {"level":"info","ts":"2024-11-02T01:15:29.287821Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 2"} 112s {"level":"info","ts":"2024-11-02T01:15:29.287832Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 2"} 112s {"level":"info","ts":"2024-11-02T01:15:29.287838Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 2"} 112s {"level":"info","ts":"2024-11-02T01:15:29.289152Z","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"} 112s {"level":"info","ts":"2024-11-02T01:15:29.289268Z","caller":"etcdserver/server.go:2651","msg":"setting up initial cluster version using v2 API","cluster-version":"3.5"} 112s {"level":"info","ts":"2024-11-02T01:15:29.289456Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 112s {"level":"info","ts":"2024-11-02T01:15:29.289767Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 112s {"level":"info","ts":"2024-11-02T01:15:29.289806Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 112s {"level":"info","ts":"2024-11-02T01:15:29.290221Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 112s {"level":"info","ts":"2024-11-02T01:15:29.290310Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 112s {"level":"info","ts":"2024-11-02T01:15:29.290331Z","caller":"etcdserver/server.go:2675","msg":"cluster version is updated","cluster-version":"3.5"} 112s {"level":"info","ts":"2024-11-02T01:15:29.290329Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 112s {"level":"info","ts":"2024-11-02T01:15:29.290692Z","caller":"embed/serve.go:188","msg":"serving client traffic insecurely; this is strongly discouraged!","traffic":"grpc+http","address":"127.0.0.1:2379"} 113s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 113s Ncat: Listening on 0.0.0.0:12345 113s 0 113s dcs-endpoints : [http://127.0.0.1:2379] 113s dcs-type : etcd 113s hostingtype : basic 113s interface : enp1s0 113s interval : 3000 113s ip : 10.0.2.123 113s manager-type : basic 113s netmask : 32 113s retry-after : 250 113s retry-num : 3 113s trigger-key : service/pgcluster/leader 113s trigger-value : autopkgtest 113s verbose : false 113s version : false 113s 2024-11-02 01:15:30.829479 I | No dcs-endpoints specified, trying to use localhost with standard ports! 113s 2024-11-02 01:15:30.830069 I | This is the config that will be used: 113s 2024-11-02 01:15:30.834542 I | IP address 10.0.2.123/32 state is false, desired false 113s 2024-11-02 01:15:30.838112 I | set WATCH on service/pgcluster/leader 115s 2024-11-02 01:15:32.850422 I | Current Leader from DCS: autopkgtest 115s 2024-11-02 01:15:32.850665 I | IP address 10.0.2.123/32 state is false, desired true 115s 2024-11-02 01:15:32.850757 I | Configuring address 10.0.2.123/32 on enp1s0 115s OK 115s 2024-11-02 01:15:32.853804 I | Sent gratuitous ARP reply 115s 2024-11-02 01:15:32.854266 I | Sent gratuitous ARP request 115s 2024-11-02 01:15:32.854596 I | IP address 10.0.2.123/32 state is true, desired true 117s inet 10.0.2.123/32 scope global enp1s0 117s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 117s Ncat: Ncat: Connection from 10.0.2.123:36876. 117s Connected to 10.0.2.123:12345. 117s Ncat: 0 bytes sent, 0 bytes received in 0.03 seconds. 117s OK 117s 2024-11-02 01:15:34.927953 I | Current Leader from DCS: 0xGARBAGE 117s 2024-11-02 01:15:34.928198 I | IP address 10.0.2.123/32 state is true, desired false 117s 2024-11-02 01:15:34.928218 I | Removing address 10.0.2.123/32 on enp1s0 117s 2024-11-02 01:15:34.931828 I | IP address 10.0.2.123/32 state is false, desired false 119s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 120s Ncat: Connection refused. 120s ### You've reached the end of the script, all "tests" have successfully been passed! ### 120s {"level":"info","ts":"2024-11-02T01:15:36.997855Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 120s {"level":"info","ts":"2024-11-02T01:15:36.997951Z","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"]} 120s {"level":"warn","ts":"2024-11-02T01:15:36.998085Z","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"} 120s {"level":"warn","ts":"2024-11-02T01:15:36.998341Z","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"} 120s {"level":"info","ts":"2024-11-02T01:15:36.998602Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 120s {"level":"info","ts":"2024-11-02T01:15:37.001139Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 120s {"level":"info","ts":"2024-11-02T01:15:37.001305Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 120s {"level":"info","ts":"2024-11-02T01:15:37.001320Z","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"]} 120s autopkgtest [01:15:37]: test test: -----------------------] 120s autopkgtest [01:15:37]: test test: - - - - - - - - - - results - - - - - - - - - - 120s test PASS 121s autopkgtest [01:15:38]: test cacert-test: preparing testbed 123s Reading package lists... 123s Building dependency tree... 123s Reading state information... 124s Starting pkgProblemResolver with broken count: 0 124s Starting 2 pkgProblemResolver with broken count: 0 124s Done 125s The following NEW packages will be installed: 125s autopkgtest-satdep 125s 0 upgraded, 1 newly installed, 0 to remove and 0 not upgraded. 125s Need to get 0 B/736 B of archives. 125s After this operation, 0 B of additional disk space will be used. 125s Get:1 /tmp/autopkgtest.iAUUFr/2-autopkgtest-satdep.deb autopkgtest-satdep arm64 0 [736 B] 126s Selecting previously unselected package autopkgtest-satdep. 126s (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 ... 79750 files and directories currently installed.) 126s Preparing to unpack .../2-autopkgtest-satdep.deb ... 126s Unpacking autopkgtest-satdep (0) ... 126s Setting up autopkgtest-satdep (0) ... 131s (Reading database ... 79750 files and directories currently installed.) 131s Removing autopkgtest-satdep (0) ... 132s autopkgtest [01:15:49]: test cacert-test: [----------------------- 133s ○ etcd.service - etcd - highly-available key value store 133s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 133s Active: inactive (dead) since Sat 2024-11-02 01:15:28 UTC; 21s ago 133s Duration: 5.476s 133s Invocation: 58804457331b46fc95c0f2fbfcd98f76 133s Docs: https://etcd.io/docs 133s man:etcd 133s Process: 2454 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 133s Main PID: 2454 (code=killed, signal=TERM) 133s Mem peak: 7.2M 133s CPU: 164ms 133s 133s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"info","ts":"2024-11-02T01:15:28.665471Z","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"]} 133s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"warn","ts":"2024-11-02T01:15:28.665597Z","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"} 133s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"warn","ts":"2024-11-02T01:15:28.666157Z","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"} 133s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"info","ts":"2024-11-02T01:15:28.666193Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 133s Nov 02 01:15:28 autopkgtest systemd[1]: Stopping etcd.service - etcd - highly-available key value store... 133s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"info","ts":"2024-11-02T01:15:28.671231Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 133s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"info","ts":"2024-11-02T01:15:28.671428Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 133s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"info","ts":"2024-11-02T01:15:28.671441Z","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"]} 133s Nov 02 01:15:28 autopkgtest systemd[1]: etcd.service: Deactivated successfully. 133s Nov 02 01:15:28 autopkgtest systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 133s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 133s {"level":"warn","ts":"2024-11-02T01:15:50.643701Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_UNSUPPORTED_ARCH=arm64"} 133s {"level":"warn","ts":"2024-11-02T01:15:50.643967Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 133s {"level":"info","ts":"2024-11-02T01:15:50.644012Z","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"]} 133s {"level":"warn","ts":"2024-11-02T01:15:50.644039Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 133s {"level":"info","ts":"2024-11-02T01:15:50.644108Z","caller":"etcdmain/etcd.go:116","msg":"server has been already initialized","data-dir":"default.etcd","dir-type":"member"} 133s {"level":"warn","ts":"2024-11-02T01:15:50.644131Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 133s {"level":"info","ts":"2024-11-02T01:15:50.644140Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 133s {"level":"info","ts":"2024-11-02T01:15:50.644640Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["https://127.0.0.1:2379"]} 133s {"level":"info","ts":"2024-11-02T01:15:50.644758Z","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.23.2","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"} 133s {"level":"info","ts":"2024-11-02T01:15:50.651252Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"6.066326ms"} 133s {"level":"info","ts":"2024-11-02T01:15:50.651604Z","caller":"etcdserver/server.go:532","msg":"No snapshot found. Recovering WAL from scratch!"} 133s {"level":"info","ts":"2024-11-02T01:15:50.652071Z","caller":"etcdserver/raft.go:540","msg":"restarting local member","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","commit-index":7} 133s {"level":"info","ts":"2024-11-02T01:15:50.652161Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 133s {"level":"info","ts":"2024-11-02T01:15:50.652203Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 2"} 133s {"level":"info","ts":"2024-11-02T01:15:50.652218Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 2, commit: 7, applied: 0, lastindex: 7, lastterm: 2]"} 133s {"level":"warn","ts":"2024-11-02T01:15:50.653798Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 133s {"level":"info","ts":"2024-11-02T01:15:50.655288Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":3} 133s {"level":"info","ts":"2024-11-02T01:15:50.656932Z","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"} 133s {"level":"info","ts":"2024-11-02T01:15:50.658657Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 133s {"level":"info","ts":"2024-11-02T01:15:50.658881Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 133s {"level":"info","ts":"2024-11-02T01:15:50.658997Z","caller":"etcdserver/server.go:773","msg":"starting initial election tick advance","election-ticks":10} 133s {"level":"info","ts":"2024-11-02T01:15:50.659158Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 133s {"level":"info","ts":"2024-11-02T01:15:50.659192Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 133s {"level":"info","ts":"2024-11-02T01:15:50.659200Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 133s {"level":"info","ts":"2024-11-02T01:15:50.659449Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 133s {"level":"info","ts":"2024-11-02T01:15:50.659501Z","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"]} 133s {"level":"info","ts":"2024-11-02T01:15:50.659597Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 133s {"level":"info","ts":"2024-11-02T01:15:50.659621Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 133s {"level":"info","ts":"2024-11-02T01:15:50.663649Z","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":[]} 133s {"level":"warn","ts":"2024-11-02T01:15:50.663849Z","caller":"embed/etcd.go:742","msg":"Flag `enable-v2` is deprecated and will get removed in etcd 3.6."} 133s {"level":"info","ts":"2024-11-02T01:15:50.663763Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 133s {"level":"info","ts":"2024-11-02T01:15:50.663999Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 133s {"level":"info","ts":"2024-11-02T01:15:50.664185Z","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":[]} 134s {"level":"info","ts":"2024-11-02T01:15:51.853498Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 2"} 134s {"level":"info","ts":"2024-11-02T01:15:51.853556Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 2"} 134s {"level":"info","ts":"2024-11-02T01:15:51.853609Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 2"} 134s {"level":"info","ts":"2024-11-02T01:15:51.853623Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 3"} 134s {"level":"info","ts":"2024-11-02T01:15:51.853649Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 3"} 134s {"level":"info","ts":"2024-11-02T01:15:51.853658Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 3"} 134s {"level":"info","ts":"2024-11-02T01:15:51.853666Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 3"} 134s {"level":"info","ts":"2024-11-02T01:15:51.861059Z","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"} 134s {"level":"info","ts":"2024-11-02T01:15:51.861059Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 134s {"level":"info","ts":"2024-11-02T01:15:51.861701Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 134s {"level":"info","ts":"2024-11-02T01:15:51.861765Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 134s {"level":"info","ts":"2024-11-02T01:15:51.862668Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 134s {"level":"info","ts":"2024-11-02T01:15:51.863660Z","caller":"embed/serve.go:251","msg":"serving client traffic securely","traffic":"grpc+http","address":"127.0.0.1:2379"} 135s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 135s Ncat: Listening on 0.0.0.0:12345 135s 1 137s OK 139s inet 10.0.2.123/32 scope global enp1s0 139s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 139s Ncat: Connected to 10.0.2.123:12345. 139s Ncat: 0 bytes sent, 0 bytes received in 0.03 seconds. 139s Ncat: Connection from 10.0.2.123:37168. 139s ### You've reached the end of the script, all "tests" have successfully been passed! ### 139s {"level":"info","ts":"2024-11-02T01:15:56.849138Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 139s {"level":"info","ts":"2024-11-02T01:15:56.849382Z","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"]} 139s {"level":"warn","ts":"2024-11-02T01:15:56.850098Z","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"} 139s {"level":"warn","ts":"2024-11-02T01:15:56.850300Z","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"} 139s {"level":"info","ts":"2024-11-02T01:15:56.851573Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 139s {"level":"info","ts":"2024-11-02T01:15:56.855726Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 139s {"level":"info","ts":"2024-11-02T01:15:56.856064Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 139s {"level":"info","ts":"2024-11-02T01:15:56.856084Z","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"]} 140s autopkgtest [01:15:57]: test cacert-test: -----------------------] 140s autopkgtest [01:15:57]: test cacert-test: - - - - - - - - - - results - - - - - - - - - - 140s cacert-test PASS 141s autopkgtest [01:15:58]: test clientcert-test: preparing testbed 146s Reading package lists... 146s Building dependency tree... 146s Reading state information... 147s Starting pkgProblemResolver with broken count: 0 147s Starting 2 pkgProblemResolver with broken count: 0 147s Done 148s The following NEW packages will be installed: 148s autopkgtest-satdep 148s 0 upgraded, 1 newly installed, 0 to remove and 0 not upgraded. 148s Need to get 0 B/732 B of archives. 148s After this operation, 0 B of additional disk space will be used. 148s Get:1 /tmp/autopkgtest.iAUUFr/3-autopkgtest-satdep.deb autopkgtest-satdep arm64 0 [732 B] 149s Selecting previously unselected package autopkgtest-satdep. 149s (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 ... 79750 files and directories currently installed.) 149s Preparing to unpack .../3-autopkgtest-satdep.deb ... 149s Unpacking autopkgtest-satdep (0) ... 149s Setting up autopkgtest-satdep (0) ... 164s (Reading database ... 79750 files and directories currently installed.) 164s Removing autopkgtest-satdep (0) ... 167s autopkgtest [01:16:24]: test clientcert-test: [----------------------- 168s ○ etcd.service - etcd - highly-available key value store 168s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 168s Active: inactive (dead) since Sat 2024-11-02 01:15:28 UTC; 56s ago 168s Duration: 5.476s 168s Invocation: 58804457331b46fc95c0f2fbfcd98f76 168s Docs: https://etcd.io/docs 168s man:etcd 168s Process: 2454 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 168s Main PID: 2454 (code=killed, signal=TERM) 168s Mem peak: 7.2M 168s CPU: 164ms 168s 168s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"info","ts":"2024-11-02T01:15:28.665471Z","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"]} 168s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"warn","ts":"2024-11-02T01:15:28.665597Z","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"} 168s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"warn","ts":"2024-11-02T01:15:28.666157Z","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"} 168s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"info","ts":"2024-11-02T01:15:28.666193Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 168s Nov 02 01:15:28 autopkgtest systemd[1]: Stopping etcd.service - etcd - highly-available key value store... 168s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"info","ts":"2024-11-02T01:15:28.671231Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 168s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"info","ts":"2024-11-02T01:15:28.671428Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 168s Nov 02 01:15:28 autopkgtest etcd[2454]: {"level":"info","ts":"2024-11-02T01:15:28.671441Z","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"]} 168s Nov 02 01:15:28 autopkgtest systemd[1]: etcd.service: Deactivated successfully. 168s Nov 02 01:15:28 autopkgtest systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 168s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 168s inet 10.0.2.123/32 scope global enp1s0 168s {"level":"warn","ts":"2024-11-02T01:16:25.615455Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_UNSUPPORTED_ARCH=arm64"} 168s {"level":"warn","ts":"2024-11-02T01:16:25.615680Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 168s {"level":"info","ts":"2024-11-02T01:16:25.615722Z","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"]} 168s {"level":"warn","ts":"2024-11-02T01:16:25.615748Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 168s {"level":"info","ts":"2024-11-02T01:16:25.615805Z","caller":"etcdmain/etcd.go:116","msg":"server has been already initialized","data-dir":"default.etcd","dir-type":"member"} 168s {"level":"warn","ts":"2024-11-02T01:16:25.615826Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 168s {"level":"info","ts":"2024-11-02T01:16:25.615884Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 168s {"level":"info","ts":"2024-11-02T01:16:25.616456Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["https://127.0.0.1:2379"]} 168s {"level":"info","ts":"2024-11-02T01:16:25.616604Z","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.23.2","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"} 168s {"level":"info","ts":"2024-11-02T01:16:25.618113Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"1.190049ms"} 168s {"level":"info","ts":"2024-11-02T01:16:25.618418Z","caller":"etcdserver/server.go:532","msg":"No snapshot found. Recovering WAL from scratch!"} 168s {"level":"info","ts":"2024-11-02T01:16:25.619042Z","caller":"etcdserver/raft.go:540","msg":"restarting local member","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","commit-index":11} 168s {"level":"info","ts":"2024-11-02T01:16:25.619132Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 168s {"level":"info","ts":"2024-11-02T01:16:25.619176Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 3"} 168s {"level":"info","ts":"2024-11-02T01:16:25.619193Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 3, commit: 11, applied: 0, lastindex: 11, lastterm: 3]"} 168s {"level":"warn","ts":"2024-11-02T01:16:25.630250Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 168s {"level":"info","ts":"2024-11-02T01:16:25.632323Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":5} 168s {"level":"info","ts":"2024-11-02T01:16:25.634360Z","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"} 168s {"level":"info","ts":"2024-11-02T01:16:25.636798Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 168s {"level":"info","ts":"2024-11-02T01:16:25.637086Z","caller":"etcdserver/server.go:773","msg":"starting initial election tick advance","election-ticks":10} 168s {"level":"info","ts":"2024-11-02T01:16:25.637298Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 168s {"level":"info","ts":"2024-11-02T01:16:25.637694Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 168s {"level":"info","ts":"2024-11-02T01:16:25.637769Z","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"]} 168s {"level":"info","ts":"2024-11-02T01:16:25.637934Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 168s {"level":"info","ts":"2024-11-02T01:16:25.637977Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 168s {"level":"info","ts":"2024-11-02T01:16:25.638136Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 168s {"level":"info","ts":"2024-11-02T01:16:25.638188Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 168s {"level":"info","ts":"2024-11-02T01:16:25.638197Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 168s {"level":"info","ts":"2024-11-02T01:16:25.645161Z","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":[]} 168s {"level":"warn","ts":"2024-11-02T01:16:25.645252Z","caller":"embed/etcd.go:742","msg":"Flag `enable-v2` is deprecated and will get removed in etcd 3.6."} 168s {"level":"info","ts":"2024-11-02T01:16:25.645384Z","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":[]} 168s {"level":"info","ts":"2024-11-02T01:16:25.645416Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 168s {"level":"info","ts":"2024-11-02T01:16:25.645455Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 169s {"level":"info","ts":"2024-11-02T01:16:26.620062Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 3"} 169s {"level":"info","ts":"2024-11-02T01:16:26.620133Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 3"} 169s {"level":"info","ts":"2024-11-02T01:16:26.620159Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 3"} 169s {"level":"info","ts":"2024-11-02T01:16:26.620172Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 4"} 169s {"level":"info","ts":"2024-11-02T01:16:26.620200Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 4"} 169s {"level":"info","ts":"2024-11-02T01:16:26.620211Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 4"} 169s {"level":"info","ts":"2024-11-02T01:16:26.620218Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 4"} 169s {"level":"info","ts":"2024-11-02T01:16:26.627469Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 169s {"level":"info","ts":"2024-11-02T01:16:26.627475Z","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"} 169s {"level":"info","ts":"2024-11-02T01:16:26.627958Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 169s {"level":"info","ts":"2024-11-02T01:16:26.627990Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 169s {"level":"info","ts":"2024-11-02T01:16:26.628695Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 169s {"level":"info","ts":"2024-11-02T01:16:26.629608Z","caller":"embed/serve.go:251","msg":"serving client traffic securely","traffic":"grpc+http","address":"127.0.0.1:2379"} 170s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 170s Ncat: Listening on 0.0.0.0:12345 170s 1 172s OK 174s inet 10.0.2.123/32 scope global enp1s0 174s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 174s Ncat: Connected to 10.0.2.123:12345. 174s Ncat: 0 bytes sent, 0 bytes received in 0.03 seconds. 174s Ncat: Connection from 10.0.2.123:48726. 174s ### You've reached the end of the script, all "tests" have successfully been passed! ### 174s {"level":"info","ts":"2024-11-02T01:16:31.787119Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 174s {"level":"info","ts":"2024-11-02T01:16:31.787190Z","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"]} 174s {"level":"warn","ts":"2024-11-02T01:16:31.787283Z","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"} 174s {"level":"warn","ts":"2024-11-02T01:16:31.787518Z","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"} 174s {"level":"info","ts":"2024-11-02T01:16:31.789271Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 174s {"level":"info","ts":"2024-11-02T01:16:31.792520Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 174s {"level":"info","ts":"2024-11-02T01:16:31.792727Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 174s {"level":"info","ts":"2024-11-02T01:16:31.792747Z","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"]} 175s autopkgtest [01:16:32]: test clientcert-test: -----------------------] 175s clientcert-test PASS 175s autopkgtest [01:16:32]: test clientcert-test: - - - - - - - - - - results - - - - - - - - - - 176s autopkgtest [01:16:33]: @@@@@@@@@@@@@@@@@@@@ summary 176s test PASS 176s cacert-test PASS 176s clientcert-test PASS 191s nova [W] Skipping flock in bos03-arm64 191s Creating nova instance adt-plucky-arm64-vip-manager2-20241102-011337-juju-7f2275-prod-proposed-migration-environment-14-b8bc0304-8ddc-43fb-ba1a-2ca187314f47 from image adt/ubuntu-plucky-arm64-server-20241101.img (UUID 520a937f-514a-4e80-b76b-163a8c247e3e)...