0s autopkgtest [10:34:45]: starting date: 2024-02-23 0s autopkgtest [10:34:45]: git checkout: d9c0295 adt_testbed.py: supress warnings from apt using a shell pipeline 0s autopkgtest [10:34:45]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.vmzcrtio/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --setup-commands /home/ubuntu/autopkgtest/setup-commands/setup-testbed --apt-pocket=proposed=src:glibc --apt-upgrade wsl-pro-service --timeout-short=300 --timeout-copy=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=glibc/2.39-0ubuntu2 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos02-arm64-14.secgroup --name adt-noble-arm64-wsl-pro-service-20240223-103445-juju-7f2275-prod-proposed-migration-environment-3 --image adt/ubuntu-noble-arm64-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-3 --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/ 150s autopkgtest [10:37:15]: @@@@@@@@@@@@@@@@@@@@ test bed setup 151s Get:1 http://ftpmaster.internal/ubuntu noble-proposed InRelease [117 kB] 152s Get:2 http://ftpmaster.internal/ubuntu noble-proposed/restricted Sources [9872 B] 152s Get:3 http://ftpmaster.internal/ubuntu noble-proposed/universe Sources [824 kB] 152s Get:4 http://ftpmaster.internal/ubuntu noble-proposed/multiverse Sources [13.8 kB] 152s Get:5 http://ftpmaster.internal/ubuntu noble-proposed/main Sources [99.8 kB] 152s Get:6 http://ftpmaster.internal/ubuntu noble-proposed/main arm64 Packages [224 kB] 152s Get:7 http://ftpmaster.internal/ubuntu noble-proposed/main arm64 c-n-f Metadata [3144 B] 152s Get:8 http://ftpmaster.internal/ubuntu noble-proposed/restricted arm64 Packages [52.0 kB] 152s Get:9 http://ftpmaster.internal/ubuntu noble-proposed/restricted arm64 c-n-f Metadata [116 B] 152s Get:10 http://ftpmaster.internal/ubuntu noble-proposed/universe arm64 Packages [930 kB] 152s Get:11 http://ftpmaster.internal/ubuntu noble-proposed/universe arm64 c-n-f Metadata [8528 B] 152s Get:12 http://ftpmaster.internal/ubuntu noble-proposed/multiverse arm64 Packages [4980 B] 152s Get:13 http://ftpmaster.internal/ubuntu noble-proposed/multiverse arm64 c-n-f Metadata [116 B] 162s Fetched 2287 kB in 3s (665 kB/s) 162s Reading package lists... 169s Reading package lists... 169s Building dependency tree... 169s Reading state information... 172s Calculating upgrade... 173s The following packages were automatically installed and are no longer required: 173s irqbalance libnuma1 173s Use 'sudo apt autoremove' to remove them. 173s The following packages will be upgraded: 173s apport apport-core-dump-handler flash-kernel gzip hostname libc-bin libc6 173s libcap2 libcap2-bin libffi8 libpam-cap libxml2 locales login 173s lto-disabled-list passwd python3-apport python3-problem-report u-boot-tools 173s ubuntu-minimal ubuntu-standard 174s 21 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 174s Need to get 10.2 MB of archives. 174s After this operation, 208 kB disk space will be freed. 174s Get:1 http://ftpmaster.internal/ubuntu noble/main arm64 gzip arm64 1.12-1ubuntu2 [97.1 kB] 174s Get:2 http://ftpmaster.internal/ubuntu noble/main arm64 hostname arm64 3.23+nmu2ubuntu1 [10.9 kB] 174s Get:3 http://ftpmaster.internal/ubuntu noble/main arm64 login arm64 1:4.13+dfsg1-4ubuntu1 [200 kB] 174s Get:4 http://ftpmaster.internal/ubuntu noble-proposed/main arm64 locales all 2.39-0ubuntu2 [4230 kB] 174s Get:5 http://ftpmaster.internal/ubuntu noble-proposed/main arm64 libc6 arm64 2.39-0ubuntu2 [2775 kB] 175s Get:6 http://ftpmaster.internal/ubuntu noble-proposed/main arm64 libc-bin arm64 2.39-0ubuntu2 [591 kB] 175s Get:7 http://ftpmaster.internal/ubuntu noble/main arm64 python3-problem-report all 2.28.0-0ubuntu1 [23.6 kB] 175s Get:8 http://ftpmaster.internal/ubuntu noble/main arm64 python3-apport all 2.28.0-0ubuntu1 [92.0 kB] 175s Get:9 http://ftpmaster.internal/ubuntu noble/main arm64 apport-core-dump-handler all 2.28.0-0ubuntu1 [16.6 kB] 175s Get:10 http://ftpmaster.internal/ubuntu noble/main arm64 apport all 2.28.0-0ubuntu1 [83.9 kB] 175s Get:11 http://ftpmaster.internal/ubuntu noble/main arm64 libcap2 arm64 1:2.66-5ubuntu1 [30.1 kB] 175s Get:12 http://ftpmaster.internal/ubuntu noble/main arm64 passwd arm64 1:4.13+dfsg1-4ubuntu1 [838 kB] 175s Get:13 http://ftpmaster.internal/ubuntu noble/main arm64 libffi8 arm64 3.4.6-1 [22.6 kB] 175s Get:14 http://ftpmaster.internal/ubuntu noble/main arm64 libpam-cap arm64 1:2.66-5ubuntu1 [12.5 kB] 175s Get:15 http://ftpmaster.internal/ubuntu noble/main arm64 libcap2-bin arm64 1:2.66-5ubuntu1 [33.5 kB] 175s Get:16 http://ftpmaster.internal/ubuntu noble/main arm64 libxml2 arm64 2.9.14+dfsg-1.3ubuntu1 [734 kB] 175s Get:17 http://ftpmaster.internal/ubuntu noble/main arm64 ubuntu-minimal arm64 1.532 [10.3 kB] 175s Get:18 http://ftpmaster.internal/ubuntu noble/main arm64 ubuntu-standard arm64 1.532 [10.3 kB] 175s Get:19 http://ftpmaster.internal/ubuntu noble/main arm64 flash-kernel arm64 3.107ubuntu5 [48.9 kB] 175s Get:20 http://ftpmaster.internal/ubuntu noble/main arm64 lto-disabled-list all 47 [12.4 kB] 175s Get:21 http://ftpmaster.internal/ubuntu noble/main arm64 u-boot-tools arm64 2024.01+dfsg-1ubuntu2 [294 kB] 177s Preconfiguring packages ... 177s Fetched 10.2 MB in 2s (6738 kB/s) 178s (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 ... 74305 files and directories currently installed.) 178s Preparing to unpack .../gzip_1.12-1ubuntu2_arm64.deb ... 178s Unpacking gzip (1.12-1ubuntu2) over (1.12-1ubuntu1) ... 179s dpkg: warning: old file '/bin/uncompress' is the same as several new files! (both '/usr/bin/gunzip' and '/usr/bin/uncompress') 179s dpkg: warning: old file '/bin/gunzip' is the same as several new files! (both '/usr/bin/gunzip' and '/usr/bin/uncompress') 179s Setting up gzip (1.12-1ubuntu2) ... 179s (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 ... 74305 files and directories currently installed.) 179s Preparing to unpack .../hostname_3.23+nmu2ubuntu1_arm64.deb ... 179s Unpacking hostname (3.23+nmu2ubuntu1) over (3.23+nmu1ubuntu1) ... 179s Setting up hostname (3.23+nmu2ubuntu1) ... 180s (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 ... 74305 files and directories currently installed.) 180s Preparing to unpack .../login_1%3a4.13+dfsg1-4ubuntu1_arm64.deb ... 180s Unpacking login (1:4.13+dfsg1-4ubuntu1) over (1:4.13+dfsg1-3ubuntu1) ... 180s Setting up login (1:4.13+dfsg1-4ubuntu1) ... 180s (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 ... 74305 files and directories currently installed.) 180s Preparing to unpack .../locales_2.39-0ubuntu2_all.deb ... 180s Unpacking locales (2.39-0ubuntu2) over (2.38-3ubuntu1) ... 183s Preparing to unpack .../libc6_2.39-0ubuntu2_arm64.deb ... 184s Checking for services that may need to be restarted... 184s Checking init scripts... 184s Checking for services that may need to be restarted... 184s Checking init scripts... 184s Stopping some services possibly affected by the upgrade (will be restarted later): 184s cron: stopping...done. 184s 184s Unpacking libc6:arm64 (2.39-0ubuntu2) over (2.38-3ubuntu1) ... 186s Setting up libc6:arm64 (2.39-0ubuntu2) ... 186s Checking for services that may need to be restarted... 186s Checking init scripts... 186s Restarting services possibly affected by the upgrade: 187s cron: restarting...done. 187s 187s Services restarted successfully. 188s (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 ... 74314 files and directories currently installed.) 188s Preparing to unpack .../libc-bin_2.39-0ubuntu2_arm64.deb ... 188s Unpacking libc-bin (2.39-0ubuntu2) over (2.38-3ubuntu1) ... 189s Setting up libc-bin (2.39-0ubuntu2) ... 189s (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 ... 74314 files and directories currently installed.) 189s Preparing to unpack .../python3-problem-report_2.28.0-0ubuntu1_all.deb ... 190s Unpacking python3-problem-report (2.28.0-0ubuntu1) over (2.27.0-0ubuntu7) ... 190s Preparing to unpack .../python3-apport_2.28.0-0ubuntu1_all.deb ... 191s Unpacking python3-apport (2.28.0-0ubuntu1) over (2.27.0-0ubuntu7) ... 191s Preparing to unpack .../apport-core-dump-handler_2.28.0-0ubuntu1_all.deb ... 191s Unpacking apport-core-dump-handler (2.28.0-0ubuntu1) over (2.27.0-0ubuntu7) ... 191s Preparing to unpack .../apport_2.28.0-0ubuntu1_all.deb ... 191s Unpacking apport (2.28.0-0ubuntu1) over (2.27.0-0ubuntu7) ... 191s Preparing to unpack .../libcap2_1%3a2.66-5ubuntu1_arm64.deb ... 191s Unpacking libcap2:arm64 (1:2.66-5ubuntu1) over (1:2.66-4ubuntu1) ... 192s Setting up libcap2:arm64 (1:2.66-5ubuntu1) ... 192s (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 ... 74317 files and directories currently installed.) 192s Preparing to unpack .../passwd_1%3a4.13+dfsg1-4ubuntu1_arm64.deb ... 192s Unpacking passwd (1:4.13+dfsg1-4ubuntu1) over (1:4.13+dfsg1-3ubuntu1) ... 192s Setting up passwd (1:4.13+dfsg1-4ubuntu1) ... 193s (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 ... 74317 files and directories currently installed.) 193s Preparing to unpack .../libffi8_3.4.6-1_arm64.deb ... 193s Unpacking libffi8:arm64 (3.4.6-1) over (3.4.4-2) ... 193s Setting up libffi8:arm64 (3.4.6-1) ... 193s (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 ... 74317 files and directories currently installed.) 193s Preparing to unpack .../0-libpam-cap_1%3a2.66-5ubuntu1_arm64.deb ... 195s Unpacking libpam-cap:arm64 (1:2.66-5ubuntu1) over (1:2.66-4ubuntu1) ... 195s Preparing to unpack .../1-libcap2-bin_1%3a2.66-5ubuntu1_arm64.deb ... 195s Unpacking libcap2-bin (1:2.66-5ubuntu1) over (1:2.66-4ubuntu1) ... 195s Preparing to unpack .../2-libxml2_2.9.14+dfsg-1.3ubuntu1_arm64.deb ... 195s Unpacking libxml2:arm64 (2.9.14+dfsg-1.3ubuntu1) over (2.9.14+dfsg-1.3build3) ... 195s Preparing to unpack .../3-ubuntu-minimal_1.532_arm64.deb ... 195s Unpacking ubuntu-minimal (1.532) over (1.531) ... 195s Preparing to unpack .../4-ubuntu-standard_1.532_arm64.deb ... 195s Unpacking ubuntu-standard (1.532) over (1.531) ... 195s Preparing to unpack .../5-flash-kernel_3.107ubuntu5_arm64.deb ... 195s Unpacking flash-kernel (3.107ubuntu5) over (3.107ubuntu4) ... 196s Preparing to unpack .../6-lto-disabled-list_47_all.deb ... 196s Unpacking lto-disabled-list (47) over (46) ... 196s Preparing to unpack .../7-u-boot-tools_2024.01+dfsg-1ubuntu2_arm64.deb ... 196s Unpacking u-boot-tools (2024.01+dfsg-1ubuntu2) over (2024.01+dfsg-1ubuntu1) ... 196s Setting up lto-disabled-list (47) ... 196s Setting up flash-kernel (3.107ubuntu5) ... 196s Installing new version of config file /etc/flash-kernel/bootscript/bootscr.zynqmp ... 198s flash-kernel: deferring update (trigger activated) 198s Setting up python3-problem-report (2.28.0-0ubuntu1) ... 198s Setting up ubuntu-standard (1.532) ... 198s Setting up locales (2.39-0ubuntu2) ... 198s Installing new version of config file /etc/locale.alias ... 202s Generating locales (this might take a while)... 220s en_US.UTF-8... done 220s Generation complete. 220s Setting up python3-apport (2.28.0-0ubuntu1) ... 221s Setting up libcap2-bin (1:2.66-5ubuntu1) ... 221s Setting up u-boot-tools (2024.01+dfsg-1ubuntu2) ... 221s Setting up libpam-cap:arm64 (1:2.66-5ubuntu1) ... 221s Setting up libxml2:arm64 (2.9.14+dfsg-1.3ubuntu1) ... 221s Setting up ubuntu-minimal (1.532) ... 221s Setting up apport-core-dump-handler (2.28.0-0ubuntu1) ... 227s Setting up apport (2.28.0-0ubuntu1) ... 230s apport-autoreport.service is a disabled or a static unit not running, not starting it. 230s Processing triggers for install-info (7.1-3) ... 231s Processing triggers for initramfs-tools (0.142ubuntu19) ... 231s update-initramfs: Generating /boot/initrd.img-6.6.0-14-generic 231s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 318s System running in EFI mode, skipping. 319s Processing triggers for libc-bin (2.39-0ubuntu2) ... 319s Processing triggers for man-db (2.12.0-3) ... 323s Processing triggers for flash-kernel (3.107ubuntu5) ... 325s System running in EFI mode, skipping. 327s Reading package lists... 328s Building dependency tree... 328s Reading state information... 330s The following packages will be REMOVED: 330s irqbalance* libnuma1* 332s 0 upgraded, 0 newly installed, 2 to remove and 0 not upgraded. 332s After this operation, 332 kB disk space will be freed. 332s (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 ... 74318 files and directories currently installed.) 332s Removing irqbalance (1.9.3-2ubuntu2) ... 334s Removing libnuma1:arm64 (2.0.18-1) ... 334s Processing triggers for man-db (2.12.0-3) ... 335s Processing triggers for libc-bin (2.39-0ubuntu2) ... 335s (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 ... 74304 files and directories currently installed.) 335s Purging configuration files for irqbalance (1.9.3-2ubuntu2) ... 342s sh: Attempting to set up Debian/Ubuntu apt sources automatically 342s sh: Distribution appears to be Ubuntu 346s Reading package lists... 347s Building dependency tree... 347s Reading state information... 350s eatmydata is already the newest version (131-1). 350s dbus is already the newest version (1.14.10-3ubuntu1). 350s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 350s Reading package lists... 351s Building dependency tree... 351s Reading state information... 353s rng-tools-debian is already the newest version (2.4). 353s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 354s Reading package lists... 355s Building dependency tree... 355s Reading state information... 357s The following additional packages will be installed: 357s libhavege2 357s The following NEW packages will be installed: 357s haveged libhavege2 357s 0 upgraded, 2 newly installed, 0 to remove and 0 not upgraded. 357s Need to get 56.9 kB of archives. 357s After this operation, 215 kB of additional disk space will be used. 357s Get:1 http://ftpmaster.internal/ubuntu noble/universe arm64 libhavege2 arm64 1.9.14-1ubuntu1 [23.9 kB] 357s Get:2 http://ftpmaster.internal/ubuntu noble/universe arm64 haveged arm64 1.9.14-1ubuntu1 [33.0 kB] 359s Fetched 56.9 kB in 0s (175 kB/s) 359s Selecting previously unselected package libhavege2:arm64. 359s (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 ... 74302 files and directories currently installed.) 359s Preparing to unpack .../libhavege2_1.9.14-1ubuntu1_arm64.deb ... 360s Unpacking libhavege2:arm64 (1.9.14-1ubuntu1) ... 360s Selecting previously unselected package haveged. 360s Preparing to unpack .../haveged_1.9.14-1ubuntu1_arm64.deb ... 360s Unpacking haveged (1.9.14-1ubuntu1) ... 360s Setting up libhavege2:arm64 (1.9.14-1ubuntu1) ... 360s Setting up haveged (1.9.14-1ubuntu1) ... 363s Created symlink /etc/systemd/system/sysinit.target.wants/haveged.service → /usr/lib/systemd/system/haveged.service. 365s Processing triggers for man-db (2.12.0-3) ... 367s Processing triggers for libc-bin (2.39-0ubuntu2) ... 369s Reading package lists... 370s Building dependency tree... 370s Reading state information... 373s The following packages will be REMOVED: 373s cloud-init* python3-configobj* python3-debconf* 374s 0 upgraded, 0 newly installed, 3 to remove and 0 not upgraded. 374s After this operation, 3228 kB disk space will be freed. 375s (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 ... 74318 files and directories currently installed.) 375s Removing cloud-init (24.1~6ga4140119-0ubuntu1) ... 378s Removing python3-configobj (5.0.8-3) ... 378s Removing python3-debconf (1.5.86) ... 378s Processing triggers for man-db (2.12.0-3) ... 380s (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 ... 73930 files and directories currently installed.) 380s Purging configuration files for cloud-init (24.1~6ga4140119-0ubuntu1) ... 383s dpkg: warning: while removing cloud-init, directory '/etc/cloud/cloud.cfg.d' not empty so not removed 383s Processing triggers for rsyslog (8.2312.0-3ubuntu3) ... 385s Reading package lists... 386s Building dependency tree... 386s Reading state information... 388s linux-generic is already the newest version (6.6.0-14.14). 388s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 390s Hit:1 http://ftpmaster.internal/ubuntu noble InRelease 390s Hit:2 http://ftpmaster.internal/ubuntu noble-updates InRelease 390s Hit:3 http://ftpmaster.internal/ubuntu noble-security InRelease 390s Hit:4 http://ftpmaster.internal/ubuntu noble-proposed InRelease 399s Reading package lists... 400s Reading package lists... 400s Building dependency tree... 400s Reading state information... 402s Calculating upgrade... 404s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 404s Reading package lists... 405s Building dependency tree... 405s Reading state information... 408s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 408s autopkgtest [10:41:33]: rebooting testbed after setup commands that affected boot 584s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 591s autopkgtest [10:44:36]: testbed running kernel: Linux 6.6.0-14-generic #14-Ubuntu SMP PREEMPT_DYNAMIC Thu Nov 30 10:53:08 UTC 2023 592s autopkgtest [10:44:37]: testbed dpkg architecture: arm64 594s autopkgtest [10:44:39]: @@@@@@@@@@@@@@@@@@@@ apt-source wsl-pro-service 597s Get:1 http://ftpmaster.internal/ubuntu noble/universe wsl-pro-service 0.1.1 (dsc) [1420 B] 597s Get:2 http://ftpmaster.internal/ubuntu noble/universe wsl-pro-service 0.1.1 (tar) [1763 kB] 598s gpgv: Signature made Mon Feb 5 09:51:14 2024 UTC 598s gpgv: using DSA key DD00EF8F4D23C30D78EC990998B24A9CE4AC208E 598s gpgv: Can't check signature: No public key 598s dpkg-source: warning: cannot verify inline signature for ./wsl-pro-service_0.1.1.dsc: no acceptable signature found 599s autopkgtest [10:44:44]: testing package wsl-pro-service version 0.1.1 599s autopkgtest [10:44:44]: build not needed 601s autopkgtest [10:44:46]: test command1: preparing testbed 605s Reading package lists... 606s Building dependency tree... 606s Reading state information... 607s Correcting dependencies...Starting pkgProblemResolver with broken count: 0 607s Starting 2 pkgProblemResolver with broken count: 0 607s Done 608s Done 608s Starting pkgProblemResolver with broken count: 0 609s Starting 2 pkgProblemResolver with broken count: 0 609s Done 610s The following additional packages will be installed: 610s autoconf automake autopoint autotools-dev build-essential cpp cpp-13 610s cpp-13-aarch64-linux-gnu cpp-aarch64-linux-gnu debhelper debugedit dh-apport 610s dh-autoreconf dh-golang dh-strip-nondeterminism dwz g++ g++-13 610s g++-13-aarch64-linux-gnu g++-aarch64-linux-gnu gcc gcc-13 610s gcc-13-aarch64-linux-gnu gcc-aarch64-linux-gnu gettext golang-1.21-go 610s golang-1.21-src golang-go golang-src intltool-debian libarchive-zip-perl 610s libasan8 libatomic1 libc-dev-bin libc6-dev libcc1-0 libcrypt-dev 610s libdebhelper-perl libdw1 libfile-stripnondeterminism-perl libgcc-13-dev 610s libgomp1 libhwasan0 libisl23 libitm1 liblsan0 libmpc3 libnsl-dev 610s libstdc++-13-dev libsub-override-perl libtirpc-dev libtool libtsan2 610s libubsan1 linux-libc-dev m4 po-debconf rpcsvc-proto 610s Suggested packages: 610s autoconf-archive gnu-standards autoconf-doc cpp-doc gcc-13-locales 610s cpp-13-doc dh-make gcc-13-doc gcc-multilib manpages-dev flex bison gdb 610s gcc-doc gdb-aarch64-linux-gnu gettext-doc libasprintf-dev libgettextpo-dev 610s bzr | brz git mercurial subversion glibc-doc libstdc++-13-doc libtool-doc 610s gfortran | fortran95-compiler gcj-jdk m4-doc libmail-box-perl 610s Recommended packages: 610s pkg-config manpages manpages-dev libc-devtools libarchive-cpio-perl 610s libltdl-dev libmail-sendmail-perl 610s The following NEW packages will be installed: 610s autoconf automake autopoint autotools-dev build-essential cpp cpp-13 610s cpp-13-aarch64-linux-gnu cpp-aarch64-linux-gnu debhelper debugedit dh-apport 610s dh-autoreconf dh-golang dh-strip-nondeterminism dwz g++ g++-13 610s g++-13-aarch64-linux-gnu g++-aarch64-linux-gnu gcc gcc-13 610s gcc-13-aarch64-linux-gnu gcc-aarch64-linux-gnu gettext golang-1.21-go 610s golang-1.21-src golang-go golang-src intltool-debian libarchive-zip-perl 610s libasan8 libatomic1 libc-dev-bin libc6-dev libcc1-0 libcrypt-dev 610s libdebhelper-perl libdw1 libfile-stripnondeterminism-perl libgcc-13-dev 610s libgomp1 libhwasan0 libisl23 libitm1 liblsan0 libmpc3 libnsl-dev 610s libstdc++-13-dev libsub-override-perl libtirpc-dev libtool libtsan2 610s libubsan1 linux-libc-dev m4 po-debconf rpcsvc-proto 611s 0 upgraded, 58 newly installed, 0 to remove and 0 not upgraded. 611s 1 not fully installed or removed. 611s Need to get 108 MB of archives. 611s After this operation, 452 MB of additional disk space will be used. 611s Get:1 http://ftpmaster.internal/ubuntu noble/main arm64 autotools-dev all 20220109.1 [44.9 kB] 611s Get:2 http://ftpmaster.internal/ubuntu noble/main arm64 m4 arm64 1.4.19-4 [240 kB] 611s Get:3 http://ftpmaster.internal/ubuntu noble/main arm64 autoconf all 2.71-3 [339 kB] 611s Get:4 http://ftpmaster.internal/ubuntu noble/main arm64 automake all 1:1.16.5-1.3ubuntu1 [558 kB] 611s Get:5 http://ftpmaster.internal/ubuntu noble/main arm64 autopoint all 0.21-14ubuntu1 [422 kB] 611s Get:6 http://ftpmaster.internal/ubuntu noble/main arm64 libdebhelper-perl all 13.13ubuntu1 [88.9 kB] 611s Get:7 http://ftpmaster.internal/ubuntu noble/main arm64 libisl23 arm64 0.26-3 [713 kB] 611s Get:8 http://ftpmaster.internal/ubuntu noble/main arm64 libmpc3 arm64 1.3.1-1 [55.3 kB] 611s Get:9 http://ftpmaster.internal/ubuntu noble/main arm64 cpp-13-aarch64-linux-gnu arm64 13.2.0-13ubuntu1 [10.3 MB] 612s Get:10 http://ftpmaster.internal/ubuntu noble/main arm64 cpp-13 arm64 13.2.0-13ubuntu1 [1030 B] 612s Get:11 http://ftpmaster.internal/ubuntu noble/main arm64 cpp-aarch64-linux-gnu arm64 4:13.2.0-7ubuntu1 [5316 B] 612s Get:12 http://ftpmaster.internal/ubuntu noble/main arm64 cpp arm64 4:13.2.0-7ubuntu1 [22.4 kB] 612s Get:13 http://ftpmaster.internal/ubuntu noble/main arm64 libcc1-0 arm64 14-20240201-3ubuntu1 [44.8 kB] 612s Get:14 http://ftpmaster.internal/ubuntu noble/main arm64 libgomp1 arm64 14-20240201-3ubuntu1 [144 kB] 612s Get:15 http://ftpmaster.internal/ubuntu noble/main arm64 libitm1 arm64 14-20240201-3ubuntu1 [27.6 kB] 612s Get:16 http://ftpmaster.internal/ubuntu noble/main arm64 libatomic1 arm64 14-20240201-3ubuntu1 [11.4 kB] 612s Get:17 http://ftpmaster.internal/ubuntu noble/main arm64 libasan8 arm64 14-20240201-3ubuntu1 [2919 kB] 612s Get:18 http://ftpmaster.internal/ubuntu noble/main arm64 liblsan0 arm64 14-20240201-3ubuntu1 [1281 kB] 612s Get:19 http://ftpmaster.internal/ubuntu noble/main arm64 libtsan2 arm64 14-20240201-3ubuntu1 [2689 kB] 612s Get:20 http://ftpmaster.internal/ubuntu noble/main arm64 libubsan1 arm64 14-20240201-3ubuntu1 [1150 kB] 612s Get:21 http://ftpmaster.internal/ubuntu noble/main arm64 libhwasan0 arm64 14-20240201-3ubuntu1 [1597 kB] 612s Get:22 http://ftpmaster.internal/ubuntu noble/main arm64 libgcc-13-dev arm64 13.2.0-13ubuntu1 [2463 kB] 612s Get:23 http://ftpmaster.internal/ubuntu noble/main arm64 gcc-13-aarch64-linux-gnu arm64 13.2.0-13ubuntu1 [20.1 MB] 613s Get:24 http://ftpmaster.internal/ubuntu noble/main arm64 gcc-13 arm64 13.2.0-13ubuntu1 [463 kB] 613s Get:25 http://ftpmaster.internal/ubuntu noble/main arm64 gcc-aarch64-linux-gnu arm64 4:13.2.0-7ubuntu1 [1198 B] 613s Get:26 http://ftpmaster.internal/ubuntu noble/main arm64 gcc arm64 4:13.2.0-7ubuntu1 [5018 B] 613s Get:27 http://ftpmaster.internal/ubuntu noble-proposed/main arm64 libc-dev-bin arm64 2.39-0ubuntu2 [19.7 kB] 613s Get:28 http://ftpmaster.internal/ubuntu noble/main arm64 linux-libc-dev arm64 6.6.0-14.14 [1554 kB] 613s Get:29 http://ftpmaster.internal/ubuntu noble/main arm64 libcrypt-dev arm64 1:4.4.36-4 [136 kB] 613s Get:30 http://ftpmaster.internal/ubuntu noble/main arm64 libtirpc-dev arm64 1.3.4+ds-1build1 [232 kB] 613s Get:31 http://ftpmaster.internal/ubuntu noble/main arm64 libnsl-dev arm64 1.3.0-3 [71.9 kB] 613s Get:32 http://ftpmaster.internal/ubuntu noble/main arm64 rpcsvc-proto arm64 1.4.2-0ubuntu6 [65.4 kB] 613s Get:33 http://ftpmaster.internal/ubuntu noble-proposed/main arm64 libc6-dev arm64 2.39-0ubuntu2 [1596 kB] 614s Get:34 http://ftpmaster.internal/ubuntu noble/main arm64 libtool all 2.4.7-7 [166 kB] 614s Get:35 http://ftpmaster.internal/ubuntu noble/main arm64 dh-autoreconf all 20 [16.1 kB] 614s Get:36 http://ftpmaster.internal/ubuntu noble/main arm64 libarchive-zip-perl all 1.68-1 [90.2 kB] 614s Get:37 http://ftpmaster.internal/ubuntu noble/main arm64 libsub-override-perl all 0.10-1 [10.0 kB] 614s Get:38 http://ftpmaster.internal/ubuntu noble/main arm64 libfile-stripnondeterminism-perl all 1.13.1-1 [18.1 kB] 614s Get:39 http://ftpmaster.internal/ubuntu noble/main arm64 dh-strip-nondeterminism all 1.13.1-1 [5362 B] 614s Get:40 http://ftpmaster.internal/ubuntu noble/main arm64 libdw1 arm64 0.190-1 [254 kB] 614s Get:41 http://ftpmaster.internal/ubuntu noble/main arm64 debugedit arm64 1:5.0-5 [45.9 kB] 614s Get:42 http://ftpmaster.internal/ubuntu noble/main arm64 dwz arm64 0.15-1 [110 kB] 614s Get:43 http://ftpmaster.internal/ubuntu noble/main arm64 gettext arm64 0.21-14ubuntu1 [846 kB] 614s Get:44 http://ftpmaster.internal/ubuntu noble/main arm64 intltool-debian all 0.35.0+20060710.6 [23.2 kB] 614s Get:45 http://ftpmaster.internal/ubuntu noble/main arm64 po-debconf all 1.0.21+nmu1 [233 kB] 614s Get:46 http://ftpmaster.internal/ubuntu noble/main arm64 debhelper all 13.13ubuntu1 [868 kB] 614s Get:47 http://ftpmaster.internal/ubuntu noble/universe arm64 dh-apport all 2.28.0-0ubuntu1 [16.9 kB] 614s Get:48 http://ftpmaster.internal/ubuntu noble/main arm64 dh-golang all 1.62 [25.2 kB] 614s Get:49 http://ftpmaster.internal/ubuntu noble/main arm64 golang-1.21-src all 1.21.7-1 [19.4 MB] 615s Get:50 http://ftpmaster.internal/ubuntu noble/main arm64 golang-1.21-go arm64 1.21.7-1 [22.7 MB] 616s Get:51 http://ftpmaster.internal/ubuntu noble/main arm64 golang-src all 2:1.21~3 [4948 B] 616s Get:52 http://ftpmaster.internal/ubuntu noble/main arm64 golang-go arm64 2:1.21~3 [43.8 kB] 616s Get:53 http://ftpmaster.internal/ubuntu noble/main arm64 libstdc++-13-dev arm64 13.2.0-13ubuntu1 [2319 kB] 616s Get:54 http://ftpmaster.internal/ubuntu noble/main arm64 g++-13-aarch64-linux-gnu arm64 13.2.0-13ubuntu1 [11.7 MB] 617s Get:55 http://ftpmaster.internal/ubuntu noble/main arm64 g++-13 arm64 13.2.0-13ubuntu1 [14.0 kB] 617s Get:56 http://ftpmaster.internal/ubuntu noble/main arm64 g++-aarch64-linux-gnu arm64 4:13.2.0-7ubuntu1 [962 B] 617s Get:57 http://ftpmaster.internal/ubuntu noble/main arm64 g++ arm64 4:13.2.0-7ubuntu1 [1082 B] 617s Get:58 http://ftpmaster.internal/ubuntu noble/main arm64 build-essential arm64 12.10ubuntu1 [4932 B] 619s Fetched 108 MB in 6s (17.7 MB/s) 619s Selecting previously unselected package autotools-dev. 619s (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 ... 73875 files and directories currently installed.) 619s Preparing to unpack .../00-autotools-dev_20220109.1_all.deb ... 619s Unpacking autotools-dev (20220109.1) ... 619s Selecting previously unselected package m4. 619s Preparing to unpack .../01-m4_1.4.19-4_arm64.deb ... 619s Unpacking m4 (1.4.19-4) ... 619s Selecting previously unselected package autoconf. 619s Preparing to unpack .../02-autoconf_2.71-3_all.deb ... 619s Unpacking autoconf (2.71-3) ... 620s Selecting previously unselected package automake. 620s Preparing to unpack .../03-automake_1%3a1.16.5-1.3ubuntu1_all.deb ... 620s Unpacking automake (1:1.16.5-1.3ubuntu1) ... 620s Selecting previously unselected package autopoint. 620s Preparing to unpack .../04-autopoint_0.21-14ubuntu1_all.deb ... 620s Unpacking autopoint (0.21-14ubuntu1) ... 620s Selecting previously unselected package libdebhelper-perl. 620s Preparing to unpack .../05-libdebhelper-perl_13.13ubuntu1_all.deb ... 620s Unpacking libdebhelper-perl (13.13ubuntu1) ... 620s Selecting previously unselected package libisl23:arm64. 620s Preparing to unpack .../06-libisl23_0.26-3_arm64.deb ... 620s Unpacking libisl23:arm64 (0.26-3) ... 620s Selecting previously unselected package libmpc3:arm64. 620s Preparing to unpack .../07-libmpc3_1.3.1-1_arm64.deb ... 620s Unpacking libmpc3:arm64 (1.3.1-1) ... 620s Selecting previously unselected package cpp-13-aarch64-linux-gnu. 620s Preparing to unpack .../08-cpp-13-aarch64-linux-gnu_13.2.0-13ubuntu1_arm64.deb ... 620s Unpacking cpp-13-aarch64-linux-gnu (13.2.0-13ubuntu1) ... 622s Selecting previously unselected package cpp-13. 622s Preparing to unpack .../09-cpp-13_13.2.0-13ubuntu1_arm64.deb ... 622s Unpacking cpp-13 (13.2.0-13ubuntu1) ... 622s Selecting previously unselected package cpp-aarch64-linux-gnu. 622s Preparing to unpack .../10-cpp-aarch64-linux-gnu_4%3a13.2.0-7ubuntu1_arm64.deb ... 622s Unpacking cpp-aarch64-linux-gnu (4:13.2.0-7ubuntu1) ... 622s Selecting previously unselected package cpp. 622s Preparing to unpack .../11-cpp_4%3a13.2.0-7ubuntu1_arm64.deb ... 622s Unpacking cpp (4:13.2.0-7ubuntu1) ... 622s Selecting previously unselected package libcc1-0:arm64. 622s Preparing to unpack .../12-libcc1-0_14-20240201-3ubuntu1_arm64.deb ... 622s Unpacking libcc1-0:arm64 (14-20240201-3ubuntu1) ... 622s Selecting previously unselected package libgomp1:arm64. 622s Preparing to unpack .../13-libgomp1_14-20240201-3ubuntu1_arm64.deb ... 622s Unpacking libgomp1:arm64 (14-20240201-3ubuntu1) ... 622s Selecting previously unselected package libitm1:arm64. 622s Preparing to unpack .../14-libitm1_14-20240201-3ubuntu1_arm64.deb ... 622s Unpacking libitm1:arm64 (14-20240201-3ubuntu1) ... 622s Selecting previously unselected package libatomic1:arm64. 622s Preparing to unpack .../15-libatomic1_14-20240201-3ubuntu1_arm64.deb ... 622s Unpacking libatomic1:arm64 (14-20240201-3ubuntu1) ... 622s Selecting previously unselected package libasan8:arm64. 622s Preparing to unpack .../16-libasan8_14-20240201-3ubuntu1_arm64.deb ... 622s Unpacking libasan8:arm64 (14-20240201-3ubuntu1) ... 623s Selecting previously unselected package liblsan0:arm64. 623s Preparing to unpack .../17-liblsan0_14-20240201-3ubuntu1_arm64.deb ... 623s Unpacking liblsan0:arm64 (14-20240201-3ubuntu1) ... 623s Selecting previously unselected package libtsan2:arm64. 623s Preparing to unpack .../18-libtsan2_14-20240201-3ubuntu1_arm64.deb ... 623s Unpacking libtsan2:arm64 (14-20240201-3ubuntu1) ... 623s Selecting previously unselected package libubsan1:arm64. 623s Preparing to unpack .../19-libubsan1_14-20240201-3ubuntu1_arm64.deb ... 623s Unpacking libubsan1:arm64 (14-20240201-3ubuntu1) ... 624s Selecting previously unselected package libhwasan0:arm64. 624s Preparing to unpack .../20-libhwasan0_14-20240201-3ubuntu1_arm64.deb ... 624s Unpacking libhwasan0:arm64 (14-20240201-3ubuntu1) ... 624s Selecting previously unselected package libgcc-13-dev:arm64. 624s Preparing to unpack .../21-libgcc-13-dev_13.2.0-13ubuntu1_arm64.deb ... 624s Unpacking libgcc-13-dev:arm64 (13.2.0-13ubuntu1) ... 624s Selecting previously unselected package gcc-13-aarch64-linux-gnu. 625s Preparing to unpack .../22-gcc-13-aarch64-linux-gnu_13.2.0-13ubuntu1_arm64.deb ... 625s Unpacking gcc-13-aarch64-linux-gnu (13.2.0-13ubuntu1) ... 627s Selecting previously unselected package gcc-13. 627s Preparing to unpack .../23-gcc-13_13.2.0-13ubuntu1_arm64.deb ... 627s Unpacking gcc-13 (13.2.0-13ubuntu1) ... 627s Selecting previously unselected package gcc-aarch64-linux-gnu. 627s Preparing to unpack .../24-gcc-aarch64-linux-gnu_4%3a13.2.0-7ubuntu1_arm64.deb ... 627s Unpacking gcc-aarch64-linux-gnu (4:13.2.0-7ubuntu1) ... 627s Selecting previously unselected package gcc. 627s Preparing to unpack .../25-gcc_4%3a13.2.0-7ubuntu1_arm64.deb ... 627s Unpacking gcc (4:13.2.0-7ubuntu1) ... 627s Selecting previously unselected package libc-dev-bin. 627s Preparing to unpack .../26-libc-dev-bin_2.39-0ubuntu2_arm64.deb ... 627s Unpacking libc-dev-bin (2.39-0ubuntu2) ... 628s Selecting previously unselected package linux-libc-dev:arm64. 628s Preparing to unpack .../27-linux-libc-dev_6.6.0-14.14_arm64.deb ... 628s Unpacking linux-libc-dev:arm64 (6.6.0-14.14) ... 629s Selecting previously unselected package libcrypt-dev:arm64. 629s Preparing to unpack .../28-libcrypt-dev_1%3a4.4.36-4_arm64.deb ... 629s Unpacking libcrypt-dev:arm64 (1:4.4.36-4) ... 629s Selecting previously unselected package libtirpc-dev:arm64. 629s Preparing to unpack .../29-libtirpc-dev_1.3.4+ds-1build1_arm64.deb ... 629s Unpacking libtirpc-dev:arm64 (1.3.4+ds-1build1) ... 629s Selecting previously unselected package libnsl-dev:arm64. 629s Preparing to unpack .../30-libnsl-dev_1.3.0-3_arm64.deb ... 629s Unpacking libnsl-dev:arm64 (1.3.0-3) ... 629s Selecting previously unselected package rpcsvc-proto. 629s Preparing to unpack .../31-rpcsvc-proto_1.4.2-0ubuntu6_arm64.deb ... 629s Unpacking rpcsvc-proto (1.4.2-0ubuntu6) ... 629s Selecting previously unselected package libc6-dev:arm64. 629s Preparing to unpack .../32-libc6-dev_2.39-0ubuntu2_arm64.deb ... 629s Unpacking libc6-dev:arm64 (2.39-0ubuntu2) ... 630s Selecting previously unselected package libtool. 630s Preparing to unpack .../33-libtool_2.4.7-7_all.deb ... 630s Unpacking libtool (2.4.7-7) ... 630s Selecting previously unselected package dh-autoreconf. 630s Preparing to unpack .../34-dh-autoreconf_20_all.deb ... 630s Unpacking dh-autoreconf (20) ... 630s Selecting previously unselected package libarchive-zip-perl. 630s Preparing to unpack .../35-libarchive-zip-perl_1.68-1_all.deb ... 630s Unpacking libarchive-zip-perl (1.68-1) ... 630s Selecting previously unselected package libsub-override-perl. 630s Preparing to unpack .../36-libsub-override-perl_0.10-1_all.deb ... 630s Unpacking libsub-override-perl (0.10-1) ... 630s Selecting previously unselected package libfile-stripnondeterminism-perl. 630s Preparing to unpack .../37-libfile-stripnondeterminism-perl_1.13.1-1_all.deb ... 630s Unpacking libfile-stripnondeterminism-perl (1.13.1-1) ... 631s Selecting previously unselected package dh-strip-nondeterminism. 631s Preparing to unpack .../38-dh-strip-nondeterminism_1.13.1-1_all.deb ... 631s Unpacking dh-strip-nondeterminism (1.13.1-1) ... 631s Selecting previously unselected package libdw1:arm64. 631s Preparing to unpack .../39-libdw1_0.190-1_arm64.deb ... 631s Unpacking libdw1:arm64 (0.190-1) ... 634s Selecting previously unselected package debugedit. 634s Preparing to unpack .../40-debugedit_1%3a5.0-5_arm64.deb ... 634s Unpacking debugedit (1:5.0-5) ... 634s Selecting previously unselected package dwz. 634s Preparing to unpack .../41-dwz_0.15-1_arm64.deb ... 634s Unpacking dwz (0.15-1) ... 634s Selecting previously unselected package gettext. 634s Preparing to unpack .../42-gettext_0.21-14ubuntu1_arm64.deb ... 634s Unpacking gettext (0.21-14ubuntu1) ... 634s Selecting previously unselected package intltool-debian. 634s Preparing to unpack .../43-intltool-debian_0.35.0+20060710.6_all.deb ... 634s Unpacking intltool-debian (0.35.0+20060710.6) ... 634s Selecting previously unselected package po-debconf. 634s Preparing to unpack .../44-po-debconf_1.0.21+nmu1_all.deb ... 634s Unpacking po-debconf (1.0.21+nmu1) ... 634s Selecting previously unselected package debhelper. 634s Preparing to unpack .../45-debhelper_13.13ubuntu1_all.deb ... 634s Unpacking debhelper (13.13ubuntu1) ... 634s Selecting previously unselected package dh-apport. 634s Preparing to unpack .../46-dh-apport_2.28.0-0ubuntu1_all.deb ... 634s Unpacking dh-apport (2.28.0-0ubuntu1) ... 634s Selecting previously unselected package dh-golang. 634s Preparing to unpack .../47-dh-golang_1.62_all.deb ... 634s Unpacking dh-golang (1.62) ... 634s Selecting previously unselected package golang-1.21-src. 634s Preparing to unpack .../48-golang-1.21-src_1.21.7-1_all.deb ... 634s Unpacking golang-1.21-src (1.21.7-1) ... 646s Selecting previously unselected package golang-1.21-go. 646s Preparing to unpack .../49-golang-1.21-go_1.21.7-1_arm64.deb ... 646s Unpacking golang-1.21-go (1.21.7-1) ... 650s Selecting previously unselected package golang-src. 650s Preparing to unpack .../50-golang-src_2%3a1.21~3_all.deb ... 650s Unpacking golang-src (2:1.21~3) ... 650s Selecting previously unselected package golang-go:arm64. 650s Preparing to unpack .../51-golang-go_2%3a1.21~3_arm64.deb ... 650s Unpacking golang-go:arm64 (2:1.21~3) ... 650s Selecting previously unselected package libstdc++-13-dev:arm64. 650s Preparing to unpack .../52-libstdc++-13-dev_13.2.0-13ubuntu1_arm64.deb ... 650s Unpacking libstdc++-13-dev:arm64 (13.2.0-13ubuntu1) ... 653s Selecting previously unselected package g++-13-aarch64-linux-gnu. 653s Preparing to unpack .../53-g++-13-aarch64-linux-gnu_13.2.0-13ubuntu1_arm64.deb ... 653s Unpacking g++-13-aarch64-linux-gnu (13.2.0-13ubuntu1) ... 653s Selecting previously unselected package g++-13. 653s Preparing to unpack .../54-g++-13_13.2.0-13ubuntu1_arm64.deb ... 653s Unpacking g++-13 (13.2.0-13ubuntu1) ... 653s Selecting previously unselected package g++-aarch64-linux-gnu. 653s Preparing to unpack .../55-g++-aarch64-linux-gnu_4%3a13.2.0-7ubuntu1_arm64.deb ... 653s Unpacking g++-aarch64-linux-gnu (4:13.2.0-7ubuntu1) ... 653s Selecting previously unselected package g++. 653s Preparing to unpack .../56-g++_4%3a13.2.0-7ubuntu1_arm64.deb ... 653s Unpacking g++ (4:13.2.0-7ubuntu1) ... 653s Selecting previously unselected package build-essential. 653s Preparing to unpack .../57-build-essential_12.10ubuntu1_arm64.deb ... 653s Unpacking build-essential (12.10ubuntu1) ... 654s Setting up libdw1:arm64 (0.190-1) ... 654s Setting up libarchive-zip-perl (1.68-1) ... 654s Setting up libdebhelper-perl (13.13ubuntu1) ... 654s Setting up linux-libc-dev:arm64 (6.6.0-14.14) ... 654s Setting up m4 (1.4.19-4) ... 654s Setting up libgomp1:arm64 (14-20240201-3ubuntu1) ... 654s Setting up dh-apport (2.28.0-0ubuntu1) ... 654s Setting up autotools-dev (20220109.1) ... 654s Setting up libtirpc-dev:arm64 (1.3.4+ds-1build1) ... 654s Setting up rpcsvc-proto (1.4.2-0ubuntu6) ... 654s Setting up golang-1.21-src (1.21.7-1) ... 654s Setting up libmpc3:arm64 (1.3.1-1) ... 654s Setting up libatomic1:arm64 (14-20240201-3ubuntu1) ... 654s Setting up autopoint (0.21-14ubuntu1) ... 654s Setting up autoconf (2.71-3) ... 654s Setting up libubsan1:arm64 (14-20240201-3ubuntu1) ... 654s Setting up dwz (0.15-1) ... 654s Setting up libnsl-dev:arm64 (1.3.0-3) ... 654s Setting up libhwasan0:arm64 (14-20240201-3ubuntu1) ... 654s Setting up libcrypt-dev:arm64 (1:4.4.36-4) ... 654s Setting up libasan8:arm64 (14-20240201-3ubuntu1) ... 654s Setting up debugedit (1:5.0-5) ... 654s Setting up libsub-override-perl (0.10-1) ... 654s Setting up libtsan2:arm64 (14-20240201-3ubuntu1) ... 654s Setting up libisl23:arm64 (0.26-3) ... 654s Setting up libc-dev-bin (2.39-0ubuntu2) ... 654s Setting up golang-src (2:1.21~3) ... 654s Setting up libcc1-0:arm64 (14-20240201-3ubuntu1) ... 654s Setting up liblsan0:arm64 (14-20240201-3ubuntu1) ... 654s Setting up libitm1:arm64 (14-20240201-3ubuntu1) ... 654s Setting up automake (1:1.16.5-1.3ubuntu1) ... 654s update-alternatives: using /usr/bin/automake-1.16 to provide /usr/bin/automake (automake) in auto mode 654s Setting up libfile-stripnondeterminism-perl (1.13.1-1) ... 654s Setting up gettext (0.21-14ubuntu1) ... 654s Setting up cpp-13-aarch64-linux-gnu (13.2.0-13ubuntu1) ... 654s Setting up golang-1.21-go (1.21.7-1) ... 654s Setting up intltool-debian (0.35.0+20060710.6) ... 654s Setting up cpp-aarch64-linux-gnu (4:13.2.0-7ubuntu1) ... 654s Setting up dh-strip-nondeterminism (1.13.1-1) ... 654s Setting up libgcc-13-dev:arm64 (13.2.0-13ubuntu1) ... 654s Setting up libc6-dev:arm64 (2.39-0ubuntu2) ... 654s Setting up libstdc++-13-dev:arm64 (13.2.0-13ubuntu1) ... 654s Setting up cpp-13 (13.2.0-13ubuntu1) ... 654s Setting up golang-go:arm64 (2:1.21~3) ... 654s Setting up po-debconf (1.0.21+nmu1) ... 654s Setting up gcc-13-aarch64-linux-gnu (13.2.0-13ubuntu1) ... 654s Setting up gcc-13 (13.2.0-13ubuntu1) ... 654s Setting up cpp (4:13.2.0-7ubuntu1) ... 654s Setting up g++-13-aarch64-linux-gnu (13.2.0-13ubuntu1) ... 654s Setting up gcc-aarch64-linux-gnu (4:13.2.0-7ubuntu1) ... 654s Setting up g++-13 (13.2.0-13ubuntu1) ... 654s Setting up libtool (2.4.7-7) ... 654s Setting up gcc (4:13.2.0-7ubuntu1) ... 654s Setting up dh-autoreconf (20) ... 654s Setting up g++-aarch64-linux-gnu (4:13.2.0-7ubuntu1) ... 654s Setting up debhelper (13.13ubuntu1) ... 654s Setting up g++ (4:13.2.0-7ubuntu1) ... 654s update-alternatives: using /usr/bin/g++ to provide /usr/bin/c++ (c++) in auto mode 654s Setting up build-essential (12.10ubuntu1) ... 654s Setting up dh-golang (1.62) ... 654s Setting up autopkgtest-satdep (0) ... 654s Processing triggers for man-db (2.12.0-3) ... 657s Processing triggers for install-info (7.1-3) ... 658s Processing triggers for libc-bin (2.39-0ubuntu2) ... 668s (Reading database ... 91789 files and directories currently installed.) 668s Removing autopkgtest-satdep (0) ... 670s autopkgtest [10:45:55]: test command1: ./debian/tests/test 670s autopkgtest [10:45:55]: test command1: [----------------------- 939s === RUN TestRunSignal 939s === RUN TestRunSignal/Send_SIGINT_exits 939s === RUN TestRunSignal/Send_SIGTERM_exits 939s --- PASS: TestRunSignal (0.20s) 939s --- PASS: TestRunSignal/Send_SIGINT_exits (0.10s) 939s --- PASS: TestRunSignal/Send_SIGTERM_exits (0.10s) 939s === RUN TestRun 939s === PAUSE TestRun 939s === CONT TestRun 939s === RUN TestRun/Run_and_exit_successfully 939s === PAUSE TestRun/Run_and_exit_successfully 939s === RUN TestRun/Run_and_return_error 939s === PAUSE TestRun/Run_and_return_error 939s === RUN TestRun/Run_and_return_usage_error 939s === PAUSE TestRun/Run_and_return_usage_error 939s === RUN TestRun/Run_and_usage_error_only_does_not_fail 939s === PAUSE TestRun/Run_and_usage_error_only_does_not_fail 939s === CONT TestRun/Run_and_exit_successfully 939s === CONT TestRun/Run_and_usage_error_only_does_not_fail 939s === CONT TestRun/Run_and_return_usage_error 939s ERROR context.Background Error requested 939s === CONT TestRun/Run_and_return_error 939s ERROR context.Background Error requested 939s --- PASS: TestRun (0.00s) 939s --- PASS: TestRun/Run_and_exit_successfully (0.10s) 939s --- PASS: TestRun/Run_and_usage_error_only_does_not_fail (0.10s) 939s --- PASS: TestRun/Run_and_return_usage_error (0.10s) 939s --- PASS: TestRun/Run_and_return_error (0.10s) 939s PASS 939s ok github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/cmd/wsl-pro-service 0.636s 944s === RUN TestHelp 944s --- PASS: TestHelp (0.01s) 944s === RUN TestCompletion 944s --- PASS: TestCompletion (0.01s) 944s === RUN TestVersion 944s --- PASS: TestVersion (0.01s) 944s === RUN TestNoUsageError 944s --- PASS: TestNoUsageError (0.01s) 944s === RUN TestUsageError 944s === PAUSE TestUsageError 944s === RUN TestCanQuitWhenExecute 944s === PAUSE TestCanQuitWhenExecute 944s === RUN TestCanQuitTwice 944s === PAUSE TestCanQuitTwice 944s === RUN TestAppCanQuitWithoutExecute 944s === PAUSE TestAppCanQuitWithoutExecute 944s === RUN TestAppRunFailsOnComponentsCreationAndQuit 944s === PAUSE TestAppRunFailsOnComponentsCreationAndQuit 944s === RUN TestAppGetRootCmd 944s === PAUSE TestAppGetRootCmd 944s === RUN TestWithProMock 944s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 944s --- SKIP: TestWithProMock (0.00s) 944s === RUN TestWithWslPathMock 944s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 944s --- SKIP: TestWithWslPathMock (0.00s) 944s === RUN TestWithWslInfoMock 944s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 944s --- SKIP: TestWithWslInfoMock (0.00s) 944s === RUN TestWithCmdExeMock 944s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 944s --- SKIP: TestWithCmdExeMock (0.00s) 944s === CONT TestUsageError 944s --- PASS: TestUsageError (0.01s) 944s === CONT TestAppGetRootCmd 944s --- PASS: TestAppGetRootCmd (0.02s) 944s === CONT TestAppRunFailsOnComponentsCreationAndQuit 960s --- PASS: TestAppRunFailsOnComponentsCreationAndQuit (15.74s) 960s === CONT TestAppCanQuitWithoutExecute 960s service_test.go:138: This test is skipped because it is flaky. There is no way to guarantee Quit has been called before run. 960s --- SKIP: TestAppCanQuitWithoutExecute (0.00s) 960s === CONT TestCanQuitTwice 960s time="2024-02-23T10:50:45Z" level=debug msg="/tmp/autopkgtest.auHzp8/build.fLD/src/cmd/wsl-pro-service/service/service.go:67 New.func1() Debug mode is enabled" 960s time="2024-02-23T10:50:45Z" level=debug msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:63 New() Building new daemon" 971s time="2024-02-23T10:50:56Z" level=info msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:256 (*Daemon).Quit() Stopping daemon requested." 971s time="2024-02-23T10:50:56Z" level=info msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:265 (*Daemon).Quit() Waiting for active requests to close." 976s time="2024-02-23T10:51:01Z" level=info msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/controlstream/session.go:23 newSession() Connecting to control stream at \"127.0.0.1:45811\"" 976s time="2024-02-23T10:51:01Z" level=debug msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/controlstream/controlstream.go:69 (*ControlStream).Connect() Connected to Windows agent via the control stream" 976s time="2024-02-23T10:51:01Z" level=info msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/testutils/mock_agent.go:136 (*wslInstanceMockService).Connected() wslInstanceMockService: Received incoming connection" 981s time="2024-02-23T10:51:06Z" level=info msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/testutils/mock_agent.go:150 (*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\"" 981s time="2024-02-23T10:51:06Z" level=info msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/testutils/mock_agent.go:178 (*wslInstanceMockService).Connected() wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 39793" 981s time="2024-02-23T10:51:06Z" level=debug msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/controlstream/controlstream.go:76 (*ControlStream).Connect() Completed handshake with Windows agent via the control stream" 981s time="2024-02-23T10:51:06Z" level=info msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:176 (*Daemon).serveOnce() Connected to control stream" 981s time="2024-02-23T10:51:06Z" level=debug msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/wslinstanceservice/wslinstanceservice.go:41 (*Service).RegisterGRPCService() Registering GRPC WSL instance service" 981s time="2024-02-23T10:51:06Z" level=debug msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:223 (*Daemon).serve() Starting to serve requests" 981s time="2024-02-23T10:51:06Z" level=info msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:233 (*Daemon).serve() Serving GRPC requests on localhost:39793" 981s time="2024-02-23T10:51:06Z" level=error msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:142 (*Daemon).Serve() serve error: WSL Pro Service stopped serving: grpc error: grpc: the server has been stopped" 981s time="2024-02-23T10:51:06Z" level=debug msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:267 (*Daemon).Quit() All connections have now ended." 981s time="2024-02-23T10:51:06Z" level=info msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:256 (*Daemon).Quit() Stopping daemon requested." 981s time="2024-02-23T10:51:06Z" level=info msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:265 (*Daemon).Quit() Waiting for active requests to close." 981s time="2024-02-23T10:51:06Z" level=debug msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:267 (*Daemon).Quit() All connections have now ended." 981s time="2024-02-23T10:51:06Z" level=info msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:256 (*Daemon).Quit() Stopping daemon requested." 981s time="2024-02-23T10:51:06Z" level=info msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:265 (*Daemon).Quit() Waiting for active requests to close." 981s time="2024-02-23T10:51:06Z" level=debug msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:267 (*Daemon).Quit() All connections have now ended." 981s --- PASS: TestCanQuitTwice (21.51s) 981s === CONT TestCanQuitWhenExecute 981s time="2024-02-23T10:51:06Z" level=info msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/testutils/mock_agent.go:82 MockWindowsAgent.func1() MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:39477\"" 981s time="2024-02-23T10:51:06Z" level=debug msg="/tmp/autopkgtest.auHzp8/build.fLD/src/cmd/wsl-pro-service/service/service.go:67 New.func1() Debug mode is enabled" 981s time="2024-02-23T10:51:06Z" level=debug msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:63 New() Building new daemon" 991s time="2024-02-23T10:51:16Z" level=info msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:256 (*Daemon).Quit() Stopping daemon requested." 991s time="2024-02-23T10:51:16Z" level=info msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:265 (*Daemon).Quit() Waiting for active requests to close." 995s time="2024-02-23T10:51:20Z" level=error msg="/tmp/autopkgtest.auHzp8/build.fLD/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/TestCanQuitWhenExecute1714803929/001/mnt/d/Users/TestUser/.ubuntupro/.address\": open /tmp/TestCanQuitWhenExecute1714803929/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 995s time="2024-02-23T10:51:20Z" level=debug msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:267 (*Daemon).Quit() All connections have now ended." 995s time="2024-02-23T10:51:20Z" level=info msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:256 (*Daemon).Quit() Stopping daemon requested." 995s time="2024-02-23T10:51:20Z" level=info msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:265 (*Daemon).Quit() Waiting for active requests to close." 995s time="2024-02-23T10:51:20Z" level=debug msg="/tmp/autopkgtest.auHzp8/build.fLD/src/internal/daemon/daemon.go:267 (*Daemon).Quit() All connections have now ended." 995s --- PASS: TestCanQuitWhenExecute (13.93s) 995s PASS 995s ok github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/cmd/wsl-pro-service/service 51.299s 995s ? github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/generate/doc [no test files] 995s ? github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/internal/consts [no test files] 998s === RUN TestNew 998s === PAUSE TestNew 998s === RUN TestConnect 998s === PAUSE TestConnect 998s === RUN TestSend 998s === PAUSE TestSend 998s === RUN TestReconnection 998s === PAUSE TestReconnection 998s === RUN TestWithProMock 998s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 998s --- SKIP: TestWithProMock (0.00s) 998s === RUN TestWithWslPathMock 998s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 998s --- SKIP: TestWithWslPathMock (0.00s) 998s === RUN TestWithWslInfoMock 998s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 998s --- SKIP: TestWithWslInfoMock (0.00s) 998s === RUN TestWithCmdExeMock 998s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 998s --- SKIP: TestWithCmdExeMock (0.00s) 998s === CONT TestNew 998s === RUN TestNew/Success 998s === PAUSE TestNew/Success 998s === RUN TestNew/Error_when_the_context_is_cancelled 998s === PAUSE TestNew/Error_when_the_context_is_cancelled 998s === RUN TestNew/Error_when_WslPath_returns_error 998s === PAUSE TestNew/Error_when_WslPath_returns_error 998s === CONT TestReconnection 998s === RUN TestReconnection/Success_connecting_after_failing_to_connect 998s === PAUSE TestReconnection/Success_connecting_after_failing_to_connect 998s === RUN TestReconnection/Success_connecting_after_previous_connection_dropped 998s === PAUSE TestReconnection/Success_connecting_after_previous_connection_dropped 998s === CONT TestSend 998s time="2024-02-23T10:51:23Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:41805\"" 1010s time="2024-02-23T10:51:35Z" level=info msg="Connecting to control stream at \"127.0.0.1:41805\"" 1010s time="2024-02-23T10:51:35Z" level=debug msg="Connected to Windows agent via the control stream" 1010s time="2024-02-23T10:51:35Z" level=info msg="wslInstanceMockService: Received incoming connection" 1015s time="2024-02-23T10:51:40Z" 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\"" 1015s time="2024-02-23T10:51:40Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 38369" 1015s time="2024-02-23T10:51:40Z" level=debug msg="Completed handshake with Windows agent via the control stream" 1020s time="2024-02-23T10:51:45Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": connected back via reserved port" 1020s time="2024-02-23T10:51:45Z" 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\"" 1021s time="2024-02-23T10:51:46Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\" ended: rpc error: code = Canceled desc = context canceled" 1021s time="2024-02-23T10:51:46Z" level=info msg="wslInstanceMockService: dropped connection" 1021s --- PASS: TestSend (23.08s) 1021s === CONT TestConnect 1021s === RUN TestConnect/Incomplete_handshake_because_Agent_sends_port_:0 1021s === PAUSE TestConnect/Incomplete_handshake_because_Agent_sends_port_:0 1021s === RUN TestConnect/Success 1021s === PAUSE TestConnect/Success 1021s === RUN TestConnect/No_connection_because_of_unreadable_port_file 1021s === PAUSE TestConnect/No_connection_because_of_unreadable_port_file 1021s === RUN TestConnect/No_connection_because_of_port_file_with_invalid_contents 1021s === PAUSE TestConnect/No_connection_because_of_port_file_with_invalid_contents 1021s === RUN TestConnect/No_connection_because_of_port_file_contains_the_wrong_port 1021s === PAUSE TestConnect/No_connection_because_of_port_file_contains_the_wrong_port 1021s === RUN TestConnect/Error_because_WindowsForwardedLocalhost_returns_error 1021s === PAUSE TestConnect/Error_because_WindowsForwardedLocalhost_returns_error 1021s === RUN TestConnect/Incomplete_handshake_because_Agent_never_receives 1021s === PAUSE TestConnect/Incomplete_handshake_because_Agent_never_receives 1021s === RUN TestConnect/Incomplete_handshake_because_Agent_never_sends_a_port 1021s === PAUSE TestConnect/Incomplete_handshake_because_Agent_never_sends_a_port 1021s === RUN TestConnect/No_connection_because_port_file_does_not_exist 1021s === PAUSE TestConnect/No_connection_because_port_file_does_not_exist 1021s === RUN TestConnect/No_connection_because_of_empty_port_file 1021s === PAUSE TestConnect/No_connection_because_of_empty_port_file 1021s === CONT TestNew/Success 1029s === CONT TestReconnection/Success_connecting_after_failing_to_connect 1042s time="2024-02-23T10:52:07Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:34967\"" 1047s time="2024-02-23T10:52:12Z" level=info msg="Connecting to control stream at \"127.0.0.1:34967\"" 1047s time="2024-02-23T10:52:12Z" level=debug msg="Connected to Windows agent via the control stream" 1047s time="2024-02-23T10:52:12Z" level=info msg="wslInstanceMockService: Received incoming connection" 1052s time="2024-02-23T10:52:17Z" 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\"" 1052s time="2024-02-23T10:52:17Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 36985" 1052s time="2024-02-23T10:52:17Z" level=debug msg="Completed handshake with Windows agent via the control stream" 1052s time="2024-02-23T10:52:17Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestReconnectionSuccess_connecting_after_failing_to_connect3644918486/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1052s === CONT TestNew/Error_when_WslPath_returns_error 1061s === CONT TestNew/Error_when_the_context_is_cancelled 1061s --- PASS: TestNew (0.00s) 1061s --- PASS: TestNew/Success (8.61s) 1061s --- PASS: TestNew/Error_when_WslPath_returns_error (9.23s) 1061s --- PASS: TestNew/Error_when_the_context_is_cancelled (0.01s) 1061s === CONT TestReconnection/Success_connecting_after_previous_connection_dropped 1069s time="2024-02-23T10:52:34Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:33575\"" 1073s time="2024-02-23T10:52:38Z" level=info msg="Connecting to control stream at \"127.0.0.1:33575\"" 1073s time="2024-02-23T10:52:38Z" level=debug msg="Connected to Windows agent via the control stream" 1073s time="2024-02-23T10:52:38Z" level=info msg="wslInstanceMockService: Received incoming connection" 1077s time="2024-02-23T10:52:42Z" level=warning msg="wslInstanceMockService: dropped connection: wslInstanceMockService: could not dial \"TEST_DISTRO\": dial tcp4 127.0.0.1:36985: connect: connection refused" 1078s time="2024-02-23T10:52:43Z" 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\"" 1078s time="2024-02-23T10:52:43Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 37797" 1078s time="2024-02-23T10:52:43Z" level=debug msg="Completed handshake with Windows agent via the control stream" 1078s time="2024-02-23T10:52:43Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:33361\"" 1082s time="2024-02-23T10:52:47Z" level=info msg="Connecting to control stream at \"127.0.0.1:33361\"" 1082s time="2024-02-23T10:52:47Z" level=debug msg="Connected to Windows agent via the control stream" 1082s time="2024-02-23T10:52:47Z" level=info msg="wslInstanceMockService: Received incoming connection" 1087s time="2024-02-23T10:52:52Z" 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\"" 1087s time="2024-02-23T10:52:52Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 40509" 1087s time="2024-02-23T10:52:52Z" level=debug msg="Completed handshake with Windows agent via the control stream" 1087s --- PASS: TestReconnection (0.00s) 1087s --- PASS: TestReconnection/Success_connecting_after_failing_to_connect (22.24s) 1087s --- PASS: TestReconnection/Success_connecting_after_previous_connection_dropped (25.89s) 1087s === CONT TestConnect/Incomplete_handshake_because_Agent_sends_port_:0 1087s time="2024-02-23T10:52:52Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:44733\"" 1102s time="2024-02-23T10:53:07Z" level=info msg="Connecting to control stream at \"127.0.0.1:44733\"" 1102s time="2024-02-23T10:53:07Z" level=debug msg="Connected to Windows agent via the control stream" 1102s time="2024-02-23T10:53:07Z" level=info msg="wslInstanceMockService: Received incoming connection" 1103s time="2024-02-23T10:53:08Z" level=warning msg="wslInstanceMockService: dropped connection: wslInstanceMockService: could not dial \"TEST_DISTRO\": dial tcp4 127.0.0.1:37797: connect: connection refused" 1106s time="2024-02-23T10:53:11Z" 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\"" 1106s time="2024-02-23T10:53:11Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Sending bad port 0" 1106s time="2024-02-23T10:53:11Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestConnectIncomplete_handshake_because_Agent_sends_port_02024146870/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1106s === CONT TestConnect/No_connection_because_of_empty_port_file 1106s time="2024-02-23T10:53:11Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:39417\"" 1112s time="2024-02-23T10:53:17Z" level=warning msg="wslInstanceMockService: dropped connection: wslInstanceMockService: could not dial \"TEST_DISTRO\": dial tcp4 127.0.0.1:40509: connect: connection refused" 1121s time="2024-02-23T10:53:26Z" level=info msg="Connecting to control stream at \"127.0.0.1:\"" 1121s time="2024-02-23T10:53:26Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestConnectNo_connection_because_of_empty_port_file4015810697/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1121s === CONT TestConnect/No_connection_because_port_file_does_not_exist 1121s time="2024-02-23T10:53:26Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:39229\"" 1131s time="2024-02-23T10:53:36Z" level=warning msg="wslInstanceMockService: dropped connection: wslInstanceMockService: could not dial \"TEST_DISTRO\": dial tcp4 127.0.0.1:0: connect: connection refused" 1135s time="2024-02-23T10:53:40Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestConnectNo_connection_because_port_file_does_not_exist951103802/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1135s === CONT TestConnect/Incomplete_handshake_because_Agent_never_sends_a_port 1135s time="2024-02-23T10:53:40Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:40821\"" 1149s time="2024-02-23T10:53:54Z" level=info msg="Connecting to control stream at \"127.0.0.1:40821\"" 1149s time="2024-02-23T10:53:54Z" level=debug msg="Connected to Windows agent via the control stream" 1149s time="2024-02-23T10:53:54Z" level=info msg="wslInstanceMockService: Received incoming connection" 1153s time="2024-02-23T10:53:58Z" 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\"" 1153s time="2024-02-23T10:53:58Z" level=info msg="connection with \"TEST_DISTRO\": mock error: dropping stream before sending port" 1153s time="2024-02-23T10:53:58Z" level=info msg="wslInstanceMockService: dropped connection" 1153s === CONT TestConnect/Incomplete_handshake_because_Agent_never_receives 1153s time="2024-02-23T10:53:58Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:40445\"" 1168s time="2024-02-23T10:54:13Z" level=info msg="Connecting to control stream at \"127.0.0.1:40445\"" 1168s time="2024-02-23T10:54:13Z" level=debug msg="Connected to Windows agent via the control stream" 1168s time="2024-02-23T10:54:13Z" level=info msg="wslInstanceMockService: Received incoming connection" 1168s time="2024-02-23T10:54:13Z" level=info msg="wslInstanceMockService: mock error: dropping stream before first Recv" 1168s time="2024-02-23T10:54:13Z" level=info msg="wslInstanceMockService: dropped connection" 1172s time="2024-02-23T10:54:17Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestConnectIncomplete_handshake_because_Agent_never_receives2633617365/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1172s === CONT TestConnect/Error_because_WindowsForwardedLocalhost_returns_error 1172s time="2024-02-23T10:54:17Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:34683\"" 1186s === CONT TestConnect/No_connection_because_of_port_file_contains_the_wrong_port 1186s time="2024-02-23T10:54:31Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:35395\"" 1200s time="2024-02-23T10:54:45Z" level=info msg="Connecting to control stream at \"127.0.0.1:43255\"" 1200s time="2024-02-23T10:54:45Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestConnectNo_connection_because_of_port_file_contains_the_wrong_port380635332/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1200s === CONT TestConnect/No_connection_because_of_port_file_with_invalid_contents 1200s time="2024-02-23T10:54:45Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:41205\"" 1212s time="2024-02-23T10:54:57Z" level=info msg="Connecting to control stream at \"127.0.0.1:This text is not a valid IP address\"" 1212s === CONT TestConnect/No_connection_because_of_unreadable_port_file 1212s time="2024-02-23T10:54:57Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:40675\"" 1226s time="2024-02-23T10:55:11Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestConnectNo_connection_because_of_unreadable_port_file4109026110/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1226s === CONT TestConnect/Success 1226s time="2024-02-23T10:55:11Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:41731\"" 1239s time="2024-02-23T10:55:24Z" level=info msg="Connecting to control stream at \"127.0.0.1:41731\"" 1239s time="2024-02-23T10:55:24Z" level=debug msg="Connected to Windows agent via the control stream" 1239s time="2024-02-23T10:55:24Z" level=info msg="wslInstanceMockService: Received incoming connection" 1244s time="2024-02-23T10:55:28Z" 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\"" 1244s time="2024-02-23T10:55:28Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 40605" 1244s time="2024-02-23T10:55:28Z" level=debug msg="Completed handshake with Windows agent via the control stream" 1245s time="2024-02-23T10:55:29Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestConnectSuccess1888564390/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1245s --- PASS: TestConnect (0.00s) 1245s --- PASS: TestConnect/Incomplete_handshake_because_Agent_sends_port_:0 (19.66s) 1245s --- PASS: TestConnect/No_connection_because_of_empty_port_file (14.73s) 1245s --- PASS: TestConnect/No_connection_because_port_file_does_not_exist (13.46s) 1245s --- PASS: TestConnect/Incomplete_handshake_because_Agent_never_sends_a_port (18.73s) 1245s --- PASS: TestConnect/Incomplete_handshake_because_Agent_never_receives (18.88s) 1245s --- PASS: TestConnect/Error_because_WindowsForwardedLocalhost_returns_error (14.10s) 1245s --- PASS: TestConnect/No_connection_because_of_port_file_contains_the_wrong_port (13.61s) 1245s --- PASS: TestConnect/No_connection_because_of_port_file_with_invalid_contents (12.45s) 1245s --- PASS: TestConnect/No_connection_because_of_unreadable_port_file (13.25s) 1245s --- PASS: TestConnect/Success (18.87s) 1245s PASS 1245s ok github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/internal/controlstream 246.849s 1248s === RUN TestNew 1248s === PAUSE TestNew 1248s === RUN TestServe 1248s === PAUSE TestServe 1248s === RUN TestServeAndQuit 1248s === PAUSE TestServeAndQuit 1248s === RUN TestReconnection 1248s === PAUSE TestReconnection 1248s === RUN TestWithProMock 1248s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 1248s --- SKIP: TestWithProMock (0.00s) 1248s === RUN TestWithWslPathMock 1248s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 1248s --- SKIP: TestWithWslPathMock (0.00s) 1248s === RUN TestWithWslInfoMock 1248s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 1248s --- SKIP: TestWithWslInfoMock (0.00s) 1248s === RUN TestWithCmdExeMock 1248s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 1248s --- SKIP: TestWithCmdExeMock (0.00s) 1248s === CONT TestNew 1248s === RUN TestNew/Success 1248s === PAUSE TestNew/Success 1248s === RUN TestNew/Error_when_WslPath_returns_error 1248s === PAUSE TestNew/Error_when_WslPath_returns_error 1248s === CONT TestNew/Success 1248s time="2024-02-23T10:55:33Z" level=debug msg="Building new daemon" 1257s === CONT TestReconnection 1257s === RUN TestReconnection/Success_connecting_after_failing_to_connect 1257s === PAUSE TestReconnection/Success_connecting_after_failing_to_connect 1257s === RUN TestReconnection/Success_connecting_after_previous_connection_dropped 1257s === PAUSE TestReconnection/Success_connecting_after_previous_connection_dropped 1257s === CONT TestServeAndQuit 1257s === RUN TestServeAndQuit/Success_with_graceful_quit 1257s === PAUSE TestServeAndQuit/Success_with_graceful_quit 1257s === RUN TestServeAndQuit/Success_with_forceful_quit 1257s === PAUSE TestServeAndQuit/Success_with_forceful_quit 1257s === RUN TestServeAndQuit/Success_with_double_quit 1257s === PAUSE TestServeAndQuit/Success_with_double_quit 1257s === RUN TestServeAndQuit/Error_due_to_quitting_before_serving 1257s === PAUSE TestServeAndQuit/Error_due_to_quitting_before_serving 1257s === CONT TestServe 1257s === RUN TestServe/Success 1257s === PAUSE TestServe/Success 1257s === RUN TestServe/Success_with_systemd_notifier_returning_true 1257s === PAUSE TestServe/Success_with_systemd_notifier_returning_true 1257s === RUN TestServe/No_connection_because_port_file_does_not_exist 1257s === PAUSE TestServe/No_connection_because_port_file_does_not_exist 1257s === RUN TestServe/No_connection_because_of_faulty_agent 1257s === PAUSE TestServe/No_connection_because_of_faulty_agent 1257s === RUN TestServe/Error_because_of_notifier_returning_error 1257s === PAUSE TestServe/Error_because_of_notifier_returning_error 1257s === RUN TestServe/Error_because_WindowsHostAddress_returns_error 1257s === PAUSE TestServe/Error_because_WindowsHostAddress_returns_error 1257s === RUN TestServe/Error_because_of_context_cancelled 1257s === PAUSE TestServe/Error_because_of_context_cancelled 1257s === CONT TestNew/Error_when_WslPath_returns_error 1257s time="2024-02-23T10:55:42Z" level=debug msg="Building new daemon" 1266s --- PASS: TestNew (0.00s) 1266s --- PASS: TestNew/Success (9.70s) 1266s --- PASS: TestNew/Error_when_WslPath_returns_error (8.81s) 1266s === CONT TestReconnection/Success_connecting_after_failing_to_connect 1266s time="2024-02-23T10:55:51Z" level=debug msg="Building new daemon" 1275s time="2024-02-23T10:56:00Z" level=debug msg="Ready state sent to systemd" 1279s time="2024-02-23T10:56: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_connect2405948173/001/mnt/d/Users/TestUser/.ubuntupro/.address\": open /tmp/TestReconnectionSuccess_connecting_after_failing_to_connect2405948173/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1279s time="2024-02-23T10:56:04Z" level=debug msg="Updated systemd status to \"Not serving: waiting to retry\"" 1280s time="2024-02-23T10:56:05Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:44061\"" 1281s time="2024-02-23T10:56:06Z" level=info msg="Retrying connection" 1281s time="2024-02-23T10:56:06Z" level=debug msg="Updated systemd status to \"Not serving: retrying\"" 1286s time="2024-02-23T10:56:11Z" level=info msg="Connecting to control stream at \"127.0.0.1:44061\"" 1286s time="2024-02-23T10:56:11Z" level=debug msg="Connected to Windows agent via the control stream" 1286s time="2024-02-23T10:56:11Z" level=info msg="wslInstanceMockService: Received incoming connection" 1291s time="2024-02-23T10:56: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\"" 1291s time="2024-02-23T10:56:15Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 35581" 1291s time="2024-02-23T10:56:15Z" level=debug msg="Completed handshake with Windows agent via the control stream" 1291s time="2024-02-23T10:56:15Z" level=info msg="Connected to control stream" 1291s time="2024-02-23T10:56:15Z" level=debug msg="Starting to serve requests" 1291s time="2024-02-23T10:56:15Z" level=info msg="Serving GRPC requests on localhost:35581" 1291s time="2024-02-23T10:56:15Z" level=debug msg="Updated systemd status to \"Serving\"" 1296s time="2024-02-23T10:56:20Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": connected back via reserved port" 1296s time="2024-02-23T10:56:21Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\" ended: rpc error: code = Canceled desc = context canceled" 1296s time="2024-02-23T10:56:21Z" level=info msg="wslInstanceMockService: dropped connection" 1296s time="2024-02-23T10:56:21Z" level=info msg="Stopping daemon requested." 1296s time="2024-02-23T10:56:21Z" level=error msg="serve error: lost connection to Windows Agent" 1296s time="2024-02-23T10:56:21Z" level=debug msg="Updated systemd status to \"Not serving: waiting to retry\"" 1296s time="2024-02-23T10:56:21Z" level=debug msg="Updated systemd status to \"Stopped\"" 1296s === CONT TestServeAndQuit/Success_with_graceful_quit 1296s time="2024-02-23T10:56:21Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:44853\"" 1296s time="2024-02-23T10:56:21Z" level=debug msg="Building new daemon" 1304s time="2024-02-23T10:56:29Z" level=debug msg="Ready state sent to systemd" 1309s time="2024-02-23T10:56:34Z" level=info msg="Connecting to control stream at \"127.0.0.1:44853\"" 1309s time="2024-02-23T10:56:34Z" level=debug msg="Connected to Windows agent via the control stream" 1309s time="2024-02-23T10:56:34Z" level=info msg="wslInstanceMockService: Received incoming connection" 1313s time="2024-02-23T10:56:38Z" 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\"" 1313s time="2024-02-23T10:56:38Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 41521" 1313s time="2024-02-23T10:56:38Z" level=debug msg="Completed handshake with Windows agent via the control stream" 1313s time="2024-02-23T10:56:38Z" level=info msg="Connected to control stream" 1313s time="2024-02-23T10:56:38Z" level=debug msg="Starting to serve requests" 1313s time="2024-02-23T10:56:38Z" level=info msg="Serving GRPC requests on localhost:41521" 1313s time="2024-02-23T10:56:38Z" level=debug msg="Updated systemd status to \"Serving\"" 1313s time="2024-02-23T10:56:38Z" level=info msg="Stopping daemon requested." 1313s time="2024-02-23T10:56:38Z" level=info msg="Waiting for active requests to close." 1313s time="2024-02-23T10:56:38Z" level=debug msg="Updated systemd status to \"Stopped\"" 1313s time="2024-02-23T10:56:38Z" level=debug msg="All connections have now ended." 1313s time="2024-02-23T10:56:38Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestServeAndQuitSuccess_with_graceful_quit1709225256/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1313s === CONT TestReconnection/Success_connecting_after_previous_connection_dropped 1313s time="2024-02-23T10:56:38Z" level=debug msg="Building new daemon" 1322s time="2024-02-23T10:56:47Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:37991\"" 1322s time="2024-02-23T10:56:47Z" level=debug msg="Ready state sent to systemd" 1327s time="2024-02-23T10:56:52Z" level=info msg="Connecting to control stream at \"127.0.0.1:37991\"" 1327s time="2024-02-23T10:56:52Z" level=debug msg="Connected to Windows agent via the control stream" 1327s time="2024-02-23T10:56:52Z" level=info msg="wslInstanceMockService: Received incoming connection" 1331s time="2024-02-23T10:56:56Z" 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\"" 1331s time="2024-02-23T10:56:56Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 44525" 1331s time="2024-02-23T10:56:56Z" level=debug msg="Completed handshake with Windows agent via the control stream" 1331s time="2024-02-23T10:56:56Z" level=info msg="Connected to control stream" 1331s time="2024-02-23T10:56:56Z" level=debug msg="Starting to serve requests" 1331s time="2024-02-23T10:56:56Z" level=info msg="Serving GRPC requests on localhost:44525" 1331s time="2024-02-23T10:56:56Z" level=debug msg="Updated systemd status to \"Serving\"" 1331s time="2024-02-23T10:56:56Z" level=error msg="serve error: lost connection to Windows Agent" 1331s time="2024-02-23T10:56:56Z" level=debug msg="Updated systemd status to \"Not serving: waiting to retry\"" 1332s time="2024-02-23T10:56:56Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:37187\"" 1333s time="2024-02-23T10:56:58Z" level=info msg="Retrying connection" 1333s time="2024-02-23T10:56:58Z" level=debug msg="Updated systemd status to \"Not serving: retrying\"" 1338s time="2024-02-23T10:57:03Z" level=info msg="Connecting to control stream at \"127.0.0.1:37187\"" 1338s time="2024-02-23T10:57:03Z" level=debug msg="Connected to Windows agent via the control stream" 1338s time="2024-02-23T10:57:03Z" level=info msg="wslInstanceMockService: Received incoming connection" 1338s time="2024-02-23T10:57:03Z" level=warning msg="wslInstanceMockService: dropped connection: wslInstanceMockService: could not dial \"TEST_DISTRO\": dial tcp4 127.0.0.1:41521: connect: connection refused" 1342s time="2024-02-23T10:57:07Z" 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\"" 1342s time="2024-02-23T10:57:07Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 44663" 1342s time="2024-02-23T10:57:07Z" level=debug msg="Completed handshake with Windows agent via the control stream" 1342s time="2024-02-23T10:57:07Z" level=info msg="Connected to control stream" 1342s time="2024-02-23T10:57:07Z" level=debug msg="Starting to serve requests" 1342s time="2024-02-23T10:57:07Z" level=info msg="Serving GRPC requests on localhost:44663" 1342s time="2024-02-23T10:57:07Z" level=debug msg="Updated systemd status to \"Serving\"" 1347s time="2024-02-23T10:57:12Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": connected back via reserved port" 1348s time="2024-02-23T10:57:12Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\" ended: rpc error: code = Canceled desc = context canceled" 1348s time="2024-02-23T10:57:12Z" level=info msg="wslInstanceMockService: dropped connection" 1348s time="2024-02-23T10:57:12Z" level=error msg="serve error: lost connection to Windows Agent" 1348s time="2024-02-23T10:57:12Z" level=debug msg="Updated systemd status to \"Not serving: waiting to retry\"" 1348s time="2024-02-23T10:57:12Z" level=info msg="Stopping daemon requested." 1348s time="2024-02-23T10:57:12Z" level=debug msg="Updated systemd status to \"Stopped\"" 1348s --- PASS: TestReconnection (0.00s) 1348s --- PASS: TestReconnection/Success_connecting_after_failing_to_connect (29.42s) 1348s --- PASS: TestReconnection/Success_connecting_after_previous_connection_dropped (34.09s) 1348s === CONT TestServe/Success 1348s time="2024-02-23T10:57:13Z" level=debug msg="Building new daemon" 1348s time="2024-02-23T10:57:13Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:39919\"" 1356s time="2024-02-23T10:57:21Z" level=warning msg="wslInstanceMockService: dropped connection: wslInstanceMockService: could not dial \"TEST_DISTRO\": dial tcp4 127.0.0.1:44525: connect: connection refused" 1360s time="2024-02-23T10:57:25Z" level=info msg="Connecting to control stream at \"127.0.0.1:39919\"" 1360s time="2024-02-23T10:57:25Z" level=debug msg="Connected to Windows agent via the control stream" 1360s time="2024-02-23T10:57:25Z" level=info msg="wslInstanceMockService: Received incoming connection" 1364s time="2024-02-23T10:57:29Z" 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\"" 1364s time="2024-02-23T10:57:29Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 39209" 1364s time="2024-02-23T10:57:29Z" level=debug msg="Completed handshake with Windows agent via the control stream" 1364s time="2024-02-23T10:57:29Z" level=info msg="Connected to control stream" 1364s time="2024-02-23T10:57:29Z" level=debug msg="Starting to serve requests" 1364s time="2024-02-23T10:57:29Z" level=info msg="Serving GRPC requests on localhost:39209" 1366s time="2024-02-23T10:57:31Z" level=info msg="Stopping daemon requested." 1366s time="2024-02-23T10:57:31Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestServeSuccess4022980458/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1366s === CONT TestServeAndQuit/Error_due_to_quitting_before_serving 1366s time="2024-02-23T10:57:31Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:37345\"" 1366s time="2024-02-23T10:57:31Z" level=debug msg="Building new daemon" 1375s time="2024-02-23T10:57:40Z" level=debug msg="Updated systemd status to \"Stopped\"" 1375s === CONT TestServeAndQuit/Success_with_double_quit 1375s time="2024-02-23T10:57:40Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:41361\"" 1375s time="2024-02-23T10:57:40Z" level=debug msg="Building new daemon" 1384s time="2024-02-23T10:57:49Z" level=debug msg="Ready state sent to systemd" 1389s time="2024-02-23T10:57:53Z" level=info msg="Connecting to control stream at \"127.0.0.1:41361\"" 1389s time="2024-02-23T10:57:53Z" level=debug msg="Connected to Windows agent via the control stream" 1389s time="2024-02-23T10:57:53Z" level=info msg="wslInstanceMockService: Received incoming connection" 1389s time="2024-02-23T10:57:54Z" level=warning msg="wslInstanceMockService: dropped connection: wslInstanceMockService: could not dial \"TEST_DISTRO\": dial tcp4 127.0.0.1:39209: connect: connection refused" 1393s time="2024-02-23T10:57:58Z" 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\"" 1393s time="2024-02-23T10:57:58Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 41743" 1393s time="2024-02-23T10:57:58Z" level=debug msg="Completed handshake with Windows agent via the control stream" 1393s time="2024-02-23T10:57:58Z" level=info msg="Connected to control stream" 1393s time="2024-02-23T10:57:58Z" level=debug msg="Starting to serve requests" 1393s time="2024-02-23T10:57:58Z" level=info msg="Serving GRPC requests on localhost:41743" 1393s time="2024-02-23T10:57:58Z" level=debug msg="Updated systemd status to \"Serving\"" 1394s time="2024-02-23T10:57:59Z" level=info msg="Stopping daemon requested." 1394s time="2024-02-23T10:57:59Z" level=info msg="Waiting for active requests to close." 1394s time="2024-02-23T10:57:59Z" level=debug msg="All connections have now ended." 1394s time="2024-02-23T10:57:59Z" level=debug msg="Updated systemd status to \"Stopped\"" 1394s time="2024-02-23T10:57:59Z" level=info msg="Stopping daemon requested." 1394s time="2024-02-23T10:57:59Z" level=info msg="Waiting for active requests to close." 1394s time="2024-02-23T10:57:59Z" level=debug msg="All connections have now ended." 1394s time="2024-02-23T10:57:59Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestServeAndQuitSuccess_with_double_quit4283228066/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1394s === CONT TestServeAndQuit/Success_with_forceful_quit 1394s time="2024-02-23T10:57:59Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:36665\"" 1394s time="2024-02-23T10:57:59Z" level=debug msg="Building new daemon" 1403s time="2024-02-23T10:58:08Z" level=debug msg="Ready state sent to systemd" 1407s time="2024-02-23T10:58:12Z" level=info msg="Connecting to control stream at \"127.0.0.1:36665\"" 1407s time="2024-02-23T10:58:12Z" level=debug msg="Connected to Windows agent via the control stream" 1407s time="2024-02-23T10:58:12Z" level=info msg="wslInstanceMockService: Received incoming connection" 1412s time="2024-02-23T10:58:17Z" 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\"" 1412s time="2024-02-23T10:58:17Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 36221" 1412s time="2024-02-23T10:58:17Z" level=debug msg="Completed handshake with Windows agent via the control stream" 1412s time="2024-02-23T10:58:17Z" level=info msg="Connected to control stream" 1412s time="2024-02-23T10:58:17Z" level=debug msg="Starting to serve requests" 1412s time="2024-02-23T10:58:17Z" level=info msg="Serving GRPC requests on localhost:36221" 1412s time="2024-02-23T10:58:17Z" level=debug msg="Updated systemd status to \"Serving\"" 1412s time="2024-02-23T10:58:17Z" level=info msg="Stopping daemon requested." 1412s time="2024-02-23T10:58:17Z" level=debug msg="Updated systemd status to \"Stopped\"" 1412s time="2024-02-23T10:58:17Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestServeAndQuitSuccess_with_forceful_quit1551017487/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1412s --- PASS: TestServeAndQuit (0.00s) 1412s --- PASS: TestServeAndQuit/Success_with_graceful_quit (17.88s) 1412s --- PASS: TestServeAndQuit/Error_due_to_quitting_before_serving (8.63s) 1412s --- PASS: TestServeAndQuit/Success_with_double_quit (19.23s) 1412s --- PASS: TestServeAndQuit/Success_with_forceful_quit (17.92s) 1412s === CONT TestServe/Error_because_of_context_cancelled 1412s time="2024-02-23T10:58:17Z" level=debug msg="Building new daemon" 1412s time="2024-02-23T10:58:17Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:35187\"" 1418s time="2024-02-23T10:58:23Z" level=warning msg="wslInstanceMockService: dropped connection: wslInstanceMockService: could not dial \"TEST_DISTRO\": dial tcp4 127.0.0.1:41743: connect: connection refused" 1421s time="2024-02-23T10:58:26Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestServeError_because_of_context_cancelled2811870929/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1421s === CONT TestServe/Error_because_WindowsHostAddress_returns_error 1421s time="2024-02-23T10:58:26Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:39461\"" 1421s time="2024-02-23T10:58:26Z" level=debug msg="Building new daemon" 1436s time="2024-02-23T10:58:41Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestServeError_because_WindowsHostAddress_returns_error778434094/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1436s === CONT TestServe/Error_because_of_notifier_returning_error 1436s time="2024-02-23T10:58:41Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:33663\"" 1436s time="2024-02-23T10:58:41Z" level=debug msg="Building new daemon" 1437s time="2024-02-23T10:58:42Z" level=warning msg="wslInstanceMockService: dropped connection: wslInstanceMockService: could not dial \"TEST_DISTRO\": dial tcp4 127.0.0.1:36221: connect: connection refused" 1442s time="2024-02-23T10:58:47Z" level=info msg="Stopping daemon requested." 1446s time="2024-02-23T10:58:51Z" level=warning msg="Could not change systemd status: couldn't update status to systemd: mock error" 1446s time="2024-02-23T10:58:51Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestServeError_because_of_notifier_returning_error1016529395/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1446s === CONT TestServe/No_connection_because_of_faulty_agent 1446s time="2024-02-23T10:58:51Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:42799\"" 1446s time="2024-02-23T10:58:51Z" level=debug msg="Building new daemon" 1456s time="2024-02-23T10:59:01Z" level=info msg="Stopping daemon requested." 1459s time="2024-02-23T10:59:04Z" level=info msg="Connecting to control stream at \"127.0.0.1:42799\"" 1459s time="2024-02-23T10:59:04Z" level=debug msg="Connected to Windows agent via the control stream" 1459s time="2024-02-23T10:59:04Z" level=info msg="wslInstanceMockService: Received incoming connection" 1459s time="2024-02-23T10:59:04Z" level=info msg="wslInstanceMockService: mock error: dropping stream before first Recv" 1459s time="2024-02-23T10:59:04Z" level=info msg="wslInstanceMockService: dropped connection" 1464s time="2024-02-23T10:59:09Z" level=error msg="serve error: could not connect to windows agent via the control stream: could not complete handshake: could not send system info: could not send system info: EOF" 1465s time="2024-02-23T10:59:10Z" level=info msg="Stopping daemon requested." 1465s time="2024-02-23T10:59:10Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestServeNo_connection_because_of_faulty_agent2853681923/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1465s === CONT TestServe/No_connection_because_port_file_does_not_exist 1465s time="2024-02-23T10:59:10Z" level=debug msg="Building new daemon" 1465s time="2024-02-23T10:59:10Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:45785\"" 1479s time="2024-02-23T10:59:24Z" 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_exist205305475/001/mnt/d/Users/TestUser/.ubuntupro/.address\": open /tmp/TestServeNo_connection_because_port_file_does_not_exist205305475/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1481s time="2024-02-23T10:59:26Z" level=info msg="Retrying connection" 1484s time="2024-02-23T10:59:29Z" level=info msg="Stopping daemon requested." 1485s time="2024-02-23T10:59:30Z" 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_exist205305475/001/mnt/d/Users/TestUser/.ubuntupro/.address\": open /tmp/TestServeNo_connection_because_port_file_does_not_exist205305475/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1485s time="2024-02-23T10:59:30Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestServeNo_connection_because_port_file_does_not_exist205305475/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1485s === CONT TestServe/Success_with_systemd_notifier_returning_true 1485s time="2024-02-23T10:59:30Z" level=info msg="MockWindowsAgent: Windows-agent mock serving on \"127.0.0.1:46843\"" 1485s time="2024-02-23T10:59:30Z" level=debug msg="Building new daemon" 1494s time="2024-02-23T10:59:39Z" level=debug msg="Ready state sent to systemd" 1498s time="2024-02-23T10:59:43Z" level=info msg="Connecting to control stream at \"127.0.0.1:46843\"" 1498s time="2024-02-23T10:59:43Z" level=debug msg="Connected to Windows agent via the control stream" 1498s time="2024-02-23T10:59:43Z" level=info msg="wslInstanceMockService: Received incoming connection" 1503s time="2024-02-23T10:59:47Z" 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\"" 1503s time="2024-02-23T10:59:47Z" level=info msg="wslInstanceMockService: Connection with \"TEST_DISTRO\": Reserved port 36409" 1503s time="2024-02-23T10:59:47Z" level=debug msg="Completed handshake with Windows agent via the control stream" 1503s time="2024-02-23T10:59:47Z" level=info msg="Connected to control stream" 1503s time="2024-02-23T10:59:47Z" level=debug msg="Starting to serve requests" 1503s time="2024-02-23T10:59:47Z" level=info msg="Serving GRPC requests on localhost:36409" 1503s time="2024-02-23T10:59:47Z" level=debug msg="Updated systemd status to \"Serving\"" 1504s time="2024-02-23T10:59:49Z" level=info msg="Stopping daemon requested." 1504s time="2024-02-23T10:59:49Z" level=debug msg="Updated systemd status to \"Stopped\"" 1504s time="2024-02-23T10:59:49Z" level=info msg="MockWindowsAgent: Remove address file returned an error: remove /tmp/TestServeSuccess_with_systemd_notifier_returning_true1130445834/001/mnt/d/Users/TestUser/.ubuntupro/.address: no such file or directory" 1504s --- PASS: TestServe (0.00s) 1504s --- PASS: TestServe/Success (18.73s) 1504s --- PASS: TestServe/Error_because_of_context_cancelled (9.04s) 1504s --- PASS: TestServe/Error_because_WindowsHostAddress_returns_error (15.02s) 1504s --- PASS: TestServe/Error_because_of_notifier_returning_error (9.88s) 1504s --- PASS: TestServe/No_connection_because_of_faulty_agent (18.79s) 1504s --- PASS: TestServe/No_connection_because_port_file_does_not_exist (20.55s) 1504s --- PASS: TestServe/Success_with_systemd_notifier_returning_true (18.65s) 1504s PASS 1504s ok github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/internal/daemon 256.410s 1507s === RUN TestActiveConnection 1507s === PAUSE TestActiveConnection 1507s === RUN TestTimeoutOnInactiveConnection 1507s === PAUSE TestTimeoutOnInactiveConnection 1507s === RUN TestCancelOnClientSide 1507s === PAUSE TestCancelOnClientSide 1507s === RUN TestClientInterceptorFailed 1507s === PAUSE TestClientInterceptorFailed 1507s === RUN TestRecvMessageError 1507s === PAUSE TestRecvMessageError 1507s === CONT TestActiveConnection 1507s --- PASS: TestActiveConnection (0.15s) 1507s === CONT TestRecvMessageError 1507s --- PASS: TestRecvMessageError (0.00s) 1507s === CONT TestClientInterceptorFailed 1507s --- PASS: TestClientInterceptorFailed (0.00s) 1507s === CONT TestCancelOnClientSide 1507s --- PASS: TestCancelOnClientSide (0.00s) 1507s === CONT TestTimeoutOnInactiveConnection 1507s --- PASS: TestTimeoutOnInactiveConnection (0.05s) 1507s PASS 1507s ok github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/internal/grpc/contextidler 0.238s 1509s === RUN TestFormat 1509s === PAUSE TestFormat 1509s === CONT TestFormat 1509s === RUN TestFormat/GRPC_Unavailable_errors_prints_daemon_name 1509s === PAUSE TestFormat/GRPC_Unavailable_errors_prints_daemon_name 1509s === RUN TestFormat/GRPC_Deadline_errors_don't_print_status_nor_daemon_nor_message 1509s === PAUSE TestFormat/GRPC_Deadline_errors_don't_print_status_nor_daemon_nor_message 1509s === RUN TestFormat/GRPC_Unknown_errors_don't_print_status_and_daemon 1509s === PAUSE TestFormat/GRPC_Unknown_errors_don't_print_status_and_daemon 1509s === RUN TestFormat/GRPC_Random_errors_prints_status_and_message 1509s === PAUSE TestFormat/GRPC_Random_errors_prints_status_and_message 1509s === RUN TestFormat/Nil_returns_nil 1509s === PAUSE TestFormat/Nil_returns_nil 1509s === RUN TestFormat/Non_GRPC_errors_are_returned_as_is 1509s === PAUSE TestFormat/Non_GRPC_errors_are_returned_as_is 1509s === CONT TestFormat/GRPC_Unavailable_errors_prints_daemon_name 1509s === CONT TestFormat/Non_GRPC_errors_are_returned_as_is 1509s === CONT TestFormat/Nil_returns_nil 1509s === CONT TestFormat/GRPC_Random_errors_prints_status_and_message 1509s === CONT TestFormat/GRPC_Unknown_errors_don't_print_status_and_daemon 1509s === CONT TestFormat/GRPC_Deadline_errors_don't_print_status_nor_daemon_nor_message 1509s --- PASS: TestFormat (0.01s) 1509s --- PASS: TestFormat/GRPC_Unavailable_errors_prints_daemon_name (0.00s) 1509s --- PASS: TestFormat/Non_GRPC_errors_are_returned_as_is (0.00s) 1509s --- PASS: TestFormat/Nil_returns_nil (0.00s) 1509s --- PASS: TestFormat/GRPC_Random_errors_prints_status_and_message (0.00s) 1509s --- PASS: TestFormat/GRPC_Unknown_errors_don't_print_status_and_daemon (0.00s) 1509s --- PASS: TestFormat/GRPC_Deadline_errors_don't_print_status_nor_daemon_nor_message (0.00s) 1509s PASS 1509s ok github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/internal/grpc/grpcerror 0.033s 1511s === RUN TestStreamServer 1511s === PAUSE TestStreamServer 1511s === RUN TestStreamClient 1511s === PAUSE TestStreamClient 1511s === CONT TestStreamServer 1511s --- PASS: TestStreamServer (0.00s) 1511s === CONT TestStreamClient 1511s --- PASS: TestStreamClient (0.00s) 1511s PASS 1511s ok github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/internal/grpc/interceptorschain 0.027s 1514s === RUN TestChildRecvMsgAndHandlerCalled 1514s === PAUSE TestChildRecvMsgAndHandlerCalled 1514s === CONT TestChildRecvMsgAndHandlerCalled 1514s === RUN TestChildRecvMsgAndHandlerCalled/Error_when_RecvMsg_errors_out 1514s === PAUSE TestChildRecvMsgAndHandlerCalled/Error_when_RecvMsg_errors_out 1514s === RUN TestChildRecvMsgAndHandlerCalled/Handler_and_RecvMsg_are_called 1514s === PAUSE TestChildRecvMsgAndHandlerCalled/Handler_and_RecvMsg_are_called 1514s === RUN TestChildRecvMsgAndHandlerCalled/Info_being_nil_has_no_impact 1514s === PAUSE TestChildRecvMsgAndHandlerCalled/Info_being_nil_has_no_impact 1514s === RUN TestChildRecvMsgAndHandlerCalled/Error_when_handler_fails_out 1514s === PAUSE TestChildRecvMsgAndHandlerCalled/Error_when_handler_fails_out 1514s === CONT TestChildRecvMsgAndHandlerCalled/Error_when_RecvMsg_errors_out 1514s === CONT TestChildRecvMsgAndHandlerCalled/Error_when_handler_fails_out 1514s time="2024-02-23T10:59:59Z" level=info msg="Error sent to client: Failing handler" 1514s === CONT TestChildRecvMsgAndHandlerCalled/Info_being_nil_has_no_impact 1514s === CONT TestChildRecvMsgAndHandlerCalled/Handler_and_RecvMsg_are_called 1514s --- PASS: TestChildRecvMsgAndHandlerCalled (0.00s) 1514s --- PASS: TestChildRecvMsgAndHandlerCalled/Error_when_RecvMsg_errors_out (0.00s) 1514s --- PASS: TestChildRecvMsgAndHandlerCalled/Error_when_handler_fails_out (0.00s) 1514s --- PASS: TestChildRecvMsgAndHandlerCalled/Info_being_nil_has_no_impact (0.00s) 1514s --- PASS: TestChildRecvMsgAndHandlerCalled/Handler_and_RecvMsg_are_called (0.00s) 1514s PASS 1514s ok github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/internal/grpc/logconnections 0.031s 1518s === RUN TestRecvLogMsg 1518s === PAUSE TestRecvLogMsg 1518s === RUN TestAddStreamToForwardLocalLogs 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:528678]]" 1518s time="2024-02-23T11:00:03Z" level=warning msg=something 1518s --- PASS: TestAddStreamToForwardLocalLogs (0.00s) 1518s === RUN TestAddStreamToForwardOtherStream 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:185052]]" 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:751677]]" 1518s --- PASS: TestAddStreamToForwardOtherStream (0.00s) 1518s === RUN TestAddStreamToForwardAfterClientIsConnected 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:923124]]" 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:170978]]" 1518s --- PASS: TestAddStreamToForwardAfterClientIsConnected (0.00s) 1518s === RUN TestAddStreamToForwardDisconnect 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:357451]]" 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:333263]]" 1518s --- PASS: TestAddStreamToForwardDisconnect (0.00s) 1518s === RUN TestAddStreamToForwardTwoClients 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:659547]]" 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:109398]]" 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:844089]]" 1518s --- PASS: TestAddStreamToForwardTwoClients (0.00s) 1518s === RUN TestAddStreamToForwardWithListenerCaller 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:939788]]" 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:787448]]" 1518s --- PASS: TestAddStreamToForwardWithListenerCaller (0.00s) 1518s === RUN TestAddStreamMultipleForwarders 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:409163]]" 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:488611]]" 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:465482]]" 1518s --- PASS: TestAddStreamMultipleForwarders (0.00s) 1518s === RUN TestAddStreamMultipleForwardersOneWithCaller 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:769430]]" 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:871962]]" 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:694648]]" 1518s --- PASS: TestAddStreamMultipleForwardersOneWithCaller (0.00s) 1518s === RUN TestAddStreamToForwardFailSend 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:487426]]" 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:809742]]" 1518s time="2024-02-23T11:00:03Z" level=warning msg="Couldn't send log to one or more listener: SendMsg failed" 1518s --- PASS: TestAddStreamToForwardFailSend (0.00s) 1518s === RUN TestRemoveAllStreams 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:914003]]" 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:010712]]" 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:711157]]" 1518s time="2024-02-23T11:00:03Z" level=warning msg="[[123456:711157]] else" 1518s --- PASS: TestRemoveAllStreams (0.00s) 1518s === RUN TestLogWarningOnly 1518s === PAUSE TestLogWarningOnly 1518s === RUN TestMultipleLogs 1518s === PAUSE TestMultipleLogs 1518s === RUN TestAllLogLevels 1518s === PAUSE TestAllLogLevels 1518s === RUN TestDebugSentToRemoteEvenIfLocalIsWarning 1518s === PAUSE TestDebugSentToRemoteEvenIfLocalIsWarning 1518s === RUN TestLogWarningWithLocalCaller 1518s === PAUSE TestLogWarningWithLocalCaller 1518s === RUN TestLogWarningWithRemoteCaller 1518s === PAUSE TestLogWarningWithRemoteCaller 1518s === RUN TestLogWithNoCaller 1518s === PAUSE TestLogWithNoCaller 1518s === RUN TestSetReportCaller 1518s === RUN TestSetReportCaller/Report_caller 1518s === RUN TestSetReportCaller/Disable_caller 1518s --- PASS: TestSetReportCaller (0.00s) 1518s --- PASS: TestSetReportCaller/Report_caller (0.00s) 1518s --- PASS: TestSetReportCaller/Disable_caller (0.00s) 1518s === RUN TestLogSendingFail 1518s === PAUSE TestLogSendingFail 1518s === RUN TestLogStreamsAreSeparated 1518s === PAUSE TestLogStreamsAreSeparated 1518s === RUN TestLogAddHook 1518s time="2024-02-23T11:00:03Z" level=info 1518s --- PASS: TestLogAddHook (0.00s) 1518s === RUN TestStreamServerInterceptor 1518s === PAUSE TestStreamServerInterceptor 1518s === RUN TestStreamServerInterceptorSendLogsFails 1518s === PAUSE TestStreamServerInterceptorSendLogsFails 1518s === RUN TestStreamServerInterceptorLoggerInvalidMetadata 1518s === PAUSE TestStreamServerInterceptorLoggerInvalidMetadata 1518s === CONT TestRecvLogMsg 1518s === RUN TestRecvLogMsg/Unknown_log_level_triggers_a_client_error_(protocole_issue) 1518s === PAUSE TestRecvLogMsg/Unknown_log_level_triggers_a_client_error_(protocole_issue) 1518s === RUN TestRecvLogMsg/Invalid_object_passed_to_RecvMsg_is_gracefully_skipped 1518s === PAUSE TestRecvLogMsg/Invalid_object_passed_to_RecvMsg_is_gracefully_skipped 1518s === RUN TestRecvLogMsg/One_message,_no_log 1518s === PAUSE TestRecvLogMsg/One_message,_no_log 1518s === RUN TestRecvLogMsg/One_log_(and_one_closing_empty_message) 1518s === PAUSE TestRecvLogMsg/One_log_(and_one_closing_empty_message) 1518s === RUN TestRecvLogMsg/Two_logs_with_different_debug_level 1518s === PAUSE TestRecvLogMsg/Two_logs_with_different_debug_level 1518s === RUN TestRecvLogMsg/No_caller_when_not_requested 1518s === PAUSE TestRecvLogMsg/No_caller_when_not_requested 1518s === RUN TestRecvLogMsg/One_message_with_error,_no_log,_error_is_preserved 1518s === PAUSE TestRecvLogMsg/One_message_with_error,_no_log,_error_is_preserved 1518s === RUN TestRecvLogMsg/Logs_and_then_message_with_error,_error_is_preserved 1518s === PAUSE TestRecvLogMsg/Logs_and_then_message_with_error,_error_is_preserved 1518s === RUN TestRecvLogMsg/Log_with_caller 1518s === PAUSE TestRecvLogMsg/Log_with_caller 1518s === RUN TestRecvLogMsg/No_caller_on_any_logs 1518s === PAUSE TestRecvLogMsg/No_caller_on_any_logs 1518s === CONT TestRecvLogMsg/Unknown_log_level_triggers_a_client_error_(protocole_issue) 1518s === CONT TestStreamServerInterceptorLoggerInvalidMetadata 1518s === RUN TestStreamServerInterceptorLoggerInvalidMetadata/Missing_caller_key 1518s === PAUSE TestStreamServerInterceptorLoggerInvalidMetadata/Missing_caller_key 1518s === RUN TestStreamServerInterceptorLoggerInvalidMetadata/Caller_key_is_not_a_boolean 1518s === PAUSE TestStreamServerInterceptorLoggerInvalidMetadata/Caller_key_is_not_a_boolean 1518s === RUN TestStreamServerInterceptorLoggerInvalidMetadata/Multiple_log_metas 1518s === PAUSE TestStreamServerInterceptorLoggerInvalidMetadata/Multiple_log_metas 1518s === RUN TestStreamServerInterceptorLoggerInvalidMetadata/No_meta_sent 1518s === PAUSE TestStreamServerInterceptorLoggerInvalidMetadata/No_meta_sent 1518s === RUN TestStreamServerInterceptorLoggerInvalidMetadata/Missing_client_ID 1518s === PAUSE TestStreamServerInterceptorLoggerInvalidMetadata/Missing_client_ID 1518s === CONT TestStreamServerInterceptorLoggerInvalidMetadata/Missing_caller_key 1518s === CONT TestStreamServerInterceptorSendLogsFails 1518s time="2024-02-23T11:00:03Z" level=warning msg="[[123456:894196]] Couldn't send initial connection log to client" 1518s Failed to fire hook: hook fired 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:894196]]" 1518s --- PASS: TestStreamServerInterceptorSendLogsFails (0.00s) 1518s === CONT TestStreamServerInterceptor 1518s Failed to fire hook: hook fired 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:301415]]" 1518s --- PASS: TestStreamServerInterceptor (0.00s) 1518s === CONT TestLogStreamsAreSeparated 1518s Failed to fire hook: hook fired 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:405094]]" 1518s Failed to fire hook: hook fired 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:796920]]" 1518s --- PASS: TestLogStreamsAreSeparated (0.00s) 1518s === CONT TestLogSendingFail 1518s Failed to fire hook: hook fired 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:077349]]" 1518s --- PASS: TestLogSendingFail (0.00s) 1518s === CONT TestLogWithNoCaller 1518s Failed to fire hook: hook fired 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:306372]]" 1518s --- PASS: TestLogWithNoCaller (0.00s) 1518s === CONT TestLogWarningWithRemoteCaller 1518s Failed to fire hook: hook fired 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:174528]]" 1518s --- PASS: TestLogWarningWithRemoteCaller (0.00s) 1518s === CONT TestLogWarningWithLocalCaller 1518s Failed to fire hook: hook fired 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:880141]]" 1518s --- PASS: TestLogWarningWithLocalCaller (0.00s) 1518s === CONT TestDebugSentToRemoteEvenIfLocalIsWarning 1518s Failed to fire hook: hook fired 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:893852]]" 1518s --- PASS: TestDebugSentToRemoteEvenIfLocalIsWarning (0.00s) 1518s === CONT TestAllLogLevels 1518s Failed to fire hook: hook fired 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:812530]]" 1518s --- PASS: TestAllLogLevels (0.00s) 1518s === CONT TestMultipleLogs 1518s Failed to fire hook: hook fired 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:536393]]" 1518s --- PASS: TestMultipleLogs (0.00s) 1518s === CONT TestLogWarningOnly 1518s Failed to fire hook: hook fired 1518s time="2024-02-23T11:00:03Z" level=info msg="New connection from client [[123456:600324]]" 1518s --- PASS: TestLogWarningOnly (0.00s) 1518s === CONT TestRecvLogMsg/No_caller_on_any_logs 1518s === CONT TestRecvLogMsg/Log_with_caller 1518s === CONT TestRecvLogMsg/Logs_and_then_message_with_error,_error_is_preserved 1518s === CONT TestRecvLogMsg/One_message_with_error,_no_log,_error_is_preserved 1518s === CONT TestRecvLogMsg/No_caller_when_not_requested 1518s === CONT TestRecvLogMsg/Two_logs_with_different_debug_level 1518s === CONT TestRecvLogMsg/One_log_(and_one_closing_empty_message) 1518s === CONT TestRecvLogMsg/One_message,_no_log 1518s === CONT TestRecvLogMsg/Invalid_object_passed_to_RecvMsg_is_gracefully_skipped 1518s --- PASS: TestRecvLogMsg (0.00s) 1518s --- PASS: TestRecvLogMsg/Unknown_log_level_triggers_a_client_error_(protocole_issue) (0.00s) 1518s --- PASS: TestRecvLogMsg/No_caller_on_any_logs (0.00s) 1518s --- PASS: TestRecvLogMsg/Log_with_caller (0.00s) 1518s --- PASS: TestRecvLogMsg/Logs_and_then_message_with_error,_error_is_preserved (0.00s) 1518s --- PASS: TestRecvLogMsg/One_message_with_error,_no_log,_error_is_preserved (0.00s) 1518s --- PASS: TestRecvLogMsg/No_caller_when_not_requested (0.00s) 1518s --- PASS: TestRecvLogMsg/Two_logs_with_different_debug_level (0.00s) 1518s --- PASS: TestRecvLogMsg/One_log_(and_one_closing_empty_message) (0.00s) 1518s --- PASS: TestRecvLogMsg/One_message,_no_log (0.00s) 1518s --- PASS: TestRecvLogMsg/Invalid_object_passed_to_RecvMsg_is_gracefully_skipped (0.00s) 1518s === CONT TestStreamServerInterceptorLoggerInvalidMetadata/Missing_client_ID 1518s === CONT TestStreamServerInterceptorLoggerInvalidMetadata/No_meta_sent 1518s === CONT TestStreamServerInterceptorLoggerInvalidMetadata/Multiple_log_metas 1518s === CONT TestStreamServerInterceptorLoggerInvalidMetadata/Caller_key_is_not_a_boolean 1518s --- PASS: TestStreamServerInterceptorLoggerInvalidMetadata (0.00s) 1518s --- PASS: TestStreamServerInterceptorLoggerInvalidMetadata/Missing_caller_key (0.00s) 1518s --- PASS: TestStreamServerInterceptorLoggerInvalidMetadata/Missing_client_ID (0.00s) 1518s --- PASS: TestStreamServerInterceptorLoggerInvalidMetadata/No_meta_sent (0.00s) 1518s --- PASS: TestStreamServerInterceptorLoggerInvalidMetadata/Multiple_log_metas (0.00s) 1518s --- PASS: TestStreamServerInterceptorLoggerInvalidMetadata/Caller_key_is_not_a_boolean (0.00s) 1518s PASS 1518s ok github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/internal/grpc/logstreamer 0.072s 1518s ? github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/internal/grpc/logstreamer/test [no test files] 1522s === RUN TestInfo 1522s === PAUSE TestInfo 1522s === RUN TestUserProfileDir 1522s === PAUSE TestUserProfileDir 1522s === RUN TestProStatus 1522s === PAUSE TestProStatus 1522s === RUN TestProAttach 1522s === PAUSE TestProAttach 1522s === RUN TestProDetach 1522s === PAUSE TestProDetach 1522s === RUN TestLandscapeEnable 1522s === PAUSE TestLandscapeEnable 1522s === RUN TestWindowsHostAddress 1522s === PAUSE TestWindowsHostAddress 1522s === RUN TestLandscapeDisable 1522s === PAUSE TestLandscapeDisable 1522s === RUN TestWithProMock 1522s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 1522s --- SKIP: TestWithProMock (0.00s) 1522s === RUN TestWithLandscapeConfigMock 1522s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 1522s --- SKIP: TestWithLandscapeConfigMock (0.00s) 1522s === RUN TestWithWslPathMock 1522s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 1522s --- SKIP: TestWithWslPathMock (0.00s) 1522s === RUN TestWithWslInfoMock 1522s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 1522s --- SKIP: TestWithWslInfoMock (0.00s) 1522s === RUN TestWithCmdExeMock 1522s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 1522s --- SKIP: TestWithCmdExeMock (0.00s) 1522s === CONT TestInfo 1522s === RUN TestInfo/Success_reading_from_WSL_DISTRO_NAME 1522s === PAUSE TestInfo/Success_reading_from_WSL_DISTRO_NAME 1522s === RUN TestInfo/Error_when_WSL_DISTRO_NAME_is_empty_and_wslpath_fails 1522s === PAUSE TestInfo/Error_when_WSL_DISTRO_NAME_is_empty_and_wslpath_fails 1522s === RUN TestInfo/Error_when_WSL_DISTRO_NAME_is_empty_and_wslpath_returns_bad_text 1522s === PAUSE TestInfo/Error_when_WSL_DISTRO_NAME_is_empty_and_wslpath_returns_bad_text 1522s === RUN TestInfo/Error_whem_/etc/os-release_returns_bad_contents 1522s === PAUSE TestInfo/Error_whem_/etc/os-release_returns_bad_contents 1522s === RUN TestInfo/Error_when_hostname_cannot_be_obtained 1522s === PAUSE TestInfo/Error_when_hostname_cannot_be_obtained 1522s === RUN TestInfo/Success_using_wslpath 1522s === PAUSE TestInfo/Success_using_wslpath 1522s === RUN TestInfo/Error_when_pro_status_command_fails 1522s === PAUSE TestInfo/Error_when_pro_status_command_fails 1522s === RUN TestInfo/Error_when_pro_status_output_cannot_be_parsed 1522s === PAUSE TestInfo/Error_when_pro_status_output_cannot_be_parsed 1522s === RUN TestInfo/Error_when_/etc/os-release_cannot_be_read 1522s === PAUSE TestInfo/Error_when_/etc/os-release_cannot_be_read 1522s === CONT TestInfo/Success_reading_from_WSL_DISTRO_NAME 1527s === CONT TestLandscapeDisable 1527s === RUN TestLandscapeDisable/Success 1527s === PAUSE TestLandscapeDisable/Success 1527s === RUN TestLandscapeDisable/Error_when_the_landscape-config_command_fails 1527s === PAUSE TestLandscapeDisable/Error_when_the_landscape-config_command_fails 1527s === CONT TestWindowsHostAddress 1527s === RUN TestWindowsHostAddress/Success_without_NAT 1527s === PAUSE TestWindowsHostAddress/Success_without_NAT 1527s === RUN TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_is_ill-formed 1527s === PAUSE TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_is_ill-formed 1527s === RUN TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_does_not_exist 1527s === PAUSE TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_does_not_exist 1527s === RUN TestWindowsHostAddress/Success_with_NAT,_nameserver_is_not_loopback 1527s === PAUSE TestWindowsHostAddress/Success_with_NAT,_nameserver_is_not_loopback 1527s === RUN TestWindowsHostAddress/Success_with_NAT,_nameserver_is_loopback 1527s === PAUSE TestWindowsHostAddress/Success_with_NAT,_nameserver_is_loopback 1527s === RUN TestWindowsHostAddress/Error_when_wslinfo_returns_an_error 1527s === PAUSE TestWindowsHostAddress/Error_when_wslinfo_returns_an_error 1527s === RUN TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_does_not_exist 1527s === PAUSE TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_does_not_exist 1527s === RUN TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_has_an_ill-formed_IP 1527s === PAUSE TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_has_an_ill-formed_IP 1527s === RUN TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_is_ill-formed 1527s === PAUSE TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_is_ill-formed 1527s === RUN TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_has_an_ill-formed_IP 1527s === PAUSE TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_has_an_ill-formed_IP 1527s === CONT TestLandscapeEnable 1527s === RUN TestLandscapeEnable/Success_overriding_computer_title 1527s === PAUSE TestLandscapeEnable/Success_overriding_computer_title 1527s === RUN TestLandscapeEnable/Success_overriding_the_SSL_certficate_path 1527s === PAUSE TestLandscapeEnable/Success_overriding_the_SSL_certficate_path 1527s === RUN TestLandscapeEnable/Error_when_the_file_cannot_be_parsed 1527s === PAUSE TestLandscapeEnable/Error_when_the_file_cannot_be_parsed 1527s === RUN TestLandscapeEnable/Error_when_the_config_file_cannot_be_written 1527s === PAUSE TestLandscapeEnable/Error_when_the_config_file_cannot_be_written 1527s === RUN TestLandscapeEnable/Error_when_the_landscape-config_command_fails 1527s === PAUSE TestLandscapeEnable/Error_when_the_landscape-config_command_fails 1527s === RUN TestLandscapeEnable/Error_when_failing_to_override_the_SSL_certficate_path 1527s === PAUSE TestLandscapeEnable/Error_when_failing_to_override_the_SSL_certficate_path 1527s === RUN TestLandscapeEnable/Success 1527s === PAUSE TestLandscapeEnable/Success 1527s === CONT TestProDetach 1527s === RUN TestProDetach/error_on_'pro_detach'_error_with_bad_JSON 1527s === PAUSE TestProDetach/error_on_'pro_detach'_error_with_bad_JSON 1527s === RUN TestProDetach/success_on_unattached_distro 1527s === PAUSE TestProDetach/success_on_unattached_distro 1527s === RUN TestProDetach/success_on_attached_distro 1527s === PAUSE TestProDetach/success_on_attached_distro 1527s === RUN TestProDetach/error_on_'pro_detach'_returning_error_and_no_reason 1527s === PAUSE TestProDetach/error_on_'pro_detach'_returning_error_and_no_reason 1527s === RUN TestProDetach/error_on_'pro_detach'_error_and_some_reason 1527s === PAUSE TestProDetach/error_on_'pro_detach'_error_and_some_reason 1527s === CONT TestProAttach 1527s === RUN TestProAttach/success 1527s === PAUSE TestProAttach/success 1527s === RUN TestProAttach/error_on_'pro_attach'_error 1527s === PAUSE TestProAttach/error_on_'pro_attach'_error 1527s === CONT TestProStatus 1527s === RUN TestProStatus/success_on_unattached_distro 1527s === PAUSE TestProStatus/success_on_unattached_distro 1527s === RUN TestProStatus/success_on_attached_distro 1527s === PAUSE TestProStatus/success_on_attached_distro 1527s === RUN TestProStatus/error_on_'pro_attach'_returning_bad_output 1527s === PAUSE TestProStatus/error_on_'pro_attach'_returning_bad_output 1527s === RUN TestProStatus/error_on_'pro_attach'_error 1527s === PAUSE TestProStatus/error_on_'pro_attach'_error 1527s === CONT TestUserProfileDir 1527s === RUN TestUserProfileDir/Error_finding_cmd.exe_because_there_is_no_/proc/mounts 1527s === PAUSE TestUserProfileDir/Error_finding_cmd.exe_because_there_is_no_/proc/mounts 1527s === RUN TestUserProfileDir/Error_finding_cmd.exe_because_there_is_no_Windows_FS_in_/proc/mounts 1527s === PAUSE TestUserProfileDir/Error_finding_cmd.exe_because_there_is_no_Windows_FS_in_/proc/mounts 1527s === RUN TestUserProfileDir/Error_on_cmd.exe_error 1527s === PAUSE TestUserProfileDir/Error_on_cmd.exe_error 1527s === RUN TestUserProfileDir/Success_with_multiple_9P_filesystem_mounts 1527s === PAUSE TestUserProfileDir/Success_with_multiple_9P_filesystem_mounts 1527s === RUN TestUserProfileDir/Success_with_multiple_types_of_filesystem_mounts 1527s === PAUSE TestUserProfileDir/Success_with_multiple_types_of_filesystem_mounts 1527s === RUN TestUserProfileDir/Error_when_cmd.exe_does_not_exist 1527s === PAUSE TestUserProfileDir/Error_when_cmd.exe_does_not_exist 1527s === RUN TestUserProfileDir/Error_on_wslpath_error 1527s === PAUSE TestUserProfileDir/Error_on_wslpath_error 1527s === RUN TestUserProfileDir/Error_when_wslpath_returns_a_bad_path 1527s === PAUSE TestUserProfileDir/Error_when_wslpath_returns_a_bad_path 1527s === RUN TestUserProfileDir/Success_with_cached_cmd.exe_path 1527s === PAUSE TestUserProfileDir/Success_with_cached_cmd.exe_path 1527s === RUN TestUserProfileDir/Success_with_a_single_9P_filesystem_mount 1527s === PAUSE TestUserProfileDir/Success_with_a_single_9P_filesystem_mount 1527s === CONT TestInfo/Error_when_/etc/os-release_cannot_be_read 1531s === CONT TestInfo/Error_when_pro_status_output_cannot_be_parsed 1535s === CONT TestInfo/Error_when_pro_status_command_fails 1539s === CONT TestInfo/Success_using_wslpath 1547s === CONT TestInfo/Error_when_hostname_cannot_be_obtained 1552s === CONT TestInfo/Error_whem_/etc/os-release_returns_bad_contents 1556s === CONT TestInfo/Error_when_WSL_DISTRO_NAME_is_empty_and_wslpath_returns_bad_text 1560s === CONT TestInfo/Error_when_WSL_DISTRO_NAME_is_empty_and_wslpath_fails 1564s --- PASS: TestInfo (0.00s) 1564s --- PASS: TestInfo/Success_reading_from_WSL_DISTRO_NAME (4.65s) 1564s --- PASS: TestInfo/Error_when_/etc/os-release_cannot_be_read (3.92s) 1564s --- PASS: TestInfo/Error_when_pro_status_output_cannot_be_parsed (4.31s) 1564s --- PASS: TestInfo/Error_when_pro_status_command_fails (4.13s) 1564s --- PASS: TestInfo/Success_using_wslpath (8.17s) 1564s --- PASS: TestInfo/Error_when_hostname_cannot_be_obtained (4.15s) 1564s --- PASS: TestInfo/Error_whem_/etc/os-release_returns_bad_contents (4.00s) 1564s --- PASS: TestInfo/Error_when_WSL_DISTRO_NAME_is_empty_and_wslpath_returns_bad_text (3.87s) 1564s --- PASS: TestInfo/Error_when_WSL_DISTRO_NAME_is_empty_and_wslpath_fails (4.22s) 1564s === CONT TestLandscapeDisable/Success 1568s === CONT TestLandscapeDisable/Error_when_the_landscape-config_command_fails 1573s --- PASS: TestLandscapeDisable (0.00s) 1573s --- PASS: TestLandscapeDisable/Success (4.33s) 1573s --- PASS: TestLandscapeDisable/Error_when_the_landscape-config_command_fails (4.49s) 1573s === CONT TestWindowsHostAddress/Success_without_NAT 1577s === CONT TestLandscapeEnable/Success_overriding_computer_title 1577s time="2024-02-23T11:01:02Z" level=info msg="Landscape config contains key \"computer_title\". Its value will be overridden with TEST_DISTRO" 1581s system_test.go:413: testdata/TestLandscapeEnable/golden/success_overriding_computer_title 1581s === CONT TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_has_an_ill-formed_IP 1585s === CONT TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_is_ill-formed 1589s === CONT TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_has_an_ill-formed_IP 1593s === CONT TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_does_not_exist 1596s === CONT TestWindowsHostAddress/Error_when_wslinfo_returns_an_error 1600s === CONT TestWindowsHostAddress/Success_with_NAT,_nameserver_is_loopback 1604s === CONT TestWindowsHostAddress/Success_with_NAT,_nameserver_is_not_loopback 1608s === CONT TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_does_not_exist 1612s === CONT TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_is_ill-formed 1616s --- PASS: TestWindowsHostAddress (0.00s) 1616s --- PASS: TestWindowsHostAddress/Success_without_NAT (4.39s) 1616s --- PASS: TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_has_an_ill-formed_IP (3.82s) 1616s --- PASS: TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_is_ill-formed (3.77s) 1616s --- PASS: TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_has_an_ill-formed_IP (3.92s) 1616s --- PASS: TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_does_not_exist (3.68s) 1616s --- PASS: TestWindowsHostAddress/Error_when_wslinfo_returns_an_error (3.83s) 1616s --- PASS: TestWindowsHostAddress/Success_with_NAT,_nameserver_is_loopback (3.91s) 1616s --- PASS: TestWindowsHostAddress/Success_with_NAT,_nameserver_is_not_loopback (3.98s) 1616s --- PASS: TestWindowsHostAddress/Error_with_NAT_when_/proc/net/route_does_not_exist (3.95s) 1616s --- PASS: TestWindowsHostAddress/Error_with_NAT_when_/etc/resolv.conf_is_ill-formed (4.26s) 1616s === CONT TestProDetach/error_on_'pro_detach'_error_with_bad_JSON 1620s === CONT TestLandscapeEnable/Success 1625s system_test.go:413: testdata/TestLandscapeEnable/golden/success 1625s === CONT TestLandscapeEnable/Error_when_failing_to_override_the_SSL_certficate_path 1628s === CONT TestLandscapeEnable/Error_when_the_landscape-config_command_fails 1632s === CONT TestLandscapeEnable/Error_when_the_config_file_cannot_be_written 1632s === CONT TestLandscapeEnable/Error_when_the_file_cannot_be_parsed 1632s === CONT TestLandscapeEnable/Success_overriding_the_SSL_certficate_path 1640s system_test.go:413: testdata/TestLandscapeEnable/golden/success_overriding_the_ssl_certficate_path 1640s --- PASS: TestLandscapeEnable (0.00s) 1640s --- PASS: TestLandscapeEnable/Success_overriding_computer_title (4.15s) 1640s --- PASS: TestLandscapeEnable/Success (4.04s) 1640s --- PASS: TestLandscapeEnable/Error_when_failing_to_override_the_SSL_certficate_path (3.97s) 1640s --- PASS: TestLandscapeEnable/Error_when_the_landscape-config_command_fails (4.18s) 1640s --- PASS: TestLandscapeEnable/Error_when_the_config_file_cannot_be_written (0.02s) 1640s --- PASS: TestLandscapeEnable/Error_when_the_file_cannot_be_parsed (0.01s) 1640s --- PASS: TestLandscapeEnable/Success_overriding_the_SSL_certficate_path (8.22s) 1640s === CONT TestProAttach/success 1644s === CONT TestProDetach/error_on_'pro_detach'_error_and_some_reason 1648s === CONT TestProDetach/error_on_'pro_detach'_returning_error_and_no_reason 1652s === CONT TestProDetach/success_on_attached_distro 1656s === CONT TestProDetach/success_on_unattached_distro 1660s --- PASS: TestProDetach (0.00s) 1660s --- PASS: TestProDetach/error_on_'pro_detach'_error_with_bad_JSON (3.78s) 1660s --- PASS: TestProDetach/error_on_'pro_detach'_error_and_some_reason (3.99s) 1660s --- PASS: TestProDetach/error_on_'pro_detach'_returning_error_and_no_reason (4.17s) 1660s --- PASS: TestProDetach/success_on_attached_distro (4.00s) 1660s --- PASS: TestProDetach/success_on_unattached_distro (3.81s) 1660s === CONT TestProStatus/success_on_unattached_distro 1664s === CONT TestProAttach/error_on_'pro_attach'_error 1668s --- PASS: TestProAttach (0.00s) 1668s --- PASS: TestProAttach/success (3.85s) 1668s --- PASS: TestProAttach/error_on_'pro_attach'_error (3.88s) 1668s === CONT TestUserProfileDir/Error_finding_cmd.exe_because_there_is_no_/proc/mounts 1668s system_test.go:166: Removing default proc/mounts 1668s === CONT TestProStatus/error_on_'pro_attach'_error 1672s === CONT TestProStatus/error_on_'pro_attach'_returning_bad_output 1676s === CONT TestProStatus/success_on_attached_distro 1680s --- PASS: TestProStatus (0.00s) 1680s --- PASS: TestProStatus/success_on_unattached_distro (3.87s) 1680s --- PASS: TestProStatus/error_on_'pro_attach'_error (3.89s) 1680s --- PASS: TestProStatus/error_on_'pro_attach'_returning_bad_output (3.77s) 1680s --- PASS: TestProStatus/success_on_attached_distro (4.05s) 1680s === CONT TestUserProfileDir/Success_with_a_single_9P_filesystem_mount 1688s === CONT TestUserProfileDir/Success_with_cached_cmd.exe_path 1695s === CONT TestUserProfileDir/Error_when_wslpath_returns_a_bad_path 1703s === CONT TestUserProfileDir/Error_on_wslpath_error 1711s === CONT TestUserProfileDir/Error_when_cmd.exe_does_not_exist 1711s === CONT TestUserProfileDir/Success_with_multiple_types_of_filesystem_mounts 1719s === CONT TestUserProfileDir/Success_with_multiple_9P_filesystem_mounts 1726s === CONT TestUserProfileDir/Error_on_cmd.exe_error 1730s === CONT TestUserProfileDir/Error_finding_cmd.exe_because_there_is_no_Windows_FS_in_/proc/mounts 1730s system_test.go:166: Removing default proc/mounts 1730s --- PASS: TestUserProfileDir (0.00s) 1730s --- PASS: TestUserProfileDir/Error_finding_cmd.exe_because_there_is_no_/proc/mounts (0.01s) 1730s --- PASS: TestUserProfileDir/Success_with_a_single_9P_filesystem_mount (7.87s) 1730s --- PASS: TestUserProfileDir/Success_with_cached_cmd.exe_path (7.59s) 1730s --- PASS: TestUserProfileDir/Error_when_wslpath_returns_a_bad_path (8.04s) 1730s --- PASS: TestUserProfileDir/Error_on_wslpath_error (7.64s) 1730s --- PASS: TestUserProfileDir/Error_when_cmd.exe_does_not_exist (0.01s) 1730s --- PASS: TestUserProfileDir/Success_with_multiple_types_of_filesystem_mounts (7.99s) 1730s --- PASS: TestUserProfileDir/Success_with_multiple_9P_filesystem_mounts (7.48s) 1730s --- PASS: TestUserProfileDir/Error_on_cmd.exe_error (3.96s) 1730s --- PASS: TestUserProfileDir/Error_finding_cmd.exe_because_there_is_no_Windows_FS_in_/proc/mounts (0.01s) 1730s PASS 1730s ok github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/internal/system 208.106s 1730s ? github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/internal/testutils [no test files] 1733s === RUN TestApplyProToken 1733s === PAUSE TestApplyProToken 1733s === RUN TestApplyLandscapeConfig 1733s === PAUSE TestApplyLandscapeConfig 1733s === RUN TestWithProMock 1733s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 1733s --- SKIP: TestWithProMock (0.00s) 1733s === RUN TestWithLandscapeConfigMock 1733s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 1733s --- SKIP: TestWithLandscapeConfigMock (0.00s) 1733s === RUN TestWithWslPathMock 1733s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 1733s --- SKIP: TestWithWslPathMock (0.00s) 1733s === RUN TestWithWslInfoMock 1733s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 1733s --- SKIP: TestWithWslInfoMock (0.00s) 1733s === RUN TestWithCmdExeMock 1733s mock_executables.go:576: Skipped because it is not a real test, but rather a mocked executable 1733s --- SKIP: TestWithCmdExeMock (0.00s) 1733s === CONT TestApplyProToken 1733s === RUN TestApplyProToken/success_attaching_non-attached_machine 1733s === PAUSE TestApplyProToken/success_attaching_non-attached_machine 1733s === RUN TestApplyProToken/success_detaching_attached_machine 1733s === PAUSE TestApplyProToken/success_detaching_attached_machine 1733s === RUN TestApplyProToken/Error_calling_pro_attach 1733s === PAUSE TestApplyProToken/Error_calling_pro_attach 1733s === RUN TestApplyProToken/Error_calling_pro_status 1733s === PAUSE TestApplyProToken/Error_calling_pro_status 1733s === RUN TestApplyProToken/Error_getting_system_info 1733s === PAUSE TestApplyProToken/Error_getting_system_info 1733s === RUN TestApplyProToken/success_attaching_attached_machine 1733s === PAUSE TestApplyProToken/success_attaching_attached_machine 1733s === RUN TestApplyProToken/success_detaching_non-attached_machine 1733s === PAUSE TestApplyProToken/success_detaching_non-attached_machine 1733s === RUN TestApplyProToken/Error_detaching_pro 1733s === PAUSE TestApplyProToken/Error_detaching_pro 1733s === RUN TestApplyProToken/Error_cannot_send_info_to_stream 1733s === PAUSE TestApplyProToken/Error_cannot_send_info_to_stream 1733s === CONT TestApplyProToken/success_attaching_non-attached_machine 1733s time="2024-02-23T11:03:38Z" level=debug msg="Registering GRPC WSL instance service" 1733s wslinstanceservice_test.go:108: Serving WslInstanceService on 127.0.0.1:39803 1733s wslinstanceservice_test.go:108: Client connected to WslInstanceService 1733s time="2024-02-23T11:03:38Z" level=info msg="ApplyProToken: Received token \"***\": attaching" 1744s === CONT TestApplyLandscapeConfig 1744s === RUN TestApplyLandscapeConfig/Error_enabling_when_landscape-config_fails 1744s === PAUSE TestApplyLandscapeConfig/Error_enabling_when_landscape-config_fails 1744s === RUN TestApplyLandscapeConfig/Error_disabling_when_landscape-config_--disable_fails 1744s === PAUSE TestApplyLandscapeConfig/Error_disabling_when_landscape-config_--disable_fails 1744s === RUN TestApplyLandscapeConfig/Success_enabling 1744s === PAUSE TestApplyLandscapeConfig/Success_enabling 1744s === RUN TestApplyLandscapeConfig/Success_disabling 1744s === PAUSE TestApplyLandscapeConfig/Success_disabling 1744s === CONT TestApplyProToken/Error_cannot_send_info_to_stream 1744s time="2024-02-23T11:03:49Z" level=debug msg="Registering GRPC WSL instance service" 1744s wslinstanceservice_test.go:108: Serving WslInstanceService on 127.0.0.1:35139 1744s wslinstanceservice_test.go:108: Client connected to WslInstanceService 1744s time="2024-02-23T11:03:49Z" level=info msg="ApplyProToken: Received empty token: detaching" 1752s time="2024-02-23T11:03:57Z" level=warning msg="Error in ApplyProToken: could not send back system info: test error" 1752s === CONT TestApplyProToken/Error_detaching_pro 1752s time="2024-02-23T11:03:57Z" level=debug msg="Registering GRPC WSL instance service" 1752s wslinstanceservice_test.go:108: Serving WslInstanceService on 127.0.0.1:42107 1752s wslinstanceservice_test.go:108: Client connected to WslInstanceService 1752s time="2024-02-23T11:03:57Z" level=info msg="ApplyProToken: Received empty token: detaching" 1756s time="2024-02-23T11:04:01Z" level=error msg="Error in ApplyProToken: detachPro: command returned error: mock_error: This error is produced by a mock instructed to fail on pro detach" 1760s === CONT TestApplyProToken/success_detaching_non-attached_machine 1760s time="2024-02-23T11:04:04Z" level=debug msg="Registering GRPC WSL instance service" 1760s wslinstanceservice_test.go:108: Serving WslInstanceService on 127.0.0.1:44355 1760s wslinstanceservice_test.go:108: Client connected to WslInstanceService 1760s time="2024-02-23T11:04:04Z" level=info msg="ApplyProToken: Received empty token: detaching" 1767s === CONT TestApplyProToken/success_attaching_attached_machine 1767s time="2024-02-23T11:04:12Z" level=debug msg="Registering GRPC WSL instance service" 1767s wslinstanceservice_test.go:108: Serving WslInstanceService on 127.0.0.1:34943 1767s wslinstanceservice_test.go:108: Client connected to WslInstanceService 1767s time="2024-02-23T11:04:12Z" level=info msg="ApplyProToken: Received token \"***\": attaching" 1778s === CONT TestApplyProToken/Error_getting_system_info 1778s time="2024-02-23T11:04:23Z" level=debug msg="Registering GRPC WSL instance service" 1778s wslinstanceservice_test.go:108: Serving WslInstanceService on 127.0.0.1:41307 1778s wslinstanceservice_test.go:108: Client connected to WslInstanceService 1778s time="2024-02-23T11:04:23Z" level=info msg="ApplyProToken: Received empty token: detaching" 1786s time="2024-02-23T11:04:31Z" level=warning msg="Error in ApplyProToken: could not gather system info: could not read /etc/os-release file: open /tmp/TestApplyProTokenError_getting_system_info1426609663/001/etc/os-release: no such file or directory" 1786s === CONT TestApplyProToken/Error_calling_pro_status 1786s time="2024-02-23T11:04:31Z" level=debug msg="Registering GRPC WSL instance service" 1786s wslinstanceservice_test.go:108: Serving WslInstanceService on 127.0.0.1:44119 1786s wslinstanceservice_test.go:108: Client connected to WslInstanceService 1786s time="2024-02-23T11:04:31Z" level=info msg="ApplyProToken: Received empty token: detaching" 1794s time="2024-02-23T11:04:39Z" level=warning msg="Error in ApplyProToken: could not gather system info: could not obtain pro status: pro status command returned error: exit status 1\nStdout:" 1794s === CONT TestApplyProToken/Error_calling_pro_attach 1794s time="2024-02-23T11:04:39Z" level=debug msg="Registering GRPC WSL instance service" 1794s wslinstanceservice_test.go:108: Serving WslInstanceService on 127.0.0.1:46125 1794s wslinstanceservice_test.go:108: Client connected to WslInstanceService 1794s time="2024-02-23T11:04:39Z" level=info msg="ApplyProToken: Received token \"***\": attaching" 1801s time="2024-02-23T11:04:46Z" level=error msg="Error in ApplyProToken: attachPro:: command returned error: exit status 1\nOutput:{\"message\": \"This error is produced by a mock instructed to fail on pro attach\", \"message_code\": \"mock_error\"}\n" 1805s === CONT TestApplyProToken/success_detaching_attached_machine 1805s time="2024-02-23T11:04:50Z" level=debug msg="Registering GRPC WSL instance service" 1805s wslinstanceservice_test.go:108: Serving WslInstanceService on 127.0.0.1:44919 1805s wslinstanceservice_test.go:108: Client connected to WslInstanceService 1805s time="2024-02-23T11:04:50Z" level=info msg="ApplyProToken: Received empty token: detaching" 1813s --- PASS: TestApplyProToken (0.00s) 1813s --- PASS: TestApplyProToken/success_attaching_non-attached_machine (11.30s) 1813s --- PASS: TestApplyProToken/Error_cannot_send_info_to_stream (7.76s) 1813s --- PASS: TestApplyProToken/Error_detaching_pro (7.68s) 1813s --- PASS: TestApplyProToken/success_detaching_non-attached_machine (7.77s) 1813s --- PASS: TestApplyProToken/success_attaching_attached_machine (11.10s) 1813s --- PASS: TestApplyProToken/Error_getting_system_info (7.65s) 1813s --- PASS: TestApplyProToken/Error_calling_pro_status (7.62s) 1813s --- PASS: TestApplyProToken/Error_calling_pro_attach (11.20s) 1813s --- PASS: TestApplyProToken/success_detaching_attached_machine (7.72s) 1813s === CONT TestApplyLandscapeConfig/Error_enabling_when_landscape-config_fails 1813s time="2024-02-23T11:04:58Z" level=debug msg="Registering GRPC WSL instance service" 1813s wslinstanceservice_test.go:167: Serving WslInstanceService on 127.0.0.1:44675 1813s wslinstanceservice_test.go:167: Client connected to WslInstanceService 1813s time="2024-02-23T11:04:58Z" level=info msg="ApplyLandscapeConfig: Received config: registering" 1817s === CONT TestApplyLandscapeConfig/Success_disabling 1817s time="2024-02-23T11:05:02Z" level=debug msg="Registering GRPC WSL instance service" 1817s wslinstanceservice_test.go:167: Serving WslInstanceService on 127.0.0.1:43765 1817s wslinstanceservice_test.go:167: Client connected to WslInstanceService 1817s time="2024-02-23T11:05:02Z" level=info msg="ApplyLandscapeConfig: Received empty config: disabling" 1821s === CONT TestApplyLandscapeConfig/Success_enabling 1821s time="2024-02-23T11:05:06Z" level=debug msg="Registering GRPC WSL instance service" 1821s wslinstanceservice_test.go:167: Serving WslInstanceService on 127.0.0.1:38479 1821s wslinstanceservice_test.go:167: Client connected to WslInstanceService 1821s time="2024-02-23T11:05:06Z" level=info msg="ApplyLandscapeConfig: Received config: registering" 1825s wslinstanceservice_test.go:192: testdata/TestApplyLandscapeConfig/golden/success_enabling 1825s === CONT TestApplyLandscapeConfig/Error_disabling_when_landscape-config_--disable_fails 1825s time="2024-02-23T11:05:10Z" level=debug msg="Registering GRPC WSL instance service" 1825s wslinstanceservice_test.go:167: Serving WslInstanceService on 127.0.0.1:44899 1825s wslinstanceservice_test.go:167: Client connected to WslInstanceService 1825s time="2024-02-23T11:05:10Z" level=info msg="ApplyLandscapeConfig: Received empty config: disabling" 1828s --- PASS: TestApplyLandscapeConfig (0.00s) 1828s --- PASS: TestApplyLandscapeConfig/Error_enabling_when_landscape-config_fails (4.16s) 1828s --- PASS: TestApplyLandscapeConfig/Success_disabling (3.98s) 1828s --- PASS: TestApplyLandscapeConfig/Success_enabling (3.90s) 1828s --- PASS: TestApplyLandscapeConfig/Error_disabling_when_landscape-config_--disable_fails (3.75s) 1828s PASS 1828s ok github.com/canonical/ubuntu-pro-for-wsl/wsl-pro-service/internal/wslinstanceservice 95.637s 1829s autopkgtest [11:05:14]: test command1: -----------------------] 1831s autopkgtest [11:05:16]: test command1: - - - - - - - - - - results - - - - - - - - - - 1831s command1 PASS 1831s autopkgtest [11:05:16]: @@@@@@@@@@@@@@@@@@@@ summary 1831s command1 PASS 1842s Creating nova instance adt-noble-arm64-wsl-pro-service-20240223-103445-juju-7f2275-prod-proposed-migration-environment-3 from image adt/ubuntu-noble-arm64-server-20240221.img (UUID 1411f613-eac1-48c7-932b-5015f299e718)...