0s autopkgtest [14:24:43]: starting date and time: 2024-04-05 14:24:43+0000 0s autopkgtest [14:24:43]: git checkout: 31124158 autopkgtest: take Paride's WIP change regarding wrong src pkg selection 0s autopkgtest [14:24:43]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.ixx1oa8x/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:ubuntu-advantage-tools --apt-upgrade wsl-pro-service --timeout-short=300 --timeout-copy=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=ubuntu-advantage-tools/31.2.3 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@lcy02-69.secgroup --name adt-noble-amd64-wsl-pro-service-20240405-142442-juju-7f2275-prod-proposed-migration-environment-2-b9ba07f6-bab8-410e-a03e-9ed9644f0b99 --image adt/ubuntu-noble-amd64-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-2 --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,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 431s autopkgtest [14:31:54]: testbed dpkg architecture: amd64 431s autopkgtest [14:31:54]: testbed apt version: 2.7.14build2 431s autopkgtest [14:31:54]: @@@@@@@@@@@@@@@@@@@@ test bed setup 432s Get:1 http://ftpmaster.internal/ubuntu noble-proposed InRelease [117 kB] 432s Get:2 http://ftpmaster.internal/ubuntu noble-proposed/multiverse Sources [21.2 kB] 432s Get:3 http://ftpmaster.internal/ubuntu noble-proposed/main Sources [140 kB] 432s Get:4 http://ftpmaster.internal/ubuntu noble-proposed/universe Sources [1070 kB] 432s Get:5 http://ftpmaster.internal/ubuntu noble-proposed/restricted Sources [4272 B] 432s Get:6 http://ftpmaster.internal/ubuntu noble-proposed/main i386 Packages [181 kB] 432s Get:7 http://ftpmaster.internal/ubuntu noble-proposed/main amd64 Packages [233 kB] 432s Get:8 http://ftpmaster.internal/ubuntu noble-proposed/main amd64 c-n-f Metadata [3508 B] 432s Get:9 http://ftpmaster.internal/ubuntu noble-proposed/restricted amd64 Packages [12.4 kB] 432s Get:10 http://ftpmaster.internal/ubuntu noble-proposed/restricted i386 Packages [2372 B] 432s Get:11 http://ftpmaster.internal/ubuntu noble-proposed/restricted amd64 c-n-f Metadata [116 B] 432s Get:12 http://ftpmaster.internal/ubuntu noble-proposed/universe i386 Packages [483 kB] 432s Get:13 http://ftpmaster.internal/ubuntu noble-proposed/universe amd64 Packages [1332 kB] 432s Get:14 http://ftpmaster.internal/ubuntu noble-proposed/universe amd64 c-n-f Metadata [9396 B] 432s Get:15 http://ftpmaster.internal/ubuntu noble-proposed/multiverse i386 Packages [17.8 kB] 432s Get:16 http://ftpmaster.internal/ubuntu noble-proposed/multiverse amd64 Packages [55.4 kB] 432s Get:17 http://ftpmaster.internal/ubuntu noble-proposed/multiverse amd64 c-n-f Metadata [196 B] 434s Fetched 3684 kB in 1s (6124 kB/s) 434s Reading package lists... 436s Reading package lists... 436s Building dependency tree... 436s Reading state information... 436s Calculating upgrade... 437s The following packages will be upgraded: 437s gcc-13-base libc-bin libc6 locales ubuntu-pro-client ubuntu-pro-client-l10n 437s 6 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 437s Need to get 8463 kB of archives. 437s After this operation, 3072 B of additional disk space will be used. 437s Get:1 http://ftpmaster.internal/ubuntu noble/main amd64 libc6 amd64 2.39-0ubuntu8 [3265 kB] 437s Get:2 http://ftpmaster.internal/ubuntu noble/main amd64 libc-bin amd64 2.39-0ubuntu8 [682 kB] 437s Get:3 http://ftpmaster.internal/ubuntu noble/main amd64 locales all 2.39-0ubuntu8 [4234 kB] 437s Get:4 http://ftpmaster.internal/ubuntu noble-proposed/main amd64 ubuntu-pro-client-l10n amd64 31.2.3 [19.4 kB] 437s Get:5 http://ftpmaster.internal/ubuntu noble-proposed/main amd64 ubuntu-pro-client amd64 31.2.3 [215 kB] 437s Get:6 http://ftpmaster.internal/ubuntu noble/main amd64 gcc-13-base amd64 13.2.0-23ubuntu3 [48.6 kB] 437s Preconfiguring packages ... 437s Fetched 8463 kB in 0s (67.3 MB/s) 437s (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 ... 71631 files and directories currently installed.) 437s Preparing to unpack .../libc6_2.39-0ubuntu8_amd64.deb ... 438s Unpacking libc6:amd64 (2.39-0ubuntu8) over (2.39-0ubuntu2) ... 438s Setting up libc6:amd64 (2.39-0ubuntu8) ... 438s (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 ... 71631 files and directories currently installed.) 438s Preparing to unpack .../libc-bin_2.39-0ubuntu8_amd64.deb ... 438s Unpacking libc-bin (2.39-0ubuntu8) over (2.39-0ubuntu2) ... 438s Setting up libc-bin (2.39-0ubuntu8) ... 438s (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 ... 71631 files and directories currently installed.) 438s Preparing to unpack .../locales_2.39-0ubuntu8_all.deb ... 438s Unpacking locales (2.39-0ubuntu8) over (2.39-0ubuntu6) ... 439s Preparing to unpack .../ubuntu-pro-client-l10n_31.2.3_amd64.deb ... 439s Unpacking ubuntu-pro-client-l10n (31.2.3) over (31.2.2build1) ... 439s Preparing to unpack .../ubuntu-pro-client_31.2.3_amd64.deb ... 439s Unpacking ubuntu-pro-client (31.2.3) over (31.2.2build1) ... 439s Preparing to unpack .../gcc-13-base_13.2.0-23ubuntu3_amd64.deb ... 439s Unpacking gcc-13-base:amd64 (13.2.0-23ubuntu3) over (13.2.0-13ubuntu1) ... 439s Setting up locales (2.39-0ubuntu8) ... 440s Generating locales (this might take a while)... 441s en_US.UTF-8... done 441s Generation complete. 441s Setting up gcc-13-base:amd64 (13.2.0-23ubuntu3) ... 441s Setting up ubuntu-pro-client (31.2.3) ... 443s Setting up ubuntu-pro-client-l10n (31.2.3) ... 443s Processing triggers for man-db (2.12.0-3) ... 444s Reading package lists... 444s Building dependency tree... 444s Reading state information... 444s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 445s Hit:1 http://ftpmaster.internal/ubuntu noble-proposed InRelease 445s Hit:2 http://ftpmaster.internal/ubuntu noble InRelease 445s Hit:3 http://ftpmaster.internal/ubuntu noble-updates InRelease 445s Hit:4 http://ftpmaster.internal/ubuntu noble-security InRelease 446s Reading package lists... 446s Reading package lists... 446s Building dependency tree... 446s Reading state information... 447s Calculating upgrade... 447s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 447s Reading package lists... 447s Building dependency tree... 447s Reading state information... 448s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 448s autopkgtest [14:32:11]: rebooting testbed after setup commands that affected boot 626s autopkgtest [14:35:09]: testbed running kernel: Linux 6.8.0-11-generic #11-Ubuntu SMP PREEMPT_DYNAMIC Wed Feb 14 00:29:05 UTC 2024 627s autopkgtest [14:35:10]: @@@@@@@@@@@@@@@@@@@@ apt-source wsl-pro-service 628s Get:1 http://ftpmaster.internal/ubuntu noble/universe wsl-pro-service 0.1.2build1 (dsc) [2084 B] 628s Get:2 http://ftpmaster.internal/ubuntu noble/universe wsl-pro-service 0.1.2build1 (tar) [1745 kB] 628s gpgv: Signature made Mon Apr 1 08:33:08 2024 UTC 628s gpgv: using RSA key A089FB36AAFBDAD5ACC1325069F790171A210984 628s gpgv: Can't check signature: No public key 628s dpkg-source: warning: cannot verify inline signature for ./wsl-pro-service_0.1.2build1.dsc: no acceptable signature found 628s autopkgtest [14:35:11]: testing package wsl-pro-service version 0.1.2build1 628s autopkgtest [14:35:11]: build not needed 629s autopkgtest [14:35:12]: test command1: preparing testbed 634s Reading package lists... 634s Building dependency tree... 634s Reading state information... 635s Starting pkgProblemResolver with broken count: 0 635s Starting 2 pkgProblemResolver with broken count: 0 635s Done 635s The following additional packages will be installed: 635s autoconf automake autopoint autotools-dev build-essential cpp cpp-13 635s cpp-13-x86-64-linux-gnu cpp-x86-64-linux-gnu debhelper debugedit dh-apport 635s dh-autoreconf dh-golang dh-strip-nondeterminism dwz g++ g++-13 635s g++-13-x86-64-linux-gnu g++-x86-64-linux-gnu gcc gcc-13 635s gcc-13-x86-64-linux-gnu gcc-x86-64-linux-gnu gettext golang-1.22-go 635s golang-1.22-src golang-go golang-src intltool-debian libarchive-zip-perl 635s libasan8 libatomic1 libc-dev-bin libc6-dev libcc1-0 libcrypt-dev 635s libdebhelper-perl libdw1t64 libfile-stripnondeterminism-perl libgcc-13-dev 635s libgomp1 libhwasan0 libisl23 libitm1 liblsan0 libmpc3 libquadmath0 635s libstdc++-13-dev libsub-override-perl libtool libtsan2 libubsan1 635s linux-libc-dev m4 po-debconf rpcsvc-proto 635s Suggested packages: 635s autoconf-archive gnu-standards autoconf-doc cpp-doc gcc-13-locales 635s cpp-13-doc dh-make g++-multilib g++-13-multilib gcc-13-doc gcc-multilib 635s manpages-dev flex bison gdb gcc-doc gcc-13-multilib gdb-x86-64-linux-gnu 635s gettext-doc libasprintf-dev libgettextpo-dev bzr | brz git mercurial 635s subversion glibc-doc libstdc++-13-doc libtool-doc gfortran 635s | fortran95-compiler gcj-jdk m4-doc libmail-box-perl 635s Recommended packages: 635s pkg-config manpages manpages-dev libc-devtools libarchive-cpio-perl 635s libltdl-dev libmail-sendmail-perl 635s The following NEW packages will be installed: 635s autoconf automake autopkgtest-satdep autopoint autotools-dev build-essential 635s cpp cpp-13 cpp-13-x86-64-linux-gnu cpp-x86-64-linux-gnu debhelper debugedit 635s dh-apport dh-autoreconf dh-golang dh-strip-nondeterminism dwz g++ g++-13 635s g++-13-x86-64-linux-gnu g++-x86-64-linux-gnu gcc gcc-13 635s gcc-13-x86-64-linux-gnu gcc-x86-64-linux-gnu gettext golang-1.22-go 635s golang-1.22-src golang-go golang-src intltool-debian libarchive-zip-perl 635s libasan8 libatomic1 libc-dev-bin libc6-dev libcc1-0 libcrypt-dev 635s libdebhelper-perl libdw1t64 libfile-stripnondeterminism-perl libgcc-13-dev 635s libgomp1 libhwasan0 libisl23 libitm1 liblsan0 libmpc3 libquadmath0 635s libstdc++-13-dev libsub-override-perl libtool libtsan2 libubsan1 635s linux-libc-dev m4 po-debconf rpcsvc-proto 635s 0 upgraded, 58 newly installed, 0 to remove and 0 not upgraded. 635s Need to get 116 MB/116 MB of archives. 635s After this operation, 485 MB of additional disk space will be used. 635s Get:1 /tmp/autopkgtest.F7y8MH/1-autopkgtest-satdep.deb autopkgtest-satdep amd64 0 [756 B] 635s Get:2 http://ftpmaster.internal/ubuntu noble/main amd64 m4 amd64 1.4.19-4 [243 kB] 635s Get:3 http://ftpmaster.internal/ubuntu noble/main amd64 autoconf all 2.71-3 [339 kB] 635s Get:4 http://ftpmaster.internal/ubuntu noble/main amd64 autotools-dev all 20220109.1 [44.9 kB] 635s Get:5 http://ftpmaster.internal/ubuntu noble/main amd64 automake all 1:1.16.5-1.3ubuntu1 [558 kB] 635s Get:6 http://ftpmaster.internal/ubuntu noble/main amd64 autopoint all 0.21-14ubuntu1 [422 kB] 635s Get:7 http://ftpmaster.internal/ubuntu noble/main amd64 libc-dev-bin amd64 2.39-0ubuntu8 [20.4 kB] 635s Get:8 http://ftpmaster.internal/ubuntu noble-updates/main amd64 linux-libc-dev amd64 6.8.0-11.11 [1595 kB] 635s Get:9 http://ftpmaster.internal/ubuntu noble/main amd64 libcrypt-dev amd64 1:4.4.36-4 [128 kB] 635s Get:10 http://ftpmaster.internal/ubuntu noble/main amd64 rpcsvc-proto amd64 1.4.2-0ubuntu6 [68.5 kB] 635s Get:11 http://ftpmaster.internal/ubuntu noble/main amd64 libc6-dev amd64 2.39-0ubuntu8 [2124 kB] 635s Get:12 http://ftpmaster.internal/ubuntu noble/main amd64 libisl23 amd64 0.26-3 [741 kB] 635s Get:13 http://ftpmaster.internal/ubuntu noble/main amd64 libmpc3 amd64 1.3.1-1 [54.1 kB] 635s Get:14 http://ftpmaster.internal/ubuntu noble/main amd64 cpp-13-x86-64-linux-gnu amd64 13.2.0-23ubuntu3 [11.2 MB] 635s Get:15 http://ftpmaster.internal/ubuntu noble/main amd64 cpp-13 amd64 13.2.0-23ubuntu3 [1034 B] 635s Get:16 http://ftpmaster.internal/ubuntu noble/main amd64 cpp-x86-64-linux-gnu amd64 4:13.2.0-7ubuntu1 [5326 B] 635s Get:17 http://ftpmaster.internal/ubuntu noble/main amd64 cpp amd64 4:13.2.0-7ubuntu1 [22.4 kB] 635s Get:18 http://ftpmaster.internal/ubuntu noble/main amd64 libcc1-0 amd64 14-20240330-1ubuntu2 [47.7 kB] 635s Get:19 http://ftpmaster.internal/ubuntu noble/main amd64 libgomp1 amd64 14-20240330-1ubuntu2 [147 kB] 635s Get:20 http://ftpmaster.internal/ubuntu noble/main amd64 libitm1 amd64 14-20240330-1ubuntu2 [29.1 kB] 635s Get:21 http://ftpmaster.internal/ubuntu noble/main amd64 libatomic1 amd64 14-20240330-1ubuntu2 [10.4 kB] 635s Get:22 http://ftpmaster.internal/ubuntu noble/main amd64 libasan8 amd64 14-20240330-1ubuntu2 [3020 kB] 635s Get:23 http://ftpmaster.internal/ubuntu noble/main amd64 liblsan0 amd64 14-20240330-1ubuntu2 [1310 kB] 635s Get:24 http://ftpmaster.internal/ubuntu noble/main amd64 libtsan2 amd64 14-20240330-1ubuntu2 [2731 kB] 635s Get:25 http://ftpmaster.internal/ubuntu noble/main amd64 libubsan1 amd64 14-20240330-1ubuntu2 [1172 kB] 635s Get:26 http://ftpmaster.internal/ubuntu noble/main amd64 libhwasan0 amd64 14-20240330-1ubuntu2 [1629 kB] 635s Get:27 http://ftpmaster.internal/ubuntu noble/main amd64 libquadmath0 amd64 14-20240330-1ubuntu2 [155 kB] 635s Get:28 http://ftpmaster.internal/ubuntu noble/main amd64 libgcc-13-dev amd64 13.2.0-23ubuntu3 [2687 kB] 635s Get:29 http://ftpmaster.internal/ubuntu noble/main amd64 gcc-13-x86-64-linux-gnu amd64 13.2.0-23ubuntu3 [21.9 MB] 635s Get:30 http://ftpmaster.internal/ubuntu noble/main amd64 gcc-13 amd64 13.2.0-23ubuntu3 [479 kB] 635s Get:31 http://ftpmaster.internal/ubuntu noble/main amd64 gcc-x86-64-linux-gnu amd64 4:13.2.0-7ubuntu1 [1212 B] 635s Get:32 http://ftpmaster.internal/ubuntu noble/main amd64 gcc amd64 4:13.2.0-7ubuntu1 [5018 B] 635s Get:33 http://ftpmaster.internal/ubuntu noble/main amd64 libstdc++-13-dev amd64 13.2.0-23ubuntu3 [2398 kB] 635s Get:34 http://ftpmaster.internal/ubuntu noble/main amd64 g++-13-x86-64-linux-gnu amd64 13.2.0-23ubuntu3 [12.5 MB] 636s Get:35 http://ftpmaster.internal/ubuntu noble/main amd64 g++-13 amd64 13.2.0-23ubuntu3 [14.5 kB] 636s Get:36 http://ftpmaster.internal/ubuntu noble/main amd64 g++-x86-64-linux-gnu amd64 4:13.2.0-7ubuntu1 [964 B] 636s Get:37 http://ftpmaster.internal/ubuntu noble/main amd64 g++ amd64 4:13.2.0-7ubuntu1 [1100 B] 636s Get:38 http://ftpmaster.internal/ubuntu noble/main amd64 build-essential amd64 12.10ubuntu1 [4928 B] 636s Get:39 http://ftpmaster.internal/ubuntu noble/main amd64 libdebhelper-perl all 13.14.1ubuntu5 [89.8 kB] 636s Get:40 http://ftpmaster.internal/ubuntu noble/main amd64 libtool all 2.4.7-7 [166 kB] 636s Get:41 http://ftpmaster.internal/ubuntu noble/main amd64 dh-autoreconf all 20 [16.1 kB] 636s Get:42 http://ftpmaster.internal/ubuntu noble/main amd64 libarchive-zip-perl all 1.68-1 [90.2 kB] 636s Get:43 http://ftpmaster.internal/ubuntu noble/main amd64 libsub-override-perl all 0.10-1 [10.0 kB] 636s Get:44 http://ftpmaster.internal/ubuntu noble/main amd64 libfile-stripnondeterminism-perl all 1.13.1-1 [18.1 kB] 636s Get:45 http://ftpmaster.internal/ubuntu noble/main amd64 dh-strip-nondeterminism all 1.13.1-1 [5362 B] 636s Get:46 http://ftpmaster.internal/ubuntu noble/main amd64 libdw1t64 amd64 0.190-1.1build3 [261 kB] 636s Get:47 http://ftpmaster.internal/ubuntu noble/main amd64 debugedit amd64 1:5.0-5build2 [46.1 kB] 636s Get:48 http://ftpmaster.internal/ubuntu noble/main amd64 dwz amd64 0.15-1build6 [115 kB] 636s Get:49 http://ftpmaster.internal/ubuntu noble/main amd64 gettext amd64 0.21-14ubuntu1 [864 kB] 636s Get:50 http://ftpmaster.internal/ubuntu noble/main amd64 intltool-debian all 0.35.0+20060710.6 [23.2 kB] 636s Get:51 http://ftpmaster.internal/ubuntu noble/main amd64 po-debconf all 1.0.21+nmu1 [233 kB] 636s Get:52 http://ftpmaster.internal/ubuntu noble/main amd64 debhelper all 13.14.1ubuntu5 [869 kB] 636s Get:53 http://ftpmaster.internal/ubuntu noble/universe amd64 dh-apport all 2.28.0-0ubuntu1 [16.9 kB] 636s Get:54 http://ftpmaster.internal/ubuntu noble/main amd64 golang-1.22-src all 1.22.1-1build1 [19.7 MB] 636s Get:55 http://ftpmaster.internal/ubuntu noble/main amd64 golang-1.22-go amd64 1.22.1-1build1 [25.9 MB] 636s Get:56 http://ftpmaster.internal/ubuntu noble/main amd64 golang-src all 2:1.22~2build1 [5078 B] 636s Get:57 http://ftpmaster.internal/ubuntu noble/main amd64 golang-go amd64 2:1.22~2build1 [43.9 kB] 636s Get:58 http://ftpmaster.internal/ubuntu noble/main amd64 dh-golang all 1.62 [25.2 kB] 636s Fetched 116 MB in 1s (126 MB/s) 636s Selecting previously unselected package m4. 637s (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 ... 71631 files and directories currently installed.) 637s Preparing to unpack .../00-m4_1.4.19-4_amd64.deb ... 637s Unpacking m4 (1.4.19-4) ... 637s Selecting previously unselected package autoconf. 637s Preparing to unpack .../01-autoconf_2.71-3_all.deb ... 637s Unpacking autoconf (2.71-3) ... 637s Selecting previously unselected package autotools-dev. 637s Preparing to unpack .../02-autotools-dev_20220109.1_all.deb ... 637s Unpacking autotools-dev (20220109.1) ... 637s Selecting previously unselected package automake. 637s Preparing to unpack .../03-automake_1%3a1.16.5-1.3ubuntu1_all.deb ... 637s Unpacking automake (1:1.16.5-1.3ubuntu1) ... 637s Selecting previously unselected package autopoint. 637s Preparing to unpack .../04-autopoint_0.21-14ubuntu1_all.deb ... 637s Unpacking autopoint (0.21-14ubuntu1) ... 637s Selecting previously unselected package libc-dev-bin. 637s Preparing to unpack .../05-libc-dev-bin_2.39-0ubuntu8_amd64.deb ... 637s Unpacking libc-dev-bin (2.39-0ubuntu8) ... 637s Selecting previously unselected package linux-libc-dev:amd64. 637s Preparing to unpack .../06-linux-libc-dev_6.8.0-11.11_amd64.deb ... 637s Unpacking linux-libc-dev:amd64 (6.8.0-11.11) ... 637s Selecting previously unselected package libcrypt-dev:amd64. 637s Preparing to unpack .../07-libcrypt-dev_1%3a4.4.36-4_amd64.deb ... 637s Unpacking libcrypt-dev:amd64 (1:4.4.36-4) ... 637s Selecting previously unselected package rpcsvc-proto. 637s Preparing to unpack .../08-rpcsvc-proto_1.4.2-0ubuntu6_amd64.deb ... 637s Unpacking rpcsvc-proto (1.4.2-0ubuntu6) ... 637s Selecting previously unselected package libc6-dev:amd64. 637s Preparing to unpack .../09-libc6-dev_2.39-0ubuntu8_amd64.deb ... 637s Unpacking libc6-dev:amd64 (2.39-0ubuntu8) ... 638s Selecting previously unselected package libisl23:amd64. 638s Preparing to unpack .../10-libisl23_0.26-3_amd64.deb ... 638s Unpacking libisl23:amd64 (0.26-3) ... 638s Selecting previously unselected package libmpc3:amd64. 638s Preparing to unpack .../11-libmpc3_1.3.1-1_amd64.deb ... 638s Unpacking libmpc3:amd64 (1.3.1-1) ... 638s Selecting previously unselected package cpp-13-x86-64-linux-gnu. 638s Preparing to unpack .../12-cpp-13-x86-64-linux-gnu_13.2.0-23ubuntu3_amd64.deb ... 638s Unpacking cpp-13-x86-64-linux-gnu (13.2.0-23ubuntu3) ... 638s Selecting previously unselected package cpp-13. 638s Preparing to unpack .../13-cpp-13_13.2.0-23ubuntu3_amd64.deb ... 638s Unpacking cpp-13 (13.2.0-23ubuntu3) ... 638s Selecting previously unselected package cpp-x86-64-linux-gnu. 638s Preparing to unpack .../14-cpp-x86-64-linux-gnu_4%3a13.2.0-7ubuntu1_amd64.deb ... 638s Unpacking cpp-x86-64-linux-gnu (4:13.2.0-7ubuntu1) ... 638s Selecting previously unselected package cpp. 638s Preparing to unpack .../15-cpp_4%3a13.2.0-7ubuntu1_amd64.deb ... 638s Unpacking cpp (4:13.2.0-7ubuntu1) ... 638s Selecting previously unselected package libcc1-0:amd64. 638s Preparing to unpack .../16-libcc1-0_14-20240330-1ubuntu2_amd64.deb ... 638s Unpacking libcc1-0:amd64 (14-20240330-1ubuntu2) ... 638s Selecting previously unselected package libgomp1:amd64. 638s Preparing to unpack .../17-libgomp1_14-20240330-1ubuntu2_amd64.deb ... 638s Unpacking libgomp1:amd64 (14-20240330-1ubuntu2) ... 638s Selecting previously unselected package libitm1:amd64. 638s Preparing to unpack .../18-libitm1_14-20240330-1ubuntu2_amd64.deb ... 638s Unpacking libitm1:amd64 (14-20240330-1ubuntu2) ... 638s Selecting previously unselected package libatomic1:amd64. 638s Preparing to unpack .../19-libatomic1_14-20240330-1ubuntu2_amd64.deb ... 638s Unpacking libatomic1:amd64 (14-20240330-1ubuntu2) ... 638s Selecting previously unselected package libasan8:amd64. 638s Preparing to unpack .../20-libasan8_14-20240330-1ubuntu2_amd64.deb ... 638s Unpacking libasan8:amd64 (14-20240330-1ubuntu2) ... 638s Selecting previously unselected package liblsan0:amd64. 638s Preparing to unpack .../21-liblsan0_14-20240330-1ubuntu2_amd64.deb ... 638s Unpacking liblsan0:amd64 (14-20240330-1ubuntu2) ... 638s Selecting previously unselected package libtsan2:amd64. 638s Preparing to unpack .../22-libtsan2_14-20240330-1ubuntu2_amd64.deb ... 638s Unpacking libtsan2:amd64 (14-20240330-1ubuntu2) ... 638s Selecting previously unselected package libubsan1:amd64. 638s Preparing to unpack .../23-libubsan1_14-20240330-1ubuntu2_amd64.deb ... 638s Unpacking libubsan1:amd64 (14-20240330-1ubuntu2) ... 638s Selecting previously unselected package libhwasan0:amd64. 638s Preparing to unpack .../24-libhwasan0_14-20240330-1ubuntu2_amd64.deb ... 638s Unpacking libhwasan0:amd64 (14-20240330-1ubuntu2) ... 638s Selecting previously unselected package libquadmath0:amd64. 638s Preparing to unpack .../25-libquadmath0_14-20240330-1ubuntu2_amd64.deb ... 638s Unpacking libquadmath0:amd64 (14-20240330-1ubuntu2) ... 638s Selecting previously unselected package libgcc-13-dev:amd64. 638s Preparing to unpack .../26-libgcc-13-dev_13.2.0-23ubuntu3_amd64.deb ... 638s Unpacking libgcc-13-dev:amd64 (13.2.0-23ubuntu3) ... 638s Selecting previously unselected package gcc-13-x86-64-linux-gnu. 638s Preparing to unpack .../27-gcc-13-x86-64-linux-gnu_13.2.0-23ubuntu3_amd64.deb ... 638s Unpacking gcc-13-x86-64-linux-gnu (13.2.0-23ubuntu3) ... 638s Selecting previously unselected package gcc-13. 638s Preparing to unpack .../28-gcc-13_13.2.0-23ubuntu3_amd64.deb ... 638s Unpacking gcc-13 (13.2.0-23ubuntu3) ... 638s Selecting previously unselected package gcc-x86-64-linux-gnu. 638s Preparing to unpack .../29-gcc-x86-64-linux-gnu_4%3a13.2.0-7ubuntu1_amd64.deb ... 638s Unpacking gcc-x86-64-linux-gnu (4:13.2.0-7ubuntu1) ... 638s Selecting previously unselected package gcc. 638s Preparing to unpack .../30-gcc_4%3a13.2.0-7ubuntu1_amd64.deb ... 638s Unpacking gcc (4:13.2.0-7ubuntu1) ... 638s Selecting previously unselected package libstdc++-13-dev:amd64. 638s Preparing to unpack .../31-libstdc++-13-dev_13.2.0-23ubuntu3_amd64.deb ... 638s Unpacking libstdc++-13-dev:amd64 (13.2.0-23ubuntu3) ... 639s Selecting previously unselected package g++-13-x86-64-linux-gnu. 639s Preparing to unpack .../32-g++-13-x86-64-linux-gnu_13.2.0-23ubuntu3_amd64.deb ... 639s Unpacking g++-13-x86-64-linux-gnu (13.2.0-23ubuntu3) ... 639s Selecting previously unselected package g++-13. 639s Preparing to unpack .../33-g++-13_13.2.0-23ubuntu3_amd64.deb ... 639s Unpacking g++-13 (13.2.0-23ubuntu3) ... 639s Selecting previously unselected package g++-x86-64-linux-gnu. 639s Preparing to unpack .../34-g++-x86-64-linux-gnu_4%3a13.2.0-7ubuntu1_amd64.deb ... 639s Unpacking g++-x86-64-linux-gnu (4:13.2.0-7ubuntu1) ... 639s Selecting previously unselected package g++. 639s Preparing to unpack .../35-g++_4%3a13.2.0-7ubuntu1_amd64.deb ... 639s Unpacking g++ (4:13.2.0-7ubuntu1) ... 639s Selecting previously unselected package build-essential. 639s Preparing to unpack .../36-build-essential_12.10ubuntu1_amd64.deb ... 639s Unpacking build-essential (12.10ubuntu1) ... 639s Selecting previously unselected package libdebhelper-perl. 639s Preparing to unpack .../37-libdebhelper-perl_13.14.1ubuntu5_all.deb ... 639s Unpacking libdebhelper-perl (13.14.1ubuntu5) ... 639s Selecting previously unselected package libtool. 639s Preparing to unpack .../38-libtool_2.4.7-7_all.deb ... 639s Unpacking libtool (2.4.7-7) ... 639s Selecting previously unselected package dh-autoreconf. 639s Preparing to unpack .../39-dh-autoreconf_20_all.deb ... 639s Unpacking dh-autoreconf (20) ... 639s Selecting previously unselected package libarchive-zip-perl. 639s Preparing to unpack .../40-libarchive-zip-perl_1.68-1_all.deb ... 639s Unpacking libarchive-zip-perl (1.68-1) ... 639s Selecting previously unselected package libsub-override-perl. 639s Preparing to unpack .../41-libsub-override-perl_0.10-1_all.deb ... 639s Unpacking libsub-override-perl (0.10-1) ... 639s Selecting previously unselected package libfile-stripnondeterminism-perl. 639s Preparing to unpack .../42-libfile-stripnondeterminism-perl_1.13.1-1_all.deb ... 639s Unpacking libfile-stripnondeterminism-perl (1.13.1-1) ... 639s Selecting previously unselected package dh-strip-nondeterminism. 639s Preparing to unpack .../43-dh-strip-nondeterminism_1.13.1-1_all.deb ... 639s Unpacking dh-strip-nondeterminism (1.13.1-1) ... 639s Selecting previously unselected package libdw1t64:amd64. 639s Preparing to unpack .../44-libdw1t64_0.190-1.1build3_amd64.deb ... 639s Unpacking libdw1t64:amd64 (0.190-1.1build3) ... 639s Selecting previously unselected package debugedit. 639s Preparing to unpack .../45-debugedit_1%3a5.0-5build2_amd64.deb ... 639s Unpacking debugedit (1:5.0-5build2) ... 639s Selecting previously unselected package dwz. 639s Preparing to unpack .../46-dwz_0.15-1build6_amd64.deb ... 639s Unpacking dwz (0.15-1build6) ... 639s Selecting previously unselected package gettext. 639s Preparing to unpack .../47-gettext_0.21-14ubuntu1_amd64.deb ... 639s Unpacking gettext (0.21-14ubuntu1) ... 639s Selecting previously unselected package intltool-debian. 639s Preparing to unpack .../48-intltool-debian_0.35.0+20060710.6_all.deb ... 639s Unpacking intltool-debian (0.35.0+20060710.6) ... 639s Selecting previously unselected package po-debconf. 639s Preparing to unpack .../49-po-debconf_1.0.21+nmu1_all.deb ... 639s Unpacking po-debconf (1.0.21+nmu1) ... 639s Selecting previously unselected package debhelper. 639s Preparing to unpack .../50-debhelper_13.14.1ubuntu5_all.deb ... 639s Unpacking debhelper (13.14.1ubuntu5) ... 639s Selecting previously unselected package dh-apport. 639s Preparing to unpack .../51-dh-apport_2.28.0-0ubuntu1_all.deb ... 639s Unpacking dh-apport (2.28.0-0ubuntu1) ... 639s Selecting previously unselected package golang-1.22-src. 639s Preparing to unpack .../52-golang-1.22-src_1.22.1-1build1_all.deb ... 639s Unpacking golang-1.22-src (1.22.1-1build1) ... 641s Selecting previously unselected package golang-1.22-go. 641s Preparing to unpack .../53-golang-1.22-go_1.22.1-1build1_amd64.deb ... 641s Unpacking golang-1.22-go (1.22.1-1build1) ... 642s Selecting previously unselected package golang-src. 642s Preparing to unpack .../54-golang-src_2%3a1.22~2build1_all.deb ... 642s Unpacking golang-src (2:1.22~2build1) ... 642s Selecting previously unselected package golang-go:amd64. 642s Preparing to unpack .../55-golang-go_2%3a1.22~2build1_amd64.deb ... 642s Unpacking golang-go:amd64 (2:1.22~2build1) ... 642s Selecting previously unselected package dh-golang. 642s Preparing to unpack .../56-dh-golang_1.62_all.deb ... 642s Unpacking dh-golang (1.62) ... 642s Selecting previously unselected package autopkgtest-satdep. 642s Preparing to unpack .../57-1-autopkgtest-satdep.deb ... 642s Unpacking autopkgtest-satdep (0) ... 642s Setting up libarchive-zip-perl (1.68-1) ... 642s Setting up libdebhelper-perl (13.14.1ubuntu5) ... 642s Setting up linux-libc-dev:amd64 (6.8.0-11.11) ... 642s Setting up m4 (1.4.19-4) ... 642s Setting up libgomp1:amd64 (14-20240330-1ubuntu2) ... 642s Setting up dh-apport (2.28.0-0ubuntu1) ... 642s Setting up libdw1t64:amd64 (0.190-1.1build3) ... 642s Setting up autotools-dev (20220109.1) ... 642s Setting up rpcsvc-proto (1.4.2-0ubuntu6) ... 642s Setting up golang-1.22-src (1.22.1-1build1) ... 642s Setting up libquadmath0:amd64 (14-20240330-1ubuntu2) ... 642s Setting up libmpc3:amd64 (1.3.1-1) ... 642s Setting up libatomic1:amd64 (14-20240330-1ubuntu2) ... 642s Setting up autopoint (0.21-14ubuntu1) ... 642s Setting up autoconf (2.71-3) ... 642s Setting up libubsan1:amd64 (14-20240330-1ubuntu2) ... 642s Setting up dwz (0.15-1build6) ... 642s Setting up libhwasan0:amd64 (14-20240330-1ubuntu2) ... 642s Setting up libcrypt-dev:amd64 (1:4.4.36-4) ... 642s Setting up libasan8:amd64 (14-20240330-1ubuntu2) ... 642s Setting up debugedit (1:5.0-5build2) ... 642s Setting up libsub-override-perl (0.10-1) ... 642s Setting up libtsan2:amd64 (14-20240330-1ubuntu2) ... 642s Setting up libisl23:amd64 (0.26-3) ... 642s Setting up libc-dev-bin (2.39-0ubuntu8) ... 642s Setting up golang-src (2:1.22~2build1) ... 642s Setting up libcc1-0:amd64 (14-20240330-1ubuntu2) ... 642s Setting up liblsan0:amd64 (14-20240330-1ubuntu2) ... 642s Setting up libitm1:amd64 (14-20240330-1ubuntu2) ... 642s Setting up automake (1:1.16.5-1.3ubuntu1) ... 642s update-alternatives: using /usr/bin/automake-1.16 to provide /usr/bin/automake (automake) in auto mode 642s Setting up libfile-stripnondeterminism-perl (1.13.1-1) ... 642s Setting up gettext (0.21-14ubuntu1) ... 642s Setting up cpp-13-x86-64-linux-gnu (13.2.0-23ubuntu3) ... 642s Setting up golang-1.22-go (1.22.1-1build1) ... 642s Setting up intltool-debian (0.35.0+20060710.6) ... 642s Setting up dh-strip-nondeterminism (1.13.1-1) ... 642s Setting up libgcc-13-dev:amd64 (13.2.0-23ubuntu3) ... 642s Setting up libc6-dev:amd64 (2.39-0ubuntu8) ... 642s Setting up libstdc++-13-dev:amd64 (13.2.0-23ubuntu3) ... 642s Setting up cpp-x86-64-linux-gnu (4:13.2.0-7ubuntu1) ... 642s Setting up cpp-13 (13.2.0-23ubuntu3) ... 642s Setting up golang-go:amd64 (2:1.22~2build1) ... 642s Setting up gcc-13-x86-64-linux-gnu (13.2.0-23ubuntu3) ... 642s Setting up po-debconf (1.0.21+nmu1) ... 642s Setting up gcc-13 (13.2.0-23ubuntu3) ... 642s Setting up cpp (4:13.2.0-7ubuntu1) ... 642s Setting up g++-13-x86-64-linux-gnu (13.2.0-23ubuntu3) ... 642s Setting up gcc-x86-64-linux-gnu (4:13.2.0-7ubuntu1) ... 642s Setting up libtool (2.4.7-7) ... 642s Setting up gcc (4:13.2.0-7ubuntu1) ... 642s Setting up dh-autoreconf (20) ... 642s Setting up g++-x86-64-linux-gnu (4:13.2.0-7ubuntu1) ... 642s Setting up g++-13 (13.2.0-23ubuntu3) ... 642s Setting up debhelper (13.14.1ubuntu5) ... 642s Setting up g++ (4:13.2.0-7ubuntu1) ... 642s update-alternatives: using /usr/bin/g++ to provide /usr/bin/c++ (c++) in auto mode 642s Setting up build-essential (12.10ubuntu1) ... 642s Setting up dh-golang (1.62) ... 642s Setting up autopkgtest-satdep (0) ... 642s Processing triggers for man-db (2.12.0-3) ... 678s Processing triggers for install-info (7.1-3build2) ... 678s Processing triggers for libc-bin (2.39-0ubuntu8) ... 678s (Reading database ... 89943 files and directories currently installed.) 678s Removing autopkgtest-satdep (0) ... 678s autopkgtest [14:36:01]: test command1: ./debian/tests/test 678s autopkgtest [14:36:01]: test command1: [----------------------- 710s === RUN TestRunSignal 710s === RUN TestRunSignal/Send_SIGINT_exits 710s INFO Starting WSL Pro Service version Dev 710s === RUN TestRunSignal/Send_SIGTERM_exits 710s INFO Starting WSL Pro Service version Dev 710s --- PASS: TestRunSignal (0.20s) 710s --- PASS: TestRunSignal/Send_SIGINT_exits (0.10s) 710s --- PASS: TestRunSignal/Send_SIGTERM_exits (0.10s) 710s === RUN TestRun 710s === PAUSE TestRun 710s === CONT TestRun 710s === RUN TestRun/Run_and_return_error 710s === PAUSE TestRun/Run_and_return_error 710s === RUN TestRun/Run_and_return_usage_error 710s === PAUSE TestRun/Run_and_return_usage_error 710s === RUN TestRun/Run_and_usage_error_only_does_not_fail 710s === PAUSE TestRun/Run_and_usage_error_only_does_not_fail 710s === RUN TestRun/Run_and_exit_successfully 710s === PAUSE TestRun/Run_and_exit_successfully 710s === CONT TestRun/Run_and_return_error 710s === CONT TestRun/Run_and_usage_error_only_does_not_fail 710s INFO Starting WSL Pro Service version Dev 710s INFO Starting WSL Pro Service version Dev 710s === CONT TestRun/Run_and_exit_successfully 710s ERROR context.Background Error requested 710s === CONT TestRun/Run_and_return_usage_error 710s INFO Starting WSL Pro Service version Dev 710s INFO Starting WSL Pro Service version Dev 710s ERROR context.Background Error requested 710s --- PASS: TestRun (0.00s) 710s --- PASS: TestRun/Run_and_usage_error_only_does_not_fail (0.10s) 710s --- PASS: TestRun/Run_and_return_error (0.10s) 710s --- PASS: TestRun/Run_and_exit_successfully (0.10s) 710s --- PASS: TestRun/Run_and_return_usage_error (0.10s) 710s PASS 710s ok github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/cmd/wsl-pro-service 0.409s 710s ? github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/generate/doc [no test files] 710s ? github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/internal/consts [no test files] 721s === RUN TestHelp 721s --- PASS: TestHelp (0.00s) 721s === RUN TestCompletion 721s --- PASS: TestCompletion (0.00s) 721s === RUN TestVersion 721s --- PASS: TestVersion (0.00s) 721s === RUN TestNoUsageError 721s --- PASS: TestNoUsageError (0.00s) 721s === RUN TestUsageError 721s === PAUSE TestUsageError 721s === RUN TestCanQuitWhenExecute 721s === PAUSE TestCanQuitWhenExecute 721s === RUN TestCanQuitTwice 721s === PAUSE TestCanQuitTwice 721s === RUN TestAppCanQuitWithoutExecute 721s === PAUSE TestAppCanQuitWithoutExecute 721s === RUN TestAppRunFailsOnComponentsCreationAndQuit 721s === PAUSE TestAppRunFailsOnComponentsCreationAndQuit 721s === RUN TestAppGetRootCmd 721s === PAUSE TestAppGetRootCmd 721s === RUN TestWithProMock 721s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 721s --- SKIP: TestWithProMock (0.00s) 721s === RUN TestWithWslPathMock 721s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 721s --- SKIP: TestWithWslPathMock (0.00s) 721s === RUN TestWithWslInfoMock 721s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 721s --- SKIP: TestWithWslInfoMock (0.00s) 721s === RUN TestWithCmdExeMock 721s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 721s --- SKIP: TestWithCmdExeMock (0.00s) 721s === CONT TestUsageError 721s === CONT TestAppCanQuitWithoutExecute 721s service_test.go:137: This test is skipped because it is flaky. There is no way to guarantee Quit has been called before run. 721s --- SKIP: TestAppCanQuitWithoutExecute (0.00s) 721s === CONT TestAppGetRootCmd 721s --- PASS: TestUsageError (0.00s) 721s === CONT TestCanQuitTwice 721s --- PASS: TestAppGetRootCmd (0.00s) 721s === CONT TestAppRunFailsOnComponentsCreationAndQuit 721s time="2024-04-05T14:36:33Z" level=debug msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/cmd/wsl-pro-service/service/service.go:67 New.func1() Debug mode is enabled" 721s time="2024-04-05T14:36:33Z" level=debug msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:63 New() Building new daemon" 721s time="2024-04-05T14:36:33Z" level=debug msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/cmd/wsl-pro-service/service/service.go:67 New.func1() Debug mode is enabled" 721s time="2024-04-05T14:36:33Z" level=debug msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:63 New() Building new daemon" 721s time="2024-04-05T14:36:33Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/testutils/mock_agent.go:80 MockWindowsAgent.func1() MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:43085\"" 721s time="2024-04-05T14:36:38Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:256 (*Daemon).Quit() Stopping daemon requested." 721s time="2024-04-05T14:36:38Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:265 (*Daemon).Quit() Waiting for active requests to close." 721s time="2024-04-05T14:36:39Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:256 (*Daemon).Quit() Stopping daemon requested." 721s time="2024-04-05T14:36:39Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:265 (*Daemon).Quit() Waiting for active requests to close." 721s time="2024-04-05T14:36:39Z" level=debug msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:267 (*Daemon).Quit() All connections have now ended." 721s --- PASS: TestAppRunFailsOnComponentsCreationAndQuit (6.10s) 721s === CONT TestCanQuitWhenExecute 721s time="2024-04-05T14:36:39Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/testutils/mock_agent.go:80 MockWindowsAgent.func1() MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:33369\"" 721s time="2024-04-05T14:36:39Z" level=debug msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/cmd/wsl-pro-service/service/service.go:67 New.func1() Debug mode is enabled" 721s time="2024-04-05T14:36:39Z" level=debug msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:63 New() Building new daemon" 721s time="2024-04-05T14:36:40Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/controlstream/session.go:25 newSession() Connecting to control stream at \"127.0.0.1:43085\"" 721s time="2024-04-05T14:36:40Z" level=debug msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/controlstream/controlstream.go:75 (*ControlStream).Connect() Control stream: starting handshake" 721s time="2024-04-05T14:36:40Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/testutils/mock_agent.go:134 (*wslInstanceMockService).Connected() wslInstanceMockService: Received incoming connection" 721s time="2024-04-05T14:36:42Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/testutils/mock_agent.go:148 (*wslInstanceMockService).Connected() wslInstanceMockService: Connection with \"TEST_DISTRO\": received info: wsl_name:\"TEST_DISTRO\" id:\"ubuntu\" version_id:\"22.04\" pretty_name:\"Ubuntu 22.04.1 LTS\" hostname:\"TEST_DISTRO_HOSTNAME\"" 721s time="2024-04-05T14:36:42Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/testutils/mock_agent.go:176 (*wslInstanceMockService).Connected() wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 42501" 721s time="2024-04-05T14:36:42Z" level=debug msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/controlstream/controlstream.go:82 (*ControlStream).Connect() Control stream: completed handshake" 721s time="2024-04-05T14:36:42Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:176 (*Daemon).serveOnce() Connected to control stream" 721s time="2024-04-05T14:36:42Z" level=debug msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/wslinstanceservice/wslinstanceservice.go:44 (*Service).RegisterGRPCService() Registering gRPC WSL instance service" 721s time="2024-04-05T14:36:42Z" level=debug msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:223 (*Daemon).serve() Starting to serve gRPC requests" 721s time="2024-04-05T14:36:42Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:233 (*Daemon).serve() Serving gRPC requests on localhost:42501" 721s time="2024-04-05T14:36:42Z" level=error msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:142 (*Daemon).Serve() Serve error: WSL Pro Service stopped serving: grpc error: grpc: the server has been stopped" 721s time="2024-04-05T14:36:42Z" level=debug msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:267 (*Daemon).Quit() All connections have now ended." 721s time="2024-04-05T14:36:42Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:256 (*Daemon).Quit() Stopping daemon requested." 721s time="2024-04-05T14:36:42Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:265 (*Daemon).Quit() Waiting for active requests to close." 721s time="2024-04-05T14:36:42Z" level=debug msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:267 (*Daemon).Quit() All connections have now ended." 721s time="2024-04-05T14:36:42Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:256 (*Daemon).Quit() Stopping daemon requested." 721s time="2024-04-05T14:36:42Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:265 (*Daemon).Quit() Waiting for active requests to close." 721s time="2024-04-05T14:36:42Z" level=debug msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:267 (*Daemon).Quit() All connections have now ended." 721s --- PASS: TestCanQuitTwice (8.36s) 721s time="2024-04-05T14:36:42Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/testutils/mock_agent.go:89 MockWindowsAgent.func1() MockWindowsAgent: Remove address file returned an error: remove /tmp/TestCanQuitTwice2880466787/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 721s time="2024-04-05T14:36:44Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:256 (*Daemon).Quit() Stopping daemon requested." 721s time="2024-04-05T14:36:44Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:265 (*Daemon).Quit() Waiting for active requests to close." 721s time="2024-04-05T14:36:44Z" level=error msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:142 (*Daemon).Serve() Serve error: could not connect to Windows Agent via the control stream: could not get address: could not read agent port file \"/tmp/TestCanQuitWhenExecute3440973013/001/mnt/d/Users/TestUser/.ubuntupro/.address\": open /tmp/TestCanQuitWhenExecute3440973013/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 721s time="2024-04-05T14:36:44Z" level=debug msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:267 (*Daemon).Quit() All connections have now ended." 721s time="2024-04-05T14:36:44Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:256 (*Daemon).Quit() Stopping daemon requested." 721s time="2024-04-05T14:36:44Z" level=info msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:265 (*Daemon).Quit() Waiting for active requests to close." 721s time="2024-04-05T14:36:44Z" level=debug msg="/tmp/autopkgtest.F7y8MH/build.BX6/src/internal/daemon/daemon.go:267 (*Daemon).Quit() All connections have now ended." 721s --- PASS: TestCanQuitWhenExecute (4.81s) 721s PASS 721s ok github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/cmd/wsl-pro-service/service 10.928s 761s === RUN TestNew 761s === PAUSE TestNew 761s === RUN TestConnect 761s === PAUSE TestConnect 761s === RUN TestSend 761s === PAUSE TestSend 761s === RUN TestReconnection 761s === PAUSE TestReconnection 761s === RUN TestWithProMock 761s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 761s --- SKIP: TestWithProMock (0.00s) 761s === RUN TestWithWslPathMock 761s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 761s --- SKIP: TestWithWslPathMock (0.00s) 761s === RUN TestWithWslInfoMock 761s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 761s --- SKIP: TestWithWslInfoMock (0.00s) 761s === RUN TestWithCmdExeMock 761s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 761s --- SKIP: TestWithCmdExeMock (0.00s) 761s === CONT TestNew 761s === RUN TestNew/Success 761s === PAUSE TestNew/Success 761s === RUN TestNew/Error_when_the_context_is_cancelled 761s === PAUSE TestNew/Error_when_the_context_is_cancelled 761s === RUN TestNew/Error_when_WslPath_returns_error 761s === PAUSE TestNew/Error_when_WslPath_returns_error 761s === CONT TestNew/Success 761s === CONT TestConnect 761s === RUN TestConnect/Success 761s === PAUSE TestConnect/Success 761s === RUN TestConnect/No_connection_because_port_file_does_not_exist 761s === PAUSE TestConnect/No_connection_because_port_file_does_not_exist 761s === RUN TestConnect/No_connection_because_of_port_file_contains_the_wrong_port 761s === PAUSE TestConnect/No_connection_because_of_port_file_contains_the_wrong_port 761s === RUN TestConnect/Error_because_WindowsForwardedLocalhost_returns_error 761s === PAUSE TestConnect/Error_because_WindowsForwardedLocalhost_returns_error 761s === RUN TestConnect/Incomplete_handshake_because_Agent_sends_port_:0 761s === PAUSE TestConnect/Incomplete_handshake_because_Agent_sends_port_:0 761s === RUN TestConnect/No_connection_because_of_unreadable_port_file 761s === PAUSE TestConnect/No_connection_because_of_unreadable_port_file 761s === RUN TestConnect/No_connection_because_of_empty_port_file 761s === PAUSE TestConnect/No_connection_because_of_empty_port_file 761s === RUN TestConnect/No_connection_because_of_port_file_with_invalid_contents 761s === PAUSE TestConnect/No_connection_because_of_port_file_with_invalid_contents 761s === RUN TestConnect/Incomplete_handshake_because_Agent_never_receives 761s === PAUSE TestConnect/Incomplete_handshake_because_Agent_never_receives 761s === RUN TestConnect/Incomplete_handshake_because_Agent_never_sends_a_port 761s === PAUSE TestConnect/Incomplete_handshake_because_Agent_never_sends_a_port 761s === RUN TestConnect/Error_when_system_cannot_retrieve_the_WSL_distro_name 761s === PAUSE TestConnect/Error_when_system_cannot_retrieve_the_WSL_distro_name 761s === CONT TestConnect/Success 761s time="2024-04-05T14:36:35Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:41745\"" 761s === CONT TestNew/Error_when_WslPath_returns_error 761s time="2024-04-05T14:36:40Z" level=info msg="Connecting to control stream at \"127.0.0.1:41745\"" 761s time="2024-04-05T14:36:40Z" level=debug msg="Control stream: starting handshake" 761s time="2024-04-05T14:36:40Z" level=info msg="wslInstanceMockService: Received incoming connection" 761s === CONT TestNew/Error_when_the_context_is_cancelled 761s --- PASS: TestNew (0.00s) 761s --- PASS: TestNew/Success (3.71s) 761s --- PASS: TestNew/Error_when_WslPath_returns_error (3.60s) 761s --- PASS: TestNew/Error_when_the_context_is_cancelled (0.00s) 761s === CONT TestConnect/No_connection_because_of_port_file_with_invalid_contents 761s time="2024-04-05T14:36:42Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:44881\"" 761s time="2024-04-05T14:36:42Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": received info: wsl_name:\"TEST_DISTRO\" id:\"ubuntu\" version_id:\"22.04\" pretty_name:\"Ubuntu 22.04.1 LTS\" hostname:\"TEST_DISTRO_HOSTNAME\"" 761s time="2024-04-05T14:36:42Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 43775" 761s time="2024-04-05T14:36:42Z" level=debug msg="Control stream: completed handshake" 761s time="2024-04-05T14:36:43Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestConnectSuccess674084018/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 761s === CONT TestReconnection 761s === RUN TestReconnection/Success_connecting_after_failing_to_connect 761s === PAUSE TestReconnection/Success_connecting_after_failing_to_connect 761s === RUN TestReconnection/Success_connecting_after_previous_connection_dropped 761s === PAUSE TestReconnection/Success_connecting_after_previous_connection_dropped 761s === CONT TestSend 761s time="2024-04-05T14:36:43Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:42553\"" 761s === CONT TestConnect/Error_when_system_cannot_retrieve_the_WSL_distro_name 761s time="2024-04-05T14:36:45Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestConnectNo_connection_because_of_port_file_with_invalid_contents2048846509/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 761s time="2024-04-05T14:36:45Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:39913\"" 761s time="2024-04-05T14:36:48Z" level=info msg="Connecting to control stream at \"127.0.0.1:42553\"" 761s time="2024-04-05T14:36:48Z" level=debug msg="Control stream: starting handshake" 761s time="2024-04-05T14:36:48Z" level=info msg="wslInstanceMockService: Received incoming connection" 761s time="2024-04-05T14:36:49Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": received info: wsl_name:\"TEST_DISTRO\" id:\"ubuntu\" version_id:\"22.04\" pretty_name:\"Ubuntu 22.04.1 LTS\" hostname:\"TEST_DISTRO_HOSTNAME\"" 761s time="2024-04-05T14:36:49Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 33017" 761s time="2024-04-05T14:36:49Z" level=debug msg="Control stream: completed handshake" 761s time="2024-04-05T14:36:52Z" level=warning msg="Controlstream: assigning arbitrary connection ID because of error: could not obtain WSL distro name: could not get distro root path: exit status 1. Stdout: " 761s time="2024-04-05T14:36:52Z" level=info msg="Connecting to control stream at \"127.0.0.1:39913\"" 761s time="2024-04-05T14:36:52Z" level=debug msg="Control stream: starting handshake" 761s time="2024-04-05T14:36:52Z" level=info msg="wslInstanceMockService: Received incoming connection" 761s time="2024-04-05T14:36:53Z" level=warning msg="wslInstanceMockService: dropped connection: new connection: did not receive info from WSL distro: rpc error: code = Canceled desc = context canceled" 761s === CONT TestConnect/Incomplete_handshake_because_Agent_never_sends_a_port 761s time="2024-04-05T14:36:53Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:38941\"" 761s time="2024-04-05T14:36:54Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": connected back via reserved port" 761s time="2024-04-05T14:36:54Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": received info: wsl_name:\"TEST_DISTRO\" id:\"ubuntu\" version_id:\"22.04\" pretty_name:\"Ubuntu 22.04.1 LTS\" hostname:\"TEST_DISTRO_HOSTNAME\"" 761s --- PASS: TestSend (12.25s) 761s === CONT TestConnect/Incomplete_handshake_because_Agent_never_receives 761s time="2024-04-05T14:36:55Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\" ended: rpc error: code = Canceled desc = context canceled" 761s time="2024-04-05T14:36:55Z" level=info msg="wslInstanceMockService: dropped connection" 761s time="2024-04-05T14:36:55Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestSend445622523/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 761s time="2024-04-05T14:36:55Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:37581\"" 761s time="2024-04-05T14:36:58Z" level=info msg="Connecting to control stream at \"127.0.0.1:38941\"" 761s time="2024-04-05T14:36:58Z" level=debug msg="Control stream: starting handshake" 761s time="2024-04-05T14:36:58Z" level=info msg="wslInstanceMockService: Received incoming connection" 761s time="2024-04-05T14:37:00Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": received info: wsl_name:\"TEST_DISTRO\" id:\"ubuntu\" version_id:\"22.04\" pretty_name:\"Ubuntu 22.04.1 LTS\" hostname:\"TEST_DISTRO_HOSTNAME\"" 761s time="2024-04-05T14:37:00Z" level=info msg="connection with \"TEST_DISTRO\": mock error: dropping stream before sending port" 761s time="2024-04-05T14:37:00Z" level=info msg="wslInstanceMockService: dropped connection" 761s === CONT TestConnect/Incomplete_handshake_because_Agent_sends_port_:0 761s time="2024-04-05T14:37:00Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestConnectIncomplete_handshake_because_Agent_never_sends_a_port360037874/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 761s time="2024-04-05T14:37:00Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:44403\"" 761s time="2024-04-05T14:37:01Z" level=info msg="Connecting to control stream at \"127.0.0.1:37581\"" 761s time="2024-04-05T14:37:01Z" level=debug msg="Control stream: starting handshake" 761s time="2024-04-05T14:37:01Z" level=info msg="wslInstanceMockService: Received incoming connection" 761s time="2024-04-05T14:37:01Z" level=info msg="wslInstanceMockService: mock error: dropping stream before first Recv" 761s time="2024-04-05T14:37:01Z" level=info msg="wslInstanceMockService: dropped connection" 761s === CONT TestConnect/No_connection_because_of_empty_port_file 761s time="2024-04-05T14:37:02Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:34671\"" 761s time="2024-04-05T14:37:05Z" level=info msg="Connecting to control stream at \"127.0.0.1:44403\"" 761s time="2024-04-05T14:37:05Z" level=debug msg="Control stream: starting handshake" 761s time="2024-04-05T14:37:05Z" level=info msg="wslInstanceMockService: Received incoming connection" 761s time="2024-04-05T14:37:06Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": received info: wsl_name:\"TEST_DISTRO\" id:\"ubuntu\" version_id:\"22.04\" pretty_name:\"Ubuntu 22.04.1 LTS\" hostname:\"TEST_DISTRO_HOSTNAME\"" 761s time="2024-04-05T14:37:06Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Sending bad port 0" 761s === CONT TestConnect/No_connection_because_of_unreadable_port_file 761s time="2024-04-05T14:37:06Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:36087\"" 761s time="2024-04-05T14:37:07Z" level=warning msg="wslInstanceMockService: dropped connection: wslInstanceMockService: could not dial \"TEST_DISTRO\": dial tcp4 127.0.0.1:43775: connect: connection refused" 761s === CONT TestConnect/No_connection_because_of_port_file_contains_the_wrong_port 761s time="2024-04-05T14:37:08Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:35265\"" 761s === CONT TestConnect/Error_because_WindowsForwardedLocalhost_returns_error 761s time="2024-04-05T14:37:11Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:38303\"" 761s time="2024-04-05T14:37:11Z" level=info msg="Connecting to control stream at \"127.0.0.1:46627\"" 761s === CONT TestConnect/No_connection_because_port_file_does_not_exist 761s time="2024-04-05T14:37:11Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestConnectNo_connection_because_of_port_file_contains_the_wrong_port3880200017/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 761s time="2024-04-05T14:37:11Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:36089\"" 761s === CONT TestReconnection/Success_connecting_after_failing_to_connect 761s --- PASS: TestConnect (0.00s) 761s --- PASS: TestConnect/Success (8.44s) 761s --- PASS: TestConnect/No_connection_because_of_port_file_with_invalid_contents (3.44s) 761s --- PASS: TestConnect/Error_when_system_cannot_retrieve_the_WSL_distro_name (8.15s) 761s --- PASS: TestConnect/Incomplete_handshake_because_Agent_never_sends_a_port (6.54s) 761s --- PASS: TestConnect/Incomplete_handshake_because_Agent_never_receives (7.25s) 761s --- PASS: TestConnect/Incomplete_handshake_because_Agent_sends_port_:0 (6.31s) 761s --- PASS: TestConnect/No_connection_because_of_empty_port_file (5.02s) 761s --- PASS: TestConnect/No_connection_because_of_unreadable_port_file (4.54s) 761s --- PASS: TestConnect/No_connection_because_of_port_file_contains_the_wrong_port (3.96s) 761s --- PASS: TestConnect/Error_because_WindowsForwardedLocalhost_returns_error (3.61s) 761s --- PASS: TestConnect/No_connection_because_port_file_does_not_exist (3.73s) 761s time="2024-04-05T14:37:15Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestConnectNo_connection_because_port_file_does_not_exist4107618261/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 761s === CONT TestReconnection/Success_connecting_after_previous_connection_dropped 761s time="2024-04-05T14:37:18Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:45931\"" 761s time="2024-04-05T14:37:19Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:46703\"" 761s time="2024-04-05T14:37:19Z" level=info msg="Connecting to control stream at \"127.0.0.1:45931\"" 761s time="2024-04-05T14:37:19Z" level=debug msg="Control stream: starting handshake" 761s time="2024-04-05T14:37:19Z" level=info msg="wslInstanceMockService: Received incoming connection" 761s time="2024-04-05T14:37:20Z" level=info msg="Connecting to control stream at \"127.0.0.1:46703\"" 761s time="2024-04-05T14:37:20Z" level=debug msg="Control stream: starting handshake" 761s time="2024-04-05T14:37:20Z" level=info msg="wslInstanceMockService: Received incoming connection" 761s time="2024-04-05T14:37:20Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": received info: wsl_name:\"TEST_DISTRO\" id:\"ubuntu\" version_id:\"22.04\" pretty_name:\"Ubuntu 22.04.1 LTS\" hostname:\"TEST_DISTRO_HOSTNAME\"" 761s time="2024-04-05T14:37:20Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 36787" 761s time="2024-04-05T14:37:20Z" level=debug msg="Control stream: completed handshake" 761s time="2024-04-05T14:37:21Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:40757\"" 761s time="2024-04-05T14:37:22Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": received info: wsl_name:\"TEST_DISTRO\" id:\"ubuntu\" version_id:\"22.04\" pretty_name:\"Ubuntu 22.04.1 LTS\" hostname:\"TEST_DISTRO_HOSTNAME\"" 761s time="2024-04-05T14:37:22Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 32885" 761s time="2024-04-05T14:37:22Z" level=debug msg="Control stream: completed handshake" 761s time="2024-04-05T14:37:22Z" level=info msg="Connecting to control stream at \"127.0.0.1:40757\"" 761s time="2024-04-05T14:37:22Z" level=debug msg="Control stream: starting handshake" 761s time="2024-04-05T14:37:22Z" level=info msg="wslInstanceMockService: Received incoming connection" 761s time="2024-04-05T14:37:24Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": received info: wsl_name:\"TEST_DISTRO\" id:\"ubuntu\" version_id:\"22.04\" pretty_name:\"Ubuntu 22.04.1 LTS\" hostname:\"TEST_DISTRO_HOSTNAME\"" 761s time="2024-04-05T14:37:24Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 37953" 761s time="2024-04-05T14:37:24Z" level=debug msg="Control stream: completed handshake" 761s --- PASS: TestReconnection (0.00s) 761s --- PASS: TestReconnection/Success_connecting_after_failing_to_connect (7.47s) 761s --- PASS: TestReconnection/Success_connecting_after_previous_connection_dropped (8.31s) 761s PASS 761s ok github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/internal/controlstream 48.978s 793s ? github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/internal/testutils [no test files] 917s === RUN TestNew 917s === PAUSE TestNew 917s === RUN TestServe 917s === PAUSE TestServe 917s === RUN TestServeAndQuit 917s === PAUSE TestServeAndQuit 917s === RUN TestReconnection 917s === PAUSE TestReconnection 917s === RUN TestWithProMock 917s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 917s --- SKIP: TestWithProMock (0.00s) 917s === RUN TestWithWslPathMock 917s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 917s --- SKIP: TestWithWslPathMock (0.00s) 917s === RUN TestWithWslInfoMock 917s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 917s --- SKIP: TestWithWslInfoMock (0.00s) 917s === RUN TestWithCmdExeMock 917s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 917s --- SKIP: TestWithCmdExeMock (0.00s) 917s === CONT TestNew 917s === RUN TestNew/Success 917s === PAUSE TestNew/Success 917s === RUN TestNew/Error_when_WslPath_returns_error 917s === PAUSE TestNew/Error_when_WslPath_returns_error 917s === CONT TestNew/Success 917s === CONT TestServeAndQuit 917s === RUN TestServeAndQuit/Error_due_to_quitting_before_serving 917s === PAUSE TestServeAndQuit/Error_due_to_quitting_before_serving 917s === RUN TestServeAndQuit/Success_with_graceful_quit 917s === PAUSE TestServeAndQuit/Success_with_graceful_quit 917s === RUN TestServeAndQuit/Success_with_forceful_quit 917s === PAUSE TestServeAndQuit/Success_with_forceful_quit 917s === RUN TestServeAndQuit/Success_with_double_quit 917s === PAUSE TestServeAndQuit/Success_with_double_quit 917s === CONT TestServeAndQuit/Error_due_to_quitting_before_serving 917s time="2024-04-05T14:36:46Z" level=debug msg="Building new daemon" 917s time="2024-04-05T14:36:46Z" level=debug msg="Building new daemon" 917s time="2024-04-05T14:36:46Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:44263\"" 917s time="2024-04-05T14:36:50Z" level=debug msg="Updated systemd status to \"Stopped\"" 917s === CONT TestReconnection 917s === RUN TestReconnection/Success_connecting_after_failing_to_connect 917s === PAUSE TestReconnection/Success_connecting_after_failing_to_connect 917s === RUN TestReconnection/Success_connecting_after_previous_connection_dropped 917s === PAUSE TestReconnection/Success_connecting_after_previous_connection_dropped 917s === CONT TestServeAndQuit/Success_with_double_quit 917s time="2024-04-05T14:36:50Z" level=debug msg="Building new daemon" 917s time="2024-04-05T14:36:50Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:44269\"" 917s === CONT TestServeAndQuit/Success_with_forceful_quit 917s time="2024-04-05T14:36:50Z" level=debug msg="Building new daemon" 917s time="2024-04-05T14:36:50Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:40847\"" 917s time="2024-04-05T14:36:52Z" level=debug msg="Ready state sent to systemd" 917s time="2024-04-05T14:36:53Z" level=debug msg="Ready state sent to systemd" 917s time="2024-04-05T14:36:54Z" level=info msg="Connecting to control stream at \"127.0.0.1:44269\"" 917s time="2024-04-05T14:36:54Z" level=debug msg="Control stream: starting handshake" 917s time="2024-04-05T14:36:54Z" level=info msg="wslInstanceMockService: Received incoming connection" 917s time="2024-04-05T14:36:54Z" level=info msg="Connecting to control stream at \"127.0.0.1:40847\"" 917s time="2024-04-05T14:36:54Z" level=debug msg="Control stream: starting handshake" 917s time="2024-04-05T14:36:54Z" level=info msg="wslInstanceMockService: Received incoming connection" 917s time="2024-04-05T14:36:55Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": received info: wsl_name:\"TEST_DISTRO\" id:\"ubuntu\" version_id:\"22.04\" pretty_name:\"Ubuntu 22.04.1 LTS\" hostname:\"TEST_DISTRO_HOSTNAME\"" 917s time="2024-04-05T14:36:55Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 34589" 917s time="2024-04-05T14:36:55Z" level=debug msg="Control stream: completed handshake" 917s time="2024-04-05T14:36:55Z" level=info msg="Connected to control stream" 917s time="2024-04-05T14:36:55Z" level=debug msg="Starting to serve gRPC requests" 917s time="2024-04-05T14:36:55Z" level=info msg="Serving gRPC requests on localhost:34589" 917s time="2024-04-05T14:36:55Z" level=debug msg="Updated systemd status to \"Serving\"" 917s time="2024-04-05T14:36:55Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": received info: wsl_name:\"TEST_DISTRO\" id:\"ubuntu\" version_id:\"22.04\" pretty_name:\"Ubuntu 22.04.1 LTS\" hostname:\"TEST_DISTRO_HOSTNAME\"" 917s time="2024-04-05T14:36:55Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 34147" 917s time="2024-04-05T14:36:55Z" level=debug msg="Control stream: completed handshake" 917s time="2024-04-05T14:36:55Z" level=info msg="Connected to control stream" 917s time="2024-04-05T14:36:55Z" level=debug msg="Starting to serve gRPC requests" 917s time="2024-04-05T14:36:55Z" level=info msg="Serving gRPC requests on localhost:34147" 917s time="2024-04-05T14:36:55Z" level=debug msg="Updated systemd status to \"Serving\"" 917s time="2024-04-05T14:36:56Z" level=info msg="Stopping daemon requested." 917s time="2024-04-05T14:36:56Z" level=debug msg="Updated systemd status to \"Stopped\"" 917s === CONT TestServeAndQuit/Success_with_graceful_quit 917s time="2024-04-05T14:36:56Z" level=debug msg="Building new daemon" 917s time="2024-04-05T14:36:56Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestServeAndQuitSuccess_with_forceful_quit1944002735/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 917s time="2024-04-05T14:36:56Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:39527\"" 917s time="2024-04-05T14:36:56Z" level=info msg="Stopping daemon requested." 917s time="2024-04-05T14:36:56Z" level=info msg="Waiting for active requests to close." 917s time="2024-04-05T14:36:56Z" level=debug msg="Updated systemd status to \"Stopped\"" 917s time="2024-04-05T14:36:56Z" level=debug msg="All connections have now ended." 917s time="2024-04-05T14:36:56Z" level=info msg="Stopping daemon requested." 917s time="2024-04-05T14:36:56Z" level=info msg="Waiting for active requests to close." 917s time="2024-04-05T14:36:56Z" level=debug msg="All connections have now ended." 917s === CONT TestServe 917s === RUN TestServe/Error_because_of_notifier_returning_error 917s === PAUSE TestServe/Error_because_of_notifier_returning_error 917s === RUN TestServe/Error_because_WindowsHostAddress_returns_error 917s === PAUSE TestServe/Error_because_WindowsHostAddress_returns_error 917s === RUN TestServe/Error_because_of_context_cancelled 917s === PAUSE TestServe/Error_because_of_context_cancelled 917s === RUN TestServe/Success 917s === PAUSE TestServe/Success 917s === RUN TestServe/Success_with_systemd_notifier_returning_true 917s === PAUSE TestServe/Success_with_systemd_notifier_returning_true 917s === RUN TestServe/No_connection_because_port_file_does_not_exist 917s === PAUSE TestServe/No_connection_because_port_file_does_not_exist 917s === RUN TestServe/No_connection_because_of_faulty_agent 917s === PAUSE TestServe/No_connection_because_of_faulty_agent 917s time="2024-04-05T14:36:56Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestServeAndQuitSuccess_with_double_quit407292/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 917s === CONT TestNew/Error_when_WslPath_returns_error 917s time="2024-04-05T14:36:56Z" level=debug msg="Building new daemon" 917s --- PASS: TestNew (0.00s) 917s --- PASS: TestNew/Success (3.87s) 917s --- PASS: TestNew/Error_when_WslPath_returns_error (3.48s) 917s === CONT TestReconnection/Success_connecting_after_failing_to_connect 917s time="2024-04-05T14:36:59Z" level=debug msg="Building new daemon" 917s time="2024-04-05T14:36:59Z" level=debug msg="Ready state sent to systemd" 917s time="2024-04-05T14:37:01Z" level=info msg="Connecting to control stream at \"127.0.0.1:39527\"" 917s time="2024-04-05T14:37:01Z" level=debug msg="Control stream: starting handshake" 917s time="2024-04-05T14:37:01Z" level=info msg="wslInstanceMockService: Received incoming connection" 917s time="2024-04-05T14:37:03Z" level=debug msg="Ready state sent to systemd" 917s time="2024-04-05T14:37:03Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": received info: wsl_name:\"TEST_DISTRO\" id:\"ubuntu\" version_id:\"22.04\" pretty_name:\"Ubuntu 22.04.1 LTS\" hostname:\"TEST_DISTRO_HOSTNAME\"" 917s time="2024-04-05T14:37:03Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 40205" 917s time="2024-04-05T14:37:03Z" level=debug msg="Control stream: completed handshake" 917s time="2024-04-05T14:37:03Z" level=info msg="Connected to control stream" 917s time="2024-04-05T14:37:03Z" level=debug msg="Starting to serve gRPC requests" 917s time="2024-04-05T14:37:03Z" level=info msg="Serving gRPC requests on localhost:40205" 917s time="2024-04-05T14:37:03Z" level=debug msg="Updated systemd status to \"Serving\"" 917s time="2024-04-05T14:37:03Z" level=info msg="Stopping daemon requested." 917s time="2024-04-05T14:37:03Z" level=info msg="Waiting for active requests to close." 917s time="2024-04-05T14:37:03Z" level=debug msg="Updated systemd status to \"Stopped\"" 917s time="2024-04-05T14:37:03Z" level=debug msg="All connections have now ended." 917s --- PASS: TestServeAndQuit (0.00s) 917s --- PASS: TestServeAndQuit/Error_due_to_quitting_before_serving (3.82s) 917s --- PASS: TestServeAndQuit/Success_with_forceful_quit (6.02s) 917s --- PASS: TestServeAndQuit/Success_with_double_quit (6.12s) 917s --- PASS: TestServeAndQuit/Success_with_graceful_quit (7.79s) 917s === CONT TestReconnection/Success_connecting_after_previous_connection_dropped 917s time="2024-04-05T14:37:03Z" level=debug msg="Building new daemon" 917s time="2024-04-05T14:37:04Z" level=error msg="Serve error: could not connect to Windows Agent via the control stream: could not get address: could not read agent port file \"/tmp/TestReconnectionSuccess_connecting_after_failing_to_connect2144357754/001/mnt/d/Users/TestUser/.ubuntupro/.address\": open /tmp/TestReconnectionSuccess_connecting_after_failing_to_connect2144357754/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 917s time="2024-04-05T14:37:04Z" level=debug msg="Updated systemd status to \"Not serving: waiting to retry\"" 917s time="2024-04-05T14:37:04Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:42699\"" 917s time="2024-04-05T14:37:06Z" level=info msg="Retrying connection to control stream" 917s time="2024-04-05T14:37:06Z" level=debug msg="Updated systemd status to \"Not serving: retrying\"" 917s time="2024-04-05T14:37:06Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:38041\"" 917s time="2024-04-05T14:37:06Z" level=debug msg="Ready state sent to systemd" 917s time="2024-04-05T14:37:08Z" level=info msg="Connecting to control stream at \"127.0.0.1:38041\"" 917s time="2024-04-05T14:37:08Z" level=debug msg="Control stream: starting handshake" 917s time="2024-04-05T14:37:08Z" level=info msg="wslInstanceMockService: Received incoming connection" 917s time="2024-04-05T14:37:08Z" level=info msg="Connecting to control stream at \"127.0.0.1:42699\"" 917s time="2024-04-05T14:37:08Z" level=debug msg="Control stream: starting handshake" 917s time="2024-04-05T14:37:08Z" level=info msg="wslInstanceMockService: Received incoming connection" 917s time="2024-04-05T14:37:10Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": received info: wsl_name:\"TEST_DISTRO\" id:\"ubuntu\" version_id:\"22.04\" pretty_name:\"Ubuntu 22.04.1 LTS\" hostname:\"TEST_DISTRO_HOSTNAME\"" 917s time="2024-04-05T14:37:10Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 33151" 917s time="2024-04-05T14:37:10Z" level=debug msg="Control stream: completed handshake" 917s time="2024-04-05T14:37:10Z" level=info msg="Connected to control stream" 917s time="2024-04-05T14:37:10Z" level=debug msg="Starting to serve gRPC requests" 917s time="2024-04-05T14:37:10Z" level=info msg="Serving gRPC requests on localhost:33151" 917s time="2024-04-05T14:37:10Z" level=debug msg="Updated systemd status to \"Serving\"" 917s time="2024-04-05T14:37:10Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": received info: wsl_name:\"TEST_DISTRO\" id:\"ubuntu\" version_id:\"22.04\" pretty_name:\"Ubuntu 22.04.1 LTS\" hostname:\"TEST_DISTRO_HOSTNAME\"" 917s time="2024-04-05T14:37:10Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 33549" 917s time="2024-04-05T14:37:10Z" level=debug msg="Control stream: completed handshake" 917s time="2024-04-05T14:37:10Z" level=info msg="Connected to control stream" 917s time="2024-04-05T14:37:10Z" level=debug msg="Starting to serve gRPC requests" 917s time="2024-04-05T14:37:10Z" level=info msg="Serving gRPC requests on localhost:33549" 917s time="2024-04-05T14:37:10Z" level=debug msg="Updated systemd status to \"Serving\"" 917s time="2024-04-05T14:37:10Z" level=error msg="Serve error: lost connection to Windows Agent" 917s time="2024-04-05T14:37:10Z" level=debug msg="Updated systemd status to \"Not serving: waiting to retry\"" 917s time="2024-04-05T14:37:11Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:37173\"" 917s time="2024-04-05T14:37:12Z" level=info msg="Retrying connection to control stream" 917s time="2024-04-05T14:37:12Z" level=debug msg="Updated systemd status to \"Not serving: retrying\"" 917s time="2024-04-05T14:37:14Z" level=info msg="Connecting to control stream at \"127.0.0.1:37173\"" 917s time="2024-04-05T14:37:14Z" level=debug msg="Control stream: starting handshake" 917s time="2024-04-05T14:37:14Z" level=info msg="wslInstanceMockService: Received incoming connection" 917s time="2024-04-05T14:37:15Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": connected back via reserved port" 917s time="2024-04-05T14:37:15Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": received info: wsl_name:\"TEST_DISTRO\" id:\"ubuntu\" version_id:\"22.04\" pretty_name:\"Ubuntu 22.04.1 LTS\" hostname:\"TEST_DISTRO_HOSTNAME\"" 917s time="2024-04-05T14:37:15Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 42321" 917s time="2024-04-05T14:37:15Z" level=debug msg="Control stream: completed handshake" 917s time="2024-04-05T14:37:15Z" level=info msg="Connected to control stream" 917s time="2024-04-05T14:37:15Z" level=debug msg="Starting to serve gRPC requests" 917s time="2024-04-05T14:37:15Z" level=info msg="Serving gRPC requests on localhost:42321" 917s time="2024-04-05T14:37:15Z" level=debug msg="Updated systemd status to \"Serving\"" 917s time="2024-04-05T14:37:15Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\" ended: rpc error: code = Canceled desc = context canceled" 917s time="2024-04-05T14:37:15Z" level=info msg="wslInstanceMockService: dropped connection" 917s time="2024-04-05T14:37:15Z" level=info msg="Stopping daemon requested." 917s time="2024-04-05T14:37:15Z" level=error msg="Serve error: lost connection to Windows Agent" 917s time="2024-04-05T14:37:15Z" level=debug msg="Updated systemd status to \"Not serving: waiting to retry\"" 917s time="2024-04-05T14:37:15Z" level=debug msg="Updated systemd status to \"Stopped\"" 917s === CONT TestServe/Error_because_of_notifier_returning_error 917s time="2024-04-05T14:37:15Z" level=debug msg="Building new daemon" 917s time="2024-04-05T14:37:15Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:38833\"" 917s time="2024-04-05T14:37:18Z" level=warning msg="Could not change systemd status: couldn't update status to systemd: mock error" 917s === CONT TestServe/Success_with_systemd_notifier_returning_true 917s time="2024-04-05T14:37:18Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:46293\"" 917s time="2024-04-05T14:37:18Z" level=debug msg="Building new daemon" 917s time="2024-04-05T14:37:20Z" level=warning msg="wslInstanceMockService: dropped connection: wslInstanceMockService: could not dial \"TEST_DISTRO\": dial tcp4 127.0.0.1:34589: connect: connection refused" 917s time="2024-04-05T14:37:20Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": connected back via reserved port" 917s time="2024-04-05T14:37:20Z" level=warning msg="wslInstanceMockService: dropped connection: wslInstanceMockService: could not dial \"TEST_DISTRO\": dial tcp4 127.0.0.1:34147: connect: connection refused" 917s time="2024-04-05T14:37:21Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\" ended: rpc error: code = Canceled desc = context canceled" 917s time="2024-04-05T14:37:21Z" level=info msg="wslInstanceMockService: dropped connection" 917s time="2024-04-05T14:37:21Z" level=info msg="Stopping daemon requested." 917s time="2024-04-05T14:37:21Z" level=error msg="Serve error: lost connection to Windows Agent" 917s time="2024-04-05T14:37:21Z" level=debug msg="Updated systemd status to \"Not serving: waiting to retry\"" 917s time="2024-04-05T14:37:21Z" level=debug msg="Updated systemd status to \"Stopped\"" 917s --- PASS: TestReconnection (0.00s) 917s --- PASS: TestReconnection/Success_connecting_after_failing_to_connect (16.36s) 917s --- PASS: TestReconnection/Success_connecting_after_previous_connection_dropped (17.23s) 917s === CONT TestServe/No_connection_because_of_faulty_agent 917s time="2024-04-05T14:37:21Z" level=debug msg="Building new daemon" 917s time="2024-04-05T14:37:21Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:45975\"" 917s time="2024-04-05T14:37:21Z" level=debug msg="Ready state sent to systemd" 917s time="2024-04-05T14:37:23Z" level=info msg="Connecting to control stream at \"127.0.0.1:46293\"" 917s time="2024-04-05T14:37:23Z" level=debug msg="Control stream: starting handshake" 917s time="2024-04-05T14:37:23Z" level=info msg="wslInstanceMockService: Received incoming connection" 917s time="2024-04-05T14:37:24Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": received info: wsl_name:\"TEST_DISTRO\" id:\"ubuntu\" version_id:\"22.04\" pretty_name:\"Ubuntu 22.04.1 LTS\" hostname:\"TEST_DISTRO_HOSTNAME\"" 917s time="2024-04-05T14:37:24Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 46693" 917s time="2024-04-05T14:37:24Z" level=debug msg="Control stream: completed handshake" 917s time="2024-04-05T14:37:24Z" level=info msg="Connected to control stream" 917s time="2024-04-05T14:37:24Z" level=debug msg="Starting to serve gRPC requests" 917s time="2024-04-05T14:37:24Z" level=info msg="Serving gRPC requests on localhost:46693" 917s time="2024-04-05T14:37:24Z" level=debug msg="Updated systemd status to \"Serving\"" 917s time="2024-04-05T14:37:25Z" level=info msg="Connecting to control stream at \"127.0.0.1:45975\"" 917s time="2024-04-05T14:37:25Z" level=debug msg="Control stream: starting handshake" 917s time="2024-04-05T14:37:25Z" level=info msg="wslInstanceMockService: Received incoming connection" 917s time="2024-04-05T14:37:25Z" level=info msg="wslInstanceMockService: mock error: dropping stream before first Recv" 917s time="2024-04-05T14:37:25Z" level=info msg="wslInstanceMockService: dropped connection" 917s time="2024-04-05T14:37:26Z" level=error msg="Serve error: could not connect to Windows Agent via the control stream: could not complete handshake: could not send system info: EOF" 917s time="2024-04-05T14:37:28Z" level=info msg="Stopping daemon requested." 917s time="2024-04-05T14:37:28Z" level=info msg="Retrying connection to control stream" 917s time="2024-04-05T14:37:28Z" level=warning msg="wslInstanceMockService: dropped connection: wslInstanceMockService: could not dial \"TEST_DISTRO\": dial tcp4 127.0.0.1:40205: connect: connection refused" 917s time="2024-04-05T14:37:29Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": connected back via reserved port" 917s time="2024-04-05T14:37:30Z" level=info msg="Connecting to control stream at \"127.0.0.1:45975\"" 917s time="2024-04-05T14:37:30Z" level=debug msg="Control stream: starting handshake" 917s time="2024-04-05T14:37:30Z" level=info msg="wslInstanceMockService: Received incoming connection" 917s time="2024-04-05T14:37:30Z" level=info msg="wslInstanceMockService: mock error: dropping stream before first Recv" 917s time="2024-04-05T14:37:30Z" level=info msg="wslInstanceMockService: dropped connection" 917s time="2024-04-05T14:37:31Z" level=info msg="Stopping daemon requested." 917s time="2024-04-05T14:37:31Z" level=error msg="Serve error: could not connect to Windows Agent via the control stream: could not complete handshake: could not send system info: EOF" 917s time="2024-04-05T14:37:34Z" level=info msg="Stopping daemon requested." 917s === CONT TestServe/No_connection_because_port_file_does_not_exist 917s time="2024-04-05T14:37:34Z" level=debug msg="Building new daemon" 917s time="2024-04-05T14:37:34Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestServeNo_connection_because_of_faulty_agent3410179486/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 917s time="2024-04-05T14:37:34Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:41335\"" 917s time="2024-04-05T14:37:35Z" level=warning msg="wslInstanceMockService: dropped connection: wslInstanceMockService: could not dial \"TEST_DISTRO\": dial tcp4 127.0.0.1:33549: connect: connection refused" 917s time="2024-04-05T14:37:38Z" level=error msg="Serve error: could not connect to Windows Agent via the control stream: could not get address: could not read agent port file \"/tmp/TestServeNo_connection_because_port_file_does_not_exist368804262/001/mnt/d/Users/TestUser/.ubuntupro/.address\": open /tmp/TestServeNo_connection_because_port_file_does_not_exist368804262/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 917s time="2024-04-05T14:37:40Z" level=info msg="Retrying connection to control stream" 917s time="2024-04-05T14:37:42Z" level=error msg="Serve error: could not connect to Windows Agent via the control stream: could not get address: could not read agent port file \"/tmp/TestServeNo_connection_because_port_file_does_not_exist368804262/001/mnt/d/Users/TestUser/.ubuntupro/.address\": open /tmp/TestServeNo_connection_because_port_file_does_not_exist368804262/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 917s time="2024-04-05T14:37:46Z" level=info msg="Retrying connection to control stream" 917s time="2024-04-05T14:37:47Z" level=info msg="Stopping daemon requested." 917s time="2024-04-05T14:37:47Z" level=error msg="Serve error: could not connect to Windows Agent via the control stream: could not get address: could not read agent port file \"/tmp/TestServeNo_connection_because_port_file_does_not_exist368804262/001/mnt/d/Users/TestUser/.ubuntupro/.address\": open /tmp/TestServeNo_connection_because_port_file_does_not_exist368804262/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 917s === CONT TestServe/Error_because_of_context_cancelled 917s time="2024-04-05T14:37:47Z" level=debug msg="Building new daemon" 917s time="2024-04-05T14:37:47Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestServeNo_connection_because_port_file_does_not_exist368804262/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 917s time="2024-04-05T14:37:47Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:40859\"" 917s === CONT TestServe/Success 917s time="2024-04-05T14:37:50Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:42341\"" 917s time="2024-04-05T14:37:50Z" level=debug msg="Building new daemon" 917s time="2024-04-05T14:37:54Z" level=info msg="Connecting to control stream at \"127.0.0.1:42341\"" 917s time="2024-04-05T14:37:54Z" level=debug msg="Updated systemd status to \"Stopped\"" 917s time="2024-04-05T14:37:54Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\" ended: rpc error: code = Canceled desc = context canceled" 917s time="2024-04-05T14:37:54Z" level=info msg="wslInstanceMockService: dropped connection" 917s === CONT TestServe/Error_because_WindowsHostAddress_returns_error 917s time="2024-04-05T14:37:54Z" level=debug msg="Building new daemon" 917s time="2024-04-05T14:37:54Z" level=debug msg="Control stream: starting handshake" 917s time="2024-04-05T14:37:54Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestServeSuccess_with_systemd_notifier_returning_true3844725863/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 917s time="2024-04-05T14:37:54Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:43227\"" 917s time="2024-04-05T14:37:54Z" level=info msg="wslInstanceMockService: Received incoming connection" 917s time="2024-04-05T14:37:55Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": received info: wsl_name:\"TEST_DISTRO\" id:\"ubuntu\" version_id:\"22.04\" pretty_name:\"Ubuntu 22.04.1 LTS\" hostname:\"TEST_DISTRO_HOSTNAME\"" 917s time="2024-04-05T14:37:55Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 35665" 917s time="2024-04-05T14:37:55Z" level=debug msg="Control stream: completed handshake" 917s time="2024-04-05T14:37:55Z" level=info msg="Connected to control stream" 917s time="2024-04-05T14:37:55Z" level=debug msg="Starting to serve gRPC requests" 917s time="2024-04-05T14:37:55Z" level=info msg="Serving gRPC requests on localhost:35665" 917s time="2024-04-05T14:37:57Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestServeError_because_WindowsHostAddress_returns_error2316772476/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 917s time="2024-04-05T14:38:00Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": connected back via reserved port" 917s time="2024-04-05T14:38:03Z" level=info msg="Stopping daemon requested." 917s time="2024-04-05T14:38:06Z" level=info msg="Stopping daemon requested." 917s time="2024-04-05T14:40:00Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\" ended: rpc error: code = Canceled desc = context canceled" 917s time="2024-04-05T14:40:00Z" level=info msg="wslInstanceMockService: dropped connection" 917s --- PASS: TestServe (0.00s) 917s --- PASS: TestServe/Error_because_of_notifier_returning_error (2.51s) 917s --- PASS: TestServe/No_connection_because_of_faulty_agent (13.23s) 917s --- PASS: TestServe/No_connection_because_port_file_does_not_exist (13.06s) 917s --- PASS: TestServe/Error_because_of_context_cancelled (2.99s) 917s --- PASS: TestServe/Success_with_systemd_notifier_returning_true (36.11s) 917s --- PASS: TestServe/Error_because_WindowsHostAddress_returns_error (2.94s) 917s --- PASS: TestServe/Success (130.58s) 917s PASS 917s ok github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/internal/daemon 194.775s 917s === RUN TestInfo 917s === PAUSE TestInfo 917s === RUN TestWslDistroName 917s === PAUSE TestWslDistroName 917s === RUN TestUserProfileDir 917s === PAUSE TestUserProfileDir 917s === RUN TestProStatus 917s === PAUSE TestProStatus 917s === RUN TestProAttach 917s === PAUSE TestProAttach 917s === RUN TestProDetach 917s === PAUSE TestProDetach 917s === RUN TestLandscapeEnable 917s === PAUSE TestLandscapeEnable 917s === RUN TestWindowsHostAddress 917s === PAUSE TestWindowsHostAddress 917s === RUN TestLandscapeDisable 917s === PAUSE TestLandscapeDisable 917s === RUN TestWithProMock 917s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 917s --- SKIP: TestWithProMock (0.00s) 917s === RUN TestWithLandscapeConfigMock 917s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 917s --- SKIP: TestWithLandscapeConfigMock (0.00s) 917s === RUN TestWithWslPathMock 917s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 917s --- SKIP: TestWithWslPathMock (0.00s) 917s === RUN TestWithWslInfoMock 917s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 917s --- SKIP: TestWithWslInfoMock (0.00s) 917s === RUN TestWithCmdExeMock 917s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 917s --- SKIP: TestWithCmdExeMock (0.00s) 917s === CONT TestInfo 917s === RUN TestInfo/Error_when_/etc/os-release_cannot_be_read 917s === PAUSE TestInfo/Error_when_/etc/os-release_cannot_be_read 917s === RUN TestInfo/Error_whem_/etc/os-release_returns_bad_contents 917s === PAUSE TestInfo/Error_whem_/etc/os-release_returns_bad_contents 917s === RUN TestInfo/Error_when_hostname_cannot_be_obtained 917s === PAUSE TestInfo/Error_when_hostname_cannot_be_obtained 917s === RUN TestInfo/Success 917s === PAUSE TestInfo/Success 917s === RUN TestInfo/Error_when_WslDistroName_fails 917s === PAUSE TestInfo/Error_when_WslDistroName_fails 917s === RUN TestInfo/Error_when_pro_status_command_fails 917s === PAUSE TestInfo/Error_when_pro_status_command_fails 917s === RUN TestInfo/Error_when_pro_status_output_cannot_be_parsed 917s === PAUSE TestInfo/Error_when_pro_status_output_cannot_be_parsed 917s === CONT TestProDetach 917s === RUN TestProDetach/success_on_attached_distro 917s === PAUSE TestProDetach/success_on_attached_distro 917s === RUN TestProDetach/error_on_'pro_detach'_returning_error_and_no_reason 917s === PAUSE TestProDetach/error_on_'pro_detach'_returning_error_and_no_reason 917s === RUN TestProDetach/error_on_'pro_detach'_error_and_some_reason 917s === PAUSE TestProDetach/error_on_'pro_detach'_error_and_some_reason 917s === RUN TestProDetach/error_on_'pro_detach'_error_with_bad_JSON 917s === PAUSE TestProDetach/error_on_'pro_detach'_error_with_bad_JSON 917s === RUN TestProDetach/success_on_unattached_distro 917s === PAUSE TestProDetach/success_on_unattached_distro 917s === CONT TestLandscapeDisable 917s === RUN TestLandscapeDisable/Error_when_the_landscape-config_command_fails 917s === PAUSE TestLandscapeDisable/Error_when_the_landscape-config_command_fails 917s === RUN TestLandscapeDisable/Success 917s === PAUSE TestLandscapeDisable/Success 917s === CONT TestWindowsHostAddress 917s === RUN TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_is_ill-formed 917s === PAUSE TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_is_ill-formed 917s === RUN TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_does_not_exist 917s === PAUSE TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_does_not_exist 917s === RUN TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_is_ill-formed 917s === PAUSE TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_is_ill-formed 917s === RUN TestWindowsHostAddress/Success_with_NAT,_nameserver_is_loopback 917s === PAUSE TestWindowsHostAddress/Success_with_NAT,_nameserver_is_loopback 917s === RUN TestWindowsHostAddress/Error_when_wslinfo_returns_an_error 917s === PAUSE TestWindowsHostAddress/Error_when_wslinfo_returns_an_error 917s === RUN TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_does_not_exist 917s === PAUSE TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_does_not_exist 917s === CONT TestLandscapeEnable 917s === RUN TestLandscapeEnable/Error_when_the_landscape-config_command_fails 917s === RUN TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_has_an_ill-formed_IP 917s === PAUSE TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_has_an_ill-formed_IP 917s === PAUSE TestLandscapeEnable/Error_when_the_landscape-config_command_fails 917s === RUN TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_has_an_ill-formed_IP 917s === RUN TestLandscapeEnable/Error_when_failing_to_override_the_SSL_certficate_path 917s === PAUSE TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_has_an_ill-formed_IP 917s === PAUSE TestLandscapeEnable/Error_when_failing_to_override_the_SSL_certficate_path 917s === RUN TestWindowsHostAddress/Success_without_NAT 917s === RUN TestLandscapeEnable/Success 917s === PAUSE TestWindowsHostAddress/Success_without_NAT 917s === PAUSE TestLandscapeEnable/Success 917s === RUN TestWindowsHostAddress/Success_with_NAT,_nameserver_is_not_loopback 917s === PAUSE TestWindowsHostAddress/Success_with_NAT,_nameserver_is_not_loopback 917s === RUN TestLandscapeEnable/Success_overriding_computer_title 917s === PAUSE TestLandscapeEnable/Success_overriding_computer_title 917s === RUN TestLandscapeEnable/Success_overriding_the_SSL_certficate_path 917s === CONT TestProStatus 917s === PAUSE TestLandscapeEnable/Success_overriding_the_SSL_certficate_path 917s === RUN TestProStatus/success_on_unattached_distro 917s === PAUSE TestProStatus/success_on_unattached_distro 917s === RUN TestProStatus/success_on_attached_distro 917s === PAUSE TestProStatus/success_on_attached_distro 917s === RUN TestProStatus/error_on_'pro_attach'_returning_bad_output 917s === PAUSE TestProStatus/error_on_'pro_attach'_returning_bad_output 917s === RUN TestProStatus/error_on_'pro_attach'_error 917s === PAUSE TestProStatus/error_on_'pro_attach'_error 917s === CONT TestProAttach 917s === RUN TestProAttach/success 917s === PAUSE TestProAttach/success 917s === RUN TestProAttach/error_on_'pro_attach'_error 917s === PAUSE TestProAttach/error_on_'pro_attach'_error 917s === CONT TestUserProfileDir 917s === RUN TestUserProfileDir/Success_with_cached_cmd.exe_path 917s === PAUSE TestUserProfileDir/Success_with_cached_cmd.exe_path 917s === RUN TestLandscapeEnable/Error_when_the_file_cannot_be_parsed 917s === PAUSE TestLandscapeEnable/Error_when_the_file_cannot_be_parsed 917s === RUN TestLandscapeEnable/Error_when_the_config_file_cannot_be_written 917s === PAUSE TestLandscapeEnable/Error_when_the_config_file_cannot_be_written 917s === RUN TestUserProfileDir/Error_finding_cmd.exe_because_there_is_no_/proc/mounts 917s === PAUSE TestUserProfileDir/Error_finding_cmd.exe_because_there_is_no_/proc/mounts 917s === RUN TestUserProfileDir/Success_with_a_single_9P_filesystem_mount 917s === PAUSE TestUserProfileDir/Success_with_a_single_9P_filesystem_mount 917s === RUN TestUserProfileDir/Success_with_multiple_9P_filesystem_mounts 917s === CONT TestWslDistroName 917s === PAUSE TestUserProfileDir/Success_with_multiple_9P_filesystem_mounts 917s === RUN TestUserProfileDir/Success_with_multiple_types_of_filesystem_mounts 917s === RUN TestWslDistroName/Error_when_WSL_DISTRO_NAME_is_empty_and_wslpath_fails 917s === PAUSE TestUserProfileDir/Success_with_multiple_types_of_filesystem_mounts 917s === PAUSE TestWslDistroName/Error_when_WSL_DISTRO_NAME_is_empty_and_wslpath_fails 917s === RUN TestUserProfileDir/Error_finding_cmd.exe_because_there_is_no_Windows_FS_in_/proc/mounts 917s === RUN TestWslDistroName/Error_when_WSL_DISTRO_NAME_is_empty_and_wslpath_returns_bad_text 917s === PAUSE TestUserProfileDir/Error_finding_cmd.exe_because_there_is_no_Windows_FS_in_/proc/mounts 917s === PAUSE TestWslDistroName/Error_when_WSL_DISTRO_NAME_is_empty_and_wslpath_returns_bad_text 917s === RUN TestUserProfileDir/Error_when_cmd.exe_does_not_exist 917s === RUN TestWslDistroName/Success_reading_from_WSL_DISTRO_NAME 917s === PAUSE TestUserProfileDir/Error_when_cmd.exe_does_not_exist 917s === PAUSE TestWslDistroName/Success_reading_from_WSL_DISTRO_NAME 917s === RUN TestUserProfileDir/Error_on_cmd.exe_error 917s === RUN TestWslDistroName/Success_using_wslpath 917s === PAUSE TestUserProfileDir/Error_on_cmd.exe_error 917s === PAUSE TestWslDistroName/Success_using_wslpath 917s === RUN TestUserProfileDir/Error_on_wslpath_error 917s === CONT TestInfo/Error_when_/etc/os-release_cannot_be_read 917s === PAUSE TestUserProfileDir/Error_on_wslpath_error 917s === RUN TestUserProfileDir/Error_when_wslpath_returns_a_bad_path 917s === PAUSE TestUserProfileDir/Error_when_wslpath_returns_a_bad_path 917s === CONT TestProDetach/success_on_attached_distro 917s === CONT TestLandscapeDisable/Error_when_the_landscape-config_command_fails 917s === CONT TestInfo/Error_when_pro_status_output_cannot_be_parsed 917s === CONT TestInfo/Error_when_pro_status_command_fails 917s === CONT TestInfo/Error_when_WslDistroName_fails 917s === CONT TestInfo/Success 917s === CONT TestInfo/Error_when_hostname_cannot_be_obtained 917s === CONT TestInfo/Error_whem_/etc/os-release_returns_bad_contents 917s === CONT TestProDetach/error_on_'pro_detach'_error_and_some_reason 917s --- PASS: TestInfo (0.00s) 917s --- PASS: TestInfo/Error_when_/etc/os-release_cannot_be_read (1.41s) 917s --- PASS: TestInfo/Error_when_pro_status_output_cannot_be_parsed (0.86s) 917s --- PASS: TestInfo/Error_when_pro_status_command_fails (0.99s) 917s --- PASS: TestInfo/Error_when_WslDistroName_fails (1.04s) 917s --- PASS: TestInfo/Success (1.26s) 917s --- PASS: TestInfo/Error_when_hostname_cannot_be_obtained (1.41s) 917s --- PASS: TestInfo/Error_whem_/etc/os-release_returns_bad_contents (1.48s) 917s === CONT TestProDetach/success_on_unattached_distro 917s === CONT TestProDetach/error_on_'pro_detach'_error_with_bad_JSON 917s === CONT TestProDetach/error_on_'pro_detach'_returning_error_and_no_reason 917s === CONT TestLandscapeDisable/Success 917s --- PASS: TestProDetach (0.00s) 917s --- PASS: TestProDetach/success_on_attached_distro (1.43s) 917s --- PASS: TestProDetach/error_on_'pro_detach'_error_and_some_reason (1.27s) 917s --- PASS: TestProDetach/success_on_unattached_distro (0.92s) 917s --- PASS: TestProDetach/error_on_'pro_detach'_error_with_bad_JSON (0.94s) 917s --- PASS: TestProDetach/error_on_'pro_detach'_returning_error_and_no_reason (0.92s) 917s === CONT TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_is_ill-formed 917s --- PASS: TestLandscapeDisable (0.00s) 917s --- PASS: TestLandscapeDisable/Error_when_the_landscape-config_command_fails (0.91s) 917s --- PASS: TestLandscapeDisable/Success (0.96s) 917s === CONT TestWindowsHostAddress/Success_with_NAT,_nameserver_is_not_loopback 917s === CONT TestWindowsHostAddress/Success_without_NAT 917s === CONT TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_has_an_ill-formed_IP 917s === CONT TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_has_an_ill-formed_IP 917s === CONT TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_does_not_exist 917s === CONT TestWindowsHostAddress/Error_when_wslinfo_returns_an_error 917s === CONT TestWindowsHostAddress/Success_with_NAT,_nameserver_is_loopback 917s === CONT TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_is_ill-formed 917s === CONT TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_does_not_exist 917s === CONT TestProStatus/success_on_unattached_distro 917s --- PASS: TestWindowsHostAddress (0.00s) 917s --- PASS: TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_is_ill-formed (0.93s) 917s --- PASS: TestWindowsHostAddress/Success_with_NAT,_nameserver_is_not_loopback (0.87s) 917s --- PASS: TestWindowsHostAddress/Success_without_NAT (1.26s) 917s --- PASS: TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_has_an_ill-formed_IP (1.33s) 917s --- PASS: TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_has_an_ill-formed_IP (1.33s) 917s --- PASS: TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_does_not_exist (1.34s) 917s --- PASS: TestWindowsHostAddress/Error_when_wslinfo_returns_an_error (1.33s) 917s --- PASS: TestWindowsHostAddress/Success_with_NAT,_nameserver_is_loopback (1.27s) 917s --- PASS: TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_does_not_exist (0.99s) 917s --- PASS: TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_is_ill-formed (1.07s) 917s === CONT TestProAttach/success 917s === CONT TestProStatus/error_on_'pro_attach'_error 917s === CONT TestProStatus/error_on_'pro_attach'_returning_bad_output 917s === CONT TestProStatus/success_on_attached_distro 917s === CONT TestProAttach/error_on_'pro_attach'_error 917s === CONT TestLandscapeEnable/Error_when_the_landscape-config_command_fails 917s --- PASS: TestProStatus (0.00s) 917s --- PASS: TestProStatus/success_on_unattached_distro (0.92s) 917s --- PASS: TestProStatus/error_on_'pro_attach'_error (1.19s) 917s --- PASS: TestProStatus/error_on_'pro_attach'_returning_bad_output (1.30s) 917s --- PASS: TestProStatus/success_on_attached_distro (1.14s) 917s === CONT TestLandscapeEnable/Success_overriding_the_SSL_certficate_path 917s --- PASS: TestProAttach (0.00s) 917s --- PASS: TestProAttach/success (0.94s) 917s --- PASS: TestProAttach/error_on_'pro_attach'_error (1.01s) 917s === CONT TestLandscapeEnable/Error_when_the_config_file_cannot_be_written 917s === CONT TestLandscapeEnable/Error_when_the_file_cannot_be_parsed 917s === CONT TestLandscapeEnable/Success 917s system_test.go:456: testdata/TestLandscapeEnable/golden/success 917s === CONT TestLandscapeEnable/Success_overriding_computer_title 917s time="2024-04-05T14:37:44Z" level=info msg="Landscape config contains key \"computer_title\". Its value will be overridden with TEST_DISTRO" 917s === NAME TestLandscapeEnable/Success_overriding_the_SSL_certficate_path 917s system_test.go:456: testdata/TestLandscapeEnable/golden/success_overriding_the_ssl_certficate_path 917s === CONT TestLandscapeEnable/Error_when_failing_to_override_the_SSL_certficate_path 917s === NAME TestLandscapeEnable/Success_overriding_computer_title 917s system_test.go:456: testdata/TestLandscapeEnable/golden/success_overriding_computer_title 917s === CONT TestWslDistroName/Error_when_WSL_DISTRO_NAME_is_empty_and_wslpath_fails 917s --- PASS: TestLandscapeEnable (0.00s) 917s --- PASS: TestLandscapeEnable/Error_when_the_landscape-config_command_fails (0.89s) 917s --- PASS: TestLandscapeEnable/Error_when_the_config_file_cannot_be_written (0.00s) 917s --- PASS: TestLandscapeEnable/Error_when_the_file_cannot_be_parsed (0.00s) 917s --- PASS: TestLandscapeEnable/Success (0.97s) 917s --- PASS: TestLandscapeEnable/Success_overriding_the_SSL_certficate_path (1.85s) 917s --- PASS: TestLandscapeEnable/Success_overriding_computer_title (0.96s) 917s --- PASS: TestLandscapeEnable/Error_when_failing_to_override_the_SSL_certficate_path (0.99s) 917s === CONT TestWslDistroName/Success_using_wslpath 917s === CONT TestWslDistroName/Success_reading_from_WSL_DISTRO_NAME 917s === CONT TestWslDistroName/Error_when_WSL_DISTRO_NAME_is_empty_and_wslpath_returns_bad_text 917s === CONT TestUserProfileDir/Success_with_cached_cmd.exe_path 917s --- PASS: TestWslDistroName (0.00s) 917s --- PASS: TestWslDistroName/Success_using_wslpath (0.97s) 917s --- PASS: TestWslDistroName/Success_reading_from_WSL_DISTRO_NAME (0.00s) 917s --- PASS: TestWslDistroName/Error_when_WSL_DISTRO_NAME_is_empty_and_wslpath_fails (1.05s) 917s --- PASS: TestWslDistroName/Error_when_WSL_DISTRO_NAME_is_empty_and_wslpath_returns_bad_text (1.30s) 917s === CONT TestUserProfileDir/Error_when_wslpath_returns_a_bad_path 917s === CONT TestUserProfileDir/Error_on_wslpath_error 917s === CONT TestUserProfileDir/Error_on_cmd.exe_error 917s === CONT TestUserProfileDir/Error_when_cmd.exe_does_not_exist 917s === CONT TestUserProfileDir/Error_finding_cmd.exe_because_there_is_no_Windows_FS_in_/proc/mounts 917s system_test.go:209: Removing default proc/mounts 917s === CONT TestUserProfileDir/Success_with_multiple_types_of_filesystem_mounts 917s === CONT TestUserProfileDir/Success_with_multiple_9P_filesystem_mounts 917s === CONT TestUserProfileDir/Success_with_a_single_9P_filesystem_mount 917s === CONT TestUserProfileDir/Error_finding_cmd.exe_because_there_is_no_/proc/mounts 917s system_test.go:209: Removing default proc/mounts 917s --- PASS: TestUserProfileDir (0.00s) 917s --- PASS: TestUserProfileDir/Success_with_cached_cmd.exe_path (2.64s) 917s --- PASS: TestUserProfileDir/Error_when_wslpath_returns_a_bad_path (2.70s) 917s --- PASS: TestUserProfileDir/Error_on_cmd.exe_error (1.49s) 917s --- PASS: TestUserProfileDir/Error_when_cmd.exe_does_not_exist (0.00s) 917s --- PASS: TestUserProfileDir/Error_finding_cmd.exe_because_there_is_no_Windows_FS_in_/proc/mounts (0.00s) 917s --- PASS: TestUserProfileDir/Error_on_wslpath_error (2.81s) 917s --- PASS: TestUserProfileDir/Success_with_multiple_types_of_filesystem_mounts (2.67s) 917s --- PASS: TestUserProfileDir/Success_with_multiple_9P_filesystem_mounts (2.78s) 917s --- PASS: TestUserProfileDir/Error_finding_cmd.exe_because_there_is_no_/proc/mounts (0.00s) 917s --- PASS: TestUserProfileDir/Success_with_a_single_9P_filesystem_mount (2.38s) 917s PASS 917s ok github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/internal/system 31.378s 917s === RUN TestApplyProToken 917s === PAUSE TestApplyProToken 917s === RUN TestApplyLandscapeConfig 917s === PAUSE TestApplyLandscapeConfig 917s === RUN TestWithProMock 917s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 917s --- SKIP: TestWithProMock (0.00s) 917s === RUN TestWithLandscapeConfigMock 917s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 917s --- SKIP: TestWithLandscapeConfigMock (0.00s) 917s === RUN TestWithWslPathMock 917s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 917s --- SKIP: TestWithWslPathMock (0.00s) 917s === RUN TestWithWslInfoMock 917s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 917s --- SKIP: TestWithWslInfoMock (0.00s) 917s === RUN TestWithCmdExeMock 917s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 917s --- SKIP: TestWithCmdExeMock (0.00s) 917s === CONT TestApplyProToken 917s === RUN TestApplyProToken/Error_detaching_pro 917s === CONT TestApplyLandscapeConfig 917s === PAUSE TestApplyProToken/Error_detaching_pro 917s === RUN TestApplyLandscapeConfig/Success_enabling 917s === PAUSE TestApplyLandscapeConfig/Success_enabling 917s === RUN TestApplyProToken/Error_calling_pro_status 917s === RUN TestApplyLandscapeConfig/Success_disabling 917s === PAUSE TestApplyProToken/Error_calling_pro_status 917s === PAUSE TestApplyLandscapeConfig/Success_disabling 917s === RUN TestApplyLandscapeConfig/Error_enabling_when_landscape-config_fails 917s === RUN TestApplyProToken/Error_cannot_send_info_to_stream 917s === PAUSE TestApplyLandscapeConfig/Error_enabling_when_landscape-config_fails 917s === PAUSE TestApplyProToken/Error_cannot_send_info_to_stream 917s === RUN TestApplyProToken/success_attaching_attached_machine 917s === RUN TestApplyLandscapeConfig/Error_disabling_when_landscape-config_--disable_fails 917s === PAUSE TestApplyProToken/success_attaching_attached_machine 917s === PAUSE TestApplyLandscapeConfig/Error_disabling_when_landscape-config_--disable_fails 917s === RUN TestApplyProToken/success_attaching_non-attached_machine 917s === CONT TestApplyLandscapeConfig/Success_enabling 917s === PAUSE TestApplyProToken/success_attaching_non-attached_machine 917s === RUN TestApplyProToken/Error_calling_pro_attach 917s === PAUSE TestApplyProToken/Error_calling_pro_attach 917s === RUN TestApplyProToken/success_detaching_attached_machine 917s === PAUSE TestApplyProToken/success_detaching_attached_machine 917s === RUN TestApplyProToken/success_detaching_non-attached_machine 917s === PAUSE TestApplyProToken/success_detaching_non-attached_machine 917s === RUN TestApplyProToken/Error_getting_system_info 917s === PAUSE TestApplyProToken/Error_getting_system_info 917s === CONT TestApplyProToken/Error_detaching_pro 917s time="2024-04-05T14:37:57Z" level=debug msg="Registering gRPC WSL instance service" 917s time="2024-04-05T14:37:57Z" level=debug msg="Registering gRPC WSL instance service" 917s wslinstanceservice_test.go:108: Serving WslInstanceService on 127.0.0.1:40989 917s === NAME TestApplyLandscapeConfig/Success_enabling 917s wslinstanceservice_test.go:167: Serving WslInstanceService on 127.0.0.1:42211 917s wslinstanceservice_test.go:167: Client connected to WslInstanceService 917s === NAME TestApplyProToken/Error_detaching_pro 917s wslinstanceservice_test.go:108: Client connected to WslInstanceService 917s time="2024-04-05T14:37:57Z" level=info msg="ApplyLandscapeConfig: received config: registering" 917s time="2024-04-05T14:37:57Z" level=info msg="ApplyProToken: Received empty token: detaching" 917s === NAME TestApplyLandscapeConfig/Success_enabling 917s wslinstanceservice_test.go:192: testdata/TestApplyLandscapeConfig/golden/success_enabling 917s === CONT TestApplyProToken/Error_getting_system_info 917s time="2024-04-05T14:37:58Z" level=debug msg="Registering gRPC WSL instance service" 917s wslinstanceservice_test.go:108: Serving WslInstanceService on 127.0.0.1:42009 917s wslinstanceservice_test.go:108: Client connected to WslInstanceService 917s time="2024-04-05T14:37:58Z" level=info msg="ApplyProToken: Received empty token: detaching" 917s === CONT TestApplyProToken/success_detaching_non-attached_machine 917s time="2024-04-05T14:37:59Z" level=debug msg="Registering gRPC WSL instance service" 917s wslinstanceservice_test.go:108: Serving WslInstanceService on 127.0.0.1:37879 917s wslinstanceservice_test.go:108: Client connected to WslInstanceService 917s time="2024-04-05T14:37:59Z" level=info msg="ApplyProToken: Received empty token: detaching" 917s time="2024-04-05T14:38:00Z" level=warning msg="ApplyProToken: could not send update via control stream: could not gather system info: could not read /etc/os-release: open /tmp/TestApplyProTokenError_getting_system_info1703528880/001/etc/os-release: no such file or directory" 917s === CONT TestApplyProToken/success_detaching_attached_machine 917s time="2024-04-05T14:38:00Z" level=debug msg="Registering gRPC WSL instance service" 917s wslinstanceservice_test.go:108: Serving WslInstanceService on 127.0.0.1:42863 917s wslinstanceservice_test.go:108: Client connected to WslInstanceService 917s time="2024-04-05T14:38:00Z" level=info msg="ApplyProToken: Received empty token: detaching" 917s === CONT TestApplyProToken/Error_calling_pro_attach 917s time="2024-04-05T14:38:01Z" level=debug msg="Registering gRPC WSL instance service" 917s wslinstanceservice_test.go:108: Serving WslInstanceService on 127.0.0.1:38407 917s wslinstanceservice_test.go:108: Client connected to WslInstanceService 917s time="2024-04-05T14:38:01Z" level=info msg="ApplyProToken: Received token \"***\": attaching" 917s === CONT TestApplyProToken/success_attaching_non-attached_machine 917s time="2024-04-05T14:38:02Z" level=debug msg="Registering gRPC WSL instance service" 917s wslinstanceservice_test.go:108: Serving WslInstanceService on 127.0.0.1:38179 917s wslinstanceservice_test.go:108: Client connected to WslInstanceService 917s time="2024-04-05T14:38:02Z" level=info msg="ApplyProToken: Received token \"***\": attaching" 917s === CONT TestApplyProToken/success_attaching_attached_machine 917s time="2024-04-05T14:38:04Z" level=debug msg="Registering gRPC WSL instance service" 917s wslinstanceservice_test.go:108: Serving WslInstanceService on 127.0.0.1:34321 917s wslinstanceservice_test.go:108: Client connected to WslInstanceService 917s time="2024-04-05T14:38:04Z" level=info msg="ApplyProToken: Received token \"***\": attaching" 917s === CONT TestApplyProToken/Error_cannot_send_info_to_stream 917s time="2024-04-05T14:38:05Z" level=debug msg="Registering gRPC WSL instance service" 917s wslinstanceservice_test.go:108: Serving WslInstanceService on 127.0.0.1:39731 917s wslinstanceservice_test.go:108: Client connected to WslInstanceService 917s time="2024-04-05T14:38:05Z" level=info msg="ApplyProToken: Received empty token: detaching" 917s === CONT TestApplyProToken/Error_calling_pro_status 917s time="2024-04-05T14:38:06Z" level=debug msg="Registering gRPC WSL instance service" 917s wslinstanceservice_test.go:108: Serving WslInstanceService on 127.0.0.1:42107 917s wslinstanceservice_test.go:108: Client connected to WslInstanceService 917s time="2024-04-05T14:38:06Z" level=info msg="ApplyProToken: Received empty token: detaching" 917s time="2024-04-05T14:38:06Z" level=warning msg="ApplyProToken: could not send update via control stream: could not send system info: test error" 917s === CONT TestApplyLandscapeConfig/Error_enabling_when_landscape-config_fails 917s time="2024-04-05T14:38:06Z" level=debug msg="Registering gRPC WSL instance service" 917s wslinstanceservice_test.go:167: Serving WslInstanceService on 127.0.0.1:45117 917s wslinstanceservice_test.go:167: Client connected to WslInstanceService 917s time="2024-04-05T14:38:06Z" level=info msg="ApplyLandscapeConfig: received config: registering" 917s === CONT TestApplyLandscapeConfig/Error_disabling_when_landscape-config_--disable_fails 917s time="2024-04-05T14:38:07Z" level=debug msg="Registering gRPC WSL instance service" 917s wslinstanceservice_test.go:167: Serving WslInstanceService on 127.0.0.1:37421 917s wslinstanceservice_test.go:167: Client connected to WslInstanceService 917s time="2024-04-05T14:38:07Z" level=info msg="ApplyLandscapeConfig: received empty config: disabling" 917s === CONT TestApplyLandscapeConfig/Success_disabling 917s time="2024-04-05T14:38:08Z" level=debug msg="Registering gRPC WSL instance service" 917s wslinstanceservice_test.go:167: Serving WslInstanceService on 127.0.0.1:45849 917s wslinstanceservice_test.go:167: Client connected to WslInstanceService 917s time="2024-04-05T14:38:08Z" level=info msg="ApplyLandscapeConfig: received empty config: disabling" 917s time="2024-04-05T14:38:08Z" level=warning msg="ApplyProToken: could not send update via control stream: could not gather system info: could not obtain pro status: pro status: command returned error: exit status 1\nStdout:" 917s --- PASS: TestApplyProToken (0.00s) 917s --- PASS: TestApplyProToken/Error_detaching_pro (1.80s) 917s --- PASS: TestApplyProToken/Error_getting_system_info (1.81s) 917s --- PASS: TestApplyProToken/success_detaching_non-attached_machine (1.91s) 917s --- PASS: TestApplyProToken/success_detaching_attached_machine (1.89s) 917s --- PASS: TestApplyProToken/Error_calling_pro_attach (2.82s) 917s --- PASS: TestApplyProToken/success_attaching_non-attached_machine (2.86s) 917s --- PASS: TestApplyProToken/success_attaching_attached_machine (2.80s) 917s --- PASS: TestApplyProToken/Error_cannot_send_info_to_stream (1.83s) 917s --- PASS: TestApplyProToken/Error_calling_pro_status (1.81s) 917s --- PASS: TestApplyLandscapeConfig (0.00s) 917s --- PASS: TestApplyLandscapeConfig/Success_enabling (0.95s) 917s --- PASS: TestApplyLandscapeConfig/Error_enabling_when_landscape-config_fails (0.86s) 917s --- PASS: TestApplyLandscapeConfig/Error_disabling_when_landscape-config_--disable_fails (0.83s) 917s --- PASS: TestApplyLandscapeConfig/Success_disabling (0.63s) 917s PASS 917s ok github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/internal/wslinstanceservice 11.678s 918s autopkgtest [14:40:01]: test command1: -----------------------] 918s autopkgtest [14:40:01]: test command1: - - - - - - - - - - results - - - - - - - - - - 918s command1 PASS 918s autopkgtest [14:40:01]: @@@@@@@@@@@@@@@@@@@@ summary 918s command1 PASS 935s Creating nova instance adt-noble-amd64-wsl-pro-service-20240405-142442-juju-7f2275-prod-proposed-migration-environment-2-b9ba07f6-bab8-410e-a03e-9ed9644f0b99 from image adt/ubuntu-noble-amd64-server-20240405.img (UUID 49ab9a7e-6ce3-4b3a-9adb-34b20d60cbd0)...