0s autopkgtest [15:51:55]: starting date and time: 2024-11-02 15:51:55+0000 0s autopkgtest [15:51:55]: git checkout: 6f3be7a8 Fix armhf LXD image generation for plucky 0s autopkgtest [15:51:55]: host juju-7f2275-prod-proposed-migration-environment-15; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.hfd65lk1/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-ppc64el --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-15@bos03-ppc64el-26.secgroup --name adt-plucky-ppc64el-vip-manager2-20241102-155155-juju-7f2275-prod-proposed-migration-environment-15-4da47be5-dbf1-4dac-bf0c-6855fc37b16c --image adt/ubuntu-plucky-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-15 --net-id=net_prod-proposed-migration-ppc64el -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/ 73s autopkgtest [15:53:08]: testbed dpkg architecture: ppc64el 73s autopkgtest [15:53:08]: testbed apt version: 2.9.8 73s autopkgtest [15:53:08]: @@@@@@@@@@@@@@@@@@@@ test bed setup 74s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [73.9 kB] 74s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [2555 kB] 75s Get:3 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [40.4 kB] 75s Get:4 http://ftpmaster.internal/ubuntu plucky-proposed/restricted Sources [7016 B] 75s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [172 kB] 75s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/main ppc64el Packages [211 kB] 75s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/universe ppc64el Packages [1773 kB] 75s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse ppc64el Packages [47.0 kB] 75s Fetched 4878 kB in 1s (3540 kB/s) 75s Reading package lists... 78s Reading package lists... 78s Building dependency tree... 78s Reading state information... 78s Calculating upgrade... 78s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 78s Reading package lists... 78s Building dependency tree... 78s Reading state information... 78s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 79s Hit:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease 79s Hit:2 http://ftpmaster.internal/ubuntu plucky InRelease 79s Hit:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease 79s Hit:4 http://ftpmaster.internal/ubuntu plucky-security InRelease 80s Reading package lists... 80s Reading package lists... 80s Building dependency tree... 80s Reading state information... 80s Calculating upgrade... 80s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 80s Reading package lists... 81s Building dependency tree... 81s Reading state information... 81s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 83s autopkgtest [15:53:18]: testbed running kernel: Linux 6.11.0-8-generic #8-Ubuntu SMP Mon Sep 16 13:49:23 UTC 2024 83s autopkgtest [15:53:18]: @@@@@@@@@@@@@@@@@@@@ apt-source vip-manager2 85s Get:1 http://ftpmaster.internal/ubuntu plucky/universe vip-manager2 2.5.0-1 (dsc) [2487 B] 85s Get:2 http://ftpmaster.internal/ubuntu plucky/universe vip-manager2 2.5.0-1 (tar) [45.4 kB] 85s Get:3 http://ftpmaster.internal/ubuntu plucky/universe vip-manager2 2.5.0-1 (diff) [8284 B] 85s gpgv: Signature made Fri May 17 08:39:51 2024 UTC 85s gpgv: using RSA key 5C48FE6157F49179597087C64C5A6BAB12D2A7AE 85s gpgv: Can't check signature: No public key 85s dpkg-source: warning: cannot verify inline signature for ./vip-manager2_2.5.0-1.dsc: no acceptable signature found 85s autopkgtest [15:53:20]: testing package vip-manager2 version 2.5.0-1 85s autopkgtest [15:53:20]: build not needed 86s autopkgtest [15:53:21]: test test: preparing testbed 87s Reading package lists... 87s Building dependency tree... 87s Reading state information... 87s Starting pkgProblemResolver with broken count: 0 87s Starting 2 pkgProblemResolver with broken count: 0 87s Done 87s The following additional packages will be installed: 87s etcd-client etcd-server liblua5.4-0 ncat vip-manager2 87s The following NEW packages will be installed: 87s autopkgtest-satdep etcd-client etcd-server liblua5.4-0 ncat vip-manager2 87s 0 upgraded, 6 newly installed, 0 to remove and 0 not upgraded. 87s Need to get 19.4 MB/19.4 MB of archives. 87s After this operation, 73.8 MB of additional disk space will be used. 87s Get:1 /tmp/autopkgtest.q4tkjh/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [744 B] 87s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/universe ppc64el etcd-server ppc64el 3.5.16-3 [10.5 MB] 88s Get:3 http://ftpmaster.internal/ubuntu plucky/main ppc64el liblua5.4-0 ppc64el 5.4.6-3build2 [216 kB] 88s Get:4 http://ftpmaster.internal/ubuntu plucky/universe ppc64el ncat ppc64el 7.94+git20230807.3be01efb1+dfsg-4 [230 kB] 88s Get:5 http://ftpmaster.internal/ubuntu plucky/universe ppc64el vip-manager2 ppc64el 2.5.0-1 [3516 kB] 88s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/universe ppc64el etcd-client ppc64el 3.5.16-3 [4981 kB] 89s Fetched 19.4 MB in 1s (15.6 MB/s) 89s Selecting previously unselected package etcd-server. 89s (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 ... 73549 files and directories currently installed.) 89s Preparing to unpack .../0-etcd-server_3.5.16-3_ppc64el.deb ... 89s Unpacking etcd-server (3.5.16-3) ... 89s Selecting previously unselected package liblua5.4-0:ppc64el. 89s Preparing to unpack .../1-liblua5.4-0_5.4.6-3build2_ppc64el.deb ... 89s Unpacking liblua5.4-0:ppc64el (5.4.6-3build2) ... 89s Selecting previously unselected package ncat. 89s Preparing to unpack .../2-ncat_7.94+git20230807.3be01efb1+dfsg-4_ppc64el.deb ... 89s Unpacking ncat (7.94+git20230807.3be01efb1+dfsg-4) ... 89s Selecting previously unselected package vip-manager2. 89s Preparing to unpack .../3-vip-manager2_2.5.0-1_ppc64el.deb ... 89s Unpacking vip-manager2 (2.5.0-1) ... 89s Selecting previously unselected package etcd-client. 89s Preparing to unpack .../4-etcd-client_3.5.16-3_ppc64el.deb ... 89s Unpacking etcd-client (3.5.16-3) ... 89s Selecting previously unselected package autopkgtest-satdep. 89s Preparing to unpack .../5-1-autopkgtest-satdep.deb ... 89s Unpacking autopkgtest-satdep (0) ... 89s Setting up vip-manager2 (2.5.0-1) ... 90s Created symlink '/etc/systemd/system/multi-user.target.wants/vip-manager.service' → '/usr/lib/systemd/system/vip-manager.service'. 90s Setting up etcd-client (3.5.16-3) ... 90s Setting up liblua5.4-0:ppc64el (5.4.6-3build2) ... 90s Setting up etcd-server (3.5.16-3) ... 90s info: Selecting UID from range 100 to 999 ... 90s 90s info: Selecting GID from range 100 to 999 ... 90s info: Adding system user `etcd' (UID 107) ... 90s info: Adding new group `etcd' (GID 108) ... 90s info: Adding new user `etcd' (UID 107) with group `etcd' ... 90s info: Creating home directory `/var/lib/etcd/' ... 90s Created symlink '/etc/systemd/system/etcd2.service' → '/usr/lib/systemd/system/etcd.service'. 90s Created symlink '/etc/systemd/system/multi-user.target.wants/etcd.service' → '/usr/lib/systemd/system/etcd.service'. 91s Setting up ncat (7.94+git20230807.3be01efb1+dfsg-4) ... 91s Setting up autopkgtest-satdep (0) ... 91s Processing triggers for man-db (2.12.1-3) ... 92s Processing triggers for libc-bin (2.40-1ubuntu3) ... 94s (Reading database ... 73594 files and directories currently installed.) 94s Removing autopkgtest-satdep (0) ... 94s autopkgtest [15:53:29]: test test: [----------------------- 95s ○ etcd.service - etcd - highly-available key value store 95s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 95s Active: inactive (dead) since Sat 2024-11-02 15:53:30 UTC; 10ms ago 95s Duration: 5.058s 95s Invocation: 9622c9b0c38a44a5ad131aae27f66025 95s Docs: https://etcd.io/docs 95s man:etcd 95s Process: 2276 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 95s Main PID: 2276 (code=killed, signal=TERM) 95s Mem peak: 21.6M 95s CPU: 46ms 95s 95s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"info","ts":"2024-11-02T15:53:30.707519Z","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"]} 95s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"warn","ts":"2024-11-02T15:53:30.707617Z","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"} 95s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"warn","ts":"2024-11-02T15:53:30.707730Z","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"} 95s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"info","ts":"2024-11-02T15:53:30.707766Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 95s Nov 02 15:53:30 autopkgtest systemd[1]: Stopping etcd.service - etcd - highly-available key value store... 95s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"info","ts":"2024-11-02T15:53:30.710982Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 95s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"info","ts":"2024-11-02T15:53:30.711066Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 95s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"info","ts":"2024-11-02T15:53:30.711089Z","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"]} 95s Nov 02 15:53:30 autopkgtest systemd[1]: etcd.service: Deactivated successfully. 95s Nov 02 15:53:30 autopkgtest systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 95s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 95s {"level":"warn","ts":"2024-11-02T15:53:30.782092Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_UNSUPPORTED_ARCH="} 95s {"level":"warn","ts":"2024-11-02T15:53:30.782211Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 95s {"level":"info","ts":"2024-11-02T15:53:30.782242Z","caller":"etcdmain/etcd.go:73","msg":"Running: ","args":["etcd"]} 95s {"level":"warn","ts":"2024-11-02T15:53:30.782262Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 95s {"level":"warn","ts":"2024-11-02T15:53:30.782285Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 95s {"level":"info","ts":"2024-11-02T15:53:30.782295Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 95s {"level":"info","ts":"2024-11-02T15:53:30.782649Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["http://localhost:2379"]} 95s {"level":"info","ts":"2024-11-02T15:53:30.782795Z","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":"ppc64le","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"} 95s {"level":"info","ts":"2024-11-02T15:53:30.788684Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"5.595812ms"} 95s {"level":"info","ts":"2024-11-02T15:53:30.795127Z","caller":"etcdserver/raft.go:505","msg":"starting local member","local-member-id":"8e9e05c52164694d","cluster-id":"cdf818194e3a8c32"} 95s {"level":"info","ts":"2024-11-02T15:53:30.795197Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 95s {"level":"info","ts":"2024-11-02T15:53:30.795225Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 0"} 95s {"level":"info","ts":"2024-11-02T15:53:30.795238Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]"} 95s {"level":"info","ts":"2024-11-02T15:53:30.795247Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 1"} 95s {"level":"info","ts":"2024-11-02T15:53:30.795286Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 95s {"level":"warn","ts":"2024-11-02T15:53:30.800695Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 95s {"level":"info","ts":"2024-11-02T15:53:30.804601Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":1} 95s {"level":"info","ts":"2024-11-02T15:53:30.805591Z","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"} 95s {"level":"info","ts":"2024-11-02T15:53:30.807120Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 95s {"level":"info","ts":"2024-11-02T15:53:30.807254Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 95s {"level":"info","ts":"2024-11-02T15:53:30.807527Z","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"} 95s {"level":"info","ts":"2024-11-02T15:53:30.808058Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 95s {"level":"info","ts":"2024-11-02T15:53:30.808135Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 95s {"level":"info","ts":"2024-11-02T15:53:30.808198Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 95s {"level":"info","ts":"2024-11-02T15:53:30.809153Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 95s {"level":"info","ts":"2024-11-02T15:53:30.809439Z","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"]} 95s {"level":"info","ts":"2024-11-02T15:53:30.810910Z","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":[]} 95s {"level":"info","ts":"2024-11-02T15:53:30.810915Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 95s {"level":"info","ts":"2024-11-02T15:53:30.811005Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 96s {"level":"info","ts":"2024-11-02T15:53:31.696310Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 1"} 96s {"level":"info","ts":"2024-11-02T15:53:31.696390Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 1"} 96s {"level":"info","ts":"2024-11-02T15:53:31.696411Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 1"} 96s {"level":"info","ts":"2024-11-02T15:53:31.696424Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 2"} 96s {"level":"info","ts":"2024-11-02T15:53:31.696432Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 2"} 96s {"level":"info","ts":"2024-11-02T15:53:31.696443Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 2"} 96s {"level":"info","ts":"2024-11-02T15:53:31.696452Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 2"} 96s {"level":"info","ts":"2024-11-02T15:53:31.698631Z","caller":"etcdserver/server.go:2651","msg":"setting up initial cluster version using v2 API","cluster-version":"3.5"} 96s {"level":"info","ts":"2024-11-02T15:53:31.699273Z","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"} 96s {"level":"info","ts":"2024-11-02T15:53:31.699368Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 96s {"level":"info","ts":"2024-11-02T15:53:31.699511Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 96s {"level":"info","ts":"2024-11-02T15:53:31.699601Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 96s {"level":"info","ts":"2024-11-02T15:53:31.699623Z","caller":"etcdserver/server.go:2675","msg":"cluster version is updated","cluster-version":"3.5"} 96s {"level":"info","ts":"2024-11-02T15:53:31.699518Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 96s {"level":"info","ts":"2024-11-02T15:53:31.699635Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 96s {"level":"info","ts":"2024-11-02T15:53:31.699881Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 96s {"level":"info","ts":"2024-11-02T15:53:31.700296Z","caller":"embed/serve.go:188","msg":"serving client traffic insecurely; this is strongly discouraged!","traffic":"grpc+http","address":"127.0.0.1:2379"} 97s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 97s Ncat: Listening on 0.0.0.0:12345 97s 0 97s dcs-endpoints : [http://127.0.0.1:2379] 97s dcs-type : etcd 97s hostingtype : basic 97s interface : enp0s1 97s interval : 3000 97s ip : 10.0.2.123 97s manager-type : basic 97s netmask : 32 97s retry-after : 250 97s retry-num : 3 97s trigger-key : service/pgcluster/leader 97s trigger-value : autopkgtest 97s verbose : false 97s version : false 97s 2024-11-02 15:53:32.815011 I | No dcs-endpoints specified, trying to use localhost with standard ports! 97s 2024-11-02 15:53:32.815285 I | This is the config that will be used: 97s 2024-11-02 15:53:32.815857 I | IP address 10.0.2.123/32 state is false, desired false 97s 2024-11-02 15:53:32.817573 I | set WATCH on service/pgcluster/leader 99s 2024-11-02 15:53:34.832342 I | Current Leader from DCS: autopkgtest 99s 2024-11-02 15:53:34.832620 I | IP address 10.0.2.123/32 state is false, desired true 99s OK 99s 2024-11-02 15:53:34.832812 I | Configuring address 10.0.2.123/32 on enp0s1 99s 2024-11-02 15:53:34.835114 I | Sent gratuitous ARP reply 99s 2024-11-02 15:53:34.835142 I | Sent gratuitous ARP request 99s 2024-11-02 15:53:34.835271 I | IP address 10.0.2.123/32 state is true, desired true 101s inet 10.0.2.123/32 scope global enp0s1 101s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 101s Ncat: Ncat: Connection from 10.0.2.123:45482. 101s Connected to 10.0.2.123:12345. 101s Ncat: 0 bytes sent, 0 bytes received in 0.03 seconds. 101s OK 101s 2024-11-02 15:53:36.890605 I | Current Leader from DCS: 0xGARBAGE 101s 2024-11-02 15:53:36.890866 I | IP address 10.0.2.123/32 state is true, desired false 101s 2024-11-02 15:53:36.890927 I | Removing address 10.0.2.123/32 on enp0s1 101s 2024-11-02 15:53:36.893100 I | IP address 10.0.2.123/32 state is false, desired false 103s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 103s Ncat: Connection refused. 103s ### You've reached the end of the script, all "tests" have successfully been passed! ### 103s {"level":"info","ts":"2024-11-02T15:53:38.934728Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 103s {"level":"info","ts":"2024-11-02T15:53:38.934772Z","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"]} 103s {"level":"warn","ts":"2024-11-02T15:53:38.934834Z","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"} 103s {"level":"warn","ts":"2024-11-02T15:53:38.935028Z","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"} 103s {"level":"info","ts":"2024-11-02T15:53:38.935046Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 103s {"level":"info","ts":"2024-11-02T15:53:38.939785Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 103s {"level":"info","ts":"2024-11-02T15:53:38.939914Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 103s {"level":"info","ts":"2024-11-02T15:53:38.939926Z","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"]} 104s autopkgtest [15:53:39]: test test: -----------------------] 104s test PASS 104s autopkgtest [15:53:39]: test test: - - - - - - - - - - results - - - - - - - - - - 105s autopkgtest [15:53:40]: test cacert-test: preparing testbed 106s Reading package lists... 107s Building dependency tree... 107s Reading state information... 107s Starting pkgProblemResolver with broken count: 0 107s Starting 2 pkgProblemResolver with broken count: 0 107s Done 107s The following NEW packages will be installed: 107s autopkgtest-satdep 107s 0 upgraded, 1 newly installed, 0 to remove and 0 not upgraded. 107s Need to get 0 B/736 B of archives. 107s After this operation, 0 B of additional disk space will be used. 107s Get:1 /tmp/autopkgtest.q4tkjh/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [736 B] 107s Selecting previously unselected package autopkgtest-satdep. 108s (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 ... 73594 files and directories currently installed.) 108s Preparing to unpack .../2-autopkgtest-satdep.deb ... 108s Unpacking autopkgtest-satdep (0) ... 108s Setting up autopkgtest-satdep (0) ... 109s (Reading database ... 73594 files and directories currently installed.) 109s Removing autopkgtest-satdep (0) ... 110s autopkgtest [15:53:45]: test cacert-test: [----------------------- 110s ○ etcd.service - etcd - highly-available key value store 110s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 110s Active: inactive (dead) since Sat 2024-11-02 15:53:30 UTC; 15s ago 110s Duration: 5.058s 110s Invocation: 9622c9b0c38a44a5ad131aae27f66025 110s Docs: https://etcd.io/docs 110s man:etcd 110s Process: 2276 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 110s Main PID: 2276 (code=killed, signal=TERM) 110s Mem peak: 21.6M 110s CPU: 46ms 110s 110s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"info","ts":"2024-11-02T15:53:30.707519Z","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"]} 110s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"warn","ts":"2024-11-02T15:53:30.707617Z","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"} 110s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"warn","ts":"2024-11-02T15:53:30.707730Z","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"} 110s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"info","ts":"2024-11-02T15:53:30.707766Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 110s Nov 02 15:53:30 autopkgtest systemd[1]: Stopping etcd.service - etcd - highly-available key value store... 110s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"info","ts":"2024-11-02T15:53:30.710982Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 110s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"info","ts":"2024-11-02T15:53:30.711066Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 110s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"info","ts":"2024-11-02T15:53:30.711089Z","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"]} 110s Nov 02 15:53:30 autopkgtest systemd[1]: etcd.service: Deactivated successfully. 110s Nov 02 15:53:30 autopkgtest systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 110s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 110s {"level":"warn","ts":"2024-11-02T15:53:45.869330Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_UNSUPPORTED_ARCH="} 110s {"level":"warn","ts":"2024-11-02T15:53:45.869442Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 110s {"level":"info","ts":"2024-11-02T15:53:45.869454Z","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"]} 110s {"level":"warn","ts":"2024-11-02T15:53:45.869471Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 110s {"level":"info","ts":"2024-11-02T15:53:45.869512Z","caller":"etcdmain/etcd.go:116","msg":"server has been already initialized","data-dir":"default.etcd","dir-type":"member"} 110s {"level":"warn","ts":"2024-11-02T15:53:45.869524Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 110s {"level":"info","ts":"2024-11-02T15:53:45.869533Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 110s {"level":"info","ts":"2024-11-02T15:53:45.869835Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["https://127.0.0.1:2379"]} 110s {"level":"info","ts":"2024-11-02T15:53:45.869905Z","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":"ppc64le","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"} 110s {"level":"info","ts":"2024-11-02T15:53:45.872667Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"2.549287ms"} 110s {"level":"info","ts":"2024-11-02T15:53:45.872863Z","caller":"etcdserver/server.go:532","msg":"No snapshot found. Recovering WAL from scratch!"} 110s {"level":"info","ts":"2024-11-02T15:53:45.873350Z","caller":"etcdserver/raft.go:540","msg":"restarting local member","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","commit-index":7} 110s {"level":"info","ts":"2024-11-02T15:53:45.873423Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 110s {"level":"info","ts":"2024-11-02T15:53:45.873525Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 2"} 110s {"level":"info","ts":"2024-11-02T15:53:45.873579Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 2, commit: 7, applied: 0, lastindex: 7, lastterm: 2]"} 110s {"level":"warn","ts":"2024-11-02T15:53:45.874891Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 110s {"level":"info","ts":"2024-11-02T15:53:45.875688Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":3} 110s {"level":"info","ts":"2024-11-02T15:53:45.876675Z","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"} 110s {"level":"info","ts":"2024-11-02T15:53:45.877527Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 110s {"level":"info","ts":"2024-11-02T15:53:45.877627Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 110s {"level":"info","ts":"2024-11-02T15:53:45.877716Z","caller":"etcdserver/server.go:773","msg":"starting initial election tick advance","election-ticks":10} 110s {"level":"info","ts":"2024-11-02T15:53:45.877797Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 110s {"level":"info","ts":"2024-11-02T15:53:45.877816Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 110s {"level":"info","ts":"2024-11-02T15:53:45.877825Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 110s {"level":"info","ts":"2024-11-02T15:53:45.877965Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 110s {"level":"info","ts":"2024-11-02T15:53:45.878009Z","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"]} 110s {"level":"info","ts":"2024-11-02T15:53:45.878236Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 110s {"level":"info","ts":"2024-11-02T15:53:45.878280Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 110s {"level":"info","ts":"2024-11-02T15:53:45.880601Z","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":[]} 110s {"level":"warn","ts":"2024-11-02T15:53:45.880618Z","caller":"embed/etcd.go:742","msg":"Flag `enable-v2` is deprecated and will get removed in etcd 3.6."} 110s {"level":"info","ts":"2024-11-02T15:53:45.880666Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 110s {"level":"info","ts":"2024-11-02T15:53:45.880678Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 110s {"level":"info","ts":"2024-11-02T15:53:45.880695Z","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":[]} 112s {"level":"info","ts":"2024-11-02T15:53:47.474024Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 2"} 112s {"level":"info","ts":"2024-11-02T15:53:47.474072Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 2"} 112s {"level":"info","ts":"2024-11-02T15:53:47.474111Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 2"} 112s {"level":"info","ts":"2024-11-02T15:53:47.474123Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 3"} 112s {"level":"info","ts":"2024-11-02T15:53:47.474132Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 3"} 112s {"level":"info","ts":"2024-11-02T15:53:47.474147Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 3"} 112s {"level":"info","ts":"2024-11-02T15:53:47.474156Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 3"} 112s {"level":"info","ts":"2024-11-02T15:53:47.479068Z","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"} 112s {"level":"info","ts":"2024-11-02T15:53:47.479083Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 112s {"level":"info","ts":"2024-11-02T15:53:47.479360Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 112s {"level":"info","ts":"2024-11-02T15:53:47.479375Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 112s {"level":"info","ts":"2024-11-02T15:53:47.479860Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 112s {"level":"info","ts":"2024-11-02T15:53:47.480526Z","caller":"embed/serve.go:251","msg":"serving client traffic securely","traffic":"grpc+http","address":"127.0.0.1:2379"} 112s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 112s Ncat: Listening on 0.0.0.0:12345 112s 1 114s OK 116s inet 10.0.2.123/32 scope global enp0s1 116s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 117s Ncat: Connected to 10.0.2.123:12345. 117s Ncat: 0 bytes sent, 0 bytes received in 0.03 seconds. 117s Ncat: Connection from 10.0.2.123:42562. 117s ### You've reached the end of the script, all "tests" have successfully been passed! ### 117s {"level":"info","ts":"2024-11-02T15:53:51.987553Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 117s {"level":"info","ts":"2024-11-02T15:53:51.987591Z","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"]} 117s {"level":"warn","ts":"2024-11-02T15:53:51.987642Z","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"} 117s {"level":"warn","ts":"2024-11-02T15:53:51.987659Z","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"} 117s {"level":"info","ts":"2024-11-02T15:53:51.989340Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 117s {"level":"info","ts":"2024-11-02T15:53:51.993942Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 117s {"level":"info","ts":"2024-11-02T15:53:51.994041Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 117s {"level":"info","ts":"2024-11-02T15:53:51.994075Z","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"]} 117s autopkgtest [15:53:52]: test cacert-test: -----------------------] 117s cacert-test PASS 117s autopkgtest [15:53:52]: test cacert-test: - - - - - - - - - - results - - - - - - - - - - 118s autopkgtest [15:53:53]: test clientcert-test: preparing testbed 119s Reading package lists... 119s Building dependency tree... 119s Reading state information... 119s Starting pkgProblemResolver with broken count: 0 119s Starting 2 pkgProblemResolver with broken count: 0 119s Done 119s The following NEW packages will be installed: 119s autopkgtest-satdep 119s 0 upgraded, 1 newly installed, 0 to remove and 0 not upgraded. 119s Need to get 0 B/744 B of archives. 119s After this operation, 0 B of additional disk space will be used. 119s Get:1 /tmp/autopkgtest.q4tkjh/3-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [744 B] 120s Selecting previously unselected package autopkgtest-satdep. 120s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 73594 files and directories currently installed.) 120s Preparing to unpack .../3-autopkgtest-satdep.deb ... 120s Unpacking autopkgtest-satdep (0) ... 120s Setting up autopkgtest-satdep (0) ... 122s (Reading database ... 73594 files and directories currently installed.) 122s Removing autopkgtest-satdep (0) ... 122s autopkgtest [15:53:57]: test clientcert-test: [----------------------- 123s ○ etcd.service - etcd - highly-available key value store 123s Loaded: loaded (/usr/lib/systemd/system/etcd.service; enabled; preset: enabled) 123s Active: inactive (dead) since Sat 2024-11-02 15:53:30 UTC; 28s ago 123s Duration: 5.058s 123s Invocation: 9622c9b0c38a44a5ad131aae27f66025 123s Docs: https://etcd.io/docs 123s man:etcd 123s Process: 2276 ExecStart=/usr/bin/etcd $DAEMON_ARGS (code=killed, signal=TERM) 123s Main PID: 2276 (code=killed, signal=TERM) 123s Mem peak: 21.6M 123s CPU: 46ms 123s 123s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"info","ts":"2024-11-02T15:53:30.707519Z","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"]} 123s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"warn","ts":"2024-11-02T15:53:30.707617Z","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"} 123s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"warn","ts":"2024-11-02T15:53:30.707730Z","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"} 123s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"info","ts":"2024-11-02T15:53:30.707766Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 123s Nov 02 15:53:30 autopkgtest systemd[1]: Stopping etcd.service - etcd - highly-available key value store... 123s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"info","ts":"2024-11-02T15:53:30.710982Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 123s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"info","ts":"2024-11-02T15:53:30.711066Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 123s Nov 02 15:53:30 autopkgtest etcd[2276]: {"level":"info","ts":"2024-11-02T15:53:30.711089Z","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"]} 123s Nov 02 15:53:30 autopkgtest systemd[1]: etcd.service: Deactivated successfully. 123s Nov 02 15:53:30 autopkgtest systemd[1]: Stopped etcd.service - etcd - highly-available key value store. 123s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 123s inet 10.0.2.123/32 scope global enp0s1 123s {"level":"warn","ts":"2024-11-02T15:53:58.767375Z","caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_UNSUPPORTED_ARCH="} 123s {"level":"warn","ts":"2024-11-02T15:53:58.767497Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 123s {"level":"info","ts":"2024-11-02T15:53:58.767509Z","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"]} 123s {"level":"warn","ts":"2024-11-02T15:53:58.767526Z","caller":"etcdmain/etcd.go:105","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"} 123s {"level":"info","ts":"2024-11-02T15:53:58.767570Z","caller":"etcdmain/etcd.go:116","msg":"server has been already initialized","data-dir":"default.etcd","dir-type":"member"} 123s {"level":"warn","ts":"2024-11-02T15:53:58.767583Z","caller":"embed/config.go:689","msg":"Running http and grpc server on single port. This is not recommended for production."} 123s {"level":"info","ts":"2024-11-02T15:53:58.767592Z","caller":"embed/etcd.go:128","msg":"configuring peer listeners","listen-peer-urls":["http://localhost:2380"]} 123s {"level":"info","ts":"2024-11-02T15:53:58.767916Z","caller":"embed/etcd.go:136","msg":"configuring client listeners","listen-client-urls":["https://127.0.0.1:2379"]} 123s {"level":"info","ts":"2024-11-02T15:53:58.767990Z","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":"ppc64le","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"} 123s {"level":"info","ts":"2024-11-02T15:53:58.768483Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"default.etcd/member/snap/db","took":"284.027µs"} 123s {"level":"info","ts":"2024-11-02T15:53:58.768701Z","caller":"etcdserver/server.go:532","msg":"No snapshot found. Recovering WAL from scratch!"} 123s {"level":"info","ts":"2024-11-02T15:53:58.769227Z","caller":"etcdserver/raft.go:540","msg":"restarting local member","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","commit-index":11} 123s {"level":"info","ts":"2024-11-02T15:53:58.769750Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=()"} 123s {"level":"info","ts":"2024-11-02T15:53:58.769771Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became follower at term 3"} 123s {"level":"info","ts":"2024-11-02T15:53:58.769791Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 8e9e05c52164694d [peers: [], term: 3, commit: 11, applied: 0, lastindex: 11, lastterm: 3]"} 123s {"level":"warn","ts":"2024-11-02T15:53:58.771261Z","caller":"auth/store.go:1241","msg":"simple token is not cryptographically signed"} 123s {"level":"info","ts":"2024-11-02T15:53:58.772207Z","caller":"mvcc/kvstore.go:423","msg":"kvstore restored","current-rev":5} 123s {"level":"info","ts":"2024-11-02T15:53:58.773308Z","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"} 123s {"level":"info","ts":"2024-11-02T15:53:58.774272Z","caller":"etcdserver/server.go:873","msg":"starting etcd server","local-member-id":"8e9e05c52164694d","local-server-version":"3.5.16","cluster-version":"to_be_decided"} 123s {"level":"info","ts":"2024-11-02T15:53:58.774375Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 123s {"level":"info","ts":"2024-11-02T15:53:58.774422Z","caller":"etcdserver/server.go:773","msg":"starting initial election tick advance","election-ticks":10} 123s {"level":"info","ts":"2024-11-02T15:53:58.774755Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap.db","max":5,"interval":"30s"} 123s {"level":"info","ts":"2024-11-02T15:53:58.774800Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/snap","suffix":"snap","max":5,"interval":"30s"} 123s {"level":"info","ts":"2024-11-02T15:53:58.774822Z","caller":"fileutil/purge.go:50","msg":"started to purge file","dir":"default.etcd/member/wal","suffix":"wal","max":5,"interval":"30s"} 123s {"level":"info","ts":"2024-11-02T15:53:58.775216Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d switched to configuration voters=(10276657743932975437)"} 123s {"level":"info","ts":"2024-11-02T15:53:58.775297Z","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"]} 123s {"level":"info","ts":"2024-11-02T15:53:58.775387Z","caller":"membership/cluster.go:584","msg":"set initial cluster version","cluster-id":"cdf818194e3a8c32","local-member-id":"8e9e05c52164694d","cluster-version":"3.5"} 123s {"level":"info","ts":"2024-11-02T15:53:58.775433Z","caller":"api/capability.go:75","msg":"enabled capabilities for version","cluster-version":"3.5"} 123s {"level":"info","ts":"2024-11-02T15:53:58.777631Z","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":[]} 123s {"level":"warn","ts":"2024-11-02T15:53:58.777664Z","caller":"embed/etcd.go:742","msg":"Flag `enable-v2` is deprecated and will get removed in etcd 3.6."} 123s {"level":"info","ts":"2024-11-02T15:53:58.777833Z","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":[]} 123s {"level":"info","ts":"2024-11-02T15:53:58.777865Z","caller":"embed/etcd.go:600","msg":"serving peer traffic","address":"127.0.0.1:2380"} 123s {"level":"info","ts":"2024-11-02T15:53:58.778267Z","caller":"embed/etcd.go:572","msg":"cmux::serve","address":"127.0.0.1:2380"} 125s {"level":"info","ts":"2024-11-02T15:54:00.271101Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d is starting a new election at term 3"} 125s {"level":"info","ts":"2024-11-02T15:54:00.271149Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became pre-candidate at term 3"} 125s {"level":"info","ts":"2024-11-02T15:54:00.271183Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgPreVoteResp from 8e9e05c52164694d at term 3"} 125s {"level":"info","ts":"2024-11-02T15:54:00.271197Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became candidate at term 4"} 125s {"level":"info","ts":"2024-11-02T15:54:00.271205Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 4"} 125s {"level":"info","ts":"2024-11-02T15:54:00.271216Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"8e9e05c52164694d became leader at term 4"} 125s {"level":"info","ts":"2024-11-02T15:54:00.271224Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 4"} 125s {"level":"info","ts":"2024-11-02T15:54:00.277908Z","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"} 125s {"level":"info","ts":"2024-11-02T15:54:00.277935Z","caller":"embed/serve.go:104","msg":"ready to serve client requests"} 125s {"level":"info","ts":"2024-11-02T15:54:00.278223Z","caller":"etcdmain/main.go:44","msg":"notifying init daemon"} 125s {"level":"info","ts":"2024-11-02T15:54:00.278244Z","caller":"etcdmain/main.go:50","msg":"successfully notified init daemon"} 125s {"level":"info","ts":"2024-11-02T15:54:00.278672Z","caller":"v3rpc/health.go:61","msg":"grpc service status changed","service":"","status":"SERVING"} 125s {"level":"info","ts":"2024-11-02T15:54:00.279348Z","caller":"embed/serve.go:251","msg":"serving client traffic securely","traffic":"grpc+http","address":"127.0.0.1:2379"} 125s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 125s Ncat: Listening on 0.0.0.0:12345 125s 1 127s OK 129s inet 10.0.2.123/32 scope global enp0s1 129s Ncat: Version 7.94SVN ( https://nmap.org/ncat ) 129s Ncat: Connected to 10.0.2.123:12345. 129s Ncat: Ncat: Connection from 10.0.2.123:59922. 129s 0 bytes sent, 0 bytes received in 0.03 seconds. 129s ### You've reached the end of the script, all "tests" have successfully been passed! ### 129s {"level":"info","ts":"2024-11-02T15:54:04.890390Z","caller":"osutil/interrupt_unix.go:64","msg":"received signal; shutting down","signal":"terminated"} 129s {"level":"info","ts":"2024-11-02T15:54:04.890450Z","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"]} 129s {"level":"warn","ts":"2024-11-02T15:54:04.890541Z","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"} 129s {"level":"warn","ts":"2024-11-02T15:54:04.890561Z","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"} 129s {"level":"info","ts":"2024-11-02T15:54:04.892282Z","caller":"etcdserver/server.go:1543","msg":"skipped leadership transfer for single voting member cluster","local-member-id":"8e9e05c52164694d","current-leader-member-id":"8e9e05c52164694d"} 129s {"level":"info","ts":"2024-11-02T15:54:04.897225Z","caller":"embed/etcd.go:582","msg":"stopping serving peer traffic","address":"127.0.0.1:2380"} 129s {"level":"info","ts":"2024-11-02T15:54:04.897366Z","caller":"embed/etcd.go:587","msg":"stopped serving peer traffic","address":"127.0.0.1:2380"} 129s {"level":"info","ts":"2024-11-02T15:54:04.897378Z","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"]} 130s autopkgtest [15:54:05]: test clientcert-test: -----------------------] 130s clientcert-test PASS 130s autopkgtest [15:54:05]: test clientcert-test: - - - - - - - - - - results - - - - - - - - - - 131s autopkgtest [15:54:06]: @@@@@@@@@@@@@@@@@@@@ summary 131s test PASS 131s cacert-test PASS 131s clientcert-test PASS 134s nova [W] Using flock in prodstack6-ppc64el 134s Creating nova instance adt-plucky-ppc64el-vip-manager2-20241102-155155-juju-7f2275-prod-proposed-migration-environment-15-4da47be5-dbf1-4dac-bf0c-6855fc37b16c from image adt/ubuntu-plucky-ppc64el-server-20241102.img (UUID 6c75d7ee-3b45-4c3b-9217-03e6a1e48086)...