0s autopkgtest [14:07:38]: starting date and time: 2025-07-02 14:07:38+0000 0s autopkgtest [14:07:38]: git checkout: 508d4a25 a-v-ssh wait_for_ssh: demote "ssh connection failed" to a debug message 0s autopkgtest [14:07:38]: host juju-7f2275-prod-proposed-migration-environment-21; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.fiyeb8vo/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:openvpn --apt-upgrade openvpn --timeout-short=300 --timeout-copy=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=openvpn/2.6.14-0ubuntu0.25.04.1 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor builder-cpu2-ram4-disk20 --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-21@bos03-2.secgroup --name adt-plucky-amd64-openvpn-20250702-114330-juju-7f2275-prod-proposed-migration-environment-21-d0339ba6-1a34-48a0-9cbb-673c672aa993 --image adt/ubuntu-plucky-amd64-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-21 --net-id=net_prod-proposed-migration-amd64 -e TERM=linux --mirror=http://ftpmaster.internal/ubuntu/ 3s Creating nova instance adt-plucky-amd64-openvpn-20250702-114330-juju-7f2275-prod-proposed-migration-environment-21-d0339ba6-1a34-48a0-9cbb-673c672aa993 from image adt/ubuntu-plucky-amd64-server-20250702.img (UUID 45bb4bdd-a982-4e47-9808-e0f053c41880)... 913s autopkgtest [14:22:51]: testbed dpkg architecture: amd64 913s autopkgtest [14:22:51]: testbed apt version: 3.0.0 914s autopkgtest [14:22:52]: @@@@@@@@@@@@@@@@@@@@ test bed setup 914s autopkgtest [14:22:52]: testbed release detected to be: None 915s autopkgtest [14:22:53]: updating testbed package index (apt update) 915s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [265 kB] 915s Hit:2 http://ftpmaster.internal/ubuntu plucky InRelease 915s Hit:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease 915s Hit:4 http://ftpmaster.internal/ubuntu plucky-security InRelease 915s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [28.0 kB] 915s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [3108 B] 915s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/restricted Sources [9056 B] 915s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [7940 B] 915s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/main amd64 Packages [78.7 kB] 915s Get:10 http://ftpmaster.internal/ubuntu plucky-proposed/main i386 Packages [29.8 kB] 915s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/main amd64 c-n-f Metadata [288 B] 915s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/restricted amd64 Packages [61.3 kB] 915s Get:13 http://ftpmaster.internal/ubuntu plucky-proposed/restricted i386 Packages [2420 B] 915s Get:14 http://ftpmaster.internal/ubuntu plucky-proposed/restricted amd64 c-n-f Metadata [232 B] 916s Get:15 http://ftpmaster.internal/ubuntu plucky-proposed/universe amd64 Packages [50.8 kB] 916s Get:16 http://ftpmaster.internal/ubuntu plucky-proposed/universe i386 Packages [27.9 kB] 916s Get:17 http://ftpmaster.internal/ubuntu plucky-proposed/universe amd64 c-n-f Metadata [9496 B] 916s Get:18 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse amd64 Packages [8488 B] 916s Get:19 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse i386 Packages [2444 B] 916s Get:20 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse amd64 c-n-f Metadata [440 B] 916s Fetched 586 kB in 1s (677 kB/s) 917s Reading package lists... 917s autopkgtest [14:22:55]: upgrading testbed (apt dist-upgrade and autopurge) 917s Reading package lists... 918s Building dependency tree... 918s Reading state information... 918s Calculating upgrade...Starting pkgProblemResolver with broken count: 0 918s Starting 2 pkgProblemResolver with broken count: 0 918s Done 919s Entering ResolveByKeep 919s 919s Calculating upgrade... 919s The following packages will be upgraded: 919s linux-firmware 919s 1 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 919s Need to get 575 MB of archives. 919s After this operation, 5120 B of additional disk space will be used. 919s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed/main amd64 linux-firmware amd64 20250317.git1d4c88ee-0ubuntu1.3 [575 MB] 937s Fetched 575 MB in 18s (32.7 MB/s) 937s (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 ... 113184 files and directories currently installed.) 937s Preparing to unpack .../linux-firmware_20250317.git1d4c88ee-0ubuntu1.3_amd64.deb ... 937s Unpacking linux-firmware (20250317.git1d4c88ee-0ubuntu1.3) over (20250317.git1d4c88ee-0ubuntu1.2) ... 940s Setting up linux-firmware (20250317.git1d4c88ee-0ubuntu1.3) ... 940s Processing triggers for initramfs-tools (0.147ubuntu1) ... 940s update-initramfs: Generating /boot/initrd.img-6.14.0-23-generic 950s Reading package lists... 950s Building dependency tree... 950s Reading state information... 951s Starting pkgProblemResolver with broken count: 0 951s Starting 2 pkgProblemResolver with broken count: 0 951s Done 951s Solving dependencies... 951s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 951s autopkgtest [14:23:29]: rebooting testbed after setup commands that affected boot 971s autopkgtest [14:23:49]: testbed running kernel: Linux 6.14.0-23-generic #23-Ubuntu SMP PREEMPT_DYNAMIC Fri Jun 13 23:02:20 UTC 2025 973s autopkgtest [14:23:51]: @@@@@@@@@@@@@@@@@@@@ apt-source openvpn 976s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed/main openvpn 2.6.14-0ubuntu0.25.04.1 (dsc) [2366 B] 976s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/main openvpn 2.6.14-0ubuntu0.25.04.1 (tar) [1926 kB] 976s Get:3 http://ftpmaster.internal/ubuntu plucky-proposed/main openvpn 2.6.14-0ubuntu0.25.04.1 (diff) [65.3 kB] 976s gpgv: Signature made Tue Jun 3 13:46:47 2025 UTC 976s gpgv: using RSA key 63EEFC3DE14D5146CE7F24BF34B8AD7D9529E793 976s gpgv: issuer "lena.voytek@canonical.com" 976s gpgv: Can't check signature: No public key 976s dpkg-source: warning: cannot verify inline signature for ./openvpn_2.6.14-0ubuntu0.25.04.1.dsc: no acceptable signature found 976s autopkgtest [14:23:54]: testing package openvpn version 2.6.14-0ubuntu0.25.04.1 977s autopkgtest [14:23:55]: build not needed 977s autopkgtest [14:23:55]: test server-setup-with-ca: preparing testbed 978s Reading package lists... 978s Building dependency tree... 978s Reading state information... 978s Starting pkgProblemResolver with broken count: 0 978s Starting 2 pkgProblemResolver with broken count: 0 978s Done 978s The following NEW packages will be installed: 978s easy-rsa libnl-genl-3-200 libpkcs11-helper1t64 openvpn 979s 0 upgraded, 4 newly installed, 0 to remove and 0 not upgraded. 979s Need to get 880 kB of archives. 979s After this operation, 2424 kB of additional disk space will be used. 979s Get:1 http://ftpmaster.internal/ubuntu plucky/main amd64 libnl-genl-3-200 amd64 3.7.0-2 [12.2 kB] 979s Get:2 http://ftpmaster.internal/ubuntu plucky/main amd64 libpkcs11-helper1t64 amd64 1.30.0-1 [50.3 kB] 979s Get:3 http://ftpmaster.internal/ubuntu plucky-proposed/main amd64 openvpn amd64 2.6.14-0ubuntu0.25.04.1 [749 kB] 979s Get:4 http://ftpmaster.internal/ubuntu plucky/universe amd64 easy-rsa all 3.2.2-1 [68.6 kB] 979s Preconfiguring packages ... 979s Fetched 880 kB in 1s (1601 kB/s) 979s Selecting previously unselected package libnl-genl-3-200:amd64. 980s (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 ... 113184 files and directories currently installed.) 980s Preparing to unpack .../libnl-genl-3-200_3.7.0-2_amd64.deb ... 980s Unpacking libnl-genl-3-200:amd64 (3.7.0-2) ... 980s Selecting previously unselected package libpkcs11-helper1t64:amd64. 980s Preparing to unpack .../libpkcs11-helper1t64_1.30.0-1_amd64.deb ... 980s Unpacking libpkcs11-helper1t64:amd64 (1.30.0-1) ... 980s Selecting previously unselected package openvpn. 980s Preparing to unpack .../openvpn_2.6.14-0ubuntu0.25.04.1_amd64.deb ... 980s Unpacking openvpn (2.6.14-0ubuntu0.25.04.1) ... 980s Selecting previously unselected package easy-rsa. 980s Preparing to unpack .../easy-rsa_3.2.2-1_all.deb ... 980s Unpacking easy-rsa (3.2.2-1) ... 980s Setting up libnl-genl-3-200:amd64 (3.7.0-2) ... 980s Setting up libpkcs11-helper1t64:amd64 (1.30.0-1) ... 980s Setting up easy-rsa (3.2.2-1) ... 980s Setting up openvpn (2.6.14-0ubuntu0.25.04.1) ... 980s Created symlink '/etc/systemd/system/multi-user.target.wants/openvpn.service' → '/usr/lib/systemd/system/openvpn.service'. 981s Processing triggers for man-db (2.13.0-1) ... 982s Processing triggers for libc-bin (2.41-6ubuntu1) ... 983s autopkgtest [14:24:01]: test server-setup-with-ca: [----------------------- 983s [I] Create the CA directory inside the config directory 983s + CONFIG_DIR=/etc/openvpn 983s + CA_DIR=easy-rsa 983s + CA_VARS_FILE=vars 983s + DEVICE=tun1 983s + IP_NETWORK=10.9.8.0 983s + NETWORK_MASK=255.255.255.0 983s + LOG_FILE=/tmp/autopkgtest.e8iquu/autopkgtest_tmp/openvpn.log 983s + info 'Create the CA directory inside the config directory' 983s + echo '[I] Create the CA directory inside the config directory' 983s + cd /etc/openvpn 983s + make-cadir easy-rsa 983s [I] Add some variables to the vars to build the CA and keys in a non interactive mode 983s + cd easy-rsa 983s + info 'Add some variables to the vars to build the CA and keys in a non interactive mode' 983s + echo '[I] Add some variables to the vars to build the CA and keys in a non interactive mode' 983s + cat 983s [I] Setup the CA and the server keys 983s + info 'Setup the CA and the server keys' 983s + echo '[I] Setup the CA and the server keys' 983s + ./easyrsa --batch init-pki 983s Using Easy-RSA 'vars' configuration: 983s * /etc/openvpn/easy-rsa/vars 983s 983s Notice 983s ------ 983s 'init-pki' complete; you may now create a CA or requests. 983s 983s Your newly created PKI dir is: 983s * /etc/openvpn/easy-rsa/pki 983s 983s Using Easy-RSA configuration: 983s * /etc/openvpn/easy-rsa/vars 983s + rm -f vars 983s + ./easyrsa --batch build-ca nopass 983s 983s Notice 983s ------ 983s CA creation complete. Your new CA certificate is at: 983s * /etc/openvpn/easy-rsa/pki/ca.crt 983s 983s Create an OpenVPN TLS-AUTH|TLS-CRYPT-V1 key now: See 'help gen-tls' 983s 983s Build-ca completed successfully. 983s 983s + ./easyrsa --batch build-server-full server nopass 984s 984s Notice 984s ------ 984s Private-Key and Public-Certificate-Request files created. 984s Your files are: 984s * req: /etc/openvpn/easy-rsa/pki/reqs/server.req 984s * key: /etc/openvpn/easy-rsa/pki/private/server.key 984s 984s 984s Notice 984s ------ 984s Inline file created: 984s * /etc/openvpn/easy-rsa/pki/inline/private/server.inline 984s 984s 984s Notice 984s ------ 984s Certificate created at: 984s * /etc/openvpn/easy-rsa/pki/issued/server.crt 984s 984s + ./easyrsa --batch gen-dh 1063s 1063s Notice 1063s ------ 1063s 1063s DH parameters of size 2048 created at: 1063s * /etc/openvpn/easy-rsa/pki/dh.pem 1063s 1063s [I] Create the OpenVPN server config file 1063s + info 'Create the OpenVPN server config file' 1063s + echo '[I] Create the OpenVPN server config file' 1063s + cat 1063s + info 'Start an OpenVPN process in background and redirect its output to a file' 1063s + echo '[I] Start an OpenVPN process in background and redirect its output to a file' 1063s [I] Start an OpenVPN process in background and redirect its output to a file 1063s + info 'Give some time to start the process, check if the TUN device is opened' 1063s + echo '[I] Give some time to start the process, check if the TUN device is opened' 1063s + openvpn --config /etc/openvpn/server.conf --verb 6 1063s + count=1 1063s + '[' -f /tmp/autopkgtest.e8iquu/autopkgtest_tmp/openvpn.log ']' 1063s + '[' 1 -gt 9 ']' 1063s ++ expr 1 + 1 1063s [I] Give some time to start the process, check if the TUN device is opened 1063s + count=2 1063s + sleep 1 1064s + '[' -f /tmp/autopkgtest.e8iquu/autopkgtest_tmp/openvpn.log ']' 1064s + cat /tmp/autopkgtest.e8iquu/autopkgtest_tmp/openvpn.log 1064s + grep 'TUN/TAP device tun1 opened' 1064s 2025-07-02 14:25:21 us=213500 TUN/TAP device tun1 opened 1064s + info 'Check if the tun1 was created and if the state is UNKNOWN at this point' 1064s + echo '[I] Check if the tun1 was created and if the state is UNKNOWN at this point' 1064s [I] Check if the tun1 was created and if the state is UNKNOWN at this point 1064s + ip address show tun1 1064s + grep 'state UNKNOWN' 1064s 3: tun1: mtu 1500 qdisc fq_codel state UNKNOWN group default qlen 500 1064s + info 'Check if OpenVPN is listening on port 1194 (default port)' 1064s + echo '[I] Check if OpenVPN is listening on port 1194 (default port)' 1064s [I] Check if OpenVPN is listening on port 1194 (default port) 1064s udp UNCONN 0 0 0.0.0.0:1194 0.0.0.0:* users:(("openvpn",pid=1616,fd=4)) 1064s [I] Check if Diffie-Hellman was initialized 1064s 2025-07-02 14:25:21 us=211895 Diffie-Hellman initialized with 2048 bit key 1064s [I] Check if the tun1 is linked 1064s 2025-07-02 14:25:21 us=213593 net_iface_up: set tun1 up 1064s [I] Check if the network route was correctly configured 1064s 2025-07-02 14:25:21 us=213795 net_route_v4_add: 10.9.8.0/24 via 10.9.8.2 dev [NULL] table 0 metric -1 1064s [I] Check if the Initialization Sequence completed 1064s 2025-07-02 14:25:21 us=214009 Initialization Sequence Completed 1064s + ss -lnptu 1064s + grep -E '([0-9]{1,3}\.){3}[0-9]{1,3}:1194.*users:\(\(\"openvpn\"' 1064s + info 'Check if Diffie-Hellman was initialized' 1064s + echo '[I] Check if Diffie-Hellman was initialized' 1064s + cat /tmp/autopkgtest.e8iquu/autopkgtest_tmp/openvpn.log 1064s + grep 'Diffie-Hellman initialized' 1064s + info 'Check if the tun1 is linked' 1064s + echo '[I] Check if the tun1 is linked' 1064s + cat /tmp/autopkgtest.e8iquu/autopkgtest_tmp/openvpn.log 1064s + grep 'net_iface_up: set tun1 up' 1064s + info 'Check if the network route was correctly configured' 1064s + echo '[I] Check if the network route was correctly configured' 1064s + cat /tmp/autopkgtest.e8iquu/autopkgtest_tmp/openvpn.log 1064s + grep 'net_route_v4_add: 10.9.8.0/24 via' 1064s + info 'Check if the Initialization Sequence completed' 1064s + echo '[I] Check if the Initialization Sequence completed' 1064s + cat /tmp/autopkgtest.e8iquu/autopkgtest_tmp/openvpn.log 1064s + grep 'Initialization Sequence Completed' 1064s + trap cleanup INT TERM EXIT 1064s + cleanup 1064s + pkill openvpn 1064s + rm -rf /etc/openvpn/easy-rsa 1064s autopkgtest [14:25:22]: test server-setup-with-ca: -----------------------] 1065s server-setup-with-ca PASS 1065s autopkgtest [14:25:23]: test server-setup-with-ca: - - - - - - - - - - results - - - - - - - - - - 1065s autopkgtest [14:25:23]: test server-setup-with-static-key: preparing testbed 1324s Creating nova instance adt-plucky-amd64-openvpn-20250702-114330-juju-7f2275-prod-proposed-migration-environment-21-d0339ba6-1a34-48a0-9cbb-673c672aa993 from image adt/ubuntu-plucky-amd64-server-20250702.img (UUID 45bb4bdd-a982-4e47-9808-e0f053c41880)... 4574s Unexpected error: 4574s Traceback (most recent call last): 4574s File "/home/ubuntu/autopkgtest/lib/VirtSubproc.py", line 872, in mainloop 4574s command() 4574s File "/home/ubuntu/autopkgtest/lib/VirtSubproc.py", line 787, in command 4574s r = f(c, ce) 4574s File "/home/ubuntu/autopkgtest/lib/VirtSubproc.py", line 436, in cmd_revert 4574s caller.hook_revert() 4574s File "/home/ubuntu/autopkgtest/virt/autopkgtest-virt-ssh", line 438, in hook_revert 4574s host_setup('revert') 4574s File "/home/ubuntu/autopkgtest/virt/autopkgtest-virt-ssh", line 252, in host_setup 4574s execute_setup_script(command) 4574s File "/home/ubuntu/autopkgtest/virt/autopkgtest-virt-ssh", line 203, in execute_setup_script 4574s (status, out, err) = VirtSubproc.execute_timeout( 4574s File "/home/ubuntu/autopkgtest/lib/VirtSubproc.py", line 156, in execute_timeout 4574s (out, err) = sp.communicate(instr) 4574s File "/usr/lib/python3.8/subprocess.py", line 1015, in communicate 4574s stdout = self.stdout.read() 4574s File "/home/ubuntu/autopkgtest/lib/VirtSubproc.py", line 75, in alarm_handler 4574s raise Timeout(to) 4574s VirtSubproc.Timeout: 1800 4574s autopkgtest [15:23:52]: ERROR: testbed failure: unexpected eof from the testbed