0s autopkgtest [08:17:00]: starting date and time: 2025-01-14 08:17:00+0000 0s autopkgtest [08:17:00]: git checkout: 325255d2 Merge branch 'pin-any-arch' into 'ubuntu/production' 0s autopkgtest [08:17:00]: host juju-7f2275-prod-proposed-migration-environment-20; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.kq2ohh0_/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:util-linux,src:golang-github-containers-buildah,src:golang-github-containers-psgo,src:mmdebstrap,src:shadow,src:sssd --apt-upgrade asterisk --timeout-short=300 --timeout-copy=20000 --timeout-build=20000 '--env=ADT_TEST_TRIGGERS=util-linux/2.40.2-14ubuntu1 golang-github-containers-buildah/1.38.0+ds1-2 golang-github-containers-psgo/1.9.0-1 mmdebstrap/1.5.6-2 shadow/1:4.16.0-7ubuntu1 sssd/2.10.1-1ubuntu2' -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-s390x --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-20@bos03-s390x-16.secgroup --name adt-plucky-s390x-asterisk-20250114-081700-juju-7f2275-prod-proposed-migration-environment-20-c97fc488-9475-4004-94b9-f4e1503b5ac5 --image adt/ubuntu-plucky-s390x-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-20 --net-id=net_prod-proposed-migration-s390x -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com,radosgw.ps5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 54s autopkgtest [08:17:54]: testbed dpkg architecture: s390x 54s autopkgtest [08:17:54]: testbed apt version: 2.9.18 55s autopkgtest [08:17:55]: @@@@@@@@@@@@@@@@@@@@ test bed setup 55s autopkgtest [08:17:55]: testbed release detected to be: None 56s autopkgtest [08:17:56]: updating testbed package index (apt update) 56s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [73.9 kB] 56s Hit:2 http://ftpmaster.internal/ubuntu plucky InRelease 56s Hit:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease 56s Hit:4 http://ftpmaster.internal/ubuntu plucky-security InRelease 56s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [138 kB] 56s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [856 kB] 57s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/restricted Sources [9708 B] 57s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [10.3 kB] 57s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x Packages [247 kB] 57s Get:10 http://ftpmaster.internal/ubuntu plucky-proposed/restricted s390x Packages [756 B] 57s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/universe s390x Packages [907 kB] 57s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse s390x Packages [4072 B] 57s Fetched 2247 kB in 1s (2335 kB/s) 57s Reading package lists... 58s Reading package lists... 58s Building dependency tree... 58s Reading state information... 58s Calculating upgrade... 58s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 58s Reading package lists... 58s Building dependency tree... 58s Reading state information... 59s 0 upgraded, 0 newly installed, 0 to remove and 14 not upgraded. 59s autopkgtest [08:17:59]: upgrading testbed (apt dist-upgrade and autopurge) 59s Reading package lists... 59s Building dependency tree... 59s Reading state information... 59s Calculating upgrade...Starting pkgProblemResolver with broken count: 0 59s Starting 2 pkgProblemResolver with broken count: 0 59s Done 59s Entering ResolveByKeep 59s 59s The following NEW packages will be installed: 59s login.defs 59s The following packages will be upgraded: 59s bsdextrautils bsdutils eject fdisk libblkid1 libfdisk1 libmount1 59s libsmartcols1 libuuid1 login mount passwd util-linux uuid-runtime 60s 14 upgraded, 1 newly installed, 0 to remove and 0 not upgraded. 60s Need to get 3481 kB of archives. 60s After this operation, 1482 kB of additional disk space will be used. 60s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x bsdutils s390x 1:2.40.2-14ubuntu1 [103 kB] 60s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x eject s390x 2.40.2-14ubuntu1 [46.1 kB] 60s Get:3 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x bsdextrautils s390x 2.40.2-14ubuntu1 [91.2 kB] 60s Get:4 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libfdisk1 s390x 2.40.2-14ubuntu1 [169 kB] 60s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x fdisk s390x 2.40.2-14ubuntu1 [144 kB] 60s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libblkid1 s390x 2.40.2-14ubuntu1 [134 kB] 60s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libmount1 s390x 2.40.2-14ubuntu1 [158 kB] 60s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libsmartcols1 s390x 2.40.2-14ubuntu1 [89.5 kB] 60s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x mount s390x 2.40.2-14ubuntu1 [139 kB] 60s Get:10 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libuuid1 s390x 2.40.2-14ubuntu1 [42.4 kB] 60s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x util-linux s390x 2.40.2-14ubuntu1 [1129 kB] 60s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x uuid-runtime s390x 2.40.2-14ubuntu1 [54.2 kB] 60s Get:13 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x login.defs all 1:4.16.0-7ubuntu1 [38.5 kB] 60s Get:14 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x login s390x 1:4.16.0-2+really2.40.2-14ubuntu1 [77.7 kB] 60s Get:15 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x passwd s390x 1:4.16.0-7ubuntu1 [1066 kB] 60s Fetched 3481 kB in 1s (4540 kB/s) 61s (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 ... 55642 files and directories currently installed.) 61s Preparing to unpack .../bsdutils_1%3a2.40.2-14ubuntu1_s390x.deb ... 61s Unpacking bsdutils (1:2.40.2-14ubuntu1) over (1:2.40.2-1ubuntu2) ... 61s Setting up bsdutils (1:2.40.2-14ubuntu1) ... 61s (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 ... 55642 files and directories currently installed.) 61s Preparing to unpack .../eject_2.40.2-14ubuntu1_s390x.deb ... 61s Unpacking eject (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 61s Preparing to unpack .../bsdextrautils_2.40.2-14ubuntu1_s390x.deb ... 61s Unpacking bsdextrautils (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 61s Preparing to unpack .../libfdisk1_2.40.2-14ubuntu1_s390x.deb ... 61s Unpacking libfdisk1:s390x (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 61s Preparing to unpack .../fdisk_2.40.2-14ubuntu1_s390x.deb ... 61s Unpacking fdisk (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 61s Preparing to unpack .../libblkid1_2.40.2-14ubuntu1_s390x.deb ... 61s Unpacking libblkid1:s390x (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 61s Setting up libblkid1:s390x (2.40.2-14ubuntu1) ... 61s (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 ... 55638 files and directories currently installed.) 61s Preparing to unpack .../libmount1_2.40.2-14ubuntu1_s390x.deb ... 61s Unpacking libmount1:s390x (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 61s Setting up libmount1:s390x (2.40.2-14ubuntu1) ... 61s (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 ... 55638 files and directories currently installed.) 61s Preparing to unpack .../libsmartcols1_2.40.2-14ubuntu1_s390x.deb ... 61s Unpacking libsmartcols1:s390x (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 61s Setting up libsmartcols1:s390x (2.40.2-14ubuntu1) ... 61s (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 ... 55638 files and directories currently installed.) 61s Preparing to unpack .../mount_2.40.2-14ubuntu1_s390x.deb ... 61s Unpacking mount (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 61s Preparing to unpack .../libuuid1_2.40.2-14ubuntu1_s390x.deb ... 61s Unpacking libuuid1:s390x (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 61s Setting up libuuid1:s390x (2.40.2-14ubuntu1) ... 61s (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 ... 55638 files and directories currently installed.) 61s Preparing to unpack .../util-linux_2.40.2-14ubuntu1_s390x.deb ... 61s Unpacking util-linux (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 61s Setting up util-linux (2.40.2-14ubuntu1) ... 61s fstrim.service is a disabled or a static unit not running, not starting it. 61s (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 ... 55631 files and directories currently installed.) 61s Preparing to unpack .../uuid-runtime_2.40.2-14ubuntu1_s390x.deb ... 61s Unpacking uuid-runtime (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 61s Selecting previously unselected package login.defs. 61s Preparing to unpack .../login.defs_1%3a4.16.0-7ubuntu1_all.deb ... 61s Unpacking login.defs (1:4.16.0-7ubuntu1) ... 61s Replacing files in old package login (1:4.15.3-3ubuntu2) ... 61s Setting up login.defs (1:4.16.0-7ubuntu1) ... 61s Installing new version of config file /etc/login.defs ... 61s (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 ... 55635 files and directories currently installed.) 61s Preparing to unpack .../login_1%3a4.16.0-2+really2.40.2-14ubuntu1_s390x.deb ... 61s Unpacking login (1:4.16.0-2+really2.40.2-14ubuntu1) over (1:4.15.3-3ubuntu2) ... 61s Preparing to unpack .../passwd_1%3a4.16.0-7ubuntu1_s390x.deb ... 61s Unpacking passwd (1:4.16.0-7ubuntu1) over (1:4.15.3-3ubuntu2) ... 62s Setting up passwd (1:4.16.0-7ubuntu1) ... 62s Setting up bsdextrautils (2.40.2-14ubuntu1) ... 62s Setting up eject (2.40.2-14ubuntu1) ... 62s Setting up libfdisk1:s390x (2.40.2-14ubuntu1) ... 62s Setting up mount (2.40.2-14ubuntu1) ... 62s Setting up uuid-runtime (2.40.2-14ubuntu1) ... 62s uuidd.service is a disabled or a static unit not running, not starting it. 62s Setting up login (1:4.16.0-2+really2.40.2-14ubuntu1) ... 62s Setting up fdisk (2.40.2-14ubuntu1) ... 62s Processing triggers for man-db (2.13.0-1) ... 63s Processing triggers for libc-bin (2.40-4ubuntu1) ... 64s Reading package lists... 64s Building dependency tree... 64s Reading state information... 64s Starting pkgProblemResolver with broken count: 0 64s Starting 2 pkgProblemResolver with broken count: 0 64s Done 64s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 64s autopkgtest [08:18:04]: rebooting testbed after setup commands that affected boot 85s autopkgtest [08:18:25]: testbed running kernel: Linux 6.11.0-8-generic #8-Ubuntu SMP Mon Sep 16 12:49:35 UTC 2024 88s autopkgtest [08:18:28]: @@@@@@@@@@@@@@@@@@@@ apt-source asterisk 94s Get:1 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:22.1.0~dfsg+~cs6.14.60671435-1 (dsc) [5416 B] 94s Get:2 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:22.1.0~dfsg+~cs6.14.60671435-1 (tar) [11.3 kB] 94s Get:3 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:22.1.0~dfsg+~cs6.14.60671435-1 (tar) [22.0 kB] 94s Get:4 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:22.1.0~dfsg+~cs6.14.60671435-1 (tar) [22.5 kB] 94s Get:5 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:22.1.0~dfsg+~cs6.14.60671435-1 (tar) [6344 kB] 94s Get:6 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:22.1.0~dfsg+~cs6.14.60671435-1 (tar) [5938 kB] 94s Get:7 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:22.1.0~dfsg+~cs6.14.60671435-1 (diff) [122 kB] 94s gpgv: Signature made Wed Nov 27 11:44:19 2024 UTC 94s gpgv: using RSA key 9FE3E9C36691A69FF53CC6842C7C3146C1A00121 94s gpgv: Can't check signature: No public key 94s dpkg-source: warning: cannot verify inline signature for ./asterisk_22.1.0~dfsg+~cs6.14.60671435-1.dsc: no acceptable signature found 95s autopkgtest [08:18:35]: testing package asterisk version 1:22.1.0~dfsg+~cs6.14.60671435-1 96s autopkgtest [08:18:36]: build not needed 101s autopkgtest [08:18:41]: test asttestmods: preparing testbed 101s Reading package lists... 101s Building dependency tree... 101s Reading state information... 101s Starting pkgProblemResolver with broken count: 0 101s Starting 2 pkgProblemResolver with broken count: 0 101s Done 102s The following NEW packages will be installed: 102s asterisk asterisk-config asterisk-core-sounds-en asterisk-core-sounds-en-gsm 102s asterisk-modules asterisk-tests freetds-common libasound2-data libasound2t64 102s libb64-0d libc-client2007e libcodec2-1.2 libdeflate0 libevent-2.1-7t64 102s libgmime-3.0-0t64 libgsm1 libical3t64 libiksemel3 libjack-jackd2-0 libjbig0 102s libjpeg-turbo8 libjpeg8 libjwt2 libltdl7 liblua5.1-0 libneon27t64 libodbc2 102s libogg0 libopencore-amrnb0 libopencore-amrwb0 libopus0 libopusenc0 102s libopusfile0 libportaudio2 libpq5 libradcli4 libresample1 libsamplerate0 102s libsharpyuv0 libsnmp-base libsnmp40t64 libspandsp2t64 libspeex1 libspeexdsp1 102s libsrtp2-1 libsybdb5 libtiff6 libunbound8 liburiparser1 libvo-amrwbenc0 102s libvorbis0a libvorbisenc2 libvorbisfile3 libwebp7 libxml2-utils libxslt1.1 102s mlock 102s 0 upgraded, 57 newly installed, 0 to remove and 0 not upgraded. 102s Need to get 29.0 MB of archives. 102s After this operation, 71.9 MB of additional disk space will be used. 102s Get:1 http://ftpmaster.internal/ubuntu plucky/universe s390x asterisk-config all 1:22.1.0~dfsg+~cs6.14.60671435-1 [223 kB] 102s Get:2 http://ftpmaster.internal/ubuntu plucky/universe s390x asterisk-core-sounds-en-gsm all 1.6.1-1 [2417 kB] 102s Get:3 http://ftpmaster.internal/ubuntu plucky/universe s390x asterisk-core-sounds-en all 1.6.1-1 [20.6 kB] 102s Get:4 http://ftpmaster.internal/ubuntu plucky/universe s390x mlock s390x 8:2007f~dfsg-7.1 [8630 B] 102s Get:5 http://ftpmaster.internal/ubuntu plucky/universe s390x libc-client2007e s390x 8:2007f~dfsg-7.1 [648 kB] 102s Get:6 http://ftpmaster.internal/ubuntu plucky/universe s390x libcodec2-1.2 s390x 1.2.0-2build1 [9028 kB] 103s Get:7 http://ftpmaster.internal/ubuntu plucky/universe s390x libgmime-3.0-0t64 s390x 3.2.15+dfsg-1 [184 kB] 103s Get:8 http://ftpmaster.internal/ubuntu plucky/universe s390x libgsm1 s390x 1.0.22-1build1 [32.7 kB] 103s Get:9 http://ftpmaster.internal/ubuntu plucky/main s390x libical3t64 s390x 3.0.19-1build1 [312 kB] 103s Get:10 http://ftpmaster.internal/ubuntu plucky/universe s390x libiksemel3 s390x 1.4-4build2 [28.7 kB] 103s Get:11 http://ftpmaster.internal/ubuntu plucky/main s390x libopus0 s390x 1.5.2-2 [2928 kB] 103s Get:12 http://ftpmaster.internal/ubuntu plucky/main s390x libsamplerate0 s390x 0.2.2-4build1 [1344 kB] 103s Get:13 http://ftpmaster.internal/ubuntu plucky/main s390x libjack-jackd2-0 s390x 1.9.22~dfsg-4 [292 kB] 103s Get:14 http://ftpmaster.internal/ubuntu plucky/universe s390x libb64-0d s390x 1.2-5build1 [9656 B] 103s Get:15 http://ftpmaster.internal/ubuntu plucky/universe s390x libjwt2 s390x 1.17.2-1 [18.2 kB] 103s Get:16 http://ftpmaster.internal/ubuntu plucky/universe s390x liblua5.1-0 s390x 5.1.5-10 [130 kB] 103s Get:17 http://ftpmaster.internal/ubuntu plucky/universe s390x libneon27t64 s390x 0.34.0-1 [105 kB] 103s Get:18 http://ftpmaster.internal/ubuntu plucky/main s390x libltdl7 s390x 2.4.7-8 [41.5 kB] 103s Get:19 http://ftpmaster.internal/ubuntu plucky/main s390x libodbc2 s390x 2.3.12-1ubuntu1 [162 kB] 103s Get:20 http://ftpmaster.internal/ubuntu plucky/main s390x libogg0 s390x 1.3.5-3build1 [24.4 kB] 103s Get:21 http://ftpmaster.internal/ubuntu plucky/universe s390x libopencore-amrnb0 s390x 0.1.6-1build1 [108 kB] 103s Get:22 http://ftpmaster.internal/ubuntu plucky/universe s390x libopencore-amrwb0 s390x 0.1.6-1build1 [56.6 kB] 103s Get:23 http://ftpmaster.internal/ubuntu plucky/universe s390x libopusenc0 s390x 0.2.1-2build1 [29.0 kB] 103s Get:24 http://ftpmaster.internal/ubuntu plucky/universe s390x libopusfile0 s390x 0.12-4build3 [48.0 kB] 103s Get:25 http://ftpmaster.internal/ubuntu plucky/main s390x libasound2-data all 1.2.12-1 [21.0 kB] 103s Get:26 http://ftpmaster.internal/ubuntu plucky/main s390x libasound2t64 s390x 1.2.12-1 [408 kB] 103s Get:27 http://ftpmaster.internal/ubuntu plucky/universe s390x libportaudio2 s390x 19.6.0-1.2build3 [71.6 kB] 103s Get:28 http://ftpmaster.internal/ubuntu plucky/main s390x libpq5 s390x 17.2-1 [146 kB] 103s Get:29 http://ftpmaster.internal/ubuntu plucky/universe s390x libradcli4 s390x 1.2.11-1build3 [40.9 kB] 103s Get:30 http://ftpmaster.internal/ubuntu plucky/universe s390x libresample1 s390x 0.1.3-8 [9388 B] 103s Get:31 http://ftpmaster.internal/ubuntu plucky/main s390x libsnmp-base all 5.9.4+dfsg-1.1ubuntu5 [206 kB] 103s Get:32 http://ftpmaster.internal/ubuntu plucky/main s390x libsnmp40t64 s390x 5.9.4+dfsg-1.1ubuntu5 [1055 kB] 103s Get:33 http://ftpmaster.internal/ubuntu plucky/main s390x libdeflate0 s390x 1.22-1 [46.1 kB] 103s Get:34 http://ftpmaster.internal/ubuntu plucky/main s390x libjbig0 s390x 2.1-6.1ubuntu2 [33.1 kB] 103s Get:35 http://ftpmaster.internal/ubuntu plucky/main s390x libjpeg-turbo8 s390x 2.1.5-3ubuntu2 [147 kB] 103s Get:36 http://ftpmaster.internal/ubuntu plucky/main s390x libjpeg8 s390x 8c-2ubuntu11 [2146 B] 103s Get:37 http://ftpmaster.internal/ubuntu plucky/main s390x libsharpyuv0 s390x 1.4.0-0.1 [16.2 kB] 103s Get:38 http://ftpmaster.internal/ubuntu plucky/main s390x libwebp7 s390x 1.4.0-0.1 [204 kB] 103s Get:39 http://ftpmaster.internal/ubuntu plucky/main s390x libtiff6 s390x 4.5.1+git230720-4ubuntu4 [217 kB] 103s Get:40 http://ftpmaster.internal/ubuntu plucky/universe s390x libspandsp2t64 s390x 0.0.6+dfsg-2.1build1 [336 kB] 103s Get:41 http://ftpmaster.internal/ubuntu plucky/main s390x libspeex1 s390x 1.2.1-3 [70.7 kB] 103s Get:42 http://ftpmaster.internal/ubuntu plucky/main s390x libspeexdsp1 s390x 1.2.1-1ubuntu3 [54.4 kB] 103s Get:43 http://ftpmaster.internal/ubuntu plucky/universe s390x libsrtp2-1 s390x 2.5.0-3build1 [41.3 kB] 103s Get:44 http://ftpmaster.internal/ubuntu plucky/main s390x freetds-common all 1.3.17+ds-2build3 [26.9 kB] 103s Get:45 http://ftpmaster.internal/ubuntu plucky/main s390x libsybdb5 s390x 1.3.17+ds-2build3 [209 kB] 103s Get:46 http://ftpmaster.internal/ubuntu plucky/main s390x libevent-2.1-7t64 s390x 2.1.12-stable-10 [145 kB] 103s Get:47 http://ftpmaster.internal/ubuntu plucky/main s390x libunbound8 s390x 1.20.0-1ubuntu2.1 [455 kB] 103s Get:48 http://ftpmaster.internal/ubuntu plucky/universe s390x libvo-amrwbenc0 s390x 0.1.3-2build1 [87.8 kB] 103s Get:49 http://ftpmaster.internal/ubuntu plucky/main s390x libvorbis0a s390x 1.3.7-2 [112 kB] 103s Get:50 http://ftpmaster.internal/ubuntu plucky/main s390x libvorbisenc2 s390x 1.3.7-2 [80.6 kB] 103s Get:51 http://ftpmaster.internal/ubuntu plucky/main s390x libvorbisfile3 s390x 1.3.7-2 [18.2 kB] 103s Get:52 http://ftpmaster.internal/ubuntu plucky/universe s390x asterisk-modules s390x 1:22.1.0~dfsg+~cs6.14.60671435-1 [3007 kB] 104s Get:53 http://ftpmaster.internal/ubuntu plucky/universe s390x liburiparser1 s390x 0.9.8+dfsg-2 [42.4 kB] 104s Get:54 http://ftpmaster.internal/ubuntu plucky/main s390x libxslt1.1 s390x 1.1.39-0exp1ubuntu2 [169 kB] 104s Get:55 http://ftpmaster.internal/ubuntu plucky/universe s390x asterisk s390x 1:22.1.0~dfsg+~cs6.14.60671435-1 [2724 kB] 104s Get:56 http://ftpmaster.internal/ubuntu plucky/universe s390x asterisk-tests s390x 1:22.1.0~dfsg+~cs6.14.60671435-1 [554 kB] 104s Get:57 http://ftpmaster.internal/ubuntu plucky/main s390x libxml2-utils s390x 2.12.7+dfsg+really2.9.14-0.2ubuntu2 [41.0 kB] 104s Fetched 29.0 MB in 2s (13.8 MB/s) 104s Selecting previously unselected package asterisk-config. 104s (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 ... 55633 files and directories currently installed.) 104s Preparing to unpack .../00-asterisk-config_1%3a22.1.0~dfsg+~cs6.14.60671435-1_all.deb ... 104s Unpacking asterisk-config (1:22.1.0~dfsg+~cs6.14.60671435-1) ... 104s Selecting previously unselected package asterisk-core-sounds-en-gsm. 104s Preparing to unpack .../01-asterisk-core-sounds-en-gsm_1.6.1-1_all.deb ... 104s Unpacking asterisk-core-sounds-en-gsm (1.6.1-1) ... 104s Selecting previously unselected package asterisk-core-sounds-en. 104s Preparing to unpack .../02-asterisk-core-sounds-en_1.6.1-1_all.deb ... 104s Unpacking asterisk-core-sounds-en (1.6.1-1) ... 104s Selecting previously unselected package mlock. 104s Preparing to unpack .../03-mlock_8%3a2007f~dfsg-7.1_s390x.deb ... 104s Unpacking mlock (8:2007f~dfsg-7.1) ... 104s Selecting previously unselected package libc-client2007e. 104s Preparing to unpack .../04-libc-client2007e_8%3a2007f~dfsg-7.1_s390x.deb ... 104s Unpacking libc-client2007e (8:2007f~dfsg-7.1) ... 104s Selecting previously unselected package libcodec2-1.2:s390x. 104s Preparing to unpack .../05-libcodec2-1.2_1.2.0-2build1_s390x.deb ... 104s Unpacking libcodec2-1.2:s390x (1.2.0-2build1) ... 104s Selecting previously unselected package libgmime-3.0-0t64:s390x. 104s Preparing to unpack .../06-libgmime-3.0-0t64_3.2.15+dfsg-1_s390x.deb ... 104s Unpacking libgmime-3.0-0t64:s390x (3.2.15+dfsg-1) ... 104s Selecting previously unselected package libgsm1:s390x. 104s Preparing to unpack .../07-libgsm1_1.0.22-1build1_s390x.deb ... 104s Unpacking libgsm1:s390x (1.0.22-1build1) ... 104s Selecting previously unselected package libical3t64:s390x. 104s Preparing to unpack .../08-libical3t64_3.0.19-1build1_s390x.deb ... 104s Unpacking libical3t64:s390x (3.0.19-1build1) ... 104s Selecting previously unselected package libiksemel3:s390x. 104s Preparing to unpack .../09-libiksemel3_1.4-4build2_s390x.deb ... 104s Unpacking libiksemel3:s390x (1.4-4build2) ... 104s Selecting previously unselected package libopus0:s390x. 104s Preparing to unpack .../10-libopus0_1.5.2-2_s390x.deb ... 104s Unpacking libopus0:s390x (1.5.2-2) ... 104s Selecting previously unselected package libsamplerate0:s390x. 104s Preparing to unpack .../11-libsamplerate0_0.2.2-4build1_s390x.deb ... 104s Unpacking libsamplerate0:s390x (0.2.2-4build1) ... 104s Selecting previously unselected package libjack-jackd2-0:s390x. 104s Preparing to unpack .../12-libjack-jackd2-0_1.9.22~dfsg-4_s390x.deb ... 104s Unpacking libjack-jackd2-0:s390x (1.9.22~dfsg-4) ... 104s Selecting previously unselected package libb64-0d:s390x. 104s Preparing to unpack .../13-libb64-0d_1.2-5build1_s390x.deb ... 104s Unpacking libb64-0d:s390x (1.2-5build1) ... 104s Selecting previously unselected package libjwt2:s390x. 104s Preparing to unpack .../14-libjwt2_1.17.2-1_s390x.deb ... 104s Unpacking libjwt2:s390x (1.17.2-1) ... 104s Selecting previously unselected package liblua5.1-0:s390x. 104s Preparing to unpack .../15-liblua5.1-0_5.1.5-10_s390x.deb ... 104s Unpacking liblua5.1-0:s390x (5.1.5-10) ... 105s Selecting previously unselected package libneon27t64:s390x. 105s Preparing to unpack .../16-libneon27t64_0.34.0-1_s390x.deb ... 105s Unpacking libneon27t64:s390x (0.34.0-1) ... 105s Selecting previously unselected package libltdl7:s390x. 105s Preparing to unpack .../17-libltdl7_2.4.7-8_s390x.deb ... 105s Unpacking libltdl7:s390x (2.4.7-8) ... 105s Selecting previously unselected package libodbc2:s390x. 105s Preparing to unpack .../18-libodbc2_2.3.12-1ubuntu1_s390x.deb ... 105s Unpacking libodbc2:s390x (2.3.12-1ubuntu1) ... 105s Selecting previously unselected package libogg0:s390x. 105s Preparing to unpack .../19-libogg0_1.3.5-3build1_s390x.deb ... 105s Unpacking libogg0:s390x (1.3.5-3build1) ... 105s Selecting previously unselected package libopencore-amrnb0:s390x. 105s Preparing to unpack .../20-libopencore-amrnb0_0.1.6-1build1_s390x.deb ... 105s Unpacking libopencore-amrnb0:s390x (0.1.6-1build1) ... 105s Selecting previously unselected package libopencore-amrwb0:s390x. 105s Preparing to unpack .../21-libopencore-amrwb0_0.1.6-1build1_s390x.deb ... 105s Unpacking libopencore-amrwb0:s390x (0.1.6-1build1) ... 105s Selecting previously unselected package libopusenc0:s390x. 105s Preparing to unpack .../22-libopusenc0_0.2.1-2build1_s390x.deb ... 105s Unpacking libopusenc0:s390x (0.2.1-2build1) ... 105s Selecting previously unselected package libopusfile0:s390x. 105s Preparing to unpack .../23-libopusfile0_0.12-4build3_s390x.deb ... 105s Unpacking libopusfile0:s390x (0.12-4build3) ... 105s Selecting previously unselected package libasound2-data. 105s Preparing to unpack .../24-libasound2-data_1.2.12-1_all.deb ... 105s Unpacking libasound2-data (1.2.12-1) ... 105s Selecting previously unselected package libasound2t64:s390x. 105s Preparing to unpack .../25-libasound2t64_1.2.12-1_s390x.deb ... 105s Unpacking libasound2t64:s390x (1.2.12-1) ... 105s Selecting previously unselected package libportaudio2:s390x. 105s Preparing to unpack .../26-libportaudio2_19.6.0-1.2build3_s390x.deb ... 105s Unpacking libportaudio2:s390x (19.6.0-1.2build3) ... 105s Selecting previously unselected package libpq5:s390x. 105s Preparing to unpack .../27-libpq5_17.2-1_s390x.deb ... 105s Unpacking libpq5:s390x (17.2-1) ... 105s Selecting previously unselected package libradcli4. 105s Preparing to unpack .../28-libradcli4_1.2.11-1build3_s390x.deb ... 105s Unpacking libradcli4 (1.2.11-1build3) ... 105s Selecting previously unselected package libresample1. 105s Preparing to unpack .../29-libresample1_0.1.3-8_s390x.deb ... 105s Unpacking libresample1 (0.1.3-8) ... 105s Selecting previously unselected package libsnmp-base. 105s Preparing to unpack .../30-libsnmp-base_5.9.4+dfsg-1.1ubuntu5_all.deb ... 105s Unpacking libsnmp-base (5.9.4+dfsg-1.1ubuntu5) ... 105s Selecting previously unselected package libsnmp40t64:s390x. 105s Preparing to unpack .../31-libsnmp40t64_5.9.4+dfsg-1.1ubuntu5_s390x.deb ... 105s Unpacking libsnmp40t64:s390x (5.9.4+dfsg-1.1ubuntu5) ... 105s Selecting previously unselected package libdeflate0:s390x. 105s Preparing to unpack .../32-libdeflate0_1.22-1_s390x.deb ... 105s Unpacking libdeflate0:s390x (1.22-1) ... 105s Selecting previously unselected package libjbig0:s390x. 105s Preparing to unpack .../33-libjbig0_2.1-6.1ubuntu2_s390x.deb ... 105s Unpacking libjbig0:s390x (2.1-6.1ubuntu2) ... 105s Selecting previously unselected package libjpeg-turbo8:s390x. 105s Preparing to unpack .../34-libjpeg-turbo8_2.1.5-3ubuntu2_s390x.deb ... 105s Unpacking libjpeg-turbo8:s390x (2.1.5-3ubuntu2) ... 105s Selecting previously unselected package libjpeg8:s390x. 105s Preparing to unpack .../35-libjpeg8_8c-2ubuntu11_s390x.deb ... 105s Unpacking libjpeg8:s390x (8c-2ubuntu11) ... 105s Selecting previously unselected package libsharpyuv0:s390x. 105s Preparing to unpack .../36-libsharpyuv0_1.4.0-0.1_s390x.deb ... 105s Unpacking libsharpyuv0:s390x (1.4.0-0.1) ... 105s Selecting previously unselected package libwebp7:s390x. 105s Preparing to unpack .../37-libwebp7_1.4.0-0.1_s390x.deb ... 105s Unpacking libwebp7:s390x (1.4.0-0.1) ... 105s Selecting previously unselected package libtiff6:s390x. 105s Preparing to unpack .../38-libtiff6_4.5.1+git230720-4ubuntu4_s390x.deb ... 105s Unpacking libtiff6:s390x (4.5.1+git230720-4ubuntu4) ... 105s Selecting previously unselected package libspandsp2t64:s390x. 105s Preparing to unpack .../39-libspandsp2t64_0.0.6+dfsg-2.1build1_s390x.deb ... 105s Unpacking libspandsp2t64:s390x (0.0.6+dfsg-2.1build1) ... 105s Selecting previously unselected package libspeex1:s390x. 105s Preparing to unpack .../40-libspeex1_1.2.1-3_s390x.deb ... 105s Unpacking libspeex1:s390x (1.2.1-3) ... 105s Selecting previously unselected package libspeexdsp1:s390x. 105s Preparing to unpack .../41-libspeexdsp1_1.2.1-1ubuntu3_s390x.deb ... 105s Unpacking libspeexdsp1:s390x (1.2.1-1ubuntu3) ... 105s Selecting previously unselected package libsrtp2-1:s390x. 105s Preparing to unpack .../42-libsrtp2-1_2.5.0-3build1_s390x.deb ... 105s Unpacking libsrtp2-1:s390x (2.5.0-3build1) ... 105s Selecting previously unselected package freetds-common. 105s Preparing to unpack .../43-freetds-common_1.3.17+ds-2build3_all.deb ... 105s Unpacking freetds-common (1.3.17+ds-2build3) ... 105s Selecting previously unselected package libsybdb5:s390x. 105s Preparing to unpack .../44-libsybdb5_1.3.17+ds-2build3_s390x.deb ... 105s Unpacking libsybdb5:s390x (1.3.17+ds-2build3) ... 105s Selecting previously unselected package libevent-2.1-7t64:s390x. 105s Preparing to unpack .../45-libevent-2.1-7t64_2.1.12-stable-10_s390x.deb ... 105s Unpacking libevent-2.1-7t64:s390x (2.1.12-stable-10) ... 105s Selecting previously unselected package libunbound8:s390x. 105s Preparing to unpack .../46-libunbound8_1.20.0-1ubuntu2.1_s390x.deb ... 105s Unpacking libunbound8:s390x (1.20.0-1ubuntu2.1) ... 105s Selecting previously unselected package libvo-amrwbenc0:s390x. 105s Preparing to unpack .../47-libvo-amrwbenc0_0.1.3-2build1_s390x.deb ... 105s Unpacking libvo-amrwbenc0:s390x (0.1.3-2build1) ... 105s Selecting previously unselected package libvorbis0a:s390x. 105s Preparing to unpack .../48-libvorbis0a_1.3.7-2_s390x.deb ... 105s Unpacking libvorbis0a:s390x (1.3.7-2) ... 105s Selecting previously unselected package libvorbisenc2:s390x. 105s Preparing to unpack .../49-libvorbisenc2_1.3.7-2_s390x.deb ... 105s Unpacking libvorbisenc2:s390x (1.3.7-2) ... 105s Selecting previously unselected package libvorbisfile3:s390x. 105s Preparing to unpack .../50-libvorbisfile3_1.3.7-2_s390x.deb ... 105s Unpacking libvorbisfile3:s390x (1.3.7-2) ... 105s Selecting previously unselected package asterisk-modules. 105s Preparing to unpack .../51-asterisk-modules_1%3a22.1.0~dfsg+~cs6.14.60671435-1_s390x.deb ... 105s Unpacking asterisk-modules (1:22.1.0~dfsg+~cs6.14.60671435-1) ... 105s Selecting previously unselected package liburiparser1:s390x. 105s Preparing to unpack .../52-liburiparser1_0.9.8+dfsg-2_s390x.deb ... 105s Unpacking liburiparser1:s390x (0.9.8+dfsg-2) ... 105s Selecting previously unselected package libxslt1.1:s390x. 105s Preparing to unpack .../53-libxslt1.1_1.1.39-0exp1ubuntu2_s390x.deb ... 105s Unpacking libxslt1.1:s390x (1.1.39-0exp1ubuntu2) ... 105s Selecting previously unselected package asterisk. 105s Preparing to unpack .../54-asterisk_1%3a22.1.0~dfsg+~cs6.14.60671435-1_s390x.deb ... 105s Unpacking asterisk (1:22.1.0~dfsg+~cs6.14.60671435-1) ... 105s Selecting previously unselected package asterisk-tests. 105s Preparing to unpack .../55-asterisk-tests_1%3a22.1.0~dfsg+~cs6.14.60671435-1_s390x.deb ... 105s Unpacking asterisk-tests (1:22.1.0~dfsg+~cs6.14.60671435-1) ... 105s Selecting previously unselected package libxml2-utils. 105s Preparing to unpack .../56-libxml2-utils_2.12.7+dfsg+really2.9.14-0.2ubuntu2_s390x.deb ... 105s Unpacking libxml2-utils (2.12.7+dfsg+really2.9.14-0.2ubuntu2) ... 105s Setting up libsharpyuv0:s390x (1.4.0-0.1) ... 105s Setting up libvo-amrwbenc0:s390x (0.1.3-2build1) ... 105s Setting up libneon27t64:s390x (0.34.0-1) ... 105s Setting up libogg0:s390x (1.3.5-3build1) ... 105s Setting up libspeex1:s390x (1.2.1-3) ... 105s Setting up libgsm1:s390x (1.0.22-1build1) ... 105s Setting up asterisk-core-sounds-en-gsm (1.6.1-1) ... 105s Setting up libsnmp-base (5.9.4+dfsg-1.1ubuntu5) ... 105s Setting up libcodec2-1.2:s390x (1.2.0-2build1) ... 105s Setting up mlock (8:2007f~dfsg-7.1) ... 105s Setting up libsrtp2-1:s390x (2.5.0-3build1) ... 105s Setting up libpq5:s390x (17.2-1) ... 105s Setting up libdeflate0:s390x (1.22-1) ... 105s Setting up libevent-2.1-7t64:s390x (2.1.12-stable-10) ... 105s Setting up libb64-0d:s390x (1.2-5build1) ... 105s Setting up libjwt2:s390x (1.17.2-1) ... 105s Setting up libjbig0:s390x (2.1-6.1ubuntu2) ... 105s Setting up libasound2-data (1.2.12-1) ... 105s Setting up libopencore-amrwb0:s390x (0.1.6-1build1) ... 105s Setting up libunbound8:s390x (1.20.0-1ubuntu2.1) ... 105s Setting up libasound2t64:s390x (1.2.12-1) ... 105s Setting up libradcli4 (1.2.11-1build3) ... 105s Setting up libopus0:s390x (1.5.2-2) ... 105s Setting up asterisk-config (1:22.1.0~dfsg+~cs6.14.60671435-1) ... 105s Setting up libvorbis0a:s390x (1.3.7-2) ... 105s Setting up libical3t64:s390x (3.0.19-1build1) ... 105s Setting up libjpeg-turbo8:s390x (2.1.5-3ubuntu2) ... 105s Setting up libltdl7:s390x (2.4.7-8) ... 105s Setting up asterisk-core-sounds-en (1.6.1-1) ... 105s update-alternatives: using /usr/share/asterisk/sounds/en_US_f_Allison to provide /usr/share/asterisk/sounds/en (asterisk-prompt-en) in auto mode 105s update-alternatives: using /usr/share/asterisk/sounds/en_US_f_Allison to provide /usr/share/asterisk/sounds/en_US (asterisk-prompt-en-us) in auto mode 105s Setting up libwebp7:s390x (1.4.0-0.1) ... 105s Setting up libiksemel3:s390x (1.4-4build2) ... 105s Setting up libodbc2:s390x (2.3.12-1ubuntu1) ... 105s Setting up liburiparser1:s390x (0.9.8+dfsg-2) ... 105s Setting up libspeexdsp1:s390x (1.2.1-1ubuntu3) ... 105s Setting up liblua5.1-0:s390x (5.1.5-10) ... 105s Setting up libxslt1.1:s390x (1.1.39-0exp1ubuntu2) ... 105s Setting up libopencore-amrnb0:s390x (0.1.6-1build1) ... 105s Setting up libc-client2007e (8:2007f~dfsg-7.1) ... 105s Setting up libresample1 (0.1.3-8) ... 105s Setting up freetds-common (1.3.17+ds-2build3) ... 105s Setting up libxml2-utils (2.12.7+dfsg+really2.9.14-0.2ubuntu2) ... 105s Setting up libgmime-3.0-0t64:s390x (3.2.15+dfsg-1) ... 105s Setting up libsamplerate0:s390x (0.2.2-4build1) ... 105s Setting up libopusfile0:s390x (0.12-4build3) ... 105s Setting up libvorbisenc2:s390x (1.3.7-2) ... 105s Setting up libjpeg8:s390x (8c-2ubuntu11) ... 105s Setting up libopusenc0:s390x (0.2.1-2build1) ... 105s Setting up libsnmp40t64:s390x (5.9.4+dfsg-1.1ubuntu5) ... 105s Setting up libsybdb5:s390x (1.3.17+ds-2build3) ... 105s Setting up libvorbisfile3:s390x (1.3.7-2) ... 105s Setting up libjack-jackd2-0:s390x (1.9.22~dfsg-4) ... 105s Setting up libtiff6:s390x (4.5.1+git230720-4ubuntu4) ... 105s Setting up libportaudio2:s390x (19.6.0-1.2build3) ... 105s Setting up libspandsp2t64:s390x (0.0.6+dfsg-2.1build1) ... 105s Setting up asterisk-modules (1:22.1.0~dfsg+~cs6.14.60671435-1) ... 105s Setting up asterisk (1:22.1.0~dfsg+~cs6.14.60671435-1) ... 105s Adding system user for Asterisk 105s info: Adding user `asterisk' to group `dialout' ... 105s info: Adding user `asterisk' to group `audio' ... 106s Created symlink '/etc/systemd/system/multi-user.target.wants/asterisk.service' → '/usr/lib/systemd/system/asterisk.service'. 107s Setting up asterisk-tests (1:22.1.0~dfsg+~cs6.14.60671435-1) ... 107s Processing triggers for libc-bin (2.40-4ubuntu1) ... 107s Processing triggers for man-db (2.13.0-1) ... 109s autopkgtest [08:18:49]: test asttestmods: [----------------------- 109s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 110s 'U' option is not compatible with remote console mode and has no effect. 110s 110s Asterisk has fully booted. 110s 'U' option is not compatible with remote console mode and has no effect. 110s 110s Running all available tests... 110s 110s START /apps/app_gosub/ - gosub application 110s END /apps/app_gosub/ - gosub application Time: <1ms Result: PASS 110s START /apps/app_voicemail/ - test_voicemail_vm_info 110s END /apps/app_voicemail/ - test_voicemail_vm_info Time: <1ms Result: PASS 110s START /apps/app_voicemail/ - test_voicemail_load_config 110s END /apps/app_voicemail/ - test_voicemail_load_config Time: <1ms Result: PASS 110s START /apps/app_voicemail/ - test_voicemail_notify_endl 110s END /apps/app_voicemail/ - test_voicemail_notify_endl Time: 2ms Result: PASS 110s START /apps/app_voicemail/ - vmuser 110s END /apps/app_voicemail/ - vmuser Time: <1ms Result: PASS 110s START /apps/app_voicemail/ - test_voicemail_msgcount 110s END /apps/app_voicemail/ - test_voicemail_msgcount Time: 26ms Result: PASS 110s START /apps/app_voicemail/ - vmsayname_exec 110s [app_voicemail.c:test_voicemail_vmsayname:15701]: Test playing of extension when greeting is not available... 115s [app_voicemail.c:test_voicemail_vmsayname:15722]: Test playing created mailbox greeting... 119s END /apps/app_voicemail/ - vmsayname_exec Time: 4294890298ms Result: PASS 119s START /ari/validators/ - validate_list 119s END /ari/validators/ - validate_list Time: <1ms Result: PASS 119s START /ari/validators/ - validate_date 119s END /ari/validators/ - validate_date Time: <1ms Result: PASS 119s START /ari/validators/ - validate_string 119s END /ari/validators/ - validate_string Time: <1ms Result: PASS 119s START /ari/validators/ - validate_long 119s END /ari/validators/ - validate_long Time: <1ms Result: PASS 119s START /ari/validators/ - validate_int 119s END /ari/validators/ - validate_int Time: <1ms Result: PASS 119s START /ari/validators/ - validate_boolean 119s END /ari/validators/ - validate_boolean Time: <1ms Result: PASS 119s START /ari/validators/ - validate_byte 119s END /ari/validators/ - validate_byte Time: <1ms Result: PASS 119s START /bridges/bridge_softmix/ - sfu_remove_destination_streams 119s END /bridges/bridge_softmix/ - sfu_remove_destination_streams Time: <1ms Result: PASS 119s START /bridges/bridge_softmix/ - sfu_append_source_streams 119s END /bridges/bridge_softmix/ - sfu_append_source_streams Time: <1ms Result: PASS 119s START /channels/features/ - test_features_channel_interval 122s END /channels/features/ - test_features_channel_interval Time: 3001ms Result: PASS 122s START /channels/features/ - test_features_channel_dtmf 124s END /channels/features/ - test_features_channel_dtmf Time: 2010ms Result: PASS 124s START /config/ - config_options_test 124s END /config/ - config_options_test Time: <1ms Result: PASS 124s START /config/ - ast_parse_arg 124s END /config/ - ast_parse_arg Time: <1ms Result: PASS 124s START /core/endpoints/ - setters 124s END /core/endpoints/ - setters Time: <1ms Result: PASS 124s START /core/endpoints/ - defaults 124s END /core/endpoints/ - defaults Time: <1ms Result: PASS 124s START /core/endpoints/ - create 124s END /core/endpoints/ - create Time: <1ms Result: PASS 124s START /funcs/func_curl/ - vulnerable_url 124s END /funcs/func_curl/ - vulnerable_url Time: <1ms Result: PASS 124s START /funcs/func_env/ - func_file 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=a'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,1)=a'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-8)=a'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-8)=a'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5,1)=b'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4,1)=b'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5,-3)=b'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4,-3)=b'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2)=c'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,2)=c'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-7)=c'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-7)=c'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,4,2)=d'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-5,2)=d'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,4,-3)=d'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-5,-3)=d'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5)=e'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5)='... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4)=e'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4)='... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=fg'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-8)=fg'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,1)=fg'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-8)=fg'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,)=h'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,,)=h'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,l)=h'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,ld)=h'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abc'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=abc'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=abc'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=abc'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=abc'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=abc'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=abc'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=abc'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=ab'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=ab'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=ab'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=ab'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=ab'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=ab'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=ab'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=ab'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcdefg'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcdefg'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcdefg'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcdefg'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcdefg'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcdefg'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcdefg'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcdefg'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcdefghijklmnop'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcdefghijklmnop'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcdefghijklmnop'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcdefghijklmnop'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcdefghijklmnop'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcdefghijklmnop'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcdefghijklmnop'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcdefghijklmnop'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,0,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,0,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,0,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,0,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,2,0,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-1,0,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,3,0,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,la)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)='... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)='... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)='... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)='... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)='... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)='... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)='... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)='... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,ld)='... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,ld)='... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,ld)='... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,ld)='... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,ld)='... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,ld)='... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,ld)='... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,ld)='... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=a'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,10)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 124s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=a'... OK! 124s END /funcs/func_env/ - func_file Time: 20ms Result: PASS 124s START /funcs/func_json/ - func_JSON_DECODE 124s END /funcs/func_json/ - func_JSON_DECODE Time: <1ms Result: PASS 124s START /funcs/func_presence/ - test_presence_state_base64_encode 124s END /funcs/func_presence/ - test_presence_state_base64_encode Time: 5ms Result: PASS 124s START /funcs/func_presence/ - test_presence_state_change 124s END /funcs/func_presence/ - test_presence_state_change Time: <1ms Result: PASS 124s START /funcs/func_presence/ - parse_invalid_presence_data 124s END /funcs/func_presence/ - parse_invalid_presence_data Time: <1ms Result: PASS 124s START /funcs/func_presence/ - parse_valid_presence_data 124s END /funcs/func_presence/ - parse_valid_presence_data Time: <1ms Result: PASS 124s START /funcs/func_sayfiles/ - test_SAYFILES_function 124s [func_sayfiles.c:test_SAYFILES_function:180]: Testing SAYFILES() substitution ... 124s END /funcs/func_sayfiles/ - test_SAYFILES_function Time: 4ms Result: PASS 124s START /funcs/func_strings/ - func_TRIM 124s END /funcs/func_strings/ - func_TRIM Time: <1ms Result: PASS 124s START /funcs/func_strings/ - func_STRBETWEEN 124s END /funcs/func_strings/ - func_STRBETWEEN Time: <1ms Result: PASS 124s START /funcs/func_strings/ - func_STRREPLACE_test 124s END /funcs/func_strings/ - func_STRREPLACE_test Time: <1ms Result: PASS 124s START /funcs/func_strings/ - func_FILTER_test 124s END /funcs/func_strings/ - func_FILTER_test Time: <1ms Result: PASS 124s START /funcs/func_strings/ - func_REPLACE_test 124s END /funcs/func_strings/ - func_REPLACE_test Time: <1ms Result: PASS 124s START /funcs/func_strings/ - func_FIELDNUM_test 124s END /funcs/func_strings/ - func_FIELDNUM_test Time: <1ms Result: PASS 124s START /geoloc/ - create_from_pidf 124s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1274]: ID: 'point-2d' pidf_element: 'tuple' format: 'GML' method: 'Manual' 124s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1286]: location_vars expected: shape=Point,crs=2d,pos=-34.410649 150.87651 124s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1287]: location_vars received: shape=Point,crs=2d,pos=-34.410649 150.87651 124s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1293]: usage_rules expected: retransmission-allowed='no',retention-expiry='2010-11-14T20:00:00Z' 124s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1294]: usage_rules received: retransmission-allowed='no',retention-expiry='2010-11-14T20:00:00Z' 124s END /geoloc/ - create_from_pidf Time: <1ms Result: PASS 124s START /geoloc/ - create_from_uri 124s END /geoloc/ - create_from_uri Time: <1ms Result: PASS 124s START /main/abstract_jb/ - AST_JB_FIXED_put_out_of_order 124s [test_abstract_jb.c:AST_JB_FIXED_put_out_of_order:531]: Executing AST_JB_FIXED_put_out_of_order... 124s END /main/abstract_jb/ - AST_JB_FIXED_put_out_of_order Time: <1ms Result: PASS 124s START /main/abstract_jb/ - AST_JB_FIXED_put_overflow 124s [test_abstract_jb.c:AST_JB_FIXED_put_overflow:529]: Executing AST_JB_FIXED_put_overflow... 124s END /main/abstract_jb/ - AST_JB_FIXED_put_overflow Time: <1ms Result: PASS 124s START /main/abstract_jb/ - AST_JB_FIXED_put 124s [test_abstract_jb.c:AST_JB_FIXED_put:527]: Executing AST_JB_FIXED_put... 124s END /main/abstract_jb/ - AST_JB_FIXED_put Time: <1ms Result: PASS 124s START /main/abstract_jb/ - AST_JB_FIXED_put_first 124s [test_abstract_jb.c:AST_JB_FIXED_put_first:525]: Executing AST_JB_FIXED_create... 124s END /main/abstract_jb/ - AST_JB_FIXED_put_first Time: <1ms Result: PASS 124s START /main/abstract_jb/ - AST_JB_FIXED_create 124s [test_abstract_jb.c:AST_JB_FIXED_create:523]: Executing AST_JB_FIXED_create... 124s END /main/abstract_jb/ - AST_JB_FIXED_create Time: <1ms Result: PASS 124s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_out_of_order 124s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_out_of_order:521]: Executing AST_JB_ADAPTIVE_put_out_of_order... 124s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_out_of_order Time: <1ms Result: PASS 124s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_overflow 124s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_overflow:519]: Executing AST_JB_ADAPTIVE_put_overflow... 124s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_overflow Time: <1ms Result: PASS 124s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put 124s [test_abstract_jb.c:AST_JB_ADAPTIVE_put:517]: Executing AST_JB_ADAPTIVE_put... 124s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put Time: <1ms Result: PASS 124s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_first 124s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_first:515]: Executing AST_JB_ADAPTIVE_create... 124s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_first Time: <1ms Result: PASS 124s START /main/abstract_jb/ - AST_JB_ADAPTIVE_create 124s [test_abstract_jb.c:AST_JB_ADAPTIVE_create:513]: Executing AST_JB_ADAPTIVE_create... 124s END /main/abstract_jb/ - AST_JB_ADAPTIVE_create Time: <1ms Result: PASS 124s START /main/acl/ - acl 124s END /main/acl/ - acl Time: <1ms Result: PASS 124s START /main/acl/ - invalid_acl 124s END /main/acl/ - invalid_acl Time: <1ms Result: PASS 124s START /main/amihooks/ - amihook_cli_send 124s END /main/amihooks/ - amihook_cli_send Time: <1ms Result: PASS 124s START /main/aoc/ - aoc_event_test 124s END /main/aoc/ - aoc_event_test Time: <1ms Result: PASS 124s START /main/aoc/ - aoc_encode_decode_test 124s END /main/aoc/ - aoc_encode_decode_test Time: <1ms Result: PASS 124s START /main/app/ - options_parsing 124s END /main/app/ - options_parsing Time: <1ms Result: PASS 124s START /main/app/ - app_group 124s [test_app.c:app_group:172]: Creating test channels with the following groups: 124s 'a groupgroupgroup', 'a groupGroupgroup', 'a group@a_category', 'a group@another!Category' 124s [test_app.c:app_group:211]: (Subtest 1) Found 4 matches as expected when examining group:'gr' category:'' 124s [test_app.c:app_group:211]: (Subtest 2) Found 1 matches as expected when examining group:'(group){2}$' category:'' 124s [test_app.c:app_group:211]: (Subtest 3) Found 4 matches as expected when examining group:'[:ascii:]' category:'' 124s [test_app.c:app_group:211]: (Subtest 4) Found 0 matches as expected when examining group:'^(NOMATCH)' category:'' 124s [test_app.c:app_group:211]: (Subtest 5) Found 2 matches as expected when examining group:'a group' category:'(gory)$' 124s [test_app.c:app_group:211]: (Subtest 6) Found 1 matches as expected when examining group:'a group' category:'[A-Z]+' 124s [test_app.c:app_group:211]: (Subtest 7) Found 0 matches as expected when examining group:'a group' category:'[[' 124s END /main/app/ - app_group Time: <1ms Result: PASS 124s START /main/ast_expr/ - expr_test 124s END /main/ast_expr/ - expr_test Time: <1ms Result: PASS 124s START /main/astdb/ - put_get_long 124s END /main/astdb/ - put_get_long Time: 73ms Result: PASS 124s START /main/astdb/ - perftest 125s END /main/astdb/ - perftest Time: 212ms Result: PASS 125s START /main/astdb/ - gettree_deltree 125s END /main/astdb/ - gettree_deltree Time: <1ms Result: PASS 125s START /main/astdb/ - put_get_del 125s END /main/astdb/ - put_get_del Time: <1ms Result: PASS 125s START /main/astobj2/ - astobj2_weak_container 125s END /main/astobj2/ - astobj2_weak_container Time: <1ms Result: PASS 125s START /main/astobj2/ - astobj2_weak1 125s END /main/astobj2/ - astobj2_weak1 Time: <1ms Result: PASS 125s START /main/astobj2/ - thrash 125s [test_astobj2_thrash.c:hash_test:266]: Executing hash concurrency test... 125s END /main/astobj2/ - thrash Time: 8ms Result: PASS 125s START /main/astobj2/ - astobj2_test4 125s [test_astobj2.c:test_traversal_nonsorted:1389]: Test 1, List containers. 125s [test_astobj2.c:test_traversal_nonsorted:1389]: Test 2, Hash containers. 125s [test_astobj2.c:test_traversal_sorted:1615]: Test 3, List containers. 125s [test_astobj2.c:test_traversal_sorted:1615]: Test 4, Hash containers. 125s [test_astobj2.c:test_traversal_sorted:1615]: Test 5, RBTree containers. 125s END /main/astobj2/ - astobj2_test4 Time: <1ms Result: PASS 125s START /main/astobj2/ - astobj2_test3 125s END /main/astobj2/ - astobj2_test3 Time: <1ms Result: PASS 125s START /main/astobj2/ - astobj2_test2 125s END /main/astobj2/ - astobj2_test2 Time: <1ms Result: PASS 125s START /main/astobj2/ - astobj2_test1 125s [test_astobj2.c:astobj2_test_1_helper:434]: Test 1, List containers (non-sorted). 125s [test_astobj2.c:astobj2_test_1_helper:488]: List container created: buckets: 1, items: 50 125s [test_astobj2.c:astobj2_test_1_helper:434]: Test 2, List containers (sorted). 125s [test_astobj2.c:astobj2_test_1_helper:488]: List container created: buckets: 1, items: 50 125s [test_astobj2.c:astobj2_test_1_helper:434]: Test 3, Hash containers (non-sorted). 125s [test_astobj2.c:astobj2_test_1_helper:488]: Hash container created: buckets: 153, items: 1000 125s [test_astobj2.c:astobj2_test_1_helper:434]: Test 4, Hash containers (sorted). 125s [test_astobj2.c:astobj2_test_1_helper:488]: Hash container created: buckets: 108, items: 1000 125s [test_astobj2.c:astobj2_test_1_helper:434]: Test 4, RBTree containers (sorted). 125s [test_astobj2.c:astobj2_test_1_helper:488]: RBTree container created: buckets: 1, items: 1000 125s END /main/astobj2/ - astobj2_test1 Time: 7ms Result: PASS 125s START /main/astobj2/perf/ - astobj2_test_perf 125s [test_astobj2.c:testloop:2001]: 20.00K traversals, List 126s [test_astobj2.c:testloop:2001]: 40.00K traversals, List 126s [test_astobj2.c:testloop:2001]: 60.00K traversals, List 127s [test_astobj2.c:testloop:2001]: 80.00K traversals, List 127s [test_astobj2.c:testloop:2006]: 100.00K traversals, List : 2701 ms 128s [test_astobj2.c:testloop:2001]: 20.00K traversals, Hash 128s [test_astobj2.c:testloop:2001]: 40.00K traversals, Hash 128s [test_astobj2.c:testloop:2001]: 60.00K traversals, Hash 129s [test_astobj2.c:testloop:2001]: 80.00K traversals, Hash 129s [test_astobj2.c:testloop:2006]: 100.00K traversals, Hash : 1523 ms 129s [test_astobj2.c:testloop:2001]: 20.00K traversals, RBTree 130s [test_astobj2.c:testloop:2001]: 40.00K traversals, RBTree 130s [test_astobj2.c:testloop:2001]: 60.00K traversals, RBTree 131s [test_astobj2.c:testloop:2001]: 80.00K traversals, RBTree 131s [test_astobj2.c:testloop:2006]: 100.00K traversals, RBTree : 2234 ms 131s END /main/astobj2/perf/ - astobj2_test_perf Time: 6460ms Result: PASS 131s START /main/bridging/ - test_bridging_deferred_queue 132s END /main/bridging/ - test_bridging_deferred_queue Time: 1005ms Result: PASS 132s START /main/bucket/ - bucket_file_json 132s END /main/bucket/ - bucket_file_json Time: <1ms Result: PASS 132s START /main/bucket/ - bucket_file_metadata_get 132s END /main/bucket/ - bucket_file_metadata_get Time: <1ms Result: PASS 132s START /main/bucket/ - bucket_file_metadata_unset 132s END /main/bucket/ - bucket_file_metadata_unset Time: <1ms Result: PASS 132s START /main/bucket/ - bucket_file_metadata_set 132s END /main/bucket/ - bucket_file_metadata_set Time: <1ms Result: PASS 132s START /main/bucket/ - bucket_file_is_stale 132s END /main/bucket/ - bucket_file_is_stale Time: <1ms Result: PASS 132s START /main/bucket/ - bucket_file_delete 132s END /main/bucket/ - bucket_file_delete Time: <1ms Result: PASS 132s START /main/bucket/ - bucket_file_update 132s END /main/bucket/ - bucket_file_update Time: <1ms Result: PASS 132s START /main/bucket/ - bucket_file_retrieve 132s END /main/bucket/ - bucket_file_retrieve Time: <1ms Result: PASS 132s START /main/bucket/ - bucket_file_copy 132s END /main/bucket/ - bucket_file_copy Time: <1ms Result: PASS 132s START /main/bucket/ - bucket_file_clone 132s END /main/bucket/ - bucket_file_clone Time: <1ms Result: PASS 132s START /main/bucket/ - bucket_file_create 132s END /main/bucket/ - bucket_file_create Time: <1ms Result: PASS 132s START /main/bucket/ - bucket_file_alloc 132s END /main/bucket/ - bucket_file_alloc Time: <1ms Result: PASS 132s START /main/bucket/ - bucket_json 132s END /main/bucket/ - bucket_json Time: <1ms Result: PASS 132s START /main/bucket/ - bucket_is_stale 132s END /main/bucket/ - bucket_is_stale Time: <1ms Result: PASS 132s START /main/bucket/ - bucket_retrieve 132s END /main/bucket/ - bucket_retrieve Time: <1ms Result: PASS 132s START /main/bucket/ - bucket_delete 132s END /main/bucket/ - bucket_delete Time: <1ms Result: PASS 132s START /main/bucket/ - bucket_clone 132s END /main/bucket/ - bucket_clone Time: <1ms Result: PASS 132s START /main/bucket/ - bucket_create 132s END /main/bucket/ - bucket_create Time: <1ms Result: PASS 132s START /main/bucket/ - bucket_alloc 132s END /main/bucket/ - bucket_alloc Time: <1ms Result: PASS 132s START /main/bucket/ - bucket_scheme_register_unregister 132s END /main/bucket/ - bucket_scheme_register_unregister Time: <1ms Result: PASS 132s START /main/callerid/ - parse_off_nominal 132s END /main/callerid/ - parse_off_nominal Time: <1ms Result: PASS 132s START /main/callerid/ - parse_nominal 132s END /main/callerid/ - parse_nominal Time: <1ms Result: PASS 132s START /main/cdr/ - test_cdr_fork_cdr 134s Verifying expected record CDRTestChannel/Alice, 134s Finished expected record CDRTestChannel/Alice, 134s Verifying expected record CDRTestChannel/Alice, 134s Finished expected record CDRTestChannel/Alice, 134s Verifying expected record CDRTestChannel/Alice, 134s Finished expected record CDRTestChannel/Alice, 134s END /main/cdr/ - test_cdr_fork_cdr Time: 2001ms Result: PASS 134s START /main/cdr/ - test_cdr_no_reset_cdr 135s Verifying expected record CDRTestChannel/Alice, 135s Finished expected record CDRTestChannel/Alice, 135s END /main/cdr/ - test_cdr_no_reset_cdr Time: 1000ms Result: PASS 135s START /main/cdr/ - test_cdr_fields 137s Verifying expected record CDRTestChannel/Alice, 137s Finished expected record CDRTestChannel/Alice, 137s Verifying expected record CDRTestChannel/Alice, 137s Finished expected record CDRTestChannel/Alice, 137s Verifying expected record CDRTestChannel/Alice, 137s Finished expected record CDRTestChannel/Alice, 137s END /main/cdr/ - test_cdr_fields Time: 2000ms Result: PASS 137s START /main/cdr/ - test_cdr_park 140s Verifying expected record CDRTestChannel/Alice, 140s Finished expected record CDRTestChannel/Alice, 140s Verifying expected record CDRTestChannel/Bob, 140s Finished expected record CDRTestChannel/Bob, 140s END /main/cdr/ - test_cdr_park Time: 3001ms Result: PASS 140s START /main/cdr/ - test_cdr_dial_answer_multiparty 145s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 145s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 145s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 145s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 145s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/David 145s Finished expected record CDRTestChannel/Alice, CDRTestChannel/David 145s Verifying expected record CDRTestChannel/Bob, CDRTestChannel/David 145s Finished expected record CDRTestChannel/Bob, CDRTestChannel/David 145s Verifying expected record CDRTestChannel/Charlie, CDRTestChannel/David 145s Finished expected record CDRTestChannel/Charlie, CDRTestChannel/David 145s Verifying expected record CDRTestChannel/Charlie, CDRTestChannel/Bob 145s Finished expected record CDRTestChannel/Charlie, CDRTestChannel/Bob 145s END /main/cdr/ - test_cdr_dial_answer_multiparty Time: 5003ms Result: PASS 145s START /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_b 148s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 148s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 148s END /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_b Time: 3001ms Result: PASS 148s START /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_a 150s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 150s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 150s END /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_a Time: 2001ms Result: PASS 150s START /main/cdr/ - test_cdr_dial_answer_no_bridge 150s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 150s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 150s Verifying expected record CDRTestChannel/Alice, 150s Finished expected record CDRTestChannel/Alice, 150s Verifying expected record CDRTestChannel/Bob, 150s Finished expected record CDRTestChannel/Bob, 150s END /main/cdr/ - test_cdr_dial_answer_no_bridge Time: <1ms Result: PASS 150s START /main/cdr/ - test_cdr_dial_parallel_failed 150s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 150s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 150s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 150s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 150s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/David 150s Finished expected record CDRTestChannel/Alice, CDRTestChannel/David 150s END /main/cdr/ - test_cdr_dial_parallel_failed Time: <1ms Result: PASS 150s START /main/cdr/ - test_cdr_dial_caller_cancel 150s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 150s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 150s END /main/cdr/ - test_cdr_dial_caller_cancel Time: <1ms Result: PASS 150s START /main/cdr/ - test_cdr_dial_unavailable 150s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 150s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 150s END /main/cdr/ - test_cdr_dial_unavailable Time: <1ms Result: PASS 150s START /main/cdr/ - test_cdr_dial_busy 150s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 150s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 150s END /main/cdr/ - test_cdr_dial_busy Time: <1ms Result: PASS 150s START /main/cdr/ - test_cdr_dial_congestion 150s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 150s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 150s END /main/cdr/ - test_cdr_dial_congestion Time: <1ms Result: PASS 150s START /main/cdr/ - test_cdr_dial_unanswered 150s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 150s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 150s END /main/cdr/ - test_cdr_dial_unanswered Time: <1ms Result: PASS 150s START /main/cdr/ - test_cdr_outbound_bridged_call 153s Verifying expected record CDRTestChannel/Bob, 153s Finished expected record CDRTestChannel/Bob, 153s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 153s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 153s END /main/cdr/ - test_cdr_outbound_bridged_call Time: 3001ms Result: PASS 153s START /main/cdr/ - test_cdr_single_multiparty_bridge 157s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 157s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 157s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 157s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 157s Verifying expected record CDRTestChannel/Bob, CDRTestChannel/Charlie 157s Finished expected record CDRTestChannel/Bob, CDRTestChannel/Charlie 157s Verifying expected record CDRTestChannel/Charlie, 157s Finished expected record CDRTestChannel/Charlie, 157s END /main/cdr/ - test_cdr_single_multiparty_bridge Time: 4002ms Result: PASS 157s START /main/cdr/ - test_cdr_single_twoparty_bridge_b 160s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 160s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 160s Verifying expected record CDRTestChannel/Bob, 160s Finished expected record CDRTestChannel/Bob, 160s END /main/cdr/ - test_cdr_single_twoparty_bridge_b Time: 3001ms Result: PASS 160s START /main/cdr/ - test_cdr_single_twoparty_bridge_a 162s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 162s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 162s Verifying expected record CDRTestChannel/Bob, 162s Finished expected record CDRTestChannel/Bob, 162s END /main/cdr/ - test_cdr_single_twoparty_bridge_a Time: 2001ms Result: PASS 162s START /main/cdr/ - test_cdr_single_bridge_continue 164s Verifying expected record CDRTestChannel/Alice, 164s Finished expected record CDRTestChannel/Alice, 164s Verifying expected record CDRTestChannel/Alice, 164s Finished expected record CDRTestChannel/Alice, 164s END /main/cdr/ - test_cdr_single_bridge_continue Time: 2000ms Result: PASS 164s START /main/cdr/ - test_cdr_single_bridge 166s Verifying expected record CDRTestChannel/Alice, 166s Finished expected record CDRTestChannel/Alice, 166s END /main/cdr/ - test_cdr_single_bridge Time: 2000ms Result: PASS 166s START /main/cdr/ - test_cdr_single_party 166s Verifying expected record CDRTestChannel/Alice, 166s Finished expected record CDRTestChannel/Alice, 166s END /main/cdr/ - test_cdr_single_party Time: <1ms Result: PASS 166s START /main/cdr/ - test_cdr_unanswered_outbound_call 166s Verifying expected record CDRTestChannel/Alice, 166s Finished expected record CDRTestChannel/Alice, 166s END /main/cdr/ - test_cdr_unanswered_outbound_call Time: <1ms Result: PASS 166s START /main/cdr/ - test_cdr_unanswered_inbound_call 166s Verifying expected record CDRTestChannel/Alice, 166s Finished expected record CDRTestChannel/Alice, 166s END /main/cdr/ - test_cdr_unanswered_inbound_call Time: <1ms Result: PASS 166s START /main/cdr/ - test_cdr_channel_creation 166s Verifying expected record CDRTestChannel/Alice, 166s Finished expected record CDRTestChannel/Alice, 166s END /main/cdr/ - test_cdr_channel_creation Time: <1ms Result: PASS 166s START /main/channel/ - add_fd 166s END /main/channel/ - add_fd Time: <1ms Result: PASS 166s START /main/channel/ - set_fd_grow 166s END /main/channel/ - set_fd_grow Time: <1ms Result: PASS 166s START /main/config/ - variable_list_from_quoted_string 166s END /main/config/ - variable_list_from_quoted_string Time: <1ms Result: PASS 166s START /main/config/ - variable_list_join_replace 166s END /main/config/ - variable_list_join_replace Time: <1ms Result: PASS 166s START /main/config/ - variable_lists_match 166s END /main/config/ - variable_lists_match Time: <1ms Result: PASS 166s START /main/config/ - config_dialplan_function 166s END /main/config/ - config_dialplan_function Time: <1ms Result: PASS 166s START /main/config/ - config_hook 166s END /main/config/ - config_hook Time: <1ms Result: PASS 166s START /main/config/ - copy_config 166s END /main/config/ - copy_config Time: <1ms Result: PASS 166s START /main/config/ - config_template_ops 166s END /main/config/ - config_template_ops Time: <1ms Result: PASS 166s START /main/config/ - config_filtered_ops 166s END /main/config/ - config_filtered_ops Time: <1ms Result: PASS 166s START /main/config/ - config_basic_ops 166s END /main/config/ - config_basic_ops Time: <1ms Result: PASS 166s START /main/config/ - config_save 166s END /main/config/ - config_save Time: <1ms Result: PASS 166s START /main/conversions/ - str_to_umax 166s END /main/conversions/ - str_to_umax Time: <1ms Result: PASS 166s START /main/conversions/ - str_to_imax 166s END /main/conversions/ - str_to_imax Time: <1ms Result: PASS 166s START /main/conversions/ - str_to_ulong 166s END /main/conversions/ - str_to_ulong Time: <1ms Result: PASS 166s START /main/conversions/ - str_to_long 166s END /main/conversions/ - str_to_long Time: <1ms Result: PASS 166s START /main/conversions/ - str_to_uint 166s END /main/conversions/ - str_to_uint Time: <1ms Result: PASS 166s START /main/conversions/ - str_to_int 166s END /main/conversions/ - str_to_int Time: <1ms Result: PASS 166s START /main/core_codec/ - codec_get_unknown 166s END /main/core_codec/ - codec_get_unknown Time: <1ms Result: PASS 166s START /main/core_codec/ - codec_get_unknown 166s END /main/core_codec/ - codec_get_unknown Time: <1ms Result: PASS 166s START /main/core_codec/ - codec_get_unregistered 166s END /main/core_codec/ - codec_get_unregistered Time: <1ms Result: PASS 166s START /main/core_codec/ - codec_get 166s END /main/core_codec/ - codec_get Time: <1ms Result: PASS 166s START /main/core_codec/ - codec_register_audio_no_sample_rate 166s END /main/core_codec/ - codec_register_audio_no_sample_rate Time: <1ms Result: PASS 166s START /main/core_codec/ - codec_register_unknown 166s END /main/core_codec/ - codec_register_unknown Time: <1ms Result: PASS 166s START /main/core_codec/ - codec_register_twice 166s END /main/core_codec/ - codec_register_twice Time: <1ms Result: PASS 166s START /main/core_codec/ - codec_register 166s END /main/core_codec/ - codec_register Time: <1ms Result: PASS 166s START /main/core_format/ - format_parse_and_generate_sdp_fmtp 166s END /main/core_format/ - format_parse_and_generate_sdp_fmtp Time: <1ms Result: PASS 166s START /main/core_format/ - format_parse_sdp_fmtp_without_interface 166s END /main/core_format/ - format_parse_sdp_fmtp_without_interface Time: <1ms Result: PASS 166s START /main/core_format/ - format_attribute_get_without_interface 166s END /main/core_format/ - format_attribute_get_without_interface Time: <1ms Result: PASS 166s START /main/core_format/ - format_attribute_set_without_interface 166s END /main/core_format/ - format_attribute_set_without_interface Time: <1ms Result: PASS 166s START /main/core_format/ - format_copy 166s END /main/core_format/ - format_copy Time: <1ms Result: PASS 166s START /main/core_format/ - format_joint_different_codec 166s END /main/core_format/ - format_joint_different_codec Time: <1ms Result: PASS 166s START /main/core_format/ - format_attr_joint_same_codec 166s END /main/core_format/ - format_attr_joint_same_codec Time: <1ms Result: PASS 166s START /main/core_format/ - format_joint_same_codec 166s END /main/core_format/ - format_joint_same_codec Time: <1ms Result: PASS 166s START /main/core_format/ - format_cmp_different_codec 166s END /main/core_format/ - format_cmp_different_codec Time: <1ms Result: PASS 166s START /main/core_format/ - format_attr_cmp_same_codec 166s END /main/core_format/ - format_attr_cmp_same_codec Time: <1ms Result: PASS 166s START /main/core_format/ - format_cmp_same_codec 166s END /main/core_format/ - format_cmp_same_codec Time: <1ms Result: PASS 166s START /main/core_format/ - format_clone 166s END /main/core_format/ - format_clone Time: <1ms Result: PASS 166s START /main/core_format/ - format_retrieve_attr 166s END /main/core_format/ - format_retrieve_attr Time: <1ms Result: PASS 166s START /main/core_format/ - format_create_attr 166s END /main/core_format/ - format_create_attr Time: <1ms Result: PASS 166s START /main/core_format/ - format_create 166s END /main/core_format/ - format_create Time: <1ms Result: PASS 166s START /main/data_buffer/ - buffer_nominal 166s END /main/data_buffer/ - buffer_nominal Time: <1ms Result: PASS 166s START /main/data_buffer/ - buffer_resize 166s END /main/data_buffer/ - buffer_resize Time: <1ms Result: PASS 166s START /main/data_buffer/ - buffer_put 166s END /main/data_buffer/ - buffer_put Time: <1ms Result: PASS 166s START /main/data_buffer/ - buffer_create 166s END /main/data_buffer/ - buffer_create Time: <1ms Result: PASS 166s START /main/devicestate/ - devstate_channels 166s END /main/devicestate/ - devstate_channels Time: <1ms Result: PASS 166s START /main/devicestate/ - devstate_conversions 166s END /main/devicestate/ - devstate_conversions Time: <1ms Result: PASS 166s START /main/devicestate/ - devstate_changed 166s [test_devicestate.c:wait_for_device_state_updates:308]: Received 8 of 8 updates 166s [test_devicestate.c:devstate_changed:716]: Testing update 0: actual is 1; expected is 1 166s [test_devicestate.c:devstate_changed:716]: Testing update 1: actual is 2; expected is 2 166s [test_devicestate.c:devstate_changed:716]: Testing update 2: actual is 3; expected is 3 166s [test_devicestate.c:devstate_changed:716]: Testing update 3: actual is 4; expected is 4 166s [test_devicestate.c:devstate_changed:716]: Testing update 4: actual is 5; expected is 5 166s [test_devicestate.c:devstate_changed:716]: Testing update 5: actual is 6; expected is 6 166s [test_devicestate.c:devstate_changed:716]: Testing update 6: actual is 7; expected is 7 166s [test_devicestate.c:devstate_changed:716]: Testing update 7: actual is 8; expected is 8 166s [test_devicestate.c:wait_for_device_state_updates:308]: Received 1 of 1 updates 166s [test_devicestate.c:wait_for_device_state_updates:308]: Received 8 of 8 updates 166s [test_devicestate.c:devstate_changed:754]: Testing update 0: actual is 1; expected is 1 166s [test_devicestate.c:devstate_changed:754]: Testing update 1: actual is 2; expected is 2 166s [test_devicestate.c:devstate_changed:754]: Testing update 2: actual is 3; expected is 3 166s [test_devicestate.c:devstate_changed:754]: Testing update 3: actual is 4; expected is 4 166s [test_devicestate.c:devstate_changed:754]: Testing update 4: actual is 5; expected is 5 166s [test_devicestate.c:devstate_changed:754]: Testing update 5: actual is 6; expected is 6 166s [test_devicestate.c:devstate_changed:754]: Testing update 6: actual is 7; expected is 7 166s [test_devicestate.c:devstate_changed:754]: Testing update 7: actual is 8; expected is 8 166s END /main/devicestate/ - devstate_changed Time: <1ms Result: PASS 166s START /main/devicestate/ - devstate_prov_del 166s END /main/devicestate/ - devstate_prov_del Time: <1ms Result: PASS 166s START /main/devicestate/ - devstate_prov_add 166s END /main/devicestate/ - devstate_prov_add Time: <1ms Result: PASS 166s START /main/devicestate/ - device2extenstate_test 166s END /main/devicestate/ - device2extenstate_test Time: <1ms Result: PASS 166s START /main/devicestate/ - device_state_aggregation_test 166s END /main/devicestate/ - device_state_aggregation_test Time: <1ms Result: PASS 166s START /main/dns/ - resolver_resolve_async_cancel 166s END /main/dns/ - resolver_resolve_async_cancel Time: <1ms Result: PASS 166s START /main/dns/ - resolver_resolve_async_off_nominal 166s END /main/dns/ - resolver_resolve_async_off_nominal Time: <1ms Result: PASS 166s START /main/dns/ - resolver_resolve_async 171s END /main/dns/ - resolver_resolve_async Time: 5000ms Result: PASS 171s START /main/dns/ - resolver_resolve_sync_off_nominal 171s END /main/dns/ - resolver_resolve_sync_off_nominal Time: <1ms Result: PASS 171s START /main/dns/ - resolver_resolve_sync 176s END /main/dns/ - resolver_resolve_sync Time: 5000ms Result: PASS 176s START /main/dns/ - resolver_add_record_off_nominal 176s END /main/dns/ - resolver_add_record_off_nominal Time: <1ms Result: PASS 176s START /main/dns/ - resolver_add_record 176s END /main/dns/ - resolver_add_record Time: <1ms Result: PASS 176s START /main/dns/ - resolver_set_result_off_nominal 176s END /main/dns/ - resolver_set_result_off_nominal Time: <1ms Result: PASS 176s START /main/dns/ - resolver_set_result 176s END /main/dns/ - resolver_set_result Time: <1ms Result: PASS 176s START /main/dns/ - resolver_data 176s END /main/dns/ - resolver_data Time: <1ms Result: PASS 176s START /main/dns/ - resolver_unregister_off_nominal 176s END /main/dns/ - resolver_unregister_off_nominal Time: <1ms Result: PASS 176s START /main/dns/ - resolver_register_off_nominal 176s END /main/dns/ - resolver_register_off_nominal Time: <1ms Result: PASS 176s START /main/dns/ - resolver_register_unregister 176s END /main/dns/ - resolver_register_unregister Time: <1ms Result: PASS 176s START /main/dns/naptr/ - naptr_resolve_off_nominal_interactions 176s END /main/dns/naptr/ - naptr_resolve_off_nominal_interactions Time: <1ms Result: PASS 176s START /main/dns/naptr/ - naptr_resolve_off_nominal_regexp 176s END /main/dns/naptr/ - naptr_resolve_off_nominal_regexp Time: <1ms Result: PASS 176s START /main/dns/naptr/ - naptr_resolve_off_nominal_services 176s END /main/dns/naptr/ - naptr_resolve_off_nominal_services Time: <1ms Result: PASS 176s START /main/dns/naptr/ - naptr_resolve_off_nominal_flags 176s END /main/dns/naptr/ - naptr_resolve_off_nominal_flags Time: <1ms Result: PASS 176s START /main/dns/naptr/ - naptr_resolve_off_nominal_length 176s END /main/dns/naptr/ - naptr_resolve_off_nominal_length Time: <1ms Result: PASS 176s START /main/dns/naptr/ - naptr_resolve 176s END /main/dns/naptr/ - naptr_resolve Time: <1ms Result: PASS 176s START /main/dns/query_set/ - query_set_off_nominal_cancel 176s END /main/dns/query_set/ - query_set_off_nominal_cancel Time: <1ms Result: PASS 176s START /main/dns/query_set/ - query_set_nominal_cancel 176s END /main/dns/query_set/ - query_set_nominal_cancel Time: <1ms Result: PASS 176s START /main/dns/query_set/ - query_set_empty 176s END /main/dns/query_set/ - query_set_empty Time: <1ms Result: PASS 176s START /main/dns/query_set/ - query_set 176s END /main/dns/query_set/ - query_set Time: <1ms Result: PASS 176s START /main/dns/recurring/ - recurring_query_cancel_during 176s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 183s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 193s END /main/dns/recurring/ - recurring_query_cancel_during Time: 16999ms Result: PASS 193s START /main/dns/recurring/ - recurring_query_cancel_between 193s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 203s END /main/dns/recurring/ - recurring_query_cancel_between Time: 10000ms Result: PASS 203s START /main/dns/recurring/ - recurring_query_off_nominal 203s END /main/dns/recurring/ - recurring_query_off_nominal Time: <1ms Result: PASS 203s START /main/dns/recurring/ - recurring_query 203s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 210s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 222s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 222s END /main/dns/recurring/ - recurring_query Time: 18998ms Result: PASS 222s START /main/dns/srv/ - srv_resolve_record_missing_host 222s END /main/dns/srv/ - srv_resolve_record_missing_host Time: <1ms Result: PASS 222s START /main/dns/srv/ - srv_resolve_record_missing_port_host 222s END /main/dns/srv/ - srv_resolve_record_missing_port_host Time: <1ms Result: PASS 222s START /main/dns/srv/ - srv_resolve_record_missing_weight_port_host 222s END /main/dns/srv/ - srv_resolve_record_missing_weight_port_host Time: <1ms Result: PASS 222s START /main/dns/srv/ - srv_resolve_different_priorities_different_weights 222s END /main/dns/srv/ - srv_resolve_different_priorities_different_weights Time: 2ms Result: PASS 222s START /main/dns/srv/ - srv_resolve_same_priority_different_weights 222s END /main/dns/srv/ - srv_resolve_same_priority_different_weights Time: 2ms Result: PASS 222s START /main/dns/srv/ - srv_resolve_same_priority_zero_weight 222s END /main/dns/srv/ - srv_resolve_same_priority_zero_weight Time: <1ms Result: PASS 222s START /main/dns/srv/ - srv_resolve_sort_priority 222s END /main/dns/srv/ - srv_resolve_sort_priority Time: <1ms Result: PASS 222s START /main/dns/srv/ - srv_resolve_single_record 222s END /main/dns/srv/ - srv_resolve_single_record Time: <1ms Result: PASS 222s START /main/dsp/ - dtmf 222s END /main/dsp/ - dtmf Time: 3ms Result: PASS 222s START /main/dsp/ - fax 223s END /main/dsp/ - fax Time: 510ms Result: PASS 223s START /main/event/ - ast_event_new_test 223s [test_event.c:event_new_test:125]: First, test dynamic event creation... 223s [test_event.c:check_event:88]: Event looks good. 223s [test_event.c:check_event:88]: Event looks good. 223s END /main/event/ - ast_event_new_test Time: <1ms Result: PASS 223s START /main/file/ - ast_format_str_reduce_test_1 223s END /main/file/ - ast_format_str_reduce_test_1 Time: <1ms Result: PASS 223s START /main/file/ - read_dir_test 223s END /main/file/ - read_dir_test Time: <1ms Result: PASS 223s START /main/format_cache/ - format_cache_get_nonxistent 223s END /main/format_cache/ - format_cache_get_nonxistent Time: <1ms Result: PASS 223s START /main/format_cache/ - format_cache_get 223s END /main/format_cache/ - format_cache_get Time: <1ms Result: PASS 223s START /main/format_cache/ - format_cache_set_null 223s END /main/format_cache/ - format_cache_set_null Time: <1ms Result: PASS 223s START /main/format_cache/ - format_cache_set_duplicate 223s END /main/format_cache/ - format_cache_set_duplicate Time: <1ms Result: PASS 223s START /main/format_cache/ - format_cache_set 223s END /main/format_cache/ - format_cache_set Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_replace_from_cap 223s END /main/format_cap/ - format_cap_replace_from_cap Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_best_by_type 223s END /main/format_cap/ - format_cap_best_by_type Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_iscompatible 223s END /main/format_cap/ - format_cap_iscompatible Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_get_compatible 223s END /main/format_cap/ - format_cap_get_compatible Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_iscompatible_format 223s END /main/format_cap/ - format_cap_iscompatible_format Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_get_compatible_format 223s END /main/format_cap/ - format_cap_get_compatible_format Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_get_names 223s END /main/format_cap/ - format_cap_get_names Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_remove_all 223s END /main/format_cap/ - format_cap_remove_all Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_remove_bytype 223s END /main/format_cap/ - format_cap_remove_bytype Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_remove_multiple 223s END /main/format_cap/ - format_cap_remove_multiple Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_remove_single 223s END /main/format_cap/ - format_cap_remove_single Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_set_framing 223s END /main/format_cap/ - format_cap_set_framing Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_append_from_cap_duplicate 223s END /main/format_cap/ - format_cap_append_from_cap_duplicate Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_append_from_cap 223s END /main/format_cap/ - format_cap_append_from_cap Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_append_duplicate 223s END /main/format_cap/ - format_cap_append_duplicate Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_append_all_audio 223s END /main/format_cap/ - format_cap_append_all_audio Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_append_all_unknown 223s END /main/format_cap/ - format_cap_append_all_unknown Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_append_multiple 223s END /main/format_cap/ - format_cap_append_multiple Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_append_single 223s END /main/format_cap/ - format_cap_append_single Time: <1ms Result: PASS 223s START /main/format_cap/ - format_cap_alloc 223s END /main/format_cap/ - format_cap_alloc Time: <1ms Result: PASS 223s START /main/hashtab/ - thrash 223s [test_hashtab_thrash.c:hash_test:246]: Executing hash concurrency test... 223s END /main/hashtab/ - thrash Time: 15ms Result: PASS 223s START /main/heap/ - heap_test_3 223s END /main/heap/ - heap_test_3 Time: 54ms Result: PASS 223s START /main/heap/ - heap_test_2 223s END /main/heap/ - heap_test_2 Time: 50ms Result: PASS 223s START /main/heap/ - heap_test_1 223s END /main/heap/ - heap_test_1 Time: <1ms Result: PASS 223s START /main/jitterbuf/ - jitterbuffer_resynch_control 223s END /main/jitterbuf/ - jitterbuffer_resynch_control Time: <1ms Result: PASS 223s START /main/jitterbuf/ - jitterbuffer_resynch_voice 223s END /main/jitterbuf/ - jitterbuffer_resynch_voice Time: <1ms Result: PASS 223s START /main/jitterbuf/ - jitterbuffer_overflow_control 223s END /main/jitterbuf/ - jitterbuffer_overflow_control Time: <1ms Result: PASS 223s START /main/jitterbuf/ - jitterbuffer_overflow_voice 223s END /main/jitterbuf/ - jitterbuffer_overflow_voice Time: <1ms Result: PASS 223s START /main/jitterbuf/ - jitterbuffer_late_control 223s END /main/jitterbuf/ - jitterbuffer_late_control Time: <1ms Result: PASS 223s START /main/jitterbuf/ - jitterbuffer_late_voice 223s END /main/jitterbuf/ - jitterbuffer_late_voice Time: <1ms Result: PASS 223s START /main/jitterbuf/ - jitterbuffer_lost_control 223s END /main/jitterbuf/ - jitterbuffer_lost_control Time: <1ms Result: PASS 223s START /main/jitterbuf/ - jitterbuffer_lost_voice 223s END /main/jitterbuf/ - jitterbuffer_lost_voice Time: <1ms Result: PASS 223s START /main/jitterbuf/ - jitterbuffer_out_of_order_voice 223s END /main/jitterbuf/ - jitterbuffer_out_of_order_voice Time: <1ms Result: PASS 223s START /main/jitterbuf/ - jitterbuffer_out_of_order_voice 223s END /main/jitterbuf/ - jitterbuffer_out_of_order_voice Time: <1ms Result: PASS 223s START /main/jitterbuf/ - jitterbuffer_nominal_control_frames 223s END /main/jitterbuf/ - jitterbuffer_nominal_control_frames Time: <1ms Result: PASS 223s START /main/jitterbuf/ - jitterbuffer_nominal_voice_frames 223s END /main/jitterbuf/ - jitterbuffer_nominal_voice_frames Time: <1ms Result: PASS 223s START /main/json/ - cep 223s END /main/json/ - cep Time: <1ms Result: PASS 223s START /main/json/ - type_timeval 223s END /main/json/ - type_timeval Time: <1ms Result: PASS 223s START /main/json/ - name_number 223s END /main/json/ - name_number Time: <1ms Result: PASS 223s START /main/json/ - clever_circle 223s END /main/json/ - clever_circle Time: <1ms Result: PASS 223s START /main/json/ - circular_array 223s END /main/json/ - circular_array Time: <1ms Result: PASS 223s START /main/json/ - circular_object 223s END /main/json/ - circular_object Time: <1ms Result: PASS 223s START /main/json/ - copy_null 223s END /main/json/ - copy_null Time: <1ms Result: PASS 223s START /main/json/ - deep_copy 223s END /main/json/ - deep_copy Time: <1ms Result: PASS 223s START /main/json/ - copy 223s END /main/json/ - copy Time: <1ms Result: PASS 223s START /main/json/ - object_alloc 223s END /main/json/ - object_alloc Time: <1ms Result: PASS 223s START /main/json/ - pack_ownership 223s END /main/json/ - pack_ownership Time: <1ms Result: PASS 223s START /main/json/ - pack 223s END /main/json/ - pack Time: <1ms Result: PASS 223s START /main/json/ - parse_errors 223s END /main/json/ - parse_errors Time: <1ms Result: PASS 223s START /main/json/ - dump_load_null 223s END /main/json/ - dump_load_null Time: <1ms Result: PASS 223s START /main/json/ - dump_load_new_file 223s END /main/json/ - dump_load_new_file Time: <1ms Result: PASS 223s START /main/json/ - dump_load_file 223s END /main/json/ - dump_load_file Time: <1ms Result: PASS 223s START /main/json/ - load_buffer 223s END /main/json/ - load_buffer Time: <1ms Result: PASS 223s START /main/json/ - dump_str_fail 223s END /main/json/ - dump_str_fail Time: <1ms Result: PASS 223s START /main/json/ - dump_load_str 223s END /main/json/ - dump_load_str Time: <1ms Result: PASS 223s START /main/json/ - dump_load_string 223s END /main/json/ - dump_load_string Time: <1ms Result: PASS 223s START /main/json/ - object_create_vars 223s END /main/json/ - object_create_vars Time: <1ms Result: PASS 223s START /main/json/ - object_iter_null 223s END /main/json/ - object_iter_null Time: <1ms Result: PASS 223s START /main/json/ - object_iter 223s END /main/json/ - object_iter Time: <1ms Result: PASS 223s START /main/json/ - object_null 223s END /main/json/ - object_null Time: <1ms Result: PASS 223s START /main/json/ - object_merge_missing 223s END /main/json/ - object_merge_missing Time: <1ms Result: PASS 223s START /main/json/ - object_alloc 223s END /main/json/ - object_alloc Time: <1ms Result: PASS 223s START /main/json/ - object_alloc 223s END /main/json/ - object_alloc Time: <1ms Result: PASS 223s START /main/json/ - object_clear 223s END /main/json/ - object_clear Time: <1ms Result: PASS 223s START /main/json/ - object_del 223s END /main/json/ - object_del Time: <1ms Result: PASS 223s START /main/json/ - object_get 223s END /main/json/ - object_get Time: <1ms Result: PASS 223s START /main/json/ - object_set_overwriting 223s END /main/json/ - object_set_overwriting Time: <1ms Result: PASS 223s START /main/json/ - object_set 223s END /main/json/ - object_set Time: <1ms Result: PASS 223s START /main/json/ - object_alloc 223s END /main/json/ - object_alloc Time: <1ms Result: PASS 223s START /main/json/ - array_null 223s END /main/json/ - array_null Time: <1ms Result: PASS 223s START /main/json/ - array_extend 223s END /main/json/ - array_extend Time: <1ms Result: PASS 223s START /main/json/ - array_clear 223s END /main/json/ - array_clear Time: <1ms Result: PASS 223s START /main/json/ - array_remove 223s END /main/json/ - array_remove Time: <1ms Result: PASS 223s START /main/json/ - array_set 223s END /main/json/ - array_set Time: <1ms Result: PASS 223s START /main/json/ - array_insert 223s END /main/json/ - array_insert Time: <1ms Result: PASS 223s START /main/json/ - array_append 223s END /main/json/ - array_append Time: <1ms Result: PASS 223s START /main/json/ - array_create 223s END /main/json/ - array_create Time: <1ms Result: PASS 223s START /main/json/ - non_int 223s END /main/json/ - non_int Time: <1ms Result: PASS 223s START /main/json/ - type_int 223s END /main/json/ - type_int Time: <1ms Result: PASS 223s START /main/json/ - stringf 223s END /main/json/ - stringf Time: <1ms Result: PASS 223s START /main/json/ - string_null 223s END /main/json/ - string_null Time: <1ms Result: PASS 223s START /main/json/ - type_string 223s END /main/json/ - type_string Time: <1ms Result: PASS 223s START /main/json/ - null_val 223s END /main/json/ - null_val Time: <1ms Result: PASS 223s START /main/json/ - type_null 223s END /main/json/ - type_null Time: <1ms Result: PASS 223s START /main/json/ - type_bool1 223s END /main/json/ - type_bool1 Time: <1ms Result: PASS 223s START /main/json/ - type_bool0 223s END /main/json/ - type_bool0 Time: <1ms Result: PASS 223s START /main/json/ - type_true 223s END /main/json/ - type_true Time: <1ms Result: PASS 223s START /main/json/ - type_false 223s END /main/json/ - type_false Time: <1ms Result: PASS 223s START /main/linkedlists/ - double_ll_tests 223s END /main/linkedlists/ - double_ll_tests Time: <1ms Result: PASS 223s START /main/linkedlists/ - ll_tests 223s END /main/linkedlists/ - ll_tests Time: <1ms Result: PASS 223s START /main/lock/ - named_lock_test 223s [test_named_lock.c:named_lock_test:80]: This test should take about 3 seconds 226s END /main/lock/ - named_lock_test Time: 3000ms Result: PASS 226s START /main/lock/ - cleanup_order_test 226s [test_scoped_lock.c:test_ref:149]: Ref is occurring 226s [test_scoped_lock.c:test_lock:117]: Lock is occurring 226s [test_scoped_lock.c:test_unlock:133]: Unlock is occurring 226s [test_scoped_lock.c:test_unref:166]: Unref is occurring 226s [test_scoped_lock.c:test_ref:149]: Ref is occurring 226s [test_scoped_lock.c:test_lock:117]: Lock is occurring 226s [test_scoped_lock.c:test_unlock:133]: Unlock is occurring 226s [test_scoped_lock.c:test_unref:166]: Unref is occurring 226s END /main/lock/ - cleanup_order_test Time: <1ms Result: PASS 226s START /main/lock/ - lock_test 226s END /main/lock/ - lock_test Time: <1ms Result: PASS 226s START /main/logging/ - scope_test 226s END /main/logging/ - scope_test Time: <1ms Result: PASS 226s START /main/manager/ - originate_permissions_test 226s END /main/manager/ - originate_permissions_test Time: <1ms Result: PASS 226s START /main/manager/ - eventfilter_test_matching 226s Loaded 7 filters 226s Tested 9 events 226s END /main/manager/ - eventfilter_test_matching Time: <1ms Result: PASS 226s START /main/manager/ - eventfilter_test_creation 226s [manager.c:eventfilter_test_creation:6189]: Tested 29 filters 226s END /main/manager/ - eventfilter_test_creation Time: <1ms Result: PASS 226s START /main/media_cache/ - create_update_off_nominal 226s END /main/media_cache/ - create_update_off_nominal Time: <1ms Result: PASS 226s START /main/media_cache/ - create_update_metadata 226s [test_media_cache.c:create_update_metadata:367]: Got /tmp/test-media-cache-OXM4mZ for second file path 226s END /main/media_cache/ - create_update_metadata Time: <1ms Result: PASS 226s START /main/media_cache/ - create_update_nominal 226s [test_media_cache.c:create_update_nominal:236]: Creating resource with /tmp/test-media-cache-y129Da 226s [test_media_cache.c:create_update_nominal:241]: Got /tmp/test-media-cache-y129Da for first file path 226s [test_media_cache.c:create_update_nominal:245]: Creating resource with /tmp/test-media-cache-yDJda2 226s [test_media_cache.c:create_update_nominal:250]: Got /tmp/test-media-cache-yDJda2 for second file path 226s END /main/media_cache/ - create_update_nominal Time: <1ms Result: PASS 226s START /main/media_cache/ - exists_off_nominal 226s END /main/media_cache/ - exists_off_nominal Time: <1ms Result: PASS 226s START /main/media_cache/ - exists_nominal 226s END /main/media_cache/ - exists_nominal Time: <1ms Result: PASS 226s START /main/netsock2/ - split_hostport 226s END /main/netsock2/ - split_hostport Time: <1ms Result: PASS 226s START /main/netsock2/ - parsing 226s END /main/netsock2/ - parsing Time: <1ms Result: PASS 226s START /main/optional_api/ - test_provide_last 226s END /main/optional_api/ - test_provide_last Time: <1ms Result: PASS 226s START /main/optional_api/ - test_provide_first 226s END /main/optional_api/ - test_provide_first Time: <1ms Result: PASS 226s START /main/pbx/ - pattern_match_test 226s [test_pbx.c:test_exten:183]: Successfully matched 200 to exten _2. in context test_pattern with the old pattern match engine 226s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the old pattern match engine 226s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the old pattern match engine 226s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern_include with the old pattern match engine 226s [test_pbx.c:test_exten:183]: Successfully matched 200 to exten _2. in context test_pattern with the new pattern match engine 226s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the new pattern match engine 226s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the new pattern match engine 226s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern_include with the new pattern match engine 226s END /main/pbx/ - pattern_match_test Time: <1ms Result: PASS 226s START /main/pbx/ - test_MATH_function 226s [func_math.c:test_MATH_function:682]: Testing MATH() substitution ... 226s END /main/pbx/ - test_MATH_function Time: <1ms Result: PASS 226s START /main/pbx/ - test_substitution 226s [test_substitution.c:test_substitution:244]: Testing variable substitution ... 226s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGANI2}' . . . . . passed 226s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGTON}' . . . . . passed 226s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGTNS}' . . . . . passed 226s [test_substitution.c:test_chan_integer_accessor:89]: Tested '${HANGUPCAUSE}' . . . . . passed 226s [test_substitution.c:test_chan_integer_accessor:89]: Tested '${PRIORITY}' . . . . . passed 226s [test_substitution.c:test_chan_string:115]: Tested '${CONTEXT}' . . . . . passed 226s [test_substitution.c:test_chan_string:115]: Tested '${EXTEN}' . . . . . passed 226s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(language)}' . . . . . passed 226s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(musicclass)}' . . . . . passed 226s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(parkinglot)}' . . . . . passed 226s [test_substitution.c:test_chan_variable:144]: Tested '${CALLERID(name)}' . . . . . passed 226s [test_substitution.c:test_chan_variable:144]: Tested '${CURLOPT(proxyuserpwd)}' . . . . . passed 226s [test_substitution.c:test_chan_variable:144]: Tested '${CDR(foo)}' . . . . . passed 226s [test_substitution.c:test_chan_variable:144]: Tested '${ENV(foo)}' . . . . . passed 226s [test_substitution.c:test_chan_variable:144]: Tested '${GLOBAL(foo)}' . . . . . passed 226s [test_substitution.c:test_chan_variable:144]: Tested '${GROUP()}' . . . . . passed 226s [test_substitution.c:test_2way_function:193]: Tested '${AES_ENCRYPT(abcdefghijklmnop,)}' and '${AES_DECRYPT(abcdefghijklmnop,)}' . . . . . passed 226s [test_substitution.c:test_2way_function:193]: Tested '${BASE64_ENCODE()}' and '${BASE64_DECODE()}' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested '123123' ('${foo}${foo}') == '123123' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested 'A123A123A' ('A${foo}A${foo}A') == 'A123A123A' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested 'A123A' ('A${${bar}}A') == 'A123A' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested 'A123A' ('A${${baz}o}A') == 'A123A' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested 'A23A' ('A${${baz}o:1}A') == 'A23A' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:1:1}A') == 'A2A' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:1:-1}A') == 'A2A' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested 'A3A' ('A${${baz}o:-1:1}A') == 'A3A' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:-2:1}A') == 'A2A' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:-2:-1}A') == 'A2A' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested 'cd&ef' ('${LISTFILTER(list1,&,ab)}') == 'cd&ef' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested 'ab&ef' ('${LISTFILTER(list1,&,cd)}') == 'ab&ef' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd' ('${LISTFILTER(list1,&,ef)}') == 'ab&cd' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,gh)}') == 'ab&cd&ef' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,c)}') == 'ab&cd&ef' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,d)}') == 'ab&cd&ef' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested '' ('${LISTFILTER(list2,&,ab)}') == '' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested '' ('${LISTFILTER(list_empty,&,ab)}') == '' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested '123,456' ('${SHELL(printf '%d' 123)},${SHELL(printf '%d' 456)}') == '123,456' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested '123,,456' ('${foo},${CDR(answer)},${SHELL(printf '%d' 456)}') == '123,,456' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested '123,0.000000,456' ('${foo},${CDR(answer,u)},${SHELL(printf '%d' 456)}') == '123,0.000000,456' . . . . . passed 226s [test_substitution.c:test_expected_result:215]: Tested '123,,' ('${foo},${this_does_not_exist},${THIS_DOES_NOT_EXIST(either)}') == '123,,' . . . . . passed 226s [test_substitution.c:test_chan_function:168]: Tested '${BLACKLIST(foo)}' . . . . . passed 226s [test_substitution.c:test_chan_function:168]: Tested '${EVAL(foo)}' . . . . . passed 226s [test_substitution.c:test_chan_function:168]: Tested '${FIELDNUM(foo)}' . . . . . passed 226s [test_substitution.c:test_chan_function:168]: Tested '${FIELDQTY(foo)}' . . . . . passed 226s [test_substitution.c:test_chan_function:168]: Tested '${HASHKEYS(foo)}' . . . . . passed 226s [test_substitution.c:test_chan_function:168]: Tested '${IMPORT(foo)}' . . . . . passed 226s [test_substitution.c:test_chan_function:168]: Tested '${PP_EACH_USER(foo)}' . . . . . passed 226s [test_substitution.c:test_chan_function:168]: Tested '${TOLOWER(foo)}' . . . . . passed 226s [test_substitution.c:test_chan_function:168]: Tested '${TOUPPER(foo)}' . . . . . passed 226s END /main/pbx/ - test_substitution Time: 9ms Result: PASS 226s START /main/pbx/ - variable_substrings 226s END /main/pbx/ - variable_substrings Time: <1ms Result: PASS 226s START /main/poll/ - poll_test 226s [test_poll.c:poll_test:95]: Creating handle that should NEVER block on write 226s [test_poll.c:poll_test:101]: Creating handle that should NEVER block on read 226s [test_poll.c:poll_test:108]: Creating handle that should block on read 226s [test_poll.c:poll_test:168]: Starting thread to ensure we don't block forever 226s [test_poll.c:poll_test:194]: Cancelling failsafe thread. 226s END /main/poll/ - poll_test Time: <1ms Result: PASS 226s START /main/presence/ - channel_presence 226s END /main/presence/ - channel_presence Time: <1ms Result: PASS 226s START /main/sample/ - sample_test 226s [test_skel.c:sample_test:57]: Executing sample test... 226s END /main/sample/ - sample_test Time: <1ms Result: PASS 226s START /main/sched/ - sched_test_freebird 226s [test_sched.c:sched_test_freebird:440]: Received signal, calling Scedule and UNREF 226s [test_sched.c:sched_test_freebird:441]: ID: 1 229s [test_sched.c:sched_test_freebird:448]: Correct number of references '2' 229s END /main/sched/ - sched_test_freebird Time: 3000ms Result: PASS 229s START /main/sched/ - sched_test_order 229s END /main/sched/ - sched_test_order Time: 400ms Result: PASS 229s START /main/sorcery/ - wizard_read_only 229s END /main/sorcery/ - wizard_read_only Time: <1ms Result: PASS 229s START /main/sorcery/ - wizard_observation 229s END /main/sorcery/ - wizard_observation Time: <1ms Result: PASS 229s START /main/sorcery/ - instance_observation 229s END /main/sorcery/ - instance_observation Time: <1ms Result: PASS 229s START /main/sorcery/ - global_observation 229s END /main/sorcery/ - global_observation Time: <1ms Result: PASS 229s START /main/sorcery/ - object_field_registered 229s END /main/sorcery/ - object_field_registered Time: <1ms Result: PASS 229s START /main/sorcery/ - dialplan_function 229s END /main/sorcery/ - dialplan_function Time: <1ms Result: PASS 229s START /main/sorcery/ - configuration_file_wizard_retrieve_multiple_all 229s END /main/sorcery/ - configuration_file_wizard_retrieve_multiple_all Time: <1ms Result: PASS 229s START /main/sorcery/ - configuration_file_wizard_retrieve_multiple 229s END /main/sorcery/ - configuration_file_wizard_retrieve_multiple Time: <1ms Result: PASS 229s START /main/sorcery/ - configuration_file_wizard_retrieve_field 229s END /main/sorcery/ - configuration_file_wizard_retrieve_field Time: <1ms Result: PASS 229s START /main/sorcery/ - configuration_file_wizard_with_criteria 229s END /main/sorcery/ - configuration_file_wizard_with_criteria Time: <1ms Result: PASS 229s START /main/sorcery/ - configuration_file_wizard_with_file_integrity 229s END /main/sorcery/ - configuration_file_wizard_with_file_integrity Time: <1ms Result: PASS 229s START /main/sorcery/ - configuration_file_wizard 229s END /main/sorcery/ - configuration_file_wizard Time: <1ms Result: PASS 229s START /main/sorcery/ - object_type_observer 229s END /main/sorcery/ - object_type_observer Time: <1ms Result: PASS 229s START /main/sorcery/ - caching_wizard_behavior 229s END /main/sorcery/ - caching_wizard_behavior Time: <1ms Result: PASS 229s START /main/sorcery/ - object_is_stale 229s END /main/sorcery/ - object_is_stale Time: <1ms Result: PASS 229s START /main/sorcery/ - object_delete_uncreated 229s END /main/sorcery/ - object_delete_uncreated Time: <1ms Result: PASS 229s START /main/sorcery/ - object_delete 229s END /main/sorcery/ - object_delete Time: <1ms Result: PASS 229s START /main/sorcery/ - object_update_uncreated 229s END /main/sorcery/ - object_update_uncreated Time: <1ms Result: PASS 229s START /main/sorcery/ - object_update 229s END /main/sorcery/ - object_update Time: <1ms Result: PASS 229s START /main/sorcery/ - object_retrieve_regex 229s END /main/sorcery/ - object_retrieve_regex Time: <1ms Result: PASS 229s START /main/sorcery/ - object_retrieve_multiple_field 229s END /main/sorcery/ - object_retrieve_multiple_field Time: <1ms Result: PASS 229s START /main/sorcery/ - object_retrieve_multiple_all 229s END /main/sorcery/ - object_retrieve_multiple_all Time: <1ms Result: PASS 229s START /main/sorcery/ - object_retrieve_field 229s END /main/sorcery/ - object_retrieve_field Time: <1ms Result: PASS 229s START /main/sorcery/ - object_retrieve_id 229s END /main/sorcery/ - object_retrieve_id Time: <1ms Result: PASS 229s START /main/sorcery/ - object_create 229s END /main/sorcery/ - object_create Time: <1ms Result: PASS 229s START /main/sorcery/ - changeset_create_unchanged 229s END /main/sorcery/ - changeset_create_unchanged Time: <1ms Result: PASS 229s START /main/sorcery/ - changeset_create 229s END /main/sorcery/ - changeset_create Time: <1ms Result: PASS 229s START /main/sorcery/ - extended_fields 229s END /main/sorcery/ - extended_fields Time: <1ms Result: PASS 229s START /main/sorcery/ - objectset_apply_fields 229s END /main/sorcery/ - objectset_apply_fields Time: <1ms Result: PASS 229s START /main/sorcery/ - objectset_transform 229s END /main/sorcery/ - objectset_transform Time: <1ms Result: PASS 229s START /main/sorcery/ - objectset_apply_invalid 229s END /main/sorcery/ - objectset_apply_invalid Time: <1ms Result: PASS 229s START /main/sorcery/ - objectset_apply_handler 229s END /main/sorcery/ - objectset_apply_handler Time: <1ms Result: PASS 229s START /main/sorcery/ - objectset_apply 229s END /main/sorcery/ - objectset_apply Time: <1ms Result: PASS 229s START /main/sorcery/ - objectset_create_regex 229s END /main/sorcery/ - objectset_create_regex Time: <1ms Result: PASS 229s START /main/sorcery/ - objectset_json_create 229s END /main/sorcery/ - objectset_json_create Time: <1ms Result: PASS 229s START /main/sorcery/ - objectset_create 229s END /main/sorcery/ - objectset_create Time: <1ms Result: PASS 229s START /main/sorcery/ - object_diff_native 229s END /main/sorcery/ - object_diff_native Time: <1ms Result: PASS 229s START /main/sorcery/ - object_diff 229s END /main/sorcery/ - object_diff Time: <1ms Result: PASS 229s START /main/sorcery/ - object_copy_native 229s END /main/sorcery/ - object_copy_native Time: <1ms Result: PASS 229s START /main/sorcery/ - object_copy 229s END /main/sorcery/ - object_copy Time: <1ms Result: PASS 229s START /main/sorcery/ - object_alloc_without_id 229s END /main/sorcery/ - object_alloc_without_id Time: <1ms Result: PASS 229s START /main/sorcery/ - object_alloc_with_id 229s END /main/sorcery/ - object_alloc_with_id Time: <1ms Result: PASS 229s START /main/sorcery/ - object_fields_register 229s END /main/sorcery/ - object_fields_register Time: <1ms Result: PASS 229s START /main/sorcery/ - object_field_register 229s END /main/sorcery/ - object_field_register Time: <1ms Result: PASS 229s START /main/sorcery/ - object_register_without_mapping 229s END /main/sorcery/ - object_register_without_mapping Time: <1ms Result: PASS 229s START /main/sorcery/ - object_register 229s END /main/sorcery/ - object_register Time: <1ms Result: PASS 229s START /main/sorcery/ - apply_config 229s END /main/sorcery/ - apply_config Time: <1ms Result: PASS 229s START /main/sorcery/ - apply_default 229s END /main/sorcery/ - apply_default Time: <1ms Result: PASS 229s START /main/sorcery/ - open 229s END /main/sorcery/ - open Time: <1ms Result: PASS 229s START /main/sorcery/ - wizard_registration 229s END /main/sorcery/ - wizard_registration Time: <1ms Result: PASS 229s START /main/sorcery/ - wizard_apply_and_insert 229s END /main/sorcery/ - wizard_apply_and_insert Time: <1ms Result: PASS 229s START /main/stdtime/ - time_create_by_unit_str 229s END /main/stdtime/ - time_create_by_unit_str Time: <1ms Result: PASS 229s START /main/stdtime/ - time_create_by_unit 229s END /main/stdtime/ - time_create_by_unit Time: <1ms Result: PASS 229s START /main/stdtime/ - time_str_to_unit 229s END /main/stdtime/ - time_str_to_unit Time: <1ms Result: PASS 229s START /main/stdtime/ - time_tv_to_usec 229s END /main/stdtime/ - time_tv_to_usec Time: <1ms Result: PASS 229s START /main/stdtime/ - timezone_watch 229s [test_time.c:test_timezone_watch:82]: Executing deletion test... 229s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.oqLXEd/test 230s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.oqLXEd/test 230s [test_time.c:test_timezone_watch:82]: Executing symlink test... 230s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.oqLXEd/test 232s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.oqLXEd/test 232s END /main/stdtime/ - timezone_watch Time: 2233ms Result: PASS 232s START /main/stream/ - stream_topology_map_create 232s END /main/stream/ - stream_topology_map_create Time: <1ms Result: PASS 232s START /main/stream/ - format_cap_from_stream_topology 232s END /main/stream/ - format_cap_from_stream_topology Time: <1ms Result: PASS 232s START /main/stream/ - stream_topology_change_request_from_channel 232s END /main/stream/ - stream_topology_change_request_from_channel Time: <1ms Result: PASS 232s START /main/stream/ - stream_topology_change_request_from_application 232s END /main/stream/ - stream_topology_change_request_from_application Time: <1ms Result: PASS 232s START /main/stream/ - stream_topology_change_request_from_channel_non_multistream 232s END /main/stream/ - stream_topology_change_request_from_channel_non_multistream Time: <1ms Result: PASS 232s START /main/stream/ - stream_topology_change_request_from_application_non_multistream 232s END /main/stream/ - stream_topology_change_request_from_application_non_multistream Time: <1ms Result: PASS 232s START /main/stream/ - stream_read_multistream 232s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 232s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 232s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 232s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 232s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 4 Frames: 16 Frames per read: 1 Expected Nulls: 8 232s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 8 232s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 4 Frames: 16 Frames per read: 1 Expected Nulls: 0 232s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 232s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 232s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 232s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 232s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 232s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 4 Frames: 16 Frames per read: 3 Expected Nulls: 8 232s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 8 232s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 4 Frames: 16 Frames per read: 3 Expected Nulls: 0 232s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 232s END /main/stream/ - stream_read_multistream Time: <1ms Result: PASS 232s START /main/stream/ - stream_read_non_multistream 232s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 232s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 232s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 232s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 232s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 232s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 232s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 232s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 232s END /main/stream/ - stream_read_non_multistream Time: <1ms Result: PASS 232s START /main/stream/ - stream_write_multistream 232s END /main/stream/ - stream_write_multistream Time: <1ms Result: PASS 232s START /main/stream/ - stream_write_non_multistream 232s END /main/stream/ - stream_write_non_multistream Time: <1ms Result: PASS 232s START /main/stream/ - stream_topology_channel_set 232s END /main/stream/ - stream_topology_channel_set Time: <1ms Result: PASS 232s START /main/stream/ - stream_topology_create_from_channel_nativeformats 232s END /main/stream/ - stream_topology_create_from_channel_nativeformats Time: <1ms Result: PASS 232s START /main/stream/ - stream_topology_get_first_stream_by_type 232s END /main/stream/ - stream_topology_get_first_stream_by_type Time: <1ms Result: PASS 232s START /main/stream/ - stream_topology_create_from_format_cap 232s END /main/stream/ - stream_topology_create_from_format_cap Time: <1ms Result: PASS 232s START /main/stream/ - stream_topology_del_stream 232s END /main/stream/ - stream_topology_del_stream Time: <1ms Result: PASS 232s START /main/stream/ - stream_topology_set_stream 232s END /main/stream/ - stream_topology_set_stream Time: <1ms Result: PASS 232s START /main/stream/ - stream_topology_append_stream 232s END /main/stream/ - stream_topology_append_stream Time: <1ms Result: PASS 232s START /main/stream/ - stream_topology_clone 232s END /main/stream/ - stream_topology_clone Time: <1ms Result: PASS 232s START /main/stream/ - stream_topology_create 232s END /main/stream/ - stream_topology_create Time: <1ms Result: PASS 232s START /main/stream/ - stream_metadata 232s END /main/stream/ - stream_metadata Time: <1ms Result: PASS 232s START /main/stream/ - stream_set_state 232s END /main/stream/ - stream_set_state Time: <1ms Result: PASS 232s START /main/stream/ - stream_set_formats 232s END /main/stream/ - stream_set_formats Time: <1ms Result: PASS 232s START /main/stream/ - stream_set_type 232s END /main/stream/ - stream_set_type Time: <1ms Result: PASS 232s START /main/stream/ - stream_create_no_name 232s END /main/stream/ - stream_create_no_name Time: <1ms Result: PASS 232s START /main/stream/ - stream_create 232s END /main/stream/ - stream_create Time: <1ms Result: PASS 232s START /main/strings/ - in_delimited_string 232s END /main/strings/ - in_delimited_string Time: <1ms Result: PASS 232s START /main/strings/ - temp_strings 232s END /main/strings/ - temp_strings Time: <1ms Result: PASS 232s START /main/strings/ - strings_match 232s END /main/strings/ - strings_match Time: <1ms Result: PASS 232s START /main/strings/ - escape 232s END /main/strings/ - escape Time: <1ms Result: PASS 232s START /main/strings/ - escape_semicolons 232s END /main/strings/ - escape_semicolons Time: <1ms Result: PASS 232s START /main/strings/ - strsep_quoted 232s END /main/strings/ - strsep_quoted Time: <1ms Result: PASS 232s START /main/strings/ - strsep 232s END /main/strings/ - strsep Time: <1ms Result: PASS 232s START /main/strings/ - ends_with 232s END /main/strings/ - ends_with Time: <1ms Result: PASS 232s START /main/strings/ - begins_with 232s END /main/strings/ - begins_with Time: <1ms Result: PASS 232s START /main/strings/ - str_test 232s END /main/strings/ - str_test Time: <1ms Result: PASS 232s START /main/taskprocessor/ - serializer_pool 236s END /main/taskprocessor/ - serializer_pool Time: 4000ms Result: PASS 236s START /main/taskprocessor/ - taskprocessor_push_local 236s END /main/taskprocessor/ - taskprocessor_push_local Time: <1ms Result: PASS 236s START /main/taskprocessor/ - taskprocessor_shutdown 236s END /main/taskprocessor/ - taskprocessor_shutdown Time: <1ms Result: PASS 236s START /main/taskprocessor/ - taskprocessor_listener 236s END /main/taskprocessor/ - taskprocessor_listener Time: <1ms Result: PASS 236s START /main/taskprocessor/ - subsystem_alert 236s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 1 236s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 2 236s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 3 236s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 4 236s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 5 236s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 6 236s [test_taskprocessor.c:subsystem_alert:237]: Subsystem alert triggered correctly at 6 236s [test_taskprocessor.c:subsystem_alert:240]: Global alert triggered correctly at 6 236s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 7 236s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 8 236s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 9 236s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 10 236s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 1 236s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 2 237s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 3 237s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 4 238s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 5 238s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 6 239s [test_taskprocessor.c:subsystem_alert:279]: Subsystem alert cleared correctly at 3 239s [test_taskprocessor.c:subsystem_alert:282]: Global alert cleared correctly at 3 239s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 7 239s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 8 240s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 9 240s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 10 241s END /main/taskprocessor/ - subsystem_alert Time: 5001ms Result: PASS 241s START /main/taskprocessor/ - default_taskprocessor_load 241s END /main/taskprocessor/ - default_taskprocessor_load Time: 14ms Result: PASS 241s START /main/taskprocessor/ - default_taskprocessor 241s END /main/taskprocessor/ - default_taskprocessor Time: 1ms Result: PASS 241s START /main/test/ - registrations 241s END /main/test/ - registrations Time: <1ms Result: PASS 241s START /main/test_capture/ - test_capture_false 241s [test_capture.c:test_capture_false:120]: Executing false exit test... 241s END /main/test_capture/ - test_capture_false Time: 6ms Result: PASS 241s START /main/test_capture/ - test_capture_true 241s [test_capture.c:test_capture_true:61]: Executing true exit test... 241s END /main/test_capture/ - test_capture_true Time: 4ms Result: PASS 241s START /main/test_capture/ - test_capture_stdout_stderr 241s [test_capture.c:test_capture_stdout_stderr:318]: Executing stdout/stderr test... 241s END /main/test_capture/ - test_capture_stdout_stderr Time: 4ms Result: PASS 241s START /main/test_capture/ - test_capture_with_dynamic 241s [test_capture.c:test_capture_with_dynamic:249]: Executing dynamic argument test... 241s END /main/test_capture/ - test_capture_with_dynamic Time: 4ms Result: PASS 241s START /main/test_capture/ - test_capture_with_stdin 241s [test_capture.c:test_capture_with_stdin:183]: Executing stdin test... 241s END /main/test_capture/ - test_capture_with_stdin Time: 4ms Result: PASS 241s START /main/threadpool/ - threadpool_serializer_dupe 241s END /main/threadpool/ - threadpool_serializer_dupe Time: <1ms Result: PASS 241s START /main/threadpool/ - threadpool_serializer 242s END /main/threadpool/ - threadpool_serializer Time: 1000ms Result: PASS 242s START /main/threadpool/ - more_destruction 242s END /main/threadpool/ - more_destruction Time: <1ms Result: PASS 242s START /main/threadpool/ - task_distribution 242s END /main/threadpool/ - task_distribution Time: <1ms Result: PASS 242s START /main/threadpool/ - reactivation 242s END /main/threadpool/ - reactivation Time: <1ms Result: PASS 242s START /main/threadpool/ - max_size 242s END /main/threadpool/ - max_size Time: <1ms Result: PASS 242s START /main/threadpool/ - auto_increment 242s END /main/threadpool/ - auto_increment Time: <1ms Result: PASS 242s START /main/threadpool/ - one_thread_multiple_tasks 242s END /main/threadpool/ - one_thread_multiple_tasks Time: <1ms Result: PASS 242s START /main/threadpool/ - one_thread_one_task 242s END /main/threadpool/ - one_thread_one_task Time: <1ms Result: PASS 242s START /main/threadpool/ - one_task_one_thread 242s END /main/threadpool/ - one_task_one_thread Time: <1ms Result: PASS 242s START /main/threadpool/ - thread_timeout_thrash 273s END /main/threadpool/ - thread_timeout_thrash Time: 31010ms Result: PASS 273s START /main/threadpool/ - thread_timeout 275s END /main/threadpool/ - thread_timeout Time: 2000ms Result: PASS 275s START /main/threadpool/ - thread_destruction 275s END /main/threadpool/ - thread_destruction Time: <1ms Result: PASS 275s START /main/threadpool/ - thread_creation 275s END /main/threadpool/ - thread_creation Time: <1ms Result: PASS 275s START /main/threadpool/ - initial_threads 275s END /main/threadpool/ - initial_threads Time: <1ms Result: PASS 275s START /main/threadpool/ - push 275s END /main/threadpool/ - push Time: <1ms Result: PASS 275s START /main/uri/ - uri_default_http_secure 275s END /main/uri/ - uri_default_http_secure Time: <1ms Result: PASS 275s START /main/uri/ - uri_default_http 275s END /main/uri/ - uri_default_http Time: <1ms Result: PASS 275s START /main/uri/ - uri_parse 275s END /main/uri/ - uri_parse Time: <1ms Result: PASS 275s START /main/utf8/ - replace_invalid 275s END /main/utf8/ - replace_invalid Time: <1ms Result: PASS 275s START /main/utf8/ - utf8_validator 275s END /main/utf8/ - utf8_validator Time: <1ms Result: PASS 275s START /main/utf8/ - copy_string 275s END /main/utf8/ - copy_string Time: <1ms Result: PASS 275s START /main/utf8/ - is_valid 275s END /main/utf8/ - is_valid Time: <1ms Result: PASS 275s START /main/utils/ - quote_unescaping 275s END /main/utils/ - quote_unescaping Time: <1ms Result: PASS 275s START /main/utils/ - quote_mutation 275s END /main/utils/ - quote_mutation Time: <1ms Result: PASS 275s START /main/utils/ - crypt_test 275s END /main/utils/ - crypt_test Time: 11ms Result: PASS 275s START /main/utils/ - safe_mkdir_test 275s END /main/utils/ - safe_mkdir_test Time: <1ms Result: PASS 275s START /main/utils/ - base64_test 275s END /main/utils/ - base64_test Time: <1ms Result: PASS 275s START /main/utils/ - sha1_test 275s [test_utils.c:sha1_test:250]: Testing SHA1 ... 275s END /main/utils/ - sha1_test Time: <1ms Result: PASS 275s START /main/utils/ - md5_test 275s [test_utils.c:md5_test:205]: Testing MD5 ... 275s END /main/utils/ - md5_test Time: <1ms Result: PASS 275s START /main/utils/ - quoted_escape_test 275s END /main/utils/ - quoted_escape_test Time: <1ms Result: PASS 275s START /main/utils/ - uri_encode_decode_test 275s END /main/utils/ - uri_encode_decode_test Time: <1ms Result: PASS 275s START /main/utils/ - string_field_aggregate_test 275s [test_stringfields.c:string_field_aggregate_test:392]: Structures 3 embedded pool initialized successfully. 275s [test_stringfields.c:string_field_aggregate_test:410]: Structures 3 additional pool initialized successfully. 275s [test_stringfields.c:string_field_aggregate_test:422]: Structures 1/2 are equal as expected. 275s [test_stringfields.c:string_field_aggregate_test:430]: Structures 1/3 are different as expected. 275s [test_stringfields.c:string_field_aggregate_test:438]: Structures 2/3 are different as expected. 275s [test_stringfields.c:string_field_aggregate_test:446]: Structures 3/4 are different as expected. 275s [test_stringfields.c:string_field_aggregate_test:454]: Copying from structure 3 to structure 1 succeeded! 275s [test_stringfields.c:string_field_aggregate_test:463]: Structures 1/3 are equal as expected. 275s [test_stringfields.c:string_field_aggregate_test:470]: Structures 1/2 are different as expected. 275s [test_stringfields.c:string_field_aggregate_test:473]: Reset but don't free. 275s [test_stringfields.c:string_field_aggregate_test:484]: Structures 1/2 are the same (empty) as expected. 275s [test_stringfields.c:string_field_aggregate_test:492]: Structure 4 embedded pool is the current pool as expected. 275s [test_stringfields.c:string_field_aggregate_test:500]: Structure 4 embedded pool does not have a previous as expected. 275s END /main/utils/ - string_field_aggregate_test Time: <1ms Result: PASS 275s START /main/utils/ - string_field_test 275s [test_stringfields.c:string_field_test:79]: First things first. Let's see if we can actually allocate string fields 275s [test_stringfields.c:string_field_test:85]: All right! Successfully allocated! Now let's get down to business 275s [test_stringfields.c:string_field_test:89]: We're going to set some string fields and perform some checks 275s [test_stringfields.c:string_field_test:94]: First we're going to make sure that the strings are actually set to what we expect 275s [test_stringfields.c:string_field_test:100]: test_struct.string1 appears to be all clear. It has 'elephant' and that's what we expect 275s [test_stringfields.c:string_field_test:107]: test_struct.string2 appears to be all clear. It has 'hippopotamus' and that's what we expect 275s [test_stringfields.c:string_field_test:110]: Now let's make sure that our recorded capacities for these strings is what we expect 275s [test_stringfields.c:string_field_test:117]: string1 has the allocation area we expect: 9 275s [test_stringfields.c:string_field_test:125]: string2 has the allocation area we expect: 13 275s [test_stringfields.c:string_field_test:128]: Now we're going to shrink string1 and see if it's in the same place in memory 275s [test_stringfields.c:string_field_test:137]: string1 successfully was changed to 'rhino' 275s [test_stringfields.c:string_field_test:144]: Shrinking string1 allowed it to stay in the same place in memory 275s [test_stringfields.c:string_field_test:151]: Shrinking string1 did not change its allocation area (This is a good thing) 275s [test_stringfields.c:string_field_test:154]: Next, let's increase it a little but not all the way to its original size 275s [test_stringfields.c:string_field_test:163]: string1 successfully was changed to 'mammoth' 275s [test_stringfields.c:string_field_test:170]: Expanding string1 allowed it to stay in the same place in memory 275s [test_stringfields.c:string_field_test:177]: Expanding string1 did not change its allocation area (This is a good thing) 275s [test_stringfields.c:string_field_test:180]: Cool, now let's bring it back to its original size and see what happens 275s [test_stringfields.c:string_field_test:188]: string1 successfully changed to 'elephant' 275s [test_stringfields.c:string_field_test:195]: Restoring string1 did not cause it to move (This is a good thing) 275s [test_stringfields.c:string_field_test:202]: The allocation amount for string1 is still holding steady 275s [test_stringfields.c:string_field_test:205]: All right, now we're going to expand string 2. It should stay in place since it was the last string allocated in this pool 275s [test_stringfields.c:string_field_test:214]: string2 successfully changed to 'hippopotamus face' 275s [test_stringfields.c:string_field_test:222]: The allocation amount successfully increased for string2 when it grew 275s [test_stringfields.c:string_field_test:229]: string2 stayed in place when it grew. Good job! 275s [test_stringfields.c:string_field_test:232]: Now we're going to set string1 to a very long string so that a new string field pool must be allocated 275s [test_stringfields.c:string_field_test:241]: string1 successfully changed to 'A professional panoramic photograph of the majestic elephant bathing itself and its young by the shores of the raging Mississippi River' 275s [test_stringfields.c:string_field_test:248]: Good. Setting string1 to a long value caused it to change addresses 275s [test_stringfields.c:string_field_test:256]: The stored allocation size of string1 is what we expect 275s [test_stringfields.c:string_field_test:260]: Now using a totally separate area of memory we're going to test a basic pool freeing scenario 275s [test_stringfields.c:string_field_test:281]: Three different pools are linked as expected. 275s [test_stringfields.c:string_field_test:289]: After removing a pool the remaining two are linked as expected. 275s END /main/utils/ - string_field_test Time: <1ms Result: PASS 275s START /main/uuid/ - uuid 275s [test_uuid.c:uuid:59]: Generate UUID direct to string, got fba88814-64b0-4a6d-86ab-4bca1ce18604 275s [test_uuid.c:uuid:90]: Second generated UUID converted to string, got 584761e3-9e5a-4bfd-b0e2-ced8966ef635 275s END /main/uuid/ - uuid Time: <1ms Result: PASS 275s START /main/vector/ - basic 275s END /main/vector/ - basic Time: <1ms Result: PASS 275s START /main/vector/ - basic_integer 275s END /main/vector/ - basic_integer Time: <1ms Result: PASS 275s START /main/vector/ - callbacks 275s END /main/vector/ - callbacks Time: <1ms Result: PASS 275s START /main/vector/ - locks 275s END /main/vector/ - locks Time: <1ms Result: PASS 275s START /main/voicemail_api/ - off_nominal_msg_playback 275s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1493]: Created message in test_vm_api_1234/Old with ID 1736842895-909401725 275s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1493]: Created message in test_vm_api_1234/INBOX with ID 1736842895-960311778 275s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1493]: Created message in test_vm_api_2345/INBOX with ID 1736842895-1500739833 275s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1493]: Created message in test_vm_api_2345/INBOX with ID 1736842895-719848782 275s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1502]: Playing back message from invalid mailbox 275s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1505]: Playing back message from NULL mailbox 275s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1508]: Playing back message from invalid context 275s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1511]: Playing back message from invalid folder 275s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1514]: Playing back message from NULL folder 275s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1517]: Playing back message with invalid message specifier 275s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1520]: Playing back message with NULL message specifier 275s END /main/voicemail_api/ - off_nominal_msg_playback Time: 3ms Result: PASS 275s START /main/voicemail_api/ - nominal_msg_playback 275s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1431]: Created message in test_vm_api_1234/Old with ID 1736842895-909401725 275s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1431]: Created message in test_vm_api_1234/INBOX with ID 1736842895-960311778 275s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1431]: Created message in test_vm_api_2345/INBOX with ID 1736842895-1500739833 275s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1431]: Created message in test_vm_api_2345/INBOX with ID 1736842895-719848782 275s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1443]: Playing back message from test_vm_api_1234 to mock channel 275s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1446]: Playing back message from test_vm_api_2345 to callback function 275s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1451]: Playing back message from test_vm_api_2345 to callback function with default context 275s END /main/voicemail_api/ - nominal_msg_playback Time: 446ms Result: PASS 275s START /main/voicemail_api/ - off_nominal_forward 275s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1353]: Created message in test_vm_api_1234/Old with ID 1736842895-909401725 275s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1353]: Created message in test_vm_api_1234/INBOX with ID 1736842895-960311778 275s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1353]: Created message in test_vm_api_2345/INBOX with ID 1736842895-1500739833 275s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1353]: Created message in test_vm_api_2345/INBOX with ID 1736842895-719848782 275s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1362]: Test forwarding from an invalid mailbox 275s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1365]: Test forwarding from a NULL mailbox 275s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1368]: Test forwarding from an invalid context 275s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1371]: Test forwarding from an invalid folder 275s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1374]: Test forwarding from a NULL folder 275s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1377]: Test forwarding to an invalid mailbox 275s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1380]: Test forwarding to a NULL mailbox 275s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1383]: Test forwarding to an invalid context 275s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1386]: Test forwarding to an invalid folder 275s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1390]: Test forwarding to a NULL folder 275s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1393]: Test forwarding when no messages are select 275s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1396]: Test forwarding a message that doesn't exist 275s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1400]: Test forwarding multiple messages, where some messages don't exist 275s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1403]: Test forwarding a message with an invalid size specifier 275s END /main/voicemail_api/ - off_nominal_forward Time: 3ms Result: PASS 275s START /main/voicemail_api/ - nominal_forward 275s [test_voicemail_api.c:voicemail_api_nominal_forward:1237]: Created message in test_vm_api_1234/Old with ID 1736842895-909401725 275s [test_voicemail_api.c:voicemail_api_nominal_forward:1237]: Created message in test_vm_api_1234/INBOX with ID 1736842895-960311778 275s [test_voicemail_api.c:voicemail_api_nominal_forward:1237]: Created message in test_vm_api_2345/INBOX with ID 1736842895-1500739833 275s [test_voicemail_api.c:voicemail_api_nominal_forward:1237]: Created message in test_vm_api_2345/INBOX with ID 1736842895-719848782 275s [test_voicemail_api.c:voicemail_api_nominal_forward:1244]: Test forwarding message 0 from test_vm_api_1234 INBOX to test_vm_api_2345 INBOX 275s [test_voicemail_api.c:voicemail_api_nominal_forward:1257]: Test forwarding message 0 from test_vm_api_1234 INBOX with default context to test_vm_api_2345 INBOX 275s [test_voicemail_api.c:voicemail_api_nominal_forward:1270]: Test forwarding message 0 from test_vm_api_1234 INBOX to test_vm_api_2345 INBOX with default context 275s [test_voicemail_api.c:voicemail_api_nominal_forward:1283]: Test forwarding message 0 from test_vm_api_1234 INBOX to test_vm_api_2345 INBOX, deleting original 275s [test_voicemail_api.c:voicemail_api_nominal_forward:1296]: Test forwarding 2 messages from test_vm_api_2345 INBOX to test_vm_api_1234 INBOX[test_voicemail_api.c:voicemail_api_nominal_forward:1309]: Test forwarding 2 messages from test_vm_api_2345 INBOX to test_vm_api_1234 Family, deleting original 275s END /main/voicemail_api/ - nominal_forward Time: 12ms Result: PASS 275s START /main/voicemail_api/ - off_nominal_remove 275s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1178]: Created message in test_vm_api_1234/Old with ID 1736842895-909401725 275s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1178]: Created message in test_vm_api_1234/INBOX with ID 1736842895-960311778 275s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1178]: Created message in test_vm_api_2345/INBOX with ID 1736842895-1500739833 275s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1178]: Created message in test_vm_api_2345/INBOX with ID 1736842895-719848782 275s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1184]: Test removing a single message with an invalid mailbox 275s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1187]: Test removing a single message with a NULL mailbox 275s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1190]: Test removing a single message with an invalid context 275s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1193]: Test removing a single message with an invalid folder 275s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1196]: Test removing a single message with a NULL folder 275s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1199]: Test removing a single message with an invalid message number 275s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1203]: Test removing multiple messages with a single invalid message number 275s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1207]: Test removing no messages with no message numbers 275s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1210]: Test removing multiple messages with an invalid size specifier 275s END /main/voicemail_api/ - off_nominal_remove Time: 3ms Result: PASS 275s START /main/voicemail_api/ - nominal_remove 275s [test_voicemail_api.c:voicemail_api_nominal_remove:1131]: Created message in test_vm_api_1234/Old with ID 1736842895-909401725 275s [test_voicemail_api.c:voicemail_api_nominal_remove:1131]: Created message in test_vm_api_1234/INBOX with ID 1736842895-960311778 275s [test_voicemail_api.c:voicemail_api_nominal_remove:1131]: Created message in test_vm_api_2345/INBOX with ID 1736842895-1500739833 275s [test_voicemail_api.c:voicemail_api_nominal_remove:1131]: Created message in test_vm_api_2345/INBOX with ID 1736842895-719848782 275s [test_voicemail_api.c:voicemail_api_nominal_remove:1139]: Test removing a single message from INBOX 275s [test_voicemail_api.c:voicemail_api_nominal_remove:1142]: Test removing a single message from Old 275s [test_voicemail_api.c:voicemail_api_nominal_remove:1145]: Test removing multiple messages from INBOX 275s END /main/voicemail_api/ - nominal_remove Time: 3ms Result: PASS 275s START /main/voicemail_api/ - off_nominal_move 275s [test_voicemail_api.c:voicemail_api_off_nominal_move:1059]: Created message in test_vm_api_1234/Old with ID 1736842895-909401725 275s [test_voicemail_api.c:voicemail_api_off_nominal_move:1059]: Created message in test_vm_api_1234/INBOX with ID 1736842895-960311778 275s [test_voicemail_api.c:voicemail_api_off_nominal_move:1059]: Created message in test_vm_api_2345/INBOX with ID 1736842895-1500739833 275s [test_voicemail_api.c:voicemail_api_off_nominal_move:1059]: Created message in test_vm_api_2345/INBOX with ID 1736842895-719848782 275s [test_voicemail_api.c:voicemail_api_off_nominal_move:1068]: Test move attempt for invalid mailbox test_vm_3456 275s [test_voicemail_api.c:voicemail_api_off_nominal_move:1073]: Test move attempt for invalid context test_vm_api_defunct 275s [test_voicemail_api.c:voicemail_api_off_nominal_move:1076]: Test move attempt to invalid folder 275s [test_voicemail_api.c:voicemail_api_off_nominal_move:1079]: Test move attempt from invalid folder 275s [test_voicemail_api.c:voicemail_api_off_nominal_move:1082]: Test move attempt to NULL folder 275s [test_voicemail_api.c:voicemail_api_off_nominal_move:1085]: Test move attempt from NULL folder 275s [test_voicemail_api.c:voicemail_api_off_nominal_move:1088]: Test move attempt with non-existent message number 275s [test_voicemail_api.c:voicemail_api_off_nominal_move:1092]: Test move attempt with invalid message number 275s [test_voicemail_api.c:voicemail_api_off_nominal_move:1096]: Test move attempt with 0 number of messages 275s [test_voicemail_api.c:voicemail_api_off_nominal_move:1100]: Test move attempt with invalid number of messages 275s [test_voicemail_api.c:voicemail_api_off_nominal_move:1103]: Test move attempt with non-existent multiple messages, where some messages exist 275s END /main/voicemail_api/ - off_nominal_move Time: 3ms Result: PASS 275s START /main/voicemail_api/ - nominal_move 275s [test_voicemail_api.c:voicemail_api_nominal_move:985]: Created message in test_vm_api_1234/Old with ID 1736842895-909401725 275s [test_voicemail_api.c:voicemail_api_nominal_move:985]: Created message in test_vm_api_1234/INBOX with ID 1736842895-960311778 275s [test_voicemail_api.c:voicemail_api_nominal_move:985]: Created message in test_vm_api_2345/INBOX with ID 1736842895-1500739833 275s [test_voicemail_api.c:voicemail_api_nominal_move:985]: Created message in test_vm_api_2345/INBOX with ID 1736842895-719848782 275s [test_voicemail_api.c:voicemail_api_nominal_move:992]: Test move of test_vm_api_1234 message from INBOX to Family 275s [test_voicemail_api.c:voicemail_api_nominal_move:995]: Test move of test_vm_api_1234 message from Old to Family 275s [test_voicemail_api.c:voicemail_api_nominal_move:1009]: Test move of test_vm_api_2345 messages from Inbox to Family 275s [test_voicemail_api.c:voicemail_api_nominal_move:1020]: Test move of test_vm_api_2345 message from Family to INBOX 275s END /main/voicemail_api/ - nominal_move Time: 5ms Result: PASS 275s START /main/voicemail_api/ - off_nominal_snapshot 275s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:945]: Created message in test_vm_api_1234/Old with ID 1736842895-909401725 275s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:945]: Created message in test_vm_api_1234/INBOX with ID 1736842895-960311778 275s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:945]: Created message in test_vm_api_2345/INBOX with ID 1736842895-1500739833 275s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:945]: Created message in test_vm_api_2345/INBOX with ID 1736842895-719848782 275s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:947]: Test access to non-existent mailbox test_vm_api_3456 275s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:950]: Test access to null mailbox 275s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:953]: Test access non-existent context test_vm_api_defunct 275s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:956]: Test non-existent folder test_vm_api_platypus 275s END /main/voicemail_api/ - off_nominal_snapshot Time: 2ms Result: PASS 275s START /main/voicemail_api/ - nominal_snapshot 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:854]: Created message in test_vm_api_1234/Old with ID 1736842895-909401725 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:854]: Created message in test_vm_api_1234/INBOX with ID 1736842895-960311778 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:854]: Created message in test_vm_api_2345/INBOX with ID 1736842895-1500739833 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:854]: Created message in test_vm_api_2345/INBOX with ID 1736842895-719848782 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:856]: Test retrieving message 1 from INBOX of test_vm_1234 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:859]: Found message 1736842895-960311778 in snapshot 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:862]: Test retrieving message 0 from Old of test_vm_1234 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:865]: Found message 1736842895-909401725 in snapshot 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:868]: Test retrieving message 0, 1 from Old and INBOX of test_vm_1234 ordered by time 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:871]: Found message 1736842895-909401725 in snapshot 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:872]: Found message 1736842895-960311778 in snapshot 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:875]: Test retrieving message 1, 0 from Old and INBOX of test_vm_1234 ordered by time desc 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:878]: Found message 1736842895-960311778 in snapshot 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:879]: Found message 1736842895-909401725 in snapshot 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:882]: Test retrieving message 0, 1 from Old and INBOX of test_vm_1234 ordered by id 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:885]: Found message 1736842895-960311778 in snapshot 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:886]: Found message 1736842895-909401725 in snapshot 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:889]: Test retrieving message 1, 0 from Old and INBOX of test_vm_1234 ordered by id desc 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:892]: Found message 1736842895-909401725 in snapshot 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:893]: Found message 1736842895-960311778 in snapshot 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:896]: Test retrieving message 0, 1 from all folders of test_vm_1234 ordered by id 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:899]: Found message 1736842895-909401725 in snapshot 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:900]: Found message 1736842895-960311778 in snapshot 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:903]: Test retrieving message 0, 1 from all folders of test_vm_1234 ordered by time 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:906]: Found message 1736842895-909401725 in snapshot 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:907]: Found message 1736842895-960311778 in snapshot 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:910]: Test retrieving message 0, 1 from all folders of test_vm_1234, default context ordered by time 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:913]: Found message 1736842895-909401725 in snapshot 275s [test_voicemail_api.c:voicemail_api_nominal_snapshot:914]: Found message 1736842895-960311778 in snapshot 275s END /main/voicemail_api/ - nominal_snapshot Time: 7ms Result: PASS 275s START /main/xml_escape/ - xml_escape_test 275s END /main/xml_escape/ - xml_escape_test Time: <1ms Result: PASS 275s START /mwi/ - explicit_publish 275s END /mwi/ - explicit_publish Time: 20ms Result: PASS 275s START /mwi/ - implicit_publish 275s END /mwi/ - implicit_publish Time: 20ms Result: PASS 275s START /res/adsi/ - adsi_loaded_test 275s END /res/adsi/ - adsi_loaded_test Time: <1ms Result: PASS 275s START /res/aeap/ - send_msg_handle_request 275s END /res/aeap/ - send_msg_handle_request Time: <1ms Result: PASS 275s START /res/aeap/ - send_msg_handle_response 275s END /res/aeap/ - send_msg_handle_response Time: <1ms Result: PASS 275s START /res/aeap/ - send_msg_handle_string 277s END /res/aeap/ - send_msg_handle_string Time: 1999ms Result: PASS 277s START /res/aeap/ - create_and_connect 277s END /res/aeap/ - create_and_connect Time: <1ms Result: PASS 277s START /res/aeap/speech/ - res_speech_aeap_test 277s END /res/aeap/speech/ - res_speech_aeap_test Time: <1ms Result: PASS 277s START /res/aeap/transaction/ - transaction_exec_timeout 277s END /res/aeap/transaction/ - transaction_exec_timeout Time: 99ms Result: PASS 277s START /res/aeap/transaction/ - transaction_exec 278s END /res/aeap/transaction/ - transaction_exec Time: 1000ms Result: PASS 278s START /res/aeap/transport/ - transport_create_invalid 278s END /res/aeap/transport/ - transport_create_invalid Time: <1ms Result: PASS 278s START /res/aeap/transport/ - transport_create 278s END /res/aeap/transport/ - transport_create Time: <1ms Result: PASS 278s START /res/aeap/transport/ - transport_connect 278s END /res/aeap/transport/ - transport_connect Time: <1ms Result: PASS 278s START /res/aeap/transport/ - transport_connect_fail 278s END /res/aeap/transport/ - transport_connect_fail Time: <1ms Result: PASS 278s START /res/aeap/transport/ - transport_binary 278s END /res/aeap/transport/ - transport_binary Time: <1ms Result: PASS 278s START /res/aeap/transport/ - transport_string 278s END /res/aeap/transport/ - transport_string Time: <1ms Result: PASS 278s START /res/agi/ - agi_loaded_test 278s END /res/agi/ - agi_loaded_test Time: <1ms Result: PASS 278s START /res/agi/ - null_agi_docs 278s END /res/agi/ - null_agi_docs Time: <1ms Result: PASS 278s START /res/ari/ - invoke_not_found 278s END /res/ari/ - invoke_not_found Time: <1ms Result: PASS 278s START /res/ari/ - invoke_bad_post 278s END /res/ari/ - invoke_bad_post Time: <1ms Result: PASS 278s START /res/ari/ - invoke_post 278s END /res/ari/ - invoke_post Time: <1ms Result: PASS 278s START /res/ari/ - invoke_delete 278s END /res/ari/ - invoke_delete Time: <1ms Result: PASS 278s START /res/ari/ - invoke_wildcard 278s END /res/ari/ - invoke_wildcard Time: <1ms Result: PASS 278s START /res/ari/ - invoke_get 278s END /res/ari/ - invoke_get Time: <1ms Result: PASS 278s START /res/ari/ - get_docs_hackerz 278s END /res/ari/ - get_docs_hackerz Time: <1ms Result: PASS 278s START /res/ari/ - get_docs_notfound 278s END /res/ari/ - get_docs_notfound Time: <1ms Result: PASS 278s START /res/ari/ - get_docs_nohost 278s END /res/ari/ - get_docs_nohost Time: <1ms Result: PASS 278s START /res/ari/ - get_docs 278s END /res/ari/ - get_docs Time: <1ms Result: PASS 278s START /res/crypto/ - crypto_loaded_test 278s END /res/crypto/ - crypto_loaded_test Time: <1ms Result: PASS 278s START /res/http_media_cache/ - retrieve_content_type 278s END /res/http_media_cache/ - retrieve_content_type Time: 1ms Result: PASS 278s START /res/http_media_cache/ - retrieve_parsed_uri 278s END /res/http_media_cache/ - retrieve_parsed_uri Time: <1ms Result: PASS 278s START /res/http_media_cache/ - retrieve_cache_control_directives 278s [test_http_media_cache.c:retrieve_cache_control_directives:322]: Testing no-cache... 278s [test_http_media_cache.c:retrieve_cache_control_directives:329]: Testing no-cache with ETag... 278s [test_http_media_cache.c:retrieve_cache_control_directives:339]: Testing no-cache with max-age... 278s [test_http_media_cache.c:retrieve_cache_control_directives:344]: Checking 1736843201 >= 1736843198 and 1736843195 <= 1736843198 278s [test_http_media_cache.c:retrieve_cache_control_directives:351]: Testing must-revalidate... 278s [test_http_media_cache.c:retrieve_cache_control_directives:358]: Testing must-revalidate with ETag... 278s [test_http_media_cache.c:retrieve_cache_control_directives:368]: Testing must-revalidate with max-age... 278s [test_http_media_cache.c:retrieve_cache_control_directives:373]: Checking 1736843201 >= 1736843198 and 1736843195 <= 1736843198 278s END /res/http_media_cache/ - retrieve_cache_control_directives Time: 1ms Result: PASS 278s START /res/http_media_cache/ - retrieve_cache_control_age 278s [test_http_media_cache.c:retrieve_cache_control_age:406]: Testing max-age... 278s [test_http_media_cache.c:retrieve_cache_control_age:410]: Checking 1736843201 >= 1736843198 and 1736843195 <= 1736843198 278s [test_http_media_cache.c:retrieve_cache_control_age:414]: Testing s-maxage... 278s [test_http_media_cache.c:retrieve_cache_control_age:420]: Checking 1736843201 >= 1736843198 and 1736843195 <= 1736843198 278s [test_http_media_cache.c:retrieve_cache_control_age:424]: Testing max-age and s-maxage... 278s [test_http_media_cache.c:retrieve_cache_control_age:430]: Checking 1736843501 >= 1736843498 and 1736843495 <= 1736843498 278s [test_http_media_cache.c:retrieve_cache_control_age:434]: Testing max-age and Expires... 278s [test_http_media_cache.c:retrieve_cache_control_age:441]: Checking 1736843201 >= 1736843198 and 1736843195 <= 1736843198 278s [test_http_media_cache.c:retrieve_cache_control_age:445]: Testing s-maxage and Expires... 278s [test_http_media_cache.c:retrieve_cache_control_age:452]: Checking 1736843201 >= 1736843198 and 1736843195 <= 1736843198 278s [test_http_media_cache.c:retrieve_cache_control_age:456]: Testing s-maxage and Expires... 278s [test_http_media_cache.c:retrieve_cache_control_age:463]: Checking 1736843201 >= 1736843198 and 1736843195 <= 1736843198 278s [test_http_media_cache.c:retrieve_cache_control_age:467]: Testing max-age, s-maxage, and Expires... 278s [test_http_media_cache.c:retrieve_cache_control_age:474]: Checking 1736843501 >= 1736843498 and 1736843495 <= 1736843498 278s END /res/http_media_cache/ - retrieve_cache_control_age Time: 1ms Result: PASS 278s START /res/http_media_cache/ - retrieve_etag_expired 278s [test_http_media_cache.c:retrieve_etag_expired:514]: Checking 1736842900 >= 1736842897 and 1736842894 <= 1736842897 278s END /res/http_media_cache/ - retrieve_etag_expired Time: <1ms Result: PASS 278s START /res/http_media_cache/ - retrieve_expires 278s [test_http_media_cache.c:retrieve_expires:554]: Checking 1736845901 >= 1736845898 and 1736845895 <= 1736845898 278s [test_http_media_cache.c:retrieve_expires:564]: Checking 1736842900 >= 1736842897 and 1736842894 <= 1736842897 278s END /res/http_media_cache/ - retrieve_expires Time: <1ms Result: PASS 278s START /res/http_media_cache/ - retrieve_etag 278s [test_http_media_cache.c:retrieve_etag:604]: Checking 1736842901 >= 1736842898 and 1736842895 <= 1736842898 278s END /res/http_media_cache/ - retrieve_etag Time: <1ms Result: PASS 278s START /res/http_media_cache/ - retrieve_nominal 278s [test_http_media_cache.c:retrieve_nominal:642]: Checking 1736842901 >= 1736842898 and 1736842895 <= 1736842898 278s END /res/http_media_cache/ - retrieve_nominal Time: <1ms Result: PASS 278s START /res/http_media_cache/ - create_nominal 278s [test_http_media_cache.c:create_nominal:675]: Checking 1736842901 >= 1736842898 and 1736842895 <= 1736842898 278s END /res/http_media_cache/ - create_nominal Time: <1ms Result: PASS 278s START /res/parking/ - dynamic_parking_variables 278s [parking/parking_tests.c:dynamic_parking_variables:756]: Creating expected configuration for dynamic parking lot 278s [parking/parking_tests.c:dynamic_parking_variables:775]: Creating template lot 278s [parking/parking_tests.c:dynamic_parking_variables:784]: Creating Alice channel to test dynamic parking lot creation. 278s [parking/parking_tests.c:dynamic_parking_variables:794]: Setting Dynamic Parking channel variables on Alice. 278s [parking/parking_tests.c:dynamic_parking_variables:802]: Generating dynamic parking lot based on Alice's channel variables. 278s [parking/parking_tests.c:dynamic_parking_variables:819]: Dynamic parking lot created successfully and matches expectations. Test passed. 278s END /res/parking/ - dynamic_parking_variables Time: <1ms Result: PASS 278s START /res/parking/ - extension_conflicts 278s [parking/parking_tests.c:extension_conflicts:597]: Creating the base lot. This should pass. 278s [parking/parking_tests.c:extension_conflicts:607]: Creating a test lot which will overlap. 278s [parking/parking_tests.c:generate_test_parking_lot:161]: Extensions for parking lot 'unit_tests_res_parking_test_lot_fail1' could not be registered. Extension Creation failed. 278s [parking/parking_tests.c:generate_test_parking_lot:161]: Extensions for parking lot 'unit_tests_res_parking_test_lot_fail2' could not be registered. Extension Creation failed. 278s [parking/parking_tests.c:generate_test_parking_lot:161]: Extensions for parking lot 'unit_tests_res_parking_test_lot_fail3' could not be registered. Extension Creation failed. 278s [parking/parking_tests.c:generate_test_parking_lot:161]: Extensions for parking lot 'unit_tests_res_parking_test_lot_fail4' could not be registered. Extension Creation failed. 278s END /res/parking/ - extension_conflicts Time: <1ms Result: PASS 278s START /res/parking/ - park_extensions 278s [parking/parking_tests.c:park_extensions:551]: Extensions for the test parking lot were verified. Cleaning up and verifying their removal. 278s [parking/parking_tests.c:park_extensions:565]: Extensions for the test parking lot verified as removed. Test completed successfully. 278s END /res/parking/ - park_extensions Time: <1ms Result: PASS 278s START /res/parking/ - park_retrieve 278s [parking/parking_tests.c:retrieve_call:405]: Creating test parking lot 'unit_tests_res_parking_test_lot' 279s [parking/parking_tests.c:retrieve_call:446]: Successfully retrieved parked user from the parking lot. Validating user data. 279s END /res/parking/ - park_retrieve Time: 1000ms Result: PASS 279s START /res/parking/ - park_channel 279s [parking/parking_tests.c:park_call:254]: Creating test parking lot 'unit_tests_res_parking_test_lot' 280s END /res/parking/ - park_channel Time: 1000ms Result: PASS 280s START /res/parking/ - create_lot 280s [parking/parking_tests.c:create_lot:206]: Creating test parking lot 'unit_tests_res_parking_test_lot' 280s [parking/parking_tests.c:create_lot:214]: Successfully created parking lot. Retrieving test parking lot from container. 280s [parking/parking_tests.c:create_lot:223]: Successfully retrieved parking lot. Removing test parking lot from container. 280s [parking/parking_tests.c:create_lot:229]: Parking lot was successfully removed from the container. Test complete. 280s END /res/parking/ - create_lot Time: <1ms Result: PASS 280s START /res/prometheus/ - bridge_to_string 280s [test_res_prometheus.c:bridge_to_string:760]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 280s # TYPE asterisk_channels_count gauge 280s asterisk_channels_count{eid="fa:16:3e:a2:96:ec"} 0 280s # HELP asterisk_calls_sum Total call count. 280s # TYPE asterisk_calls_sum counter 280s asterisk_calls_sum{eid="fa:16:3e:a2:96:ec"} 0 280s # HELP asterisk_calls_count Current call count. 280s # TYPE asterisk_calls_count gauge 280s asterisk_calls_count{eid="fa:16:3e:a2:96:ec"} 0 280s # HELP asterisk_endpoints_count Current endpoint count. 280s # TYPE asterisk_endpoints_count gauge 280s asterisk_endpoints_count{eid="fa:16:3e:a2:96:ec"} 0 280s # HELP asterisk_bridges_count Current bridge count. 280s # TYPE asterisk_bridges_count gauge 280s asterisk_bridges_count{eid="fa:16:3e:a2:96:ec"} 3 280s # HELP asterisk_bridges_channels_count Number of channels in the bridge. 280s # TYPE asterisk_bridges_channels_count gauge 280s asterisk_bridges_channels_count{eid="fa:16:3e:a2:96:ec",id="8aa0cb3c-2a5a-4820-af72-78783a6eb085",tech="simple_bridge",subclass="basic",creator="",name=""} 0 280s asterisk_bridges_channels_count{eid="fa:16:3e:a2:96:ec",id="e36ecb9d-bd93-47d6-bfac-5d5469d9d5cb",tech="simple_bridge",subclass="basic",creator="",name=""} 0 280s 280s END /res/prometheus/ - bridge_to_string Time: <1ms Result: PASS 280s START /res/prometheus/ - config_general_core_metrics 280s [test_res_prometheus.c:config_general_core_metrics:680]: -> CURLing request... 280s [test_res_prometheus.c:config_general_core_metrics:688]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 280s # TYPE asterisk_channels_count gauge 280s asterisk_channels_count{eid="fa:16:3e:a2:96:ec"} 0 280s # HELP asterisk_calls_sum Total call count. 280s # TYPE asterisk_calls_sum counter 280s asterisk_calls_sum{eid="fa:16:3e:a2:96:ec"} 0 280s # HELP asterisk_calls_count Current call count. 280s # TYPE asterisk_calls_count gauge 280s asterisk_calls_count{eid="fa:16:3e:a2:96:ec"} 0 280s # HELP asterisk_endpoints_count Current endpoint count. 280s # TYPE asterisk_endpoints_count gauge 280s asterisk_endpoints_count{eid="fa:16:3e:a2:96:ec"} 0 280s # HELP asterisk_bridges_count Current bridge count. 280s # TYPE asterisk_bridges_count gauge 280s asterisk_bridges_count{eid="fa:16:3e:a2:96:ec"} 0 280s # HELP asterisk_core_properties Asterisk instance properties. The value of this will always be 1. 280s # TYPE asterisk_core_properties counter 280s asterisk_core_properties{eid="fa:16:3e:a2:96:ec",version="22.1.0~dfsg+~cs6.14.60671435-1",build_options="OPTIONAL_API, TEST_FRAMEWORK",build_date="2024-11-27 11:37:42 UTC",build_os="Linux",build_kernel="unknown",build_host="buildd.debian.org"} 1 280s # HELP asterisk_core_uptime_seconds Asterisk instance uptime in seconds. 280s # TYPE asterisk_core_uptime_seconds counter 280s asterisk_core_uptime_seconds{eid="fa:16:3e:a2:96:ec"} 84 280s # HELP asterisk_core_last_reload_seconds Time since last Asterisk reload in seconds. 280s # TYPE asterisk_core_last_reload_seconds counter 280s asterisk_core_last_reload_seconds{eid="fa:16:3e:a2:96:ec"} 84 280s # HELP asterisk_core_scrape_time_ms Total time taken to collect metrics, in milliseconds 280s # TYPE asterisk_core_scrape_time_ms counter 280s asterisk_core_scrape_time_ms{eid="fa:16:3e:a2:96:ec"} 0 280s 280s [test_res_prometheus.c:config_general_core_metrics:690]: -> Checking for core properties 280s [test_res_prometheus.c:config_general_core_metrics:693]: -> Checking for uptime 280s [test_res_prometheus.c:config_general_core_metrics:696]: -> Checking for last reload 280s [test_res_prometheus.c:config_general_core_metrics:699]: -> Checking for scrape time 280s END /res/prometheus/ - config_general_core_metrics Time: <1ms Result: PASS 280s START /res/prometheus/ - config_general_basic_auth 280s [test_res_prometheus.c:config_general_basic_auth:555]: Testing without auth credentials 280s [test_res_prometheus.c:config_general_basic_auth:556]: -> CURLing request... 280s [test_res_prometheus.c:config_general_basic_auth:563]: -> CURL returned 401 280s [test_res_prometheus.c:config_general_basic_auth:566]: Testing with invalid auth credentials 280s [test_res_prometheus.c:config_general_basic_auth:567]: -> CURLing request... 280s [test_res_prometheus.c:config_general_basic_auth:576]: -> CURL returned 401 280s [test_res_prometheus.c:config_general_basic_auth:579]: Testing with valid auth credentials 280s [test_res_prometheus.c:config_general_basic_auth:580]: -> CURLing request... 280s [test_res_prometheus.c:config_general_basic_auth:588]: -> CURL returned 200 280s END /res/prometheus/ - config_general_basic_auth Time: <1ms Result: PASS 280s START /res/prometheus/ - config_general_enabled 280s [test_res_prometheus.c:config_general_enabled:628]: -> CURLing request... 280s [test_res_prometheus.c:config_general_enabled:635]: -> CURL returned 503 280s END /res/prometheus/ - config_general_enabled Time: <1ms Result: PASS 280s START /res/prometheus/ - gauge_create 280s END /res/prometheus/ - gauge_create Time: <1ms Result: PASS 280s START /res/prometheus/ - gauge_to_string 280s END /res/prometheus/ - gauge_to_string Time: <1ms Result: PASS 280s START /res/prometheus/ - counter_create 280s END /res/prometheus/ - counter_create Time: <1ms Result: PASS 280s START /res/prometheus/ - counter_to_string 280s END /res/prometheus/ - counter_to_string Time: <1ms Result: PASS 280s START /res/prometheus/ - metric_register 280s [test_res_prometheus.c:metric_register:291]: Testing nominal registration 280s [test_res_prometheus.c:metric_register:292]: -> Static metric 280s [test_res_prometheus.c:metric_register:294]: -> Malloc'd metric 280s [test_res_prometheus.c:metric_register:300]: Testing nominal registration of child metrics 280s [test_res_prometheus.c:metric_register:315]: Testing name collisions 280s [test_res_prometheus.c:metric_register:322]: Testing label collisions 280s [test_res_prometheus.c:metric_register:331]: Testing removal of metrics 280s END /res/prometheus/ - metric_register Time: <1ms Result: PASS 280s START /res/prometheus/ - metric_callback_register 280s [test_res_prometheus.c:metric_callback_register:241]: -> CURLing request... 280s [test_res_prometheus.c:metric_callback_register:250]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 280s # TYPE asterisk_channels_count gauge 280s asterisk_channels_count{eid="fa:16:3e:a2:96:ec"} 0 280s # HELP asterisk_calls_sum Total call count. 280s # TYPE asterisk_calls_sum counter 280s asterisk_calls_sum{eid="fa:16:3e:a2:96:ec"} 0 280s # HELP asterisk_calls_count Current call count. 280s # TYPE asterisk_calls_count gauge 280s asterisk_calls_count{eid="fa:16:3e:a2:96:ec"} 0 280s # HELP asterisk_endpoints_count Current endpoint count. 280s # TYPE asterisk_endpoints_count gauge 280s asterisk_endpoints_count{eid="fa:16:3e:a2:96:ec"} 0 280s # HELP asterisk_bridges_count Current bridge count. 280s # TYPE asterisk_bridges_count gauge 280s asterisk_bridges_count{eid="fa:16:3e:a2:96:ec"} 0 280s # HELP test_counter A test counter 280s # TYPE test_counter counter 280s test_counter 0 280s 280s END /res/prometheus/ - metric_callback_register Time: <1ms Result: PASS 280s START /res/prometheus/ - metric_values 280s [test_res_prometheus.c:metric_values:166]: -> CURLing request... 280s [test_res_prometheus.c:metric_values:176]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 280s # TYPE asterisk_channels_count gauge 280s asterisk_channels_count{eid="fa:16:3e:a2:96:ec"} 0 280s # HELP asterisk_calls_sum Total call count. 280s # TYPE asterisk_calls_sum counter 280s asterisk_calls_sum{eid="fa:16:3e:a2:96:ec"} 0 280s # HELP asterisk_calls_count Current call count. 280s # TYPE asterisk_calls_count gauge 280s asterisk_calls_count{eid="fa:16:3e:a2:96:ec"} 0 280s # HELP asterisk_endpoints_count Current endpoint count. 280s # TYPE asterisk_endpoints_count gauge 280s asterisk_endpoints_count{eid="fa:16:3e:a2:96:ec"} 0 280s # HELP asterisk_bridges_count Current bridge count. 280s # TYPE asterisk_bridges_count gauge 280s asterisk_bridges_count{eid="fa:16:3e:a2:96:ec"} 0 280s # HELP test_counter_one A test counter 280s # TYPE test_counter_one counter 280s test_counter_one 1 280s # HELP test_counter_two A test counter 280s # TYPE test_counter_two counter 280s test_counter_two 2 280s 280s END /res/prometheus/ - metric_values Time: <1ms Result: PASS 280s START /res/res_crypto/ - crypto_aes_decrypt 280s [test_crypto.c:crypto_aes_decrypt:607]: Executing AES-ECB decryption test 280s END /res/res_crypto/ - crypto_aes_decrypt Time: 11ms Result: PASS 280s START /res/res_crypto/ - crypto_aes_encrypt 280s [test_crypto.c:crypto_aes_encrypt:531]: Executing AES-ECB encryption test 280s END /res/res_crypto/ - crypto_aes_encrypt Time: 6ms Result: PASS 280s START /res/res_crypto/ - crypto_verify 280s [test_crypto.c:crypto_verify:425]: Executing RSA signature verification test 280s [test_crypto.c:crypto_verify:456]: Couldn't read key: rsa_key1 280s END /res/res_crypto/ - crypto_verify Time: <1ms Result: FAIL 280s START /res/res_crypto/ - crypto_sign 280s [test_crypto.c:crypto_sign:306]: Executing RSA signing test 280s [test_crypto.c:crypto_sign:341]: Couldn't read key: rsa_key1 280s END /res/res_crypto/ - crypto_sign Time: <1ms Result: FAIL 280s START /res/res_crypto/ - crypto_decrypt_pub_key 280s [test_crypto.c:crypto_rsa_decrypt:203]: Executing RSA decryption test 280s [test_crypto.c:crypto_rsa_decrypt:231]: Couldn't read key: rsa_key1 280s END /res/res_crypto/ - crypto_decrypt_pub_key Time: <1ms Result: FAIL 280s START /res/res_crypto/ - crypto_rsa_encrypt 280s [test_crypto.c:crypto_rsa_encrypt:107]: Executing RSA encryption test 280s [test_crypto.c:crypto_rsa_encrypt:138]: Couldn't read key: rsa_key1 280s END /res/res_crypto/ - crypto_rsa_encrypt Time: <1ms Result: FAIL 280s START /res/res_pjproject/ - ast_sockaddr_from_pj_sockaddr_test 280s END /res/res_pjproject/ - ast_sockaddr_from_pj_sockaddr_test Time: <1ms Result: PASS 280s START /res/res_pjproject/ - ast_sockaddr_to_pj_sockaddr_test 280s END /res/res_pjproject/ - ast_sockaddr_to_pj_sockaddr_test Time: <1ms Result: PASS 280s START /res/res_pjsip/ - xml_sanitization_exceeds_buffer 280s END /res/res_pjsip/ - xml_sanitization_exceeds_buffer Time: <1ms Result: PASS 280s START /res/res_pjsip/ - xml_sanitization_end_null 280s END /res/res_pjsip/ - xml_sanitization_end_null Time: <1ms Result: PASS 280s START /res/res_pjsip/scheduler/ - scheduler_policy 280s [test_res_pjsip_scheduler.c:scheduler_policy:355]: This test will take about 4.5 seconds 285s END /res/res_pjsip/scheduler/ - scheduler_policy Time: 4499ms Result: PASS 285s START /res/res_pjsip/scheduler/ - scheduler_cancel 285s [test_res_pjsip_scheduler.c:scheduler_cancel:301]: This test will take about 1.5 seconds 286s END /res/res_pjsip/scheduler/ - scheduler_cancel Time: 1500ms Result: PASS 286s START /res/res_pjsip/scheduler/ - scheduler_cleanup 286s [test_res_pjsip_scheduler.c:scheduler_cleanup:250]: This test will take about 1.6 seconds 288s END /res/res_pjsip/scheduler/ - scheduler_cleanup Time: 1600ms Result: PASS 288s START /res/res_pjsip/scheduler/ - unserialized_scheduler 288s [test_res_pjsip_scheduler.c:scheduler:136]: This test will take about 3.0 seconds 291s END /res/res_pjsip/scheduler/ - unserialized_scheduler Time: 2999ms Result: PASS 291s START /res/res_pjsip/scheduler/ - serialized_scheduler 291s [test_res_pjsip_scheduler.c:scheduler:131]: This test will take about 4.0 seconds 295s END /res/res_pjsip/scheduler/ - serialized_scheduler Time: 3999ms Result: PASS 295s START /res/res_pjsip_pubsub/ - bad_event 295s END /res/res_pjsip_pubsub/ - bad_event Time: <1ms Result: PASS 295s START /res/res_pjsip_pubsub/ - loop 295s END /res/res_pjsip_pubsub/ - loop Time: <1ms Result: PASS 295s START /res/res_pjsip_pubsub/ - duplicate_resource 295s END /res/res_pjsip_pubsub/ - duplicate_resource Time: <1ms Result: PASS 295s START /res/res_pjsip_pubsub/ - bad_branch 295s END /res/res_pjsip_pubsub/ - bad_branch Time: <1ms Result: PASS 295s START /res/res_pjsip_pubsub/ - bad_resource 295s END /res/res_pjsip_pubsub/ - bad_resource Time: <1ms Result: PASS 295s START /res/res_pjsip_pubsub/ - complex_resource_tree 295s END /res/res_pjsip_pubsub/ - complex_resource_tree Time: <1ms Result: PASS 295s START /res/res_pjsip_pubsub/ - resource_tree 295s END /res/res_pjsip_pubsub/ - resource_tree Time: <1ms Result: PASS 295s START /res/res_pjsip_session/ - merge_refresh_topologies 295s [res_pjsip_session.c:test_resolve_refresh_media_states:5892]: Test 1 passed 295s [res_pjsip_session.c:test_resolve_refresh_media_states:5912]: Test 2 passed 295s [res_pjsip_session.c:test_resolve_refresh_media_states:5936]: Test 3 passed 295s [res_pjsip_session.c:test_resolve_refresh_media_states:5955]: Test 4 passed 295s [res_pjsip_session.c:test_resolve_refresh_media_states:5973]: Test 5 passed 295s [res_pjsip_session.c:test_resolve_refresh_media_states:5994]: Test 6 passed 295s [res_pjsip_session.c:test_resolve_refresh_media_states:6020]: Test 7 passed 295s [res_pjsip_session.c:test_resolve_refresh_media_states:6041]: Test 8 passed 295s [res_pjsip_session.c:test_resolve_refresh_media_states:6061]: Test 9 passed 295s [res_pjsip_session.c:test_resolve_refresh_media_states:6081]: Test 10 passed 295s [res_pjsip_session.c:test_resolve_refresh_media_states:6104]: Test 11 passed 295s [res_pjsip_session.c:test_resolve_refresh_media_states:6129]: Test 12 passed 295s [res_pjsip_session.c:test_resolve_refresh_media_states:6163]: Test 13 passed 295s [res_pjsip_session.c:test_resolve_refresh_media_states:6187]: Test 14 passed 295s [res_pjsip_session.c:test_resolve_refresh_media_states:6211]: Test 15 passed 295s END /res/res_pjsip_session/ - merge_refresh_topologies Time: <1ms Result: PASS 295s START /res/res_pjsip_session/caps/ - low_level 295s [test_res_pjsip_session_caps.c:low_level:134]: Testing incoming expected pass 295s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (ulaw,alaw,g722), remote: (g722,alaw,g729), pref: (local ), outgoing: (no ), expected: (alaw,g722) expected result: (PASS) 295s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (ulaw,alaw,g722), remote: (g722,alaw,g729), pref: (local_first ), outgoing: (no ), expected: (alaw) expected result: (PASS) 295s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (slin), remote: (all), pref: (local ), outgoing: (no ), expected: (slin) expected result: (PASS) 295s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (ulaw,alaw,g722), remote: (g722,alaw,g729), pref: (remote ), outgoing: (no ), expected: (g722,alaw) expected result: (PASS) 295s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (ulaw,alaw,g722), remote: (g722,alaw,g729), pref: (remote_first), outgoing: (no ), expected: (g722) expected result: (PASS) 295s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (all), remote: (slin), pref: (remote_first), outgoing: (no ), expected: (slin) expected result: (PASS) 295s [test_res_pjsip_session_caps.c:low_level:142]: Testing incoming expected fail 295s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (ulaw,alaw,g722), remote: (g729), pref: (local ), outgoing: (no ), expected: () expected result: (FAIL) 295s [test_res_pjsip_session_caps.c:test_create_joint:102]: Expected Failure: Expected: () Actual: (nothing) 295s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (ulaw,alaw,g722), remote: (g722,alaw,g729), pref: (local_merge ), outgoing: (no ), expected: () expected result: (FAIL) 295s [test_res_pjsip_session_caps.c:test_create_joint:81]: Expected Failure: Invalid preference string incoming/outgoing combination. 295s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (ulaw,alaw,g722), remote: (g722,alaw,g729), pref: (remote_merge), outgoing: (no ), expected: () expected result: (FAIL) 295s [test_res_pjsip_session_caps.c:test_create_joint:81]: Expected Failure: Invalid preference string incoming/outgoing combination. 295s [test_res_pjsip_session_caps.c:low_level:147]: Testing outgoing expected pass 295s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (ulaw,alaw,g722), remote: (g722,g729,alaw), pref: (local ), outgoing: (yes), expected: (alaw,g722) expected result: (PASS) 295s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (ulaw,alaw,g722), remote: (g722,g729,alaw), pref: (local_first ), outgoing: (yes), expected: (alaw) expected result: (PASS) 295s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (ulaw,alaw,g722), remote: (g722,g729,alaw), pref: (local_merge ), outgoing: (yes), expected: (ulaw,alaw,g722) expected result: (PASS) 295s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (ulaw,alaw,g722), remote: (g722,g729,alaw), pref: (remote ), outgoing: (yes), expected: (g722,alaw) expected result: (PASS) 295s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (ulaw,alaw,g722), remote: (g722,g729,alaw), pref: (remote_first), outgoing: (yes), expected: (g722) expected result: (PASS) 295s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (ulaw,alaw,g722), remote: (g722,g729,alaw), pref: (remote_merge), outgoing: (yes), expected: (g722,alaw,ulaw) expected result: (PASS) 295s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (!all), remote: (g722,g729,alaw), pref: (remote_merge), outgoing: (yes), expected: (nothing) expected result: (PASS) 295s END /res/res_pjsip_session/caps/ - low_level Time: <1ms Result: PASS 295s START /res/res_resolver_unbound/ - resolve_srv 295s END /res/res_resolver_unbound/ - resolve_srv Time: 2ms Result: PASS 295s START /res/res_resolver_unbound/ - resolve_naptr 295s END /res/res_resolver_unbound/ - resolve_naptr Time: <1ms Result: PASS 295s START /res/res_resolver_unbound/ - resolve_cancel_off_nominal 295s END /res/res_resolver_unbound/ - resolve_cancel_off_nominal Time: 83ms Result: PASS 295s START /res/res_resolver_unbound/ - resolve_async_off_nominal 295s [res_resolver_unbound.c:off_nominal_async_run:1004]: Performing DNS query 'duck.feathers', type 1 295s [res_resolver_unbound.c:off_nominal_async_run:1004]: Performing DNS query 'goose.feathers', type 28 295s [res_resolver_unbound.c:off_nominal_async_run:1004]: Performing DNS query 'goose.feathers', type 1 295s [res_resolver_unbound.c:off_nominal_async_run:1004]: Performing DNS query '.1', type 1 295s [res_resolver_unbound.c:off_nominal_async_run:1004]: Performing DNS query '.www', type 1 295s [res_resolver_unbound.c:off_nominal_async_run:1004]: Performing DNS query '.1', type 12 295s [res_resolver_unbound.c:off_nominal_async_run:1004]: Performing DNS query '.www', type 12 295s END /res/res_resolver_unbound/ - resolve_async_off_nominal Time: <1ms Result: PASS 295s START /res/res_resolver_unbound/ - resolve_sync_off_nominal 295s END /res/res_resolver_unbound/ - resolve_sync_off_nominal Time: <1ms Result: PASS 295s START /res/res_resolver_unbound/ - resolve_async 295s [res_resolver_unbound.c:nominal_async_run:721]: Performing DNS query 'goose.feathers', type 1 295s [res_resolver_unbound.c:nominal_async_run:721]: Performing DNS query 'goose.feathers', type 28 295s [res_resolver_unbound.c:nominal_async_run:721]: Performing DNS query 'duck.feathers', type 1 295s END /res/res_resolver_unbound/ - resolve_async Time: <1ms Result: PASS 295s START /res/res_resolver_unbound/ - resolve_sync 295s [res_resolver_unbound.c:nominal_sync_run:571]: Performing DNS query 'goose.feathers', type 1 295s [res_resolver_unbound.c:nominal_sync_run:571]: Performing DNS query 'goose.feathers', type 28 295s [res_resolver_unbound.c:nominal_sync_run:571]: Performing DNS query 'duck.feathers', type 1 295s END /res/res_resolver_unbound/ - resolve_sync Time: <1ms Result: PASS 295s START /res/res_rtp/ - fir_nominal 295s END /res/res_rtp/ - fir_nominal Time: <1ms Result: PASS 295s START /res/res_rtp/ - sr_rr_nominal 295s END /res/res_rtp/ - sr_rr_nominal Time: <1ms Result: PASS 295s START /res/res_rtp/ - remb_nominal 295s END /res/res_rtp/ - remb_nominal Time: <1ms Result: PASS 295s START /res/res_rtp/ - lost_packet_stats_nominal 295s END /res/res_rtp/ - lost_packet_stats_nominal Time: <1ms Result: PASS 295s START /res/res_rtp/ - nack_overflow 295s END /res/res_rtp/ - nack_overflow Time: <1ms Result: PASS 295s START /res/res_rtp/ - nack_nominal 295s END /res/res_rtp/ - nack_nominal Time: <1ms Result: PASS 295s START /res/res_rtp/ - nack_no_packet_loss 295s END /res/res_rtp/ - nack_no_packet_loss Time: <1ms Result: PASS 295s START /res/res_sorcery_memory_cache/ - full_backend_cache_stale 310s END /res/res_sorcery_memory_cache/ - full_backend_cache_stale Time: 15000ms Result: PASS 310s START /res/res_sorcery_memory_cache/ - full_backend_cache_expiration 315s END /res/res_sorcery_memory_cache/ - full_backend_cache_expiration Time: 5000ms Result: PASS 315s START /res/res_sorcery_memory_cache/ - expiration 320s END /res/res_sorcery_memory_cache/ - expiration Time: 4999ms Result: PASS 320s START /res/res_sorcery_memory_cache/ - maximum_objects 320s END /res/res_sorcery_memory_cache/ - maximum_objects Time: 4ms Result: PASS 320s START /res/res_sorcery_memory_cache/ - delete 320s END /res/res_sorcery_memory_cache/ - delete Time: <1ms Result: PASS 320s START /res/res_sorcery_memory_cache/ - create 320s END /res/res_sorcery_memory_cache/ - create Time: <1ms Result: PASS 320s START /res/res_sorcery_memory_cache/ - create 320s END /res/res_sorcery_memory_cache/ - create Time: <1ms Result: PASS 320s START /res/res_sorcery_memory_cache/ - open_with_invalid_options 320s END /res/res_sorcery_memory_cache/ - open_with_invalid_options Time: <1ms Result: PASS 320s START /res/res_sorcery_memory_cache/ - open_with_valid_options 320s END /res/res_sorcery_memory_cache/ - open_with_valid_options Time: <1ms Result: PASS 320s START /res/res_sorcery_memory_cache/ - stale 320s [res_sorcery_memory_cache.c:stale:3189]: Begininning iteration 0 325s [res_sorcery_memory_cache.c:stale:3189]: Begininning iteration 1 330s [res_sorcery_memory_cache.c:stale:3189]: Begininning iteration 2 335s END /res/res_sorcery_memory_cache/ - stale Time: 15000ms Result: PASS 335s START /res/res_sorcery_memory_cache/thrash/ - high_object_count_without_expiration 338s END /res/res_sorcery_memory_cache/thrash/ - high_object_count_without_expiration Time: 3043ms Result: PASS 338s START /res/res_sorcery_memory_cache/thrash/ - conflicting_expire_and_stale 344s END /res/res_sorcery_memory_cache/thrash/ - conflicting_expire_and_stale Time: 6068ms Result: PASS 344s START /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum_with_expire_and_stale 350s END /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum_with_expire_and_stale Time: 6009ms Result: PASS 350s START /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum 353s END /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum Time: 3010ms Result: PASS 353s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_high_concurrent_updates 356s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_high_concurrent_updates Time: 3001ms Result: PASS 356s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_expire 359s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_expire Time: 3039ms Result: PASS 359s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_stale 362s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_stale Time: 3004ms Result: PASS 362s START /res/sorcery_astdb/ - object_delete_uncreated 362s END /res/sorcery_astdb/ - object_delete_uncreated Time: <1ms Result: PASS 362s START /res/sorcery_astdb/ - object_delete 362s END /res/sorcery_astdb/ - object_delete Time: <1ms Result: PASS 362s START /res/sorcery_astdb/ - object_update_uncreated 362s END /res/sorcery_astdb/ - object_update_uncreated Time: <1ms Result: PASS 362s START /res/sorcery_astdb/ - object_update 362s END /res/sorcery_astdb/ - object_update Time: <1ms Result: PASS 362s START /res/sorcery_astdb/ - object_retrieve_regex 362s END /res/sorcery_astdb/ - object_retrieve_regex Time: <1ms Result: PASS 362s START /res/sorcery_astdb/ - object_retrieve_multiple_field 362s END /res/sorcery_astdb/ - object_retrieve_multiple_field Time: <1ms Result: PASS 362s START /res/sorcery_astdb/ - object_retrieve_multiple_all 362s END /res/sorcery_astdb/ - object_retrieve_multiple_all Time: <1ms Result: PASS 362s START /res/sorcery_astdb/ - object_retrieve_field 362s END /res/sorcery_astdb/ - object_retrieve_field Time: <1ms Result: PASS 362s START /res/sorcery_astdb/ - object_retrieve_id 362s END /res/sorcery_astdb/ - object_retrieve_id Time: <1ms Result: PASS 362s START /res/sorcery_astdb/ - object_create 362s END /res/sorcery_astdb/ - object_create Time: <1ms Result: PASS 362s START /res/sorcery_realtime/ - object_filter 362s END /res/sorcery_realtime/ - object_filter Time: <1ms Result: PASS 362s START /res/sorcery_realtime/ - object_allocate_on_retrieval 362s END /res/sorcery_realtime/ - object_allocate_on_retrieval Time: <1ms Result: PASS 362s START /res/sorcery_realtime/ - object_delete_uncreated 362s END /res/sorcery_realtime/ - object_delete_uncreated Time: <1ms Result: PASS 362s START /res/sorcery_realtime/ - object_delete 362s END /res/sorcery_realtime/ - object_delete Time: <1ms Result: PASS 362s START /res/sorcery_realtime/ - object_update 362s END /res/sorcery_realtime/ - object_update Time: <1ms Result: PASS 362s START /res/sorcery_realtime/ - object_retrieve_regex_nofetch 362s END /res/sorcery_realtime/ - object_retrieve_regex_nofetch Time: <1ms Result: PASS 362s START /res/sorcery_realtime/ - object_retrieve_regex 362s END /res/sorcery_realtime/ - object_retrieve_regex Time: <1ms Result: PASS 362s START /res/sorcery_realtime/ - object_retrieve_multiple_field 362s END /res/sorcery_realtime/ - object_retrieve_multiple_field Time: <1ms Result: PASS 362s START /res/sorcery_realtime/ - object_retrieve_multiple_all_nofetch 362s END /res/sorcery_realtime/ - object_retrieve_multiple_all_nofetch Time: <1ms Result: PASS 362s START /res/sorcery_realtime/ - object_retrieve_multiple_all 362s END /res/sorcery_realtime/ - object_retrieve_multiple_all Time: <1ms Result: PASS 362s START /res/sorcery_realtime/ - object_retrieve_field 362s END /res/sorcery_realtime/ - object_retrieve_field Time: <1ms Result: PASS 362s START /res/sorcery_realtime/ - object_retrieve_id 362s END /res/sorcery_realtime/ - object_retrieve_id Time: <1ms Result: PASS 362s START /res/sorcery_realtime/ - object_create 362s END /res/sorcery_realtime/ - object_create Time: <1ms Result: PASS 362s START /res/websocket/ - websocket_client_multiple_protocols 362s END /res/websocket/ - websocket_client_multiple_protocols Time: <1ms Result: PASS 362s START /res/websocket/ - websocket_client_unsupported_protocol 362s END /res/websocket/ - websocket_client_unsupported_protocol Time: <1ms Result: PASS 362s START /res/websocket/ - websocket_client_bad_url 362s END /res/websocket/ - websocket_client_bad_url Time: <1ms Result: PASS 362s START /stasis/channels/ - channel_redirect_snapshot_json 362s END /stasis/channels/ - channel_redirect_snapshot_json Time: <1ms Result: PASS 362s START /stasis/channels/ - channel_snapshot_json 362s END /stasis/channels/ - channel_snapshot_json Time: <1ms Result: PASS 362s START /stasis/channels/ - multi_channel_blob_snapshots 362s END /stasis/channels/ - multi_channel_blob_snapshots Time: <1ms Result: PASS 362s START /stasis/channels/ - multi_channel_blob_create 362s END /stasis/channels/ - multi_channel_blob_create Time: <1ms Result: PASS 362s START /stasis/channels/ - null_blob 362s END /stasis/channels/ - null_blob Time: <1ms Result: PASS 362s START /stasis/channels/ - channel_blob_create 362s END /stasis/channels/ - channel_blob_create Time: <1ms Result: PASS 362s START /stasis/core/ - caching_dtor_order 362s END /stasis/core/ - caching_dtor_order Time: <1ms Result: PASS 362s START /stasis/core/ - dtor_order 362s END /stasis/core/ - dtor_order Time: <1ms Result: PASS 362s START /stasis/core/ - to_ami 362s END /stasis/core/ - to_ami Time: <1ms Result: PASS 362s START /stasis/core/ - no_to_ami 362s END /stasis/core/ - no_to_ami Time: <1ms Result: PASS 362s START /stasis/core/ - to_json 362s END /stasis/core/ - to_json Time: <1ms Result: PASS 362s START /stasis/core/ - no_to_json 362s END /stasis/core/ - no_to_json Time: <1ms Result: PASS 362s START /stasis/core/ - subscription_interleaving 362s END /stasis/core/ - subscription_interleaving Time: <1ms Result: PASS 362s START /stasis/core/ - interleaving 362s END /stasis/core/ - interleaving Time: <1ms Result: PASS 362s START /stasis/core/ - router_cache_updates 362s END /stasis/core/ - router_cache_updates Time: 100ms Result: PASS 362s START /stasis/core/ - router_pool 362s END /stasis/core/ - router_pool Time: <1ms Result: PASS 362s START /stasis/core/ - router 362s END /stasis/core/ - router Time: <1ms Result: PASS 362s START /stasis/core/ - cache_eid_aggregate 362s END /stasis/core/ - cache_eid_aggregate Time: <1ms Result: PASS 362s START /stasis/core/ - cache_dump 362s END /stasis/core/ - cache_dump Time: <1ms Result: PASS 362s START /stasis/core/ - cache 362s END /stasis/core/ - cache Time: <1ms Result: PASS 362s START /stasis/core/ - cache_filter 362s END /stasis/core/ - cache_filter Time: 100ms Result: PASS 362s START /stasis/core/ - forward 362s END /stasis/core/ - forward Time: <1ms Result: PASS 362s START /stasis/core/ - unsubscribe_stops_messages 362s END /stasis/core/ - unsubscribe_stops_messages Time: 100ms Result: PASS 362s START /stasis/core/ - publish_pool 362s END /stasis/core/ - publish_pool Time: <1ms Result: PASS 362s START /stasis/core/ - publish_sync 362s END /stasis/core/ - publish_sync Time: <1ms Result: PASS 362s START /stasis/core/ - publish 362s END /stasis/core/ - publish Time: <1ms Result: PASS 362s START /stasis/core/ - subscription_pool_messages 362s END /stasis/core/ - subscription_pool_messages Time: <1ms Result: PASS 362s START /stasis/core/ - subscription_messages 362s END /stasis/core/ - subscription_messages Time: <1ms Result: PASS 362s START /stasis/core/ - message 362s END /stasis/core/ - message Time: <1ms Result: PASS 362s START /stasis/core/ - message_type 362s END /stasis/core/ - message_type Time: <1ms Result: PASS 362s START /stasis/core/filtering/ - combo_filters 362s [test_stasis.c:dump_consumer:2198]: Messages received: 7 Final? yes 362s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 362s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType1 Pass 362s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass 362s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMI Pass 362s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass 362s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageJSON Pass 362s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 362s END /stasis/core/filtering/ - combo_filters Time: <1ms Result: PASS 362s START /stasis/core/filtering/ - formatter_filters 362s [test_stasis.c:dump_consumer:2198]: Messages received: 7 Final? yes 362s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 362s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMI Pass 362s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageJSON Pass 362s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass 362s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass2 362s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageEVENT Pass 362s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 362s END /stasis/core/filtering/ - formatter_filters Time: <1ms Result: PASS 362s START /stasis/core/filtering/ - type_filters 362s [test_stasis.c:dump_consumer:2198]: Messages received: 5 Final? yes 362s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 362s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType1 Pass 362s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass 362s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass2 362s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 362s END /stasis/core/filtering/ - type_filters Time: <1ms Result: PASS 362s START /stasis/core/state/ - explicit_publish 362s END /stasis/core/state/ - explicit_publish Time: 16ms Result: PASS 362s START /stasis/core/state/ - implicit_publish 362s END /stasis/core/state/ - implicit_publish Time: 12ms Result: PASS 362s START /stasis/endpoints/ - channel_messages 362s END /stasis/endpoints/ - channel_messages Time: <1ms Result: PASS 362s START /stasis/endpoints/ - cache_clear 362s END /stasis/endpoints/ - cache_clear Time: <1ms Result: PASS 362s START /stasis/endpoints/ - state_changes 362s END /stasis/endpoints/ - state_changes Time: <1ms Result: PASS 362s START /stasis/res/ - app_invoke_dne 362s END /stasis/res/ - app_invoke_dne Time: <1ms Result: PASS 362s START /stasis/res/ - app_invoke_one 362s END /stasis/res/ - app_invoke_one Time: <1ms Result: PASS 362s START /stasis/res/ - app_replaced 362s END /stasis/res/ - app_replaced Time: <1ms Result: PASS 362s 362s 659 Test(s) Executed 655 Passed 4 Failed 362s Results Generated Successfully: /tmp/autopkgtest.SuX6t4/build.Zvm/src/debian/tests/testmods/output/results.txt 362s Some test modules were not loaded: 362s 20a21 362s > test_cel.so 362s 53a55 362s > test_message.so 362s Manually disabled: 362s test_message 362s test_cel 362s 362s 'U' option is not compatible with remote console mode and has no effect. 362s 362s 'U' option is not compatible with remote console mode and has no effect. 362s 362s 'U' option is not compatible with remote console mode and has no effect. 362s 364s autopkgtest [08:23:04]: test asttestmods: -----------------------] 364s asttestmods PASS 364s autopkgtest [08:23:04]: test asttestmods: - - - - - - - - - - results - - - - - - - - - - 365s autopkgtest [08:23:05]: test amr: preparing testbed 468s autopkgtest [08:24:48]: testbed dpkg architecture: s390x 468s autopkgtest [08:24:48]: testbed apt version: 2.9.18 468s autopkgtest [08:24:48]: @@@@@@@@@@@@@@@@@@@@ test bed setup 468s autopkgtest [08:24:48]: testbed release detected to be: plucky 469s autopkgtest [08:24:49]: updating testbed package index (apt update) 469s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [73.9 kB] 469s Hit:2 http://ftpmaster.internal/ubuntu plucky InRelease 470s Hit:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease 470s Hit:4 http://ftpmaster.internal/ubuntu plucky-security InRelease 470s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [138 kB] 470s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [856 kB] 470s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/restricted Sources [9708 B] 470s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [10.3 kB] 470s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x Packages [247 kB] 470s Get:10 http://ftpmaster.internal/ubuntu plucky-proposed/restricted s390x Packages [756 B] 470s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/universe s390x Packages [907 kB] 470s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse s390x Packages [4072 B] 470s Fetched 2247 kB in 1s (2368 kB/s) 471s Reading package lists... 471s Reading package lists... 471s Building dependency tree... 471s Reading state information... 472s Calculating upgrade... 472s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 472s Reading package lists... 472s Building dependency tree... 472s Reading state information... 472s 0 upgraded, 0 newly installed, 0 to remove and 14 not upgraded. 472s autopkgtest [08:24:52]: upgrading testbed (apt dist-upgrade and autopurge) 472s Reading package lists... 472s Building dependency tree... 472s Reading state information... 472s Calculating upgrade...Starting pkgProblemResolver with broken count: 0 472s Starting 2 pkgProblemResolver with broken count: 0 472s Done 473s Entering ResolveByKeep 473s 473s The following NEW packages will be installed: 473s login.defs 473s The following packages will be upgraded: 473s bsdextrautils bsdutils eject fdisk libblkid1 libfdisk1 libmount1 473s libsmartcols1 libuuid1 login mount passwd util-linux uuid-runtime 473s 14 upgraded, 1 newly installed, 0 to remove and 0 not upgraded. 473s Need to get 3481 kB of archives. 473s After this operation, 1482 kB of additional disk space will be used. 473s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x bsdutils s390x 1:2.40.2-14ubuntu1 [103 kB] 473s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x eject s390x 2.40.2-14ubuntu1 [46.1 kB] 473s Get:3 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x bsdextrautils s390x 2.40.2-14ubuntu1 [91.2 kB] 473s Get:4 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libfdisk1 s390x 2.40.2-14ubuntu1 [169 kB] 473s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x fdisk s390x 2.40.2-14ubuntu1 [144 kB] 474s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libblkid1 s390x 2.40.2-14ubuntu1 [134 kB] 474s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libmount1 s390x 2.40.2-14ubuntu1 [158 kB] 474s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libsmartcols1 s390x 2.40.2-14ubuntu1 [89.5 kB] 474s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x mount s390x 2.40.2-14ubuntu1 [139 kB] 474s Get:10 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x libuuid1 s390x 2.40.2-14ubuntu1 [42.4 kB] 474s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x util-linux s390x 2.40.2-14ubuntu1 [1129 kB] 474s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x uuid-runtime s390x 2.40.2-14ubuntu1 [54.2 kB] 474s Get:13 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x login.defs all 1:4.16.0-7ubuntu1 [38.5 kB] 474s Get:14 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x login s390x 1:4.16.0-2+really2.40.2-14ubuntu1 [77.7 kB] 474s Get:15 http://ftpmaster.internal/ubuntu plucky-proposed/main s390x passwd s390x 1:4.16.0-7ubuntu1 [1066 kB] 474s Fetched 3481 kB in 1s (5024 kB/s) 474s (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 ... 55642 files and directories currently installed.) 474s Preparing to unpack .../bsdutils_1%3a2.40.2-14ubuntu1_s390x.deb ... 474s Unpacking bsdutils (1:2.40.2-14ubuntu1) over (1:2.40.2-1ubuntu2) ... 474s Setting up bsdutils (1:2.40.2-14ubuntu1) ... 474s (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 ... 55642 files and directories currently installed.) 474s Preparing to unpack .../eject_2.40.2-14ubuntu1_s390x.deb ... 474s Unpacking eject (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 474s Preparing to unpack .../bsdextrautils_2.40.2-14ubuntu1_s390x.deb ... 474s Unpacking bsdextrautils (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 474s Preparing to unpack .../libfdisk1_2.40.2-14ubuntu1_s390x.deb ... 474s Unpacking libfdisk1:s390x (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 474s Preparing to unpack .../fdisk_2.40.2-14ubuntu1_s390x.deb ... 474s Unpacking fdisk (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 474s Preparing to unpack .../libblkid1_2.40.2-14ubuntu1_s390x.deb ... 474s Unpacking libblkid1:s390x (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 474s Setting up libblkid1:s390x (2.40.2-14ubuntu1) ... 474s (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 ... 55638 files and directories currently installed.) 474s Preparing to unpack .../libmount1_2.40.2-14ubuntu1_s390x.deb ... 474s Unpacking libmount1:s390x (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 474s Setting up libmount1:s390x (2.40.2-14ubuntu1) ... 474s (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 ... 55638 files and directories currently installed.) 474s Preparing to unpack .../libsmartcols1_2.40.2-14ubuntu1_s390x.deb ... 474s Unpacking libsmartcols1:s390x (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 474s Setting up libsmartcols1:s390x (2.40.2-14ubuntu1) ... 474s (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 ... 55638 files and directories currently installed.) 474s Preparing to unpack .../mount_2.40.2-14ubuntu1_s390x.deb ... 474s Unpacking mount (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 474s Preparing to unpack .../libuuid1_2.40.2-14ubuntu1_s390x.deb ... 474s Unpacking libuuid1:s390x (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 474s Setting up libuuid1:s390x (2.40.2-14ubuntu1) ... 474s (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 ... 55638 files and directories currently installed.) 474s Preparing to unpack .../util-linux_2.40.2-14ubuntu1_s390x.deb ... 474s Unpacking util-linux (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 474s Setting up util-linux (2.40.2-14ubuntu1) ... 475s fstrim.service is a disabled or a static unit not running, not starting it. 475s (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 ... 55631 files and directories currently installed.) 475s Preparing to unpack .../uuid-runtime_2.40.2-14ubuntu1_s390x.deb ... 475s Unpacking uuid-runtime (2.40.2-14ubuntu1) over (2.40.2-1ubuntu2) ... 475s Selecting previously unselected package login.defs. 475s Preparing to unpack .../login.defs_1%3a4.16.0-7ubuntu1_all.deb ... 475s Unpacking login.defs (1:4.16.0-7ubuntu1) ... 475s Replacing files in old package login (1:4.15.3-3ubuntu2) ... 475s Setting up login.defs (1:4.16.0-7ubuntu1) ... 475s Installing new version of config file /etc/login.defs ... 475s (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 ... 55635 files and directories currently installed.) 475s Preparing to unpack .../login_1%3a4.16.0-2+really2.40.2-14ubuntu1_s390x.deb ... 475s Unpacking login (1:4.16.0-2+really2.40.2-14ubuntu1) over (1:4.15.3-3ubuntu2) ... 475s Preparing to unpack .../passwd_1%3a4.16.0-7ubuntu1_s390x.deb ... 475s Unpacking passwd (1:4.16.0-7ubuntu1) over (1:4.15.3-3ubuntu2) ... 475s Setting up passwd (1:4.16.0-7ubuntu1) ... 475s Setting up bsdextrautils (2.40.2-14ubuntu1) ... 475s Setting up eject (2.40.2-14ubuntu1) ... 475s Setting up libfdisk1:s390x (2.40.2-14ubuntu1) ... 475s Setting up mount (2.40.2-14ubuntu1) ... 475s Setting up uuid-runtime (2.40.2-14ubuntu1) ... 476s uuidd.service is a disabled or a static unit not running, not starting it. 476s Setting up login (1:4.16.0-2+really2.40.2-14ubuntu1) ... 476s Setting up fdisk (2.40.2-14ubuntu1) ... 476s Processing triggers for man-db (2.13.0-1) ... 477s Processing triggers for libc-bin (2.40-4ubuntu1) ... 477s Reading package lists... 477s Building dependency tree... 477s Reading state information... 478s Starting pkgProblemResolver with broken count: 0 478s Starting 2 pkgProblemResolver with broken count: 0 478s Done 478s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 478s autopkgtest [08:24:58]: rebooting testbed after setup commands that affected boot 499s Reading package lists... 499s Building dependency tree... 499s Reading state information... 499s Starting pkgProblemResolver with broken count: 0 499s Starting 2 pkgProblemResolver with broken count: 0 499s Done 499s The following NEW packages will be installed: 499s asterisk asterisk-config asterisk-core-sounds-en asterisk-core-sounds-en-gsm 499s asterisk-modules freetds-common libasound2-data libasound2t64 libb64-0d 499s libc-client2007e libcodec2-1.2 libdeflate0 libevent-2.1-7t64 499s libgmime-3.0-0t64 libgsm1 libical3t64 libiksemel3 libjack-jackd2-0 libjbig0 499s libjpeg-turbo8 libjpeg8 libjwt2 libltdl7 liblua5.1-0 libneon27t64 libodbc2 499s libogg0 libopencore-amrnb0 libopencore-amrwb0 libopus0 libopusenc0 499s libopusfile0 libportaudio2 libpq5 libradcli4 libresample1 libsamplerate0 499s libsharpyuv0 libsnmp-base libsnmp40t64 libspandsp2t64 libspeex1 libspeexdsp1 499s libsrtp2-1 libsybdb5 libtiff6 libunbound8 liburiparser1 libvo-amrwbenc0 499s libvorbis0a libvorbisenc2 libvorbisfile3 libwebp7 libxslt1.1 mlock 499s 0 upgraded, 55 newly installed, 0 to remove and 0 not upgraded. 499s Need to get 28.4 MB of archives. 499s After this operation, 69.1 MB of additional disk space will be used. 499s Get:1 http://ftpmaster.internal/ubuntu plucky/universe s390x asterisk-config all 1:22.1.0~dfsg+~cs6.14.60671435-1 [223 kB] 500s Get:2 http://ftpmaster.internal/ubuntu plucky/universe s390x asterisk-core-sounds-en-gsm all 1.6.1-1 [2417 kB] 500s Get:3 http://ftpmaster.internal/ubuntu plucky/universe s390x asterisk-core-sounds-en all 1.6.1-1 [20.6 kB] 500s Get:4 http://ftpmaster.internal/ubuntu plucky/universe s390x mlock s390x 8:2007f~dfsg-7.1 [8630 B] 500s Get:5 http://ftpmaster.internal/ubuntu plucky/universe s390x libc-client2007e s390x 8:2007f~dfsg-7.1 [648 kB] 500s Get:6 http://ftpmaster.internal/ubuntu plucky/universe s390x libcodec2-1.2 s390x 1.2.0-2build1 [9028 kB] 500s Get:7 http://ftpmaster.internal/ubuntu plucky/universe s390x libgmime-3.0-0t64 s390x 3.2.15+dfsg-1 [184 kB] 500s Get:8 http://ftpmaster.internal/ubuntu plucky/universe s390x libgsm1 s390x 1.0.22-1build1 [32.7 kB] 500s Get:9 http://ftpmaster.internal/ubuntu plucky/main s390x libical3t64 s390x 3.0.19-1build1 [312 kB] 500s Get:10 http://ftpmaster.internal/ubuntu plucky/universe s390x libiksemel3 s390x 1.4-4build2 [28.7 kB] 500s Get:11 http://ftpmaster.internal/ubuntu plucky/main s390x libopus0 s390x 1.5.2-2 [2928 kB] 500s Get:12 http://ftpmaster.internal/ubuntu plucky/main s390x libsamplerate0 s390x 0.2.2-4build1 [1344 kB] 501s Get:13 http://ftpmaster.internal/ubuntu plucky/main s390x libjack-jackd2-0 s390x 1.9.22~dfsg-4 [292 kB] 501s Get:14 http://ftpmaster.internal/ubuntu plucky/universe s390x libb64-0d s390x 1.2-5build1 [9656 B] 501s Get:15 http://ftpmaster.internal/ubuntu plucky/universe s390x libjwt2 s390x 1.17.2-1 [18.2 kB] 501s Get:16 http://ftpmaster.internal/ubuntu plucky/universe s390x liblua5.1-0 s390x 5.1.5-10 [130 kB] 501s Get:17 http://ftpmaster.internal/ubuntu plucky/universe s390x libneon27t64 s390x 0.34.0-1 [105 kB] 501s Get:18 http://ftpmaster.internal/ubuntu plucky/main s390x libltdl7 s390x 2.4.7-8 [41.5 kB] 501s Get:19 http://ftpmaster.internal/ubuntu plucky/main s390x libodbc2 s390x 2.3.12-1ubuntu1 [162 kB] 501s Get:20 http://ftpmaster.internal/ubuntu plucky/main s390x libogg0 s390x 1.3.5-3build1 [24.4 kB] 501s Get:21 http://ftpmaster.internal/ubuntu plucky/universe s390x libopencore-amrnb0 s390x 0.1.6-1build1 [108 kB] 501s Get:22 http://ftpmaster.internal/ubuntu plucky/universe s390x libopencore-amrwb0 s390x 0.1.6-1build1 [56.6 kB] 501s Get:23 http://ftpmaster.internal/ubuntu plucky/universe s390x libopusenc0 s390x 0.2.1-2build1 [29.0 kB] 501s Get:24 http://ftpmaster.internal/ubuntu plucky/universe s390x libopusfile0 s390x 0.12-4build3 [48.0 kB] 501s Get:25 http://ftpmaster.internal/ubuntu plucky/main s390x libasound2-data all 1.2.12-1 [21.0 kB] 501s Get:26 http://ftpmaster.internal/ubuntu plucky/main s390x libasound2t64 s390x 1.2.12-1 [408 kB] 501s Get:27 http://ftpmaster.internal/ubuntu plucky/universe s390x libportaudio2 s390x 19.6.0-1.2build3 [71.6 kB] 501s Get:28 http://ftpmaster.internal/ubuntu plucky/main s390x libpq5 s390x 17.2-1 [146 kB] 501s Get:29 http://ftpmaster.internal/ubuntu plucky/universe s390x libradcli4 s390x 1.2.11-1build3 [40.9 kB] 501s Get:30 http://ftpmaster.internal/ubuntu plucky/universe s390x libresample1 s390x 0.1.3-8 [9388 B] 501s Get:31 http://ftpmaster.internal/ubuntu plucky/main s390x libsnmp-base all 5.9.4+dfsg-1.1ubuntu5 [206 kB] 501s Get:32 http://ftpmaster.internal/ubuntu plucky/main s390x libsnmp40t64 s390x 5.9.4+dfsg-1.1ubuntu5 [1055 kB] 501s Get:33 http://ftpmaster.internal/ubuntu plucky/main s390x libdeflate0 s390x 1.22-1 [46.1 kB] 501s Get:34 http://ftpmaster.internal/ubuntu plucky/main s390x libjbig0 s390x 2.1-6.1ubuntu2 [33.1 kB] 501s Get:35 http://ftpmaster.internal/ubuntu plucky/main s390x libjpeg-turbo8 s390x 2.1.5-3ubuntu2 [147 kB] 501s Get:36 http://ftpmaster.internal/ubuntu plucky/main s390x libjpeg8 s390x 8c-2ubuntu11 [2146 B] 501s Get:37 http://ftpmaster.internal/ubuntu plucky/main s390x libsharpyuv0 s390x 1.4.0-0.1 [16.2 kB] 501s Get:38 http://ftpmaster.internal/ubuntu plucky/main s390x libwebp7 s390x 1.4.0-0.1 [204 kB] 501s Get:39 http://ftpmaster.internal/ubuntu plucky/main s390x libtiff6 s390x 4.5.1+git230720-4ubuntu4 [217 kB] 501s Get:40 http://ftpmaster.internal/ubuntu plucky/universe s390x libspandsp2t64 s390x 0.0.6+dfsg-2.1build1 [336 kB] 501s Get:41 http://ftpmaster.internal/ubuntu plucky/main s390x libspeex1 s390x 1.2.1-3 [70.7 kB] 501s Get:42 http://ftpmaster.internal/ubuntu plucky/main s390x libspeexdsp1 s390x 1.2.1-1ubuntu3 [54.4 kB] 501s Get:43 http://ftpmaster.internal/ubuntu plucky/universe s390x libsrtp2-1 s390x 2.5.0-3build1 [41.3 kB] 501s Get:44 http://ftpmaster.internal/ubuntu plucky/main s390x freetds-common all 1.3.17+ds-2build3 [26.9 kB] 501s Get:45 http://ftpmaster.internal/ubuntu plucky/main s390x libsybdb5 s390x 1.3.17+ds-2build3 [209 kB] 501s Get:46 http://ftpmaster.internal/ubuntu plucky/main s390x libevent-2.1-7t64 s390x 2.1.12-stable-10 [145 kB] 501s Get:47 http://ftpmaster.internal/ubuntu plucky/main s390x libunbound8 s390x 1.20.0-1ubuntu2.1 [455 kB] 501s Get:48 http://ftpmaster.internal/ubuntu plucky/universe s390x libvo-amrwbenc0 s390x 0.1.3-2build1 [87.8 kB] 501s Get:49 http://ftpmaster.internal/ubuntu plucky/main s390x libvorbis0a s390x 1.3.7-2 [112 kB] 501s Get:50 http://ftpmaster.internal/ubuntu plucky/main s390x libvorbisenc2 s390x 1.3.7-2 [80.6 kB] 501s Get:51 http://ftpmaster.internal/ubuntu plucky/main s390x libvorbisfile3 s390x 1.3.7-2 [18.2 kB] 501s Get:52 http://ftpmaster.internal/ubuntu plucky/universe s390x asterisk-modules s390x 1:22.1.0~dfsg+~cs6.14.60671435-1 [3007 kB] 501s Get:53 http://ftpmaster.internal/ubuntu plucky/universe s390x liburiparser1 s390x 0.9.8+dfsg-2 [42.4 kB] 501s Get:54 http://ftpmaster.internal/ubuntu plucky/main s390x libxslt1.1 s390x 1.1.39-0exp1ubuntu2 [169 kB] 501s Get:55 http://ftpmaster.internal/ubuntu plucky/universe s390x asterisk s390x 1:22.1.0~dfsg+~cs6.14.60671435-1 [2724 kB] 501s Fetched 28.4 MB in 2s (15.1 MB/s) 502s Selecting previously unselected package asterisk-config. 502s (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 ... 55633 files and directories currently installed.) 502s Preparing to unpack .../00-asterisk-config_1%3a22.1.0~dfsg+~cs6.14.60671435-1_all.deb ... 502s Unpacking asterisk-config (1:22.1.0~dfsg+~cs6.14.60671435-1) ... 502s Selecting previously unselected package asterisk-core-sounds-en-gsm. 502s Preparing to unpack .../01-asterisk-core-sounds-en-gsm_1.6.1-1_all.deb ... 502s Unpacking asterisk-core-sounds-en-gsm (1.6.1-1) ... 502s Selecting previously unselected package asterisk-core-sounds-en. 502s Preparing to unpack .../02-asterisk-core-sounds-en_1.6.1-1_all.deb ... 502s Unpacking asterisk-core-sounds-en (1.6.1-1) ... 502s Selecting previously unselected package mlock. 502s Preparing to unpack .../03-mlock_8%3a2007f~dfsg-7.1_s390x.deb ... 502s Unpacking mlock (8:2007f~dfsg-7.1) ... 502s Selecting previously unselected package libc-client2007e. 502s Preparing to unpack .../04-libc-client2007e_8%3a2007f~dfsg-7.1_s390x.deb ... 502s Unpacking libc-client2007e (8:2007f~dfsg-7.1) ... 502s Selecting previously unselected package libcodec2-1.2:s390x. 502s Preparing to unpack .../05-libcodec2-1.2_1.2.0-2build1_s390x.deb ... 502s Unpacking libcodec2-1.2:s390x (1.2.0-2build1) ... 502s Selecting previously unselected package libgmime-3.0-0t64:s390x. 502s Preparing to unpack .../06-libgmime-3.0-0t64_3.2.15+dfsg-1_s390x.deb ... 502s Unpacking libgmime-3.0-0t64:s390x (3.2.15+dfsg-1) ... 502s Selecting previously unselected package libgsm1:s390x. 502s Preparing to unpack .../07-libgsm1_1.0.22-1build1_s390x.deb ... 502s Unpacking libgsm1:s390x (1.0.22-1build1) ... 502s Selecting previously unselected package libical3t64:s390x. 502s Preparing to unpack .../08-libical3t64_3.0.19-1build1_s390x.deb ... 502s Unpacking libical3t64:s390x (3.0.19-1build1) ... 502s Selecting previously unselected package libiksemel3:s390x. 502s Preparing to unpack .../09-libiksemel3_1.4-4build2_s390x.deb ... 502s Unpacking libiksemel3:s390x (1.4-4build2) ... 502s Selecting previously unselected package libopus0:s390x. 502s Preparing to unpack .../10-libopus0_1.5.2-2_s390x.deb ... 502s Unpacking libopus0:s390x (1.5.2-2) ... 502s Selecting previously unselected package libsamplerate0:s390x. 502s Preparing to unpack .../11-libsamplerate0_0.2.2-4build1_s390x.deb ... 502s Unpacking libsamplerate0:s390x (0.2.2-4build1) ... 502s Selecting previously unselected package libjack-jackd2-0:s390x. 502s Preparing to unpack .../12-libjack-jackd2-0_1.9.22~dfsg-4_s390x.deb ... 502s Unpacking libjack-jackd2-0:s390x (1.9.22~dfsg-4) ... 502s Selecting previously unselected package libb64-0d:s390x. 502s Preparing to unpack .../13-libb64-0d_1.2-5build1_s390x.deb ... 502s Unpacking libb64-0d:s390x (1.2-5build1) ... 502s Selecting previously unselected package libjwt2:s390x. 502s Preparing to unpack .../14-libjwt2_1.17.2-1_s390x.deb ... 502s Unpacking libjwt2:s390x (1.17.2-1) ... 502s Selecting previously unselected package liblua5.1-0:s390x. 502s Preparing to unpack .../15-liblua5.1-0_5.1.5-10_s390x.deb ... 502s Unpacking liblua5.1-0:s390x (5.1.5-10) ... 502s Selecting previously unselected package libneon27t64:s390x. 502s Preparing to unpack .../16-libneon27t64_0.34.0-1_s390x.deb ... 502s Unpacking libneon27t64:s390x (0.34.0-1) ... 502s Selecting previously unselected package libltdl7:s390x. 502s Preparing to unpack .../17-libltdl7_2.4.7-8_s390x.deb ... 502s Unpacking libltdl7:s390x (2.4.7-8) ... 502s Selecting previously unselected package libodbc2:s390x. 502s Preparing to unpack .../18-libodbc2_2.3.12-1ubuntu1_s390x.deb ... 502s Unpacking libodbc2:s390x (2.3.12-1ubuntu1) ... 502s Selecting previously unselected package libogg0:s390x. 502s Preparing to unpack .../19-libogg0_1.3.5-3build1_s390x.deb ... 502s Unpacking libogg0:s390x (1.3.5-3build1) ... 502s Selecting previously unselected package libopencore-amrnb0:s390x. 502s Preparing to unpack .../20-libopencore-amrnb0_0.1.6-1build1_s390x.deb ... 502s Unpacking libopencore-amrnb0:s390x (0.1.6-1build1) ... 502s Selecting previously unselected package libopencore-amrwb0:s390x. 502s Preparing to unpack .../21-libopencore-amrwb0_0.1.6-1build1_s390x.deb ... 502s Unpacking libopencore-amrwb0:s390x (0.1.6-1build1) ... 502s Selecting previously unselected package libopusenc0:s390x. 502s Preparing to unpack .../22-libopusenc0_0.2.1-2build1_s390x.deb ... 502s Unpacking libopusenc0:s390x (0.2.1-2build1) ... 502s Selecting previously unselected package libopusfile0:s390x. 502s Preparing to unpack .../23-libopusfile0_0.12-4build3_s390x.deb ... 502s Unpacking libopusfile0:s390x (0.12-4build3) ... 502s Selecting previously unselected package libasound2-data. 502s Preparing to unpack .../24-libasound2-data_1.2.12-1_all.deb ... 502s Unpacking libasound2-data (1.2.12-1) ... 502s Selecting previously unselected package libasound2t64:s390x. 502s Preparing to unpack .../25-libasound2t64_1.2.12-1_s390x.deb ... 502s Unpacking libasound2t64:s390x (1.2.12-1) ... 502s Selecting previously unselected package libportaudio2:s390x. 502s Preparing to unpack .../26-libportaudio2_19.6.0-1.2build3_s390x.deb ... 502s Unpacking libportaudio2:s390x (19.6.0-1.2build3) ... 502s Selecting previously unselected package libpq5:s390x. 502s Preparing to unpack .../27-libpq5_17.2-1_s390x.deb ... 502s Unpacking libpq5:s390x (17.2-1) ... 502s Selecting previously unselected package libradcli4. 502s Preparing to unpack .../28-libradcli4_1.2.11-1build3_s390x.deb ... 502s Unpacking libradcli4 (1.2.11-1build3) ... 502s Selecting previously unselected package libresample1. 502s Preparing to unpack .../29-libresample1_0.1.3-8_s390x.deb ... 502s Unpacking libresample1 (0.1.3-8) ... 502s Selecting previously unselected package libsnmp-base. 502s Preparing to unpack .../30-libsnmp-base_5.9.4+dfsg-1.1ubuntu5_all.deb ... 502s Unpacking libsnmp-base (5.9.4+dfsg-1.1ubuntu5) ... 502s Selecting previously unselected package libsnmp40t64:s390x. 502s Preparing to unpack .../31-libsnmp40t64_5.9.4+dfsg-1.1ubuntu5_s390x.deb ... 502s Unpacking libsnmp40t64:s390x (5.9.4+dfsg-1.1ubuntu5) ... 502s Selecting previously unselected package libdeflate0:s390x. 502s Preparing to unpack .../32-libdeflate0_1.22-1_s390x.deb ... 502s Unpacking libdeflate0:s390x (1.22-1) ... 502s Selecting previously unselected package libjbig0:s390x. 502s Preparing to unpack .../33-libjbig0_2.1-6.1ubuntu2_s390x.deb ... 502s Unpacking libjbig0:s390x (2.1-6.1ubuntu2) ... 502s Selecting previously unselected package libjpeg-turbo8:s390x. 502s Preparing to unpack .../34-libjpeg-turbo8_2.1.5-3ubuntu2_s390x.deb ... 502s Unpacking libjpeg-turbo8:s390x (2.1.5-3ubuntu2) ... 502s Selecting previously unselected package libjpeg8:s390x. 502s Preparing to unpack .../35-libjpeg8_8c-2ubuntu11_s390x.deb ... 502s Unpacking libjpeg8:s390x (8c-2ubuntu11) ... 502s Selecting previously unselected package libsharpyuv0:s390x. 502s Preparing to unpack .../36-libsharpyuv0_1.4.0-0.1_s390x.deb ... 502s Unpacking libsharpyuv0:s390x (1.4.0-0.1) ... 502s Selecting previously unselected package libwebp7:s390x. 502s Preparing to unpack .../37-libwebp7_1.4.0-0.1_s390x.deb ... 502s Unpacking libwebp7:s390x (1.4.0-0.1) ... 502s Selecting previously unselected package libtiff6:s390x. 502s Preparing to unpack .../38-libtiff6_4.5.1+git230720-4ubuntu4_s390x.deb ... 502s Unpacking libtiff6:s390x (4.5.1+git230720-4ubuntu4) ... 502s Selecting previously unselected package libspandsp2t64:s390x. 502s Preparing to unpack .../39-libspandsp2t64_0.0.6+dfsg-2.1build1_s390x.deb ... 502s Unpacking libspandsp2t64:s390x (0.0.6+dfsg-2.1build1) ... 502s Selecting previously unselected package libspeex1:s390x. 502s Preparing to unpack .../40-libspeex1_1.2.1-3_s390x.deb ... 502s Unpacking libspeex1:s390x (1.2.1-3) ... 502s Selecting previously unselected package libspeexdsp1:s390x. 502s Preparing to unpack .../41-libspeexdsp1_1.2.1-1ubuntu3_s390x.deb ... 502s Unpacking libspeexdsp1:s390x (1.2.1-1ubuntu3) ... 502s Selecting previously unselected package libsrtp2-1:s390x. 502s Preparing to unpack .../42-libsrtp2-1_2.5.0-3build1_s390x.deb ... 502s Unpacking libsrtp2-1:s390x (2.5.0-3build1) ... 502s Selecting previously unselected package freetds-common. 502s Preparing to unpack .../43-freetds-common_1.3.17+ds-2build3_all.deb ... 502s Unpacking freetds-common (1.3.17+ds-2build3) ... 502s Selecting previously unselected package libsybdb5:s390x. 502s Preparing to unpack .../44-libsybdb5_1.3.17+ds-2build3_s390x.deb ... 502s Unpacking libsybdb5:s390x (1.3.17+ds-2build3) ... 502s Selecting previously unselected package libevent-2.1-7t64:s390x. 502s Preparing to unpack .../45-libevent-2.1-7t64_2.1.12-stable-10_s390x.deb ... 502s Unpacking libevent-2.1-7t64:s390x (2.1.12-stable-10) ... 502s Selecting previously unselected package libunbound8:s390x. 502s Preparing to unpack .../46-libunbound8_1.20.0-1ubuntu2.1_s390x.deb ... 502s Unpacking libunbound8:s390x (1.20.0-1ubuntu2.1) ... 502s Selecting previously unselected package libvo-amrwbenc0:s390x. 502s Preparing to unpack .../47-libvo-amrwbenc0_0.1.3-2build1_s390x.deb ... 502s Unpacking libvo-amrwbenc0:s390x (0.1.3-2build1) ... 502s Selecting previously unselected package libvorbis0a:s390x. 502s Preparing to unpack .../48-libvorbis0a_1.3.7-2_s390x.deb ... 502s Unpacking libvorbis0a:s390x (1.3.7-2) ... 502s Selecting previously unselected package libvorbisenc2:s390x. 502s Preparing to unpack .../49-libvorbisenc2_1.3.7-2_s390x.deb ... 502s Unpacking libvorbisenc2:s390x (1.3.7-2) ... 502s Selecting previously unselected package libvorbisfile3:s390x. 502s Preparing to unpack .../50-libvorbisfile3_1.3.7-2_s390x.deb ... 502s Unpacking libvorbisfile3:s390x (1.3.7-2) ... 503s Selecting previously unselected package asterisk-modules. 503s Preparing to unpack .../51-asterisk-modules_1%3a22.1.0~dfsg+~cs6.14.60671435-1_s390x.deb ... 503s Unpacking asterisk-modules (1:22.1.0~dfsg+~cs6.14.60671435-1) ... 503s Selecting previously unselected package liburiparser1:s390x. 503s Preparing to unpack .../52-liburiparser1_0.9.8+dfsg-2_s390x.deb ... 503s Unpacking liburiparser1:s390x (0.9.8+dfsg-2) ... 503s Selecting previously unselected package libxslt1.1:s390x. 503s Preparing to unpack .../53-libxslt1.1_1.1.39-0exp1ubuntu2_s390x.deb ... 503s Unpacking libxslt1.1:s390x (1.1.39-0exp1ubuntu2) ... 503s Selecting previously unselected package asterisk. 503s Preparing to unpack .../54-asterisk_1%3a22.1.0~dfsg+~cs6.14.60671435-1_s390x.deb ... 503s Unpacking asterisk (1:22.1.0~dfsg+~cs6.14.60671435-1) ... 503s Setting up libsharpyuv0:s390x (1.4.0-0.1) ... 503s Setting up libvo-amrwbenc0:s390x (0.1.3-2build1) ... 503s Setting up libneon27t64:s390x (0.34.0-1) ... 503s Setting up libogg0:s390x (1.3.5-3build1) ... 503s Setting up libspeex1:s390x (1.2.1-3) ... 503s Setting up libgsm1:s390x (1.0.22-1build1) ... 503s Setting up asterisk-core-sounds-en-gsm (1.6.1-1) ... 503s Setting up libsnmp-base (5.9.4+dfsg-1.1ubuntu5) ... 503s Setting up libcodec2-1.2:s390x (1.2.0-2build1) ... 503s Setting up mlock (8:2007f~dfsg-7.1) ... 503s Setting up libsrtp2-1:s390x (2.5.0-3build1) ... 503s Setting up libpq5:s390x (17.2-1) ... 503s Setting up libdeflate0:s390x (1.22-1) ... 503s Setting up libevent-2.1-7t64:s390x (2.1.12-stable-10) ... 503s Setting up libb64-0d:s390x (1.2-5build1) ... 503s Setting up libjwt2:s390x (1.17.2-1) ... 503s Setting up libjbig0:s390x (2.1-6.1ubuntu2) ... 503s Setting up libasound2-data (1.2.12-1) ... 503s Setting up libopencore-amrwb0:s390x (0.1.6-1build1) ... 503s Setting up libunbound8:s390x (1.20.0-1ubuntu2.1) ... 503s Setting up libasound2t64:s390x (1.2.12-1) ... 503s Setting up libradcli4 (1.2.11-1build3) ... 503s Setting up libopus0:s390x (1.5.2-2) ... 503s Setting up asterisk-config (1:22.1.0~dfsg+~cs6.14.60671435-1) ... 503s Setting up libvorbis0a:s390x (1.3.7-2) ... 503s Setting up libical3t64:s390x (3.0.19-1build1) ... 503s Setting up libjpeg-turbo8:s390x (2.1.5-3ubuntu2) ... 503s Setting up libltdl7:s390x (2.4.7-8) ... 503s Setting up asterisk-core-sounds-en (1.6.1-1) ... 503s update-alternatives: using /usr/share/asterisk/sounds/en_US_f_Allison to provide /usr/share/asterisk/sounds/en (asterisk-prompt-en) in auto mode 503s update-alternatives: using /usr/share/asterisk/sounds/en_US_f_Allison to provide /usr/share/asterisk/sounds/en_US (asterisk-prompt-en-us) in auto mode 503s Setting up libwebp7:s390x (1.4.0-0.1) ... 503s Setting up libiksemel3:s390x (1.4-4build2) ... 503s Setting up libodbc2:s390x (2.3.12-1ubuntu1) ... 503s Setting up liburiparser1:s390x (0.9.8+dfsg-2) ... 503s Setting up libspeexdsp1:s390x (1.2.1-1ubuntu3) ... 503s Setting up liblua5.1-0:s390x (5.1.5-10) ... 503s Setting up libxslt1.1:s390x (1.1.39-0exp1ubuntu2) ... 503s Setting up libopencore-amrnb0:s390x (0.1.6-1build1) ... 503s Setting up libc-client2007e (8:2007f~dfsg-7.1) ... 503s Setting up libresample1 (0.1.3-8) ... 503s Setting up freetds-common (1.3.17+ds-2build3) ... 503s Setting up libgmime-3.0-0t64:s390x (3.2.15+dfsg-1) ... 503s Setting up libsamplerate0:s390x (0.2.2-4build1) ... 503s Setting up libopusfile0:s390x (0.12-4build3) ... 503s Setting up libvorbisenc2:s390x (1.3.7-2) ... 503s Setting up libjpeg8:s390x (8c-2ubuntu11) ... 503s Setting up libopusenc0:s390x (0.2.1-2build1) ... 503s Setting up libsnmp40t64:s390x (5.9.4+dfsg-1.1ubuntu5) ... 503s Setting up libsybdb5:s390x (1.3.17+ds-2build3) ... 503s Setting up libvorbisfile3:s390x (1.3.7-2) ... 503s Setting up libjack-jackd2-0:s390x (1.9.22~dfsg-4) ... 503s Setting up libtiff6:s390x (4.5.1+git230720-4ubuntu4) ... 503s Setting up libportaudio2:s390x (19.6.0-1.2build3) ... 503s Setting up libspandsp2t64:s390x (0.0.6+dfsg-2.1build1) ... 503s Setting up asterisk-modules (1:22.1.0~dfsg+~cs6.14.60671435-1) ... 503s Setting up asterisk (1:22.1.0~dfsg+~cs6.14.60671435-1) ... 503s Adding system user for Asterisk 503s info: Adding user `asterisk' to group `dialout' ... 503s info: Adding user `asterisk' to group `audio' ... 503s Created symlink '/etc/systemd/system/multi-user.target.wants/asterisk.service' → '/usr/lib/systemd/system/asterisk.service'. 504s Processing triggers for man-db (2.13.0-1) ... 505s Processing triggers for libc-bin (2.40-4ubuntu1) ... 525s autopkgtest [08:25:45]: test amr: [----------------------- 526s 1 audio amr amr 0 (AMR) 526s 2 audio amrwb amrwb 0 (AMR-WB) 526s amr amrwb codec2 ulaw alaw gsm g726 g726aal2 adpcm slin8 slin12 slin16 slin24 slin32 slin44 slin48 slin96 slin192 lpc10 speex8 speex16 speex32 g722 opus 526s amr - 23000 15000 15000 15000 15000 15000 15000 15000 9000 17000 17000 17000 17000 17000 17000 17000 17000 15000 15000 23000 23000 17250 15000 526s amr amrwb codec2 ulaw alaw gsm g726 g726aal2 adpcm slin8 slin12 slin16 slin24 slin32 slin44 slin48 slin96 slin192 lpc10 speex8 speex16 speex32 g722 opus 526s amrwb 23500 - 23500 23500 23500 23500 23500 23500 23500 17500 17500 9000 17000 17000 17000 17000 17000 17000 23500 23500 15000 23000 15000 14999 526s autopkgtest [08:25:46]: test amr: -----------------------] 526s amr PASS 526s autopkgtest [08:25:46]: test amr: - - - - - - - - - - results - - - - - - - - - - 527s autopkgtest [08:25:47]: @@@@@@@@@@@@@@@@@@@@ summary 527s asttestmods PASS 527s amr PASS 544s nova [W] Using flock in prodstack6-s390x 544s Creating nova instance adt-plucky-s390x-asterisk-20250114-081700-juju-7f2275-prod-proposed-migration-environment-20-c97fc488-9475-4004-94b9-f4e1503b5ac5 from image adt/ubuntu-plucky-s390x-server-20250114.img (UUID 3f50fe0a-1e1d-40bd-b69f-120c0091b5d9)... 544s nova [W] Timed out waiting for 01d767d9-c1f1-4c8d-8127-f22c772774a0 to get deleted. 544s nova [W] Using flock in prodstack6-s390x 544s Creating nova instance adt-plucky-s390x-asterisk-20250114-081700-juju-7f2275-prod-proposed-migration-environment-20-c97fc488-9475-4004-94b9-f4e1503b5ac5 from image adt/ubuntu-plucky-s390x-server-20250114.img (UUID 3f50fe0a-1e1d-40bd-b69f-120c0091b5d9)... 544s nova [W] Timed out waiting for eb878ccd-b076-46ab-9052-62d9f51db87e to get deleted.