0s autopkgtest [14:30:39]: starting date: 2024-03-18 0s autopkgtest [14:30:39]: git checkout: 399018f5 lib/adt_testbed.py: Fix supression of warning messages from apt 0s autopkgtest [14:30:39]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.5noht3vv/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:openssl --apt-upgrade asterisk --timeout-short=300 --timeout-copy=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=openssl/3.0.13-0ubuntu2 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos03-arm64-15.secgroup --name adt-noble-arm64-asterisk-20240318-143039-juju-7f2275-prod-proposed-migration-environment-2 --image adt/ubuntu-noble-arm64-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-2 --net-id=net_prod-proposed-migration -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 66s autopkgtest [14:31:45]: @@@@@@@@@@@@@@@@@@@@ test bed setup 66s Get:1 http://ftpmaster.internal/ubuntu noble-proposed InRelease [117 kB] 66s Get:2 http://ftpmaster.internal/ubuntu noble-proposed/main Sources [485 kB] 67s Get:3 http://ftpmaster.internal/ubuntu noble-proposed/multiverse Sources [52.0 kB] 67s Get:4 http://ftpmaster.internal/ubuntu noble-proposed/universe Sources [3728 kB] 67s Get:5 http://ftpmaster.internal/ubuntu noble-proposed/restricted Sources [6540 B] 67s Get:6 http://ftpmaster.internal/ubuntu noble-proposed/main arm64 Packages [654 kB] 67s Get:7 http://ftpmaster.internal/ubuntu noble-proposed/main arm64 c-n-f Metadata [3144 B] 67s Get:8 http://ftpmaster.internal/ubuntu noble-proposed/restricted arm64 Packages [33.6 kB] 67s Get:9 http://ftpmaster.internal/ubuntu noble-proposed/restricted arm64 c-n-f Metadata [116 B] 67s Get:10 http://ftpmaster.internal/ubuntu noble-proposed/universe arm64 Packages [4103 kB] 67s Get:11 http://ftpmaster.internal/ubuntu noble-proposed/universe arm64 c-n-f Metadata [8528 B] 67s Get:12 http://ftpmaster.internal/ubuntu noble-proposed/multiverse arm64 Packages [55.5 kB] 67s Get:13 http://ftpmaster.internal/ubuntu noble-proposed/multiverse arm64 c-n-f Metadata [116 B] 69s Fetched 9246 kB in 2s (4859 kB/s) 69s Reading package lists... 71s Reading package lists... 72s Building dependency tree... 72s Reading state information... 72s Calculating upgrade... 72s The following packages will be REMOVED: 72s libssl3 72s The following NEW packages will be installed: 72s libssl3t64 72s The following packages will be upgraded: 72s openssl 73s 1 upgraded, 1 newly installed, 1 to remove and 0 not upgraded. 73s Need to get 2777 kB of archives. 73s After this operation, 139 kB of additional disk space will be used. 73s Get:1 http://ftpmaster.internal/ubuntu noble-proposed/main arm64 openssl arm64 3.0.13-0ubuntu2 [985 kB] 75s Get:2 http://ftpmaster.internal/ubuntu noble-proposed/main arm64 libssl3t64 arm64 3.0.13-0ubuntu2 [1793 kB] 75s Fetched 2777 kB in 1s (3727 kB/s) 75s (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 ... 74758 files and directories currently installed.) 75s Preparing to unpack .../openssl_3.0.13-0ubuntu2_arm64.deb ... 75s Unpacking openssl (3.0.13-0ubuntu2) over (3.0.10-1ubuntu4) ... 75s dpkg: libssl3:arm64: dependency problems, but removing anyway as you requested: 75s wget depends on libssl3 (>= 3.0.0). 75s u-boot-tools depends on libssl3 (>= 3.0.0). 75s tnftp depends on libssl3 (>= 3.0.0). 75s tcpdump depends on libssl3 (>= 3.0.0). 75s systemd-resolved depends on libssl3 (>= 3.0.0). 75s systemd depends on libssl3 (>= 3.0.0). 75s sudo depends on libssl3 (>= 3.0.0). 75s sbsigntool depends on libssl3 (>= 3.0.0). 75s rsync depends on libssl3 (>= 3.0.0). 75s python3-cryptography depends on libssl3 (>= 3.0.0). 75s openssh-server depends on libssl3 (>= 3.0.10). 75s openssh-client depends on libssl3 (>= 3.0.10). 75s mtd-utils depends on libssl3 (>= 3.0.0). 75s mokutil depends on libssl3 (>= 3.0.0). 75s linux-headers-6.8.0-11-generic depends on libssl3 (>= 3.0.0). 75s libsystemd-shared:arm64 depends on libssl3 (>= 3.0.0). 75s libssh-4:arm64 depends on libssl3 (>= 3.0.0). 75s libsasl2-modules:arm64 depends on libssl3 (>= 3.0.0). 75s libsasl2-2:arm64 depends on libssl3 (>= 3.0.0). 75s libpython3.12-minimal:arm64 depends on libssl3 (>= 3.0.0). 75s libnvme1 depends on libssl3 (>= 3.0.0). 75s libkrb5-3:arm64 depends on libssl3 (>= 3.0.0). 75s libkmod2:arm64 depends on libssl3 (>= 3.0.0). 75s libfido2-1:arm64 depends on libssl3 (>= 3.0.0). 75s libcurl4:arm64 depends on libssl3 (>= 3.0.0). 75s libcryptsetup12:arm64 depends on libssl3 (>= 3.0.0). 75s kmod depends on libssl3 (>= 3.0.0). 75s dhcpcd-base depends on libssl3 (>= 3.0.0). 75s bind9-libs:arm64 depends on libssl3 (>= 3.0.0). 75s 75s (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 ... 74758 files and directories currently installed.) 75s Removing libssl3:arm64 (3.0.10-1ubuntu4) ... 75s Selecting previously unselected package libssl3t64:arm64. 75s (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 ... 74747 files and directories currently installed.) 75s Preparing to unpack .../libssl3t64_3.0.13-0ubuntu2_arm64.deb ... 75s Unpacking libssl3t64:arm64 (3.0.13-0ubuntu2) ... 75s Setting up libssl3t64:arm64 (3.0.13-0ubuntu2) ... 75s Setting up openssl (3.0.13-0ubuntu2) ... 75s Processing triggers for man-db (2.12.0-3) ... 75s Processing triggers for libc-bin (2.39-0ubuntu2) ... 75s Reading package lists... 75s Building dependency tree... 75s Reading state information... 76s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 76s Hit:1 http://ftpmaster.internal/ubuntu noble InRelease 76s Hit:2 http://ftpmaster.internal/ubuntu noble-updates InRelease 76s Hit:3 http://ftpmaster.internal/ubuntu noble-security InRelease 76s Hit:4 http://ftpmaster.internal/ubuntu noble-proposed InRelease 78s Reading package lists... 78s Reading package lists... 78s Building dependency tree... 78s Reading state information... 78s Calculating upgrade... 79s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 79s Reading package lists... 79s Building dependency tree... 79s Reading state information... 80s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 80s autopkgtest [14:31:59]: testbed dpkg architecture: arm64 81s autopkgtest [14:32:00]: testbed running kernel: Linux 6.8.0-11-generic #11-Ubuntu SMP PREEMPT_DYNAMIC Wed Feb 14 02:53:31 UTC 2024 81s autopkgtest [14:32:00]: @@@@@@@@@@@@@@@@@@@@ apt-source asterisk 86s Get:1 http://ftpmaster.internal/ubuntu noble/universe asterisk 1:20.6.0~dfsg+~cs6.13.40431414-2 (dsc) [5333 B] 86s Get:2 http://ftpmaster.internal/ubuntu noble/universe asterisk 1:20.6.0~dfsg+~cs6.13.40431414-2 (tar) [11.3 kB] 86s Get:3 http://ftpmaster.internal/ubuntu noble/universe asterisk 1:20.6.0~dfsg+~cs6.13.40431414-2 (tar) [21.9 kB] 86s Get:4 http://ftpmaster.internal/ubuntu noble/universe asterisk 1:20.6.0~dfsg+~cs6.13.40431414-2 (tar) [22.5 kB] 86s Get:5 http://ftpmaster.internal/ubuntu noble/universe asterisk 1:20.6.0~dfsg+~cs6.13.40431414-2 (tar) [5841 kB] 86s Get:6 http://ftpmaster.internal/ubuntu noble/universe asterisk 1:20.6.0~dfsg+~cs6.13.40431414-2 (tar) [7300 kB] 86s Get:7 http://ftpmaster.internal/ubuntu noble/universe asterisk 1:20.6.0~dfsg+~cs6.13.40431414-2 (diff) [135 kB] 86s gpgv: Signature made Tue Jan 30 14:24:07 2024 UTC 86s gpgv: using RSA key 9FE3E9C36691A69FF53CC6842C7C3146C1A00121 86s gpgv: Can't check signature: No public key 86s dpkg-source: warning: cannot verify inline signature for ./asterisk_20.6.0~dfsg+~cs6.13.40431414-2.dsc: no acceptable signature found 87s autopkgtest [14:32:06]: testing package asterisk version 1:20.6.0~dfsg+~cs6.13.40431414-2 87s autopkgtest [14:32:06]: build not needed 105s autopkgtest [14:32:24]: test asttestmods: preparing testbed 109s Reading package lists... 109s Building dependency tree... 109s Reading state information... 109s Correcting dependencies...Starting pkgProblemResolver with broken count: 0 109s Starting 2 pkgProblemResolver with broken count: 0 109s Done 110s Done 110s Starting pkgProblemResolver with broken count: 0 110s Starting 2 pkgProblemResolver with broken count: 0 110s Done 111s The following additional packages will be installed: 111s asterisk asterisk-config asterisk-core-sounds-en asterisk-core-sounds-en-gsm 111s asterisk-modules asterisk-tests freetds-common libasound2 libasound2-data 111s libc-client2007e libcodec2-1.2 libdeflate0 libevent-2.1-7 libgmime-3.0-0 111s libgsm1 libical3 libiksemel3 libjack-jackd2-0 libjbig0 libjpeg-turbo8 111s libjpeg8 liblerc4 libltdl7 liblua5.1-0 libneon27 libodbc2 libogg0 111s libopencore-amrnb0 libopencore-amrwb0 libopus0 libopusenc0 libopusfile0 111s libportaudio2 libpq5 libradcli4 libresample1 libsamplerate0 libsharpyuv0 111s libsnmp-base libsnmp40 libspandsp2 libspeex1 libspeexdsp1 libsrtp2-1 111s libsybdb5 libtiff6 libunbound8 liburiparser1 libvo-amrwbenc0 libvorbis0a 111s libvorbisenc2 libvorbisfile3 libwebp7 libxml2-utils libxslt1.1 mlock 111s Suggested packages: 111s asterisk-dahdi asterisk-dev asterisk-doc asterisk-ooh323 asterisk-opus 111s libasound2-plugins alsa-utils uw-mailutils jackd2 odbc-postgresql tdsodbc 111s opus-tools snmp-mibs-downloader speex 111s Recommended packages: 111s asterisk-moh-opsound-gsm sox alsa-ucm-conf alsa-topology-conf 111s The following NEW packages will be installed: 111s asterisk asterisk-config asterisk-core-sounds-en asterisk-core-sounds-en-gsm 111s asterisk-modules asterisk-tests freetds-common libasound2 libasound2-data 111s libc-client2007e libcodec2-1.2 libdeflate0 libevent-2.1-7 libgmime-3.0-0 111s libgsm1 libical3 libiksemel3 libjack-jackd2-0 libjbig0 libjpeg-turbo8 111s libjpeg8 liblerc4 libltdl7 liblua5.1-0 libneon27 libodbc2 libogg0 111s libopencore-amrnb0 libopencore-amrwb0 libopus0 libopusenc0 libopusfile0 111s libportaudio2 libpq5 libradcli4 libresample1 libsamplerate0 libsharpyuv0 111s libsnmp-base libsnmp40 libspandsp2 libspeex1 libspeexdsp1 libsrtp2-1 111s libsybdb5 libtiff6 libunbound8 liburiparser1 libvo-amrwbenc0 libvorbis0a 111s libvorbisenc2 libvorbisfile3 libwebp7 libxml2-utils libxslt1.1 mlock 111s 0 upgraded, 56 newly installed, 0 to remove and 0 not upgraded. 111s 1 not fully installed or removed. 111s Need to get 26.1 MB of archives. 111s After this operation, 90.3 MB of additional disk space will be used. 111s Get:1 http://ftpmaster.internal/ubuntu noble/universe arm64 asterisk-config all 1:20.6.0~dfsg+~cs6.13.40431414-2 [242 kB] 111s Get:2 http://ftpmaster.internal/ubuntu noble/universe arm64 asterisk-core-sounds-en-gsm all 1.6.1-1 [2417 kB] 112s Get:3 http://ftpmaster.internal/ubuntu noble/universe arm64 asterisk-core-sounds-en all 1.6.1-1 [20.6 kB] 112s Get:4 http://ftpmaster.internal/ubuntu noble/universe arm64 mlock arm64 8:2007f~dfsg-7build1 [11.8 kB] 112s Get:5 http://ftpmaster.internal/ubuntu noble/universe arm64 libc-client2007e arm64 8:2007f~dfsg-7build1 [648 kB] 112s Get:6 http://ftpmaster.internal/ubuntu noble/universe arm64 libcodec2-1.2 arm64 1.2.0-2 [8995 kB] 112s Get:7 http://ftpmaster.internal/ubuntu noble/universe arm64 libgmime-3.0-0 arm64 3.2.13+dfsg-2 [168 kB] 112s Get:8 http://ftpmaster.internal/ubuntu noble/universe arm64 libgsm1 arm64 1.0.22-1 [26.3 kB] 112s Get:9 http://ftpmaster.internal/ubuntu noble/main arm64 libical3 arm64 3.0.17-1build1 [299 kB] 112s Get:10 http://ftpmaster.internal/ubuntu noble/universe arm64 libiksemel3 arm64 1.4-4 [28.3 kB] 112s Get:11 http://ftpmaster.internal/ubuntu noble/main arm64 libopus0 arm64 1.4-1 [194 kB] 112s Get:12 http://ftpmaster.internal/ubuntu noble/main arm64 libsamplerate0 arm64 0.2.2-4 [1342 kB] 112s Get:13 http://ftpmaster.internal/ubuntu noble/main arm64 libjack-jackd2-0 arm64 1.9.21~dfsg-3 [281 kB] 112s Get:14 http://ftpmaster.internal/ubuntu noble/universe arm64 liblua5.1-0 arm64 5.1.5-9 [115 kB] 112s Get:15 http://ftpmaster.internal/ubuntu noble/universe arm64 libneon27 arm64 0.33.0-1 [101 kB] 112s Get:16 http://ftpmaster.internal/ubuntu noble/main arm64 libltdl7 arm64 2.4.7-7 [40.3 kB] 112s Get:17 http://ftpmaster.internal/ubuntu noble/main arm64 libodbc2 arm64 2.3.12-1 [144 kB] 112s Get:18 http://ftpmaster.internal/ubuntu noble/main arm64 libogg0 arm64 1.3.5-3 [22.1 kB] 112s Get:19 http://ftpmaster.internal/ubuntu noble/universe arm64 libopencore-amrnb0 arm64 0.1.6-1 [96.2 kB] 112s Get:20 http://ftpmaster.internal/ubuntu noble/universe arm64 libopencore-amrwb0 arm64 0.1.6-1 [49.5 kB] 112s Get:21 http://ftpmaster.internal/ubuntu noble/universe arm64 libopusenc0 arm64 0.2.1-2 [24.9 kB] 112s Get:22 http://ftpmaster.internal/ubuntu noble/universe arm64 libopusfile0 arm64 0.12-4 [44.5 kB] 112s Get:23 http://ftpmaster.internal/ubuntu noble/main arm64 libasound2-data all 1.2.10-3build1 [20.7 kB] 112s Get:24 http://ftpmaster.internal/ubuntu noble/main arm64 libasound2 arm64 1.2.10-3build1 [386 kB] 112s Get:25 http://ftpmaster.internal/ubuntu noble/universe arm64 libportaudio2 arm64 19.6.0-1.2 [65.8 kB] 112s Get:26 http://ftpmaster.internal/ubuntu noble/main arm64 libpq5 arm64 16.2-1 [136 kB] 112s Get:27 http://ftpmaster.internal/ubuntu noble/universe arm64 libradcli4 arm64 1.2.11-1build1 [37.6 kB] 112s Get:28 http://ftpmaster.internal/ubuntu noble/universe arm64 libresample1 arm64 0.1.3-6 [8522 B] 112s Get:29 http://ftpmaster.internal/ubuntu noble/main arm64 libsnmp-base all 5.9.4+dfsg-1ubuntu2 [206 kB] 112s Get:30 http://ftpmaster.internal/ubuntu noble/main arm64 libsnmp40 arm64 5.9.4+dfsg-1ubuntu2 [1055 kB] 112s Get:31 http://ftpmaster.internal/ubuntu noble/main arm64 libdeflate0 arm64 1.19-1 [43.4 kB] 112s Get:32 http://ftpmaster.internal/ubuntu noble/main arm64 libjbig0 arm64 2.1-6.1ubuntu1 [28.9 kB] 112s Get:33 http://ftpmaster.internal/ubuntu noble/main arm64 libjpeg-turbo8 arm64 2.1.5-2ubuntu1 [160 kB] 112s Get:34 http://ftpmaster.internal/ubuntu noble/main arm64 libjpeg8 arm64 8c-2ubuntu11 [2148 B] 112s Get:35 http://ftpmaster.internal/ubuntu noble/main arm64 liblerc4 arm64 4.0.0+ds-4ubuntu1 [153 kB] 112s Get:36 http://ftpmaster.internal/ubuntu noble/main arm64 libsharpyuv0 arm64 1.3.2-0.4 [14.4 kB] 112s Get:37 http://ftpmaster.internal/ubuntu noble/main arm64 libwebp7 arm64 1.3.2-0.4 [191 kB] 112s Get:38 http://ftpmaster.internal/ubuntu noble/main arm64 libtiff6 arm64 4.5.1+git230720-3ubuntu1 [226 kB] 112s Get:39 http://ftpmaster.internal/ubuntu noble/universe arm64 libspandsp2 arm64 0.0.6+dfsg-2build1 [308 kB] 112s Get:40 http://ftpmaster.internal/ubuntu noble/main arm64 libspeex1 arm64 1.2.1-2ubuntu1 [55.1 kB] 112s Get:41 http://ftpmaster.internal/ubuntu noble/main arm64 libspeexdsp1 arm64 1.2.1-1ubuntu2 [40.1 kB] 112s Get:42 http://ftpmaster.internal/ubuntu noble/universe arm64 libsrtp2-1 arm64 2.5.0-3 [41.5 kB] 112s Get:43 http://ftpmaster.internal/ubuntu noble/main arm64 freetds-common all 1.3.17+ds-2 [26.8 kB] 112s Get:44 http://ftpmaster.internal/ubuntu noble/main arm64 libsybdb5 arm64 1.3.17+ds-2 [184 kB] 112s Get:45 http://ftpmaster.internal/ubuntu noble/main arm64 libevent-2.1-7 arm64 2.1.12-stable-9 [138 kB] 112s Get:46 http://ftpmaster.internal/ubuntu noble/main arm64 libunbound8 arm64 1.19.1-1ubuntu1 [423 kB] 112s Get:47 http://ftpmaster.internal/ubuntu noble/universe arm64 libvo-amrwbenc0 arm64 0.1.3-2 [65.9 kB] 112s Get:48 http://ftpmaster.internal/ubuntu noble/main arm64 libvorbis0a arm64 1.3.7-1build2 [95.5 kB] 112s Get:49 http://ftpmaster.internal/ubuntu noble/main arm64 libvorbisenc2 arm64 1.3.7-1build2 [82.3 kB] 112s Get:50 http://ftpmaster.internal/ubuntu noble/main arm64 libvorbisfile3 arm64 1.3.7-1build2 [16.8 kB] 112s Get:51 http://ftpmaster.internal/ubuntu noble/universe arm64 asterisk-modules arm64 1:20.6.0~dfsg+~cs6.13.40431414-2 [3216 kB] 112s Get:52 http://ftpmaster.internal/ubuntu noble/universe arm64 liburiparser1 arm64 0.9.7+dfsg-2 [34.0 kB] 112s Get:53 http://ftpmaster.internal/ubuntu noble/main arm64 libxslt1.1 arm64 1.1.35-1 [161 kB] 112s Get:54 http://ftpmaster.internal/ubuntu noble/universe arm64 asterisk arm64 1:20.6.0~dfsg+~cs6.13.40431414-2 [2585 kB] 112s Get:55 http://ftpmaster.internal/ubuntu noble/universe arm64 asterisk-tests arm64 1:20.6.0~dfsg+~cs6.13.40431414-2 [544 kB] 112s Get:56 http://ftpmaster.internal/ubuntu noble/main arm64 libxml2-utils arm64 2.9.14+dfsg-1.3ubuntu1 [39.2 kB] 113s Fetched 26.1 MB in 2s (17.3 MB/s) 113s Selecting previously unselected package asterisk-config. 113s (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 ... 74760 files and directories currently installed.) 113s Preparing to unpack .../00-asterisk-config_1%3a20.6.0~dfsg+~cs6.13.40431414-2_all.deb ... 113s Unpacking asterisk-config (1:20.6.0~dfsg+~cs6.13.40431414-2) ... 113s Selecting previously unselected package asterisk-core-sounds-en-gsm. 113s Preparing to unpack .../01-asterisk-core-sounds-en-gsm_1.6.1-1_all.deb ... 113s Unpacking asterisk-core-sounds-en-gsm (1.6.1-1) ... 113s Selecting previously unselected package asterisk-core-sounds-en. 113s Preparing to unpack .../02-asterisk-core-sounds-en_1.6.1-1_all.deb ... 113s Unpacking asterisk-core-sounds-en (1.6.1-1) ... 113s Selecting previously unselected package mlock. 113s Preparing to unpack .../03-mlock_8%3a2007f~dfsg-7build1_arm64.deb ... 113s Unpacking mlock (8:2007f~dfsg-7build1) ... 113s Selecting previously unselected package libc-client2007e. 113s Preparing to unpack .../04-libc-client2007e_8%3a2007f~dfsg-7build1_arm64.deb ... 113s Unpacking libc-client2007e (8:2007f~dfsg-7build1) ... 113s Selecting previously unselected package libcodec2-1.2:arm64. 113s Preparing to unpack .../05-libcodec2-1.2_1.2.0-2_arm64.deb ... 113s Unpacking libcodec2-1.2:arm64 (1.2.0-2) ... 113s Selecting previously unselected package libgmime-3.0-0:arm64. 113s Preparing to unpack .../06-libgmime-3.0-0_3.2.13+dfsg-2_arm64.deb ... 113s Unpacking libgmime-3.0-0:arm64 (3.2.13+dfsg-2) ... 113s Selecting previously unselected package libgsm1:arm64. 113s Preparing to unpack .../07-libgsm1_1.0.22-1_arm64.deb ... 113s Unpacking libgsm1:arm64 (1.0.22-1) ... 113s Selecting previously unselected package libical3:arm64. 113s Preparing to unpack .../08-libical3_3.0.17-1build1_arm64.deb ... 113s Unpacking libical3:arm64 (3.0.17-1build1) ... 113s Selecting previously unselected package libiksemel3:arm64. 113s Preparing to unpack .../09-libiksemel3_1.4-4_arm64.deb ... 113s Unpacking libiksemel3:arm64 (1.4-4) ... 113s Selecting previously unselected package libopus0:arm64. 113s Preparing to unpack .../10-libopus0_1.4-1_arm64.deb ... 113s Unpacking libopus0:arm64 (1.4-1) ... 113s Selecting previously unselected package libsamplerate0:arm64. 113s Preparing to unpack .../11-libsamplerate0_0.2.2-4_arm64.deb ... 113s Unpacking libsamplerate0:arm64 (0.2.2-4) ... 113s Selecting previously unselected package libjack-jackd2-0:arm64. 113s Preparing to unpack .../12-libjack-jackd2-0_1.9.21~dfsg-3_arm64.deb ... 113s Unpacking libjack-jackd2-0:arm64 (1.9.21~dfsg-3) ... 113s Selecting previously unselected package liblua5.1-0:arm64. 113s Preparing to unpack .../13-liblua5.1-0_5.1.5-9_arm64.deb ... 113s Unpacking liblua5.1-0:arm64 (5.1.5-9) ... 114s Selecting previously unselected package libneon27:arm64. 114s Preparing to unpack .../14-libneon27_0.33.0-1_arm64.deb ... 114s Unpacking libneon27:arm64 (0.33.0-1) ... 114s Selecting previously unselected package libltdl7:arm64. 114s Preparing to unpack .../15-libltdl7_2.4.7-7_arm64.deb ... 114s Unpacking libltdl7:arm64 (2.4.7-7) ... 114s Selecting previously unselected package libodbc2:arm64. 114s Preparing to unpack .../16-libodbc2_2.3.12-1_arm64.deb ... 114s Unpacking libodbc2:arm64 (2.3.12-1) ... 114s Selecting previously unselected package libogg0:arm64. 114s Preparing to unpack .../17-libogg0_1.3.5-3_arm64.deb ... 114s Unpacking libogg0:arm64 (1.3.5-3) ... 114s Selecting previously unselected package libopencore-amrnb0:arm64. 114s Preparing to unpack .../18-libopencore-amrnb0_0.1.6-1_arm64.deb ... 114s Unpacking libopencore-amrnb0:arm64 (0.1.6-1) ... 114s Selecting previously unselected package libopencore-amrwb0:arm64. 114s Preparing to unpack .../19-libopencore-amrwb0_0.1.6-1_arm64.deb ... 114s Unpacking libopencore-amrwb0:arm64 (0.1.6-1) ... 114s Selecting previously unselected package libopusenc0:arm64. 114s Preparing to unpack .../20-libopusenc0_0.2.1-2_arm64.deb ... 114s Unpacking libopusenc0:arm64 (0.2.1-2) ... 114s Selecting previously unselected package libopusfile0:arm64. 114s Preparing to unpack .../21-libopusfile0_0.12-4_arm64.deb ... 114s Unpacking libopusfile0:arm64 (0.12-4) ... 114s Selecting previously unselected package libasound2-data. 114s Preparing to unpack .../22-libasound2-data_1.2.10-3build1_all.deb ... 114s Unpacking libasound2-data (1.2.10-3build1) ... 114s Selecting previously unselected package libasound2:arm64. 114s Preparing to unpack .../23-libasound2_1.2.10-3build1_arm64.deb ... 114s Unpacking libasound2:arm64 (1.2.10-3build1) ... 114s Selecting previously unselected package libportaudio2:arm64. 114s Preparing to unpack .../24-libportaudio2_19.6.0-1.2_arm64.deb ... 114s Unpacking libportaudio2:arm64 (19.6.0-1.2) ... 114s Selecting previously unselected package libpq5:arm64. 114s Preparing to unpack .../25-libpq5_16.2-1_arm64.deb ... 114s Unpacking libpq5:arm64 (16.2-1) ... 114s Selecting previously unselected package libradcli4. 114s Preparing to unpack .../26-libradcli4_1.2.11-1build1_arm64.deb ... 114s Unpacking libradcli4 (1.2.11-1build1) ... 114s Selecting previously unselected package libresample1. 114s Preparing to unpack .../27-libresample1_0.1.3-6_arm64.deb ... 114s Unpacking libresample1 (0.1.3-6) ... 114s Selecting previously unselected package libsnmp-base. 114s Preparing to unpack .../28-libsnmp-base_5.9.4+dfsg-1ubuntu2_all.deb ... 114s Unpacking libsnmp-base (5.9.4+dfsg-1ubuntu2) ... 114s Selecting previously unselected package libsnmp40:arm64. 114s Preparing to unpack .../29-libsnmp40_5.9.4+dfsg-1ubuntu2_arm64.deb ... 114s Unpacking libsnmp40:arm64 (5.9.4+dfsg-1ubuntu2) ... 114s Selecting previously unselected package libdeflate0:arm64. 114s Preparing to unpack .../30-libdeflate0_1.19-1_arm64.deb ... 114s Unpacking libdeflate0:arm64 (1.19-1) ... 114s Selecting previously unselected package libjbig0:arm64. 114s Preparing to unpack .../31-libjbig0_2.1-6.1ubuntu1_arm64.deb ... 114s Unpacking libjbig0:arm64 (2.1-6.1ubuntu1) ... 114s Selecting previously unselected package libjpeg-turbo8:arm64. 114s Preparing to unpack .../32-libjpeg-turbo8_2.1.5-2ubuntu1_arm64.deb ... 114s Unpacking libjpeg-turbo8:arm64 (2.1.5-2ubuntu1) ... 114s Selecting previously unselected package libjpeg8:arm64. 114s Preparing to unpack .../33-libjpeg8_8c-2ubuntu11_arm64.deb ... 114s Unpacking libjpeg8:arm64 (8c-2ubuntu11) ... 114s Selecting previously unselected package liblerc4:arm64. 114s Preparing to unpack .../34-liblerc4_4.0.0+ds-4ubuntu1_arm64.deb ... 114s Unpacking liblerc4:arm64 (4.0.0+ds-4ubuntu1) ... 114s Selecting previously unselected package libsharpyuv0:arm64. 114s Preparing to unpack .../35-libsharpyuv0_1.3.2-0.4_arm64.deb ... 114s Unpacking libsharpyuv0:arm64 (1.3.2-0.4) ... 114s Selecting previously unselected package libwebp7:arm64. 114s Preparing to unpack .../36-libwebp7_1.3.2-0.4_arm64.deb ... 114s Unpacking libwebp7:arm64 (1.3.2-0.4) ... 114s Selecting previously unselected package libtiff6:arm64. 114s Preparing to unpack .../37-libtiff6_4.5.1+git230720-3ubuntu1_arm64.deb ... 114s Unpacking libtiff6:arm64 (4.5.1+git230720-3ubuntu1) ... 114s Selecting previously unselected package libspandsp2:arm64. 114s Preparing to unpack .../38-libspandsp2_0.0.6+dfsg-2build1_arm64.deb ... 114s Unpacking libspandsp2:arm64 (0.0.6+dfsg-2build1) ... 114s Selecting previously unselected package libspeex1:arm64. 114s Preparing to unpack .../39-libspeex1_1.2.1-2ubuntu1_arm64.deb ... 114s Unpacking libspeex1:arm64 (1.2.1-2ubuntu1) ... 114s Selecting previously unselected package libspeexdsp1:arm64. 114s Preparing to unpack .../40-libspeexdsp1_1.2.1-1ubuntu2_arm64.deb ... 114s Unpacking libspeexdsp1:arm64 (1.2.1-1ubuntu2) ... 114s Selecting previously unselected package libsrtp2-1:arm64. 115s Preparing to unpack .../41-libsrtp2-1_2.5.0-3_arm64.deb ... 115s Unpacking libsrtp2-1:arm64 (2.5.0-3) ... 115s Selecting previously unselected package freetds-common. 115s Preparing to unpack .../42-freetds-common_1.3.17+ds-2_all.deb ... 115s Unpacking freetds-common (1.3.17+ds-2) ... 115s Selecting previously unselected package libsybdb5:arm64. 115s Preparing to unpack .../43-libsybdb5_1.3.17+ds-2_arm64.deb ... 115s Unpacking libsybdb5:arm64 (1.3.17+ds-2) ... 115s Selecting previously unselected package libevent-2.1-7:arm64. 115s Preparing to unpack .../44-libevent-2.1-7_2.1.12-stable-9_arm64.deb ... 115s Unpacking libevent-2.1-7:arm64 (2.1.12-stable-9) ... 115s Selecting previously unselected package libunbound8:arm64. 115s Preparing to unpack .../45-libunbound8_1.19.1-1ubuntu1_arm64.deb ... 115s Unpacking libunbound8:arm64 (1.19.1-1ubuntu1) ... 115s Selecting previously unselected package libvo-amrwbenc0:arm64. 115s Preparing to unpack .../46-libvo-amrwbenc0_0.1.3-2_arm64.deb ... 115s Unpacking libvo-amrwbenc0:arm64 (0.1.3-2) ... 115s Selecting previously unselected package libvorbis0a:arm64. 115s Preparing to unpack .../47-libvorbis0a_1.3.7-1build2_arm64.deb ... 115s Unpacking libvorbis0a:arm64 (1.3.7-1build2) ... 115s Selecting previously unselected package libvorbisenc2:arm64. 115s Preparing to unpack .../48-libvorbisenc2_1.3.7-1build2_arm64.deb ... 115s Unpacking libvorbisenc2:arm64 (1.3.7-1build2) ... 115s Selecting previously unselected package libvorbisfile3:arm64. 115s Preparing to unpack .../49-libvorbisfile3_1.3.7-1build2_arm64.deb ... 115s Unpacking libvorbisfile3:arm64 (1.3.7-1build2) ... 115s Selecting previously unselected package asterisk-modules. 115s Preparing to unpack .../50-asterisk-modules_1%3a20.6.0~dfsg+~cs6.13.40431414-2_arm64.deb ... 115s Unpacking asterisk-modules (1:20.6.0~dfsg+~cs6.13.40431414-2) ... 115s Selecting previously unselected package liburiparser1:arm64. 115s Preparing to unpack .../51-liburiparser1_0.9.7+dfsg-2_arm64.deb ... 115s Unpacking liburiparser1:arm64 (0.9.7+dfsg-2) ... 115s Selecting previously unselected package libxslt1.1:arm64. 115s Preparing to unpack .../52-libxslt1.1_1.1.35-1_arm64.deb ... 115s Unpacking libxslt1.1:arm64 (1.1.35-1) ... 115s Selecting previously unselected package asterisk. 115s Preparing to unpack .../53-asterisk_1%3a20.6.0~dfsg+~cs6.13.40431414-2_arm64.deb ... 115s Unpacking asterisk (1:20.6.0~dfsg+~cs6.13.40431414-2) ... 115s Selecting previously unselected package asterisk-tests. 115s Preparing to unpack .../54-asterisk-tests_1%3a20.6.0~dfsg+~cs6.13.40431414-2_arm64.deb ... 115s Unpacking asterisk-tests (1:20.6.0~dfsg+~cs6.13.40431414-2) ... 115s Selecting previously unselected package libxml2-utils. 115s Preparing to unpack .../55-libxml2-utils_2.9.14+dfsg-1.3ubuntu1_arm64.deb ... 115s Unpacking libxml2-utils (2.9.14+dfsg-1.3ubuntu1) ... 115s Setting up libgmime-3.0-0:arm64 (3.2.13+dfsg-2) ... 115s Setting up libsharpyuv0:arm64 (1.3.2-0.4) ... 115s Setting up libvo-amrwbenc0:arm64 (0.1.3-2) ... 115s Setting up libogg0:arm64 (1.3.5-3) ... 115s Setting up liblerc4:arm64 (4.0.0+ds-4ubuntu1) ... 115s Setting up libspeex1:arm64 (1.2.1-2ubuntu1) ... 115s Setting up libgsm1:arm64 (1.0.22-1) ... 115s Setting up asterisk-core-sounds-en-gsm (1.6.1-1) ... 115s Setting up libsnmp-base (5.9.4+dfsg-1ubuntu2) ... 115s Setting up libcodec2-1.2:arm64 (1.2.0-2) ... 115s Setting up mlock (8:2007f~dfsg-7build1) ... 115s Setting up libsrtp2-1:arm64 (2.5.0-3) ... 115s Setting up libpq5:arm64 (16.2-1) ... 115s Setting up libdeflate0:arm64 (1.19-1) ... 115s Setting up libjbig0:arm64 (2.1-6.1ubuntu1) ... 115s Setting up libasound2-data (1.2.10-3build1) ... 115s Setting up libopencore-amrwb0:arm64 (0.1.6-1) ... 115s Setting up libsnmp40:arm64 (5.9.4+dfsg-1ubuntu2) ... 115s Setting up libradcli4 (1.2.11-1build1) ... 115s Setting up libopus0:arm64 (1.4-1) ... 115s Setting up asterisk-config (1:20.6.0~dfsg+~cs6.13.40431414-2) ... 116s Setting up libvorbis0a:arm64 (1.3.7-1build2) ... 116s Setting up libevent-2.1-7:arm64 (2.1.12-stable-9) ... 116s Setting up libjpeg-turbo8:arm64 (2.1.5-2ubuntu1) ... 116s Setting up libltdl7:arm64 (2.4.7-7) ... 116s Setting up asterisk-core-sounds-en (1.6.1-1) ... 116s update-alternatives: using /usr/share/asterisk/sounds/en_US_f_Allison to provide /usr/share/asterisk/sounds/en (asterisk-prompt-en) in auto mode 116s 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 116s Setting up libwebp7:arm64 (1.3.2-0.4) ... 116s Setting up libiksemel3:arm64 (1.4-4) ... 116s Setting up libodbc2:arm64 (2.3.12-1) ... 116s Setting up liburiparser1:arm64 (0.9.7+dfsg-2) ... 116s Setting up libneon27:arm64 (0.33.0-1) ... 116s Setting up libspeexdsp1:arm64 (1.2.1-1ubuntu2) ... 116s Setting up libasound2:arm64 (1.2.10-3build1) ... 116s Setting up liblua5.1-0:arm64 (5.1.5-9) ... 116s Setting up libxslt1.1:arm64 (1.1.35-1) ... 116s Setting up libopencore-amrnb0:arm64 (0.1.6-1) ... 116s Setting up libical3:arm64 (3.0.17-1build1) ... 116s Setting up libc-client2007e (8:2007f~dfsg-7build1) ... 116s Setting up libresample1 (0.1.3-6) ... 116s Setting up freetds-common (1.3.17+ds-2) ... 116s Setting up libxml2-utils (2.9.14+dfsg-1.3ubuntu1) ... 116s Setting up libsamplerate0:arm64 (0.2.2-4) ... 116s Setting up libopusfile0:arm64 (0.12-4) ... 116s Setting up libvorbisenc2:arm64 (1.3.7-1build2) ... 116s Setting up libjpeg8:arm64 (8c-2ubuntu11) ... 116s Setting up libopusenc0:arm64 (0.2.1-2) ... 116s Setting up libsybdb5:arm64 (1.3.17+ds-2) ... 116s Setting up libvorbisfile3:arm64 (1.3.7-1build2) ... 116s Setting up libunbound8:arm64 (1.19.1-1ubuntu1) ... 116s Setting up libjack-jackd2-0:arm64 (1.9.21~dfsg-3) ... 116s Setting up libtiff6:arm64 (4.5.1+git230720-3ubuntu1) ... 116s Setting up libportaudio2:arm64 (19.6.0-1.2) ... 116s Setting up libspandsp2:arm64 (0.0.6+dfsg-2build1) ... 116s Setting up asterisk-modules (1:20.6.0~dfsg+~cs6.13.40431414-2) ... 116s Setting up asterisk (1:20.6.0~dfsg+~cs6.13.40431414-2) ... 116s Adding system user for Asterisk 116s info: Adding user `asterisk' to group `dialout' ... 116s info: Adding user `asterisk' to group `audio' ... 117s Created symlink /etc/systemd/system/multi-user.target.wants/asterisk.service → /usr/lib/systemd/system/asterisk.service. 118s Setting up asterisk-tests (1:20.6.0~dfsg+~cs6.13.40431414-2) ... 118s Setting up autopkgtest-satdep (0) ... 118s Processing triggers for man-db (2.12.0-3) ... 119s Processing triggers for libc-bin (2.39-0ubuntu2) ... 125s (Reading database ... 76823 files and directories currently installed.) 125s Removing autopkgtest-satdep (0) ... 126s autopkgtest [14:32:45]: test asttestmods: [----------------------- 126s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 128s 'U' option is not compatible with remote console mode and has no effect. 128s 128s Asterisk has fully booted. 128s 'U' option is not compatible with remote console mode and has no effect. 128s 128s Running all available tests... 128s 128s START /apps/app_gosub/ - gosub application 128s END /apps/app_gosub/ - gosub application Time: <1ms Result: PASS 128s START /apps/app_voicemail/ - test_voicemail_vm_info 128s END /apps/app_voicemail/ - test_voicemail_vm_info Time: <1ms Result: PASS 128s START /apps/app_voicemail/ - test_voicemail_load_config 128s END /apps/app_voicemail/ - test_voicemail_load_config Time: <1ms Result: PASS 128s START /apps/app_voicemail/ - test_voicemail_notify_endl 128s END /apps/app_voicemail/ - test_voicemail_notify_endl Time: 2ms Result: PASS 128s START /apps/app_voicemail/ - vmuser 128s END /apps/app_voicemail/ - vmuser Time: <1ms Result: PASS 128s START /apps/app_voicemail/ - test_voicemail_msgcount 128s END /apps/app_voicemail/ - test_voicemail_msgcount Time: 78ms Result: PASS 128s START /apps/app_voicemail/ - vmsayname_exec 128s [app_voicemail.c:test_voicemail_vmsayname:15218]: Test playing of extension when greeting is not available... 133s [app_voicemail.c:test_voicemail_vmsayname:15239]: Test playing created mailbox greeting... 137s END /apps/app_voicemail/ - vmsayname_exec Time: 8886ms Result: PASS 137s START /ari/validators/ - validate_list 137s END /ari/validators/ - validate_list Time: <1ms Result: PASS 137s START /ari/validators/ - validate_date 137s END /ari/validators/ - validate_date Time: <1ms Result: PASS 137s START /ari/validators/ - validate_string 137s END /ari/validators/ - validate_string Time: <1ms Result: PASS 137s START /ari/validators/ - validate_long 137s END /ari/validators/ - validate_long Time: <1ms Result: PASS 137s START /ari/validators/ - validate_int 137s END /ari/validators/ - validate_int Time: <1ms Result: PASS 137s START /ari/validators/ - validate_boolean 137s END /ari/validators/ - validate_boolean Time: <1ms Result: PASS 137s START /ari/validators/ - validate_byte 137s END /ari/validators/ - validate_byte Time: <1ms Result: PASS 137s START /bridges/bridge_softmix/ - sfu_remove_destination_streams 137s END /bridges/bridge_softmix/ - sfu_remove_destination_streams Time: <1ms Result: PASS 137s START /bridges/bridge_softmix/ - sfu_append_source_streams 137s END /bridges/bridge_softmix/ - sfu_append_source_streams Time: <1ms Result: PASS 137s START /channels/features/ - test_features_channel_interval 140s END /channels/features/ - test_features_channel_interval Time: 3002ms Result: PASS 140s START /channels/features/ - test_features_channel_dtmf 142s END /channels/features/ - test_features_channel_dtmf Time: 2010ms Result: PASS 142s START /config/ - config_options_test 142s END /config/ - config_options_test Time: <1ms Result: PASS 142s START /config/ - ast_parse_arg 142s END /config/ - ast_parse_arg Time: <1ms Result: PASS 142s START /core/endpoints/ - setters 142s END /core/endpoints/ - setters Time: <1ms Result: PASS 142s START /core/endpoints/ - defaults 142s END /core/endpoints/ - defaults Time: <1ms Result: PASS 142s START /core/endpoints/ - create 142s END /core/endpoints/ - create Time: <1ms Result: PASS 142s START /funcs/func_curl/ - vulnerable_url 142s END /funcs/func_curl/ - vulnerable_url Time: <1ms Result: PASS 142s START /funcs/func_env/ - func_file 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=a'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,1)=a'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-8)=a'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-8)=a'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5,1)=b'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4,1)=b'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5,-3)=b'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4,-3)=b'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2)=c'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,2)=c'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-7)=c'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-7)=c'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,4,2)=d'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-5,2)=d'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,4,-3)=d'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-5,-3)=d'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5)=e'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5)='... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4)=e'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4)='... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=fg'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-8)=fg'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,1)=fg'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-8)=fg'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,)=h'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,,)=h'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,l)=h'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,ld)=h'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abc'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=abc'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=abc'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=abc'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=abc'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=abc'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=abc'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=abc'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=ab'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=ab'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=ab'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=ab'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=ab'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=ab'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=ab'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=ab'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcdefg'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcdefg'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcdefg'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcdefg'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcdefg'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcdefg'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcdefg'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcdefg'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcdefghijklmnop'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcdefghijklmnop'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcdefghijklmnop'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcdefghijklmnop'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcdefghijklmnop'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcdefghijklmnop'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcdefghijklmnop'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcdefghijklmnop'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,0,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,0,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,0,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,0,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,2,0,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-1,0,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,3,0,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,la)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)='... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)='... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)='... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)='... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)='... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)='... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)='... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)='... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,ld)='... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,ld)='... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,ld)='... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,ld)='... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,ld)='... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,ld)='... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,ld)='... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,ld)='... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=a'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,10)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 142s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=a'... OK! 142s END /funcs/func_env/ - func_file Time: 26ms Result: PASS 142s START /funcs/func_json/ - func_JSON_DECODE 142s END /funcs/func_json/ - func_JSON_DECODE Time: <1ms Result: PASS 142s START /funcs/func_presence/ - test_presence_state_base64_encode 142s END /funcs/func_presence/ - test_presence_state_base64_encode Time: 4ms Result: PASS 142s START /funcs/func_presence/ - test_presence_state_change 142s END /funcs/func_presence/ - test_presence_state_change Time: <1ms Result: PASS 142s START /funcs/func_presence/ - parse_invalid_presence_data 142s END /funcs/func_presence/ - parse_invalid_presence_data Time: <1ms Result: PASS 142s START /funcs/func_presence/ - parse_valid_presence_data 142s END /funcs/func_presence/ - parse_valid_presence_data Time: <1ms Result: PASS 142s START /funcs/func_sayfiles/ - test_SAYFILES_function 142s [func_sayfiles.c:test_SAYFILES_function:180]: Testing SAYFILES() substitution ... 142s END /funcs/func_sayfiles/ - test_SAYFILES_function Time: 4ms Result: PASS 142s START /funcs/func_strings/ - func_TRIM 142s END /funcs/func_strings/ - func_TRIM Time: <1ms Result: PASS 142s START /funcs/func_strings/ - func_STRBETWEEN 142s END /funcs/func_strings/ - func_STRBETWEEN Time: <1ms Result: PASS 142s START /funcs/func_strings/ - func_STRREPLACE_test 142s END /funcs/func_strings/ - func_STRREPLACE_test Time: <1ms Result: PASS 142s START /funcs/func_strings/ - func_FILTER_test 142s END /funcs/func_strings/ - func_FILTER_test Time: <1ms Result: PASS 142s START /funcs/func_strings/ - func_REPLACE_test 142s END /funcs/func_strings/ - func_REPLACE_test Time: <1ms Result: PASS 142s START /funcs/func_strings/ - func_FIELDNUM_test 142s END /funcs/func_strings/ - func_FIELDNUM_test Time: <1ms Result: PASS 142s START /geoloc/ - create_from_pidf 142s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1274]: ID: 'point-2d' pidf_element: 'tuple' format: 'GML' method: 'Manual' 142s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1286]: location_vars expected: shape=Point,crs=2d,pos=-34.410649 150.87651 142s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1287]: location_vars received: shape=Point,crs=2d,pos=-34.410649 150.87651 142s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1293]: usage_rules expected: retransmission-allowed='no',retention-expiry='2010-11-14T20:00:00Z' 142s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1294]: usage_rules received: retransmission-allowed='no',retention-expiry='2010-11-14T20:00:00Z' 142s END /geoloc/ - create_from_pidf Time: <1ms Result: PASS 142s START /geoloc/ - create_from_uri 142s END /geoloc/ - create_from_uri Time: <1ms Result: PASS 142s START /main/abstract_jb/ - AST_JB_FIXED_put_out_of_order 142s [test_abstract_jb.c:AST_JB_FIXED_put_out_of_order:531]: Executing AST_JB_FIXED_put_out_of_order... 142s END /main/abstract_jb/ - AST_JB_FIXED_put_out_of_order Time: <1ms Result: PASS 142s START /main/abstract_jb/ - AST_JB_FIXED_put_overflow 142s [test_abstract_jb.c:AST_JB_FIXED_put_overflow:529]: Executing AST_JB_FIXED_put_overflow... 142s END /main/abstract_jb/ - AST_JB_FIXED_put_overflow Time: <1ms Result: PASS 142s START /main/abstract_jb/ - AST_JB_FIXED_put 142s [test_abstract_jb.c:AST_JB_FIXED_put:527]: Executing AST_JB_FIXED_put... 142s END /main/abstract_jb/ - AST_JB_FIXED_put Time: <1ms Result: PASS 142s START /main/abstract_jb/ - AST_JB_FIXED_put_first 142s [test_abstract_jb.c:AST_JB_FIXED_put_first:525]: Executing AST_JB_FIXED_create... 142s END /main/abstract_jb/ - AST_JB_FIXED_put_first Time: <1ms Result: PASS 142s START /main/abstract_jb/ - AST_JB_FIXED_create 142s [test_abstract_jb.c:AST_JB_FIXED_create:523]: Executing AST_JB_FIXED_create... 142s END /main/abstract_jb/ - AST_JB_FIXED_create Time: <1ms Result: PASS 142s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_out_of_order 142s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_out_of_order:521]: Executing AST_JB_ADAPTIVE_put_out_of_order... 142s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_out_of_order Time: <1ms Result: PASS 142s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_overflow 142s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_overflow:519]: Executing AST_JB_ADAPTIVE_put_overflow... 142s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_overflow Time: <1ms Result: PASS 142s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put 142s [test_abstract_jb.c:AST_JB_ADAPTIVE_put:517]: Executing AST_JB_ADAPTIVE_put... 142s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put Time: <1ms Result: PASS 142s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_first 142s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_first:515]: Executing AST_JB_ADAPTIVE_create... 142s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_first Time: <1ms Result: PASS 142s START /main/abstract_jb/ - AST_JB_ADAPTIVE_create 142s [test_abstract_jb.c:AST_JB_ADAPTIVE_create:513]: Executing AST_JB_ADAPTIVE_create... 142s END /main/abstract_jb/ - AST_JB_ADAPTIVE_create Time: <1ms Result: PASS 142s START /main/acl/ - acl 142s END /main/acl/ - acl Time: <1ms Result: PASS 142s START /main/acl/ - invalid_acl 142s END /main/acl/ - invalid_acl Time: <1ms Result: PASS 142s START /main/amihooks/ - amihook_cli_send 142s END /main/amihooks/ - amihook_cli_send Time: <1ms Result: PASS 142s START /main/aoc/ - aoc_event_test 142s END /main/aoc/ - aoc_event_test Time: <1ms Result: PASS 142s START /main/aoc/ - aoc_encode_decode_test 142s END /main/aoc/ - aoc_encode_decode_test Time: <1ms Result: PASS 142s START /main/app/ - options_parsing 142s END /main/app/ - options_parsing Time: <1ms Result: PASS 142s START /main/app/ - app_group 142s [test_app.c:app_group:172]: Creating test channels with the following groups: 142s 'a groupgroupgroup', 'a groupGroupgroup', 'a group@a_category', 'a group@another!Category' 142s [test_app.c:app_group:211]: (Subtest 1) Found 4 matches as expected when examining group:'gr' category:'' 142s [test_app.c:app_group:211]: (Subtest 2) Found 1 matches as expected when examining group:'(group){2}$' category:'' 142s [test_app.c:app_group:211]: (Subtest 3) Found 4 matches as expected when examining group:'[:ascii:]' category:'' 142s [test_app.c:app_group:211]: (Subtest 4) Found 0 matches as expected when examining group:'^(NOMATCH)' category:'' 142s [test_app.c:app_group:211]: (Subtest 5) Found 2 matches as expected when examining group:'a group' category:'(gory)$' 142s [test_app.c:app_group:211]: (Subtest 6) Found 1 matches as expected when examining group:'a group' category:'[A-Z]+' 142s [test_app.c:app_group:211]: (Subtest 7) Found 0 matches as expected when examining group:'a group' category:'[[' 142s END /main/app/ - app_group Time: <1ms Result: PASS 142s START /main/ast_expr/ - expr_test 142s END /main/ast_expr/ - expr_test Time: <1ms Result: PASS 142s START /main/astdb/ - put_get_long 142s END /main/astdb/ - put_get_long Time: 93ms Result: PASS 142s START /main/astdb/ - perftest 143s END /main/astdb/ - perftest Time: 245ms Result: PASS 143s START /main/astdb/ - gettree_deltree 143s END /main/astdb/ - gettree_deltree Time: <1ms Result: PASS 143s START /main/astdb/ - put_get_del 143s END /main/astdb/ - put_get_del Time: <1ms Result: PASS 143s START /main/astobj2/ - thrash 143s [test_astobj2_thrash.c:hash_test:266]: Executing hash concurrency test... 143s END /main/astobj2/ - thrash Time: 24ms Result: PASS 143s START /main/astobj2/ - astobj2_test4 143s [test_astobj2.c:test_traversal_nonsorted:1389]: Test 1, List containers. 143s [test_astobj2.c:test_traversal_nonsorted:1389]: Test 2, Hash containers. 143s [test_astobj2.c:test_traversal_sorted:1615]: Test 3, List containers. 143s [test_astobj2.c:test_traversal_sorted:1615]: Test 4, Hash containers. 143s [test_astobj2.c:test_traversal_sorted:1615]: Test 5, RBTree containers. 143s END /main/astobj2/ - astobj2_test4 Time: <1ms Result: PASS 143s START /main/astobj2/ - astobj2_test3 143s END /main/astobj2/ - astobj2_test3 Time: <1ms Result: PASS 143s START /main/astobj2/ - astobj2_test2 143s END /main/astobj2/ - astobj2_test2 Time: <1ms Result: PASS 143s START /main/astobj2/ - astobj2_test1 143s [test_astobj2.c:astobj2_test_1_helper:434]: Test 1, List containers (non-sorted). 143s [test_astobj2.c:astobj2_test_1_helper:488]: List container created: buckets: 1, items: 50 143s [test_astobj2.c:astobj2_test_1_helper:434]: Test 2, List containers (sorted). 143s [test_astobj2.c:astobj2_test_1_helper:488]: List container created: buckets: 1, items: 50 143s [test_astobj2.c:astobj2_test_1_helper:434]: Test 3, Hash containers (non-sorted). 143s [test_astobj2.c:astobj2_test_1_helper:488]: Hash container created: buckets: 42, items: 1000 143s [test_astobj2.c:astobj2_test_1_helper:434]: Test 4, Hash containers (sorted). 143s [test_astobj2.c:astobj2_test_1_helper:488]: Hash container created: buckets: 160, items: 1000 143s [test_astobj2.c:astobj2_test_1_helper:434]: Test 4, RBTree containers (sorted). 143s [test_astobj2.c:astobj2_test_1_helper:488]: RBTree container created: buckets: 1, items: 1000 143s END /main/astobj2/ - astobj2_test1 Time: 9ms Result: PASS 143s START /main/astobj2/ - astobj2_weak_container 143s END /main/astobj2/ - astobj2_weak_container Time: <1ms Result: PASS 143s START /main/astobj2/ - astobj2_weak1 143s END /main/astobj2/ - astobj2_weak1 Time: <1ms Result: PASS 143s START /main/astobj2/perf/ - astobj2_test_perf 143s [test_astobj2.c:testloop:2001]: 20.00K traversals, List 144s [test_astobj2.c:testloop:2001]: 40.00K traversals, List 145s [test_astobj2.c:testloop:2001]: 60.00K traversals, List 146s [test_astobj2.c:testloop:2001]: 80.00K traversals, List 147s [test_astobj2.c:testloop:2006]: 100.00K traversals, List : 4325 ms 147s [test_astobj2.c:testloop:2001]: 20.00K traversals, Hash 148s [test_astobj2.c:testloop:2001]: 40.00K traversals, Hash 148s [test_astobj2.c:testloop:2001]: 60.00K traversals, Hash 149s [test_astobj2.c:testloop:2001]: 80.00K traversals, Hash 149s [test_astobj2.c:testloop:2006]: 100.00K traversals, Hash : 2480 ms 150s [test_astobj2.c:testloop:2001]: 20.00K traversals, RBTree 151s [test_astobj2.c:testloop:2001]: 40.00K traversals, RBTree 151s [test_astobj2.c:testloop:2001]: 60.00K traversals, RBTree 152s [test_astobj2.c:testloop:2001]: 80.00K traversals, RBTree 152s [test_astobj2.c:testloop:2006]: 100.00K traversals, RBTree : 3000 ms 152s END /main/astobj2/perf/ - astobj2_test_perf Time: 9805ms Result: PASS 152s START /main/bridging/ - test_bridging_deferred_queue 153s END /main/bridging/ - test_bridging_deferred_queue Time: 1016ms Result: PASS 153s START /main/bucket/ - bucket_file_json 153s [test_bucket.c:bucket_file_json:956]: Failed to allocate bucket 153s END /main/bucket/ - bucket_file_json Time: 50ms Result: FAIL 153s START /main/bucket/ - bucket_file_metadata_get 153s [test_bucket.c:bucket_file_metadata_get:914]: Failed to allocate file 153s END /main/bucket/ - bucket_file_metadata_get Time: <1ms Result: FAIL 153s START /main/bucket/ - bucket_file_metadata_unset 153s [test_bucket.c:bucket_file_metadata_unset:874]: Failed to allocate file 153s END /main/bucket/ - bucket_file_metadata_unset Time: <1ms Result: FAIL 153s START /main/bucket/ - bucket_file_metadata_set 153s [test_bucket.c:bucket_file_metadata_set:808]: Failed to allocate file 153s END /main/bucket/ - bucket_file_metadata_set Time: <1ms Result: FAIL 154s START /main/bucket/ - bucket_file_is_stale 154s [test_bucket.c:bucket_file_is_stale:775]: Failed to allocate file 154s END /main/bucket/ - bucket_file_is_stale Time: <1ms Result: FAIL 154s START /main/bucket/ - bucket_file_delete 154s [test_bucket.c:bucket_file_delete:732]: Failed to allocate file 154s END /main/bucket/ - bucket_file_delete Time: <1ms Result: FAIL 154s START /main/bucket/ - bucket_file_update 154s [test_bucket.c:bucket_file_update:689]: Failed to allocate file 154s END /main/bucket/ - bucket_file_update Time: <1ms Result: FAIL 154s START /main/bucket/ - bucket_file_retrieve 154s [test_bucket.c:bucket_file_retrieve:665]: Failed to retrieve known valid file 154s END /main/bucket/ - bucket_file_retrieve Time: <1ms Result: FAIL 154s START /main/bucket/ - bucket_file_copy 154s [test_bucket.c:bucket_file_copy:594]: Failed to allocate file 154s END /main/bucket/ - bucket_file_copy Time: <1ms Result: FAIL 154s START /main/bucket/ - bucket_file_clone 154s [test_bucket.c:bucket_file_clone:545]: Failed to allocate file 154s END /main/bucket/ - bucket_file_clone Time: <1ms Result: FAIL 154s START /main/bucket/ - bucket_file_create 154s [test_bucket.c:bucket_file_create:501]: Failed to allocate file 154s END /main/bucket/ - bucket_file_create Time: <1ms Result: FAIL 154s START /main/bucket/ - bucket_file_alloc 154s [test_bucket.c:bucket_file_alloc:460]: Failed to allocate file 154s END /main/bucket/ - bucket_file_alloc Time: <1ms Result: FAIL 154s START /main/bucket/ - bucket_json 154s END /main/bucket/ - bucket_json Time: <1ms Result: PASS 154s START /main/bucket/ - bucket_is_stale 154s END /main/bucket/ - bucket_is_stale Time: <1ms Result: PASS 154s START /main/bucket/ - bucket_retrieve 154s END /main/bucket/ - bucket_retrieve Time: <1ms Result: PASS 154s START /main/bucket/ - bucket_delete 154s END /main/bucket/ - bucket_delete Time: <1ms Result: PASS 154s START /main/bucket/ - bucket_clone 154s END /main/bucket/ - bucket_clone Time: <1ms Result: PASS 154s START /main/bucket/ - bucket_create 154s END /main/bucket/ - bucket_create Time: <1ms Result: PASS 154s START /main/bucket/ - bucket_alloc 154s END /main/bucket/ - bucket_alloc Time: <1ms Result: PASS 154s START /main/bucket/ - bucket_scheme_register_unregister 154s END /main/bucket/ - bucket_scheme_register_unregister Time: <1ms Result: PASS 154s START /main/callerid/ - parse_off_nominal 154s END /main/callerid/ - parse_off_nominal Time: <1ms Result: PASS 154s START /main/callerid/ - parse_nominal 154s END /main/callerid/ - parse_nominal Time: <1ms Result: PASS 154s START /main/cdr/ - test_cdr_fork_cdr 155s Verifying expected record CDRTestChannel/Alice, 155s Finished expected record CDRTestChannel/Alice, 155s Verifying expected record CDRTestChannel/Alice, 155s Finished expected record CDRTestChannel/Alice, 155s Verifying expected record CDRTestChannel/Alice, 155s Finished expected record CDRTestChannel/Alice, 155s END /main/cdr/ - test_cdr_fork_cdr Time: 2001ms Result: PASS 155s START /main/cdr/ - test_cdr_no_reset_cdr 156s Verifying expected record CDRTestChannel/Alice, 156s Finished expected record CDRTestChannel/Alice, 156s END /main/cdr/ - test_cdr_no_reset_cdr Time: 1000ms Result: PASS 156s START /main/cdr/ - test_cdr_fields 159s Verifying expected record CDRTestChannel/Alice, 159s Finished expected record CDRTestChannel/Alice, 159s Verifying expected record CDRTestChannel/Alice, 159s Finished expected record CDRTestChannel/Alice, 159s Verifying expected record CDRTestChannel/Alice, 159s Finished expected record CDRTestChannel/Alice, 159s END /main/cdr/ - test_cdr_fields Time: 2000ms Result: PASS 159s START /main/cdr/ - test_cdr_park 161s Verifying expected record CDRTestChannel/Alice, 161s Finished expected record CDRTestChannel/Alice, 161s Verifying expected record CDRTestChannel/Bob, 161s Finished expected record CDRTestChannel/Bob, 161s END /main/cdr/ - test_cdr_park Time: 3001ms Result: PASS 161s START /main/cdr/ - test_cdr_dial_answer_multiparty 166s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 166s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 166s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 166s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 166s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/David 166s Finished expected record CDRTestChannel/Alice, CDRTestChannel/David 166s Verifying expected record CDRTestChannel/Bob, CDRTestChannel/David 166s Finished expected record CDRTestChannel/Bob, CDRTestChannel/David 166s Verifying expected record CDRTestChannel/Charlie, CDRTestChannel/David 166s Finished expected record CDRTestChannel/Charlie, CDRTestChannel/David 166s Verifying expected record CDRTestChannel/Charlie, CDRTestChannel/Bob 166s Finished expected record CDRTestChannel/Charlie, CDRTestChannel/Bob 166s END /main/cdr/ - test_cdr_dial_answer_multiparty Time: 5003ms Result: PASS 166s START /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_b 170s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 170s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 170s END /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_b Time: 3065ms Result: PASS 170s START /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_a 172s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 172s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 172s END /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_a Time: 2002ms Result: PASS 172s START /main/cdr/ - test_cdr_dial_answer_no_bridge 172s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 172s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 172s Verifying expected record CDRTestChannel/Alice, 172s Finished expected record CDRTestChannel/Alice, 172s Verifying expected record CDRTestChannel/Bob, 172s Finished expected record CDRTestChannel/Bob, 172s END /main/cdr/ - test_cdr_dial_answer_no_bridge Time: <1ms Result: PASS 172s START /main/cdr/ - test_cdr_dial_parallel_failed 172s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 172s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 172s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 172s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 172s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/David 172s Finished expected record CDRTestChannel/Alice, CDRTestChannel/David 172s END /main/cdr/ - test_cdr_dial_parallel_failed Time: 1ms Result: PASS 172s START /main/cdr/ - test_cdr_dial_caller_cancel 172s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 172s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 172s END /main/cdr/ - test_cdr_dial_caller_cancel Time: <1ms Result: PASS 172s START /main/cdr/ - test_cdr_dial_unavailable 172s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 172s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 172s END /main/cdr/ - test_cdr_dial_unavailable Time: <1ms Result: PASS 172s START /main/cdr/ - test_cdr_dial_busy 172s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 172s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 172s END /main/cdr/ - test_cdr_dial_busy Time: <1ms Result: PASS 172s START /main/cdr/ - test_cdr_dial_congestion 172s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 172s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 172s END /main/cdr/ - test_cdr_dial_congestion Time: <1ms Result: PASS 172s START /main/cdr/ - test_cdr_dial_unanswered 172s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 172s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 172s END /main/cdr/ - test_cdr_dial_unanswered Time: <1ms Result: PASS 172s START /main/cdr/ - test_cdr_outbound_bridged_call 175s Verifying expected record CDRTestChannel/Bob, 175s Finished expected record CDRTestChannel/Bob, 175s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 175s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 175s END /main/cdr/ - test_cdr_outbound_bridged_call Time: 3002ms Result: PASS 175s START /main/cdr/ - test_cdr_single_multiparty_bridge 179s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 179s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 179s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 179s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 179s Verifying expected record CDRTestChannel/Bob, CDRTestChannel/Charlie 179s Finished expected record CDRTestChannel/Bob, CDRTestChannel/Charlie 179s Verifying expected record CDRTestChannel/Charlie, 179s Finished expected record CDRTestChannel/Charlie, 179s END /main/cdr/ - test_cdr_single_multiparty_bridge Time: 4002ms Result: PASS 179s START /main/cdr/ - test_cdr_single_twoparty_bridge_b 182s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 182s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 182s Verifying expected record CDRTestChannel/Bob, 182s Finished expected record CDRTestChannel/Bob, 182s END /main/cdr/ - test_cdr_single_twoparty_bridge_b Time: 3001ms Result: PASS 182s START /main/cdr/ - test_cdr_single_twoparty_bridge_a 184s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 184s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 184s Verifying expected record CDRTestChannel/Bob, 184s Finished expected record CDRTestChannel/Bob, 184s END /main/cdr/ - test_cdr_single_twoparty_bridge_a Time: 2001ms Result: PASS 184s START /main/cdr/ - test_cdr_single_bridge_continue 186s Verifying expected record CDRTestChannel/Alice, 186s Finished expected record CDRTestChannel/Alice, 186s Verifying expected record CDRTestChannel/Alice, 186s Finished expected record CDRTestChannel/Alice, 186s END /main/cdr/ - test_cdr_single_bridge_continue Time: 2001ms Result: PASS 186s START /main/cdr/ - test_cdr_single_bridge 188s Verifying expected record CDRTestChannel/Alice, 188s Finished expected record CDRTestChannel/Alice, 188s END /main/cdr/ - test_cdr_single_bridge Time: 2001ms Result: PASS 188s START /main/cdr/ - test_cdr_single_party 188s Verifying expected record CDRTestChannel/Alice, 188s Finished expected record CDRTestChannel/Alice, 188s END /main/cdr/ - test_cdr_single_party Time: <1ms Result: PASS 188s START /main/cdr/ - test_cdr_unanswered_outbound_call 188s Verifying expected record CDRTestChannel/Alice, 188s Finished expected record CDRTestChannel/Alice, 188s END /main/cdr/ - test_cdr_unanswered_outbound_call Time: <1ms Result: PASS 188s START /main/cdr/ - test_cdr_unanswered_inbound_call 188s Verifying expected record CDRTestChannel/Alice, 188s Finished expected record CDRTestChannel/Alice, 188s END /main/cdr/ - test_cdr_unanswered_inbound_call Time: <1ms Result: PASS 188s START /main/cdr/ - test_cdr_channel_creation 188s Verifying expected record CDRTestChannel/Alice, 188s Finished expected record CDRTestChannel/Alice, 188s END /main/cdr/ - test_cdr_channel_creation Time: <1ms Result: PASS 188s START /main/channel/ - add_fd 188s END /main/channel/ - add_fd Time: 4ms Result: PASS 188s START /main/channel/ - set_fd_grow 188s END /main/channel/ - set_fd_grow Time: <1ms Result: PASS 188s START /main/config/ - variable_list_from_quoted_string 188s END /main/config/ - variable_list_from_quoted_string Time: <1ms Result: PASS 188s START /main/config/ - variable_list_join_replace 188s END /main/config/ - variable_list_join_replace Time: <1ms Result: PASS 188s START /main/config/ - variable_lists_match 188s END /main/config/ - variable_lists_match Time: <1ms Result: PASS 188s START /main/config/ - config_dialplan_function 188s END /main/config/ - config_dialplan_function Time: 6ms Result: PASS 188s START /main/config/ - config_hook 188s END /main/config/ - config_hook Time: <1ms Result: PASS 188s START /main/config/ - copy_config 188s END /main/config/ - copy_config Time: <1ms Result: PASS 188s START /main/config/ - config_template_ops 188s END /main/config/ - config_template_ops Time: <1ms Result: PASS 188s START /main/config/ - config_filtered_ops 188s END /main/config/ - config_filtered_ops Time: <1ms Result: PASS 188s START /main/config/ - config_basic_ops 188s END /main/config/ - config_basic_ops Time: <1ms Result: PASS 188s START /main/config/ - config_save 188s END /main/config/ - config_save Time: <1ms Result: PASS 188s START /main/conversions/ - str_to_umax 188s END /main/conversions/ - str_to_umax Time: <1ms Result: PASS 188s START /main/conversions/ - str_to_imax 188s END /main/conversions/ - str_to_imax Time: <1ms Result: PASS 188s START /main/conversions/ - str_to_ulong 188s END /main/conversions/ - str_to_ulong Time: <1ms Result: PASS 188s START /main/conversions/ - str_to_long 188s END /main/conversions/ - str_to_long Time: <1ms Result: PASS 188s START /main/conversions/ - str_to_uint 188s END /main/conversions/ - str_to_uint Time: <1ms Result: PASS 188s START /main/conversions/ - str_to_int 188s END /main/conversions/ - str_to_int Time: <1ms Result: PASS 188s START /main/core_codec/ - codec_get_unknown 188s END /main/core_codec/ - codec_get_unknown Time: <1ms Result: PASS 188s START /main/core_codec/ - codec_get_unknown 188s END /main/core_codec/ - codec_get_unknown Time: <1ms Result: PASS 188s START /main/core_codec/ - codec_get_unregistered 188s END /main/core_codec/ - codec_get_unregistered Time: <1ms Result: PASS 188s START /main/core_codec/ - codec_get 188s END /main/core_codec/ - codec_get Time: <1ms Result: PASS 188s START /main/core_codec/ - codec_register_audio_no_sample_rate 188s END /main/core_codec/ - codec_register_audio_no_sample_rate Time: <1ms Result: PASS 188s START /main/core_codec/ - codec_register_unknown 188s END /main/core_codec/ - codec_register_unknown Time: <1ms Result: PASS 188s START /main/core_codec/ - codec_register_twice 188s END /main/core_codec/ - codec_register_twice Time: <1ms Result: PASS 188s START /main/core_codec/ - codec_register 188s END /main/core_codec/ - codec_register Time: <1ms Result: PASS 188s START /main/core_format/ - format_parse_and_generate_sdp_fmtp 188s END /main/core_format/ - format_parse_and_generate_sdp_fmtp Time: <1ms Result: PASS 188s START /main/core_format/ - format_parse_sdp_fmtp_without_interface 188s END /main/core_format/ - format_parse_sdp_fmtp_without_interface Time: <1ms Result: PASS 188s START /main/core_format/ - format_attribute_get_without_interface 188s END /main/core_format/ - format_attribute_get_without_interface Time: <1ms Result: PASS 188s START /main/core_format/ - format_attribute_set_without_interface 188s END /main/core_format/ - format_attribute_set_without_interface Time: <1ms Result: PASS 188s START /main/core_format/ - format_copy 188s END /main/core_format/ - format_copy Time: <1ms Result: PASS 188s START /main/core_format/ - format_joint_different_codec 188s END /main/core_format/ - format_joint_different_codec Time: <1ms Result: PASS 188s START /main/core_format/ - format_attr_joint_same_codec 188s END /main/core_format/ - format_attr_joint_same_codec Time: <1ms Result: PASS 188s START /main/core_format/ - format_joint_same_codec 188s END /main/core_format/ - format_joint_same_codec Time: <1ms Result: PASS 188s START /main/core_format/ - format_cmp_different_codec 188s END /main/core_format/ - format_cmp_different_codec Time: <1ms Result: PASS 188s START /main/core_format/ - format_attr_cmp_same_codec 188s END /main/core_format/ - format_attr_cmp_same_codec Time: <1ms Result: PASS 188s START /main/core_format/ - format_cmp_same_codec 188s END /main/core_format/ - format_cmp_same_codec Time: <1ms Result: PASS 188s START /main/core_format/ - format_clone 188s END /main/core_format/ - format_clone Time: <1ms Result: PASS 188s START /main/core_format/ - format_retrieve_attr 188s END /main/core_format/ - format_retrieve_attr Time: <1ms Result: PASS 188s START /main/core_format/ - format_create_attr 188s END /main/core_format/ - format_create_attr Time: <1ms Result: PASS 188s START /main/core_format/ - format_create 188s END /main/core_format/ - format_create Time: <1ms Result: PASS 188s START /main/data_buffer/ - buffer_nominal 188s END /main/data_buffer/ - buffer_nominal Time: <1ms Result: PASS 188s START /main/data_buffer/ - buffer_resize 188s END /main/data_buffer/ - buffer_resize Time: <1ms Result: PASS 188s START /main/data_buffer/ - buffer_put 188s END /main/data_buffer/ - buffer_put Time: <1ms Result: PASS 188s START /main/data_buffer/ - buffer_create 188s END /main/data_buffer/ - buffer_create Time: <1ms Result: PASS 188s START /main/devicestate/ - devstate_channels 188s END /main/devicestate/ - devstate_channels Time: <1ms Result: PASS 188s START /main/devicestate/ - devstate_conversions 188s END /main/devicestate/ - devstate_conversions Time: <1ms Result: PASS 188s START /main/devicestate/ - devstate_changed 188s [test_devicestate.c:wait_for_device_state_updates:308]: Received 8 of 8 updates 188s [test_devicestate.c:devstate_changed:716]: Testing update 0: actual is 1; expected is 1 188s [test_devicestate.c:devstate_changed:716]: Testing update 1: actual is 2; expected is 2 188s [test_devicestate.c:devstate_changed:716]: Testing update 2: actual is 3; expected is 3 188s [test_devicestate.c:devstate_changed:716]: Testing update 3: actual is 4; expected is 4 188s [test_devicestate.c:devstate_changed:716]: Testing update 4: actual is 5; expected is 5 188s [test_devicestate.c:devstate_changed:716]: Testing update 5: actual is 6; expected is 6 188s [test_devicestate.c:devstate_changed:716]: Testing update 6: actual is 7; expected is 7 188s [test_devicestate.c:devstate_changed:716]: Testing update 7: actual is 8; expected is 8 188s [test_devicestate.c:wait_for_device_state_updates:308]: Received 1 of 1 updates 188s [test_devicestate.c:wait_for_device_state_updates:308]: Received 8 of 8 updates 188s [test_devicestate.c:devstate_changed:754]: Testing update 0: actual is 1; expected is 1 188s [test_devicestate.c:devstate_changed:754]: Testing update 1: actual is 2; expected is 2 188s [test_devicestate.c:devstate_changed:754]: Testing update 2: actual is 3; expected is 3 188s [test_devicestate.c:devstate_changed:754]: Testing update 3: actual is 4; expected is 4 188s [test_devicestate.c:devstate_changed:754]: Testing update 4: actual is 5; expected is 5 188s [test_devicestate.c:devstate_changed:754]: Testing update 5: actual is 6; expected is 6 188s [test_devicestate.c:devstate_changed:754]: Testing update 6: actual is 7; expected is 7 188s [test_devicestate.c:devstate_changed:754]: Testing update 7: actual is 8; expected is 8 188s END /main/devicestate/ - devstate_changed Time: 1ms Result: PASS 188s START /main/devicestate/ - devstate_prov_del 188s END /main/devicestate/ - devstate_prov_del Time: <1ms Result: PASS 188s START /main/devicestate/ - devstate_prov_add 188s END /main/devicestate/ - devstate_prov_add Time: <1ms Result: PASS 188s START /main/devicestate/ - device2extenstate_test 188s END /main/devicestate/ - device2extenstate_test Time: <1ms Result: PASS 188s START /main/devicestate/ - device_state_aggregation_test 188s END /main/devicestate/ - device_state_aggregation_test Time: <1ms Result: PASS 188s START /main/dns/ - resolver_resolve_async_cancel 188s END /main/dns/ - resolver_resolve_async_cancel Time: <1ms Result: PASS 188s START /main/dns/ - resolver_resolve_async_off_nominal 188s END /main/dns/ - resolver_resolve_async_off_nominal Time: <1ms Result: PASS 188s START /main/dns/ - resolver_resolve_async 193s END /main/dns/ - resolver_resolve_async Time: 5000ms Result: PASS 193s START /main/dns/ - resolver_resolve_sync_off_nominal 193s END /main/dns/ - resolver_resolve_sync_off_nominal Time: <1ms Result: PASS 193s START /main/dns/ - resolver_resolve_sync 198s END /main/dns/ - resolver_resolve_sync Time: 5000ms Result: PASS 198s START /main/dns/ - resolver_add_record_off_nominal 198s END /main/dns/ - resolver_add_record_off_nominal Time: <1ms Result: PASS 198s START /main/dns/ - resolver_add_record 198s END /main/dns/ - resolver_add_record Time: <1ms Result: PASS 198s START /main/dns/ - resolver_set_result_off_nominal 198s END /main/dns/ - resolver_set_result_off_nominal Time: <1ms Result: PASS 198s START /main/dns/ - resolver_set_result 198s END /main/dns/ - resolver_set_result Time: <1ms Result: PASS 198s START /main/dns/ - resolver_data 198s END /main/dns/ - resolver_data Time: <1ms Result: PASS 198s START /main/dns/ - resolver_unregister_off_nominal 198s END /main/dns/ - resolver_unregister_off_nominal Time: <1ms Result: PASS 198s START /main/dns/ - resolver_register_off_nominal 198s END /main/dns/ - resolver_register_off_nominal Time: <1ms Result: PASS 198s START /main/dns/ - resolver_register_unregister 198s END /main/dns/ - resolver_register_unregister Time: <1ms Result: PASS 198s START /main/dns/naptr/ - naptr_resolve_off_nominal_interactions 198s END /main/dns/naptr/ - naptr_resolve_off_nominal_interactions Time: <1ms Result: PASS 198s START /main/dns/naptr/ - naptr_resolve_off_nominal_regexp 198s END /main/dns/naptr/ - naptr_resolve_off_nominal_regexp Time: <1ms Result: PASS 198s START /main/dns/naptr/ - naptr_resolve_off_nominal_services 198s END /main/dns/naptr/ - naptr_resolve_off_nominal_services Time: <1ms Result: PASS 198s START /main/dns/naptr/ - naptr_resolve_off_nominal_flags 198s END /main/dns/naptr/ - naptr_resolve_off_nominal_flags Time: <1ms Result: PASS 198s START /main/dns/naptr/ - naptr_resolve_off_nominal_length 198s END /main/dns/naptr/ - naptr_resolve_off_nominal_length Time: <1ms Result: PASS 198s START /main/dns/naptr/ - naptr_resolve 198s END /main/dns/naptr/ - naptr_resolve Time: <1ms Result: PASS 198s START /main/dns/query_set/ - query_set_off_nominal_cancel 198s END /main/dns/query_set/ - query_set_off_nominal_cancel Time: <1ms Result: PASS 198s START /main/dns/query_set/ - query_set_nominal_cancel 198s END /main/dns/query_set/ - query_set_nominal_cancel Time: <1ms Result: PASS 198s START /main/dns/query_set/ - query_set_empty 198s END /main/dns/query_set/ - query_set_empty Time: <1ms Result: PASS 198s START /main/dns/query_set/ - query_set 198s END /main/dns/query_set/ - query_set Time: <1ms Result: PASS 198s START /main/dns/recurring/ - recurring_query_cancel_during 198s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 205s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 215s END /main/dns/recurring/ - recurring_query_cancel_during Time: 16999ms Result: PASS 215s START /main/dns/recurring/ - recurring_query_cancel_between 215s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 225s END /main/dns/recurring/ - recurring_query_cancel_between Time: 10000ms Result: PASS 225s START /main/dns/recurring/ - recurring_query_off_nominal 225s END /main/dns/recurring/ - recurring_query_off_nominal Time: <1ms Result: PASS 225s START /main/dns/recurring/ - recurring_query 225s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 232s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 244s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 244s END /main/dns/recurring/ - recurring_query Time: 19031ms Result: PASS 244s START /main/dns/srv/ - srv_resolve_record_missing_host 244s END /main/dns/srv/ - srv_resolve_record_missing_host Time: <1ms Result: PASS 244s START /main/dns/srv/ - srv_resolve_record_missing_port_host 244s END /main/dns/srv/ - srv_resolve_record_missing_port_host Time: <1ms Result: PASS 244s START /main/dns/srv/ - srv_resolve_record_missing_weight_port_host 244s END /main/dns/srv/ - srv_resolve_record_missing_weight_port_host Time: <1ms Result: PASS 244s START /main/dns/srv/ - srv_resolve_different_priorities_different_weights 244s END /main/dns/srv/ - srv_resolve_different_priorities_different_weights Time: 4ms Result: PASS 244s START /main/dns/srv/ - srv_resolve_same_priority_different_weights 244s END /main/dns/srv/ - srv_resolve_same_priority_different_weights Time: 4ms Result: PASS 244s START /main/dns/srv/ - srv_resolve_same_priority_zero_weight 244s END /main/dns/srv/ - srv_resolve_same_priority_zero_weight Time: <1ms Result: PASS 244s START /main/dns/srv/ - srv_resolve_sort_priority 244s END /main/dns/srv/ - srv_resolve_sort_priority Time: <1ms Result: PASS 244s START /main/dns/srv/ - srv_resolve_single_record 244s END /main/dns/srv/ - srv_resolve_single_record Time: <1ms Result: PASS 244s START /main/dsp/ - dtmf 244s END /main/dsp/ - dtmf Time: 2ms Result: PASS 244s START /main/dsp/ - fax 244s END /main/dsp/ - fax Time: 332ms Result: PASS 244s START /main/event/ - ast_event_new_test 244s [test_event.c:event_new_test:125]: First, test dynamic event creation... 244s [test_event.c:check_event:88]: Event looks good. 244s [test_event.c:check_event:88]: Event looks good. 244s END /main/event/ - ast_event_new_test Time: <1ms Result: PASS 244s START /main/file/ - ast_format_str_reduce_test_1 244s END /main/file/ - ast_format_str_reduce_test_1 Time: 4ms Result: PASS 244s START /main/file/ - read_dir_test 244s END /main/file/ - read_dir_test Time: <1ms Result: PASS 244s START /main/format_cache/ - format_cache_get_nonxistent 244s END /main/format_cache/ - format_cache_get_nonxistent Time: <1ms Result: PASS 244s START /main/format_cache/ - format_cache_get 244s END /main/format_cache/ - format_cache_get Time: <1ms Result: PASS 244s START /main/format_cache/ - format_cache_set_null 244s END /main/format_cache/ - format_cache_set_null Time: <1ms Result: PASS 244s START /main/format_cache/ - format_cache_set_duplicate 244s END /main/format_cache/ - format_cache_set_duplicate Time: <1ms Result: PASS 244s START /main/format_cache/ - format_cache_set 244s END /main/format_cache/ - format_cache_set Time: <1ms Result: PASS 244s START /main/format_cap/ - format_cap_replace_from_cap 244s END /main/format_cap/ - format_cap_replace_from_cap Time: <1ms Result: PASS 244s START /main/format_cap/ - format_cap_best_by_type 244s END /main/format_cap/ - format_cap_best_by_type Time: 5ms Result: PASS 244s START /main/format_cap/ - format_cap_iscompatible 244s END /main/format_cap/ - format_cap_iscompatible Time: <1ms Result: PASS 244s START /main/format_cap/ - format_cap_get_compatible 244s END /main/format_cap/ - format_cap_get_compatible Time: <1ms Result: PASS 244s START /main/format_cap/ - format_cap_iscompatible_format 244s END /main/format_cap/ - format_cap_iscompatible_format Time: <1ms Result: PASS 244s START /main/format_cap/ - format_cap_get_compatible_format 244s END /main/format_cap/ - format_cap_get_compatible_format Time: <1ms Result: PASS 244s START /main/format_cap/ - format_cap_get_names 244s END /main/format_cap/ - format_cap_get_names Time: <1ms Result: PASS 244s START /main/format_cap/ - format_cap_remove_all 244s END /main/format_cap/ - format_cap_remove_all Time: <1ms Result: PASS 244s START /main/format_cap/ - format_cap_remove_bytype 244s END /main/format_cap/ - format_cap_remove_bytype Time: <1ms Result: PASS 244s START /main/format_cap/ - format_cap_remove_multiple 244s END /main/format_cap/ - format_cap_remove_multiple Time: <1ms Result: PASS 244s START /main/format_cap/ - format_cap_remove_single 244s END /main/format_cap/ - format_cap_remove_single Time: <1ms Result: PASS 244s START /main/format_cap/ - format_cap_set_framing 244s END /main/format_cap/ - format_cap_set_framing Time: <1ms Result: PASS 244s START /main/format_cap/ - format_cap_append_from_cap_duplicate 244s END /main/format_cap/ - format_cap_append_from_cap_duplicate Time: <1ms Result: PASS 244s START /main/format_cap/ - format_cap_append_from_cap 244s END /main/format_cap/ - format_cap_append_from_cap Time: <1ms Result: PASS 244s START /main/format_cap/ - format_cap_append_duplicate 244s END /main/format_cap/ - format_cap_append_duplicate Time: <1ms Result: PASS 244s START /main/format_cap/ - format_cap_append_all_audio 244s END /main/format_cap/ - format_cap_append_all_audio Time: <1ms Result: PASS 244s START /main/format_cap/ - format_cap_append_all_unknown 244s END /main/format_cap/ - format_cap_append_all_unknown Time: <1ms Result: PASS 244s START /main/format_cap/ - format_cap_append_multiple 244s END /main/format_cap/ - format_cap_append_multiple Time: <1ms Result: PASS 244s START /main/format_cap/ - format_cap_append_single 244s END /main/format_cap/ - format_cap_append_single Time: <1ms Result: PASS 244s START /main/format_cap/ - format_cap_alloc 244s END /main/format_cap/ - format_cap_alloc Time: <1ms Result: PASS 244s START /main/hashtab/ - thrash 244s [test_hashtab_thrash.c:hash_test:246]: Executing hash concurrency test... 244s END /main/hashtab/ - thrash Time: 23ms Result: PASS 244s START /main/heap/ - heap_test_3 244s END /main/heap/ - heap_test_3 Time: 95ms Result: PASS 244s START /main/heap/ - heap_test_2 244s END /main/heap/ - heap_test_2 Time: 84ms Result: PASS 244s START /main/heap/ - heap_test_1 244s END /main/heap/ - heap_test_1 Time: <1ms Result: PASS 244s START /main/jitterbuf/ - jitterbuffer_resynch_control 244s END /main/jitterbuf/ - jitterbuffer_resynch_control Time: <1ms Result: PASS 244s START /main/jitterbuf/ - jitterbuffer_resynch_voice 244s END /main/jitterbuf/ - jitterbuffer_resynch_voice Time: 4ms Result: PASS 244s START /main/jitterbuf/ - jitterbuffer_overflow_control 244s END /main/jitterbuf/ - jitterbuffer_overflow_control Time: <1ms Result: PASS 244s START /main/jitterbuf/ - jitterbuffer_overflow_voice 244s END /main/jitterbuf/ - jitterbuffer_overflow_voice Time: <1ms Result: PASS 244s START /main/jitterbuf/ - jitterbuffer_late_control 244s END /main/jitterbuf/ - jitterbuffer_late_control Time: <1ms Result: PASS 244s START /main/jitterbuf/ - jitterbuffer_late_voice 244s END /main/jitterbuf/ - jitterbuffer_late_voice Time: <1ms Result: PASS 244s START /main/jitterbuf/ - jitterbuffer_lost_control 244s END /main/jitterbuf/ - jitterbuffer_lost_control Time: <1ms Result: PASS 244s START /main/jitterbuf/ - jitterbuffer_lost_voice 244s END /main/jitterbuf/ - jitterbuffer_lost_voice Time: <1ms Result: PASS 244s START /main/jitterbuf/ - jitterbuffer_out_of_order_voice 244s END /main/jitterbuf/ - jitterbuffer_out_of_order_voice Time: <1ms Result: PASS 244s START /main/jitterbuf/ - jitterbuffer_out_of_order_voice 244s END /main/jitterbuf/ - jitterbuffer_out_of_order_voice Time: <1ms Result: PASS 244s START /main/jitterbuf/ - jitterbuffer_nominal_control_frames 244s END /main/jitterbuf/ - jitterbuffer_nominal_control_frames Time: <1ms Result: PASS 244s START /main/jitterbuf/ - jitterbuffer_nominal_voice_frames 244s END /main/jitterbuf/ - jitterbuffer_nominal_voice_frames Time: <1ms Result: PASS 244s START /main/json/ - cep 244s END /main/json/ - cep Time: <1ms Result: PASS 244s START /main/json/ - type_timeval 244s END /main/json/ - type_timeval Time: <1ms Result: PASS 244s START /main/json/ - name_number 244s END /main/json/ - name_number Time: <1ms Result: PASS 244s START /main/json/ - clever_circle 244s END /main/json/ - clever_circle Time: <1ms Result: PASS 244s START /main/json/ - circular_array 244s END /main/json/ - circular_array Time: <1ms Result: PASS 244s START /main/json/ - circular_object 244s END /main/json/ - circular_object Time: <1ms Result: PASS 244s START /main/json/ - copy_null 244s END /main/json/ - copy_null Time: <1ms Result: PASS 244s START /main/json/ - deep_copy 244s END /main/json/ - deep_copy Time: <1ms Result: PASS 244s START /main/json/ - copy 244s END /main/json/ - copy Time: <1ms Result: PASS 244s START /main/json/ - object_alloc 244s END /main/json/ - object_alloc Time: 1ms Result: PASS 244s START /main/json/ - pack_ownership 244s END /main/json/ - pack_ownership Time: <1ms Result: PASS 244s START /main/json/ - pack 244s END /main/json/ - pack Time: <1ms Result: PASS 244s START /main/json/ - parse_errors 244s END /main/json/ - parse_errors Time: <1ms Result: PASS 244s START /main/json/ - dump_load_null 244s END /main/json/ - dump_load_null Time: <1ms Result: PASS 244s START /main/json/ - dump_load_new_file 244s END /main/json/ - dump_load_new_file Time: <1ms Result: PASS 244s START /main/json/ - dump_load_file 244s END /main/json/ - dump_load_file Time: <1ms Result: PASS 244s START /main/json/ - load_buffer 244s END /main/json/ - load_buffer Time: <1ms Result: PASS 244s START /main/json/ - dump_str_fail 244s END /main/json/ - dump_str_fail Time: <1ms Result: PASS 244s START /main/json/ - dump_load_str 244s END /main/json/ - dump_load_str Time: <1ms Result: PASS 244s START /main/json/ - dump_load_string 244s END /main/json/ - dump_load_string Time: <1ms Result: PASS 244s START /main/json/ - object_create_vars 244s END /main/json/ - object_create_vars Time: <1ms Result: PASS 244s START /main/json/ - object_iter_null 244s END /main/json/ - object_iter_null Time: <1ms Result: PASS 244s START /main/json/ - object_iter 244s END /main/json/ - object_iter Time: <1ms Result: PASS 244s START /main/json/ - object_null 244s END /main/json/ - object_null Time: <1ms Result: PASS 244s START /main/json/ - object_merge_missing 244s END /main/json/ - object_merge_missing Time: <1ms Result: PASS 244s START /main/json/ - object_alloc 244s END /main/json/ - object_alloc Time: <1ms Result: PASS 244s START /main/json/ - object_alloc 244s END /main/json/ - object_alloc Time: <1ms Result: PASS 244s START /main/json/ - object_clear 244s END /main/json/ - object_clear Time: <1ms Result: PASS 244s START /main/json/ - object_del 244s END /main/json/ - object_del Time: <1ms Result: PASS 244s START /main/json/ - object_get 244s END /main/json/ - object_get Time: <1ms Result: PASS 244s START /main/json/ - object_set_overwriting 244s END /main/json/ - object_set_overwriting Time: <1ms Result: PASS 244s START /main/json/ - object_set 244s END /main/json/ - object_set Time: <1ms Result: PASS 244s START /main/json/ - object_alloc 244s END /main/json/ - object_alloc Time: <1ms Result: PASS 244s START /main/json/ - array_null 244s END /main/json/ - array_null Time: <1ms Result: PASS 244s START /main/json/ - array_extend 244s END /main/json/ - array_extend Time: <1ms Result: PASS 244s START /main/json/ - array_clear 244s END /main/json/ - array_clear Time: <1ms Result: PASS 244s START /main/json/ - array_remove 244s END /main/json/ - array_remove Time: <1ms Result: PASS 244s START /main/json/ - array_set 244s END /main/json/ - array_set Time: <1ms Result: PASS 244s START /main/json/ - array_insert 244s END /main/json/ - array_insert Time: <1ms Result: PASS 244s START /main/json/ - array_append 244s END /main/json/ - array_append Time: <1ms Result: PASS 244s START /main/json/ - array_create 244s END /main/json/ - array_create Time: <1ms Result: PASS 244s START /main/json/ - non_int 244s END /main/json/ - non_int Time: <1ms Result: PASS 244s START /main/json/ - type_int 244s END /main/json/ - type_int Time: <1ms Result: PASS 244s START /main/json/ - stringf 244s END /main/json/ - stringf Time: <1ms Result: PASS 244s START /main/json/ - string_null 244s END /main/json/ - string_null Time: <1ms Result: PASS 244s START /main/json/ - type_string 244s END /main/json/ - type_string Time: <1ms Result: PASS 244s START /main/json/ - null_val 244s END /main/json/ - null_val Time: <1ms Result: PASS 244s START /main/json/ - type_null 244s END /main/json/ - type_null Time: <1ms Result: PASS 244s START /main/json/ - type_bool1 244s END /main/json/ - type_bool1 Time: <1ms Result: PASS 244s START /main/json/ - type_bool0 244s END /main/json/ - type_bool0 Time: <1ms Result: PASS 244s START /main/json/ - type_true 244s END /main/json/ - type_true Time: <1ms Result: PASS 244s START /main/json/ - type_false 244s END /main/json/ - type_false Time: <1ms Result: PASS 244s START /main/linkedlists/ - double_ll_tests 244s END /main/linkedlists/ - double_ll_tests Time: <1ms Result: PASS 244s START /main/linkedlists/ - ll_tests 244s END /main/linkedlists/ - ll_tests Time: <1ms Result: PASS 244s START /main/lock/ - named_lock_test 244s [test_named_lock.c:named_lock_test:80]: This test should take about 3 seconds 247s END /main/lock/ - named_lock_test Time: 3000ms Result: PASS 247s START /main/lock/ - cleanup_order_test 247s [test_scoped_lock.c:test_ref:149]: Ref is occurring 247s [test_scoped_lock.c:test_lock:117]: Lock is occurring 247s [test_scoped_lock.c:test_unlock:133]: Unlock is occurring 247s [test_scoped_lock.c:test_unref:166]: Unref is occurring 247s [test_scoped_lock.c:test_ref:149]: Ref is occurring 247s [test_scoped_lock.c:test_lock:117]: Lock is occurring 247s [test_scoped_lock.c:test_unlock:133]: Unlock is occurring 247s [test_scoped_lock.c:test_unref:166]: Unref is occurring 247s END /main/lock/ - cleanup_order_test Time: <1ms Result: PASS 247s START /main/lock/ - lock_test 247s END /main/lock/ - lock_test Time: <1ms Result: PASS 247s START /main/logging/ - scope_test 247s END /main/logging/ - scope_test Time: <1ms Result: PASS 247s START /main/media_cache/ - create_update_off_nominal 247s END /main/media_cache/ - create_update_off_nominal Time: 34ms Result: PASS 247s START /main/media_cache/ - create_update_metadata 247s [test_media_cache.c:create_update_metadata:364]: Got /tmp/test-media-cache-IimoUd for second file path 247s END /main/media_cache/ - create_update_metadata Time: <1ms Result: PASS 247s START /main/media_cache/ - create_update_nominal 247s [test_media_cache.c:create_update_nominal:235]: Creating resource with /tmp/test-media-cache-qv2NIH 247s [test_media_cache.c:create_update_nominal:240]: Got /tmp/test-media-cache-qv2NIH for first file path 247s [test_media_cache.c:create_update_nominal:244]: Creating resource with /tmp/test-media-cache-NBm0NK 247s [test_media_cache.c:create_update_nominal:249]: Got /tmp/test-media-cache-NBm0NK for second file path 247s END /main/media_cache/ - create_update_nominal Time: 13ms Result: PASS 247s START /main/media_cache/ - exists_off_nominal 247s END /main/media_cache/ - exists_off_nominal Time: <1ms Result: PASS 247s START /main/media_cache/ - exists_nominal 247s END /main/media_cache/ - exists_nominal Time: <1ms Result: PASS 247s START /main/netsock2/ - split_hostport 247s END /main/netsock2/ - split_hostport Time: <1ms Result: PASS 247s START /main/netsock2/ - parsing 247s END /main/netsock2/ - parsing Time: <1ms Result: PASS 247s START /main/optional_api/ - test_provide_last 247s END /main/optional_api/ - test_provide_last Time: <1ms Result: PASS 247s START /main/optional_api/ - test_provide_first 247s END /main/optional_api/ - test_provide_first Time: <1ms Result: PASS 247s START /main/pbx/ - pattern_match_test 247s [test_pbx.c:test_exten:183]: Successfully matched 200 to exten _2. in context test_pattern with the old pattern match engine 247s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the old pattern match engine 247s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the old pattern match engine 247s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern_include with the old pattern match engine 247s [test_pbx.c:test_exten:183]: Successfully matched 200 to exten _2. in context test_pattern with the new pattern match engine 247s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the new pattern match engine 247s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the new pattern match engine 247s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern_include with the new pattern match engine 247s END /main/pbx/ - pattern_match_test Time: 1ms Result: PASS 247s START /main/pbx/ - test_MATH_function 247s [func_math.c:test_MATH_function:682]: Testing MATH() substitution ... 247s END /main/pbx/ - test_MATH_function Time: 7ms Result: PASS 247s START /main/pbx/ - test_substitution 247s [test_substitution.c:test_substitution:244]: Testing variable substitution ... 247s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGANI2}' . . . . . passed 247s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGTON}' . . . . . passed 247s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGTNS}' . . . . . passed 247s [test_substitution.c:test_chan_integer_accessor:89]: Tested '${HANGUPCAUSE}' . . . . . passed 247s [test_substitution.c:test_chan_integer_accessor:89]: Tested '${PRIORITY}' . . . . . passed 247s [test_substitution.c:test_chan_string:115]: Tested '${CONTEXT}' . . . . . passed 247s [test_substitution.c:test_chan_string:115]: Tested '${EXTEN}' . . . . . passed 247s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(language)}' . . . . . passed 247s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(musicclass)}' . . . . . passed 247s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(parkinglot)}' . . . . . passed 247s [test_substitution.c:test_chan_variable:144]: Tested '${CALLERID(name)}' . . . . . passed 247s [test_substitution.c:test_chan_variable:144]: Tested '${CURLOPT(proxyuserpwd)}' . . . . . passed 247s [test_substitution.c:test_chan_variable:144]: Tested '${CDR(foo)}' . . . . . passed 247s [test_substitution.c:test_chan_variable:144]: Tested '${ENV(foo)}' . . . . . passed 247s [test_substitution.c:test_chan_variable:144]: Tested '${GLOBAL(foo)}' . . . . . passed 247s [test_substitution.c:test_chan_variable:144]: Tested '${GROUP()}' . . . . . passed 247s [test_substitution.c:test_2way_function:193]: Tested '${AES_ENCRYPT(abcdefghijklmnop,)}' and '${AES_DECRYPT(abcdefghijklmnop,)}' . . . . . passed 247s [test_substitution.c:test_2way_function:193]: Tested '${BASE64_ENCODE()}' and '${BASE64_DECODE()}' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested '123123' ('${foo}${foo}') == '123123' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested 'A123A123A' ('A${foo}A${foo}A') == 'A123A123A' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested 'A123A' ('A${${bar}}A') == 'A123A' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested 'A123A' ('A${${baz}o}A') == 'A123A' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested 'A23A' ('A${${baz}o:1}A') == 'A23A' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:1:1}A') == 'A2A' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:1:-1}A') == 'A2A' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested 'A3A' ('A${${baz}o:-1:1}A') == 'A3A' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:-2:1}A') == 'A2A' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:-2:-1}A') == 'A2A' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested 'cd&ef' ('${LISTFILTER(list1,&,ab)}') == 'cd&ef' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested 'ab&ef' ('${LISTFILTER(list1,&,cd)}') == 'ab&ef' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd' ('${LISTFILTER(list1,&,ef)}') == 'ab&cd' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,gh)}') == 'ab&cd&ef' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,c)}') == 'ab&cd&ef' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,d)}') == 'ab&cd&ef' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested '' ('${LISTFILTER(list2,&,ab)}') == '' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested '' ('${LISTFILTER(list_empty,&,ab)}') == '' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested '123,456' ('${SHELL(printf '%d' 123)},${SHELL(printf '%d' 456)}') == '123,456' . . . . . passed 247s [test_substitution.c:test_expected_result:215]: Tested '123,,456' ('${foo},${CDR(answer)},${SHELL(printf '%d' 456)}') == '123,,456' . . . . . passed 247s [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 247s [test_substitution.c:test_expected_result:215]: Tested '123,,' ('${foo},${this_does_not_exist},${THIS_DOES_NOT_EXIST(either)}') == '123,,' . . . . . passed 247s [test_substitution.c:test_chan_function:168]: Tested '${BLACKLIST(foo)}' . . . . . passed 247s [test_substitution.c:test_chan_function:168]: Tested '${EVAL(foo)}' . . . . . passed 247s [test_substitution.c:test_chan_function:168]: Tested '${FIELDNUM(foo)}' . . . . . passed 247s [test_substitution.c:test_chan_function:168]: Tested '${FIELDQTY(foo)}' . . . . . passed 247s [test_substitution.c:test_chan_function:168]: Tested '${HASHKEYS(foo)}' . . . . . passed 247s [test_substitution.c:test_chan_function:168]: Tested '${IMPORT(foo)}' . . . . . passed 247s [test_substitution.c:test_chan_function:168]: Tested '${PP_EACH_USER(foo)}' . . . . . passed 247s [test_substitution.c:test_chan_function:168]: Tested '${TOLOWER(foo)}' . . . . . passed 247s [test_substitution.c:test_chan_function:168]: Tested '${TOUPPER(foo)}' . . . . . passed 247s END /main/pbx/ - test_substitution Time: 23ms Result: PASS 247s START /main/pbx/ - variable_substrings 247s END /main/pbx/ - variable_substrings Time: 3ms Result: PASS 247s START /main/poll/ - poll_test 247s [test_poll.c:poll_test:95]: Creating handle that should NEVER block on write 247s [test_poll.c:poll_test:101]: Creating handle that should NEVER block on read 247s [test_poll.c:poll_test:108]: Creating handle that should block on read 247s [test_poll.c:poll_test:168]: Starting thread to ensure we don't block forever 247s [test_poll.c:poll_test:194]: Cancelling failsafe thread. 247s END /main/poll/ - poll_test Time: <1ms Result: PASS 247s START /main/presence/ - channel_presence 247s END /main/presence/ - channel_presence Time: <1ms Result: PASS 247s START /main/sample/ - sample_test 247s [test_skel.c:sample_test:57]: Executing sample test... 247s END /main/sample/ - sample_test Time: <1ms Result: PASS 247s START /main/sched/ - sched_test_freebird 247s [test_sched.c:sched_test_freebird:440]: Received signal, calling Scedule and UNREF 247s [test_sched.c:sched_test_freebird:441]: ID: 1 250s [test_sched.c:sched_test_freebird:448]: Correct number of references '2' 250s END /main/sched/ - sched_test_freebird Time: 3000ms Result: PASS 250s START /main/sched/ - sched_test_order 251s END /main/sched/ - sched_test_order Time: 400ms Result: PASS 251s START /main/sorcery/ - wizard_read_only 251s END /main/sorcery/ - wizard_read_only Time: <1ms Result: PASS 251s START /main/sorcery/ - wizard_observation 251s END /main/sorcery/ - wizard_observation Time: <1ms Result: PASS 251s START /main/sorcery/ - instance_observation 251s END /main/sorcery/ - instance_observation Time: <1ms Result: PASS 251s START /main/sorcery/ - global_observation 251s END /main/sorcery/ - global_observation Time: <1ms Result: PASS 251s START /main/sorcery/ - object_field_registered 251s END /main/sorcery/ - object_field_registered Time: <1ms Result: PASS 251s START /main/sorcery/ - dialplan_function 251s END /main/sorcery/ - dialplan_function Time: <1ms Result: PASS 251s START /main/sorcery/ - configuration_file_wizard_retrieve_multiple_all 251s END /main/sorcery/ - configuration_file_wizard_retrieve_multiple_all Time: <1ms Result: PASS 251s START /main/sorcery/ - configuration_file_wizard_retrieve_multiple 251s END /main/sorcery/ - configuration_file_wizard_retrieve_multiple Time: <1ms Result: PASS 251s START /main/sorcery/ - configuration_file_wizard_retrieve_field 251s END /main/sorcery/ - configuration_file_wizard_retrieve_field Time: <1ms Result: PASS 251s START /main/sorcery/ - configuration_file_wizard_with_criteria 251s END /main/sorcery/ - configuration_file_wizard_with_criteria Time: <1ms Result: PASS 251s START /main/sorcery/ - configuration_file_wizard_with_file_integrity 251s END /main/sorcery/ - configuration_file_wizard_with_file_integrity Time: <1ms Result: PASS 251s START /main/sorcery/ - configuration_file_wizard 251s END /main/sorcery/ - configuration_file_wizard Time: <1ms Result: PASS 251s START /main/sorcery/ - object_type_observer 251s END /main/sorcery/ - object_type_observer Time: <1ms Result: PASS 251s START /main/sorcery/ - caching_wizard_behavior 251s END /main/sorcery/ - caching_wizard_behavior Time: <1ms Result: PASS 251s START /main/sorcery/ - object_is_stale 251s END /main/sorcery/ - object_is_stale Time: <1ms Result: PASS 251s START /main/sorcery/ - object_delete_uncreated 251s END /main/sorcery/ - object_delete_uncreated Time: <1ms Result: PASS 251s START /main/sorcery/ - object_delete 251s END /main/sorcery/ - object_delete Time: <1ms Result: PASS 251s START /main/sorcery/ - object_update_uncreated 251s END /main/sorcery/ - object_update_uncreated Time: <1ms Result: PASS 251s START /main/sorcery/ - object_update 251s END /main/sorcery/ - object_update Time: <1ms Result: PASS 251s START /main/sorcery/ - object_retrieve_regex 251s END /main/sorcery/ - object_retrieve_regex Time: <1ms Result: PASS 251s START /main/sorcery/ - object_retrieve_multiple_field 251s END /main/sorcery/ - object_retrieve_multiple_field Time: <1ms Result: PASS 251s START /main/sorcery/ - object_retrieve_multiple_all 251s END /main/sorcery/ - object_retrieve_multiple_all Time: <1ms Result: PASS 251s START /main/sorcery/ - object_retrieve_field 251s END /main/sorcery/ - object_retrieve_field Time: <1ms Result: PASS 251s START /main/sorcery/ - object_retrieve_id 251s END /main/sorcery/ - object_retrieve_id Time: <1ms Result: PASS 251s START /main/sorcery/ - object_create 251s END /main/sorcery/ - object_create Time: <1ms Result: PASS 251s START /main/sorcery/ - changeset_create_unchanged 251s END /main/sorcery/ - changeset_create_unchanged Time: <1ms Result: PASS 251s START /main/sorcery/ - changeset_create 251s END /main/sorcery/ - changeset_create Time: <1ms Result: PASS 251s START /main/sorcery/ - extended_fields 251s END /main/sorcery/ - extended_fields Time: <1ms Result: PASS 251s START /main/sorcery/ - objectset_apply_fields 251s END /main/sorcery/ - objectset_apply_fields Time: <1ms Result: PASS 251s START /main/sorcery/ - objectset_transform 251s END /main/sorcery/ - objectset_transform Time: <1ms Result: PASS 251s START /main/sorcery/ - objectset_apply_invalid 251s END /main/sorcery/ - objectset_apply_invalid Time: <1ms Result: PASS 251s START /main/sorcery/ - objectset_apply_handler 251s END /main/sorcery/ - objectset_apply_handler Time: <1ms Result: PASS 251s START /main/sorcery/ - objectset_apply 251s END /main/sorcery/ - objectset_apply Time: <1ms Result: PASS 251s START /main/sorcery/ - objectset_create_regex 251s END /main/sorcery/ - objectset_create_regex Time: <1ms Result: PASS 251s START /main/sorcery/ - objectset_json_create 251s END /main/sorcery/ - objectset_json_create Time: <1ms Result: PASS 251s START /main/sorcery/ - objectset_create 251s END /main/sorcery/ - objectset_create Time: <1ms Result: PASS 251s START /main/sorcery/ - object_diff_native 251s END /main/sorcery/ - object_diff_native Time: <1ms Result: PASS 251s START /main/sorcery/ - object_diff 251s END /main/sorcery/ - object_diff Time: <1ms Result: PASS 251s START /main/sorcery/ - object_copy_native 251s END /main/sorcery/ - object_copy_native Time: <1ms Result: PASS 251s START /main/sorcery/ - object_copy 251s END /main/sorcery/ - object_copy Time: <1ms Result: PASS 251s START /main/sorcery/ - object_alloc_without_id 251s END /main/sorcery/ - object_alloc_without_id Time: <1ms Result: PASS 251s START /main/sorcery/ - object_alloc_with_id 251s END /main/sorcery/ - object_alloc_with_id Time: <1ms Result: PASS 251s START /main/sorcery/ - object_fields_register 251s END /main/sorcery/ - object_fields_register Time: <1ms Result: PASS 251s START /main/sorcery/ - object_field_register 251s END /main/sorcery/ - object_field_register Time: <1ms Result: PASS 251s START /main/sorcery/ - object_register_without_mapping 251s END /main/sorcery/ - object_register_without_mapping Time: <1ms Result: PASS 251s START /main/sorcery/ - object_register 251s END /main/sorcery/ - object_register Time: <1ms Result: PASS 251s START /main/sorcery/ - apply_config 251s END /main/sorcery/ - apply_config Time: <1ms Result: PASS 251s START /main/sorcery/ - apply_default 251s END /main/sorcery/ - apply_default Time: <1ms Result: PASS 251s START /main/sorcery/ - open 251s END /main/sorcery/ - open Time: <1ms Result: PASS 251s START /main/sorcery/ - wizard_registration 251s END /main/sorcery/ - wizard_registration Time: <1ms Result: PASS 251s START /main/sorcery/ - wizard_apply_and_insert 251s END /main/sorcery/ - wizard_apply_and_insert Time: <1ms Result: PASS 251s START /main/stdtime/ - time_create_by_unit_str 251s END /main/stdtime/ - time_create_by_unit_str Time: <1ms Result: PASS 251s START /main/stdtime/ - time_create_by_unit 251s END /main/stdtime/ - time_create_by_unit Time: <1ms Result: PASS 251s START /main/stdtime/ - time_str_to_unit 251s END /main/stdtime/ - time_str_to_unit Time: <1ms Result: PASS 251s START /main/stdtime/ - time_tv_to_usec 251s END /main/stdtime/ - time_tv_to_usec Time: <1ms Result: PASS 251s START /main/stdtime/ - timezone_watch 251s [test_time.c:test_timezone_watch:82]: Executing deletion test... 251s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.IDWdf0/test 252s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.IDWdf0/test 252s [test_time.c:test_timezone_watch:82]: Executing symlink test... 252s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.IDWdf0/test 253s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.IDWdf0/test 253s END /main/stdtime/ - timezone_watch Time: 2278ms Result: PASS 253s START /main/stream/ - stream_topology_map_create 253s END /main/stream/ - stream_topology_map_create Time: <1ms Result: PASS 253s START /main/stream/ - format_cap_from_stream_topology 253s END /main/stream/ - format_cap_from_stream_topology Time: <1ms Result: PASS 253s START /main/stream/ - stream_topology_change_request_from_channel 253s END /main/stream/ - stream_topology_change_request_from_channel Time: <1ms Result: PASS 253s START /main/stream/ - stream_topology_change_request_from_application 253s END /main/stream/ - stream_topology_change_request_from_application Time: <1ms Result: PASS 253s START /main/stream/ - stream_topology_change_request_from_channel_non_multistream 253s END /main/stream/ - stream_topology_change_request_from_channel_non_multistream Time: <1ms Result: PASS 253s START /main/stream/ - stream_topology_change_request_from_application_non_multistream 253s END /main/stream/ - stream_topology_change_request_from_application_non_multistream Time: <1ms Result: PASS 253s START /main/stream/ - stream_read_multistream 253s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 253s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 253s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 253s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 253s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 4 Frames: 16 Frames per read: 1 Expected Nulls: 8 253s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 8 253s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 4 Frames: 16 Frames per read: 1 Expected Nulls: 0 253s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 253s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 253s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 253s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 253s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 253s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 4 Frames: 16 Frames per read: 3 Expected Nulls: 8 253s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 8 253s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 4 Frames: 16 Frames per read: 3 Expected Nulls: 0 253s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 253s END /main/stream/ - stream_read_multistream Time: <1ms Result: PASS 253s START /main/stream/ - stream_read_non_multistream 253s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 253s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 253s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 253s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 253s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 253s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 253s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 253s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 253s END /main/stream/ - stream_read_non_multistream Time: <1ms Result: PASS 253s START /main/stream/ - stream_write_multistream 253s END /main/stream/ - stream_write_multistream Time: <1ms Result: PASS 253s START /main/stream/ - stream_write_non_multistream 253s END /main/stream/ - stream_write_non_multistream Time: <1ms Result: PASS 253s START /main/stream/ - stream_topology_channel_set 253s END /main/stream/ - stream_topology_channel_set Time: <1ms Result: PASS 253s START /main/stream/ - stream_topology_create_from_channel_nativeformats 253s END /main/stream/ - stream_topology_create_from_channel_nativeformats Time: <1ms Result: PASS 253s START /main/stream/ - stream_topology_get_first_stream_by_type 253s END /main/stream/ - stream_topology_get_first_stream_by_type Time: <1ms Result: PASS 253s START /main/stream/ - stream_topology_create_from_format_cap 253s END /main/stream/ - stream_topology_create_from_format_cap Time: <1ms Result: PASS 253s START /main/stream/ - stream_topology_del_stream 253s END /main/stream/ - stream_topology_del_stream Time: <1ms Result: PASS 253s START /main/stream/ - stream_topology_set_stream 253s END /main/stream/ - stream_topology_set_stream Time: <1ms Result: PASS 253s START /main/stream/ - stream_topology_append_stream 253s END /main/stream/ - stream_topology_append_stream Time: <1ms Result: PASS 253s START /main/stream/ - stream_topology_clone 253s END /main/stream/ - stream_topology_clone Time: <1ms Result: PASS 253s START /main/stream/ - stream_topology_create 253s END /main/stream/ - stream_topology_create Time: <1ms Result: PASS 253s START /main/stream/ - stream_metadata 253s END /main/stream/ - stream_metadata Time: <1ms Result: PASS 253s START /main/stream/ - stream_set_state 253s END /main/stream/ - stream_set_state Time: <1ms Result: PASS 253s START /main/stream/ - stream_set_formats 253s END /main/stream/ - stream_set_formats Time: <1ms Result: PASS 253s START /main/stream/ - stream_set_type 253s END /main/stream/ - stream_set_type Time: <1ms Result: PASS 253s START /main/stream/ - stream_create_no_name 253s END /main/stream/ - stream_create_no_name Time: <1ms Result: PASS 253s START /main/stream/ - stream_create 253s END /main/stream/ - stream_create Time: <1ms Result: PASS 253s START /main/strings/ - in_delimited_string 253s END /main/strings/ - in_delimited_string Time: <1ms Result: PASS 253s START /main/strings/ - temp_strings 253s END /main/strings/ - temp_strings Time: <1ms Result: PASS 253s START /main/strings/ - strings_match 253s END /main/strings/ - strings_match Time: <1ms Result: PASS 253s START /main/strings/ - escape 253s END /main/strings/ - escape Time: <1ms Result: PASS 253s START /main/strings/ - escape_semicolons 253s END /main/strings/ - escape_semicolons Time: <1ms Result: PASS 253s START /main/strings/ - strsep_quoted 253s END /main/strings/ - strsep_quoted Time: <1ms Result: PASS 253s START /main/strings/ - strsep 253s END /main/strings/ - strsep Time: <1ms Result: PASS 253s START /main/strings/ - ends_with 253s END /main/strings/ - ends_with Time: <1ms Result: PASS 253s START /main/strings/ - begins_with 253s END /main/strings/ - begins_with Time: <1ms Result: PASS 253s START /main/strings/ - str_test 253s END /main/strings/ - str_test Time: <1ms Result: PASS 253s START /main/taskprocessor/ - serializer_pool 257s END /main/taskprocessor/ - serializer_pool Time: 4000ms Result: PASS 257s START /main/taskprocessor/ - taskprocessor_push_local 257s END /main/taskprocessor/ - taskprocessor_push_local Time: <1ms Result: PASS 257s START /main/taskprocessor/ - taskprocessor_shutdown 257s END /main/taskprocessor/ - taskprocessor_shutdown Time: <1ms Result: PASS 257s START /main/taskprocessor/ - taskprocessor_listener 257s END /main/taskprocessor/ - taskprocessor_listener Time: <1ms Result: PASS 257s START /main/taskprocessor/ - subsystem_alert 257s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 1 257s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 2 257s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 3 257s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 4 257s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 5 257s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 6 257s [test_taskprocessor.c:subsystem_alert:237]: Subsystem alert triggered correctly at 6 257s [test_taskprocessor.c:subsystem_alert:240]: Global alert triggered correctly at 6 257s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 7 257s [test_taskprocessor.c:subsystem_alert:237]: Subsystem alert triggered correctly at 6 257s [test_taskprocessor.c:subsystem_alert:240]: Global alert triggered correctly at 6 257s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 8 257s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 9 257s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 10 257s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 1 257s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 2 258s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 3 258s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 4 259s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 5 259s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 6 260s [test_taskprocessor.c:subsystem_alert:279]: Subsystem alert cleared correctly at 3 260s [test_taskprocessor.c:subsystem_alert:282]: Global alert cleared correctly at 3 260s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 7 260s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 8 261s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 9 261s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 10 262s END /main/taskprocessor/ - subsystem_alert Time: 5001ms Result: PASS 262s START /main/taskprocessor/ - default_taskprocessor_load 262s END /main/taskprocessor/ - default_taskprocessor_load Time: 26ms Result: PASS 262s START /main/taskprocessor/ - default_taskprocessor 262s END /main/taskprocessor/ - default_taskprocessor Time: <1ms Result: PASS 262s START /main/test/ - registrations 262s END /main/test/ - registrations Time: <1ms Result: PASS 262s START /main/test_capture/ - test_capture_false 262s [test_capture.c:test_capture_false:120]: Executing false exit test... 262s END /main/test_capture/ - test_capture_false Time: 40ms Result: PASS 262s START /main/test_capture/ - test_capture_true 262s [test_capture.c:test_capture_true:61]: Executing true exit test... 262s END /main/test_capture/ - test_capture_true Time: 12ms Result: PASS 262s START /main/test_capture/ - test_capture_stdout_stderr 262s [test_capture.c:test_capture_stdout_stderr:318]: Executing stdout/stderr test... 262s END /main/test_capture/ - test_capture_stdout_stderr Time: 13ms Result: PASS 262s START /main/test_capture/ - test_capture_with_dynamic 262s [test_capture.c:test_capture_with_dynamic:249]: Executing dynamic argument test... 262s END /main/test_capture/ - test_capture_with_dynamic Time: 15ms Result: PASS 262s START /main/test_capture/ - test_capture_with_stdin 262s [test_capture.c:test_capture_with_stdin:183]: Executing stdin test... 262s END /main/test_capture/ - test_capture_with_stdin Time: 33ms Result: PASS 262s START /main/threadpool/ - threadpool_serializer_dupe 262s END /main/threadpool/ - threadpool_serializer_dupe Time: 2ms Result: PASS 262s START /main/threadpool/ - threadpool_serializer 263s END /main/threadpool/ - threadpool_serializer Time: 1001ms Result: PASS 263s START /main/threadpool/ - more_destruction 263s END /main/threadpool/ - more_destruction Time: <1ms Result: PASS 263s START /main/threadpool/ - task_distribution 263s END /main/threadpool/ - task_distribution Time: <1ms Result: PASS 263s START /main/threadpool/ - reactivation 263s END /main/threadpool/ - reactivation Time: <1ms Result: PASS 263s START /main/threadpool/ - max_size 263s END /main/threadpool/ - max_size Time: <1ms Result: PASS 263s START /main/threadpool/ - auto_increment 263s END /main/threadpool/ - auto_increment Time: <1ms Result: PASS 263s START /main/threadpool/ - one_thread_multiple_tasks 263s END /main/threadpool/ - one_thread_multiple_tasks Time: <1ms Result: PASS 263s START /main/threadpool/ - one_thread_one_task 263s END /main/threadpool/ - one_thread_one_task Time: <1ms Result: PASS 263s START /main/threadpool/ - one_task_one_thread 263s END /main/threadpool/ - one_task_one_thread Time: <1ms Result: PASS 263s START /main/threadpool/ - thread_timeout_thrash 294s END /main/threadpool/ - thread_timeout_thrash Time: 31011ms Result: PASS 294s START /main/threadpool/ - thread_timeout 296s END /main/threadpool/ - thread_timeout Time: 2000ms Result: PASS 296s START /main/threadpool/ - thread_destruction 296s END /main/threadpool/ - thread_destruction Time: <1ms Result: PASS 296s START /main/threadpool/ - thread_creation 296s END /main/threadpool/ - thread_creation Time: <1ms Result: PASS 296s START /main/threadpool/ - initial_threads 296s END /main/threadpool/ - initial_threads Time: <1ms Result: PASS 296s START /main/threadpool/ - push 296s END /main/threadpool/ - push Time: <1ms Result: PASS 296s START /main/uri/ - uri_default_http_secure 296s END /main/uri/ - uri_default_http_secure Time: <1ms Result: PASS 296s START /main/uri/ - uri_default_http 296s END /main/uri/ - uri_default_http Time: <1ms Result: PASS 296s START /main/uri/ - uri_parse 296s END /main/uri/ - uri_parse Time: <1ms Result: PASS 296s START /main/utf8/ - replace_invalid 296s END /main/utf8/ - replace_invalid Time: <1ms Result: PASS 296s START /main/utf8/ - utf8_validator 296s END /main/utf8/ - utf8_validator Time: <1ms Result: PASS 296s START /main/utf8/ - copy_string 296s END /main/utf8/ - copy_string Time: <1ms Result: PASS 296s START /main/utf8/ - is_valid 296s END /main/utf8/ - is_valid Time: <1ms Result: PASS 296s START /main/utils/ - quote_unescaping 296s END /main/utils/ - quote_unescaping Time: <1ms Result: PASS 296s START /main/utils/ - quote_mutation 296s END /main/utils/ - quote_mutation Time: <1ms Result: PASS 296s START /main/utils/ - crypt_test 296s END /main/utils/ - crypt_test Time: 10ms Result: PASS 296s START /main/utils/ - safe_mkdir_test 296s END /main/utils/ - safe_mkdir_test Time: <1ms Result: PASS 296s START /main/utils/ - base64_test 296s END /main/utils/ - base64_test Time: <1ms Result: PASS 296s START /main/utils/ - sha1_test 296s [test_utils.c:sha1_test:250]: Testing SHA1 ... 296s END /main/utils/ - sha1_test Time: <1ms Result: PASS 296s START /main/utils/ - md5_test 296s [test_utils.c:md5_test:205]: Testing MD5 ... 296s END /main/utils/ - md5_test Time: <1ms Result: PASS 296s START /main/utils/ - quoted_escape_test 296s END /main/utils/ - quoted_escape_test Time: <1ms Result: PASS 296s START /main/utils/ - uri_encode_decode_test 296s END /main/utils/ - uri_encode_decode_test Time: <1ms Result: PASS 296s START /main/utils/ - string_field_aggregate_test 296s [test_stringfields.c:string_field_aggregate_test:392]: Structures 3 embedded pool initialized successfully. 296s [test_stringfields.c:string_field_aggregate_test:410]: Structures 3 additional pool initialized successfully. 296s [test_stringfields.c:string_field_aggregate_test:422]: Structures 1/2 are equal as expected. 296s [test_stringfields.c:string_field_aggregate_test:430]: Structures 1/3 are different as expected. 296s [test_stringfields.c:string_field_aggregate_test:438]: Structures 2/3 are different as expected. 296s [test_stringfields.c:string_field_aggregate_test:446]: Structures 3/4 are different as expected. 296s [test_stringfields.c:string_field_aggregate_test:454]: Copying from structure 3 to structure 1 succeeded! 296s [test_stringfields.c:string_field_aggregate_test:463]: Structures 1/3 are equal as expected. 296s [test_stringfields.c:string_field_aggregate_test:470]: Structures 1/2 are different as expected. 296s [test_stringfields.c:string_field_aggregate_test:473]: Reset but don't free. 296s [test_stringfields.c:string_field_aggregate_test:484]: Structures 1/2 are the same (empty) as expected. 296s [test_stringfields.c:string_field_aggregate_test:492]: Structure 4 embedded pool is the current pool as expected. 296s [test_stringfields.c:string_field_aggregate_test:500]: Structure 4 embedded pool does not have a previous as expected. 296s END /main/utils/ - string_field_aggregate_test Time: <1ms Result: PASS 296s START /main/utils/ - string_field_test 296s [test_stringfields.c:string_field_test:79]: First things first. Let's see if we can actually allocate string fields 296s [test_stringfields.c:string_field_test:85]: All right! Successfully allocated! Now let's get down to business 296s [test_stringfields.c:string_field_test:89]: We're going to set some string fields and perform some checks 296s [test_stringfields.c:string_field_test:94]: First we're going to make sure that the strings are actually set to what we expect 296s [test_stringfields.c:string_field_test:100]: test_struct.string1 appears to be all clear. It has 'elephant' and that's what we expect 296s [test_stringfields.c:string_field_test:107]: test_struct.string2 appears to be all clear. It has 'hippopotamus' and that's what we expect 296s [test_stringfields.c:string_field_test:110]: Now let's make sure that our recorded capacities for these strings is what we expect 296s [test_stringfields.c:string_field_test:117]: string1 has the allocation area we expect: 9 296s [test_stringfields.c:string_field_test:125]: string2 has the allocation area we expect: 13 296s [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 296s [test_stringfields.c:string_field_test:137]: string1 successfully was changed to 'rhino' 296s [test_stringfields.c:string_field_test:144]: Shrinking string1 allowed it to stay in the same place in memory 296s [test_stringfields.c:string_field_test:151]: Shrinking string1 did not change its allocation area (This is a good thing) 296s [test_stringfields.c:string_field_test:154]: Next, let's increase it a little but not all the way to its original size 296s [test_stringfields.c:string_field_test:163]: string1 successfully was changed to 'mammoth' 296s [test_stringfields.c:string_field_test:170]: Expanding string1 allowed it to stay in the same place in memory 296s [test_stringfields.c:string_field_test:177]: Expanding string1 did not change its allocation area (This is a good thing) 296s [test_stringfields.c:string_field_test:180]: Cool, now let's bring it back to its original size and see what happens 296s [test_stringfields.c:string_field_test:188]: string1 successfully changed to 'elephant' 296s [test_stringfields.c:string_field_test:195]: Restoring string1 did not cause it to move (This is a good thing) 296s [test_stringfields.c:string_field_test:202]: The allocation amount for string1 is still holding steady 296s [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 296s [test_stringfields.c:string_field_test:214]: string2 successfully changed to 'hippopotamus face' 296s [test_stringfields.c:string_field_test:222]: The allocation amount successfully increased for string2 when it grew 296s [test_stringfields.c:string_field_test:229]: string2 stayed in place when it grew. Good job! 296s [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 296s [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' 296s [test_stringfields.c:string_field_test:248]: Good. Setting string1 to a long value caused it to change addresses 296s [test_stringfields.c:string_field_test:256]: The stored allocation size of string1 is what we expect 296s [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 296s [test_stringfields.c:string_field_test:281]: Three different pools are linked as expected. 296s [test_stringfields.c:string_field_test:289]: After removing a pool the remaining two are linked as expected. 296s END /main/utils/ - string_field_test Time: <1ms Result: PASS 296s START /main/uuid/ - uuid 296s [test_uuid.c:uuid:59]: Generate UUID direct to string, got cf7546ad-9aa8-45a8-aeda-8d15b4fd5f37 296s [test_uuid.c:uuid:90]: Second generated UUID converted to string, got e98ae6f8-72c9-4c42-9939-1f723cd0af9c 296s END /main/uuid/ - uuid Time: <1ms Result: PASS 296s START /main/vector/ - basic 296s END /main/vector/ - basic Time: <1ms Result: PASS 296s START /main/vector/ - basic_integer 296s END /main/vector/ - basic_integer Time: <1ms Result: PASS 296s START /main/vector/ - callbacks 296s END /main/vector/ - callbacks Time: <1ms Result: PASS 296s START /main/vector/ - locks 296s END /main/vector/ - locks Time: <1ms Result: PASS 296s START /main/voicemail_api/ - off_nominal_msg_playback 296s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1495]: Created message in test_vm_api_1234/Old with ID 1710772535-909401725 296s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1495]: Created message in test_vm_api_1234/INBOX with ID 1710772535-960311778 296s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1495]: Created message in test_vm_api_2345/INBOX with ID 1710772535-1500739833 296s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1495]: Created message in test_vm_api_2345/INBOX with ID 1710772535-719848782 296s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1504]: Playing back message from invalid mailbox 296s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1507]: Playing back message from NULL mailbox 296s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1510]: Playing back message from invalid context 296s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1513]: Playing back message from invalid folder 296s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1516]: Playing back message from NULL folder 296s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1519]: Playing back message with invalid message specifier 296s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1522]: Playing back message with NULL message specifier 296s END /main/voicemail_api/ - off_nominal_msg_playback Time: 22ms Result: PASS 296s START /main/voicemail_api/ - nominal_msg_playback 296s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1433]: Created message in test_vm_api_1234/Old with ID 1710772535-909401725 296s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1433]: Created message in test_vm_api_1234/INBOX with ID 1710772535-960311778 296s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1433]: Created message in test_vm_api_2345/INBOX with ID 1710772535-1500739833 296s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1433]: Created message in test_vm_api_2345/INBOX with ID 1710772535-719848782 296s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1445]: Playing back message from test_vm_api_1234 to mock channel 297s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1448]: Playing back message from test_vm_api_2345 to callback function 297s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1453]: Playing back message from test_vm_api_2345 to callback function with default context 297s END /main/voicemail_api/ - nominal_msg_playback Time: 449ms Result: PASS 297s START /main/voicemail_api/ - off_nominal_forward 297s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1355]: Created message in test_vm_api_1234/Old with ID 1710772536-909401725 297s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1355]: Created message in test_vm_api_1234/INBOX with ID 1710772536-960311778 297s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1355]: Created message in test_vm_api_2345/INBOX with ID 1710772536-1500739833 297s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1355]: Created message in test_vm_api_2345/INBOX with ID 1710772536-719848782 297s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1364]: Test forwarding from an invalid mailbox 297s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1367]: Test forwarding from a NULL mailbox 297s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1370]: Test forwarding from an invalid context 297s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1373]: Test forwarding from an invalid folder 297s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1376]: Test forwarding from a NULL folder 297s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1379]: Test forwarding to an invalid mailbox 297s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1382]: Test forwarding to a NULL mailbox 297s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1385]: Test forwarding to an invalid context 297s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1388]: Test forwarding to an invalid folder 297s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1392]: Test forwarding to a NULL folder 297s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1395]: Test forwarding when no messages are select 297s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1398]: Test forwarding a message that doesn't exist 297s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1402]: Test forwarding multiple messages, where some messages don't exist 297s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1405]: Test forwarding a message with an invalid size specifier 297s END /main/voicemail_api/ - off_nominal_forward Time: 5ms Result: PASS 297s START /main/voicemail_api/ - nominal_forward 297s [test_voicemail_api.c:voicemail_api_nominal_forward:1239]: Created message in test_vm_api_1234/Old with ID 1710772536-909401725 297s [test_voicemail_api.c:voicemail_api_nominal_forward:1239]: Created message in test_vm_api_1234/INBOX with ID 1710772536-960311778 297s [test_voicemail_api.c:voicemail_api_nominal_forward:1239]: Created message in test_vm_api_2345/INBOX with ID 1710772536-1500739833 297s [test_voicemail_api.c:voicemail_api_nominal_forward:1239]: Created message in test_vm_api_2345/INBOX with ID 1710772536-719848782 297s [test_voicemail_api.c:voicemail_api_nominal_forward:1246]: Test forwarding message 0 from test_vm_api_1234 INBOX to test_vm_api_2345 INBOX 297s [test_voicemail_api.c:voicemail_api_nominal_forward:1259]: Test forwarding message 0 from test_vm_api_1234 INBOX with default context to test_vm_api_2345 INBOX 297s [test_voicemail_api.c:voicemail_api_nominal_forward:1272]: Test forwarding message 0 from test_vm_api_1234 INBOX to test_vm_api_2345 INBOX with default context 297s [test_voicemail_api.c:voicemail_api_nominal_forward:1285]: Test forwarding message 0 from test_vm_api_1234 INBOX to test_vm_api_2345 INBOX, deleting original 297s [test_voicemail_api.c:voicemail_api_nominal_forward:1298]: Test forwarding 2 messages from test_vm_api_2345 INBOX to test_vm_api_1234 INBOX[test_voicemail_api.c:voicemail_api_nominal_forward:1311]: Test forwarding 2 messages from test_vm_api_2345 INBOX to test_vm_api_1234 Family, deleting original 297s END /main/voicemail_api/ - nominal_forward Time: 17ms Result: PASS 297s START /main/voicemail_api/ - off_nominal_remove 297s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1180]: Created message in test_vm_api_1234/Old with ID 1710772536-909401725 297s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1180]: Created message in test_vm_api_1234/INBOX with ID 1710772536-960311778 297s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1180]: Created message in test_vm_api_2345/INBOX with ID 1710772536-1500739833 297s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1180]: Created message in test_vm_api_2345/INBOX with ID 1710772536-719848782 297s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1186]: Test removing a single message with an invalid mailbox 297s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1189]: Test removing a single message with a NULL mailbox 297s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1192]: Test removing a single message with an invalid context 297s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1195]: Test removing a single message with an invalid folder 297s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1198]: Test removing a single message with a NULL folder 297s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1201]: Test removing a single message with an invalid message number 297s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1205]: Test removing multiple messages with a single invalid message number 297s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1209]: Test removing no messages with no message numbers 297s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1212]: Test removing multiple messages with an invalid size specifier 297s END /main/voicemail_api/ - off_nominal_remove Time: 5ms Result: PASS 297s START /main/voicemail_api/ - nominal_remove 297s [test_voicemail_api.c:voicemail_api_nominal_remove:1133]: Created message in test_vm_api_1234/Old with ID 1710772536-909401725 297s [test_voicemail_api.c:voicemail_api_nominal_remove:1133]: Created message in test_vm_api_1234/INBOX with ID 1710772536-960311778 297s [test_voicemail_api.c:voicemail_api_nominal_remove:1133]: Created message in test_vm_api_2345/INBOX with ID 1710772536-1500739833 297s [test_voicemail_api.c:voicemail_api_nominal_remove:1133]: Created message in test_vm_api_2345/INBOX with ID 1710772536-719848782 297s [test_voicemail_api.c:voicemail_api_nominal_remove:1141]: Test removing a single message from INBOX 297s [test_voicemail_api.c:voicemail_api_nominal_remove:1144]: Test removing a single message from Old 297s [test_voicemail_api.c:voicemail_api_nominal_remove:1147]: Test removing multiple messages from INBOX 297s END /main/voicemail_api/ - nominal_remove Time: 6ms Result: PASS 297s START /main/voicemail_api/ - off_nominal_move 297s [test_voicemail_api.c:voicemail_api_off_nominal_move:1061]: Created message in test_vm_api_1234/Old with ID 1710772536-909401725 297s [test_voicemail_api.c:voicemail_api_off_nominal_move:1061]: Created message in test_vm_api_1234/INBOX with ID 1710772536-960311778 297s [test_voicemail_api.c:voicemail_api_off_nominal_move:1061]: Created message in test_vm_api_2345/INBOX with ID 1710772536-1500739833 297s [test_voicemail_api.c:voicemail_api_off_nominal_move:1061]: Created message in test_vm_api_2345/INBOX with ID 1710772536-719848782 297s [test_voicemail_api.c:voicemail_api_off_nominal_move:1070]: Test move attempt for invalid mailbox test_vm_3456 297s [test_voicemail_api.c:voicemail_api_off_nominal_move:1075]: Test move attempt for invalid context test_vm_api_defunct 297s [test_voicemail_api.c:voicemail_api_off_nominal_move:1078]: Test move attempt to invalid folder 297s [test_voicemail_api.c:voicemail_api_off_nominal_move:1081]: Test move attempt from invalid folder 297s [test_voicemail_api.c:voicemail_api_off_nominal_move:1084]: Test move attempt to NULL folder 297s [test_voicemail_api.c:voicemail_api_off_nominal_move:1087]: Test move attempt from NULL folder 297s [test_voicemail_api.c:voicemail_api_off_nominal_move:1090]: Test move attempt with non-existent message number 297s [test_voicemail_api.c:voicemail_api_off_nominal_move:1094]: Test move attempt with invalid message number 297s [test_voicemail_api.c:voicemail_api_off_nominal_move:1098]: Test move attempt with 0 number of messages 297s [test_voicemail_api.c:voicemail_api_off_nominal_move:1102]: Test move attempt with invalid number of messages 297s [test_voicemail_api.c:voicemail_api_off_nominal_move:1105]: Test move attempt with non-existent multiple messages, where some messages exist 297s END /main/voicemail_api/ - off_nominal_move Time: 5ms Result: PASS 297s START /main/voicemail_api/ - nominal_move 297s [test_voicemail_api.c:voicemail_api_nominal_move:987]: Created message in test_vm_api_1234/Old with ID 1710772536-909401725 297s [test_voicemail_api.c:voicemail_api_nominal_move:987]: Created message in test_vm_api_1234/INBOX with ID 1710772536-960311778 297s [test_voicemail_api.c:voicemail_api_nominal_move:987]: Created message in test_vm_api_2345/INBOX with ID 1710772536-1500739833 297s [test_voicemail_api.c:voicemail_api_nominal_move:987]: Created message in test_vm_api_2345/INBOX with ID 1710772536-719848782 297s [test_voicemail_api.c:voicemail_api_nominal_move:994]: Test move of test_vm_api_1234 message from INBOX to Family 297s [test_voicemail_api.c:voicemail_api_nominal_move:997]: Test move of test_vm_api_1234 message from Old to Family 297s [test_voicemail_api.c:voicemail_api_nominal_move:1011]: Test move of test_vm_api_2345 messages from Inbox to Family 297s [test_voicemail_api.c:voicemail_api_nominal_move:1022]: Test move of test_vm_api_2345 message from Family to INBOX 297s END /main/voicemail_api/ - nominal_move Time: 8ms Result: PASS 297s START /main/voicemail_api/ - off_nominal_snapshot 297s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:947]: Created message in test_vm_api_1234/Old with ID 1710772536-909401725 297s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:947]: Created message in test_vm_api_1234/INBOX with ID 1710772536-960311778 297s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:947]: Created message in test_vm_api_2345/INBOX with ID 1710772536-1500739833 297s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:947]: Created message in test_vm_api_2345/INBOX with ID 1710772536-719848782 297s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:949]: Test access to non-existent mailbox test_vm_api_3456 297s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:952]: Test access to null mailbox 297s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:955]: Test access non-existent context test_vm_api_defunct 297s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:958]: Test non-existent folder test_vm_api_platypus 297s END /main/voicemail_api/ - off_nominal_snapshot Time: 4ms Result: PASS 297s START /main/voicemail_api/ - nominal_snapshot 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:856]: Created message in test_vm_api_1234/Old with ID 1710772536-909401725 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:856]: Created message in test_vm_api_1234/INBOX with ID 1710772536-960311778 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:856]: Created message in test_vm_api_2345/INBOX with ID 1710772536-1500739833 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:856]: Created message in test_vm_api_2345/INBOX with ID 1710772536-719848782 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:858]: Test retrieving message 1 from INBOX of test_vm_1234 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:861]: Found message 1710772536-960311778 in snapshot 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:864]: Test retrieving message 0 from Old of test_vm_1234 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:867]: Found message 1710772536-909401725 in snapshot 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:870]: Test retrieving message 0, 1 from Old and INBOX of test_vm_1234 ordered by time 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:873]: Found message 1710772536-909401725 in snapshot 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:874]: Found message 1710772536-960311778 in snapshot 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:877]: Test retrieving message 1, 0 from Old and INBOX of test_vm_1234 ordered by time desc 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:880]: Found message 1710772536-960311778 in snapshot 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:881]: Found message 1710772536-909401725 in snapshot 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:884]: Test retrieving message 0, 1 from Old and INBOX of test_vm_1234 ordered by id 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:887]: Found message 1710772536-960311778 in snapshot 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:888]: Found message 1710772536-909401725 in snapshot 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:891]: Test retrieving message 1, 0 from Old and INBOX of test_vm_1234 ordered by id desc 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:894]: Found message 1710772536-909401725 in snapshot 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:895]: Found message 1710772536-960311778 in snapshot 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:898]: Test retrieving message 0, 1 from all folders of test_vm_1234 ordered by id 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:901]: Found message 1710772536-909401725 in snapshot 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:902]: Found message 1710772536-960311778 in snapshot 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:905]: Test retrieving message 0, 1 from all folders of test_vm_1234 ordered by time 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:908]: Found message 1710772536-909401725 in snapshot 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:909]: Found message 1710772536-960311778 in snapshot 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:912]: Test retrieving message 0, 1 from all folders of test_vm_1234, default context ordered by time 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:915]: Found message 1710772536-909401725 in snapshot 297s [test_voicemail_api.c:voicemail_api_nominal_snapshot:916]: Found message 1710772536-960311778 in snapshot 297s END /main/voicemail_api/ - nominal_snapshot Time: 10ms Result: PASS 297s START /main/xml_escape/ - xml_escape_test 297s END /main/xml_escape/ - xml_escape_test Time: <1ms Result: PASS 297s START /mwi/ - explicit_publish 297s END /mwi/ - explicit_publish Time: 44ms Result: PASS 297s START /mwi/ - implicit_publish 297s END /mwi/ - implicit_publish Time: 43ms Result: PASS 297s START /res/adsi/ - adsi_loaded_test 297s END /res/adsi/ - adsi_loaded_test Time: <1ms Result: PASS 297s START /res/aeap/ - send_msg_handle_request 297s END /res/aeap/ - send_msg_handle_request Time: 1ms Result: PASS 297s START /res/aeap/ - send_msg_handle_response 297s END /res/aeap/ - send_msg_handle_response Time: <1ms Result: PASS 297s START /res/aeap/ - send_msg_handle_string 299s END /res/aeap/ - send_msg_handle_string Time: 1999ms Result: PASS 299s START /res/aeap/ - create_and_connect 299s END /res/aeap/ - create_and_connect Time: <1ms Result: PASS 299s START /res/aeap/speech/ - res_speech_aeap_test 299s END /res/aeap/speech/ - res_speech_aeap_test Time: 1ms Result: PASS 299s START /res/aeap/transaction/ - transaction_exec_timeout 299s END /res/aeap/transaction/ - transaction_exec_timeout Time: 99ms Result: PASS 299s START /res/aeap/transaction/ - transaction_exec 300s END /res/aeap/transaction/ - transaction_exec Time: 1000ms Result: PASS 300s START /res/aeap/transport/ - transport_create_invalid 300s END /res/aeap/transport/ - transport_create_invalid Time: <1ms Result: PASS 300s START /res/aeap/transport/ - transport_create 300s END /res/aeap/transport/ - transport_create Time: <1ms Result: PASS 300s START /res/aeap/transport/ - transport_connect 300s END /res/aeap/transport/ - transport_connect Time: <1ms Result: PASS 300s START /res/aeap/transport/ - transport_connect_fail 300s END /res/aeap/transport/ - transport_connect_fail Time: <1ms Result: PASS 300s START /res/aeap/transport/ - transport_binary 300s END /res/aeap/transport/ - transport_binary Time: <1ms Result: PASS 300s START /res/aeap/transport/ - transport_string 300s END /res/aeap/transport/ - transport_string Time: <1ms Result: PASS 300s START /res/agi/ - agi_loaded_test 300s END /res/agi/ - agi_loaded_test Time: 1ms Result: PASS 300s START /res/agi/ - null_agi_docs 300s END /res/agi/ - null_agi_docs Time: <1ms Result: PASS 300s START /res/ari/ - invoke_not_found 300s END /res/ari/ - invoke_not_found Time: <1ms Result: PASS 300s START /res/ari/ - invoke_bad_post 300s END /res/ari/ - invoke_bad_post Time: <1ms Result: PASS 300s START /res/ari/ - invoke_post 300s END /res/ari/ - invoke_post Time: <1ms Result: PASS 300s START /res/ari/ - invoke_delete 300s END /res/ari/ - invoke_delete Time: <1ms Result: PASS 300s START /res/ari/ - invoke_wildcard 300s END /res/ari/ - invoke_wildcard Time: <1ms Result: PASS 300s START /res/ari/ - invoke_get 300s END /res/ari/ - invoke_get Time: <1ms Result: PASS 300s START /res/ari/ - get_docs_hackerz 300s END /res/ari/ - get_docs_hackerz Time: <1ms Result: PASS 300s START /res/ari/ - get_docs_notfound 300s END /res/ari/ - get_docs_notfound Time: <1ms Result: PASS 300s START /res/ari/ - get_docs_nohost 300s END /res/ari/ - get_docs_nohost Time: <1ms Result: PASS 300s START /res/ari/ - get_docs 300s END /res/ari/ - get_docs Time: <1ms Result: PASS 300s START /res/crypto/ - crypto_loaded_test 300s END /res/crypto/ - crypto_loaded_test Time: <1ms Result: PASS 300s START /res/http_media_cache/ - retrieve_content_type 300s [test_http_media_cache.c:retrieve_content_type:255]: Condition failed: bucket_file != NULL 300s END /res/http_media_cache/ - retrieve_content_type Time: <1ms Result: FAIL 300s START /res/http_media_cache/ - retrieve_parsed_uri 300s [test_http_media_cache.c:retrieve_parsed_uri:289]: Condition failed: bucket_file != NULL 300s END /res/http_media_cache/ - retrieve_parsed_uri Time: <1ms Result: FAIL 300s START /res/http_media_cache/ - retrieve_cache_control_directives 300s [test_http_media_cache.c:retrieve_cache_control_directives:322]: Testing no-cache... 300s [test_http_media_cache.c:retrieve_cache_control_directives:325]: Condition failed: bucket_file != NULL 300s END /res/http_media_cache/ - retrieve_cache_control_directives Time: <1ms Result: FAIL 300s START /res/http_media_cache/ - retrieve_cache_control_age 300s [test_http_media_cache.c:retrieve_cache_control_age:406]: Testing max-age... 300s [test_http_media_cache.c:retrieve_cache_control_age:409]: Condition failed: bucket_file != NULL 300s END /res/http_media_cache/ - retrieve_cache_control_age Time: <1ms Result: FAIL 300s START /res/http_media_cache/ - retrieve_etag_expired 300s [test_http_media_cache.c:retrieve_etag_expired:510]: Condition failed: bucket_file != NULL 300s END /res/http_media_cache/ - retrieve_etag_expired Time: <1ms Result: FAIL 300s START /res/http_media_cache/ - retrieve_expires 300s [test_http_media_cache.c:retrieve_expires:551]: Condition failed: bucket_file != NULL 300s END /res/http_media_cache/ - retrieve_expires Time: <1ms Result: FAIL 300s START /res/http_media_cache/ - retrieve_etag 300s [test_http_media_cache.c:retrieve_etag:600]: Condition failed: bucket_file != NULL 300s END /res/http_media_cache/ - retrieve_etag Time: <1ms Result: FAIL 300s START /res/http_media_cache/ - retrieve_nominal 300s [test_http_media_cache.c:retrieve_nominal:639]: Condition failed: bucket_file != NULL 300s END /res/http_media_cache/ - retrieve_nominal Time: <1ms Result: FAIL 300s START /res/http_media_cache/ - create_nominal 300s [test_http_media_cache.c:create_nominal:673]: Condition failed: ast_bucket_file_temporary_create(bucket_file) == 0 300s END /res/http_media_cache/ - create_nominal Time: <1ms Result: FAIL 300s START /res/parking/ - dynamic_parking_variables 300s [parking/parking_tests.c:dynamic_parking_variables:756]: Creating expected configuration for dynamic parking lot 300s [parking/parking_tests.c:dynamic_parking_variables:775]: Creating template lot 300s [parking/parking_tests.c:dynamic_parking_variables:784]: Creating Alice channel to test dynamic parking lot creation. 300s [parking/parking_tests.c:dynamic_parking_variables:794]: Setting Dynamic Parking channel variables on Alice. 300s [parking/parking_tests.c:dynamic_parking_variables:802]: Generating dynamic parking lot based on Alice's channel variables. 300s [parking/parking_tests.c:dynamic_parking_variables:819]: Dynamic parking lot created successfully and matches expectations. Test passed. 300s END /res/parking/ - dynamic_parking_variables Time: <1ms Result: PASS 300s START /res/parking/ - extension_conflicts 300s [parking/parking_tests.c:extension_conflicts:597]: Creating the base lot. This should pass. 300s [parking/parking_tests.c:extension_conflicts:607]: Creating a test lot which will overlap. 300s [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. 300s [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. 300s [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. 300s [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. 300s END /res/parking/ - extension_conflicts Time: <1ms Result: PASS 300s START /res/parking/ - park_extensions 300s [parking/parking_tests.c:park_extensions:551]: Extensions for the test parking lot were verified. Cleaning up and verifying their removal. 300s [parking/parking_tests.c:park_extensions:565]: Extensions for the test parking lot verified as removed. Test completed successfully. 300s END /res/parking/ - park_extensions Time: <1ms Result: PASS 300s START /res/parking/ - park_retrieve 300s [parking/parking_tests.c:retrieve_call:405]: Creating test parking lot 'unit_tests_res_parking_test_lot' 301s [parking/parking_tests.c:retrieve_call:446]: Successfully retrieved parked user from the parking lot. Validating user data. 301s END /res/parking/ - park_retrieve Time: 1008ms Result: PASS 301s START /res/parking/ - park_channel 301s [parking/parking_tests.c:park_call:254]: Creating test parking lot 'unit_tests_res_parking_test_lot' 302s END /res/parking/ - park_channel Time: 1000ms Result: PASS 302s START /res/parking/ - create_lot 302s [parking/parking_tests.c:create_lot:206]: Creating test parking lot 'unit_tests_res_parking_test_lot' 302s [parking/parking_tests.c:create_lot:214]: Successfully created parking lot. Retrieving test parking lot from container. 302s [parking/parking_tests.c:create_lot:223]: Successfully retrieved parking lot. Removing test parking lot from container. 302s [parking/parking_tests.c:create_lot:229]: Parking lot was successfully removed from the container. Test complete. 302s END /res/parking/ - create_lot Time: <1ms Result: PASS 302s START /res/prometheus/ - bridge_to_string 302s [test_res_prometheus.c:bridge_to_string:744]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 302s # TYPE asterisk_channels_count gauge 302s asterisk_channels_count{eid="fa:16:3e:ae:d1:62"} 0 302s # HELP asterisk_calls_sum Total call count. 302s # TYPE asterisk_calls_sum counter 302s asterisk_calls_sum{eid="fa:16:3e:ae:d1:62"} 0 302s # HELP asterisk_calls_count Current call count. 302s # TYPE asterisk_calls_count gauge 302s asterisk_calls_count{eid="fa:16:3e:ae:d1:62"} 0 302s # HELP asterisk_endpoints_count Current endpoint count. 302s # TYPE asterisk_endpoints_count gauge 302s asterisk_endpoints_count{eid="fa:16:3e:ae:d1:62"} 0 302s # HELP asterisk_bridges_count Current bridge count. 302s # TYPE asterisk_bridges_count gauge 302s asterisk_bridges_count{eid="fa:16:3e:ae:d1:62"} 2 302s # HELP asterisk_bridges_channels_count Number of channels in the bridge. 302s # TYPE asterisk_bridges_channels_count gauge 302s asterisk_bridges_channels_count{eid="fa:16:3e:ae:d1:62",id="f667754c-bfcf-43bb-9ab0-7566c7df0f68",tech="simple_bridge",subclass="basic",creator="",name=""} 0 302s asterisk_bridges_channels_count{eid="fa:16:3e:ae:d1:62",id="f667754c-bfcf-43bb-9ab0-7566c7df0f68",tech="simple_bridge",subclass="basic",creator="",name=""} 0 302s 302s END /res/prometheus/ - bridge_to_string Time: <1ms Result: PASS 302s START /res/prometheus/ - config_general_core_metrics 302s [test_res_prometheus.c:config_general_core_metrics:680]: -> CURLing request... 302s [test_res_prometheus.c:config_general_core_metrics:688]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 302s # TYPE asterisk_channels_count gauge 302s asterisk_channels_count{eid="fa:16:3e:ae:d1:62"} 0 302s # HELP asterisk_calls_sum Total call count. 302s # TYPE asterisk_calls_sum counter 302s asterisk_calls_sum{eid="fa:16:3e:ae:d1:62"} 0 302s # HELP asterisk_calls_count Current call count. 302s # TYPE asterisk_calls_count gauge 302s asterisk_calls_count{eid="fa:16:3e:ae:d1:62"} 0 302s # HELP asterisk_endpoints_count Current endpoint count. 302s # TYPE asterisk_endpoints_count gauge 302s asterisk_endpoints_count{eid="fa:16:3e:ae:d1:62"} 0 302s # HELP asterisk_bridges_count Current bridge count. 302s # TYPE asterisk_bridges_count gauge 302s asterisk_bridges_count{eid="fa:16:3e:ae:d1:62"} 0 302s # HELP asterisk_core_properties Asterisk instance properties. The value of this will always be 1. 302s # TYPE asterisk_core_properties counter 302s asterisk_core_properties{eid="fa:16:3e:ae:d1:62",version="20.6.0~dfsg+~cs6.13.40431414-2",build_options="OPTIONAL_API, TEST_FRAMEWORK",build_date="2024-01-30 10:42:08 UTC",build_os="Linux",build_kernel="unknown",build_host="buildd.debian.org"} 1 302s # HELP asterisk_core_uptime_seconds Asterisk instance uptime in seconds. 302s # TYPE asterisk_core_uptime_seconds counter 302s asterisk_core_uptime_seconds{eid="fa:16:3e:ae:d1:62"} 174 302s # HELP asterisk_core_last_reload_seconds Time since last Asterisk reload in seconds. 302s # TYPE asterisk_core_last_reload_seconds counter 302s asterisk_core_last_reload_seconds{eid="fa:16:3e:ae:d1:62"} 174 302s # HELP asterisk_core_scrape_time_ms Total time taken to collect metrics, in milliseconds 302s # TYPE asterisk_core_scrape_time_ms counter 302s asterisk_core_scrape_time_ms{eid="fa:16:3e:ae:d1:62"} 0 302s 302s [test_res_prometheus.c:config_general_core_metrics:690]: -> Checking for core properties 302s [test_res_prometheus.c:config_general_core_metrics:693]: -> Checking for uptime 302s [test_res_prometheus.c:config_general_core_metrics:696]: -> Checking for last reload 302s [test_res_prometheus.c:config_general_core_metrics:699]: -> Checking for scrape time 302s END /res/prometheus/ - config_general_core_metrics Time: 40ms Result: PASS 302s START /res/prometheus/ - config_general_basic_auth 302s [test_res_prometheus.c:config_general_basic_auth:555]: Testing without auth credentials 302s [test_res_prometheus.c:config_general_basic_auth:556]: -> CURLing request... 302s [test_res_prometheus.c:config_general_basic_auth:563]: -> CURL returned 401 302s [test_res_prometheus.c:config_general_basic_auth:566]: Testing with invalid auth credentials 302s [test_res_prometheus.c:config_general_basic_auth:567]: -> CURLing request... 302s [test_res_prometheus.c:config_general_basic_auth:576]: -> CURL returned 401 302s [test_res_prometheus.c:config_general_basic_auth:579]: Testing with valid auth credentials 302s [test_res_prometheus.c:config_general_basic_auth:580]: -> CURLing request... 302s [test_res_prometheus.c:config_general_basic_auth:588]: -> CURL returned 200 302s END /res/prometheus/ - config_general_basic_auth Time: <1ms Result: PASS 302s START /res/prometheus/ - config_general_enabled 302s [test_res_prometheus.c:config_general_enabled:628]: -> CURLing request... 302s [test_res_prometheus.c:config_general_enabled:635]: -> CURL returned 503 302s END /res/prometheus/ - config_general_enabled Time: <1ms Result: PASS 302s START /res/prometheus/ - gauge_create 302s END /res/prometheus/ - gauge_create Time: <1ms Result: PASS 302s START /res/prometheus/ - gauge_to_string 302s END /res/prometheus/ - gauge_to_string Time: <1ms Result: PASS 302s START /res/prometheus/ - counter_create 302s END /res/prometheus/ - counter_create Time: <1ms Result: PASS 302s START /res/prometheus/ - counter_to_string 302s END /res/prometheus/ - counter_to_string Time: <1ms Result: PASS 302s START /res/prometheus/ - metric_register 302s [test_res_prometheus.c:metric_register:291]: Testing nominal registration 302s [test_res_prometheus.c:metric_register:292]: -> Static metric 302s [test_res_prometheus.c:metric_register:294]: -> Malloc'd metric 302s [test_res_prometheus.c:metric_register:300]: Testing nominal registration of child metrics 302s [test_res_prometheus.c:metric_register:315]: Testing name collisions 302s [test_res_prometheus.c:metric_register:322]: Testing label collisions 302s [test_res_prometheus.c:metric_register:331]: Testing removal of metrics 302s END /res/prometheus/ - metric_register Time: <1ms Result: PASS 302s START /res/prometheus/ - metric_callback_register 302s [test_res_prometheus.c:metric_callback_register:241]: -> CURLing request... 302s [test_res_prometheus.c:metric_callback_register:250]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 302s # TYPE asterisk_channels_count gauge 302s asterisk_channels_count{eid="fa:16:3e:ae:d1:62"} 0 302s # HELP asterisk_calls_sum Total call count. 302s # TYPE asterisk_calls_sum counter 302s asterisk_calls_sum{eid="fa:16:3e:ae:d1:62"} 0 302s # HELP asterisk_calls_count Current call count. 302s # TYPE asterisk_calls_count gauge 302s asterisk_calls_count{eid="fa:16:3e:ae:d1:62"} 0 302s # HELP asterisk_endpoints_count Current endpoint count. 302s # TYPE asterisk_endpoints_count gauge 302s asterisk_endpoints_count{eid="fa:16:3e:ae:d1:62"} 0 302s # HELP asterisk_bridges_count Current bridge count. 302s # TYPE asterisk_bridges_count gauge 302s asterisk_bridges_count{eid="fa:16:3e:ae:d1:62"} 0 302s # HELP test_counter A test counter 302s # TYPE test_counter counter 302s test_counter 0 302s 302s END /res/prometheus/ - metric_callback_register Time: <1ms Result: PASS 302s START /res/prometheus/ - metric_values 302s [test_res_prometheus.c:metric_values:166]: -> CURLing request... 302s [test_res_prometheus.c:metric_values:176]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 302s # TYPE asterisk_channels_count gauge 302s asterisk_channels_count{eid="fa:16:3e:ae:d1:62"} 0 302s # HELP asterisk_calls_sum Total call count. 302s # TYPE asterisk_calls_sum counter 302s asterisk_calls_sum{eid="fa:16:3e:ae:d1:62"} 0 302s # HELP asterisk_calls_count Current call count. 302s # TYPE asterisk_calls_count gauge 302s asterisk_calls_count{eid="fa:16:3e:ae:d1:62"} 0 302s # HELP asterisk_endpoints_count Current endpoint count. 302s # TYPE asterisk_endpoints_count gauge 302s asterisk_endpoints_count{eid="fa:16:3e:ae:d1:62"} 0 302s # HELP asterisk_bridges_count Current bridge count. 302s # TYPE asterisk_bridges_count gauge 302s asterisk_bridges_count{eid="fa:16:3e:ae:d1:62"} 0 302s # HELP test_counter_one A test counter 302s # TYPE test_counter_one counter 302s test_counter_one 1 302s # HELP test_counter_two A test counter 302s # TYPE test_counter_two counter 302s test_counter_two 2 302s 302s END /res/prometheus/ - metric_values Time: <1ms Result: PASS 302s START /res/res_crypto/ - crypto_aes_decrypt 302s [test_crypto.c:crypto_aes_decrypt:607]: Executing AES-ECB decryption test 302s END /res/res_crypto/ - crypto_aes_decrypt Time: 26ms Result: PASS 302s START /res/res_crypto/ - crypto_aes_encrypt 302s [test_crypto.c:crypto_aes_encrypt:531]: Executing AES-ECB encryption test 302s END /res/res_crypto/ - crypto_aes_encrypt Time: 14ms Result: PASS 302s START /res/res_crypto/ - crypto_verify 302s [test_crypto.c:crypto_verify:425]: Executing RSA signature verification test 302s [test_crypto.c:crypto_verify:456]: Couldn't read key: rsa_key1 302s END /res/res_crypto/ - crypto_verify Time: <1ms Result: FAIL 302s START /res/res_crypto/ - crypto_sign 302s [test_crypto.c:crypto_sign:306]: Executing RSA signing test 302s [test_crypto.c:crypto_sign:341]: Couldn't read key: rsa_key1 302s END /res/res_crypto/ - crypto_sign Time: <1ms Result: FAIL 302s START /res/res_crypto/ - crypto_decrypt_pub_key 302s [test_crypto.c:crypto_rsa_decrypt:203]: Executing RSA decryption test 302s [test_crypto.c:crypto_rsa_decrypt:231]: Couldn't read key: rsa_key1 302s END /res/res_crypto/ - crypto_decrypt_pub_key Time: <1ms Result: FAIL 302s START /res/res_crypto/ - crypto_rsa_encrypt 302s [test_crypto.c:crypto_rsa_encrypt:107]: Executing RSA encryption test 302s [test_crypto.c:crypto_rsa_encrypt:138]: Couldn't read key: rsa_key1 302s END /res/res_crypto/ - crypto_rsa_encrypt Time: <1ms Result: FAIL 302s START /res/res_pjproject/ - ast_sockaddr_from_pj_sockaddr_test 302s END /res/res_pjproject/ - ast_sockaddr_from_pj_sockaddr_test Time: <1ms Result: PASS 302s START /res/res_pjproject/ - ast_sockaddr_to_pj_sockaddr_test 302s END /res/res_pjproject/ - ast_sockaddr_to_pj_sockaddr_test Time: <1ms Result: PASS 302s START /res/res_pjsip/ - xml_sanitization_exceeds_buffer 302s END /res/res_pjsip/ - xml_sanitization_exceeds_buffer Time: <1ms Result: PASS 302s START /res/res_pjsip/ - xml_sanitization_end_null 302s END /res/res_pjsip/ - xml_sanitization_end_null Time: <1ms Result: PASS 302s START /res/res_pjsip/scheduler/ - scheduler_policy 302s [test_res_pjsip_scheduler.c:scheduler_policy:355]: This test will take about 4.5 seconds 306s END /res/res_pjsip/scheduler/ - scheduler_policy Time: 4498ms Result: PASS 306s START /res/res_pjsip/scheduler/ - scheduler_cancel 306s [test_res_pjsip_scheduler.c:scheduler_cancel:301]: This test will take about 1.5 seconds 308s END /res/res_pjsip/scheduler/ - scheduler_cancel Time: 1500ms Result: PASS 308s START /res/res_pjsip/scheduler/ - scheduler_cleanup 308s [test_res_pjsip_scheduler.c:scheduler_cleanup:250]: This test will take about 1.6 seconds 310s END /res/res_pjsip/scheduler/ - scheduler_cleanup Time: 1600ms Result: PASS 310s START /res/res_pjsip/scheduler/ - unserialized_scheduler 310s [test_res_pjsip_scheduler.c:scheduler:136]: This test will take about 3.0 seconds 313s END /res/res_pjsip/scheduler/ - unserialized_scheduler Time: 2999ms Result: PASS 313s START /res/res_pjsip/scheduler/ - serialized_scheduler 313s [test_res_pjsip_scheduler.c:scheduler:131]: This test will take about 4.0 seconds 317s END /res/res_pjsip/scheduler/ - serialized_scheduler Time: 3999ms Result: PASS 317s START /res/res_pjsip_pubsub/ - bad_event 317s END /res/res_pjsip_pubsub/ - bad_event Time: <1ms Result: PASS 317s START /res/res_pjsip_pubsub/ - loop 317s END /res/res_pjsip_pubsub/ - loop Time: <1ms Result: PASS 317s START /res/res_pjsip_pubsub/ - duplicate_resource 317s END /res/res_pjsip_pubsub/ - duplicate_resource Time: <1ms Result: PASS 317s START /res/res_pjsip_pubsub/ - bad_branch 317s END /res/res_pjsip_pubsub/ - bad_branch Time: <1ms Result: PASS 317s START /res/res_pjsip_pubsub/ - bad_resource 317s END /res/res_pjsip_pubsub/ - bad_resource Time: <1ms Result: PASS 317s START /res/res_pjsip_pubsub/ - complex_resource_tree 317s END /res/res_pjsip_pubsub/ - complex_resource_tree Time: <1ms Result: PASS 317s START /res/res_pjsip_pubsub/ - resource_tree 317s END /res/res_pjsip_pubsub/ - resource_tree Time: <1ms Result: PASS 317s START /res/res_pjsip_session/ - merge_refresh_topologies 317s [res_pjsip_session.c:test_resolve_refresh_media_states:5894]: Test 1 passed 317s [res_pjsip_session.c:test_resolve_refresh_media_states:5914]: Test 2 passed 317s [res_pjsip_session.c:test_resolve_refresh_media_states:5938]: Test 3 passed 317s [res_pjsip_session.c:test_resolve_refresh_media_states:5957]: Test 4 passed 317s [res_pjsip_session.c:test_resolve_refresh_media_states:5975]: Test 5 passed 317s [res_pjsip_session.c:test_resolve_refresh_media_states:5996]: Test 6 passed 317s [res_pjsip_session.c:test_resolve_refresh_media_states:6022]: Test 7 passed 317s [res_pjsip_session.c:test_resolve_refresh_media_states:6043]: Test 8 passed 317s [res_pjsip_session.c:test_resolve_refresh_media_states:6063]: Test 9 passed 317s [res_pjsip_session.c:test_resolve_refresh_media_states:6083]: Test 10 passed 317s [res_pjsip_session.c:test_resolve_refresh_media_states:6106]: Test 11 passed 317s [res_pjsip_session.c:test_resolve_refresh_media_states:6131]: Test 12 passed 317s [res_pjsip_session.c:test_resolve_refresh_media_states:6165]: Test 13 passed 317s [res_pjsip_session.c:test_resolve_refresh_media_states:6189]: Test 14 passed 317s [res_pjsip_session.c:test_resolve_refresh_media_states:6213]: Test 15 passed 317s END /res/res_pjsip_session/ - merge_refresh_topologies Time: <1ms Result: PASS 317s START /res/res_pjsip_session/caps/ - low_level 317s [test_res_pjsip_session_caps.c:low_level:134]: Testing incoming expected pass 317s [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) 317s [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) 317s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (slin), remote: (all), pref: (local ), outgoing: (no ), expected: (slin) expected result: (PASS) 317s [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) 317s [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) 317s [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) 317s [test_res_pjsip_session_caps.c:low_level:142]: Testing incoming expected fail 317s [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) 317s [test_res_pjsip_session_caps.c:test_create_joint:102]: Expected Failure: Expected: () Actual: (nothing) 317s [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) 317s [test_res_pjsip_session_caps.c:test_create_joint:81]: Expected Failure: Invalid preference string incoming/outgoing combination. 317s [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) 317s [test_res_pjsip_session_caps.c:test_create_joint:81]: Expected Failure: Invalid preference string incoming/outgoing combination. 317s [test_res_pjsip_session_caps.c:low_level:147]: Testing outgoing expected pass 317s [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) 317s [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) 317s [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) 317s [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) 317s [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) 317s [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) 317s [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) 317s END /res/res_pjsip_session/caps/ - low_level Time: <1ms Result: PASS 317s START /res/res_resolver_unbound/ - resolve_srv 317s END /res/res_resolver_unbound/ - resolve_srv Time: 19ms Result: PASS 317s START /res/res_resolver_unbound/ - resolve_naptr 317s END /res/res_resolver_unbound/ - resolve_naptr Time: <1ms Result: PASS 317s START /res/res_resolver_unbound/ - resolve_cancel_off_nominal 317s END /res/res_resolver_unbound/ - resolve_cancel_off_nominal Time: 128ms Result: PASS 317s START /res/res_resolver_unbound/ - resolve_async_off_nominal 317s [res_resolver_unbound.c:off_nominal_async_run:995]: Performing DNS query 'duck.feathers', type 1 317s [res_resolver_unbound.c:off_nominal_async_run:995]: Performing DNS query 'goose.feathers', type 28 317s [res_resolver_unbound.c:off_nominal_async_run:995]: Performing DNS query 'goose.feathers', type 1 317s END /res/res_resolver_unbound/ - resolve_async_off_nominal Time: <1ms Result: PASS 317s START /res/res_resolver_unbound/ - resolve_sync_off_nominal 317s END /res/res_resolver_unbound/ - resolve_sync_off_nominal Time: <1ms Result: PASS 317s START /res/res_resolver_unbound/ - resolve_async 317s [res_resolver_unbound.c:nominal_async_run:713]: Performing DNS query 'goose.feathers', type 1 317s [res_resolver_unbound.c:nominal_async_run:713]: Performing DNS query 'goose.feathers', type 28 317s [res_resolver_unbound.c:nominal_async_run:713]: Performing DNS query 'duck.feathers', type 1 317s END /res/res_resolver_unbound/ - resolve_async Time: <1ms Result: PASS 317s START /res/res_resolver_unbound/ - resolve_sync 317s [res_resolver_unbound.c:nominal_sync_run:563]: Performing DNS query 'goose.feathers', type 1 317s [res_resolver_unbound.c:nominal_sync_run:563]: Performing DNS query 'goose.feathers', type 28 317s [res_resolver_unbound.c:nominal_sync_run:563]: Performing DNS query 'duck.feathers', type 1 317s END /res/res_resolver_unbound/ - resolve_sync Time: <1ms Result: PASS 317s START /res/res_rtp/ - fir_nominal 317s END /res/res_rtp/ - fir_nominal Time: 1ms Result: PASS 317s START /res/res_rtp/ - sr_rr_nominal 317s END /res/res_rtp/ - sr_rr_nominal Time: 1ms Result: PASS 317s START /res/res_rtp/ - remb_nominal 317s END /res/res_rtp/ - remb_nominal Time: 1ms Result: PASS 317s START /res/res_rtp/ - lost_packet_stats_nominal 317s END /res/res_rtp/ - lost_packet_stats_nominal Time: <1ms Result: PASS 317s START /res/res_rtp/ - nack_overflow 317s END /res/res_rtp/ - nack_overflow Time: 1ms Result: PASS 317s START /res/res_rtp/ - nack_nominal 317s END /res/res_rtp/ - nack_nominal Time: 1ms Result: PASS 317s START /res/res_rtp/ - nack_no_packet_loss 317s END /res/res_rtp/ - nack_no_packet_loss Time: 1ms Result: PASS 317s START /res/res_sorcery_memory_cache/ - full_backend_cache_stale 332s END /res/res_sorcery_memory_cache/ - full_backend_cache_stale Time: 15010ms Result: PASS 332s START /res/res_sorcery_memory_cache/ - full_backend_cache_expiration 337s END /res/res_sorcery_memory_cache/ - full_backend_cache_expiration Time: 5000ms Result: PASS 337s START /res/res_sorcery_memory_cache/ - expiration 342s END /res/res_sorcery_memory_cache/ - expiration Time: 4999ms Result: PASS 342s START /res/res_sorcery_memory_cache/ - maximum_objects 342s END /res/res_sorcery_memory_cache/ - maximum_objects Time: 4ms Result: PASS 342s START /res/res_sorcery_memory_cache/ - delete 342s END /res/res_sorcery_memory_cache/ - delete Time: <1ms Result: PASS 342s START /res/res_sorcery_memory_cache/ - create 342s END /res/res_sorcery_memory_cache/ - create Time: <1ms Result: PASS 342s START /res/res_sorcery_memory_cache/ - create 342s END /res/res_sorcery_memory_cache/ - create Time: <1ms Result: PASS 342s START /res/res_sorcery_memory_cache/ - open_with_invalid_options 342s END /res/res_sorcery_memory_cache/ - open_with_invalid_options Time: <1ms Result: PASS 342s START /res/res_sorcery_memory_cache/ - open_with_valid_options 342s END /res/res_sorcery_memory_cache/ - open_with_valid_options Time: <1ms Result: PASS 342s START /res/res_sorcery_memory_cache/ - stale 342s [res_sorcery_memory_cache.c:stale:3189]: Begininning iteration 0 347s [res_sorcery_memory_cache.c:stale:3189]: Begininning iteration 1 352s [res_sorcery_memory_cache.c:stale:3189]: Begininning iteration 2 357s END /res/res_sorcery_memory_cache/ - stale Time: 15000ms Result: PASS 357s START /res/res_sorcery_memory_cache/thrash/ - high_object_count_without_expiration 360s END /res/res_sorcery_memory_cache/thrash/ - high_object_count_without_expiration Time: 3038ms Result: PASS 360s START /res/res_sorcery_memory_cache/thrash/ - conflicting_expire_and_stale 366s END /res/res_sorcery_memory_cache/thrash/ - conflicting_expire_and_stale Time: 6033ms Result: PASS 366s START /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum_with_expire_and_stale 372s END /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum_with_expire_and_stale Time: 6003ms Result: PASS 372s START /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum 375s END /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum Time: 3016ms Result: PASS 375s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_high_concurrent_updates 378s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_high_concurrent_updates Time: 3004ms Result: PASS 378s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_expire 381s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_expire Time: 3011ms Result: PASS 381s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_stale 384s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_stale Time: 3031ms Result: PASS 384s START /res/res_stir_shaken/ - stir_shaken_verify 384s END /res/res_stir_shaken/ - stir_shaken_verify Time: 2ms Result: PASS 384s START /res/res_stir_shaken/ - stir_shaken_sign 384s END /res/res_stir_shaken/ - stir_shaken_sign Time: 1ms Result: PASS 384s START /res/sorcery_astdb/ - object_delete_uncreated 384s END /res/sorcery_astdb/ - object_delete_uncreated Time: 4ms Result: PASS 384s START /res/sorcery_astdb/ - object_delete 384s END /res/sorcery_astdb/ - object_delete Time: <1ms Result: PASS 384s START /res/sorcery_astdb/ - object_update_uncreated 384s END /res/sorcery_astdb/ - object_update_uncreated Time: <1ms Result: PASS 384s START /res/sorcery_astdb/ - object_update 384s END /res/sorcery_astdb/ - object_update Time: <1ms Result: PASS 384s START /res/sorcery_astdb/ - object_retrieve_regex 384s END /res/sorcery_astdb/ - object_retrieve_regex Time: <1ms Result: PASS 384s START /res/sorcery_astdb/ - object_retrieve_multiple_field 384s END /res/sorcery_astdb/ - object_retrieve_multiple_field Time: <1ms Result: PASS 384s START /res/sorcery_astdb/ - object_retrieve_multiple_all 384s END /res/sorcery_astdb/ - object_retrieve_multiple_all Time: <1ms Result: PASS 384s START /res/sorcery_astdb/ - object_retrieve_field 384s END /res/sorcery_astdb/ - object_retrieve_field Time: <1ms Result: PASS 384s START /res/sorcery_astdb/ - object_retrieve_id 384s END /res/sorcery_astdb/ - object_retrieve_id Time: <1ms Result: PASS 384s START /res/sorcery_astdb/ - object_create 384s END /res/sorcery_astdb/ - object_create Time: <1ms Result: PASS 384s START /res/sorcery_realtime/ - object_filter 384s END /res/sorcery_realtime/ - object_filter Time: <1ms Result: PASS 384s START /res/sorcery_realtime/ - object_allocate_on_retrieval 384s END /res/sorcery_realtime/ - object_allocate_on_retrieval Time: <1ms Result: PASS 384s START /res/sorcery_realtime/ - object_delete_uncreated 384s END /res/sorcery_realtime/ - object_delete_uncreated Time: <1ms Result: PASS 384s START /res/sorcery_realtime/ - object_delete 384s END /res/sorcery_realtime/ - object_delete Time: <1ms Result: PASS 384s START /res/sorcery_realtime/ - object_update 384s END /res/sorcery_realtime/ - object_update Time: <1ms Result: PASS 384s START /res/sorcery_realtime/ - object_retrieve_regex_nofetch 384s END /res/sorcery_realtime/ - object_retrieve_regex_nofetch Time: <1ms Result: PASS 384s START /res/sorcery_realtime/ - object_retrieve_regex 384s END /res/sorcery_realtime/ - object_retrieve_regex Time: <1ms Result: PASS 384s START /res/sorcery_realtime/ - object_retrieve_multiple_field 384s END /res/sorcery_realtime/ - object_retrieve_multiple_field Time: <1ms Result: PASS 384s START /res/sorcery_realtime/ - object_retrieve_multiple_all_nofetch 384s END /res/sorcery_realtime/ - object_retrieve_multiple_all_nofetch Time: <1ms Result: PASS 384s START /res/sorcery_realtime/ - object_retrieve_multiple_all 384s END /res/sorcery_realtime/ - object_retrieve_multiple_all Time: <1ms Result: PASS 384s START /res/sorcery_realtime/ - object_retrieve_field 384s END /res/sorcery_realtime/ - object_retrieve_field Time: <1ms Result: PASS 384s START /res/sorcery_realtime/ - object_retrieve_id 384s END /res/sorcery_realtime/ - object_retrieve_id Time: <1ms Result: PASS 384s START /res/sorcery_realtime/ - object_create 384s END /res/sorcery_realtime/ - object_create Time: <1ms Result: PASS 384s START /res/websocket/ - websocket_client_multiple_protocols 384s END /res/websocket/ - websocket_client_multiple_protocols Time: 46ms Result: PASS 384s START /res/websocket/ - websocket_client_unsupported_protocol 384s END /res/websocket/ - websocket_client_unsupported_protocol Time: <1ms Result: PASS 384s START /res/websocket/ - websocket_client_bad_url 384s END /res/websocket/ - websocket_client_bad_url Time: <1ms Result: PASS 384s START /stasis/channels/ - channel_redirect_snapshot_json 384s END /stasis/channels/ - channel_redirect_snapshot_json Time: <1ms Result: PASS 384s START /stasis/channels/ - channel_snapshot_json 384s END /stasis/channels/ - channel_snapshot_json Time: <1ms Result: PASS 384s START /stasis/channels/ - multi_channel_blob_snapshots 384s END /stasis/channels/ - multi_channel_blob_snapshots Time: <1ms Result: PASS 384s START /stasis/channels/ - multi_channel_blob_create 384s END /stasis/channels/ - multi_channel_blob_create Time: <1ms Result: PASS 384s START /stasis/channels/ - null_blob 384s END /stasis/channels/ - null_blob Time: <1ms Result: PASS 384s START /stasis/channels/ - channel_blob_create 384s END /stasis/channels/ - channel_blob_create Time: <1ms Result: PASS 384s START /stasis/core/ - caching_dtor_order 384s END /stasis/core/ - caching_dtor_order Time: <1ms Result: PASS 384s START /stasis/core/ - dtor_order 384s END /stasis/core/ - dtor_order Time: <1ms Result: PASS 384s START /stasis/core/ - to_ami 384s END /stasis/core/ - to_ami Time: <1ms Result: PASS 384s START /stasis/core/ - no_to_ami 384s END /stasis/core/ - no_to_ami Time: <1ms Result: PASS 384s START /stasis/core/ - to_json 384s END /stasis/core/ - to_json Time: <1ms Result: PASS 384s START /stasis/core/ - no_to_json 384s END /stasis/core/ - no_to_json Time: <1ms Result: PASS 384s START /stasis/core/ - subscription_interleaving 384s END /stasis/core/ - subscription_interleaving Time: <1ms Result: PASS 384s START /stasis/core/ - interleaving 384s END /stasis/core/ - interleaving Time: <1ms Result: PASS 384s START /stasis/core/ - router_cache_updates 384s END /stasis/core/ - router_cache_updates Time: 100ms Result: PASS 384s START /stasis/core/ - router_pool 384s END /stasis/core/ - router_pool Time: <1ms Result: PASS 384s START /stasis/core/ - router 384s END /stasis/core/ - router Time: <1ms Result: PASS 384s START /stasis/core/ - cache_eid_aggregate 384s END /stasis/core/ - cache_eid_aggregate Time: <1ms Result: PASS 384s START /stasis/core/ - cache_dump 384s END /stasis/core/ - cache_dump Time: <1ms Result: PASS 384s START /stasis/core/ - cache 384s END /stasis/core/ - cache Time: <1ms Result: PASS 384s START /stasis/core/ - cache_filter 384s END /stasis/core/ - cache_filter Time: 100ms Result: PASS 384s START /stasis/core/ - forward 384s END /stasis/core/ - forward Time: <1ms Result: PASS 384s START /stasis/core/ - unsubscribe_stops_messages 384s END /stasis/core/ - unsubscribe_stops_messages Time: 100ms Result: PASS 384s START /stasis/core/ - publish_pool 384s END /stasis/core/ - publish_pool Time: <1ms Result: PASS 384s START /stasis/core/ - publish_sync 384s END /stasis/core/ - publish_sync Time: <1ms Result: PASS 384s START /stasis/core/ - publish 384s END /stasis/core/ - publish Time: <1ms Result: PASS 384s START /stasis/core/ - subscription_pool_messages 384s END /stasis/core/ - subscription_pool_messages Time: <1ms Result: PASS 384s START /stasis/core/ - subscription_messages 384s END /stasis/core/ - subscription_messages Time: <1ms Result: PASS 384s START /stasis/core/ - message 384s END /stasis/core/ - message Time: <1ms Result: PASS 384s START /stasis/core/ - message_type 384s END /stasis/core/ - message_type Time: <1ms Result: PASS 384s START /stasis/core/filtering/ - combo_filters 384s [test_stasis.c:dump_consumer:2198]: Messages received: 7 Final? yes 384s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 384s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType1 Pass 384s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass 384s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMI Pass 384s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass 384s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageJSON Pass 384s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 384s END /stasis/core/filtering/ - combo_filters Time: <1ms Result: PASS 384s START /stasis/core/filtering/ - formatter_filters 384s [test_stasis.c:dump_consumer:2198]: Messages received: 7 Final? yes 384s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 384s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMI Pass 384s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageJSON Pass 384s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass 384s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass2 384s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageEVENT Pass 384s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 384s END /stasis/core/filtering/ - formatter_filters Time: <1ms Result: PASS 384s START /stasis/core/filtering/ - type_filters 384s [test_stasis.c:dump_consumer:2198]: Messages received: 5 Final? yes 384s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 384s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType1 Pass 384s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass 384s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass2 384s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 384s END /stasis/core/filtering/ - type_filters Time: <1ms Result: PASS 384s START /stasis/core/state/ - explicit_publish 384s END /stasis/core/state/ - explicit_publish Time: 31ms Result: PASS 384s START /stasis/core/state/ - implicit_publish 384s END /stasis/core/state/ - implicit_publish Time: 24ms Result: PASS 384s START /stasis/endpoints/ - channel_messages 384s END /stasis/endpoints/ - channel_messages Time: <1ms Result: PASS 384s START /stasis/endpoints/ - cache_clear 384s END /stasis/endpoints/ - cache_clear Time: <1ms Result: PASS 384s START /stasis/endpoints/ - state_changes 384s END /stasis/endpoints/ - state_changes Time: <1ms Result: PASS 384s START /stasis/res/ - app_invoke_dne 384s END /stasis/res/ - app_invoke_dne Time: <1ms Result: PASS 384s START /stasis/res/ - app_invoke_one 384s END /stasis/res/ - app_invoke_one Time: <1ms Result: PASS 384s START /stasis/res/ - app_replaced 384s END /stasis/res/ - app_replaced Time: <1ms Result: PASS 384s 384s 658 Test(s) Executed 633 Passed 25 Failed 384s 'U' option is not compatible with remote console mode and has no effect. 384s 384s Results Generated Successfully: /tmp/autopkgtest.5BJMcc/build.SlA/src/debian/tests/testmods/output/results.txt 384s 'U' option is not compatible with remote console mode and has no effect. 384s 384s Some test modules were not loaded: 384s 20a21 384s > test_cel.so 384s 53a55 384s > test_message.so 384s Manually disabled: 384s test_message 384s test_cel 384s 384s 'U' option is not compatible with remote console mode and has no effect. 384s 386s autopkgtest [14:37:05]: test asttestmods: -----------------------] 387s autopkgtest [14:37:06]: test asttestmods: - - - - - - - - - - results - - - - - - - - - - 387s asttestmods PASS 387s autopkgtest [14:37:06]: test amr: preparing testbed 621s autopkgtest [14:41:00]: @@@@@@@@@@@@@@@@@@@@ test bed setup 622s Get:1 http://ftpmaster.internal/ubuntu noble-proposed InRelease [117 kB] 622s Get:2 http://ftpmaster.internal/ubuntu noble-proposed/restricted Sources [6540 B] 622s Get:3 http://ftpmaster.internal/ubuntu noble-proposed/multiverse Sources [52.0 kB] 622s Get:4 http://ftpmaster.internal/ubuntu noble-proposed/main Sources [485 kB] 622s Get:5 http://ftpmaster.internal/ubuntu noble-proposed/universe Sources [3728 kB] 624s Get:6 http://ftpmaster.internal/ubuntu noble-proposed/main arm64 Packages [654 kB] 624s Get:7 http://ftpmaster.internal/ubuntu noble-proposed/main arm64 c-n-f Metadata [3144 B] 624s Get:8 http://ftpmaster.internal/ubuntu noble-proposed/restricted arm64 Packages [33.6 kB] 624s Get:9 http://ftpmaster.internal/ubuntu noble-proposed/restricted arm64 c-n-f Metadata [116 B] 624s Get:10 http://ftpmaster.internal/ubuntu noble-proposed/universe arm64 Packages [4103 kB] 624s Get:11 http://ftpmaster.internal/ubuntu noble-proposed/universe arm64 c-n-f Metadata [8528 B] 624s Get:12 http://ftpmaster.internal/ubuntu noble-proposed/multiverse arm64 Packages [55.5 kB] 624s Get:13 http://ftpmaster.internal/ubuntu noble-proposed/multiverse arm64 c-n-f Metadata [116 B] 625s Fetched 9246 kB in 3s (3254 kB/s) 626s Reading package lists... 628s Reading package lists... 628s Building dependency tree... 628s Reading state information... 629s Calculating upgrade... 629s The following packages will be REMOVED: 629s libssl3 629s The following NEW packages will be installed: 629s libssl3t64 629s The following packages will be upgraded: 629s openssl 629s 1 upgraded, 1 newly installed, 1 to remove and 0 not upgraded. 629s Need to get 2777 kB of archives. 629s After this operation, 139 kB of additional disk space will be used. 629s Get:1 http://ftpmaster.internal/ubuntu noble-proposed/main arm64 openssl arm64 3.0.13-0ubuntu2 [985 kB] 629s Get:2 http://ftpmaster.internal/ubuntu noble-proposed/main arm64 libssl3t64 arm64 3.0.13-0ubuntu2 [1793 kB] 630s Fetched 2777 kB in 1s (4181 kB/s) 630s (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 ... 74758 files and directories currently installed.) 630s Preparing to unpack .../openssl_3.0.13-0ubuntu2_arm64.deb ... 630s Unpacking openssl (3.0.13-0ubuntu2) over (3.0.10-1ubuntu4) ... 631s dpkg: libssl3:arm64: dependency problems, but removing anyway as you requested: 631s wget depends on libssl3 (>= 3.0.0). 631s u-boot-tools depends on libssl3 (>= 3.0.0). 631s tnftp depends on libssl3 (>= 3.0.0). 631s tcpdump depends on libssl3 (>= 3.0.0). 631s systemd-resolved depends on libssl3 (>= 3.0.0). 631s systemd depends on libssl3 (>= 3.0.0). 631s sudo depends on libssl3 (>= 3.0.0). 631s sbsigntool depends on libssl3 (>= 3.0.0). 631s rsync depends on libssl3 (>= 3.0.0). 631s python3-cryptography depends on libssl3 (>= 3.0.0). 631s openssh-server depends on libssl3 (>= 3.0.10). 631s openssh-client depends on libssl3 (>= 3.0.10). 631s mtd-utils depends on libssl3 (>= 3.0.0). 631s mokutil depends on libssl3 (>= 3.0.0). 631s linux-headers-6.8.0-11-generic depends on libssl3 (>= 3.0.0). 631s libsystemd-shared:arm64 depends on libssl3 (>= 3.0.0). 631s libssh-4:arm64 depends on libssl3 (>= 3.0.0). 631s libsasl2-modules:arm64 depends on libssl3 (>= 3.0.0). 631s libsasl2-2:arm64 depends on libssl3 (>= 3.0.0). 631s libpython3.12-minimal:arm64 depends on libssl3 (>= 3.0.0). 631s libnvme1 depends on libssl3 (>= 3.0.0). 631s libkrb5-3:arm64 depends on libssl3 (>= 3.0.0). 631s libkmod2:arm64 depends on libssl3 (>= 3.0.0). 631s libfido2-1:arm64 depends on libssl3 (>= 3.0.0). 631s libcurl4:arm64 depends on libssl3 (>= 3.0.0). 631s libcryptsetup12:arm64 depends on libssl3 (>= 3.0.0). 631s kmod depends on libssl3 (>= 3.0.0). 631s dhcpcd-base depends on libssl3 (>= 3.0.0). 631s bind9-libs:arm64 depends on libssl3 (>= 3.0.0). 631s 631s (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 ... 74758 files and directories currently installed.) 631s Removing libssl3:arm64 (3.0.10-1ubuntu4) ... 631s Selecting previously unselected package libssl3t64:arm64. 631s (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 ... 74747 files and directories currently installed.) 631s Preparing to unpack .../libssl3t64_3.0.13-0ubuntu2_arm64.deb ... 631s Unpacking libssl3t64:arm64 (3.0.13-0ubuntu2) ... 631s Setting up libssl3t64:arm64 (3.0.13-0ubuntu2) ... 631s Setting up openssl (3.0.13-0ubuntu2) ... 631s Processing triggers for man-db (2.12.0-3) ... 631s Processing triggers for libc-bin (2.39-0ubuntu2) ... 632s Reading package lists... 632s Building dependency tree... 632s Reading state information... 633s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 633s Hit:1 http://ftpmaster.internal/ubuntu noble InRelease 633s Hit:2 http://ftpmaster.internal/ubuntu noble-updates InRelease 633s Hit:3 http://ftpmaster.internal/ubuntu noble-security InRelease 633s Hit:4 http://ftpmaster.internal/ubuntu noble-proposed InRelease 635s Reading package lists... 635s Reading package lists... 635s Building dependency tree... 635s Reading state information... 635s Calculating upgrade... 636s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 636s Reading package lists... 636s Building dependency tree... 636s Reading state information... 637s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 637s autopkgtest [14:41:16]: testbed dpkg architecture: arm64 640s Reading package lists... 641s Building dependency tree... 641s Reading state information... 641s Correcting dependencies...Starting pkgProblemResolver with broken count: 0 641s Starting 2 pkgProblemResolver with broken count: 0 641s Done 642s Done 642s Starting pkgProblemResolver with broken count: 0 642s Starting 2 pkgProblemResolver with broken count: 0 642s Done 643s The following additional packages will be installed: 643s asterisk asterisk-config asterisk-core-sounds-en asterisk-core-sounds-en-gsm 643s asterisk-modules freetds-common libasound2 libasound2-data libc-client2007e 643s libcodec2-1.2 libdeflate0 libevent-2.1-7 libgmime-3.0-0 libgsm1 libical3 643s libiksemel3 libjack-jackd2-0 libjbig0 libjpeg-turbo8 libjpeg8 liblerc4 643s libltdl7 liblua5.1-0 libneon27 libodbc2 libogg0 libopencore-amrnb0 643s libopencore-amrwb0 libopus0 libopusenc0 libopusfile0 libportaudio2 libpq5 643s libradcli4 libresample1 libsamplerate0 libsharpyuv0 libsnmp-base libsnmp40 643s libspandsp2 libspeex1 libspeexdsp1 libsrtp2-1 libsybdb5 libtiff6 libunbound8 643s liburiparser1 libvo-amrwbenc0 libvorbis0a libvorbisenc2 libvorbisfile3 643s libwebp7 libxslt1.1 mlock 643s Suggested packages: 643s asterisk-dahdi asterisk-dev asterisk-doc asterisk-ooh323 asterisk-opus 643s libasound2-plugins alsa-utils uw-mailutils jackd2 odbc-postgresql tdsodbc 643s opus-tools snmp-mibs-downloader speex 643s Recommended packages: 643s asterisk-moh-opsound-gsm sox alsa-ucm-conf alsa-topology-conf 643s The following NEW packages will be installed: 643s asterisk asterisk-config asterisk-core-sounds-en asterisk-core-sounds-en-gsm 643s asterisk-modules freetds-common libasound2 libasound2-data libc-client2007e 643s libcodec2-1.2 libdeflate0 libevent-2.1-7 libgmime-3.0-0 libgsm1 libical3 643s libiksemel3 libjack-jackd2-0 libjbig0 libjpeg-turbo8 libjpeg8 liblerc4 643s libltdl7 liblua5.1-0 libneon27 libodbc2 libogg0 libopencore-amrnb0 643s libopencore-amrwb0 libopus0 libopusenc0 libopusfile0 libportaudio2 libpq5 643s libradcli4 libresample1 libsamplerate0 libsharpyuv0 libsnmp-base libsnmp40 643s libspandsp2 libspeex1 libspeexdsp1 libsrtp2-1 libsybdb5 libtiff6 libunbound8 643s liburiparser1 libvo-amrwbenc0 libvorbis0a libvorbisenc2 libvorbisfile3 643s libwebp7 libxslt1.1 mlock 643s 0 upgraded, 54 newly installed, 0 to remove and 0 not upgraded. 643s 1 not fully installed or removed. 643s Need to get 25.5 MB of archives. 643s After this operation, 83.0 MB of additional disk space will be used. 643s Get:1 http://ftpmaster.internal/ubuntu noble/universe arm64 asterisk-config all 1:20.6.0~dfsg+~cs6.13.40431414-2 [242 kB] 643s Get:2 http://ftpmaster.internal/ubuntu noble/universe arm64 asterisk-core-sounds-en-gsm all 1.6.1-1 [2417 kB] 643s Get:3 http://ftpmaster.internal/ubuntu noble/universe arm64 asterisk-core-sounds-en all 1.6.1-1 [20.6 kB] 643s Get:4 http://ftpmaster.internal/ubuntu noble/universe arm64 mlock arm64 8:2007f~dfsg-7build1 [11.8 kB] 643s Get:5 http://ftpmaster.internal/ubuntu noble/universe arm64 libc-client2007e arm64 8:2007f~dfsg-7build1 [648 kB] 643s Get:6 http://ftpmaster.internal/ubuntu noble/universe arm64 libcodec2-1.2 arm64 1.2.0-2 [8995 kB] 643s Get:7 http://ftpmaster.internal/ubuntu noble/universe arm64 libgmime-3.0-0 arm64 3.2.13+dfsg-2 [168 kB] 643s Get:8 http://ftpmaster.internal/ubuntu noble/universe arm64 libgsm1 arm64 1.0.22-1 [26.3 kB] 643s Get:9 http://ftpmaster.internal/ubuntu noble/main arm64 libical3 arm64 3.0.17-1build1 [299 kB] 644s Get:10 http://ftpmaster.internal/ubuntu noble/universe arm64 libiksemel3 arm64 1.4-4 [28.3 kB] 644s Get:11 http://ftpmaster.internal/ubuntu noble/main arm64 libopus0 arm64 1.4-1 [194 kB] 644s Get:12 http://ftpmaster.internal/ubuntu noble/main arm64 libsamplerate0 arm64 0.2.2-4 [1342 kB] 644s Get:13 http://ftpmaster.internal/ubuntu noble/main arm64 libjack-jackd2-0 arm64 1.9.21~dfsg-3 [281 kB] 644s Get:14 http://ftpmaster.internal/ubuntu noble/universe arm64 liblua5.1-0 arm64 5.1.5-9 [115 kB] 644s Get:15 http://ftpmaster.internal/ubuntu noble/universe arm64 libneon27 arm64 0.33.0-1 [101 kB] 644s Get:16 http://ftpmaster.internal/ubuntu noble/main arm64 libltdl7 arm64 2.4.7-7 [40.3 kB] 644s Get:17 http://ftpmaster.internal/ubuntu noble/main arm64 libodbc2 arm64 2.3.12-1 [144 kB] 644s Get:18 http://ftpmaster.internal/ubuntu noble/main arm64 libogg0 arm64 1.3.5-3 [22.1 kB] 644s Get:19 http://ftpmaster.internal/ubuntu noble/universe arm64 libopencore-amrnb0 arm64 0.1.6-1 [96.2 kB] 644s Get:20 http://ftpmaster.internal/ubuntu noble/universe arm64 libopencore-amrwb0 arm64 0.1.6-1 [49.5 kB] 644s Get:21 http://ftpmaster.internal/ubuntu noble/universe arm64 libopusenc0 arm64 0.2.1-2 [24.9 kB] 644s Get:22 http://ftpmaster.internal/ubuntu noble/universe arm64 libopusfile0 arm64 0.12-4 [44.5 kB] 644s Get:23 http://ftpmaster.internal/ubuntu noble/main arm64 libasound2-data all 1.2.10-3build1 [20.7 kB] 644s Get:24 http://ftpmaster.internal/ubuntu noble/main arm64 libasound2 arm64 1.2.10-3build1 [386 kB] 644s Get:25 http://ftpmaster.internal/ubuntu noble/universe arm64 libportaudio2 arm64 19.6.0-1.2 [65.8 kB] 644s Get:26 http://ftpmaster.internal/ubuntu noble/main arm64 libpq5 arm64 16.2-1 [136 kB] 644s Get:27 http://ftpmaster.internal/ubuntu noble/universe arm64 libradcli4 arm64 1.2.11-1build1 [37.6 kB] 644s Get:28 http://ftpmaster.internal/ubuntu noble/universe arm64 libresample1 arm64 0.1.3-6 [8522 B] 644s Get:29 http://ftpmaster.internal/ubuntu noble/main arm64 libsnmp-base all 5.9.4+dfsg-1ubuntu2 [206 kB] 644s Get:30 http://ftpmaster.internal/ubuntu noble/main arm64 libsnmp40 arm64 5.9.4+dfsg-1ubuntu2 [1055 kB] 644s Get:31 http://ftpmaster.internal/ubuntu noble/main arm64 libdeflate0 arm64 1.19-1 [43.4 kB] 644s Get:32 http://ftpmaster.internal/ubuntu noble/main arm64 libjbig0 arm64 2.1-6.1ubuntu1 [28.9 kB] 644s Get:33 http://ftpmaster.internal/ubuntu noble/main arm64 libjpeg-turbo8 arm64 2.1.5-2ubuntu1 [160 kB] 644s Get:34 http://ftpmaster.internal/ubuntu noble/main arm64 libjpeg8 arm64 8c-2ubuntu11 [2148 B] 644s Get:35 http://ftpmaster.internal/ubuntu noble/main arm64 liblerc4 arm64 4.0.0+ds-4ubuntu1 [153 kB] 644s Get:36 http://ftpmaster.internal/ubuntu noble/main arm64 libsharpyuv0 arm64 1.3.2-0.4 [14.4 kB] 644s Get:37 http://ftpmaster.internal/ubuntu noble/main arm64 libwebp7 arm64 1.3.2-0.4 [191 kB] 644s Get:38 http://ftpmaster.internal/ubuntu noble/main arm64 libtiff6 arm64 4.5.1+git230720-3ubuntu1 [226 kB] 644s Get:39 http://ftpmaster.internal/ubuntu noble/universe arm64 libspandsp2 arm64 0.0.6+dfsg-2build1 [308 kB] 644s Get:40 http://ftpmaster.internal/ubuntu noble/main arm64 libspeex1 arm64 1.2.1-2ubuntu1 [55.1 kB] 644s Get:41 http://ftpmaster.internal/ubuntu noble/main arm64 libspeexdsp1 arm64 1.2.1-1ubuntu2 [40.1 kB] 644s Get:42 http://ftpmaster.internal/ubuntu noble/universe arm64 libsrtp2-1 arm64 2.5.0-3 [41.5 kB] 644s Get:43 http://ftpmaster.internal/ubuntu noble/main arm64 freetds-common all 1.3.17+ds-2 [26.8 kB] 644s Get:44 http://ftpmaster.internal/ubuntu noble/main arm64 libsybdb5 arm64 1.3.17+ds-2 [184 kB] 644s Get:45 http://ftpmaster.internal/ubuntu noble/main arm64 libevent-2.1-7 arm64 2.1.12-stable-9 [138 kB] 644s Get:46 http://ftpmaster.internal/ubuntu noble/main arm64 libunbound8 arm64 1.19.1-1ubuntu1 [423 kB] 644s Get:47 http://ftpmaster.internal/ubuntu noble/universe arm64 libvo-amrwbenc0 arm64 0.1.3-2 [65.9 kB] 644s Get:48 http://ftpmaster.internal/ubuntu noble/main arm64 libvorbis0a arm64 1.3.7-1build2 [95.5 kB] 644s Get:49 http://ftpmaster.internal/ubuntu noble/main arm64 libvorbisenc2 arm64 1.3.7-1build2 [82.3 kB] 644s Get:50 http://ftpmaster.internal/ubuntu noble/main arm64 libvorbisfile3 arm64 1.3.7-1build2 [16.8 kB] 644s Get:51 http://ftpmaster.internal/ubuntu noble/universe arm64 asterisk-modules arm64 1:20.6.0~dfsg+~cs6.13.40431414-2 [3216 kB] 644s Get:52 http://ftpmaster.internal/ubuntu noble/universe arm64 liburiparser1 arm64 0.9.7+dfsg-2 [34.0 kB] 644s Get:53 http://ftpmaster.internal/ubuntu noble/main arm64 libxslt1.1 arm64 1.1.35-1 [161 kB] 644s Get:54 http://ftpmaster.internal/ubuntu noble/universe arm64 asterisk arm64 1:20.6.0~dfsg+~cs6.13.40431414-2 [2585 kB] 645s Fetched 25.5 MB in 1s (17.1 MB/s) 645s Selecting previously unselected package asterisk-config. 645s (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 ... 74760 files and directories currently installed.) 645s Preparing to unpack .../00-asterisk-config_1%3a20.6.0~dfsg+~cs6.13.40431414-2_all.deb ... 645s Unpacking asterisk-config (1:20.6.0~dfsg+~cs6.13.40431414-2) ... 645s Selecting previously unselected package asterisk-core-sounds-en-gsm. 645s Preparing to unpack .../01-asterisk-core-sounds-en-gsm_1.6.1-1_all.deb ... 645s Unpacking asterisk-core-sounds-en-gsm (1.6.1-1) ... 645s Selecting previously unselected package asterisk-core-sounds-en. 645s Preparing to unpack .../02-asterisk-core-sounds-en_1.6.1-1_all.deb ... 645s Unpacking asterisk-core-sounds-en (1.6.1-1) ... 645s Selecting previously unselected package mlock. 645s Preparing to unpack .../03-mlock_8%3a2007f~dfsg-7build1_arm64.deb ... 645s Unpacking mlock (8:2007f~dfsg-7build1) ... 645s Selecting previously unselected package libc-client2007e. 645s Preparing to unpack .../04-libc-client2007e_8%3a2007f~dfsg-7build1_arm64.deb ... 645s Unpacking libc-client2007e (8:2007f~dfsg-7build1) ... 645s Selecting previously unselected package libcodec2-1.2:arm64. 645s Preparing to unpack .../05-libcodec2-1.2_1.2.0-2_arm64.deb ... 645s Unpacking libcodec2-1.2:arm64 (1.2.0-2) ... 645s Selecting previously unselected package libgmime-3.0-0:arm64. 645s Preparing to unpack .../06-libgmime-3.0-0_3.2.13+dfsg-2_arm64.deb ... 645s Unpacking libgmime-3.0-0:arm64 (3.2.13+dfsg-2) ... 645s Selecting previously unselected package libgsm1:arm64. 645s Preparing to unpack .../07-libgsm1_1.0.22-1_arm64.deb ... 645s Unpacking libgsm1:arm64 (1.0.22-1) ... 645s Selecting previously unselected package libical3:arm64. 645s Preparing to unpack .../08-libical3_3.0.17-1build1_arm64.deb ... 645s Unpacking libical3:arm64 (3.0.17-1build1) ... 646s Selecting previously unselected package libiksemel3:arm64. 646s Preparing to unpack .../09-libiksemel3_1.4-4_arm64.deb ... 646s Unpacking libiksemel3:arm64 (1.4-4) ... 646s Selecting previously unselected package libopus0:arm64. 646s Preparing to unpack .../10-libopus0_1.4-1_arm64.deb ... 646s Unpacking libopus0:arm64 (1.4-1) ... 646s Selecting previously unselected package libsamplerate0:arm64. 646s Preparing to unpack .../11-libsamplerate0_0.2.2-4_arm64.deb ... 646s Unpacking libsamplerate0:arm64 (0.2.2-4) ... 646s Selecting previously unselected package libjack-jackd2-0:arm64. 646s Preparing to unpack .../12-libjack-jackd2-0_1.9.21~dfsg-3_arm64.deb ... 646s Unpacking libjack-jackd2-0:arm64 (1.9.21~dfsg-3) ... 646s Selecting previously unselected package liblua5.1-0:arm64. 646s Preparing to unpack .../13-liblua5.1-0_5.1.5-9_arm64.deb ... 646s Unpacking liblua5.1-0:arm64 (5.1.5-9) ... 646s Selecting previously unselected package libneon27:arm64. 646s Preparing to unpack .../14-libneon27_0.33.0-1_arm64.deb ... 646s Unpacking libneon27:arm64 (0.33.0-1) ... 646s Selecting previously unselected package libltdl7:arm64. 646s Preparing to unpack .../15-libltdl7_2.4.7-7_arm64.deb ... 646s Unpacking libltdl7:arm64 (2.4.7-7) ... 646s Selecting previously unselected package libodbc2:arm64. 646s Preparing to unpack .../16-libodbc2_2.3.12-1_arm64.deb ... 646s Unpacking libodbc2:arm64 (2.3.12-1) ... 646s Selecting previously unselected package libogg0:arm64. 646s Preparing to unpack .../17-libogg0_1.3.5-3_arm64.deb ... 646s Unpacking libogg0:arm64 (1.3.5-3) ... 646s Selecting previously unselected package libopencore-amrnb0:arm64. 646s Preparing to unpack .../18-libopencore-amrnb0_0.1.6-1_arm64.deb ... 646s Unpacking libopencore-amrnb0:arm64 (0.1.6-1) ... 646s Selecting previously unselected package libopencore-amrwb0:arm64. 646s Preparing to unpack .../19-libopencore-amrwb0_0.1.6-1_arm64.deb ... 646s Unpacking libopencore-amrwb0:arm64 (0.1.6-1) ... 646s Selecting previously unselected package libopusenc0:arm64. 646s Preparing to unpack .../20-libopusenc0_0.2.1-2_arm64.deb ... 646s Unpacking libopusenc0:arm64 (0.2.1-2) ... 646s Selecting previously unselected package libopusfile0:arm64. 646s Preparing to unpack .../21-libopusfile0_0.12-4_arm64.deb ... 646s Unpacking libopusfile0:arm64 (0.12-4) ... 646s Selecting previously unselected package libasound2-data. 646s Preparing to unpack .../22-libasound2-data_1.2.10-3build1_all.deb ... 646s Unpacking libasound2-data (1.2.10-3build1) ... 646s Selecting previously unselected package libasound2:arm64. 646s Preparing to unpack .../23-libasound2_1.2.10-3build1_arm64.deb ... 646s Unpacking libasound2:arm64 (1.2.10-3build1) ... 646s Selecting previously unselected package libportaudio2:arm64. 646s Preparing to unpack .../24-libportaudio2_19.6.0-1.2_arm64.deb ... 646s Unpacking libportaudio2:arm64 (19.6.0-1.2) ... 646s Selecting previously unselected package libpq5:arm64. 646s Preparing to unpack .../25-libpq5_16.2-1_arm64.deb ... 646s Unpacking libpq5:arm64 (16.2-1) ... 646s Selecting previously unselected package libradcli4. 646s Preparing to unpack .../26-libradcli4_1.2.11-1build1_arm64.deb ... 646s Unpacking libradcli4 (1.2.11-1build1) ... 646s Selecting previously unselected package libresample1. 646s Preparing to unpack .../27-libresample1_0.1.3-6_arm64.deb ... 646s Unpacking libresample1 (0.1.3-6) ... 646s Selecting previously unselected package libsnmp-base. 646s Preparing to unpack .../28-libsnmp-base_5.9.4+dfsg-1ubuntu2_all.deb ... 646s Unpacking libsnmp-base (5.9.4+dfsg-1ubuntu2) ... 646s Selecting previously unselected package libsnmp40:arm64. 647s Preparing to unpack .../29-libsnmp40_5.9.4+dfsg-1ubuntu2_arm64.deb ... 647s Unpacking libsnmp40:arm64 (5.9.4+dfsg-1ubuntu2) ... 647s Selecting previously unselected package libdeflate0:arm64. 647s Preparing to unpack .../30-libdeflate0_1.19-1_arm64.deb ... 647s Unpacking libdeflate0:arm64 (1.19-1) ... 647s Selecting previously unselected package libjbig0:arm64. 647s Preparing to unpack .../31-libjbig0_2.1-6.1ubuntu1_arm64.deb ... 647s Unpacking libjbig0:arm64 (2.1-6.1ubuntu1) ... 647s Selecting previously unselected package libjpeg-turbo8:arm64. 647s Preparing to unpack .../32-libjpeg-turbo8_2.1.5-2ubuntu1_arm64.deb ... 647s Unpacking libjpeg-turbo8:arm64 (2.1.5-2ubuntu1) ... 647s Selecting previously unselected package libjpeg8:arm64. 647s Preparing to unpack .../33-libjpeg8_8c-2ubuntu11_arm64.deb ... 647s Unpacking libjpeg8:arm64 (8c-2ubuntu11) ... 647s Selecting previously unselected package liblerc4:arm64. 647s Preparing to unpack .../34-liblerc4_4.0.0+ds-4ubuntu1_arm64.deb ... 647s Unpacking liblerc4:arm64 (4.0.0+ds-4ubuntu1) ... 647s Selecting previously unselected package libsharpyuv0:arm64. 647s Preparing to unpack .../35-libsharpyuv0_1.3.2-0.4_arm64.deb ... 647s Unpacking libsharpyuv0:arm64 (1.3.2-0.4) ... 647s Selecting previously unselected package libwebp7:arm64. 647s Preparing to unpack .../36-libwebp7_1.3.2-0.4_arm64.deb ... 647s Unpacking libwebp7:arm64 (1.3.2-0.4) ... 647s Selecting previously unselected package libtiff6:arm64. 647s Preparing to unpack .../37-libtiff6_4.5.1+git230720-3ubuntu1_arm64.deb ... 647s Unpacking libtiff6:arm64 (4.5.1+git230720-3ubuntu1) ... 647s Selecting previously unselected package libspandsp2:arm64. 647s Preparing to unpack .../38-libspandsp2_0.0.6+dfsg-2build1_arm64.deb ... 647s Unpacking libspandsp2:arm64 (0.0.6+dfsg-2build1) ... 647s Selecting previously unselected package libspeex1:arm64. 647s Preparing to unpack .../39-libspeex1_1.2.1-2ubuntu1_arm64.deb ... 647s Unpacking libspeex1:arm64 (1.2.1-2ubuntu1) ... 647s Selecting previously unselected package libspeexdsp1:arm64. 647s Preparing to unpack .../40-libspeexdsp1_1.2.1-1ubuntu2_arm64.deb ... 647s Unpacking libspeexdsp1:arm64 (1.2.1-1ubuntu2) ... 647s Selecting previously unselected package libsrtp2-1:arm64. 647s Preparing to unpack .../41-libsrtp2-1_2.5.0-3_arm64.deb ... 647s Unpacking libsrtp2-1:arm64 (2.5.0-3) ... 647s Selecting previously unselected package freetds-common. 647s Preparing to unpack .../42-freetds-common_1.3.17+ds-2_all.deb ... 647s Unpacking freetds-common (1.3.17+ds-2) ... 647s Selecting previously unselected package libsybdb5:arm64. 647s Preparing to unpack .../43-libsybdb5_1.3.17+ds-2_arm64.deb ... 647s Unpacking libsybdb5:arm64 (1.3.17+ds-2) ... 647s Selecting previously unselected package libevent-2.1-7:arm64. 647s Preparing to unpack .../44-libevent-2.1-7_2.1.12-stable-9_arm64.deb ... 647s Unpacking libevent-2.1-7:arm64 (2.1.12-stable-9) ... 647s Selecting previously unselected package libunbound8:arm64. 647s Preparing to unpack .../45-libunbound8_1.19.1-1ubuntu1_arm64.deb ... 647s Unpacking libunbound8:arm64 (1.19.1-1ubuntu1) ... 647s Selecting previously unselected package libvo-amrwbenc0:arm64. 647s Preparing to unpack .../46-libvo-amrwbenc0_0.1.3-2_arm64.deb ... 647s Unpacking libvo-amrwbenc0:arm64 (0.1.3-2) ... 647s Selecting previously unselected package libvorbis0a:arm64. 647s Preparing to unpack .../47-libvorbis0a_1.3.7-1build2_arm64.deb ... 647s Unpacking libvorbis0a:arm64 (1.3.7-1build2) ... 647s Selecting previously unselected package libvorbisenc2:arm64. 647s Preparing to unpack .../48-libvorbisenc2_1.3.7-1build2_arm64.deb ... 647s Unpacking libvorbisenc2:arm64 (1.3.7-1build2) ... 647s Selecting previously unselected package libvorbisfile3:arm64. 648s Preparing to unpack .../49-libvorbisfile3_1.3.7-1build2_arm64.deb ... 648s Unpacking libvorbisfile3:arm64 (1.3.7-1build2) ... 648s Selecting previously unselected package asterisk-modules. 648s Preparing to unpack .../50-asterisk-modules_1%3a20.6.0~dfsg+~cs6.13.40431414-2_arm64.deb ... 648s Unpacking asterisk-modules (1:20.6.0~dfsg+~cs6.13.40431414-2) ... 648s Selecting previously unselected package liburiparser1:arm64. 648s Preparing to unpack .../51-liburiparser1_0.9.7+dfsg-2_arm64.deb ... 648s Unpacking liburiparser1:arm64 (0.9.7+dfsg-2) ... 648s Selecting previously unselected package libxslt1.1:arm64. 648s Preparing to unpack .../52-libxslt1.1_1.1.35-1_arm64.deb ... 648s Unpacking libxslt1.1:arm64 (1.1.35-1) ... 648s Selecting previously unselected package asterisk. 648s Preparing to unpack .../53-asterisk_1%3a20.6.0~dfsg+~cs6.13.40431414-2_arm64.deb ... 648s Unpacking asterisk (1:20.6.0~dfsg+~cs6.13.40431414-2) ... 648s Setting up libgmime-3.0-0:arm64 (3.2.13+dfsg-2) ... 648s Setting up libsharpyuv0:arm64 (1.3.2-0.4) ... 648s Setting up libvo-amrwbenc0:arm64 (0.1.3-2) ... 648s Setting up libogg0:arm64 (1.3.5-3) ... 648s Setting up liblerc4:arm64 (4.0.0+ds-4ubuntu1) ... 648s Setting up libspeex1:arm64 (1.2.1-2ubuntu1) ... 648s Setting up libgsm1:arm64 (1.0.22-1) ... 648s Setting up asterisk-core-sounds-en-gsm (1.6.1-1) ... 648s Setting up libsnmp-base (5.9.4+dfsg-1ubuntu2) ... 648s Setting up libcodec2-1.2:arm64 (1.2.0-2) ... 648s Setting up mlock (8:2007f~dfsg-7build1) ... 648s Setting up libsrtp2-1:arm64 (2.5.0-3) ... 648s Setting up libpq5:arm64 (16.2-1) ... 648s Setting up libdeflate0:arm64 (1.19-1) ... 648s Setting up libjbig0:arm64 (2.1-6.1ubuntu1) ... 648s Setting up libasound2-data (1.2.10-3build1) ... 648s Setting up libopencore-amrwb0:arm64 (0.1.6-1) ... 648s Setting up libsnmp40:arm64 (5.9.4+dfsg-1ubuntu2) ... 648s Setting up libradcli4 (1.2.11-1build1) ... 648s Setting up libopus0:arm64 (1.4-1) ... 648s Setting up asterisk-config (1:20.6.0~dfsg+~cs6.13.40431414-2) ... 649s Setting up libvorbis0a:arm64 (1.3.7-1build2) ... 649s Setting up libevent-2.1-7:arm64 (2.1.12-stable-9) ... 649s Setting up libjpeg-turbo8:arm64 (2.1.5-2ubuntu1) ... 649s Setting up libltdl7:arm64 (2.4.7-7) ... 649s Setting up asterisk-core-sounds-en (1.6.1-1) ... 649s update-alternatives: using /usr/share/asterisk/sounds/en_US_f_Allison to provide /usr/share/asterisk/sounds/en (asterisk-prompt-en) in auto mode 649s 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 649s Setting up libwebp7:arm64 (1.3.2-0.4) ... 649s Setting up libiksemel3:arm64 (1.4-4) ... 649s Setting up libodbc2:arm64 (2.3.12-1) ... 649s Setting up liburiparser1:arm64 (0.9.7+dfsg-2) ... 649s Setting up libneon27:arm64 (0.33.0-1) ... 649s Setting up libspeexdsp1:arm64 (1.2.1-1ubuntu2) ... 649s Setting up libasound2:arm64 (1.2.10-3build1) ... 649s Setting up liblua5.1-0:arm64 (5.1.5-9) ... 649s Setting up libxslt1.1:arm64 (1.1.35-1) ... 649s Setting up libopencore-amrnb0:arm64 (0.1.6-1) ... 649s Setting up libical3:arm64 (3.0.17-1build1) ... 649s Setting up libc-client2007e (8:2007f~dfsg-7build1) ... 649s Setting up libresample1 (0.1.3-6) ... 649s Setting up freetds-common (1.3.17+ds-2) ... 649s Setting up libsamplerate0:arm64 (0.2.2-4) ... 649s Setting up libopusfile0:arm64 (0.12-4) ... 649s Setting up libvorbisenc2:arm64 (1.3.7-1build2) ... 649s Setting up libjpeg8:arm64 (8c-2ubuntu11) ... 649s Setting up libopusenc0:arm64 (0.2.1-2) ... 649s Setting up libsybdb5:arm64 (1.3.17+ds-2) ... 649s Setting up libvorbisfile3:arm64 (1.3.7-1build2) ... 649s Setting up libunbound8:arm64 (1.19.1-1ubuntu1) ... 649s Setting up libjack-jackd2-0:arm64 (1.9.21~dfsg-3) ... 649s Setting up libtiff6:arm64 (4.5.1+git230720-3ubuntu1) ... 649s Setting up libportaudio2:arm64 (19.6.0-1.2) ... 649s Setting up libspandsp2:arm64 (0.0.6+dfsg-2build1) ... 649s Setting up asterisk-modules (1:20.6.0~dfsg+~cs6.13.40431414-2) ... 649s Setting up asterisk (1:20.6.0~dfsg+~cs6.13.40431414-2) ... 649s Adding system user for Asterisk 649s info: Adding user `asterisk' to group `dialout' ... 649s info: Adding user `asterisk' to group `audio' ... 650s Created symlink /etc/systemd/system/multi-user.target.wants/asterisk.service → /usr/lib/systemd/system/asterisk.service. 651s Setting up autopkgtest-satdep (0) ... 651s Processing triggers for man-db (2.12.0-3) ... 652s Processing triggers for libc-bin (2.39-0ubuntu2) ... 657s (Reading database ... 76713 files and directories currently installed.) 657s Removing autopkgtest-satdep (0) ... 667s autopkgtest [14:41:46]: test amr: [----------------------- 667s 1 audio amr amr (AMR) 667s 2 audio amrwb amrwb (AMR-WB) 667s amr amrwb codec2 ulaw alaw gsm g726 g726aal2 adpcm slin8 slin12 slin16 slin24 slin32 slin44 slin48 slin96 slin192 lpc10 speex8 speex16 speex32 g722 opus 667s amr - 23000 15000 15000 15000 15000 15000 15000 15000 9000 17000 17000 17000 17000 17000 17000 17000 17000 15000 15000 23000 23000 17250 15000 667s amr amrwb codec2 ulaw alaw gsm g726 g726aal2 adpcm slin8 slin12 slin16 slin24 slin32 slin44 slin48 slin96 slin192 lpc10 speex8 speex16 speex32 g722 opus 667s amrwb 23500 - 23500 23500 23500 23500 23500 23500 23500 17500 17500 9000 17000 17000 17000 17000 17000 17000 23500 23500 15000 23000 15000 14999 668s autopkgtest [14:41:47]: test amr: -----------------------] 668s autopkgtest [14:41:47]: test amr: - - - - - - - - - - results - - - - - - - - - - 668s amr PASS 669s autopkgtest [14:41:48]: @@@@@@@@@@@@@@@@@@@@ summary 669s asttestmods PASS 669s amr PASS 673s Creating nova instance adt-noble-arm64-asterisk-20240318-143039-juju-7f2275-prod-proposed-migration-environment-2 from image adt/ubuntu-noble-arm64-server-20240318.img (UUID 6b9ea2ac-1792-4f95-a56d-e128e96ab6e9)... 673s Creating nova instance adt-noble-arm64-asterisk-20240318-143039-juju-7f2275-prod-proposed-migration-environment-2 from image adt/ubuntu-noble-arm64-server-20240318.img (UUID 6b9ea2ac-1792-4f95-a56d-e128e96ab6e9)...