0s autopkgtest [04:54:31]: starting date and time: 2024-11-04 04:54:31+0000 0s autopkgtest [04:54:31]: git checkout: 6f3be7a8 Fix armhf LXD image generation for plucky 0s autopkgtest [04:54:31]: host juju-7f2275-prod-proposed-migration-environment-14; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.cmpoirl1/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@lcy02-26.secgroup --name adt-plucky-amd64-vip-manager2-20241104-045430-juju-7f2275-prod-proposed-migration-environment-14-9aa9ffb5-a0d1-4b05-90d9-7aceb038a858 --image adt/ubuntu-plucky-amd64-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/ 43s autopkgtest [04:55:14]: testbed dpkg architecture: amd64 43s autopkgtest [04:55:14]: testbed apt version: 2.9.8 43s autopkgtest [04:55:14]: @@@@@@@@@@@@@@@@@@@@ test bed setup 43s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [73.9 kB] 43s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [31.2 kB] 43s Get:3 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [2268 kB] 43s Get:4 http://ftpmaster.internal/ubuntu plucky-proposed/restricted Sources [7016 B] 43s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [177 kB] 43s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/main i386 Packages [165 kB] 43s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/main amd64 Packages [238 kB] 43s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/restricted amd64 Packages [32.6 kB] 43s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/universe i386 Packages [833 kB] 43s Get:10 http://ftpmaster.internal/ubuntu plucky-proposed/universe amd64 Packages [1715 kB] 43s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse i386 Packages [18.1 kB] 43s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse amd64 Packages [58.6 kB] 44s Fetched 5618 kB in 1s (10.0 MB/s) 44s Reading package lists... 45s Reading package lists... 45s Building dependency tree... 45s Reading state information... 46s Calculating upgrade... 46s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 46s Reading package lists... 46s Building dependency tree... 46s Reading state information... 46s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 47s Hit:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease 47s Hit:2 http://ftpmaster.internal/ubuntu plucky InRelease 47s Hit:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease 47s Hit:4 http://ftpmaster.internal/ubuntu plucky-security InRelease 48s Reading package lists... 48s Reading package lists... 48s Building dependency tree... 48s Reading state information... 48s Calculating upgrade... 49s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 49s Reading package lists... 49s Building dependency tree... 49s Reading state information... 49s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 50s autopkgtest [04:55:21]: testbed running kernel: Linux 6.11.0-8-generic #8-Ubuntu SMP PREEMPT_DYNAMIC Mon Sep 16 13:41:20 UTC 2024 50s autopkgtest [04:55:21]: @@@@@@@@@@@@@@@@@@@@ apt-source vip-manager2 51s Get:1 http://ftpmaster.internal/ubuntu plucky/universe vip-manager2 2.5.0-1 (dsc) [2487 B] 51s Get:2 http://ftpmaster.internal/ubuntu plucky/universe vip-manager2 2.5.0-1 (tar) [45.4 kB] 51s Get:3 http://ftpmaster.internal/ubuntu plucky/universe vip-manager2 2.5.0-1 (diff) [8284 B] 51s gpgv: Signature made Fri May 17 08:39:51 2024 UTC 51s gpgv: using RSA key 5C48FE6157F49179597087C64C5A6BAB12D2A7AE 51s gpgv: Can't check signature: No public key 51s dpkg-source: warning: cannot verify inline signature for ./vip-manager2_2.5.0-1.dsc: no acceptable signature found 51s autopkgtest [04:55:22]: testing package vip-manager2 version 2.5.0-1 51s autopkgtest [04:55:22]: build not needed 51s autopkgtest [04:55:22]: test test: preparing testbed 51s Reading package lists... 52s Building dependency tree... 52s Reading state information... 52s Starting pkgProblemResolver with broken count: 0 52s Starting 2 pkgProblemResolver with broken count: 0 52s Done 52s The following additional packages will be installed: 52s etcd-client etcd-server liblua5.4-0 ncat vip-manager2 52s The following NEW packages will be installed: 52s autopkgtest-satdep etcd-client etcd-server liblua5.4-0 ncat vip-manager2 52s 0 upgraded, 6 newly installed, 0 to remove and 0 not upgraded. 52s Need to get 21.9 MB/21.9 MB of archives. 52s After this operation, 73.9 MB of additional disk space will be used. 52s Get:1 /tmp/autopkgtest.9kUWL4/1-autopkgtest-satdep.deb autopkgtest-satdep amd64 0 [740 B] 52s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/universe amd64 etcd-server amd64 3.5.16-3 [11.9 MB] 53s Get:3 http://ftpmaster.internal/ubuntu plucky/main amd64 liblua5.4-0 amd64 5.4.6-3build2 [166 kB] 53s Get:4 http://ftpmaster.internal/ubuntu plucky/universe amd64 ncat amd64 7.94+git20230807.3be01efb1+dfsg-4 [215 kB] 53s Get:5 http://ftpmaster.internal/ubuntu plucky/universe amd64 vip-manager2 amd64 2.5.0-1 [3994 kB] 53s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/universe amd64 etcd-client amd64 3.5.16-3 [5647 kB] 53s Fetched 21.9 MB in 0s (46.4 MB/s) 53s Selecting previously unselected package etcd-server. 53s (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 ... 75323 files and directories currently installed.) 53s Preparing to unpack .../0-etcd-server_3.5.16-3_amd64.deb ... 53s Unpacking etcd-server (3.5.16-3) ... 54s Selecting previously unselected package liblua5.4-0:amd64. 54s Preparing to unpack .../1-liblua5.4-0_5.4.6-3build2_amd64.deb ... 54s Unpacking liblua5.4-0:amd64 (5.4.6-3build2) ... 54s Selecting previously unselected package ncat. 54s Preparing to unpack .../2-ncat_7.94+git20230807.3be01efb1+dfsg-4_amd64.deb ... 54s Unpacking ncat (7.94+git20230807.3be01efb1+dfsg-4) ... 54s Selecting previously unselected package vip-manager2. 54s Preparing to unpack .../3-vip-manager2_2.5.0-1_amd64.deb ... 54s Unpacking vip-manager2 (2.5.0-1) ... 54s Selecting previously unselected package etcd-client. 54s Preparing to unpack .../4-etcd-client_3.5.16-3_amd64.deb ... 54s Unpacking etcd-client (3.5.16-3) ... 54s Selecting previously unselected package autopkgtest-satdep. 54s Preparing to unpack .../5-1-autopkgtest-satdep.deb ... 54s Unpacking autopkgtest-satdep (0) ... 54s Setting up vip-manager2 (2.5.0-1) ... 54s Created symlink '/etc/systemd/system/multi-user.target.wants/vip-manager.service' → '/usr/lib/systemd/system/vip-manager.service'. 54s Setting up etcd-client (3.5.16-3) ... 54s Setting up liblua5.4-0:amd64 (5.4.6-3build2) ... 54s Setting up etcd-server (3.5.16-3) ... 54s info: Selecting UID from range 100 to 999 ... 54s 54s info: Selecting GID from range 100 to 999 ... 54s info: Adding system user `etcd' (UID 108) ... 54s info: Adding new group `etcd' (GID 109) ... 54s info: Adding new user `etcd' (UID 108) with group `etcd' ... 54s info: Creating home directory `/var/lib/etcd/' ... 55s Created symlink '/etc/systemd/system/etcd2.service' → '/usr/lib/systemd/system/etcd.service'. 55s Created symlink '/etc/systemd/system/multi-user.target.wants/etcd.service' → '/usr/lib/systemd/system/etcd.service'. 56s Setting up ncat (7.94+git20230807.3be01efb1+dfsg-4) ... 56s Setting up autopkgtest-satdep (0) ... 56s Processing triggers for man-db (2.12.1-3) ... 56s Processing triggers for libc-bin (2.40-1ubuntu3) ... 58s (Reading database ... 75368 files and directories currently installed.) 58s Removing autopkgtest-satdep (0) ... 58s autopkgtest [04:55:29]: test test: [----------------------- 59s ○ etcd.service - etcd - highly-available key value store 59s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 59s Active: inactive (dead) since Mon 2024-11-04 04:55:30 UTC; 15ms ago 59s Duration: 3.567s 59s Invocation: a6d8150a3637403a8cb81e1668ecfa31 59s Docs: https://etcd.io/docs 59s man:etcd 59s Process: 2214 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 59s Main PID: 2214 (code=killed, signal=TERM) 59s Mem peak: 7M 59s CPU: 52ms 59s 59s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"info","ts":"2024-11-04T04:55:30.673025Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 59s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"info","ts":"2024-11-04T04:55:30.673074Z","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"]} 59s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"warn","ts":"2024-11-04T04:55:30.673148Z","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"} 59s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"warn","ts":"2024-11-04T04:55:30.673276Z","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"} 59s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"info","ts":"2024-11-04T04:55:30.673291Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 59s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"info","ts":"2024-11-04T04:55:30.675690Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 59s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"info","ts":"2024-11-04T04:55:30.675787Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 59s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"info","ts":"2024-11-04T04:55:30.675804Z","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"]} 59s Nov 04 04:55:30 autopkgtest systemd[1]: etcd.service: Deactivated successfully. 59s Nov 04 04:55:30 autopkgtest systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 59s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 59s {"level":"warn","ts":"2024-11-04T04:55:30.764678Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_UNSUPPORTED_ARCH="} 59s {"level":"warn","ts":"2024-11-04T04:55:30.764897Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 59s {"level":"info","ts":"2024-11-04T04:55:30.764930Z","caller":"etcdmain/etcd.go:73","msg":"Running: ","args":["etcd"]} 59s {"level":"warn","ts":"2024-11-04T04:55:30.764950Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 59s {"level":"warn","ts":"2024-11-04T04:55:30.764980Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 59s {"level":"info","ts":"2024-11-04T04:55:30.764990Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 59s {"level":"info","ts":"2024-11-04T04:55:30.765607Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["http://localhost:2379"]} 59s {"level":"info","ts":"2024-11-04T04:55:30.765789Z","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":"amd64","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"} 59s {"level":"info","ts":"2024-11-04T04:55:30.774498Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"8.291468ms"} 59s {"level":"info","ts":"2024-11-04T04:55:30.781957Z","caller":"etcdserver/raft.go:505","msg":"starting local member","local-member-id":"8e9e05c52164694d","cluster-id":"cdf818194e3a8c32"} 59s {"level":"info","ts":"2024-11-04T04:55:30.782021Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 59s {"level":"info","ts":"2024-11-04T04:55:30.782051Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 0"} 59s {"level":"info","ts":"2024-11-04T04:55:30.782058Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]"} 59s {"level":"info","ts":"2024-11-04T04:55:30.782068Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 1"} 59s {"level":"info","ts":"2024-11-04T04:55:30.782094Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 59s {"level":"warn","ts":"2024-11-04T04:55:30.788592Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 59s {"level":"info","ts":"2024-11-04T04:55:30.790098Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":1} 59s {"level":"info","ts":"2024-11-04T04:55:30.791326Z","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"} 59s {"level":"info","ts":"2024-11-04T04:55:30.792589Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 59s {"level":"info","ts":"2024-11-04T04:55:30.792749Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 59s {"level":"info","ts":"2024-11-04T04:55:30.793365Z","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"} 59s {"level":"info","ts":"2024-11-04T04:55:30.793476Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 59s {"level":"info","ts":"2024-11-04T04:55:30.793516Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 59s {"level":"info","ts":"2024-11-04T04:55:30.793524Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 59s {"level":"info","ts":"2024-11-04T04:55:30.793768Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 59s {"level":"info","ts":"2024-11-04T04:55:30.794322Z","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"]} 59s {"level":"info","ts":"2024-11-04T04:55:30.795844Z","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":[]} 59s {"level":"info","ts":"2024-11-04T04:55:30.797244Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 59s {"level":"info","ts":"2024-11-04T04:55:30.797279Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 59s {"level":"info","ts":"2024-11-04T04:55:30.883205Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 1"} 59s {"level":"info","ts":"2024-11-04T04:55:30.883259Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 1"} 59s {"level":"info","ts":"2024-11-04T04:55:30.883290Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 1"} 59s {"level":"info","ts":"2024-11-04T04:55:30.883304Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 2"} 59s {"level":"info","ts":"2024-11-04T04:55:30.883332Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 2"} 59s {"level":"info","ts":"2024-11-04T04:55:30.883342Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 2"} 59s {"level":"info","ts":"2024-11-04T04:55:30.883348Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 2"} 59s {"level":"info","ts":"2024-11-04T04:55:30.884191Z","caller":"etcdserver/server.go:2651","msg":"setting up initial cluster version using v2 API","cluster-version":"3.5"} 59s {"level":"info","ts":"2024-11-04T04:55:30.884790Z","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"} 59s {"level":"info","ts":"2024-11-04T04:55:30.885051Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 59s {"level":"info","ts":"2024-11-04T04:55:30.885277Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 59s {"level":"info","ts":"2024-11-04T04:55:30.885320Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 59s {"level":"info","ts":"2024-11-04T04:55:30.885332Z","caller":"etcdserver/server.go:2675","msg":"cluster version is updated","cluster-version":"3.5"} 59s {"level":"info","ts":"2024-11-04T04:55:30.885712Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 59s {"level":"info","ts":"2024-11-04T04:55:30.885967Z","caller":"embed/serve.go:188","msg":"serving client traffic insecurely; this is strongly discouraged!","traffic":"grpc+http","address":"127.0.0.1:2379"} 59s {"level":"info","ts":"2024-11-04T04:55:30.886175Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 59s {"level":"info","ts":"2024-11-04T04:55:30.886205Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 61s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 61s Ncat: Listening on 0.0.0.0:12345 61s 0 61s dcs-endpoints : [http://127.0.0.1:2379] 61s dcs-type : etcd 61s hostingtype : basic 61s interface : ens3 61s interval : 3000 61s ip : 10.0.2.123 61s manager-type : basic 61s netmask : 32 61s retry-after : 250 61s retry-num : 3 61s trigger-key : service/pgcluster/leader 61s trigger-value : autopkgtest 61s verbose : false 61s version : false 61s 2024-11-04 04:55:32.779188 I | No dcs-endpoints specified, trying to use localhost with standard ports! 61s 2024-11-04 04:55:32.779413 I | This is the config that will be used: 61s 2024-11-04 04:55:32.781247 I | IP address 10.0.2.123/32 state is false, desired false 61s 2024-11-04 04:55:32.782185 I | set WATCH on service/pgcluster/leader 63s 2024-11-04 04:55:34.800236 I | Current Leader from DCS: autopkgtest 63s OK 63s 2024-11-04 04:55:34.800412 I | IP address 10.0.2.123/32 state is false, desired true 63s 2024-11-04 04:55:34.800488 I | Configuring address 10.0.2.123/32 on ens3 63s 2024-11-04 04:55:34.803458 I | Sent gratuitous ARP reply 63s 2024-11-04 04:55:34.803482 I | Sent gratuitous ARP request 63s 2024-11-04 04:55:34.803648 I | IP address 10.0.2.123/32 state is true, desired true 65s inet 10.0.2.123/32 scope global ens3 65s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 65s Ncat: Connected to 10.0.2.123:12345. 65s Ncat: 0 bytes sent, 0 bytes received in 0.02 seconds. 65s Ncat: Connection from 10.0.2.123:41016. 65s 2024-11-04 04:55:36.851513 I | Current Leader from DCS: 0xGARBAGE 65s 2024-11-04 04:55:36.851738 I | IP address 10.0.2.123/32 state is true, desired false 65s 2024-11-04 04:55:36.851754 I | Removing address 10.0.2.123/32 on ens3 65s OK 65s 2024-11-04 04:55:36.856273 I | IP address 10.0.2.123/32 state is false, desired false 67s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 68s Ncat: TIMEOUT. 68s ### You've reached the end of the script, all "tests" have successfully been passed! ### 68s {"level":"info","ts":"2024-11-04T04:55:39.897079Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 68s {"level":"info","ts":"2024-11-04T04:55:39.897123Z","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"]} 68s {"level":"warn","ts":"2024-11-04T04:55:39.897162Z","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"} 68s {"level":"warn","ts":"2024-11-04T04:55:39.897269Z","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"} 68s {"level":"info","ts":"2024-11-04T04:55:39.897283Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 68s {"level":"info","ts":"2024-11-04T04:55:39.901839Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 68s {"level":"info","ts":"2024-11-04T04:55:39.901937Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 68s {"level":"info","ts":"2024-11-04T04:55:39.901947Z","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"]} 69s autopkgtest [04:55:40]: test test: -----------------------] 69s test PASS 69s autopkgtest [04:55:40]: test test: - - - - - - - - - - results - - - - - - - - - - 69s autopkgtest [04:55:40]: test cacert-test: preparing testbed 70s Reading package lists... 70s Building dependency tree... 70s Reading state information... 70s Starting pkgProblemResolver with broken count: 0 70s Starting 2 pkgProblemResolver with broken count: 0 70s Done 71s The following NEW packages will be installed: 71s autopkgtest-satdep 71s 0 upgraded, 1 newly installed, 0 to remove and 0 not upgraded. 71s Need to get 0 B/736 B of archives. 71s After this operation, 0 B of additional disk space will be used. 71s Get:1 /tmp/autopkgtest.9kUWL4/2-autopkgtest-satdep.deb autopkgtest-satdep amd64 0 [736 B] 71s Selecting previously unselected package autopkgtest-satdep. 71s (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 ... 75368 files and directories currently installed.) 71s Preparing to unpack .../2-autopkgtest-satdep.deb ... 71s Unpacking autopkgtest-satdep (0) ... 71s Setting up autopkgtest-satdep (0) ... 73s (Reading database ... 75368 files and directories currently installed.) 73s Removing autopkgtest-satdep (0) ... 73s autopkgtest [04:55:44]: test cacert-test: [----------------------- 74s ○ etcd.service - etcd - highly-available key value store 74s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 74s Active: inactive (dead) since Mon 2024-11-04 04:55:30 UTC; 14s ago 74s Duration: 3.567s 74s Invocation: a6d8150a3637403a8cb81e1668ecfa31 74s Docs: https://etcd.io/docs 74s man:etcd 74s Process: 2214 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 74s Main PID: 2214 (code=killed, signal=TERM) 74s Mem peak: 7M 74s CPU: 52ms 74s 74s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"info","ts":"2024-11-04T04:55:30.673025Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 74s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"info","ts":"2024-11-04T04:55:30.673074Z","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"]} 74s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"warn","ts":"2024-11-04T04:55:30.673148Z","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"} 74s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"warn","ts":"2024-11-04T04:55:30.673276Z","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"} 74s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"info","ts":"2024-11-04T04:55:30.673291Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 74s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"info","ts":"2024-11-04T04:55:30.675690Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 74s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"info","ts":"2024-11-04T04:55:30.675787Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 74s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"info","ts":"2024-11-04T04:55:30.675804Z","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"]} 74s Nov 04 04:55:30 autopkgtest systemd[1]: etcd.service: Deactivated successfully. 74s Nov 04 04:55:30 autopkgtest systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 74s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 74s {"level":"warn","ts":"2024-11-04T04:55:45.275264Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_UNSUPPORTED_ARCH="} 74s {"level":"warn","ts":"2024-11-04T04:55:45.275475Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 74s {"level":"info","ts":"2024-11-04T04:55:45.275497Z","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"]} 74s {"level":"warn","ts":"2024-11-04T04:55:45.275518Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 74s {"level":"info","ts":"2024-11-04T04:55:45.275580Z","caller":"etcdmain/etcd.go:116","msg":"server has been already initialized","data-dir":"default.etcd","dir-type":"member"} 74s {"level":"warn","ts":"2024-11-04T04:55:45.275599Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 74s {"level":"info","ts":"2024-11-04T04:55:45.275607Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 74s {"level":"info","ts":"2024-11-04T04:55:45.276114Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["https://127.0.0.1:2379"]} 74s {"level":"info","ts":"2024-11-04T04:55:45.276234Z","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":"amd64","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"} 74s {"level":"info","ts":"2024-11-04T04:55:45.285550Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"9.092156ms"} 74s {"level":"info","ts":"2024-11-04T04:55:45.285939Z","caller":"etcdserver/server.go:532","msg":"No snapshot found. Recovering WAL from scratch!"} 74s {"level":"info","ts":"2024-11-04T04:55:45.286506Z","caller":"etcdserver/raft.go:540","msg":"restarting local member","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","commit-index":7} 74s {"level":"info","ts":"2024-11-04T04:55:45.287470Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 74s {"level":"info","ts":"2024-11-04T04:55:45.287512Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 2"} 74s {"level":"info","ts":"2024-11-04T04:55:45.287543Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 2, commit: 7, applied: 0, lastindex: 7, lastterm: 2]"} 74s {"level":"warn","ts":"2024-11-04T04:55:45.293897Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 74s {"level":"info","ts":"2024-11-04T04:55:45.295002Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":3} 74s {"level":"info","ts":"2024-11-04T04:55:45.296242Z","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"} 74s {"level":"info","ts":"2024-11-04T04:55:45.297501Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 74s {"level":"info","ts":"2024-11-04T04:55:45.297665Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 74s {"level":"info","ts":"2024-11-04T04:55:45.297770Z","caller":"etcdserver/server.go:773","msg":"starting initial election tick advance","election-ticks":10} 74s {"level":"info","ts":"2024-11-04T04:55:45.297959Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 74s {"level":"info","ts":"2024-11-04T04:55:45.298032Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 74s {"level":"info","ts":"2024-11-04T04:55:45.298042Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 74s {"level":"info","ts":"2024-11-04T04:55:45.298266Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 74s {"level":"info","ts":"2024-11-04T04:55:45.298343Z","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"]} 74s {"level":"info","ts":"2024-11-04T04:55:45.298882Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 74s {"level":"info","ts":"2024-11-04T04:55:45.299003Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 74s {"level":"info","ts":"2024-11-04T04:55:45.300756Z","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":[]} 74s {"level":"warn","ts":"2024-11-04T04:55:45.301006Z","caller":"embed/etcd.go:742","msg":"Flag `enable-v2` is deprecated and will get removed in etcd 3.6."} 74s {"level":"info","ts":"2024-11-04T04:55:45.300958Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 74s {"level":"info","ts":"2024-11-04T04:55:45.301152Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 74s {"level":"info","ts":"2024-11-04T04:55:45.301240Z","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":[]} 75s {"level":"info","ts":"2024-11-04T04:55:46.288050Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 2"} 75s {"level":"info","ts":"2024-11-04T04:55:46.288099Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 2"} 75s {"level":"info","ts":"2024-11-04T04:55:46.288134Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 2"} 75s {"level":"info","ts":"2024-11-04T04:55:46.288144Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 3"} 75s {"level":"info","ts":"2024-11-04T04:55:46.288170Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 3"} 75s {"level":"info","ts":"2024-11-04T04:55:46.288187Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 3"} 75s {"level":"info","ts":"2024-11-04T04:55:46.288194Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 3"} 75s {"level":"info","ts":"2024-11-04T04:55:46.292705Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 75s {"level":"info","ts":"2024-11-04T04:55:46.292709Z","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"} 75s {"level":"info","ts":"2024-11-04T04:55:46.292969Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 75s {"level":"info","ts":"2024-11-04T04:55:46.292982Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 75s {"level":"info","ts":"2024-11-04T04:55:46.293604Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 75s {"level":"info","ts":"2024-11-04T04:55:46.294243Z","caller":"embed/serve.go:251","msg":"serving client traffic securely","traffic":"grpc+http","address":"127.0.0.1:2379"} 76s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 76s Ncat: Listening on 0.0.0.0:12345 76s 1 78s OK 80s inet 10.0.2.123/32 scope global ens3 80s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 80s Ncat: Connected to 10.0.2.123:12345. 80s Ncat: 0 bytes sent, 0 bytes received in 0.02 seconds. 80s Ncat: Connection from 10.0.2.123:53352. 80s ### You've reached the end of the script, all "tests" have successfully been passed! ### 80s {"level":"info","ts":"2024-11-04T04:55:51.379406Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 80s {"level":"info","ts":"2024-11-04T04:55:51.379523Z","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"]} 80s {"level":"warn","ts":"2024-11-04T04:55:51.379629Z","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"} 80s {"level":"warn","ts":"2024-11-04T04:55:51.379914Z","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"} 80s {"level":"info","ts":"2024-11-04T04:55:51.381940Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 80s {"level":"info","ts":"2024-11-04T04:55:51.386519Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 80s {"level":"info","ts":"2024-11-04T04:55:51.388616Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 80s {"level":"info","ts":"2024-11-04T04:55:51.388674Z","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"]} 80s autopkgtest [04:55:51]: test cacert-test: -----------------------] 80s cacert-test PASS 80s autopkgtest [04:55:51]: test cacert-test: - - - - - - - - - - results - - - - - - - - - - 81s autopkgtest [04:55:52]: test clientcert-test: preparing testbed 81s Reading package lists... 81s Building dependency tree... 81s Reading state information... 82s Starting pkgProblemResolver with broken count: 0 82s Starting 2 pkgProblemResolver with broken count: 0 82s Done 82s The following NEW packages will be installed: 82s autopkgtest-satdep 82s 0 upgraded, 1 newly installed, 0 to remove and 0 not upgraded. 82s Need to get 0 B/736 B of archives. 82s After this operation, 0 B of additional disk space will be used. 82s Get:1 /tmp/autopkgtest.9kUWL4/3-autopkgtest-satdep.deb autopkgtest-satdep amd64 0 [736 B] 83s Selecting previously unselected package autopkgtest-satdep. 83s (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 ... 75368 files and directories currently installed.) 83s Preparing to unpack .../3-autopkgtest-satdep.deb ... 83s Unpacking autopkgtest-satdep (0) ... 83s Setting up autopkgtest-satdep (0) ... 84s (Reading database ... 75368 files and directories currently installed.) 84s Removing autopkgtest-satdep (0) ... 84s autopkgtest [04:55:55]: test clientcert-test: [----------------------- 85s ○ etcd.service - etcd - highly-available key value store 85s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 85s Active: inactive (dead) since Mon 2024-11-04 04:55:30 UTC; 25s ago 85s Duration: 3.567s 85s Invocation: a6d8150a3637403a8cb81e1668ecfa31 85s Docs: https://etcd.io/docs 85s man:etcd 85s Process: 2214 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 85s Main PID: 2214 (code=killed, signal=TERM) 85s Mem peak: 7M 85s CPU: 52ms 85s 85s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"info","ts":"2024-11-04T04:55:30.673025Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 85s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"info","ts":"2024-11-04T04:55:30.673074Z","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"]} 85s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"warn","ts":"2024-11-04T04:55:30.673148Z","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"} 85s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"warn","ts":"2024-11-04T04:55:30.673276Z","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"} 85s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"info","ts":"2024-11-04T04:55:30.673291Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 85s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"info","ts":"2024-11-04T04:55:30.675690Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 85s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"info","ts":"2024-11-04T04:55:30.675787Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 85s Nov 04 04:55:30 autopkgtest etcd[2214]: {"level":"info","ts":"2024-11-04T04:55:30.675804Z","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"]} 85s Nov 04 04:55:30 autopkgtest systemd[1]: etcd.service: Deactivated successfully. 85s Nov 04 04:55:30 autopkgtest systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 85s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 85s inet 10.0.2.123/32 scope global ens3 85s {"level":"warn","ts":"2024-11-04T04:55:56.676038Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_UNSUPPORTED_ARCH="} 85s {"level":"warn","ts":"2024-11-04T04:55:56.676249Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 85s {"level":"info","ts":"2024-11-04T04:55:56.676268Z","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"]} 85s {"level":"warn","ts":"2024-11-04T04:55:56.676290Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 85s {"level":"info","ts":"2024-11-04T04:55:56.676338Z","caller":"etcdmain/etcd.go:116","msg":"server has been already initialized","data-dir":"default.etcd","dir-type":"member"} 85s {"level":"warn","ts":"2024-11-04T04:55:56.676352Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 85s {"level":"info","ts":"2024-11-04T04:55:56.676360Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 85s {"level":"info","ts":"2024-11-04T04:55:56.676842Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["https://127.0.0.1:2379"]} 85s {"level":"info","ts":"2024-11-04T04:55:56.676916Z","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":"amd64","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"} 85s {"level":"info","ts":"2024-11-04T04:55:56.679474Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"2.347137ms"} 85s {"level":"info","ts":"2024-11-04T04:55:56.679855Z","caller":"etcdserver/server.go:532","msg":"No snapshot found. Recovering WAL from scratch!"} 85s {"level":"info","ts":"2024-11-04T04:55:56.680399Z","caller":"etcdserver/raft.go:540","msg":"restarting local member","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","commit-index":11} 85s {"level":"info","ts":"2024-11-04T04:55:56.681288Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 85s {"level":"info","ts":"2024-11-04T04:55:56.681333Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 3"} 85s {"level":"info","ts":"2024-11-04T04:55:56.681347Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 3, commit: 11, applied: 0, lastindex: 11, lastterm: 3]"} 85s {"level":"warn","ts":"2024-11-04T04:55:56.683900Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 85s {"level":"info","ts":"2024-11-04T04:55:56.685022Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":5} 85s {"level":"info","ts":"2024-11-04T04:55:56.686275Z","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"} 85s {"level":"info","ts":"2024-11-04T04:55:56.687516Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 85s {"level":"info","ts":"2024-11-04T04:55:56.687766Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 85s {"level":"info","ts":"2024-11-04T04:55:56.687898Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 85s {"level":"info","ts":"2024-11-04T04:55:56.687936Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 85s {"level":"info","ts":"2024-11-04T04:55:56.687944Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 85s {"level":"info","ts":"2024-11-04T04:55:56.688133Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 85s {"level":"info","ts":"2024-11-04T04:55:56.688194Z","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"]} 85s {"level":"info","ts":"2024-11-04T04:55:56.688280Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 85s {"level":"info","ts":"2024-11-04T04:55:56.688321Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 85s {"level":"info","ts":"2024-11-04T04:55:56.687766Z","caller":"etcdserver/server.go:773","msg":"starting initial election tick advance","election-ticks":10} 85s {"level":"info","ts":"2024-11-04T04:55:56.690849Z","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":[]} 85s {"level":"warn","ts":"2024-11-04T04:55:56.690884Z","caller":"embed/etcd.go:742","msg":"Flag `enable-v2` is deprecated and will get removed in etcd 3.6."} 85s {"level":"info","ts":"2024-11-04T04:55:56.690955Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 85s {"level":"info","ts":"2024-11-04T04:55:56.690981Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 85s {"level":"info","ts":"2024-11-04T04:55:56.691003Z","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":[]} 86s {"level":"info","ts":"2024-11-04T04:55:57.981769Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 3"} 86s {"level":"info","ts":"2024-11-04T04:55:57.981849Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 3"} 86s {"level":"info","ts":"2024-11-04T04:55:57.981867Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 3"} 86s {"level":"info","ts":"2024-11-04T04:55:57.981880Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 4"} 86s {"level":"info","ts":"2024-11-04T04:55:57.981912Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 4"} 86s {"level":"info","ts":"2024-11-04T04:55:57.981924Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 4"} 86s {"level":"info","ts":"2024-11-04T04:55:57.981933Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 4"} 86s {"level":"info","ts":"2024-11-04T04:55:57.987796Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 86s {"level":"info","ts":"2024-11-04T04:55:57.987808Z","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"} 86s {"level":"info","ts":"2024-11-04T04:55:57.988142Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 86s {"level":"info","ts":"2024-11-04T04:55:57.988159Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 86s {"level":"info","ts":"2024-11-04T04:55:57.988755Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 86s {"level":"info","ts":"2024-11-04T04:55:57.989385Z","caller":"embed/serve.go:251","msg":"serving client traffic securely","traffic":"grpc+http","address":"127.0.0.1:2379"} 87s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 87s Ncat: Listening on 0.0.0.0:12345 87s 1 89s OK 91s inet 10.0.2.123/32 scope global ens3 91s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 91s Ncat: Connected to 10.0.2.123:12345. 91s Ncat: 0 bytes sent, 0 bytes received in 0.02 seconds. 91s Ncat: Connection from 10.0.2.123:36672. 91s ### You've reached the end of the script, all "tests" have successfully been passed! ### 91s {"level":"info","ts":"2024-11-04T04:56:02.769864Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 91s {"level":"info","ts":"2024-11-04T04:56:02.769999Z","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"]} 91s {"level":"warn","ts":"2024-11-04T04:56:02.770119Z","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"} 91s {"level":"warn","ts":"2024-11-04T04:56:02.770323Z","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"} 91s {"level":"info","ts":"2024-11-04T04:56:02.773856Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 91s {"level":"info","ts":"2024-11-04T04:56:02.779188Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 91s {"level":"info","ts":"2024-11-04T04:56:02.779274Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 91s {"level":"info","ts":"2024-11-04T04:56:02.779282Z","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"]} 92s autopkgtest [04:56:03]: test clientcert-test: -----------------------] 92s clientcert-test PASS 92s autopkgtest [04:56:03]: test clientcert-test: - - - - - - - - - - results - - - - - - - - - - 92s autopkgtest [04:56:03]: @@@@@@@@@@@@@@@@@@@@ summary 92s test PASS 92s cacert-test PASS 92s clientcert-test PASS 111s nova [W] Skipping flock for amd64 111s Creating nova instance adt-plucky-amd64-vip-manager2-20241104-045430-juju-7f2275-prod-proposed-migration-environment-14-9aa9ffb5-a0d1-4b05-90d9-7aceb038a858 from image adt/ubuntu-plucky-amd64-server-20241103.img (UUID 35ab818c-a1b8-49b0-b1ec-61e6c5b42b5f)...