0s autopkgtest [18:16:52]: starting date and time: 2025-03-15 18:16:52+0000 0s autopkgtest [18:16:52]: git checkout: 325255d2 Merge branch 'pin-any-arch' into 'ubuntu/production' 0s autopkgtest [18:16:52]: host juju-7f2275-prod-proposed-migration-environment-9; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.5375moix/out --timeout-copy=6000 --setup-commands 'ln -s /dev/null /etc/systemd/system/bluetooth.service; printf "http_proxy=http://squid.internal:3128\nhttps_proxy=http://squid.internal:3128\nno_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\n" >> /etc/environment' --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 -- lxd -r lxd-armhf-10.145.243.229 lxd-armhf-10.145.243.229:autopkgtest/ubuntu/plucky/armhf 22s autopkgtest [18:17:14]: testbed dpkg architecture: armhf 24s autopkgtest [18:17:16]: testbed apt version: 2.9.33 27s autopkgtest [18:17:19]: @@@@@@@@@@@@@@@@@@@@ test bed setup 29s autopkgtest [18:17:21]: testbed release detected to be: None 38s autopkgtest [18:17:30]: updating testbed package index (apt update) 40s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [126 kB] 40s Get:2 http://ftpmaster.internal/ubuntu plucky InRelease [257 kB] 40s Get:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease [126 kB] 40s Get:4 http://ftpmaster.internal/ubuntu plucky-security InRelease [126 kB] 41s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [15.8 kB] 41s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [99.7 kB] 41s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [379 kB] 41s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/main armhf Packages [114 kB] 41s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/main armhf c-n-f Metadata [1832 B] 41s Get:10 http://ftpmaster.internal/ubuntu plucky-proposed/restricted armhf c-n-f Metadata [116 B] 41s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/universe armhf Packages [312 kB] 42s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/universe armhf c-n-f Metadata [11.1 kB] 42s Get:13 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse armhf Packages [3472 B] 42s Get:14 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse armhf c-n-f Metadata [240 B] 42s Get:15 http://ftpmaster.internal/ubuntu plucky/main Sources [1394 kB] 43s Get:16 http://ftpmaster.internal/ubuntu plucky/universe Sources [21.0 MB] 62s Get:17 http://ftpmaster.internal/ubuntu plucky/multiverse Sources [299 kB] 62s Get:18 http://ftpmaster.internal/ubuntu plucky/main armhf Packages [1378 kB] 63s Get:19 http://ftpmaster.internal/ubuntu plucky/main armhf c-n-f Metadata [29.4 kB] 63s Get:20 http://ftpmaster.internal/ubuntu plucky/restricted armhf c-n-f Metadata [108 B] 63s Get:21 http://ftpmaster.internal/ubuntu plucky/universe armhf Packages [15.1 MB] 79s Get:22 http://ftpmaster.internal/ubuntu plucky/multiverse armhf Packages [172 kB] 81s Fetched 41.0 MB in 41s (998 kB/s) 82s Reading package lists... 88s autopkgtest [18:18:20]: upgrading testbed (apt dist-upgrade and autopurge) 89s Reading package lists... 90s Building dependency tree... 90s Reading state information... 90s Calculating upgrade...Starting pkgProblemResolver with broken count: 0 91s Starting 2 pkgProblemResolver with broken count: 0 91s Done 92s Entering ResolveByKeep 93s 94s Calculating upgrade... 94s The following packages will be upgraded: 94s libc-bin libc6 locales pinentry-curses python3-jinja2 sos strace 95s 7 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 95s Need to get 8683 kB of archives. 95s After this operation, 23.6 kB of additional disk space will be used. 95s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed/main armhf libc6 armhf 2.41-1ubuntu2 [2932 kB] 98s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/main armhf libc-bin armhf 2.41-1ubuntu2 [545 kB] 98s Get:3 http://ftpmaster.internal/ubuntu plucky-proposed/main armhf locales all 2.41-1ubuntu2 [4246 kB] 102s Get:4 http://ftpmaster.internal/ubuntu plucky/main armhf strace armhf 6.13+ds-1ubuntu1 [445 kB] 102s Get:5 http://ftpmaster.internal/ubuntu plucky/main armhf pinentry-curses armhf 1.3.1-2ubuntu3 [40.6 kB] 102s Get:6 http://ftpmaster.internal/ubuntu plucky/main armhf python3-jinja2 all 3.1.5-2ubuntu1 [109 kB] 102s Get:7 http://ftpmaster.internal/ubuntu plucky/main armhf sos all 4.9.0-5 [365 kB] 103s Preconfiguring packages ... 103s Fetched 8683 kB in 8s (1056 kB/s) 104s (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 ... 64655 files and directories currently installed.) 104s Preparing to unpack .../libc6_2.41-1ubuntu2_armhf.deb ... 104s Unpacking libc6:armhf (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 104s Setting up libc6:armhf (2.41-1ubuntu2) ... 104s (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 ... 64655 files and directories currently installed.) 104s Preparing to unpack .../libc-bin_2.41-1ubuntu2_armhf.deb ... 104s Unpacking libc-bin (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 104s Setting up libc-bin (2.41-1ubuntu2) ... 105s (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 ... 64655 files and directories currently installed.) 105s Preparing to unpack .../locales_2.41-1ubuntu2_all.deb ... 105s Unpacking locales (2.41-1ubuntu2) over (2.41-1ubuntu1) ... 105s Preparing to unpack .../strace_6.13+ds-1ubuntu1_armhf.deb ... 105s Unpacking strace (6.13+ds-1ubuntu1) over (6.11-0ubuntu1) ... 105s Preparing to unpack .../pinentry-curses_1.3.1-2ubuntu3_armhf.deb ... 105s Unpacking pinentry-curses (1.3.1-2ubuntu3) over (1.3.1-2ubuntu2) ... 105s Preparing to unpack .../python3-jinja2_3.1.5-2ubuntu1_all.deb ... 105s Unpacking python3-jinja2 (3.1.5-2ubuntu1) over (3.1.5-2) ... 105s Preparing to unpack .../archives/sos_4.9.0-5_all.deb ... 106s Unpacking sos (4.9.0-5) over (4.9.0-4) ... 106s Setting up sos (4.9.0-5) ... 106s Setting up pinentry-curses (1.3.1-2ubuntu3) ... 106s Setting up locales (2.41-1ubuntu2) ... 107s Generating locales (this might take a while)... 110s en_US.UTF-8... done 110s Generation complete. 110s Setting up python3-jinja2 (3.1.5-2ubuntu1) ... 110s Setting up strace (6.13+ds-1ubuntu1) ... 110s Processing triggers for man-db (2.13.0-1) ... 111s Processing triggers for systemd (257.3-1ubuntu3) ... 114s Reading package lists... 114s Building dependency tree... 114s Reading state information... 114s Starting pkgProblemResolver with broken count: 0 115s Starting 2 pkgProblemResolver with broken count: 0 115s Done 115s Solving dependencies... 116s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 118s autopkgtest [18:18:50]: rebooting testbed after setup commands that affected boot 160s autopkgtest [18:19:32]: testbed running kernel: Linux 6.8.0-52-generic #53~22.04.1-Ubuntu SMP PREEMPT_DYNAMIC Wed Jan 15 18:10:51 UTC 2 196s autopkgtest [18:20:08]: @@@@@@@@@@@@@@@@@@@@ apt-source vip-manager2 206s Get:1 http://ftpmaster.internal/ubuntu plucky/universe vip-manager2 3.0.0-2 (dsc) [2487 B] 206s Get:2 http://ftpmaster.internal/ubuntu plucky/universe vip-manager2 3.0.0-2 (tar) [46.4 kB] 206s Get:3 http://ftpmaster.internal/ubuntu plucky/universe vip-manager2 3.0.0-2 (diff) [9200 B] 206s gpgv: Signature made Mon Feb 3 15:49:05 2025 UTC 206s gpgv: using RSA key 5C48FE6157F49179597087C64C5A6BAB12D2A7AE 206s gpgv: Can't check signature: No public key 206s dpkg-source: warning: cannot verify inline signature for ./vip-manager2_3.0.0-2.dsc: no acceptable signature found 207s autopkgtest [18:20:19]: testing package vip-manager2 version 3.0.0-2 209s autopkgtest [18:20:21]: build not needed 212s autopkgtest [18:20:24]: test test: preparing testbed 214s Reading package lists... 214s Building dependency tree... 214s Reading state information... 214s Starting pkgProblemResolver with broken count: 0 214s Starting 2 pkgProblemResolver with broken count: 0 214s Done 215s The following NEW packages will be installed: 215s etcd-client etcd-server liblua5.4-0 ncat vip-manager2 216s 0 upgraded, 5 newly installed, 0 to remove and 0 not upgraded. 216s Need to get 21.2 MB of archives. 216s After this operation, 75.3 MB of additional disk space will be used. 216s Get:1 http://ftpmaster.internal/ubuntu plucky/universe armhf etcd-server armhf 3.5.16-4 [11.3 MB] 223s Get:2 http://ftpmaster.internal/ubuntu plucky/main armhf liblua5.4-0 armhf 5.4.7-1 [134 kB] 223s Get:3 http://ftpmaster.internal/ubuntu plucky/universe armhf ncat armhf 7.95+dfsg-2 [217 kB] 223s Get:4 http://ftpmaster.internal/ubuntu plucky/universe armhf vip-manager2 armhf 3.0.0-2 [4268 kB] 226s Get:5 http://ftpmaster.internal/ubuntu plucky/universe armhf etcd-client armhf 3.5.16-4 [5341 kB] 230s Fetched 21.2 MB in 14s (1522 kB/s) 230s Selecting previously unselected package etcd-server. 230s (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 ... 64655 files and directories currently installed.) 230s Preparing to unpack .../etcd-server_3.5.16-4_armhf.deb ... 230s Unpacking etcd-server (3.5.16-4) ... 230s Selecting previously unselected package liblua5.4-0:armhf. 230s Preparing to unpack .../liblua5.4-0_5.4.7-1_armhf.deb ... 230s Unpacking liblua5.4-0:armhf (5.4.7-1) ... 230s Selecting previously unselected package ncat. 230s Preparing to unpack .../ncat_7.95+dfsg-2_armhf.deb ... 230s Unpacking ncat (7.95+dfsg-2) ... 230s Selecting previously unselected package vip-manager2. 230s Preparing to unpack .../vip-manager2_3.0.0-2_armhf.deb ... 230s Unpacking vip-manager2 (3.0.0-2) ... 231s Selecting previously unselected package etcd-client. 231s Preparing to unpack .../etcd-client_3.5.16-4_armhf.deb ... 231s Unpacking etcd-client (3.5.16-4) ... 231s Setting up vip-manager2 (3.0.0-2) ... 231s Created symlink '/etc/systemd/system/multi-user.target.wants/vip-manager.service' → '/usr/lib/systemd/system/vip-manager.service'. 231s Setting up etcd-client (3.5.16-4) ... 231s Setting up liblua5.4-0:armhf (5.4.7-1) ... 231s Setting up etcd-server (3.5.16-4) ... 231s info: Selecting UID from range 100 to 999 ... 231s 231s info: Selecting GID from range 100 to 999 ... 231s info: Adding system user `etcd' (UID 107) ... 231s info: Adding new group `etcd' (GID 108) ... 231s info: Adding new user `etcd' (UID 107) with group `etcd' ... 231s info: Creating home directory `/var/lib/etcd/' ... 232s Created symlink '/etc/systemd/system/etcd2.service' → '/usr/lib/systemd/system/etcd.service'. 232s Created symlink '/etc/systemd/system/multi-user.target.wants/etcd.service' → '/usr/lib/systemd/system/etcd.service'. 233s Setting up ncat (7.95+dfsg-2) ... 233s Processing triggers for man-db (2.13.0-1) ... 234s Processing triggers for libc-bin (2.41-1ubuntu2) ... 242s autopkgtest [18:20:54]: test test: [----------------------- 245s ○ etcd.service - etcd - highly-available key value store 245s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 245s Active: inactive (dead) since Sat 2025-03-15 18:20:57 UTC; 20ms ago 245s Duration: 11.531s 245s Invocation: 6f76ef22a2874badb0dd5df0862a851e 245s Docs: https://etcd.io/docs 245s man:etcd 245s Process: 956 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 245s Main PID: 956 (code=killed, signal=TERM) 245s 245s Mar 15 18:20:57 autopkgtest-lxd-vzftql systemd[1]: Stopping etcd.service - etcd - highly-available key value store... 245s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"info","ts":"2025-03-15T18:20:57.132511Z","caller":"embed/etcd.go:378","msg":"closing etcd server","name":"autopkgtest-lxd-vzftql","data-dir":"/var/lib/etcd/default","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["http://localhost:2379"]} 245s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"warn","ts":"2025-03-15T18:20:57.132763Z","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"} 245s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"warn","ts":"2025-03-15T18:20:57.133215Z","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"} 245s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"info","ts":"2025-03-15T18:20:57.133343Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 245s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"info","ts":"2025-03-15T18:20:57.139153Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 245s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"info","ts":"2025-03-15T18:20:57.139451Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 245s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"info","ts":"2025-03-15T18:20:57.139518Z","caller":"embed/etcd.go:380","msg":"closed etcd server","name":"autopkgtest-lxd-vzftql","data-dir":"/var/lib/etcd/default","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["http://localhost:2379"]} 245s Mar 15 18:20:57 autopkgtest-lxd-vzftql systemd[1]: etcd.service: Deactivated successfully. 245s Mar 15 18:20:57 autopkgtest-lxd-vzftql systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 245s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 245s {"level":"info","ts":"2025-03-15T18:20:57.247013Z","caller":"etcdmain/etcd.go:482","msg":"running etcd on unsupported architecture since ETCD_UNSUPPORTED_ARCH is set","arch":"arm"} 245s {"level":"warn","ts":"2025-03-15T18:20:57.249217Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 245s {"level":"info","ts":"2025-03-15T18:20:57.249334Z","caller":"etcdmain/etcd.go:73","msg":"Running: ","args":["etcd"]} 245s {"level":"warn","ts":"2025-03-15T18:20:57.249377Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 245s {"level":"warn","ts":"2025-03-15T18:20:57.249447Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 245s {"level":"info","ts":"2025-03-15T18:20:57.249462Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 245s {"level":"info","ts":"2025-03-15T18:20:57.250165Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["http://localhost:2379"]} 245s {"level":"info","ts":"2025-03-15T18:20:57.250422Z","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":"arm","max-cpu-set":8,"max-cpu-available":8,"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"} 245s {"level":"info","ts":"2025-03-15T18:20:57.253496Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"2.232016ms"} 245s {"level":"info","ts":"2025-03-15T18:20:57.260582Z","caller":"etcdserver/raft.go:505","msg":"starting local member","local-member-id":"8e9e05c52164694d","cluster-id":"cdf818194e3a8c32"} 245s {"level":"info","ts":"2025-03-15T18:20:57.260801Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 245s {"level":"info","ts":"2025-03-15T18:20:57.260919Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 0"} 245s {"level":"info","ts":"2025-03-15T18:20:57.260933Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]"} 245s {"level":"info","ts":"2025-03-15T18:20:57.260950Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 1"} 245s {"level":"info","ts":"2025-03-15T18:20:57.261027Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 245s {"level":"warn","ts":"2025-03-15T18:20:57.265583Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 245s {"level":"info","ts":"2025-03-15T18:20:57.269639Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":1} 245s {"level":"info","ts":"2025-03-15T18:20:57.273237Z","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"} 245s {"level":"info","ts":"2025-03-15T18:20:57.276497Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 245s {"level":"info","ts":"2025-03-15T18:20:57.276834Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 245s {"level":"info","ts":"2025-03-15T18:20:57.276844Z","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"} 245s {"level":"info","ts":"2025-03-15T18:20:57.277000Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 245s {"level":"info","ts":"2025-03-15T18:20:57.277368Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 245s {"level":"info","ts":"2025-03-15T18:20:57.277415Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 245s {"level":"info","ts":"2025-03-15T18:20:57.279565Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 245s {"level":"info","ts":"2025-03-15T18:20:57.280797Z","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":[]} 245s {"level":"info","ts":"2025-03-15T18:20:57.280860Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 245s {"level":"info","ts":"2025-03-15T18:20:57.280962Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 245s {"level":"info","ts":"2025-03-15T18:20:57.281859Z","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"]} 246s {"level":"info","ts":"2025-03-15T18:20:58.261895Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 1"} 246s {"level":"info","ts":"2025-03-15T18:20:58.261968Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 1"} 246s {"level":"info","ts":"2025-03-15T18:20:58.262024Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 1"} 246s {"level":"info","ts":"2025-03-15T18:20:58.262045Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 2"} 246s {"level":"info","ts":"2025-03-15T18:20:58.262057Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 2"} 246s {"level":"info","ts":"2025-03-15T18:20:58.262074Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 2"} 246s {"level":"info","ts":"2025-03-15T18:20:58.262092Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 2"} 246s {"level":"info","ts":"2025-03-15T18:20:58.264735Z","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"} 246s {"level":"info","ts":"2025-03-15T18:20:58.264779Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 246s {"level":"info","ts":"2025-03-15T18:20:58.264956Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 246s {"level":"info","ts":"2025-03-15T18:20:58.265051Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 246s {"level":"info","ts":"2025-03-15T18:20:58.264863Z","caller":"etcdserver/server.go:2651","msg":"setting up initial cluster version using v2 API","cluster-version":"3.5"} 246s {"level":"info","ts":"2025-03-15T18:20:58.266372Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 246s {"level":"info","ts":"2025-03-15T18:20:58.267142Z","caller":"embed/serve.go:188","msg":"serving client traffic insecurely; this is strongly discouraged!","traffic":"grpc+http","address":"127.0.0.1:2379"} 246s {"level":"info","ts":"2025-03-15T18:20:58.267867Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 246s {"level":"info","ts":"2025-03-15T18:20:58.268065Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 246s {"level":"info","ts":"2025-03-15T18:20:58.268143Z","caller":"etcdserver/server.go:2675","msg":"cluster version is updated","cluster-version":"3.5"} 247s Ncat: Version 7.95 ( https://nmap.org/ncat ) 247s Ncat: Listening on 0.0.0.0:12345 247s 0 247s No dcs-endpoints specified, trying to use localhost with standard ports! 247s This is the config that will be used: 247s dcs-endpoints : [http://127.0.0.1:2379] 247s dcs-type : etcd 247s hostingtype : basic 247s interface : eth0 247s interval : 3000 247s ip : 10.0.2.123 247s manager-type : basic 247s netmask : 32 247s retry-after : 250 247s retry-num : 3 247s trigger-key : service/pgcluster/leader 247s trigger-value : autopkgtest-lxd-vzftql 247s verbose : false 247s version : false 247s 2025-03-15T18:20:59.319Z INFO IP address 10.0.2.123/32 is down, must be down 247s 2025-03-15T18:20:59.319Z INFO Setting WATCH on service/pgcluster/leader 249s 2025-03-15T18:21:01.328Z INFO Current leader from DCS: autopkgtest-lxd-vzftql 249s OK 249s 2025-03-15T18:21:01.329Z INFO IP address 10.0.2.123/32 is down, must be up 249s 2025-03-15T18:21:01.329Z INFO Configuring address 10.0.2.123/32 on eth0 249s 2025-03-15T18:21:01.335Z INFO Sent gratuitous ARP reply 249s 2025-03-15T18:21:01.335Z INFO Sent gratuitous ARP request 251s inet 10.0.2.123/32 scope global eth0 251s Ncat: Version 7.95 ( https://nmap.org/ncat ) 251s Ncat: Connected to 10.0.2.123:12345. 251s Ncat: 0 bytes sent, 0 bytes received in 0.03 seconds. 251s Ncat: Connection from 10.0.2.123:56820. 251s 2025-03-15T18:21:03.408Z INFO Current leader from DCS: 0xGARBAGE 251s OK 251s 2025-03-15T18:21:03.409Z INFO IP address 10.0.2.123/32 is up, must be down 251s 2025-03-15T18:21:03.409Z INFO Removing address 10.0.2.123/32 on eth0 253s Ncat: Version 7.95 ( https://nmap.org/ncat ) 253s ### You've reached the end of the script, all "tests" have successfully been passed! ### 253s Ncat: Connection refused. 253s {"level":"info","ts":"2025-03-15T18:21:05.476531Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 253s {"level":"info","ts":"2025-03-15T18:21:05.476647Z","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"]} 253s {"level":"warn","ts":"2025-03-15T18:21:05.476795Z","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"} 253s {"level":"warn","ts":"2025-03-15T18:21:05.477243Z","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"} 253s {"level":"info","ts":"2025-03-15T18:21:05.477328Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 253s {"level":"info","ts":"2025-03-15T18:21:05.486224Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 253s {"level":"info","ts":"2025-03-15T18:21:05.486476Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 253s {"level":"info","ts":"2025-03-15T18:21:05.486501Z","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"]} 253s autopkgtest [18:21:05]: test test: -----------------------] 257s autopkgtest [18:21:09]: test test: - - - - - - - - - - results - - - - - - - - - - 257s test PASS 261s autopkgtest [18:21:13]: test cacert-test: preparing testbed 264s Reading package lists... 264s Building dependency tree... 264s Reading state information... 264s Starting pkgProblemResolver with broken count: 0 265s Starting 2 pkgProblemResolver with broken count: 0 265s Done 266s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 274s autopkgtest [18:21:26]: test cacert-test: [----------------------- 276s ○ etcd.service - etcd - highly-available key value store 276s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 276s Active: inactive (dead) since Sat 2025-03-15 18:20:57 UTC; 31s ago 276s Duration: 11.531s 276s Invocation: 6f76ef22a2874badb0dd5df0862a851e 276s Docs: https://etcd.io/docs 276s man:etcd 276s Process: 956 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 276s Main PID: 956 (code=killed, signal=TERM) 276s 276s Mar 15 18:20:57 autopkgtest-lxd-vzftql systemd[1]: Stopping etcd.service - etcd - highly-available key value store... 276s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"info","ts":"2025-03-15T18:20:57.132511Z","caller":"embed/etcd.go:378","msg":"closing etcd server","name":"autopkgtest-lxd-vzftql","data-dir":"/var/lib/etcd/default","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["http://localhost:2379"]} 276s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"warn","ts":"2025-03-15T18:20:57.132763Z","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"} 276s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"warn","ts":"2025-03-15T18:20:57.133215Z","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"} 276s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"info","ts":"2025-03-15T18:20:57.133343Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 276s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"info","ts":"2025-03-15T18:20:57.139153Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 276s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"info","ts":"2025-03-15T18:20:57.139451Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 276s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"info","ts":"2025-03-15T18:20:57.139518Z","caller":"embed/etcd.go:380","msg":"closed etcd server","name":"autopkgtest-lxd-vzftql","data-dir":"/var/lib/etcd/default","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["http://localhost:2379"]} 276s Mar 15 18:20:57 autopkgtest-lxd-vzftql systemd[1]: etcd.service: Deactivated successfully. 276s Mar 15 18:20:57 autopkgtest-lxd-vzftql systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 276s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 277s {"level":"info","ts":"2025-03-15T18:21:28.975080Z","caller":"etcdmain/etcd.go:482","msg":"running etcd on unsupported architecture since ETCD_UNSUPPORTED_ARCH is set","arch":"arm"} 277s {"level":"warn","ts":"2025-03-15T18:21:28.976956Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 277s {"level":"info","ts":"2025-03-15T18:21:28.977079Z","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"]} 277s {"level":"warn","ts":"2025-03-15T18:21:28.977121Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 277s {"level":"info","ts":"2025-03-15T18:21:28.977244Z","caller":"etcdmain/etcd.go:116","msg":"server has been already initialized","data-dir":"default.etcd","dir-type":"member"} 277s {"level":"warn","ts":"2025-03-15T18:21:28.977281Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 277s {"level":"info","ts":"2025-03-15T18:21:28.977296Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 277s {"level":"info","ts":"2025-03-15T18:21:28.978036Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["https://127.0.0.1:2379"]} 277s {"level":"info","ts":"2025-03-15T18:21:28.978285Z","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":"arm","max-cpu-set":8,"max-cpu-available":8,"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"} 277s {"level":"info","ts":"2025-03-15T18:21:28.979071Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"398.483µs"} 277s {"level":"info","ts":"2025-03-15T18:21:28.979478Z","caller":"etcdserver/server.go:532","msg":"No snapshot found. Recovering WAL from scratch!"} 277s {"level":"info","ts":"2025-03-15T18:21:28.981394Z","caller":"etcdserver/raft.go:540","msg":"restarting local member","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","commit-index":7} 277s {"level":"info","ts":"2025-03-15T18:21:28.981548Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 277s {"level":"info","ts":"2025-03-15T18:21:28.981857Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 2"} 277s {"level":"info","ts":"2025-03-15T18:21:28.982270Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 2, commit: 7, applied: 0, lastindex: 7, lastterm: 2]"} 277s {"level":"warn","ts":"2025-03-15T18:21:28.987160Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 277s {"level":"info","ts":"2025-03-15T18:21:28.991712Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":3} 277s {"level":"info","ts":"2025-03-15T18:21:29.005332Z","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"} 277s {"level":"info","ts":"2025-03-15T18:21:29.015801Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 277s {"level":"info","ts":"2025-03-15T18:21:29.016380Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 277s {"level":"info","ts":"2025-03-15T18:21:29.016490Z","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"]} 277s {"level":"info","ts":"2025-03-15T18:21:29.016383Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 277s {"level":"info","ts":"2025-03-15T18:21:29.016875Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 277s {"level":"info","ts":"2025-03-15T18:21:29.017100Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 277s {"level":"info","ts":"2025-03-15T18:21:29.017114Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 277s {"level":"info","ts":"2025-03-15T18:21:29.016716Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 277s {"level":"info","ts":"2025-03-15T18:21:29.017198Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 277s {"level":"info","ts":"2025-03-15T18:21:29.017298Z","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"} 277s {"level":"info","ts":"2025-03-15T18:21:29.020466Z","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":[]} 277s {"level":"info","ts":"2025-03-15T18:21:29.020624Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 277s {"level":"info","ts":"2025-03-15T18:21:29.020794Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 277s {"level":"warn","ts":"2025-03-15T18:21:29.020858Z","caller":"embed/etcd.go:742","msg":"Flag `enable-v2` is deprecated and will get removed in etcd 3.6."} 277s {"level":"info","ts":"2025-03-15T18:21:29.021317Z","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":[]} 277s {"level":"info","ts":"2025-03-15T18:21:29.883040Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 2"} 277s {"level":"info","ts":"2025-03-15T18:21:29.883136Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 2"} 277s {"level":"info","ts":"2025-03-15T18:21:29.883213Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 2"} 277s {"level":"info","ts":"2025-03-15T18:21:29.883233Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 3"} 277s {"level":"info","ts":"2025-03-15T18:21:29.883243Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 3"} 277s {"level":"info","ts":"2025-03-15T18:21:29.883256Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 3"} 277s {"level":"info","ts":"2025-03-15T18:21:29.883267Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 3"} 277s {"level":"info","ts":"2025-03-15T18:21:29.887303Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 277s {"level":"info","ts":"2025-03-15T18:21:29.887318Z","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"} 277s {"level":"info","ts":"2025-03-15T18:21:29.887557Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 277s {"level":"info","ts":"2025-03-15T18:21:29.887642Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 277s {"level":"info","ts":"2025-03-15T18:21:29.890445Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 277s {"level":"info","ts":"2025-03-15T18:21:29.893201Z","caller":"embed/serve.go:251","msg":"serving client traffic securely","traffic":"grpc+http","address":"127.0.0.1:2379"} 278s Ncat: Version 7.95 ( https://nmap.org/ncat ) 278s Ncat: Listening on 0.0.0.0:12345 279s 1 281s OK 283s inet 10.0.2.123/32 scope global eth0 283s Ncat: Version 7.95 ( https://nmap.org/ncat ) 283s Ncat: Connected to 10.0.2.123:12345. 283s Ncat: 0 bytes sent, 0 bytes received in 0.03 seconds. 283s Ncat: Connection from 10.0.2.123:52676. 283s ### You've reached the end of the script, all "tests" have successfully been passed! ### 283s {"level":"info","ts":"2025-03-15T18:21:35.253621Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 283s {"level":"info","ts":"2025-03-15T18:21:35.253751Z","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"]} 283s {"level":"warn","ts":"2025-03-15T18:21:35.253898Z","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"} 283s {"level":"warn","ts":"2025-03-15T18:21:35.253936Z","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"} 283s {"level":"info","ts":"2025-03-15T18:21:35.255640Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 283s {"level":"info","ts":"2025-03-15T18:21:35.259745Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 283s {"level":"info","ts":"2025-03-15T18:21:35.260137Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 283s {"level":"info","ts":"2025-03-15T18:21:35.260170Z","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"]} 283s autopkgtest [18:21:35]: test cacert-test: -----------------------] 287s cacert-test PASS 287s autopkgtest [18:21:39]: test cacert-test: - - - - - - - - - - results - - - - - - - - - - 291s autopkgtest [18:21:43]: test clientcert-test: preparing testbed 294s Reading package lists... 294s Building dependency tree... 294s Reading state information... 294s Starting pkgProblemResolver with broken count: 0 294s Starting 2 pkgProblemResolver with broken count: 0 294s Done 295s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 305s autopkgtest [18:21:57]: test clientcert-test: [----------------------- 307s ○ etcd.service - etcd - highly-available key value store 307s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 307s Active: inactive (dead) since Sat 2025-03-15 18:20:57 UTC; 1min 2s ago 307s Duration: 11.531s 307s Invocation: 6f76ef22a2874badb0dd5df0862a851e 307s Docs: https://etcd.io/docs 307s man:etcd 307s Process: 956 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 307s Main PID: 956 (code=killed, signal=TERM) 307s 307s Mar 15 18:20:57 autopkgtest-lxd-vzftql systemd[1]: Stopping etcd.service - etcd - highly-available key value store... 307s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"info","ts":"2025-03-15T18:20:57.132511Z","caller":"embed/etcd.go:378","msg":"closing etcd server","name":"autopkgtest-lxd-vzftql","data-dir":"/var/lib/etcd/default","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["http://localhost:2379"]} 307s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"warn","ts":"2025-03-15T18:20:57.132763Z","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"} 307s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"warn","ts":"2025-03-15T18:20:57.133215Z","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"} 307s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"info","ts":"2025-03-15T18:20:57.133343Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 307s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"info","ts":"2025-03-15T18:20:57.139153Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 307s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"info","ts":"2025-03-15T18:20:57.139451Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 307s Mar 15 18:20:57 autopkgtest-lxd-vzftql etcd[956]: {"level":"info","ts":"2025-03-15T18:20:57.139518Z","caller":"embed/etcd.go:380","msg":"closed etcd server","name":"autopkgtest-lxd-vzftql","data-dir":"/var/lib/etcd/default","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["http://localhost:2379"]} 307s Mar 15 18:20:57 autopkgtest-lxd-vzftql systemd[1]: etcd.service: Deactivated successfully. 307s Mar 15 18:20:57 autopkgtest-lxd-vzftql systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 307s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 308s inet 10.0.2.123/32 scope global eth0 308s {"level":"info","ts":"2025-03-15T18:22:00.018146Z","caller":"etcdmain/etcd.go:482","msg":"running etcd on unsupported architecture since ETCD_UNSUPPORTED_ARCH is set","arch":"arm"} 308s {"level":"warn","ts":"2025-03-15T18:22:00.021164Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 308s {"level":"info","ts":"2025-03-15T18:22:00.021386Z","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"]} 308s {"level":"warn","ts":"2025-03-15T18:22:00.021445Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 308s {"level":"info","ts":"2025-03-15T18:22:00.021672Z","caller":"etcdmain/etcd.go:116","msg":"server has been already initialized","data-dir":"default.etcd","dir-type":"member"} 308s {"level":"warn","ts":"2025-03-15T18:22:00.021733Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 308s {"level":"info","ts":"2025-03-15T18:22:00.021760Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 308s {"level":"info","ts":"2025-03-15T18:22:00.022763Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["https://127.0.0.1:2379"]} 308s {"level":"info","ts":"2025-03-15T18:22:00.023234Z","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":"arm","max-cpu-set":8,"max-cpu-available":8,"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"} 308s {"level":"info","ts":"2025-03-15T18:22:00.024298Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"464.163µs"} 308s {"level":"info","ts":"2025-03-15T18:22:00.025063Z","caller":"etcdserver/server.go:532","msg":"No snapshot found. Recovering WAL from scratch!"} 308s {"level":"info","ts":"2025-03-15T18:22:00.027054Z","caller":"etcdserver/raft.go:540","msg":"restarting local member","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","commit-index":11} 308s {"level":"info","ts":"2025-03-15T18:22:00.027533Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 308s {"level":"info","ts":"2025-03-15T18:22:00.027727Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 3"} 308s {"level":"info","ts":"2025-03-15T18:22:00.027788Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 3, commit: 11, applied: 0, lastindex: 11, lastterm: 3]"} 308s {"level":"warn","ts":"2025-03-15T18:22:00.032551Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 308s {"level":"info","ts":"2025-03-15T18:22:00.035826Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":5} 308s {"level":"info","ts":"2025-03-15T18:22:00.040378Z","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"} 308s {"level":"info","ts":"2025-03-15T18:22:00.044272Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 308s {"level":"info","ts":"2025-03-15T18:22:00.044602Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 308s {"level":"info","ts":"2025-03-15T18:22:00.044824Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 308s {"level":"info","ts":"2025-03-15T18:22:00.044925Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 308s {"level":"info","ts":"2025-03-15T18:22:00.044938Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 308s {"level":"info","ts":"2025-03-15T18:22:00.045153Z","caller":"etcdserver/server.go:773","msg":"starting initial election tick advance","election-ticks":10} 308s {"level":"info","ts":"2025-03-15T18:22:00.046086Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 308s {"level":"info","ts":"2025-03-15T18:22:00.046351Z","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"]} 308s {"level":"info","ts":"2025-03-15T18:22:00.046585Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 308s {"level":"info","ts":"2025-03-15T18:22:00.046683Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 308s {"level":"info","ts":"2025-03-15T18:22:00.049415Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 308s {"level":"info","ts":"2025-03-15T18:22:00.049342Z","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":[]} 308s {"level":"info","ts":"2025-03-15T18:22:00.049530Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 308s {"level":"warn","ts":"2025-03-15T18:22:00.049574Z","caller":"embed/etcd.go:742","msg":"Flag `enable-v2` is deprecated and will get removed in etcd 3.6."} 308s {"level":"info","ts":"2025-03-15T18:22:00.050996Z","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":[]} 309s {"level":"info","ts":"2025-03-15T18:22:01.629432Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 3"} 309s {"level":"info","ts":"2025-03-15T18:22:01.629763Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 3"} 309s {"level":"info","ts":"2025-03-15T18:22:01.629806Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 3"} 309s {"level":"info","ts":"2025-03-15T18:22:01.629845Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 4"} 309s {"level":"info","ts":"2025-03-15T18:22:01.629870Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 4"} 309s {"level":"info","ts":"2025-03-15T18:22:01.629895Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 4"} 309s {"level":"info","ts":"2025-03-15T18:22:01.629914Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 4"} 309s {"level":"info","ts":"2025-03-15T18:22:01.633291Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 309s {"level":"info","ts":"2025-03-15T18:22:01.633259Z","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"} 309s {"level":"info","ts":"2025-03-15T18:22:01.633826Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 309s {"level":"info","ts":"2025-03-15T18:22:01.633925Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 309s {"level":"info","ts":"2025-03-15T18:22:01.636867Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 309s {"level":"info","ts":"2025-03-15T18:22:01.639654Z","caller":"embed/serve.go:251","msg":"serving client traffic securely","traffic":"grpc+http","address":"127.0.0.1:2379"} 310s Ncat: Version 7.95 ( https://nmap.org/ncat ) 310s Ncat: Listening on 0.0.0.0:12345 310s 1 312s OK 314s inet 10.0.2.123/32 scope global eth0 314s Ncat: Version 7.95 ( https://nmap.org/ncat ) 314s Ncat: Ncat: Connection from 10.0.2.123:41952. 314s Connected to 10.0.2.123:12345. 314s Ncat: 0 bytes sent, 0 bytes received in 0.03 seconds. 314s ### You've reached the end of the script, all "tests" have successfully been passed! ### 314s {"level":"info","ts":"2025-03-15T18:22:06.308268Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 314s {"level":"info","ts":"2025-03-15T18:22:06.308598Z","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"]} 314s {"level":"warn","ts":"2025-03-15T18:22:06.308788Z","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"} 314s {"level":"warn","ts":"2025-03-15T18:22:06.309348Z","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"} 314s {"level":"info","ts":"2025-03-15T18:22:06.314210Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 314s {"level":"info","ts":"2025-03-15T18:22:06.324533Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 314s {"level":"info","ts":"2025-03-15T18:22:06.324967Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 314s {"level":"info","ts":"2025-03-15T18:22:06.325120Z","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"]} 314s autopkgtest [18:22:06]: test clientcert-test: -----------------------] 318s clientcert-test PASS 318s autopkgtest [18:22:10]: test clientcert-test: - - - - - - - - - - results - - - - - - - - - - 323s autopkgtest [18:22:15]: @@@@@@@@@@@@@@@@@@@@ summary 323s test PASS 323s cacert-test PASS 323s clientcert-test PASS