0s autopkgtest [10:09:17]: starting date and time: 2024-11-01 10:09:17+0000 0s autopkgtest [10:09:17]: git checkout: 6f3be7a8 Fix armhf LXD image generation for plucky 0s autopkgtest [10:09:17]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.fkq8dv35/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:libxcrypt --apt-upgrade asterisk --timeout-short=300 --timeout-copy=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=libxcrypt/1:4.4.36-5 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos03-arm64-40.secgroup --name adt-plucky-arm64-asterisk-20241101-100917-juju-7f2275-prod-proposed-migration-environment-2-de71e4d2-0f5b-4d64-ae7d-32da51644ac5 --image adt/ubuntu-plucky-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,keyserver.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/ 73s autopkgtest [10:10:30]: testbed dpkg architecture: arm64 74s autopkgtest [10:10:31]: testbed apt version: 2.9.8 74s autopkgtest [10:10:31]: @@@@@@@@@@@@@@@@@@@@ test bed setup 75s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [73.9 kB] 75s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [51.2 kB] 75s Get:3 http://ftpmaster.internal/ubuntu plucky-proposed/restricted Sources [7016 B] 75s Get:4 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [194 kB] 75s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [3094 kB] 76s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 Packages [247 kB] 76s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/restricted arm64 Packages [50.3 kB] 76s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/universe arm64 Packages [2058 kB] 76s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse arm64 Packages [39.5 kB] 77s Fetched 5816 kB in 2s (3075 kB/s) 77s Reading package lists... 80s Reading package lists... 81s Building dependency tree... 81s Reading state information... 82s Calculating upgrade... 83s The following packages will be upgraded: 83s libcrypt-dev libcrypt1 83s 2 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 83s Need to get 206 kB of archives. 83s After this operation, 0 B of additional disk space will be used. 83s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 libcrypt-dev arm64 1:4.4.36-5 [119 kB] 83s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 libcrypt1 arm64 1:4.4.36-5 [86.7 kB] 84s Fetched 206 kB in 0s (472 kB/s) 84s (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 ... 79705 files and directories currently installed.) 84s Preparing to unpack .../libcrypt-dev_1%3a4.4.36-5_arm64.deb ... 84s Unpacking libcrypt-dev:arm64 (1:4.4.36-5) over (1:4.4.36-4build1) ... 84s Preparing to unpack .../libcrypt1_1%3a4.4.36-5_arm64.deb ... 84s Unpacking libcrypt1:arm64 (1:4.4.36-5) over (1:4.4.36-4build1) ... 84s Setting up libcrypt1:arm64 (1:4.4.36-5) ... 84s Setting up libcrypt-dev:arm64 (1:4.4.36-5) ... 84s Processing triggers for man-db (2.12.1-3) ... 85s Processing triggers for libc-bin (2.40-1ubuntu3) ... 85s Reading package lists... 86s Building dependency tree... 86s Reading state information... 87s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 87s Hit:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease 87s Hit:2 http://ftpmaster.internal/ubuntu plucky InRelease 87s Hit:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease 88s Hit:4 http://ftpmaster.internal/ubuntu plucky-security InRelease 89s Reading package lists... 89s Reading package lists... 89s Building dependency tree... 89s Reading state information... 90s Calculating upgrade... 91s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 91s Reading package lists... 92s Building dependency tree... 92s Reading state information... 93s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 97s autopkgtest [10:10:54]: testbed running kernel: Linux 6.11.0-8-generic #8-Ubuntu SMP PREEMPT_DYNAMIC Mon Sep 16 14:19:41 UTC 2024 97s autopkgtest [10:10:54]: @@@@@@@@@@@@@@@@@@@@ apt-source asterisk 109s Get:1 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:20.8.1~dfsg+~cs6.14.40431414-1 (dsc) [5333 B] 109s Get:2 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:20.8.1~dfsg+~cs6.14.40431414-1 (tar) [11.3 kB] 109s Get:3 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:20.8.1~dfsg+~cs6.14.40431414-1 (tar) [21.9 kB] 109s Get:4 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:20.8.1~dfsg+~cs6.14.40431414-1 (tar) [22.5 kB] 109s Get:5 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:20.8.1~dfsg+~cs6.14.40431414-1 (tar) [6344 kB] 109s Get:6 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:20.8.1~dfsg+~cs6.14.40431414-1 (tar) [7351 kB] 109s Get:7 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:20.8.1~dfsg+~cs6.14.40431414-1 (diff) [136 kB] 109s gpgv: Signature made Fri Jun 7 12:32:46 2024 UTC 109s gpgv: using RSA key 9FE3E9C36691A69FF53CC6842C7C3146C1A00121 109s gpgv: Can't check signature: No public key 109s dpkg-source: warning: cannot verify inline signature for ./asterisk_20.8.1~dfsg+~cs6.14.40431414-1.dsc: no acceptable signature found 111s autopkgtest [10:11:08]: testing package asterisk version 1:20.8.1~dfsg+~cs6.14.40431414-1 111s autopkgtest [10:11:08]: build not needed 122s autopkgtest [10:11:19]: test asttestmods: preparing testbed 125s Reading package lists... 125s Building dependency tree... 125s Reading state information... 126s Starting pkgProblemResolver with broken count: 0 126s Starting 2 pkgProblemResolver with broken count: 0 126s Done 128s The following additional packages will be installed: 128s asterisk asterisk-config asterisk-core-sounds-en asterisk-core-sounds-en-gsm 128s asterisk-modules asterisk-tests freetds-common libasound2-data libasound2t64 128s libb64-0d libc-client2007e libcodec2-1.2 libdeflate0 libevent-2.1-7t64 128s libgmime-3.0-0t64 libgsm1 libical3t64 libiksemel3 libjack-jackd2-0 libjbig0 128s libjpeg-turbo8 libjpeg8 libjwt2 liblerc4 libltdl7 liblua5.1-0 libneon27t64 128s libodbc2 libogg0 libopencore-amrnb0 libopencore-amrwb0 libopus0 libopusenc0 128s libopusfile0 libportaudio2 libpq5 libradcli4 libresample1 libsamplerate0 128s libsharpyuv0 libsnmp-base libsnmp40t64 libspandsp2t64 libspeex1 libspeexdsp1 128s libsrtp2-1 libsybdb5 libtiff6 libunbound8 liburiparser1 libvo-amrwbenc0 128s libvorbis0a libvorbisenc2 libvorbisfile3 libwebp7 libxml2-utils libxslt1.1 128s mlock 128s Suggested packages: 128s asterisk-dahdi asterisk-dev asterisk-doc asterisk-ooh323 asterisk-opus 128s alsa-utils libasound2-plugins uw-mailutils jackd2 odbc-postgresql tdsodbc 128s opus-tools snmp-mibs-downloader speex 128s Recommended packages: 128s asterisk-moh-opsound-gsm sox alsa-ucm-conf alsa-topology-conf 128s The following NEW packages will be installed: 128s asterisk asterisk-config asterisk-core-sounds-en asterisk-core-sounds-en-gsm 128s asterisk-modules asterisk-tests autopkgtest-satdep freetds-common 128s libasound2-data libasound2t64 libb64-0d libc-client2007e libcodec2-1.2 128s libdeflate0 libevent-2.1-7t64 libgmime-3.0-0t64 libgsm1 libical3t64 128s libiksemel3 libjack-jackd2-0 libjbig0 libjpeg-turbo8 libjpeg8 libjwt2 128s liblerc4 libltdl7 liblua5.1-0 libneon27t64 libodbc2 libogg0 128s libopencore-amrnb0 libopencore-amrwb0 libopus0 libopusenc0 libopusfile0 128s libportaudio2 libpq5 libradcli4 libresample1 libsamplerate0 libsharpyuv0 128s libsnmp-base libsnmp40t64 libspandsp2t64 libspeex1 libspeexdsp1 libsrtp2-1 128s libsybdb5 libtiff6 libunbound8 liburiparser1 libvo-amrwbenc0 libvorbis0a 128s libvorbisenc2 libvorbisfile3 libwebp7 libxml2-utils libxslt1.1 mlock 128s 0 upgraded, 59 newly installed, 0 to remove and 0 not upgraded. 128s Need to get 29.0 MB/29.0 MB of archives. 128s After this operation, 95.1 MB of additional disk space will be used. 128s Get:1 /tmp/autopkgtest.0TqZbv/1-autopkgtest-satdep.deb autopkgtest-satdep arm64 0 [736 B] 128s Get:2 http://ftpmaster.internal/ubuntu plucky/universe arm64 asterisk-config all 1:20.8.1~dfsg+~cs6.14.40431414-1 [245 kB] 129s Get:3 http://ftpmaster.internal/ubuntu plucky/universe arm64 asterisk-core-sounds-en-gsm all 1.6.1-1 [2417 kB] 129s Get:4 http://ftpmaster.internal/ubuntu plucky/universe arm64 asterisk-core-sounds-en all 1.6.1-1 [20.6 kB] 129s Get:5 http://ftpmaster.internal/ubuntu plucky/universe arm64 mlock arm64 8:2007f~dfsg-7build3 [7918 B] 129s Get:6 http://ftpmaster.internal/ubuntu plucky/universe arm64 libc-client2007e arm64 8:2007f~dfsg-7build3 [628 kB] 129s Get:7 http://ftpmaster.internal/ubuntu plucky/universe arm64 libcodec2-1.2 arm64 1.2.0-2build1 [8996 kB] 130s Get:8 http://ftpmaster.internal/ubuntu plucky/universe arm64 libgmime-3.0-0t64 arm64 3.2.15+dfsg-1 [173 kB] 130s Get:9 http://ftpmaster.internal/ubuntu plucky/universe arm64 libgsm1 arm64 1.0.22-1build1 [27.0 kB] 130s Get:10 http://ftpmaster.internal/ubuntu plucky/main arm64 libical3t64 arm64 3.0.18-1 [299 kB] 130s Get:11 http://ftpmaster.internal/ubuntu plucky/universe arm64 libiksemel3 arm64 1.4-4build2 [27.6 kB] 130s Get:12 http://ftpmaster.internal/ubuntu plucky/main arm64 libopus0 arm64 1.5.2-2 [2891 kB] 130s Get:13 http://ftpmaster.internal/ubuntu plucky/main arm64 libsamplerate0 arm64 0.2.2-4build1 [1343 kB] 130s Get:14 http://ftpmaster.internal/ubuntu plucky/main arm64 libjack-jackd2-0 arm64 1.9.21~dfsg-3ubuntu3 [285 kB] 130s Get:15 http://ftpmaster.internal/ubuntu plucky/universe arm64 libb64-0d arm64 1.2-5build1 [9590 B] 130s Get:16 http://ftpmaster.internal/ubuntu plucky/universe arm64 libjwt2 arm64 1.17.0-2build2 [17.4 kB] 130s Get:17 http://ftpmaster.internal/ubuntu plucky/universe arm64 liblua5.1-0 arm64 5.1.5-9build2 [115 kB] 130s Get:18 http://ftpmaster.internal/ubuntu plucky/universe arm64 libneon27t64 arm64 0.33.0-1.1build3 [101 kB] 130s Get:19 http://ftpmaster.internal/ubuntu plucky/main arm64 libltdl7 arm64 2.4.7-7build1 [40.4 kB] 130s Get:20 http://ftpmaster.internal/ubuntu plucky/main arm64 libodbc2 arm64 2.3.12-1ubuntu1 [145 kB] 130s Get:21 http://ftpmaster.internal/ubuntu plucky/main arm64 libogg0 arm64 1.3.5-3build1 [22.6 kB] 130s Get:22 http://ftpmaster.internal/ubuntu plucky/universe arm64 libopencore-amrnb0 arm64 0.1.6-1build1 [97.0 kB] 130s Get:23 http://ftpmaster.internal/ubuntu plucky/universe arm64 libopencore-amrwb0 arm64 0.1.6-1build1 [50.3 kB] 130s Get:24 http://ftpmaster.internal/ubuntu plucky/universe arm64 libopusenc0 arm64 0.2.1-2build1 [25.6 kB] 130s Get:25 http://ftpmaster.internal/ubuntu plucky/universe arm64 libopusfile0 arm64 0.12-4build3 [44.7 kB] 130s Get:26 http://ftpmaster.internal/ubuntu plucky/main arm64 libasound2-data all 1.2.12-1 [21.0 kB] 130s Get:27 http://ftpmaster.internal/ubuntu plucky/main arm64 libasound2t64 arm64 1.2.12-1 [384 kB] 130s Get:28 http://ftpmaster.internal/ubuntu plucky/universe arm64 libportaudio2 arm64 19.6.0-1.2build3 [65.4 kB] 130s Get:29 http://ftpmaster.internal/ubuntu plucky/main arm64 libpq5 arm64 17.0-1 [248 kB] 130s Get:30 http://ftpmaster.internal/ubuntu plucky/universe arm64 libradcli4 arm64 1.2.11-1build3 [40.2 kB] 130s Get:31 http://ftpmaster.internal/ubuntu plucky/universe arm64 libresample1 arm64 0.1.3-8 [8668 B] 130s Get:32 http://ftpmaster.internal/ubuntu plucky/main arm64 libsnmp-base all 5.9.4+dfsg-1.1ubuntu5 [206 kB] 130s Get:33 http://ftpmaster.internal/ubuntu plucky/main arm64 libsnmp40t64 arm64 5.9.4+dfsg-1.1ubuntu5 [1053 kB] 131s Get:34 http://ftpmaster.internal/ubuntu plucky/main arm64 libdeflate0 arm64 1.21-1 [46.2 kB] 131s Get:35 http://ftpmaster.internal/ubuntu plucky/main arm64 libjbig0 arm64 2.1-6.1ubuntu2 [29.3 kB] 131s Get:36 http://ftpmaster.internal/ubuntu plucky/main arm64 libjpeg-turbo8 arm64 2.1.5-2ubuntu2 [163 kB] 131s Get:37 http://ftpmaster.internal/ubuntu plucky/main arm64 libjpeg8 arm64 8c-2ubuntu11 [2148 B] 131s Get:38 http://ftpmaster.internal/ubuntu plucky/main arm64 liblerc4 arm64 4.0.0+ds-4ubuntu2 [154 kB] 131s Get:39 http://ftpmaster.internal/ubuntu plucky/main arm64 libsharpyuv0 arm64 1.4.0-0.1 [16.3 kB] 131s Get:40 http://ftpmaster.internal/ubuntu plucky/main arm64 libwebp7 arm64 1.4.0-0.1 [192 kB] 131s Get:41 http://ftpmaster.internal/ubuntu plucky/main arm64 libtiff6 arm64 4.5.1+git230720-4ubuntu4 [193 kB] 131s Get:42 http://ftpmaster.internal/ubuntu plucky/universe arm64 libspandsp2t64 arm64 0.0.6+dfsg-2.1build1 [313 kB] 131s Get:43 http://ftpmaster.internal/ubuntu plucky/main arm64 libspeex1 arm64 1.2.1-2ubuntu3 [57.4 kB] 131s Get:44 http://ftpmaster.internal/ubuntu plucky/main arm64 libspeexdsp1 arm64 1.2.1-1ubuntu3 [40.2 kB] 131s Get:45 http://ftpmaster.internal/ubuntu plucky/universe arm64 libsrtp2-1 arm64 2.5.0-3build1 [42.9 kB] 131s Get:46 http://ftpmaster.internal/ubuntu plucky/main arm64 freetds-common all 1.3.17+ds-2build3 [26.9 kB] 131s Get:47 http://ftpmaster.internal/ubuntu plucky/main arm64 libsybdb5 arm64 1.3.17+ds-2build3 [186 kB] 131s Get:48 http://ftpmaster.internal/ubuntu plucky/main arm64 libevent-2.1-7t64 arm64 2.1.12-stable-10 [140 kB] 131s Get:49 http://ftpmaster.internal/ubuntu plucky/main arm64 libunbound8 arm64 1.20.0-1ubuntu2.1 [431 kB] 131s Get:50 http://ftpmaster.internal/ubuntu plucky/universe arm64 libvo-amrwbenc0 arm64 0.1.3-2build1 [73.2 kB] 131s Get:51 http://ftpmaster.internal/ubuntu plucky/main arm64 libvorbis0a arm64 1.3.7-2 [95.0 kB] 131s Get:52 http://ftpmaster.internal/ubuntu plucky/main arm64 libvorbisenc2 arm64 1.3.7-2 [80.0 kB] 131s Get:53 http://ftpmaster.internal/ubuntu plucky/main arm64 libvorbisfile3 arm64 1.3.7-2 [17.1 kB] 131s Get:54 http://ftpmaster.internal/ubuntu plucky/universe arm64 asterisk-modules arm64 1:20.8.1~dfsg+~cs6.14.40431414-1 [3254 kB] 131s Get:55 http://ftpmaster.internal/ubuntu plucky/universe arm64 liburiparser1 arm64 0.9.8+dfsg-1 [35.4 kB] 131s Get:56 http://ftpmaster.internal/ubuntu plucky/main arm64 libxslt1.1 arm64 1.1.39-0exp1ubuntu1 [167 kB] 131s Get:57 http://ftpmaster.internal/ubuntu plucky/universe arm64 asterisk arm64 1:20.8.1~dfsg+~cs6.14.40431414-1 [2607 kB] 131s Get:58 http://ftpmaster.internal/ubuntu plucky/universe arm64 asterisk-tests arm64 1:20.8.1~dfsg+~cs6.14.40431414-1 [545 kB] 131s Get:59 http://ftpmaster.internal/ubuntu plucky/main arm64 libxml2-utils arm64 2.12.7+dfsg-3 [40.3 kB] 132s Fetched 29.0 MB in 3s (9880 kB/s) 132s Selecting previously unselected package asterisk-config. 132s (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 ... 79705 files and directories currently installed.) 132s Preparing to unpack .../00-asterisk-config_1%3a20.8.1~dfsg+~cs6.14.40431414-1_all.deb ... 132s Unpacking asterisk-config (1:20.8.1~dfsg+~cs6.14.40431414-1) ... 132s Selecting previously unselected package asterisk-core-sounds-en-gsm. 132s Preparing to unpack .../01-asterisk-core-sounds-en-gsm_1.6.1-1_all.deb ... 132s Unpacking asterisk-core-sounds-en-gsm (1.6.1-1) ... 132s Selecting previously unselected package asterisk-core-sounds-en. 132s Preparing to unpack .../02-asterisk-core-sounds-en_1.6.1-1_all.deb ... 132s Unpacking asterisk-core-sounds-en (1.6.1-1) ... 132s Selecting previously unselected package mlock. 132s Preparing to unpack .../03-mlock_8%3a2007f~dfsg-7build3_arm64.deb ... 132s Unpacking mlock (8:2007f~dfsg-7build3) ... 132s Selecting previously unselected package libc-client2007e. 132s Preparing to unpack .../04-libc-client2007e_8%3a2007f~dfsg-7build3_arm64.deb ... 132s Unpacking libc-client2007e (8:2007f~dfsg-7build3) ... 132s Selecting previously unselected package libcodec2-1.2:arm64. 132s Preparing to unpack .../05-libcodec2-1.2_1.2.0-2build1_arm64.deb ... 132s Unpacking libcodec2-1.2:arm64 (1.2.0-2build1) ... 132s Selecting previously unselected package libgmime-3.0-0t64:arm64. 132s Preparing to unpack .../06-libgmime-3.0-0t64_3.2.15+dfsg-1_arm64.deb ... 132s Unpacking libgmime-3.0-0t64:arm64 (3.2.15+dfsg-1) ... 132s Selecting previously unselected package libgsm1:arm64. 132s Preparing to unpack .../07-libgsm1_1.0.22-1build1_arm64.deb ... 132s Unpacking libgsm1:arm64 (1.0.22-1build1) ... 132s Selecting previously unselected package libical3t64:arm64. 132s Preparing to unpack .../08-libical3t64_3.0.18-1_arm64.deb ... 132s Unpacking libical3t64:arm64 (3.0.18-1) ... 132s Selecting previously unselected package libiksemel3:arm64. 132s Preparing to unpack .../09-libiksemel3_1.4-4build2_arm64.deb ... 132s Unpacking libiksemel3:arm64 (1.4-4build2) ... 132s Selecting previously unselected package libopus0:arm64. 132s Preparing to unpack .../10-libopus0_1.5.2-2_arm64.deb ... 132s Unpacking libopus0:arm64 (1.5.2-2) ... 133s Selecting previously unselected package libsamplerate0:arm64. 133s Preparing to unpack .../11-libsamplerate0_0.2.2-4build1_arm64.deb ... 133s Unpacking libsamplerate0:arm64 (0.2.2-4build1) ... 133s Selecting previously unselected package libjack-jackd2-0:arm64. 133s Preparing to unpack .../12-libjack-jackd2-0_1.9.21~dfsg-3ubuntu3_arm64.deb ... 133s Unpacking libjack-jackd2-0:arm64 (1.9.21~dfsg-3ubuntu3) ... 133s Selecting previously unselected package libb64-0d:arm64. 133s Preparing to unpack .../13-libb64-0d_1.2-5build1_arm64.deb ... 133s Unpacking libb64-0d:arm64 (1.2-5build1) ... 133s Selecting previously unselected package libjwt2:arm64. 133s Preparing to unpack .../14-libjwt2_1.17.0-2build2_arm64.deb ... 133s Unpacking libjwt2:arm64 (1.17.0-2build2) ... 133s Selecting previously unselected package liblua5.1-0:arm64. 133s Preparing to unpack .../15-liblua5.1-0_5.1.5-9build2_arm64.deb ... 133s Unpacking liblua5.1-0:arm64 (5.1.5-9build2) ... 133s Selecting previously unselected package libneon27t64:arm64. 133s Preparing to unpack .../16-libneon27t64_0.33.0-1.1build3_arm64.deb ... 133s Unpacking libneon27t64:arm64 (0.33.0-1.1build3) ... 133s Selecting previously unselected package libltdl7:arm64. 133s Preparing to unpack .../17-libltdl7_2.4.7-7build1_arm64.deb ... 133s Unpacking libltdl7:arm64 (2.4.7-7build1) ... 133s Selecting previously unselected package libodbc2:arm64. 133s Preparing to unpack .../18-libodbc2_2.3.12-1ubuntu1_arm64.deb ... 133s Unpacking libodbc2:arm64 (2.3.12-1ubuntu1) ... 133s Selecting previously unselected package libogg0:arm64. 133s Preparing to unpack .../19-libogg0_1.3.5-3build1_arm64.deb ... 133s Unpacking libogg0:arm64 (1.3.5-3build1) ... 133s Selecting previously unselected package libopencore-amrnb0:arm64. 133s Preparing to unpack .../20-libopencore-amrnb0_0.1.6-1build1_arm64.deb ... 133s Unpacking libopencore-amrnb0:arm64 (0.1.6-1build1) ... 133s Selecting previously unselected package libopencore-amrwb0:arm64. 133s Preparing to unpack .../21-libopencore-amrwb0_0.1.6-1build1_arm64.deb ... 133s Unpacking libopencore-amrwb0:arm64 (0.1.6-1build1) ... 133s Selecting previously unselected package libopusenc0:arm64. 133s Preparing to unpack .../22-libopusenc0_0.2.1-2build1_arm64.deb ... 133s Unpacking libopusenc0:arm64 (0.2.1-2build1) ... 133s Selecting previously unselected package libopusfile0:arm64. 133s Preparing to unpack .../23-libopusfile0_0.12-4build3_arm64.deb ... 133s Unpacking libopusfile0:arm64 (0.12-4build3) ... 133s Selecting previously unselected package libasound2-data. 133s Preparing to unpack .../24-libasound2-data_1.2.12-1_all.deb ... 133s Unpacking libasound2-data (1.2.12-1) ... 133s Selecting previously unselected package libasound2t64:arm64. 133s Preparing to unpack .../25-libasound2t64_1.2.12-1_arm64.deb ... 133s Unpacking libasound2t64:arm64 (1.2.12-1) ... 133s Selecting previously unselected package libportaudio2:arm64. 133s Preparing to unpack .../26-libportaudio2_19.6.0-1.2build3_arm64.deb ... 133s Unpacking libportaudio2:arm64 (19.6.0-1.2build3) ... 133s Selecting previously unselected package libpq5:arm64. 133s Preparing to unpack .../27-libpq5_17.0-1_arm64.deb ... 133s Unpacking libpq5:arm64 (17.0-1) ... 134s Selecting previously unselected package libradcli4. 134s Preparing to unpack .../28-libradcli4_1.2.11-1build3_arm64.deb ... 134s Unpacking libradcli4 (1.2.11-1build3) ... 134s Selecting previously unselected package libresample1. 134s Preparing to unpack .../29-libresample1_0.1.3-8_arm64.deb ... 134s Unpacking libresample1 (0.1.3-8) ... 134s Selecting previously unselected package libsnmp-base. 134s Preparing to unpack .../30-libsnmp-base_5.9.4+dfsg-1.1ubuntu5_all.deb ... 134s Unpacking libsnmp-base (5.9.4+dfsg-1.1ubuntu5) ... 134s Selecting previously unselected package libsnmp40t64:arm64. 134s Preparing to unpack .../31-libsnmp40t64_5.9.4+dfsg-1.1ubuntu5_arm64.deb ... 134s Unpacking libsnmp40t64:arm64 (5.9.4+dfsg-1.1ubuntu5) ... 134s Selecting previously unselected package libdeflate0:arm64. 134s Preparing to unpack .../32-libdeflate0_1.21-1_arm64.deb ... 134s Unpacking libdeflate0:arm64 (1.21-1) ... 134s Selecting previously unselected package libjbig0:arm64. 134s Preparing to unpack .../33-libjbig0_2.1-6.1ubuntu2_arm64.deb ... 134s Unpacking libjbig0:arm64 (2.1-6.1ubuntu2) ... 134s Selecting previously unselected package libjpeg-turbo8:arm64. 134s Preparing to unpack .../34-libjpeg-turbo8_2.1.5-2ubuntu2_arm64.deb ... 134s Unpacking libjpeg-turbo8:arm64 (2.1.5-2ubuntu2) ... 134s Selecting previously unselected package libjpeg8:arm64. 134s Preparing to unpack .../35-libjpeg8_8c-2ubuntu11_arm64.deb ... 134s Unpacking libjpeg8:arm64 (8c-2ubuntu11) ... 134s Selecting previously unselected package liblerc4:arm64. 134s Preparing to unpack .../36-liblerc4_4.0.0+ds-4ubuntu2_arm64.deb ... 134s Unpacking liblerc4:arm64 (4.0.0+ds-4ubuntu2) ... 134s Selecting previously unselected package libsharpyuv0:arm64. 134s Preparing to unpack .../37-libsharpyuv0_1.4.0-0.1_arm64.deb ... 134s Unpacking libsharpyuv0:arm64 (1.4.0-0.1) ... 134s Selecting previously unselected package libwebp7:arm64. 134s Preparing to unpack .../38-libwebp7_1.4.0-0.1_arm64.deb ... 134s Unpacking libwebp7:arm64 (1.4.0-0.1) ... 134s Selecting previously unselected package libtiff6:arm64. 134s Preparing to unpack .../39-libtiff6_4.5.1+git230720-4ubuntu4_arm64.deb ... 134s Unpacking libtiff6:arm64 (4.5.1+git230720-4ubuntu4) ... 134s Selecting previously unselected package libspandsp2t64:arm64. 134s Preparing to unpack .../40-libspandsp2t64_0.0.6+dfsg-2.1build1_arm64.deb ... 134s Unpacking libspandsp2t64:arm64 (0.0.6+dfsg-2.1build1) ... 134s Selecting previously unselected package libspeex1:arm64. 134s Preparing to unpack .../41-libspeex1_1.2.1-2ubuntu3_arm64.deb ... 134s Unpacking libspeex1:arm64 (1.2.1-2ubuntu3) ... 134s Selecting previously unselected package libspeexdsp1:arm64. 134s Preparing to unpack .../42-libspeexdsp1_1.2.1-1ubuntu3_arm64.deb ... 134s Unpacking libspeexdsp1:arm64 (1.2.1-1ubuntu3) ... 134s Selecting previously unselected package libsrtp2-1:arm64. 134s Preparing to unpack .../43-libsrtp2-1_2.5.0-3build1_arm64.deb ... 134s Unpacking libsrtp2-1:arm64 (2.5.0-3build1) ... 134s Selecting previously unselected package freetds-common. 134s Preparing to unpack .../44-freetds-common_1.3.17+ds-2build3_all.deb ... 134s Unpacking freetds-common (1.3.17+ds-2build3) ... 134s Selecting previously unselected package libsybdb5:arm64. 135s Preparing to unpack .../45-libsybdb5_1.3.17+ds-2build3_arm64.deb ... 135s Unpacking libsybdb5:arm64 (1.3.17+ds-2build3) ... 135s Selecting previously unselected package libevent-2.1-7t64:arm64. 135s Preparing to unpack .../46-libevent-2.1-7t64_2.1.12-stable-10_arm64.deb ... 135s Unpacking libevent-2.1-7t64:arm64 (2.1.12-stable-10) ... 135s Selecting previously unselected package libunbound8:arm64. 135s Preparing to unpack .../47-libunbound8_1.20.0-1ubuntu2.1_arm64.deb ... 135s Unpacking libunbound8:arm64 (1.20.0-1ubuntu2.1) ... 135s Selecting previously unselected package libvo-amrwbenc0:arm64. 135s Preparing to unpack .../48-libvo-amrwbenc0_0.1.3-2build1_arm64.deb ... 135s Unpacking libvo-amrwbenc0:arm64 (0.1.3-2build1) ... 135s Selecting previously unselected package libvorbis0a:arm64. 135s Preparing to unpack .../49-libvorbis0a_1.3.7-2_arm64.deb ... 135s Unpacking libvorbis0a:arm64 (1.3.7-2) ... 135s Selecting previously unselected package libvorbisenc2:arm64. 135s Preparing to unpack .../50-libvorbisenc2_1.3.7-2_arm64.deb ... 135s Unpacking libvorbisenc2:arm64 (1.3.7-2) ... 135s Selecting previously unselected package libvorbisfile3:arm64. 135s Preparing to unpack .../51-libvorbisfile3_1.3.7-2_arm64.deb ... 135s Unpacking libvorbisfile3:arm64 (1.3.7-2) ... 135s Selecting previously unselected package asterisk-modules. 135s Preparing to unpack .../52-asterisk-modules_1%3a20.8.1~dfsg+~cs6.14.40431414-1_arm64.deb ... 135s Unpacking asterisk-modules (1:20.8.1~dfsg+~cs6.14.40431414-1) ... 135s Selecting previously unselected package liburiparser1:arm64. 135s Preparing to unpack .../53-liburiparser1_0.9.8+dfsg-1_arm64.deb ... 135s Unpacking liburiparser1:arm64 (0.9.8+dfsg-1) ... 135s Selecting previously unselected package libxslt1.1:arm64. 135s Preparing to unpack .../54-libxslt1.1_1.1.39-0exp1ubuntu1_arm64.deb ... 135s Unpacking libxslt1.1:arm64 (1.1.39-0exp1ubuntu1) ... 135s Selecting previously unselected package asterisk. 135s Preparing to unpack .../55-asterisk_1%3a20.8.1~dfsg+~cs6.14.40431414-1_arm64.deb ... 135s Unpacking asterisk (1:20.8.1~dfsg+~cs6.14.40431414-1) ... 135s Selecting previously unselected package asterisk-tests. 135s Preparing to unpack .../56-asterisk-tests_1%3a20.8.1~dfsg+~cs6.14.40431414-1_arm64.deb ... 135s Unpacking asterisk-tests (1:20.8.1~dfsg+~cs6.14.40431414-1) ... 136s Selecting previously unselected package libxml2-utils. 136s Preparing to unpack .../57-libxml2-utils_2.12.7+dfsg-3_arm64.deb ... 136s Unpacking libxml2-utils (2.12.7+dfsg-3) ... 136s Selecting previously unselected package autopkgtest-satdep. 136s Preparing to unpack .../58-1-autopkgtest-satdep.deb ... 136s Unpacking autopkgtest-satdep (0) ... 136s Setting up libsharpyuv0:arm64 (1.4.0-0.1) ... 136s Setting up libvo-amrwbenc0:arm64 (0.1.3-2build1) ... 136s Setting up libneon27t64:arm64 (0.33.0-1.1build3) ... 136s Setting up libogg0:arm64 (1.3.5-3build1) ... 136s Setting up liblerc4:arm64 (4.0.0+ds-4ubuntu2) ... 136s Setting up libspeex1:arm64 (1.2.1-2ubuntu3) ... 136s Setting up libgsm1:arm64 (1.0.22-1build1) ... 136s Setting up asterisk-core-sounds-en-gsm (1.6.1-1) ... 136s Setting up libsnmp-base (5.9.4+dfsg-1.1ubuntu5) ... 136s Setting up libcodec2-1.2:arm64 (1.2.0-2build1) ... 136s Setting up mlock (8:2007f~dfsg-7build3) ... 136s Setting up libsrtp2-1:arm64 (2.5.0-3build1) ... 136s Setting up libpq5:arm64 (17.0-1) ... 136s Setting up libdeflate0:arm64 (1.21-1) ... 136s Setting up libevent-2.1-7t64:arm64 (2.1.12-stable-10) ... 136s Setting up libb64-0d:arm64 (1.2-5build1) ... 136s Setting up libjwt2:arm64 (1.17.0-2build2) ... 136s Setting up libjbig0:arm64 (2.1-6.1ubuntu2) ... 136s Setting up libasound2-data (1.2.12-1) ... 136s Setting up libopencore-amrwb0:arm64 (0.1.6-1build1) ... 136s Setting up libunbound8:arm64 (1.20.0-1ubuntu2.1) ... 136s Setting up libasound2t64:arm64 (1.2.12-1) ... 136s Setting up libradcli4 (1.2.11-1build3) ... 136s Setting up libopus0:arm64 (1.5.2-2) ... 136s Setting up asterisk-config (1:20.8.1~dfsg+~cs6.14.40431414-1) ... 136s Setting up libvorbis0a:arm64 (1.3.7-2) ... 136s Setting up libical3t64:arm64 (3.0.18-1) ... 136s Setting up libjpeg-turbo8:arm64 (2.1.5-2ubuntu2) ... 136s Setting up libltdl7:arm64 (2.4.7-7build1) ... 136s Setting up asterisk-core-sounds-en (1.6.1-1) ... 136s update-alternatives: using /usr/share/asterisk/sounds/en_US_f_Allison to provide /usr/share/asterisk/sounds/en (asterisk-prompt-en) in auto mode 136s 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 136s Setting up libwebp7:arm64 (1.4.0-0.1) ... 136s Setting up libiksemel3:arm64 (1.4-4build2) ... 136s Setting up libodbc2:arm64 (2.3.12-1ubuntu1) ... 136s Setting up liburiparser1:arm64 (0.9.8+dfsg-1) ... 136s Setting up libspeexdsp1:arm64 (1.2.1-1ubuntu3) ... 136s Setting up liblua5.1-0:arm64 (5.1.5-9build2) ... 136s Setting up libxslt1.1:arm64 (1.1.39-0exp1ubuntu1) ... 136s Setting up libopencore-amrnb0:arm64 (0.1.6-1build1) ... 136s Setting up libc-client2007e (8:2007f~dfsg-7build3) ... 136s Setting up libresample1 (0.1.3-8) ... 136s Setting up freetds-common (1.3.17+ds-2build3) ... 136s Setting up libxml2-utils (2.12.7+dfsg-3) ... 136s Setting up libgmime-3.0-0t64:arm64 (3.2.15+dfsg-1) ... 136s Setting up libsamplerate0:arm64 (0.2.2-4build1) ... 136s Setting up libopusfile0:arm64 (0.12-4build3) ... 136s Setting up libvorbisenc2:arm64 (1.3.7-2) ... 136s Setting up libjpeg8:arm64 (8c-2ubuntu11) ... 136s Setting up libopusenc0:arm64 (0.2.1-2build1) ... 136s Setting up libsnmp40t64:arm64 (5.9.4+dfsg-1.1ubuntu5) ... 136s Setting up libsybdb5:arm64 (1.3.17+ds-2build3) ... 136s Setting up libvorbisfile3:arm64 (1.3.7-2) ... 136s Setting up libjack-jackd2-0:arm64 (1.9.21~dfsg-3ubuntu3) ... 136s Setting up libtiff6:arm64 (4.5.1+git230720-4ubuntu4) ... 136s Setting up libportaudio2:arm64 (19.6.0-1.2build3) ... 136s Setting up libspandsp2t64:arm64 (0.0.6+dfsg-2.1build1) ... 136s Setting up asterisk-modules (1:20.8.1~dfsg+~cs6.14.40431414-1) ... 136s Setting up asterisk (1:20.8.1~dfsg+~cs6.14.40431414-1) ... 136s Adding system user for Asterisk 136s info: Adding user `asterisk' to group `dialout' ... 136s info: Adding user `asterisk' to group `audio' ... 138s Created symlink '/etc/systemd/system/multi-user.target.wants/asterisk.service' → '/usr/lib/systemd/system/asterisk.service'. 140s Setting up asterisk-tests (1:20.8.1~dfsg+~cs6.14.40431414-1) ... 140s Setting up autopkgtest-satdep (0) ... 140s Processing triggers for man-db (2.12.1-3) ... 141s Processing triggers for libc-bin (2.40-1ubuntu3) ... 147s (Reading database ... 81803 files and directories currently installed.) 147s Removing autopkgtest-satdep (0) ... 148s autopkgtest [10:11:45]: test asttestmods: [----------------------- 149s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 151s 'U' option is not compatible with remote console mode and has no effect. 151s 151s Asterisk has fully booted. 151s 'U' option is not compatible with remote console mode and has no effect. 151s 151s Running all available tests... 151s 151s START /apps/app_gosub/ - gosub application 151s END /apps/app_gosub/ - gosub application Time: <1ms Result: PASS 151s START /apps/app_voicemail/ - test_voicemail_vm_info 151s END /apps/app_voicemail/ - test_voicemail_vm_info Time: <1ms Result: PASS 151s START /apps/app_voicemail/ - test_voicemail_load_config 151s END /apps/app_voicemail/ - test_voicemail_load_config Time: <1ms Result: PASS 151s START /apps/app_voicemail/ - test_voicemail_notify_endl 151s END /apps/app_voicemail/ - test_voicemail_notify_endl Time: 6ms Result: PASS 151s START /apps/app_voicemail/ - vmuser 151s END /apps/app_voicemail/ - vmuser Time: <1ms Result: PASS 151s START /apps/app_voicemail/ - test_voicemail_msgcount 151s END /apps/app_voicemail/ - test_voicemail_msgcount Time: 105ms Result: PASS 151s START /apps/app_voicemail/ - vmsayname_exec 151s [app_voicemail.c:test_voicemail_vmsayname:15253]: Test playing of extension when greeting is not available... 156s [app_voicemail.c:test_voicemail_vmsayname:15274]: Test playing created mailbox greeting... 160s END /apps/app_voicemail/ - vmsayname_exec Time: 8887ms Result: PASS 160s START /ari/validators/ - validate_list 160s END /ari/validators/ - validate_list Time: <1ms Result: PASS 160s START /ari/validators/ - validate_date 160s END /ari/validators/ - validate_date Time: <1ms Result: PASS 160s START /ari/validators/ - validate_string 160s END /ari/validators/ - validate_string Time: <1ms Result: PASS 160s START /ari/validators/ - validate_long 160s END /ari/validators/ - validate_long Time: <1ms Result: PASS 160s START /ari/validators/ - validate_int 160s END /ari/validators/ - validate_int Time: <1ms Result: PASS 160s START /ari/validators/ - validate_boolean 160s END /ari/validators/ - validate_boolean Time: <1ms Result: PASS 160s START /ari/validators/ - validate_byte 160s END /ari/validators/ - validate_byte Time: <1ms Result: PASS 160s START /bridges/bridge_softmix/ - sfu_remove_destination_streams 160s END /bridges/bridge_softmix/ - sfu_remove_destination_streams Time: <1ms Result: PASS 160s START /bridges/bridge_softmix/ - sfu_append_source_streams 160s END /bridges/bridge_softmix/ - sfu_append_source_streams Time: <1ms Result: PASS 160s START /channels/features/ - test_features_channel_interval 163s END /channels/features/ - test_features_channel_interval Time: 3003ms Result: PASS 163s START /channels/features/ - test_features_channel_dtmf 165s END /channels/features/ - test_features_channel_dtmf Time: 2019ms Result: PASS 165s START /config/ - config_options_test 165s END /config/ - config_options_test Time: <1ms Result: PASS 165s START /config/ - ast_parse_arg 165s END /config/ - ast_parse_arg Time: <1ms Result: PASS 165s START /core/endpoints/ - setters 165s END /core/endpoints/ - setters Time: <1ms Result: PASS 165s START /core/endpoints/ - defaults 165s END /core/endpoints/ - defaults Time: <1ms Result: PASS 165s START /core/endpoints/ - create 165s END /core/endpoints/ - create Time: <1ms Result: PASS 165s START /funcs/func_curl/ - vulnerable_url 165s END /funcs/func_curl/ - vulnerable_url Time: <1ms Result: PASS 165s START /funcs/func_env/ - func_file 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=a'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,1)=a'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-8)=a'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-8)=a'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5,1)=b'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4,1)=b'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5,-3)=b'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4,-3)=b'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2)=c'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,2)=c'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-7)=c'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-7)=c'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,4,2)=d'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-5,2)=d'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,4,-3)=d'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-5,-3)=d'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5)=e'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5)='... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4)=e'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4)='... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=fg'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-8)=fg'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,1)=fg'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-8)=fg'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,)=h'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,,)=h'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,l)=h'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,ld)=h'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abc'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=abc'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=abc'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=abc'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=abc'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=abc'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=abc'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=abc'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=ab'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=ab'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=ab'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=ab'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=ab'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=ab'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=ab'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=ab'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcdefg'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcdefg'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcdefg'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcdefg'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcdefg'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcdefg'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcdefg'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcdefg'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcdefghijklmnop'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcdefghijklmnop'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcdefghijklmnop'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcdefghijklmnop'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcdefghijklmnop'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcdefghijklmnop'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcdefghijklmnop'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcdefghijklmnop'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,0,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,0,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,0,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,0,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,2,0,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-1,0,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,3,0,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,la)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)='... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)='... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)='... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)='... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)='... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)='... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)='... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)='... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,ld)='... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,ld)='... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,ld)='... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,ld)='... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,ld)='... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,ld)='... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,ld)='... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,ld)='... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=a'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,10)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 165s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=a'... OK! 165s END /funcs/func_env/ - func_file Time: 52ms Result: PASS 165s START /funcs/func_json/ - func_JSON_DECODE 165s END /funcs/func_json/ - func_JSON_DECODE Time: <1ms Result: PASS 165s START /funcs/func_presence/ - test_presence_state_base64_encode 165s END /funcs/func_presence/ - test_presence_state_base64_encode Time: 9ms Result: PASS 165s START /funcs/func_presence/ - test_presence_state_change 165s END /funcs/func_presence/ - test_presence_state_change Time: <1ms Result: PASS 165s START /funcs/func_presence/ - parse_invalid_presence_data 165s END /funcs/func_presence/ - parse_invalid_presence_data Time: <1ms Result: PASS 165s START /funcs/func_presence/ - parse_valid_presence_data 165s END /funcs/func_presence/ - parse_valid_presence_data Time: <1ms Result: PASS 165s START /funcs/func_sayfiles/ - test_SAYFILES_function 165s [func_sayfiles.c:test_SAYFILES_function:180]: Testing SAYFILES() substitution ... 165s END /funcs/func_sayfiles/ - test_SAYFILES_function Time: 7ms Result: PASS 165s START /funcs/func_strings/ - func_TRIM 165s END /funcs/func_strings/ - func_TRIM Time: <1ms Result: PASS 165s START /funcs/func_strings/ - func_STRBETWEEN 165s END /funcs/func_strings/ - func_STRBETWEEN Time: <1ms Result: PASS 165s START /funcs/func_strings/ - func_STRREPLACE_test 165s END /funcs/func_strings/ - func_STRREPLACE_test Time: <1ms Result: PASS 165s START /funcs/func_strings/ - func_FILTER_test 165s END /funcs/func_strings/ - func_FILTER_test Time: <1ms Result: PASS 165s START /funcs/func_strings/ - func_REPLACE_test 165s END /funcs/func_strings/ - func_REPLACE_test Time: <1ms Result: PASS 165s START /funcs/func_strings/ - func_FIELDNUM_test 165s END /funcs/func_strings/ - func_FIELDNUM_test Time: <1ms Result: PASS 165s START /geoloc/ - create_from_pidf 165s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1274]: ID: 'point-2d' pidf_element: 'tuple' format: 'GML' method: 'Manual' 165s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1286]: location_vars expected: shape=Point,crs=2d,pos=-34.410649 150.87651 165s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1287]: location_vars received: shape=Point,crs=2d,pos=-34.410649 150.87651 165s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1293]: usage_rules expected: retransmission-allowed='no',retention-expiry='2010-11-14T20:00:00Z' 165s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1294]: usage_rules received: retransmission-allowed='no',retention-expiry='2010-11-14T20:00:00Z' 165s END /geoloc/ - create_from_pidf Time: <1ms Result: PASS 165s START /geoloc/ - create_from_uri 165s END /geoloc/ - create_from_uri Time: <1ms Result: PASS 165s START /main/abstract_jb/ - AST_JB_FIXED_put_out_of_order 165s [test_abstract_jb.c:AST_JB_FIXED_put_out_of_order:531]: Executing AST_JB_FIXED_put_out_of_order... 165s END /main/abstract_jb/ - AST_JB_FIXED_put_out_of_order Time: <1ms Result: PASS 165s START /main/abstract_jb/ - AST_JB_FIXED_put_overflow 165s [test_abstract_jb.c:AST_JB_FIXED_put_overflow:529]: Executing AST_JB_FIXED_put_overflow... 165s END /main/abstract_jb/ - AST_JB_FIXED_put_overflow Time: <1ms Result: PASS 165s START /main/abstract_jb/ - AST_JB_FIXED_put 165s [test_abstract_jb.c:AST_JB_FIXED_put:527]: Executing AST_JB_FIXED_put... 165s END /main/abstract_jb/ - AST_JB_FIXED_put Time: <1ms Result: PASS 165s START /main/abstract_jb/ - AST_JB_FIXED_put_first 165s [test_abstract_jb.c:AST_JB_FIXED_put_first:525]: Executing AST_JB_FIXED_create... 165s END /main/abstract_jb/ - AST_JB_FIXED_put_first Time: <1ms Result: PASS 165s START /main/abstract_jb/ - AST_JB_FIXED_create 165s [test_abstract_jb.c:AST_JB_FIXED_create:523]: Executing AST_JB_FIXED_create... 165s END /main/abstract_jb/ - AST_JB_FIXED_create Time: <1ms Result: PASS 165s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_out_of_order 165s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_out_of_order:521]: Executing AST_JB_ADAPTIVE_put_out_of_order... 165s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_out_of_order Time: <1ms Result: PASS 165s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_overflow 165s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_overflow:519]: Executing AST_JB_ADAPTIVE_put_overflow... 165s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_overflow Time: <1ms Result: PASS 165s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put 165s [test_abstract_jb.c:AST_JB_ADAPTIVE_put:517]: Executing AST_JB_ADAPTIVE_put... 165s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put Time: <1ms Result: PASS 165s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_first 165s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_first:515]: Executing AST_JB_ADAPTIVE_create... 165s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_first Time: <1ms Result: PASS 165s START /main/abstract_jb/ - AST_JB_ADAPTIVE_create 165s [test_abstract_jb.c:AST_JB_ADAPTIVE_create:513]: Executing AST_JB_ADAPTIVE_create... 165s END /main/abstract_jb/ - AST_JB_ADAPTIVE_create Time: <1ms Result: PASS 165s START /main/acl/ - acl 165s END /main/acl/ - acl Time: <1ms Result: PASS 165s START /main/acl/ - invalid_acl 165s END /main/acl/ - invalid_acl Time: <1ms Result: PASS 165s START /main/amihooks/ - amihook_cli_send 165s END /main/amihooks/ - amihook_cli_send Time: <1ms Result: PASS 165s START /main/aoc/ - aoc_event_test 165s END /main/aoc/ - aoc_event_test Time: <1ms Result: PASS 165s START /main/aoc/ - aoc_encode_decode_test 165s END /main/aoc/ - aoc_encode_decode_test Time: <1ms Result: PASS 165s START /main/app/ - options_parsing 165s END /main/app/ - options_parsing Time: <1ms Result: PASS 165s START /main/app/ - app_group 165s [test_app.c:app_group:172]: Creating test channels with the following groups: 165s 'a groupgroupgroup', 'a groupGroupgroup', 'a group@a_category', 'a group@another!Category' 165s [test_app.c:app_group:211]: (Subtest 1) Found 4 matches as expected when examining group:'gr' category:'' 165s [test_app.c:app_group:211]: (Subtest 2) Found 1 matches as expected when examining group:'(group){2}$' category:'' 165s [test_app.c:app_group:211]: (Subtest 3) Found 4 matches as expected when examining group:'[:ascii:]' category:'' 165s [test_app.c:app_group:211]: (Subtest 4) Found 0 matches as expected when examining group:'^(NOMATCH)' category:'' 165s [test_app.c:app_group:211]: (Subtest 5) Found 2 matches as expected when examining group:'a group' category:'(gory)$' 165s [test_app.c:app_group:211]: (Subtest 6) Found 1 matches as expected when examining group:'a group' category:'[A-Z]+' 165s [test_app.c:app_group:211]: (Subtest 7) Found 0 matches as expected when examining group:'a group' category:'[[' 165s END /main/app/ - app_group Time: <1ms Result: PASS 165s START /main/ast_expr/ - expr_test 165s END /main/ast_expr/ - expr_test Time: <1ms Result: PASS 165s START /main/astdb/ - put_get_long 165s END /main/astdb/ - put_get_long Time: 139ms Result: PASS 165s START /main/astdb/ - perftest 166s END /main/astdb/ - perftest Time: 289ms Result: PASS 166s START /main/astdb/ - gettree_deltree 166s END /main/astdb/ - gettree_deltree Time: <1ms Result: PASS 166s START /main/astdb/ - put_get_del 166s END /main/astdb/ - put_get_del Time: <1ms Result: PASS 166s START /main/astobj2/ - astobj2_weak_container 166s END /main/astobj2/ - astobj2_weak_container Time: <1ms Result: PASS 166s START /main/astobj2/ - astobj2_weak1 166s END /main/astobj2/ - astobj2_weak1 Time: <1ms Result: PASS 166s START /main/astobj2/ - thrash 166s [test_astobj2_thrash.c:hash_test:266]: Executing hash concurrency test... 166s END /main/astobj2/ - thrash Time: 82ms Result: PASS 166s START /main/astobj2/ - astobj2_test4 166s [test_astobj2.c:test_traversal_nonsorted:1389]: Test 1, List containers. 166s [test_astobj2.c:test_traversal_nonsorted:1389]: Test 2, Hash containers. 166s [test_astobj2.c:test_traversal_sorted:1615]: Test 3, List containers. 166s [test_astobj2.c:test_traversal_sorted:1615]: Test 4, Hash containers. 166s [test_astobj2.c:test_traversal_sorted:1615]: Test 5, RBTree containers. 166s END /main/astobj2/ - astobj2_test4 Time: <1ms Result: PASS 166s START /main/astobj2/ - astobj2_test3 166s END /main/astobj2/ - astobj2_test3 Time: <1ms Result: PASS 166s START /main/astobj2/ - astobj2_test2 166s END /main/astobj2/ - astobj2_test2 Time: <1ms Result: PASS 166s START /main/astobj2/ - astobj2_test1 166s [test_astobj2.c:astobj2_test_1_helper:434]: Test 1, List containers (non-sorted). 166s [test_astobj2.c:astobj2_test_1_helper:488]: List container created: buckets: 1, items: 50 166s [test_astobj2.c:astobj2_test_1_helper:434]: Test 2, List containers (sorted). 166s [test_astobj2.c:astobj2_test_1_helper:488]: List container created: buckets: 1, items: 50 166s [test_astobj2.c:astobj2_test_1_helper:434]: Test 3, Hash containers (non-sorted). 166s [test_astobj2.c:astobj2_test_1_helper:488]: Hash container created: buckets: 9, items: 1000 166s [test_astobj2.c:astobj2_test_1_helper:434]: Test 4, Hash containers (sorted). 166s [test_astobj2.c:astobj2_test_1_helper:488]: Hash container created: buckets: 19, items: 1000 166s [test_astobj2.c:astobj2_test_1_helper:434]: Test 4, RBTree containers (sorted). 166s [test_astobj2.c:astobj2_test_1_helper:488]: RBTree container created: buckets: 1, items: 1000 166s END /main/astobj2/ - astobj2_test1 Time: 10ms Result: PASS 166s START /main/astobj2/perf/ - astobj2_test_perf 167s [test_astobj2.c:testloop:2001]: 20.00K traversals, List 168s [test_astobj2.c:testloop:2001]: 40.00K traversals, List 168s [test_astobj2.c:testloop:2001]: 60.00K traversals, List 169s [test_astobj2.c:testloop:2001]: 80.00K traversals, List 170s [test_astobj2.c:testloop:2006]: 100.00K traversals, List : 4408 ms 171s [test_astobj2.c:testloop:2001]: 20.00K traversals, Hash 171s [test_astobj2.c:testloop:2001]: 40.00K traversals, Hash 172s [test_astobj2.c:testloop:2001]: 60.00K traversals, Hash 172s [test_astobj2.c:testloop:2001]: 80.00K traversals, Hash 173s [test_astobj2.c:testloop:2006]: 100.00K traversals, Hash : 2578 ms 173s [test_astobj2.c:testloop:2001]: 20.00K traversals, RBTree 174s [test_astobj2.c:testloop:2001]: 40.00K traversals, RBTree 175s [test_astobj2.c:testloop:2001]: 60.00K traversals, RBTree 175s [test_astobj2.c:testloop:2001]: 80.00K traversals, RBTree 176s [test_astobj2.c:testloop:2006]: 100.00K traversals, RBTree : 3030 ms 176s END /main/astobj2/perf/ - astobj2_test_perf Time: 10019ms Result: PASS 176s START /main/bridging/ - test_bridging_deferred_queue 177s END /main/bridging/ - test_bridging_deferred_queue Time: 1020ms Result: PASS 177s START /main/bucket/ - bucket_file_json 177s END /main/bucket/ - bucket_file_json Time: 2ms Result: PASS 177s START /main/bucket/ - bucket_file_metadata_get 177s END /main/bucket/ - bucket_file_metadata_get Time: <1ms Result: PASS 177s START /main/bucket/ - bucket_file_metadata_unset 177s END /main/bucket/ - bucket_file_metadata_unset Time: <1ms Result: PASS 177s START /main/bucket/ - bucket_file_metadata_set 177s END /main/bucket/ - bucket_file_metadata_set Time: <1ms Result: PASS 177s START /main/bucket/ - bucket_file_is_stale 177s END /main/bucket/ - bucket_file_is_stale Time: <1ms Result: PASS 177s START /main/bucket/ - bucket_file_delete 177s END /main/bucket/ - bucket_file_delete Time: <1ms Result: PASS 177s START /main/bucket/ - bucket_file_update 177s END /main/bucket/ - bucket_file_update Time: <1ms Result: PASS 177s START /main/bucket/ - bucket_file_retrieve 177s END /main/bucket/ - bucket_file_retrieve Time: <1ms Result: PASS 177s START /main/bucket/ - bucket_file_copy 177s END /main/bucket/ - bucket_file_copy Time: <1ms Result: PASS 177s START /main/bucket/ - bucket_file_clone 177s END /main/bucket/ - bucket_file_clone Time: <1ms Result: PASS 177s START /main/bucket/ - bucket_file_create 177s END /main/bucket/ - bucket_file_create Time: <1ms Result: PASS 177s START /main/bucket/ - bucket_file_alloc 177s END /main/bucket/ - bucket_file_alloc Time: <1ms Result: PASS 177s START /main/bucket/ - bucket_json 177s END /main/bucket/ - bucket_json Time: <1ms Result: PASS 177s START /main/bucket/ - bucket_is_stale 177s END /main/bucket/ - bucket_is_stale Time: <1ms Result: PASS 177s START /main/bucket/ - bucket_retrieve 177s END /main/bucket/ - bucket_retrieve Time: <1ms Result: PASS 177s START /main/bucket/ - bucket_delete 177s END /main/bucket/ - bucket_delete Time: <1ms Result: PASS 177s START /main/bucket/ - bucket_clone 177s END /main/bucket/ - bucket_clone Time: <1ms Result: PASS 177s START /main/bucket/ - bucket_create 177s END /main/bucket/ - bucket_create Time: <1ms Result: PASS 177s START /main/bucket/ - bucket_alloc 177s END /main/bucket/ - bucket_alloc Time: <1ms Result: PASS 177s START /main/bucket/ - bucket_scheme_register_unregister 177s END /main/bucket/ - bucket_scheme_register_unregister Time: <1ms Result: PASS 177s START /main/callerid/ - parse_off_nominal 177s END /main/callerid/ - parse_off_nominal Time: <1ms Result: PASS 177s START /main/callerid/ - parse_nominal 177s END /main/callerid/ - parse_nominal Time: <1ms Result: PASS 177s START /main/cdr/ - test_cdr_fork_cdr 179s Verifying expected record CDRTestChannel/Alice, 179s Finished expected record CDRTestChannel/Alice, 179s Verifying expected record CDRTestChannel/Alice, 179s Finished expected record CDRTestChannel/Alice, 179s Verifying expected record CDRTestChannel/Alice, 179s Finished expected record CDRTestChannel/Alice, 179s END /main/cdr/ - test_cdr_fork_cdr Time: 2002ms Result: PASS 179s START /main/cdr/ - test_cdr_no_reset_cdr 180s Verifying expected record CDRTestChannel/Alice, 180s Finished expected record CDRTestChannel/Alice, 180s END /main/cdr/ - test_cdr_no_reset_cdr Time: 1001ms Result: PASS 180s START /main/cdr/ - test_cdr_fields 182s Verifying expected record CDRTestChannel/Alice, 182s Finished expected record CDRTestChannel/Alice, 182s Verifying expected record CDRTestChannel/Alice, 182s Finished expected record CDRTestChannel/Alice, 182s Verifying expected record CDRTestChannel/Alice, 182s Finished expected record CDRTestChannel/Alice, 182s END /main/cdr/ - test_cdr_fields Time: 2001ms Result: PASS 182s START /main/cdr/ - test_cdr_park 185s Verifying expected record CDRTestChannel/Alice, 185s Finished expected record CDRTestChannel/Alice, 185s Verifying expected record CDRTestChannel/Bob, 185s Finished expected record CDRTestChannel/Bob, 185s END /main/cdr/ - test_cdr_park Time: 3003ms Result: PASS 185s START /main/cdr/ - test_cdr_dial_answer_multiparty 190s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 190s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 190s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 190s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 190s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/David 190s Finished expected record CDRTestChannel/Alice, CDRTestChannel/David 190s Verifying expected record CDRTestChannel/Bob, CDRTestChannel/David 190s Finished expected record CDRTestChannel/Bob, CDRTestChannel/David 190s Verifying expected record CDRTestChannel/Charlie, CDRTestChannel/David 190s Finished expected record CDRTestChannel/Charlie, CDRTestChannel/David 190s Verifying expected record CDRTestChannel/Charlie, CDRTestChannel/Bob 190s Finished expected record CDRTestChannel/Charlie, CDRTestChannel/Bob 190s END /main/cdr/ - test_cdr_dial_answer_multiparty Time: 5006ms Result: PASS 190s START /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_b 193s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 193s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 193s END /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_b Time: 3002ms Result: PASS 193s START /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_a 195s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 195s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 195s END /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_a Time: 2006ms Result: PASS 195s START /main/cdr/ - test_cdr_dial_answer_no_bridge 195s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 195s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 195s Verifying expected record CDRTestChannel/Alice, 195s Finished expected record CDRTestChannel/Alice, 195s Verifying expected record CDRTestChannel/Bob, 195s Finished expected record CDRTestChannel/Bob, 195s END /main/cdr/ - test_cdr_dial_answer_no_bridge Time: 1ms Result: PASS 195s START /main/cdr/ - test_cdr_dial_parallel_failed 195s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 195s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 195s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 195s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 195s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/David 195s Finished expected record CDRTestChannel/Alice, CDRTestChannel/David 195s END /main/cdr/ - test_cdr_dial_parallel_failed Time: 1ms Result: PASS 195s START /main/cdr/ - test_cdr_dial_caller_cancel 195s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 195s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 195s END /main/cdr/ - test_cdr_dial_caller_cancel Time: <1ms Result: PASS 195s START /main/cdr/ - test_cdr_dial_unavailable 195s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 195s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 195s END /main/cdr/ - test_cdr_dial_unavailable Time: <1ms Result: PASS 195s START /main/cdr/ - test_cdr_dial_busy 195s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 195s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 195s END /main/cdr/ - test_cdr_dial_busy Time: <1ms Result: PASS 195s START /main/cdr/ - test_cdr_dial_congestion 195s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 195s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 195s END /main/cdr/ - test_cdr_dial_congestion Time: <1ms Result: PASS 195s START /main/cdr/ - test_cdr_dial_unanswered 195s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 195s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 195s END /main/cdr/ - test_cdr_dial_unanswered Time: <1ms Result: PASS 195s START /main/cdr/ - test_cdr_outbound_bridged_call 198s Verifying expected record CDRTestChannel/Bob, 198s Finished expected record CDRTestChannel/Bob, 198s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 198s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 198s END /main/cdr/ - test_cdr_outbound_bridged_call Time: 3002ms Result: PASS 198s START /main/cdr/ - test_cdr_single_multiparty_bridge 202s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 202s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 202s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 202s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 202s Verifying expected record CDRTestChannel/Bob, CDRTestChannel/Charlie 202s Finished expected record CDRTestChannel/Bob, CDRTestChannel/Charlie 202s Verifying expected record CDRTestChannel/Charlie, 202s Finished expected record CDRTestChannel/Charlie, 202s END /main/cdr/ - test_cdr_single_multiparty_bridge Time: 4004ms Result: PASS 202s START /main/cdr/ - test_cdr_single_twoparty_bridge_b 205s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 205s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 205s Verifying expected record CDRTestChannel/Bob, 205s Finished expected record CDRTestChannel/Bob, 205s END /main/cdr/ - test_cdr_single_twoparty_bridge_b Time: 3002ms Result: PASS 205s START /main/cdr/ - test_cdr_single_twoparty_bridge_a 207s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 207s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 207s Verifying expected record CDRTestChannel/Bob, 207s Finished expected record CDRTestChannel/Bob, 207s END /main/cdr/ - test_cdr_single_twoparty_bridge_a Time: 2003ms Result: PASS 207s START /main/cdr/ - test_cdr_single_bridge_continue 209s Verifying expected record CDRTestChannel/Alice, 209s Finished expected record CDRTestChannel/Alice, 209s Verifying expected record CDRTestChannel/Alice, 209s Finished expected record CDRTestChannel/Alice, 209s END /main/cdr/ - test_cdr_single_bridge_continue Time: 2001ms Result: PASS 209s START /main/cdr/ - test_cdr_single_bridge 211s Verifying expected record CDRTestChannel/Alice, 211s Finished expected record CDRTestChannel/Alice, 211s END /main/cdr/ - test_cdr_single_bridge Time: 2001ms Result: PASS 211s START /main/cdr/ - test_cdr_single_party 211s Verifying expected record CDRTestChannel/Alice, 211s Finished expected record CDRTestChannel/Alice, 211s END /main/cdr/ - test_cdr_single_party Time: <1ms Result: PASS 211s START /main/cdr/ - test_cdr_unanswered_outbound_call 211s Verifying expected record CDRTestChannel/Alice, 211s Finished expected record CDRTestChannel/Alice, 211s END /main/cdr/ - test_cdr_unanswered_outbound_call Time: <1ms Result: PASS 211s START /main/cdr/ - test_cdr_unanswered_inbound_call 211s Verifying expected record CDRTestChannel/Alice, 211s Finished expected record CDRTestChannel/Alice, 211s END /main/cdr/ - test_cdr_unanswered_inbound_call Time: <1ms Result: PASS 211s START /main/cdr/ - test_cdr_channel_creation 211s Verifying expected record CDRTestChannel/Alice, 211s Finished expected record CDRTestChannel/Alice, 211s END /main/cdr/ - test_cdr_channel_creation Time: <1ms Result: PASS 211s START /main/channel/ - add_fd 211s END /main/channel/ - add_fd Time: 1ms Result: PASS 211s START /main/channel/ - set_fd_grow 211s END /main/channel/ - set_fd_grow Time: <1ms Result: PASS 211s START /main/config/ - variable_list_from_quoted_string 211s END /main/config/ - variable_list_from_quoted_string Time: <1ms Result: PASS 211s START /main/config/ - variable_list_join_replace 211s END /main/config/ - variable_list_join_replace Time: <1ms Result: PASS 211s START /main/config/ - variable_lists_match 211s END /main/config/ - variable_lists_match Time: <1ms Result: PASS 211s START /main/config/ - config_dialplan_function 211s END /main/config/ - config_dialplan_function Time: 3ms Result: PASS 211s START /main/config/ - config_hook 211s END /main/config/ - config_hook Time: <1ms Result: PASS 211s START /main/config/ - copy_config 211s END /main/config/ - copy_config Time: <1ms Result: PASS 211s START /main/config/ - config_template_ops 211s END /main/config/ - config_template_ops Time: <1ms Result: PASS 211s START /main/config/ - config_filtered_ops 211s END /main/config/ - config_filtered_ops Time: <1ms Result: PASS 211s START /main/config/ - config_basic_ops 211s END /main/config/ - config_basic_ops Time: <1ms Result: PASS 211s START /main/config/ - config_save 211s END /main/config/ - config_save Time: 2ms Result: PASS 211s START /main/conversions/ - str_to_umax 211s END /main/conversions/ - str_to_umax Time: <1ms Result: PASS 211s START /main/conversions/ - str_to_imax 211s END /main/conversions/ - str_to_imax Time: <1ms Result: PASS 211s START /main/conversions/ - str_to_ulong 211s END /main/conversions/ - str_to_ulong Time: <1ms Result: PASS 211s START /main/conversions/ - str_to_long 211s END /main/conversions/ - str_to_long Time: <1ms Result: PASS 211s START /main/conversions/ - str_to_uint 211s END /main/conversions/ - str_to_uint Time: <1ms Result: PASS 211s START /main/conversions/ - str_to_int 211s END /main/conversions/ - str_to_int Time: <1ms Result: PASS 211s START /main/core_codec/ - codec_get_unknown 211s END /main/core_codec/ - codec_get_unknown Time: <1ms Result: PASS 211s START /main/core_codec/ - codec_get_unknown 211s END /main/core_codec/ - codec_get_unknown Time: <1ms Result: PASS 211s START /main/core_codec/ - codec_get_unregistered 211s END /main/core_codec/ - codec_get_unregistered Time: <1ms Result: PASS 211s START /main/core_codec/ - codec_get 211s END /main/core_codec/ - codec_get Time: <1ms Result: PASS 211s START /main/core_codec/ - codec_register_audio_no_sample_rate 211s END /main/core_codec/ - codec_register_audio_no_sample_rate Time: <1ms Result: PASS 211s START /main/core_codec/ - codec_register_unknown 211s END /main/core_codec/ - codec_register_unknown Time: <1ms Result: PASS 211s START /main/core_codec/ - codec_register_twice 211s END /main/core_codec/ - codec_register_twice Time: <1ms Result: PASS 211s START /main/core_codec/ - codec_register 211s END /main/core_codec/ - codec_register Time: <1ms Result: PASS 211s START /main/core_format/ - format_parse_and_generate_sdp_fmtp 211s END /main/core_format/ - format_parse_and_generate_sdp_fmtp Time: <1ms Result: PASS 211s START /main/core_format/ - format_parse_sdp_fmtp_without_interface 211s END /main/core_format/ - format_parse_sdp_fmtp_without_interface Time: <1ms Result: PASS 211s START /main/core_format/ - format_attribute_get_without_interface 211s END /main/core_format/ - format_attribute_get_without_interface Time: <1ms Result: PASS 211s START /main/core_format/ - format_attribute_set_without_interface 211s END /main/core_format/ - format_attribute_set_without_interface Time: <1ms Result: PASS 211s START /main/core_format/ - format_copy 211s END /main/core_format/ - format_copy Time: <1ms Result: PASS 211s START /main/core_format/ - format_joint_different_codec 211s END /main/core_format/ - format_joint_different_codec Time: <1ms Result: PASS 211s START /main/core_format/ - format_attr_joint_same_codec 211s END /main/core_format/ - format_attr_joint_same_codec Time: <1ms Result: PASS 211s START /main/core_format/ - format_joint_same_codec 211s END /main/core_format/ - format_joint_same_codec Time: <1ms Result: PASS 211s START /main/core_format/ - format_cmp_different_codec 211s END /main/core_format/ - format_cmp_different_codec Time: <1ms Result: PASS 211s START /main/core_format/ - format_attr_cmp_same_codec 211s END /main/core_format/ - format_attr_cmp_same_codec Time: <1ms Result: PASS 211s START /main/core_format/ - format_cmp_same_codec 211s END /main/core_format/ - format_cmp_same_codec Time: <1ms Result: PASS 211s START /main/core_format/ - format_clone 211s END /main/core_format/ - format_clone Time: <1ms Result: PASS 211s START /main/core_format/ - format_retrieve_attr 211s END /main/core_format/ - format_retrieve_attr Time: <1ms Result: PASS 211s START /main/core_format/ - format_create_attr 211s END /main/core_format/ - format_create_attr Time: <1ms Result: PASS 211s START /main/core_format/ - format_create 211s END /main/core_format/ - format_create Time: <1ms Result: PASS 211s START /main/data_buffer/ - buffer_nominal 211s END /main/data_buffer/ - buffer_nominal Time: <1ms Result: PASS 211s START /main/data_buffer/ - buffer_resize 211s END /main/data_buffer/ - buffer_resize Time: <1ms Result: PASS 211s START /main/data_buffer/ - buffer_put 211s END /main/data_buffer/ - buffer_put Time: <1ms Result: PASS 211s START /main/data_buffer/ - buffer_create 211s END /main/data_buffer/ - buffer_create Time: <1ms Result: PASS 211s START /main/devicestate/ - devstate_channels 211s END /main/devicestate/ - devstate_channels Time: <1ms Result: PASS 211s START /main/devicestate/ - devstate_conversions 211s END /main/devicestate/ - devstate_conversions Time: <1ms Result: PASS 211s START /main/devicestate/ - devstate_changed 211s [test_devicestate.c:wait_for_device_state_updates:308]: Received 8 of 8 updates 211s [test_devicestate.c:devstate_changed:716]: Testing update 0: actual is 1; expected is 1 211s [test_devicestate.c:devstate_changed:716]: Testing update 1: actual is 2; expected is 2 211s [test_devicestate.c:devstate_changed:716]: Testing update 2: actual is 3; expected is 3 211s [test_devicestate.c:devstate_changed:716]: Testing update 3: actual is 4; expected is 4 211s [test_devicestate.c:devstate_changed:716]: Testing update 4: actual is 5; expected is 5 211s [test_devicestate.c:devstate_changed:716]: Testing update 5: actual is 6; expected is 6 211s [test_devicestate.c:devstate_changed:716]: Testing update 6: actual is 7; expected is 7 211s [test_devicestate.c:devstate_changed:716]: Testing update 7: actual is 8; expected is 8 211s [test_devicestate.c:wait_for_device_state_updates:308]: Received 1 of 1 updates 211s [test_devicestate.c:wait_for_device_state_updates:308]: Received 8 of 8 updates 211s [test_devicestate.c:devstate_changed:754]: Testing update 0: actual is 1; expected is 1 211s [test_devicestate.c:devstate_changed:754]: Testing update 1: actual is 2; expected is 2 211s [test_devicestate.c:devstate_changed:754]: Testing update 2: actual is 3; expected is 3 211s [test_devicestate.c:devstate_changed:754]: Testing update 3: actual is 4; expected is 4 211s [test_devicestate.c:devstate_changed:754]: Testing update 4: actual is 5; expected is 5 211s [test_devicestate.c:devstate_changed:754]: Testing update 5: actual is 6; expected is 6 211s [test_devicestate.c:devstate_changed:754]: Testing update 6: actual is 7; expected is 7 211s [test_devicestate.c:devstate_changed:754]: Testing update 7: actual is 8; expected is 8 211s END /main/devicestate/ - devstate_changed Time: 1ms Result: PASS 211s START /main/devicestate/ - devstate_prov_del 211s END /main/devicestate/ - devstate_prov_del Time: <1ms Result: PASS 211s START /main/devicestate/ - devstate_prov_add 211s END /main/devicestate/ - devstate_prov_add Time: <1ms Result: PASS 211s START /main/devicestate/ - device2extenstate_test 211s END /main/devicestate/ - device2extenstate_test Time: <1ms Result: PASS 211s START /main/devicestate/ - device_state_aggregation_test 211s END /main/devicestate/ - device_state_aggregation_test Time: <1ms Result: PASS 211s START /main/dns/ - resolver_resolve_async_cancel 211s END /main/dns/ - resolver_resolve_async_cancel Time: <1ms Result: PASS 211s START /main/dns/ - resolver_resolve_async_off_nominal 211s END /main/dns/ - resolver_resolve_async_off_nominal Time: <1ms Result: PASS 211s START /main/dns/ - resolver_resolve_async 216s END /main/dns/ - resolver_resolve_async Time: 5000ms Result: PASS 216s START /main/dns/ - resolver_resolve_sync_off_nominal 216s END /main/dns/ - resolver_resolve_sync_off_nominal Time: <1ms Result: PASS 216s START /main/dns/ - resolver_resolve_sync 221s END /main/dns/ - resolver_resolve_sync Time: 5000ms Result: PASS 221s START /main/dns/ - resolver_add_record_off_nominal 221s END /main/dns/ - resolver_add_record_off_nominal Time: <1ms Result: PASS 221s START /main/dns/ - resolver_add_record 221s END /main/dns/ - resolver_add_record Time: <1ms Result: PASS 221s START /main/dns/ - resolver_set_result_off_nominal 221s END /main/dns/ - resolver_set_result_off_nominal Time: <1ms Result: PASS 221s START /main/dns/ - resolver_set_result 221s END /main/dns/ - resolver_set_result Time: <1ms Result: PASS 221s START /main/dns/ - resolver_data 221s END /main/dns/ - resolver_data Time: <1ms Result: PASS 221s START /main/dns/ - resolver_unregister_off_nominal 221s END /main/dns/ - resolver_unregister_off_nominal Time: <1ms Result: PASS 221s START /main/dns/ - resolver_register_off_nominal 221s END /main/dns/ - resolver_register_off_nominal Time: <1ms Result: PASS 221s START /main/dns/ - resolver_register_unregister 221s END /main/dns/ - resolver_register_unregister Time: <1ms Result: PASS 221s START /main/dns/naptr/ - naptr_resolve_off_nominal_interactions 221s END /main/dns/naptr/ - naptr_resolve_off_nominal_interactions Time: <1ms Result: PASS 221s START /main/dns/naptr/ - naptr_resolve_off_nominal_regexp 221s END /main/dns/naptr/ - naptr_resolve_off_nominal_regexp Time: <1ms Result: PASS 221s START /main/dns/naptr/ - naptr_resolve_off_nominal_services 221s END /main/dns/naptr/ - naptr_resolve_off_nominal_services Time: <1ms Result: PASS 221s START /main/dns/naptr/ - naptr_resolve_off_nominal_flags 221s END /main/dns/naptr/ - naptr_resolve_off_nominal_flags Time: <1ms Result: PASS 221s START /main/dns/naptr/ - naptr_resolve_off_nominal_length 221s END /main/dns/naptr/ - naptr_resolve_off_nominal_length Time: <1ms Result: PASS 221s START /main/dns/naptr/ - naptr_resolve 221s END /main/dns/naptr/ - naptr_resolve Time: <1ms Result: PASS 221s START /main/dns/query_set/ - query_set_off_nominal_cancel 221s END /main/dns/query_set/ - query_set_off_nominal_cancel Time: <1ms Result: PASS 221s START /main/dns/query_set/ - query_set_nominal_cancel 221s END /main/dns/query_set/ - query_set_nominal_cancel Time: <1ms Result: PASS 221s START /main/dns/query_set/ - query_set_empty 221s END /main/dns/query_set/ - query_set_empty Time: <1ms Result: PASS 221s START /main/dns/query_set/ - query_set 221s END /main/dns/query_set/ - query_set Time: <1ms Result: PASS 221s START /main/dns/recurring/ - recurring_query_cancel_during 221s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 228s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 238s END /main/dns/recurring/ - recurring_query_cancel_during Time: 16999ms Result: PASS 238s START /main/dns/recurring/ - recurring_query_cancel_between 238s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 248s END /main/dns/recurring/ - recurring_query_cancel_between Time: 10000ms Result: PASS 248s START /main/dns/recurring/ - recurring_query_off_nominal 248s END /main/dns/recurring/ - recurring_query_off_nominal Time: <1ms Result: PASS 248s START /main/dns/recurring/ - recurring_query 248s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 255s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 267s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 267s END /main/dns/recurring/ - recurring_query Time: 18999ms Result: PASS 267s START /main/dns/srv/ - srv_resolve_record_missing_host 267s END /main/dns/srv/ - srv_resolve_record_missing_host Time: <1ms Result: PASS 267s START /main/dns/srv/ - srv_resolve_record_missing_port_host 267s END /main/dns/srv/ - srv_resolve_record_missing_port_host Time: <1ms Result: PASS 267s START /main/dns/srv/ - srv_resolve_record_missing_weight_port_host 267s END /main/dns/srv/ - srv_resolve_record_missing_weight_port_host Time: <1ms Result: PASS 267s START /main/dns/srv/ - srv_resolve_different_priorities_different_weights 267s END /main/dns/srv/ - srv_resolve_different_priorities_different_weights Time: 13ms Result: PASS 267s START /main/dns/srv/ - srv_resolve_same_priority_different_weights 267s END /main/dns/srv/ - srv_resolve_same_priority_different_weights Time: 13ms Result: PASS 267s START /main/dns/srv/ - srv_resolve_same_priority_zero_weight 267s END /main/dns/srv/ - srv_resolve_same_priority_zero_weight Time: <1ms Result: PASS 267s START /main/dns/srv/ - srv_resolve_sort_priority 267s END /main/dns/srv/ - srv_resolve_sort_priority Time: <1ms Result: PASS 267s START /main/dns/srv/ - srv_resolve_single_record 267s END /main/dns/srv/ - srv_resolve_single_record Time: <1ms Result: PASS 267s START /main/dsp/ - dtmf 267s END /main/dsp/ - dtmf Time: 2ms Result: PASS 267s START /main/dsp/ - fax 267s END /main/dsp/ - fax Time: 338ms Result: PASS 267s START /main/event/ - ast_event_new_test 267s [test_event.c:event_new_test:125]: First, test dynamic event creation... 267s [test_event.c:check_event:88]: Event looks good. 267s [test_event.c:check_event:88]: Event looks good. 267s END /main/event/ - ast_event_new_test Time: <1ms Result: PASS 267s START /main/file/ - ast_format_str_reduce_test_1 267s END /main/file/ - ast_format_str_reduce_test_1 Time: <1ms Result: PASS 267s START /main/file/ - read_dir_test 267s END /main/file/ - read_dir_test Time: <1ms Result: PASS 267s START /main/format_cache/ - format_cache_get_nonxistent 267s END /main/format_cache/ - format_cache_get_nonxistent Time: <1ms Result: PASS 267s START /main/format_cache/ - format_cache_get 267s END /main/format_cache/ - format_cache_get Time: <1ms Result: PASS 267s START /main/format_cache/ - format_cache_set_null 267s END /main/format_cache/ - format_cache_set_null Time: <1ms Result: PASS 267s START /main/format_cache/ - format_cache_set_duplicate 267s END /main/format_cache/ - format_cache_set_duplicate Time: <1ms Result: PASS 267s START /main/format_cache/ - format_cache_set 267s END /main/format_cache/ - format_cache_set Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_replace_from_cap 267s END /main/format_cap/ - format_cap_replace_from_cap Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_best_by_type 267s END /main/format_cap/ - format_cap_best_by_type Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_iscompatible 267s END /main/format_cap/ - format_cap_iscompatible Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_get_compatible 267s END /main/format_cap/ - format_cap_get_compatible Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_iscompatible_format 267s END /main/format_cap/ - format_cap_iscompatible_format Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_get_compatible_format 267s END /main/format_cap/ - format_cap_get_compatible_format Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_get_names 267s END /main/format_cap/ - format_cap_get_names Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_remove_all 267s END /main/format_cap/ - format_cap_remove_all Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_remove_bytype 267s END /main/format_cap/ - format_cap_remove_bytype Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_remove_multiple 267s END /main/format_cap/ - format_cap_remove_multiple Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_remove_single 267s END /main/format_cap/ - format_cap_remove_single Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_set_framing 267s END /main/format_cap/ - format_cap_set_framing Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_append_from_cap_duplicate 267s END /main/format_cap/ - format_cap_append_from_cap_duplicate Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_append_from_cap 267s END /main/format_cap/ - format_cap_append_from_cap Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_append_duplicate 267s END /main/format_cap/ - format_cap_append_duplicate Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_append_all_audio 267s END /main/format_cap/ - format_cap_append_all_audio Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_append_all_unknown 267s END /main/format_cap/ - format_cap_append_all_unknown Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_append_multiple 267s END /main/format_cap/ - format_cap_append_multiple Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_append_single 267s END /main/format_cap/ - format_cap_append_single Time: <1ms Result: PASS 267s START /main/format_cap/ - format_cap_alloc 267s END /main/format_cap/ - format_cap_alloc Time: <1ms Result: PASS 267s START /main/hashtab/ - thrash 267s [test_hashtab_thrash.c:hash_test:246]: Executing hash concurrency test... 267s END /main/hashtab/ - thrash Time: 54ms Result: PASS 267s START /main/heap/ - heap_test_3 267s END /main/heap/ - heap_test_3 Time: 130ms Result: PASS 267s START /main/heap/ - heap_test_2 268s END /main/heap/ - heap_test_2 Time: 117ms Result: PASS 268s START /main/heap/ - heap_test_1 268s END /main/heap/ - heap_test_1 Time: <1ms Result: PASS 268s START /main/jitterbuf/ - jitterbuffer_resynch_control 268s END /main/jitterbuf/ - jitterbuffer_resynch_control Time: <1ms Result: PASS 268s START /main/jitterbuf/ - jitterbuffer_resynch_voice 268s END /main/jitterbuf/ - jitterbuffer_resynch_voice Time: <1ms Result: PASS 268s START /main/jitterbuf/ - jitterbuffer_overflow_control 268s END /main/jitterbuf/ - jitterbuffer_overflow_control Time: <1ms Result: PASS 268s START /main/jitterbuf/ - jitterbuffer_overflow_voice 268s END /main/jitterbuf/ - jitterbuffer_overflow_voice Time: <1ms Result: PASS 268s START /main/jitterbuf/ - jitterbuffer_late_control 268s END /main/jitterbuf/ - jitterbuffer_late_control Time: <1ms Result: PASS 268s START /main/jitterbuf/ - jitterbuffer_late_voice 268s END /main/jitterbuf/ - jitterbuffer_late_voice Time: <1ms Result: PASS 268s START /main/jitterbuf/ - jitterbuffer_lost_control 268s END /main/jitterbuf/ - jitterbuffer_lost_control Time: <1ms Result: PASS 268s START /main/jitterbuf/ - jitterbuffer_lost_voice 268s END /main/jitterbuf/ - jitterbuffer_lost_voice Time: <1ms Result: PASS 268s START /main/jitterbuf/ - jitterbuffer_out_of_order_voice 268s END /main/jitterbuf/ - jitterbuffer_out_of_order_voice Time: <1ms Result: PASS 268s START /main/jitterbuf/ - jitterbuffer_out_of_order_voice 268s END /main/jitterbuf/ - jitterbuffer_out_of_order_voice Time: <1ms Result: PASS 268s START /main/jitterbuf/ - jitterbuffer_nominal_control_frames 268s END /main/jitterbuf/ - jitterbuffer_nominal_control_frames Time: <1ms Result: PASS 268s START /main/jitterbuf/ - jitterbuffer_nominal_voice_frames 268s END /main/jitterbuf/ - jitterbuffer_nominal_voice_frames Time: <1ms Result: PASS 268s START /main/json/ - cep 268s END /main/json/ - cep Time: <1ms Result: PASS 268s START /main/json/ - type_timeval 268s END /main/json/ - type_timeval Time: <1ms Result: PASS 268s START /main/json/ - name_number 268s END /main/json/ - name_number Time: <1ms Result: PASS 268s START /main/json/ - clever_circle 268s END /main/json/ - clever_circle Time: <1ms Result: PASS 268s START /main/json/ - circular_array 268s END /main/json/ - circular_array Time: <1ms Result: PASS 268s START /main/json/ - circular_object 268s END /main/json/ - circular_object Time: <1ms Result: PASS 268s START /main/json/ - copy_null 268s END /main/json/ - copy_null Time: <1ms Result: PASS 268s START /main/json/ - deep_copy 268s END /main/json/ - deep_copy Time: <1ms Result: PASS 268s START /main/json/ - copy 268s END /main/json/ - copy Time: <1ms Result: PASS 268s START /main/json/ - object_alloc 268s END /main/json/ - object_alloc Time: 2ms Result: PASS 268s START /main/json/ - pack_ownership 268s END /main/json/ - pack_ownership Time: <1ms Result: PASS 268s START /main/json/ - pack 268s END /main/json/ - pack Time: <1ms Result: PASS 268s START /main/json/ - parse_errors 268s END /main/json/ - parse_errors Time: <1ms Result: PASS 268s START /main/json/ - dump_load_null 268s END /main/json/ - dump_load_null Time: <1ms Result: PASS 268s START /main/json/ - dump_load_new_file 268s END /main/json/ - dump_load_new_file Time: <1ms Result: PASS 268s START /main/json/ - dump_load_file 268s END /main/json/ - dump_load_file Time: <1ms Result: PASS 268s START /main/json/ - load_buffer 268s END /main/json/ - load_buffer Time: <1ms Result: PASS 268s START /main/json/ - dump_str_fail 268s END /main/json/ - dump_str_fail Time: <1ms Result: PASS 268s START /main/json/ - dump_load_str 268s END /main/json/ - dump_load_str Time: <1ms Result: PASS 268s START /main/json/ - dump_load_string 268s END /main/json/ - dump_load_string Time: <1ms Result: PASS 268s START /main/json/ - object_create_vars 268s END /main/json/ - object_create_vars Time: <1ms Result: PASS 268s START /main/json/ - object_iter_null 268s END /main/json/ - object_iter_null Time: <1ms Result: PASS 268s START /main/json/ - object_iter 268s END /main/json/ - object_iter Time: <1ms Result: PASS 268s START /main/json/ - object_null 268s END /main/json/ - object_null Time: <1ms Result: PASS 268s START /main/json/ - object_merge_missing 268s END /main/json/ - object_merge_missing Time: <1ms Result: PASS 268s START /main/json/ - object_alloc 268s END /main/json/ - object_alloc Time: <1ms Result: PASS 268s START /main/json/ - object_alloc 268s END /main/json/ - object_alloc Time: <1ms Result: PASS 268s START /main/json/ - object_clear 268s END /main/json/ - object_clear Time: <1ms Result: PASS 268s START /main/json/ - object_del 268s END /main/json/ - object_del Time: <1ms Result: PASS 268s START /main/json/ - object_get 268s END /main/json/ - object_get Time: <1ms Result: PASS 268s START /main/json/ - object_set_overwriting 268s END /main/json/ - object_set_overwriting Time: <1ms Result: PASS 268s START /main/json/ - object_set 268s END /main/json/ - object_set Time: <1ms Result: PASS 268s START /main/json/ - object_alloc 268s END /main/json/ - object_alloc Time: <1ms Result: PASS 268s START /main/json/ - array_null 268s END /main/json/ - array_null Time: <1ms Result: PASS 268s START /main/json/ - array_extend 268s END /main/json/ - array_extend Time: <1ms Result: PASS 268s START /main/json/ - array_clear 268s END /main/json/ - array_clear Time: <1ms Result: PASS 268s START /main/json/ - array_remove 268s END /main/json/ - array_remove Time: <1ms Result: PASS 268s START /main/json/ - array_set 268s END /main/json/ - array_set Time: <1ms Result: PASS 268s START /main/json/ - array_insert 268s END /main/json/ - array_insert Time: <1ms Result: PASS 268s START /main/json/ - array_append 268s END /main/json/ - array_append Time: <1ms Result: PASS 268s START /main/json/ - array_create 268s END /main/json/ - array_create Time: <1ms Result: PASS 268s START /main/json/ - non_int 268s END /main/json/ - non_int Time: <1ms Result: PASS 268s START /main/json/ - type_int 268s END /main/json/ - type_int Time: <1ms Result: PASS 268s START /main/json/ - stringf 268s END /main/json/ - stringf Time: <1ms Result: PASS 268s START /main/json/ - string_null 268s END /main/json/ - string_null Time: <1ms Result: PASS 268s START /main/json/ - type_string 268s END /main/json/ - type_string Time: <1ms Result: PASS 268s START /main/json/ - null_val 268s END /main/json/ - null_val Time: <1ms Result: PASS 268s START /main/json/ - type_null 268s END /main/json/ - type_null Time: <1ms Result: PASS 268s START /main/json/ - type_bool1 268s END /main/json/ - type_bool1 Time: <1ms Result: PASS 268s START /main/json/ - type_bool0 268s END /main/json/ - type_bool0 Time: <1ms Result: PASS 268s START /main/json/ - type_true 268s END /main/json/ - type_true Time: <1ms Result: PASS 268s START /main/json/ - type_false 268s END /main/json/ - type_false Time: <1ms Result: PASS 268s START /main/linkedlists/ - double_ll_tests 268s END /main/linkedlists/ - double_ll_tests Time: <1ms Result: PASS 268s START /main/linkedlists/ - ll_tests 268s END /main/linkedlists/ - ll_tests Time: <1ms Result: PASS 268s START /main/lock/ - cleanup_order_test 268s [test_scoped_lock.c:test_ref:149]: Ref is occurring 268s [test_scoped_lock.c:test_lock:117]: Lock is occurring 268s [test_scoped_lock.c:test_unlock:133]: Unlock is occurring 268s [test_scoped_lock.c:test_unref:166]: Unref is occurring 268s [test_scoped_lock.c:test_ref:149]: Ref is occurring 268s [test_scoped_lock.c:test_lock:117]: Lock is occurring 268s [test_scoped_lock.c:test_unlock:133]: Unlock is occurring 268s [test_scoped_lock.c:test_unref:166]: Unref is occurring 268s END /main/lock/ - cleanup_order_test Time: <1ms Result: PASS 268s START /main/lock/ - lock_test 268s END /main/lock/ - lock_test Time: <1ms Result: PASS 268s START /main/lock/ - named_lock_test 268s [test_named_lock.c:named_lock_test:80]: This test should take about 3 seconds 271s END /main/lock/ - named_lock_test Time: 3000ms Result: PASS 271s START /main/logging/ - scope_test 271s END /main/logging/ - scope_test Time: <1ms Result: PASS 271s START /main/media_cache/ - create_update_off_nominal 271s END /main/media_cache/ - create_update_off_nominal Time: <1ms Result: PASS 271s START /main/media_cache/ - create_update_metadata 271s [test_media_cache.c:create_update_metadata:364]: Got /tmp/test-media-cache-tLeodT for second file path 271s END /main/media_cache/ - create_update_metadata Time: <1ms Result: PASS 271s START /main/media_cache/ - create_update_nominal 271s [test_media_cache.c:create_update_nominal:235]: Creating resource with /tmp/test-media-cache-3G4STc 271s [test_media_cache.c:create_update_nominal:240]: Got /tmp/test-media-cache-3G4STc for first file path 271s [test_media_cache.c:create_update_nominal:244]: Creating resource with /tmp/test-media-cache-WePUEU 271s [test_media_cache.c:create_update_nominal:249]: Got /tmp/test-media-cache-WePUEU for second file path 271s END /main/media_cache/ - create_update_nominal Time: <1ms Result: PASS 271s START /main/media_cache/ - exists_off_nominal 271s END /main/media_cache/ - exists_off_nominal Time: <1ms Result: PASS 271s START /main/media_cache/ - exists_nominal 271s END /main/media_cache/ - exists_nominal Time: <1ms Result: PASS 271s START /main/netsock2/ - split_hostport 271s END /main/netsock2/ - split_hostport Time: <1ms Result: PASS 271s START /main/netsock2/ - parsing 271s END /main/netsock2/ - parsing Time: <1ms Result: PASS 271s START /main/optional_api/ - test_provide_last 271s END /main/optional_api/ - test_provide_last Time: <1ms Result: PASS 271s START /main/optional_api/ - test_provide_first 271s END /main/optional_api/ - test_provide_first Time: <1ms Result: PASS 271s START /main/pbx/ - test_MATH_function 271s [func_math.c:test_MATH_function:682]: Testing MATH() substitution ... 271s END /main/pbx/ - test_MATH_function Time: <1ms Result: PASS 271s START /main/pbx/ - test_substitution 271s [test_substitution.c:test_substitution:244]: Testing variable substitution ... 271s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGANI2}' . . . . . passed 271s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGTON}' . . . . . passed 271s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGTNS}' . . . . . passed 271s [test_substitution.c:test_chan_integer_accessor:89]: Tested '${HANGUPCAUSE}' . . . . . passed 271s [test_substitution.c:test_chan_integer_accessor:89]: Tested '${PRIORITY}' . . . . . passed 271s [test_substitution.c:test_chan_string:115]: Tested '${CONTEXT}' . . . . . passed 271s [test_substitution.c:test_chan_string:115]: Tested '${EXTEN}' . . . . . passed 271s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(language)}' . . . . . passed 271s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(musicclass)}' . . . . . passed 271s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(parkinglot)}' . . . . . passed 271s [test_substitution.c:test_chan_variable:144]: Tested '${CALLERID(name)}' . . . . . passed 271s [test_substitution.c:test_chan_variable:144]: Tested '${CURLOPT(proxyuserpwd)}' . . . . . passed 271s [test_substitution.c:test_chan_variable:144]: Tested '${CDR(foo)}' . . . . . passed 271s [test_substitution.c:test_chan_variable:144]: Tested '${ENV(foo)}' . . . . . passed 271s [test_substitution.c:test_chan_variable:144]: Tested '${GLOBAL(foo)}' . . . . . passed 271s [test_substitution.c:test_chan_variable:144]: Tested '${GROUP()}' . . . . . passed 271s [test_substitution.c:test_2way_function:193]: Tested '${AES_ENCRYPT(abcdefghijklmnop,)}' and '${AES_DECRYPT(abcdefghijklmnop,)}' . . . . . passed 271s [test_substitution.c:test_2way_function:193]: Tested '${BASE64_ENCODE()}' and '${BASE64_DECODE()}' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested '123123' ('${foo}${foo}') == '123123' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested 'A123A123A' ('A${foo}A${foo}A') == 'A123A123A' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested 'A123A' ('A${${bar}}A') == 'A123A' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested 'A123A' ('A${${baz}o}A') == 'A123A' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested 'A23A' ('A${${baz}o:1}A') == 'A23A' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:1:1}A') == 'A2A' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:1:-1}A') == 'A2A' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested 'A3A' ('A${${baz}o:-1:1}A') == 'A3A' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:-2:1}A') == 'A2A' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:-2:-1}A') == 'A2A' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested 'cd&ef' ('${LISTFILTER(list1,&,ab)}') == 'cd&ef' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested 'ab&ef' ('${LISTFILTER(list1,&,cd)}') == 'ab&ef' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd' ('${LISTFILTER(list1,&,ef)}') == 'ab&cd' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,gh)}') == 'ab&cd&ef' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,c)}') == 'ab&cd&ef' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,d)}') == 'ab&cd&ef' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested '' ('${LISTFILTER(list2,&,ab)}') == '' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested '' ('${LISTFILTER(list_empty,&,ab)}') == '' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested '123,456' ('${SHELL(printf '%d' 123)},${SHELL(printf '%d' 456)}') == '123,456' . . . . . passed 271s [test_substitution.c:test_expected_result:215]: Tested '123,,456' ('${foo},${CDR(answer)},${SHELL(printf '%d' 456)}') == '123,,456' . . . . . passed 271s [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 271s [test_substitution.c:test_expected_result:215]: Tested '123,,' ('${foo},${this_does_not_exist},${THIS_DOES_NOT_EXIST(either)}') == '123,,' . . . . . passed 271s [test_substitution.c:test_chan_function:168]: Tested '${BLACKLIST(foo)}' . . . . . passed 271s [test_substitution.c:test_chan_function:168]: Tested '${EVAL(foo)}' . . . . . passed 271s [test_substitution.c:test_chan_function:168]: Tested '${FIELDNUM(foo)}' . . . . . passed 271s [test_substitution.c:test_chan_function:168]: Tested '${FIELDQTY(foo)}' . . . . . passed 271s [test_substitution.c:test_chan_function:168]: Tested '${HASHKEYS(foo)}' . . . . . passed 271s [test_substitution.c:test_chan_function:168]: Tested '${IMPORT(foo)}' . . . . . passed 271s [test_substitution.c:test_chan_function:168]: Tested '${PP_EACH_USER(foo)}' . . . . . passed 271s [test_substitution.c:test_chan_function:168]: Tested '${TOLOWER(foo)}' . . . . . passed 271s [test_substitution.c:test_chan_function:168]: Tested '${TOUPPER(foo)}' . . . . . passed 271s END /main/pbx/ - test_substitution Time: 18ms Result: PASS 271s START /main/pbx/ - pattern_match_test 271s [test_pbx.c:test_exten:183]: Successfully matched 200 to exten _2. in context test_pattern with the old pattern match engine 271s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the old pattern match engine 271s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the old pattern match engine 271s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern_include with the old pattern match engine 271s [test_pbx.c:test_exten:183]: Successfully matched 200 to exten _2. in context test_pattern with the new pattern match engine 271s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the new pattern match engine 271s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the new pattern match engine 271s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern_include with the new pattern match engine 271s END /main/pbx/ - pattern_match_test Time: <1ms Result: PASS 271s START /main/pbx/ - variable_substrings 271s END /main/pbx/ - variable_substrings Time: <1ms Result: PASS 271s START /main/poll/ - poll_test 271s [test_poll.c:poll_test:95]: Creating handle that should NEVER block on write 271s [test_poll.c:poll_test:101]: Creating handle that should NEVER block on read 271s [test_poll.c:poll_test:108]: Creating handle that should block on read 271s [test_poll.c:poll_test:168]: Starting thread to ensure we don't block forever 271s [test_poll.c:poll_test:194]: Cancelling failsafe thread. 271s END /main/poll/ - poll_test Time: <1ms Result: PASS 271s START /main/presence/ - channel_presence 271s END /main/presence/ - channel_presence Time: <1ms Result: PASS 271s START /main/sample/ - sample_test 271s [test_skel.c:sample_test:57]: Executing sample test... 271s END /main/sample/ - sample_test Time: <1ms Result: PASS 271s START /main/sched/ - sched_test_freebird 271s [test_sched.c:sched_test_freebird:440]: Received signal, calling Scedule and UNREF 271s [test_sched.c:sched_test_freebird:441]: ID: 1 274s [test_sched.c:sched_test_freebird:448]: Correct number of references '2' 274s END /main/sched/ - sched_test_freebird Time: 3000ms Result: PASS 274s START /main/sched/ - sched_test_order 274s END /main/sched/ - sched_test_order Time: 400ms Result: PASS 274s START /main/sorcery/ - wizard_read_only 274s END /main/sorcery/ - wizard_read_only Time: <1ms Result: PASS 274s START /main/sorcery/ - wizard_observation 274s END /main/sorcery/ - wizard_observation Time: <1ms Result: PASS 274s START /main/sorcery/ - instance_observation 274s END /main/sorcery/ - instance_observation Time: <1ms Result: PASS 274s START /main/sorcery/ - global_observation 274s END /main/sorcery/ - global_observation Time: <1ms Result: PASS 274s START /main/sorcery/ - object_field_registered 274s END /main/sorcery/ - object_field_registered Time: <1ms Result: PASS 274s START /main/sorcery/ - dialplan_function 274s END /main/sorcery/ - dialplan_function Time: <1ms Result: PASS 274s START /main/sorcery/ - configuration_file_wizard_retrieve_multiple_all 274s END /main/sorcery/ - configuration_file_wizard_retrieve_multiple_all Time: <1ms Result: PASS 274s START /main/sorcery/ - configuration_file_wizard_retrieve_multiple 274s END /main/sorcery/ - configuration_file_wizard_retrieve_multiple Time: <1ms Result: PASS 274s START /main/sorcery/ - configuration_file_wizard_retrieve_field 274s END /main/sorcery/ - configuration_file_wizard_retrieve_field Time: <1ms Result: PASS 274s START /main/sorcery/ - configuration_file_wizard_with_criteria 274s END /main/sorcery/ - configuration_file_wizard_with_criteria Time: <1ms Result: PASS 274s START /main/sorcery/ - configuration_file_wizard_with_file_integrity 274s END /main/sorcery/ - configuration_file_wizard_with_file_integrity Time: <1ms Result: PASS 274s START /main/sorcery/ - configuration_file_wizard 274s END /main/sorcery/ - configuration_file_wizard Time: <1ms Result: PASS 274s START /main/sorcery/ - object_type_observer 274s END /main/sorcery/ - object_type_observer Time: <1ms Result: PASS 274s START /main/sorcery/ - caching_wizard_behavior 274s END /main/sorcery/ - caching_wizard_behavior Time: <1ms Result: PASS 274s START /main/sorcery/ - object_is_stale 274s END /main/sorcery/ - object_is_stale Time: <1ms Result: PASS 274s START /main/sorcery/ - object_delete_uncreated 274s END /main/sorcery/ - object_delete_uncreated Time: <1ms Result: PASS 274s START /main/sorcery/ - object_delete 274s END /main/sorcery/ - object_delete Time: <1ms Result: PASS 274s START /main/sorcery/ - object_update_uncreated 274s END /main/sorcery/ - object_update_uncreated Time: <1ms Result: PASS 274s START /main/sorcery/ - object_update 274s END /main/sorcery/ - object_update Time: <1ms Result: PASS 274s START /main/sorcery/ - object_retrieve_regex 274s END /main/sorcery/ - object_retrieve_regex Time: <1ms Result: PASS 274s START /main/sorcery/ - object_retrieve_multiple_field 274s END /main/sorcery/ - object_retrieve_multiple_field Time: <1ms Result: PASS 274s START /main/sorcery/ - object_retrieve_multiple_all 274s END /main/sorcery/ - object_retrieve_multiple_all Time: <1ms Result: PASS 274s START /main/sorcery/ - object_retrieve_field 274s END /main/sorcery/ - object_retrieve_field Time: <1ms Result: PASS 274s START /main/sorcery/ - object_retrieve_id 274s END /main/sorcery/ - object_retrieve_id Time: <1ms Result: PASS 274s START /main/sorcery/ - object_create 274s END /main/sorcery/ - object_create Time: <1ms Result: PASS 274s START /main/sorcery/ - changeset_create_unchanged 274s END /main/sorcery/ - changeset_create_unchanged Time: <1ms Result: PASS 274s START /main/sorcery/ - changeset_create 274s END /main/sorcery/ - changeset_create Time: <1ms Result: PASS 274s START /main/sorcery/ - extended_fields 274s END /main/sorcery/ - extended_fields Time: <1ms Result: PASS 274s START /main/sorcery/ - objectset_apply_fields 274s END /main/sorcery/ - objectset_apply_fields Time: <1ms Result: PASS 274s START /main/sorcery/ - objectset_transform 274s END /main/sorcery/ - objectset_transform Time: <1ms Result: PASS 274s START /main/sorcery/ - objectset_apply_invalid 274s END /main/sorcery/ - objectset_apply_invalid Time: <1ms Result: PASS 274s START /main/sorcery/ - objectset_apply_handler 274s END /main/sorcery/ - objectset_apply_handler Time: <1ms Result: PASS 274s START /main/sorcery/ - objectset_apply 274s END /main/sorcery/ - objectset_apply Time: <1ms Result: PASS 274s START /main/sorcery/ - objectset_create_regex 274s END /main/sorcery/ - objectset_create_regex Time: <1ms Result: PASS 274s START /main/sorcery/ - objectset_json_create 274s END /main/sorcery/ - objectset_json_create Time: <1ms Result: PASS 274s START /main/sorcery/ - objectset_create 274s END /main/sorcery/ - objectset_create Time: <1ms Result: PASS 274s START /main/sorcery/ - object_diff_native 274s END /main/sorcery/ - object_diff_native Time: <1ms Result: PASS 274s START /main/sorcery/ - object_diff 274s END /main/sorcery/ - object_diff Time: <1ms Result: PASS 274s START /main/sorcery/ - object_copy_native 274s END /main/sorcery/ - object_copy_native Time: <1ms Result: PASS 274s START /main/sorcery/ - object_copy 274s END /main/sorcery/ - object_copy Time: <1ms Result: PASS 274s START /main/sorcery/ - object_alloc_without_id 274s END /main/sorcery/ - object_alloc_without_id Time: <1ms Result: PASS 274s START /main/sorcery/ - object_alloc_with_id 274s END /main/sorcery/ - object_alloc_with_id Time: <1ms Result: PASS 274s START /main/sorcery/ - object_fields_register 274s END /main/sorcery/ - object_fields_register Time: <1ms Result: PASS 274s START /main/sorcery/ - object_field_register 274s END /main/sorcery/ - object_field_register Time: <1ms Result: PASS 274s START /main/sorcery/ - object_register_without_mapping 274s END /main/sorcery/ - object_register_without_mapping Time: <1ms Result: PASS 274s START /main/sorcery/ - object_register 274s END /main/sorcery/ - object_register Time: <1ms Result: PASS 274s START /main/sorcery/ - apply_config 274s END /main/sorcery/ - apply_config Time: <1ms Result: PASS 274s START /main/sorcery/ - apply_default 274s END /main/sorcery/ - apply_default Time: <1ms Result: PASS 274s START /main/sorcery/ - open 274s END /main/sorcery/ - open Time: <1ms Result: PASS 274s START /main/sorcery/ - wizard_registration 274s END /main/sorcery/ - wizard_registration Time: <1ms Result: PASS 274s START /main/sorcery/ - wizard_apply_and_insert 274s END /main/sorcery/ - wizard_apply_and_insert Time: <1ms Result: PASS 274s START /main/stdtime/ - time_create_by_unit_str 274s END /main/stdtime/ - time_create_by_unit_str Time: <1ms Result: PASS 274s START /main/stdtime/ - time_create_by_unit 274s END /main/stdtime/ - time_create_by_unit Time: <1ms Result: PASS 274s START /main/stdtime/ - time_str_to_unit 274s END /main/stdtime/ - time_str_to_unit Time: <1ms Result: PASS 274s START /main/stdtime/ - time_tv_to_usec 274s END /main/stdtime/ - time_tv_to_usec Time: <1ms Result: PASS 274s START /main/stdtime/ - timezone_watch 274s [test_time.c:test_timezone_watch:82]: Executing deletion test... 274s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.dxQyyH/test 275s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.dxQyyH/test 275s [test_time.c:test_timezone_watch:82]: Executing symlink test... 275s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.dxQyyH/test 276s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.dxQyyH/test 276s END /main/stdtime/ - timezone_watch Time: 2299ms Result: PASS 276s START /main/stream/ - stream_topology_map_create 276s END /main/stream/ - stream_topology_map_create Time: <1ms Result: PASS 276s START /main/stream/ - format_cap_from_stream_topology 276s END /main/stream/ - format_cap_from_stream_topology Time: <1ms Result: PASS 276s START /main/stream/ - stream_topology_change_request_from_channel 276s END /main/stream/ - stream_topology_change_request_from_channel Time: <1ms Result: PASS 276s START /main/stream/ - stream_topology_change_request_from_application 276s END /main/stream/ - stream_topology_change_request_from_application Time: <1ms Result: PASS 276s START /main/stream/ - stream_topology_change_request_from_channel_non_multistream 276s END /main/stream/ - stream_topology_change_request_from_channel_non_multistream Time: <1ms Result: PASS 276s START /main/stream/ - stream_topology_change_request_from_application_non_multistream 276s END /main/stream/ - stream_topology_change_request_from_application_non_multistream Time: <1ms Result: PASS 276s START /main/stream/ - stream_read_multistream 276s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 276s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 276s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 276s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 276s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 4 Frames: 16 Frames per read: 1 Expected Nulls: 8 276s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 8 276s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 4 Frames: 16 Frames per read: 1 Expected Nulls: 0 276s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 276s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 276s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 276s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 276s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 276s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 4 Frames: 16 Frames per read: 3 Expected Nulls: 8 276s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 8 276s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 4 Frames: 16 Frames per read: 3 Expected Nulls: 0 276s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 276s END /main/stream/ - stream_read_multistream Time: 1ms Result: PASS 276s START /main/stream/ - stream_read_non_multistream 276s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 276s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 276s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 276s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 276s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 276s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 276s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 276s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 276s END /main/stream/ - stream_read_non_multistream Time: <1ms Result: PASS 276s START /main/stream/ - stream_write_multistream 276s END /main/stream/ - stream_write_multistream Time: <1ms Result: PASS 276s START /main/stream/ - stream_write_non_multistream 276s END /main/stream/ - stream_write_non_multistream Time: <1ms Result: PASS 276s START /main/stream/ - stream_topology_channel_set 276s END /main/stream/ - stream_topology_channel_set Time: <1ms Result: PASS 276s START /main/stream/ - stream_topology_create_from_channel_nativeformats 276s END /main/stream/ - stream_topology_create_from_channel_nativeformats Time: <1ms Result: PASS 276s START /main/stream/ - stream_topology_get_first_stream_by_type 276s END /main/stream/ - stream_topology_get_first_stream_by_type Time: <1ms Result: PASS 276s START /main/stream/ - stream_topology_create_from_format_cap 276s END /main/stream/ - stream_topology_create_from_format_cap Time: <1ms Result: PASS 276s START /main/stream/ - stream_topology_del_stream 276s END /main/stream/ - stream_topology_del_stream Time: <1ms Result: PASS 276s START /main/stream/ - stream_topology_set_stream 276s END /main/stream/ - stream_topology_set_stream Time: <1ms Result: PASS 276s START /main/stream/ - stream_topology_append_stream 276s END /main/stream/ - stream_topology_append_stream Time: <1ms Result: PASS 276s START /main/stream/ - stream_topology_clone 276s END /main/stream/ - stream_topology_clone Time: <1ms Result: PASS 276s START /main/stream/ - stream_topology_create 276s END /main/stream/ - stream_topology_create Time: <1ms Result: PASS 276s START /main/stream/ - stream_metadata 276s END /main/stream/ - stream_metadata Time: <1ms Result: PASS 276s START /main/stream/ - stream_set_state 276s END /main/stream/ - stream_set_state Time: <1ms Result: PASS 276s START /main/stream/ - stream_set_formats 276s END /main/stream/ - stream_set_formats Time: <1ms Result: PASS 276s START /main/stream/ - stream_set_type 276s END /main/stream/ - stream_set_type Time: <1ms Result: PASS 276s START /main/stream/ - stream_create_no_name 276s END /main/stream/ - stream_create_no_name Time: <1ms Result: PASS 276s START /main/stream/ - stream_create 276s END /main/stream/ - stream_create Time: <1ms Result: PASS 276s START /main/strings/ - in_delimited_string 276s END /main/strings/ - in_delimited_string Time: <1ms Result: PASS 276s START /main/strings/ - temp_strings 276s END /main/strings/ - temp_strings Time: <1ms Result: PASS 276s START /main/strings/ - strings_match 276s END /main/strings/ - strings_match Time: <1ms Result: PASS 276s START /main/strings/ - escape 276s END /main/strings/ - escape Time: <1ms Result: PASS 276s START /main/strings/ - escape_semicolons 276s END /main/strings/ - escape_semicolons Time: <1ms Result: PASS 276s START /main/strings/ - strsep_quoted 276s END /main/strings/ - strsep_quoted Time: <1ms Result: PASS 276s START /main/strings/ - strsep 276s END /main/strings/ - strsep Time: <1ms Result: PASS 276s START /main/strings/ - ends_with 276s END /main/strings/ - ends_with Time: <1ms Result: PASS 276s START /main/strings/ - begins_with 276s END /main/strings/ - begins_with Time: <1ms Result: PASS 276s START /main/strings/ - str_test 276s END /main/strings/ - str_test Time: <1ms Result: PASS 276s START /main/taskprocessor/ - serializer_pool 280s END /main/taskprocessor/ - serializer_pool Time: 4001ms Result: PASS 280s START /main/taskprocessor/ - taskprocessor_push_local 280s END /main/taskprocessor/ - taskprocessor_push_local Time: <1ms Result: PASS 280s START /main/taskprocessor/ - taskprocessor_shutdown 280s END /main/taskprocessor/ - taskprocessor_shutdown Time: <1ms Result: PASS 280s START /main/taskprocessor/ - taskprocessor_listener 280s END /main/taskprocessor/ - taskprocessor_listener Time: <1ms Result: PASS 280s START /main/taskprocessor/ - subsystem_alert 280s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 1 280s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 2 280s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 3 280s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 4 280s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 5 280s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 6 280s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 7 280s [test_taskprocessor.c:subsystem_alert:237]: Subsystem alert triggered correctly at 6 280s [test_taskprocessor.c:subsystem_alert:240]: Global alert triggered correctly at 6 280s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 8 280s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 9 280s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 10 280s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 1 281s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 2 281s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 3 282s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 4 282s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 5 283s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 6 283s [test_taskprocessor.c:subsystem_alert:279]: Subsystem alert cleared correctly at 3 283s [test_taskprocessor.c:subsystem_alert:282]: Global alert cleared correctly at 3 283s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 7 284s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 8 284s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 9 285s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 10 285s END /main/taskprocessor/ - subsystem_alert Time: 5001ms Result: PASS 285s START /main/taskprocessor/ - default_taskprocessor_load 285s END /main/taskprocessor/ - default_taskprocessor_load Time: 43ms Result: PASS 285s START /main/taskprocessor/ - default_taskprocessor 285s END /main/taskprocessor/ - default_taskprocessor Time: <1ms Result: PASS 285s START /main/test/ - registrations 285s END /main/test/ - registrations Time: <1ms Result: PASS 285s START /main/test_capture/ - test_capture_false 285s [test_capture.c:test_capture_false:120]: Executing false exit test... 285s END /main/test_capture/ - test_capture_false Time: 18ms Result: PASS 285s START /main/test_capture/ - test_capture_true 285s [test_capture.c:test_capture_true:61]: Executing true exit test... 285s END /main/test_capture/ - test_capture_true Time: 16ms Result: PASS 285s START /main/test_capture/ - test_capture_stdout_stderr 285s [test_capture.c:test_capture_stdout_stderr:318]: Executing stdout/stderr test... 285s END /main/test_capture/ - test_capture_stdout_stderr Time: 16ms Result: PASS 285s START /main/test_capture/ - test_capture_with_dynamic 285s [test_capture.c:test_capture_with_dynamic:249]: Executing dynamic argument test... 285s END /main/test_capture/ - test_capture_with_dynamic Time: 16ms Result: PASS 285s START /main/test_capture/ - test_capture_with_stdin 285s [test_capture.c:test_capture_with_stdin:183]: Executing stdin test... 285s END /main/test_capture/ - test_capture_with_stdin Time: 18ms Result: PASS 285s START /main/threadpool/ - threadpool_serializer_dupe 285s END /main/threadpool/ - threadpool_serializer_dupe Time: <1ms Result: PASS 285s START /main/threadpool/ - threadpool_serializer 286s END /main/threadpool/ - threadpool_serializer Time: 1001ms Result: PASS 286s START /main/threadpool/ - more_destruction 286s END /main/threadpool/ - more_destruction Time: 1ms Result: PASS 286s START /main/threadpool/ - task_distribution 286s END /main/threadpool/ - task_distribution Time: <1ms Result: PASS 286s START /main/threadpool/ - reactivation 286s END /main/threadpool/ - reactivation Time: <1ms Result: PASS 286s START /main/threadpool/ - max_size 286s END /main/threadpool/ - max_size Time: <1ms Result: PASS 286s START /main/threadpool/ - auto_increment 286s END /main/threadpool/ - auto_increment Time: <1ms Result: PASS 286s START /main/threadpool/ - one_thread_multiple_tasks 287s END /main/threadpool/ - one_thread_multiple_tasks Time: <1ms Result: PASS 287s START /main/threadpool/ - one_thread_one_task 287s END /main/threadpool/ - one_thread_one_task Time: <1ms Result: PASS 287s START /main/threadpool/ - one_task_one_thread 287s END /main/threadpool/ - one_task_one_thread Time: <1ms Result: PASS 287s START /main/threadpool/ - thread_timeout_thrash 317s END /main/threadpool/ - thread_timeout_thrash Time: 31018ms Result: PASS 317s START /main/threadpool/ - thread_timeout 319s END /main/threadpool/ - thread_timeout Time: 2000ms Result: PASS 319s START /main/threadpool/ - thread_destruction 319s END /main/threadpool/ - thread_destruction Time: 1ms Result: PASS 319s START /main/threadpool/ - thread_creation 319s END /main/threadpool/ - thread_creation Time: <1ms Result: PASS 319s START /main/threadpool/ - initial_threads 319s END /main/threadpool/ - initial_threads Time: <1ms Result: PASS 319s START /main/threadpool/ - push 319s END /main/threadpool/ - push Time: <1ms Result: PASS 319s START /main/uri/ - uri_default_http_secure 319s END /main/uri/ - uri_default_http_secure Time: <1ms Result: PASS 319s START /main/uri/ - uri_default_http 319s END /main/uri/ - uri_default_http Time: <1ms Result: PASS 320s START /main/uri/ - uri_parse 320s END /main/uri/ - uri_parse Time: <1ms Result: PASS 320s START /main/utf8/ - replace_invalid 320s END /main/utf8/ - replace_invalid Time: <1ms Result: PASS 320s START /main/utf8/ - utf8_validator 320s END /main/utf8/ - utf8_validator Time: <1ms Result: PASS 320s START /main/utf8/ - copy_string 320s END /main/utf8/ - copy_string Time: <1ms Result: PASS 320s START /main/utf8/ - is_valid 320s END /main/utf8/ - is_valid Time: <1ms Result: PASS 320s START /main/utils/ - string_field_aggregate_test 320s [test_stringfields.c:string_field_aggregate_test:392]: Structures 3 embedded pool initialized successfully. 320s [test_stringfields.c:string_field_aggregate_test:410]: Structures 3 additional pool initialized successfully. 320s [test_stringfields.c:string_field_aggregate_test:422]: Structures 1/2 are equal as expected. 320s [test_stringfields.c:string_field_aggregate_test:430]: Structures 1/3 are different as expected. 320s [test_stringfields.c:string_field_aggregate_test:438]: Structures 2/3 are different as expected. 320s [test_stringfields.c:string_field_aggregate_test:446]: Structures 3/4 are different as expected. 320s [test_stringfields.c:string_field_aggregate_test:454]: Copying from structure 3 to structure 1 succeeded! 320s [test_stringfields.c:string_field_aggregate_test:463]: Structures 1/3 are equal as expected. 320s [test_stringfields.c:string_field_aggregate_test:470]: Structures 1/2 are different as expected. 320s [test_stringfields.c:string_field_aggregate_test:473]: Reset but don't free. 320s [test_stringfields.c:string_field_aggregate_test:484]: Structures 1/2 are the same (empty) as expected. 320s [test_stringfields.c:string_field_aggregate_test:492]: Structure 4 embedded pool is the current pool as expected. 320s [test_stringfields.c:string_field_aggregate_test:500]: Structure 4 embedded pool does not have a previous as expected. 320s END /main/utils/ - string_field_aggregate_test Time: <1ms Result: PASS 320s START /main/utils/ - string_field_test 320s [test_stringfields.c:string_field_test:79]: First things first. Let's see if we can actually allocate string fields 320s [test_stringfields.c:string_field_test:85]: All right! Successfully allocated! Now let's get down to business 320s [test_stringfields.c:string_field_test:89]: We're going to set some string fields and perform some checks 320s [test_stringfields.c:string_field_test:94]: First we're going to make sure that the strings are actually set to what we expect 320s [test_stringfields.c:string_field_test:100]: test_struct.string1 appears to be all clear. It has 'elephant' and that's what we expect 320s [test_stringfields.c:string_field_test:107]: test_struct.string2 appears to be all clear. It has 'hippopotamus' and that's what we expect 320s [test_stringfields.c:string_field_test:110]: Now let's make sure that our recorded capacities for these strings is what we expect 320s [test_stringfields.c:string_field_test:117]: string1 has the allocation area we expect: 9 320s [test_stringfields.c:string_field_test:125]: string2 has the allocation area we expect: 13 320s [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 320s [test_stringfields.c:string_field_test:137]: string1 successfully was changed to 'rhino' 320s [test_stringfields.c:string_field_test:144]: Shrinking string1 allowed it to stay in the same place in memory 320s [test_stringfields.c:string_field_test:151]: Shrinking string1 did not change its allocation area (This is a good thing) 320s [test_stringfields.c:string_field_test:154]: Next, let's increase it a little but not all the way to its original size 320s [test_stringfields.c:string_field_test:163]: string1 successfully was changed to 'mammoth' 320s [test_stringfields.c:string_field_test:170]: Expanding string1 allowed it to stay in the same place in memory 320s [test_stringfields.c:string_field_test:177]: Expanding string1 did not change its allocation area (This is a good thing) 320s [test_stringfields.c:string_field_test:180]: Cool, now let's bring it back to its original size and see what happens 320s [test_stringfields.c:string_field_test:188]: string1 successfully changed to 'elephant' 320s [test_stringfields.c:string_field_test:195]: Restoring string1 did not cause it to move (This is a good thing) 320s [test_stringfields.c:string_field_test:202]: The allocation amount for string1 is still holding steady 320s [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 320s [test_stringfields.c:string_field_test:214]: string2 successfully changed to 'hippopotamus face' 320s [test_stringfields.c:string_field_test:222]: The allocation amount successfully increased for string2 when it grew 320s [test_stringfields.c:string_field_test:229]: string2 stayed in place when it grew. Good job! 320s [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 320s [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' 320s [test_stringfields.c:string_field_test:248]: Good. Setting string1 to a long value caused it to change addresses 320s [test_stringfields.c:string_field_test:256]: The stored allocation size of string1 is what we expect 320s [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 320s [test_stringfields.c:string_field_test:281]: Three different pools are linked as expected. 320s [test_stringfields.c:string_field_test:289]: After removing a pool the remaining two are linked as expected. 320s END /main/utils/ - string_field_test Time: <1ms Result: PASS 320s START /main/utils/ - quote_unescaping 320s END /main/utils/ - quote_unescaping Time: <1ms Result: PASS 320s START /main/utils/ - quote_mutation 320s END /main/utils/ - quote_mutation Time: <1ms Result: PASS 320s START /main/utils/ - crypt_test 320s END /main/utils/ - crypt_test Time: 10ms Result: PASS 320s START /main/utils/ - safe_mkdir_test 320s END /main/utils/ - safe_mkdir_test Time: 1ms Result: PASS 320s START /main/utils/ - base64_test 320s END /main/utils/ - base64_test Time: <1ms Result: PASS 320s START /main/utils/ - sha1_test 320s [test_utils.c:sha1_test:250]: Testing SHA1 ... 320s END /main/utils/ - sha1_test Time: <1ms Result: PASS 320s START /main/utils/ - md5_test 320s [test_utils.c:md5_test:205]: Testing MD5 ... 320s END /main/utils/ - md5_test Time: <1ms Result: PASS 320s START /main/utils/ - quoted_escape_test 320s END /main/utils/ - quoted_escape_test Time: <1ms Result: PASS 320s START /main/utils/ - uri_encode_decode_test 320s END /main/utils/ - uri_encode_decode_test Time: <1ms Result: PASS 320s START /main/uuid/ - uuid 320s [test_uuid.c:uuid:59]: Generate UUID direct to string, got 75964497-c694-4510-8d35-3e64ed10db64 320s [test_uuid.c:uuid:90]: Second generated UUID converted to string, got e721896a-f035-4606-94af-ce7a84c08f6d 320s END /main/uuid/ - uuid Time: <1ms Result: PASS 320s START /main/vector/ - basic 320s END /main/vector/ - basic Time: <1ms Result: PASS 320s START /main/vector/ - basic_integer 320s END /main/vector/ - basic_integer Time: <1ms Result: PASS 320s START /main/vector/ - callbacks 320s END /main/vector/ - callbacks Time: <1ms Result: PASS 320s START /main/vector/ - locks 320s END /main/vector/ - locks Time: <1ms Result: PASS 320s START /main/voicemail_api/ - off_nominal_msg_playback 320s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1495]: Created message in test_vm_api_1234/Old with ID 1730456076-909401725 320s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1495]: Created message in test_vm_api_1234/INBOX with ID 1730456076-960311778 320s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1495]: Created message in test_vm_api_2345/INBOX with ID 1730456076-1500739833 320s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1495]: Created message in test_vm_api_2345/INBOX with ID 1730456076-719848782 320s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1504]: Playing back message from invalid mailbox 320s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1507]: Playing back message from NULL mailbox 320s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1510]: Playing back message from invalid context 320s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1513]: Playing back message from invalid folder 320s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1516]: Playing back message from NULL folder 320s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1519]: Playing back message with invalid message specifier 320s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1522]: Playing back message with NULL message specifier 320s END /main/voicemail_api/ - off_nominal_msg_playback Time: 7ms Result: PASS 320s START /main/voicemail_api/ - nominal_msg_playback 320s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1433]: Created message in test_vm_api_1234/Old with ID 1730456076-909401725 320s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1433]: Created message in test_vm_api_1234/INBOX with ID 1730456076-960311778 320s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1433]: Created message in test_vm_api_2345/INBOX with ID 1730456076-1500739833 320s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1433]: Created message in test_vm_api_2345/INBOX with ID 1730456076-719848782 320s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1445]: Playing back message from test_vm_api_1234 to mock channel 320s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1448]: Playing back message from test_vm_api_2345 to callback function 320s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1453]: Playing back message from test_vm_api_2345 to callback function with default context 320s END /main/voicemail_api/ - nominal_msg_playback Time: 452ms Result: PASS 320s START /main/voicemail_api/ - off_nominal_forward 320s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1355]: Created message in test_vm_api_1234/Old with ID 1730456077-909401725 320s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1355]: Created message in test_vm_api_1234/INBOX with ID 1730456077-960311778 320s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1355]: Created message in test_vm_api_2345/INBOX with ID 1730456077-1500739833 320s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1355]: Created message in test_vm_api_2345/INBOX with ID 1730456077-719848782 320s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1364]: Test forwarding from an invalid mailbox 320s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1367]: Test forwarding from a NULL mailbox 320s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1370]: Test forwarding from an invalid context 320s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1373]: Test forwarding from an invalid folder 320s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1376]: Test forwarding from a NULL folder 320s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1379]: Test forwarding to an invalid mailbox 320s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1382]: Test forwarding to a NULL mailbox 320s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1385]: Test forwarding to an invalid context 320s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1388]: Test forwarding to an invalid folder 320s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1392]: Test forwarding to a NULL folder 320s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1395]: Test forwarding when no messages are select 320s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1398]: Test forwarding a message that doesn't exist 320s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1402]: Test forwarding multiple messages, where some messages don't exist 320s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1405]: Test forwarding a message with an invalid size specifier 320s END /main/voicemail_api/ - off_nominal_forward Time: 7ms Result: PASS 320s START /main/voicemail_api/ - nominal_forward 320s [test_voicemail_api.c:voicemail_api_nominal_forward:1239]: Created message in test_vm_api_1234/Old with ID 1730456077-909401725 320s [test_voicemail_api.c:voicemail_api_nominal_forward:1239]: Created message in test_vm_api_1234/INBOX with ID 1730456077-960311778 320s [test_voicemail_api.c:voicemail_api_nominal_forward:1239]: Created message in test_vm_api_2345/INBOX with ID 1730456077-1500739833 320s [test_voicemail_api.c:voicemail_api_nominal_forward:1239]: Created message in test_vm_api_2345/INBOX with ID 1730456077-719848782 320s [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 320s [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 320s [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 320s [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 320s [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 320s END /main/voicemail_api/ - nominal_forward Time: 22ms Result: PASS 320s START /main/voicemail_api/ - off_nominal_remove 320s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1180]: Created message in test_vm_api_1234/Old with ID 1730456077-909401725 320s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1180]: Created message in test_vm_api_1234/INBOX with ID 1730456077-960311778 320s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1180]: Created message in test_vm_api_2345/INBOX with ID 1730456077-1500739833 320s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1180]: Created message in test_vm_api_2345/INBOX with ID 1730456077-719848782 320s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1186]: Test removing a single message with an invalid mailbox 320s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1189]: Test removing a single message with a NULL mailbox 320s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1192]: Test removing a single message with an invalid context 320s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1195]: Test removing a single message with an invalid folder 320s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1198]: Test removing a single message with a NULL folder 320s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1201]: Test removing a single message with an invalid message number 320s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1205]: Test removing multiple messages with a single invalid message number 320s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1209]: Test removing no messages with no message numbers 320s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1212]: Test removing multiple messages with an invalid size specifier 320s END /main/voicemail_api/ - off_nominal_remove Time: 6ms Result: PASS 320s START /main/voicemail_api/ - nominal_remove 320s [test_voicemail_api.c:voicemail_api_nominal_remove:1133]: Created message in test_vm_api_1234/Old with ID 1730456077-909401725 320s [test_voicemail_api.c:voicemail_api_nominal_remove:1133]: Created message in test_vm_api_1234/INBOX with ID 1730456077-960311778 320s [test_voicemail_api.c:voicemail_api_nominal_remove:1133]: Created message in test_vm_api_2345/INBOX with ID 1730456077-1500739833 320s [test_voicemail_api.c:voicemail_api_nominal_remove:1133]: Created message in test_vm_api_2345/INBOX with ID 1730456077-719848782 320s [test_voicemail_api.c:voicemail_api_nominal_remove:1141]: Test removing a single message from INBOX 320s [test_voicemail_api.c:voicemail_api_nominal_remove:1144]: Test removing a single message from Old 320s [test_voicemail_api.c:voicemail_api_nominal_remove:1147]: Test removing multiple messages from INBOX 320s END /main/voicemail_api/ - nominal_remove Time: 7ms Result: PASS 320s START /main/voicemail_api/ - off_nominal_move 320s [test_voicemail_api.c:voicemail_api_off_nominal_move:1061]: Created message in test_vm_api_1234/Old with ID 1730456077-909401725 320s [test_voicemail_api.c:voicemail_api_off_nominal_move:1061]: Created message in test_vm_api_1234/INBOX with ID 1730456077-960311778 320s [test_voicemail_api.c:voicemail_api_off_nominal_move:1061]: Created message in test_vm_api_2345/INBOX with ID 1730456077-1500739833 320s [test_voicemail_api.c:voicemail_api_off_nominal_move:1061]: Created message in test_vm_api_2345/INBOX with ID 1730456077-719848782 320s [test_voicemail_api.c:voicemail_api_off_nominal_move:1070]: Test move attempt for invalid mailbox test_vm_3456 320s [test_voicemail_api.c:voicemail_api_off_nominal_move:1075]: Test move attempt for invalid context test_vm_api_defunct 320s [test_voicemail_api.c:voicemail_api_off_nominal_move:1078]: Test move attempt to invalid folder 320s [test_voicemail_api.c:voicemail_api_off_nominal_move:1081]: Test move attempt from invalid folder 320s [test_voicemail_api.c:voicemail_api_off_nominal_move:1084]: Test move attempt to NULL folder 320s [test_voicemail_api.c:voicemail_api_off_nominal_move:1087]: Test move attempt from NULL folder 320s [test_voicemail_api.c:voicemail_api_off_nominal_move:1090]: Test move attempt with non-existent message number 320s [test_voicemail_api.c:voicemail_api_off_nominal_move:1094]: Test move attempt with invalid message number 320s [test_voicemail_api.c:voicemail_api_off_nominal_move:1098]: Test move attempt with 0 number of messages 320s [test_voicemail_api.c:voicemail_api_off_nominal_move:1102]: Test move attempt with invalid number of messages 320s [test_voicemail_api.c:voicemail_api_off_nominal_move:1105]: Test move attempt with non-existent multiple messages, where some messages exist 320s END /main/voicemail_api/ - off_nominal_move Time: 6ms Result: PASS 320s START /main/voicemail_api/ - nominal_move 320s [test_voicemail_api.c:voicemail_api_nominal_move:987]: Created message in test_vm_api_1234/Old with ID 1730456077-909401725 320s [test_voicemail_api.c:voicemail_api_nominal_move:987]: Created message in test_vm_api_1234/INBOX with ID 1730456077-960311778 320s [test_voicemail_api.c:voicemail_api_nominal_move:987]: Created message in test_vm_api_2345/INBOX with ID 1730456077-1500739833 320s [test_voicemail_api.c:voicemail_api_nominal_move:987]: Created message in test_vm_api_2345/INBOX with ID 1730456077-719848782 320s [test_voicemail_api.c:voicemail_api_nominal_move:994]: Test move of test_vm_api_1234 message from INBOX to Family 320s [test_voicemail_api.c:voicemail_api_nominal_move:997]: Test move of test_vm_api_1234 message from Old to Family 320s [test_voicemail_api.c:voicemail_api_nominal_move:1011]: Test move of test_vm_api_2345 messages from Inbox to Family 320s [test_voicemail_api.c:voicemail_api_nominal_move:1022]: Test move of test_vm_api_2345 message from Family to INBOX 320s END /main/voicemail_api/ - nominal_move Time: 10ms Result: PASS 320s START /main/voicemail_api/ - off_nominal_snapshot 320s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:947]: Created message in test_vm_api_1234/Old with ID 1730456077-909401725 320s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:947]: Created message in test_vm_api_1234/INBOX with ID 1730456077-960311778 320s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:947]: Created message in test_vm_api_2345/INBOX with ID 1730456077-1500739833 320s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:947]: Created message in test_vm_api_2345/INBOX with ID 1730456077-719848782 320s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:949]: Test access to non-existent mailbox test_vm_api_3456 320s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:952]: Test access to null mailbox 320s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:955]: Test access non-existent context test_vm_api_defunct 320s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:958]: Test non-existent folder test_vm_api_platypus 320s END /main/voicemail_api/ - off_nominal_snapshot Time: 5ms Result: PASS 320s START /main/voicemail_api/ - nominal_snapshot 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:856]: Created message in test_vm_api_1234/Old with ID 1730456077-909401725 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:856]: Created message in test_vm_api_1234/INBOX with ID 1730456077-960311778 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:856]: Created message in test_vm_api_2345/INBOX with ID 1730456077-1500739833 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:856]: Created message in test_vm_api_2345/INBOX with ID 1730456077-719848782 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:858]: Test retrieving message 1 from INBOX of test_vm_1234 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:861]: Found message 1730456077-960311778 in snapshot 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:864]: Test retrieving message 0 from Old of test_vm_1234 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:867]: Found message 1730456077-909401725 in snapshot 320s [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 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:873]: Found message 1730456077-909401725 in snapshot 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:874]: Found message 1730456077-960311778 in snapshot 320s [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 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:880]: Found message 1730456077-960311778 in snapshot 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:881]: Found message 1730456077-909401725 in snapshot 320s [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 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:887]: Found message 1730456077-960311778 in snapshot 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:888]: Found message 1730456077-909401725 in snapshot 320s [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 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:894]: Found message 1730456077-909401725 in snapshot 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:895]: Found message 1730456077-960311778 in snapshot 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:898]: Test retrieving message 0, 1 from all folders of test_vm_1234 ordered by id 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:901]: Found message 1730456077-909401725 in snapshot 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:902]: Found message 1730456077-960311778 in snapshot 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:905]: Test retrieving message 0, 1 from all folders of test_vm_1234 ordered by time 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:908]: Found message 1730456077-909401725 in snapshot 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:909]: Found message 1730456077-960311778 in snapshot 320s [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 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:915]: Found message 1730456077-909401725 in snapshot 320s [test_voicemail_api.c:voicemail_api_nominal_snapshot:916]: Found message 1730456077-960311778 in snapshot 320s END /main/voicemail_api/ - nominal_snapshot Time: 14ms Result: PASS 320s START /main/xml_escape/ - xml_escape_test 320s END /main/xml_escape/ - xml_escape_test Time: <1ms Result: PASS 320s START /mwi/ - explicit_publish 320s END /mwi/ - explicit_publish Time: 73ms Result: PASS 320s START /mwi/ - implicit_publish 320s END /mwi/ - implicit_publish Time: 70ms Result: PASS 320s START /res/adsi/ - adsi_loaded_test 320s END /res/adsi/ - adsi_loaded_test Time: <1ms Result: PASS 320s START /res/aeap/ - send_msg_handle_request 320s END /res/aeap/ - send_msg_handle_request Time: 1ms Result: PASS 320s START /res/aeap/ - send_msg_handle_response 320s END /res/aeap/ - send_msg_handle_response Time: 1ms Result: PASS 320s START /res/aeap/ - send_msg_handle_string 322s END /res/aeap/ - send_msg_handle_string Time: 2000ms Result: PASS 322s START /res/aeap/ - create_and_connect 322s END /res/aeap/ - create_and_connect Time: <1ms Result: PASS 322s START /res/aeap/speech/ - res_speech_aeap_test 322s END /res/aeap/speech/ - res_speech_aeap_test Time: 2ms Result: PASS 322s START /res/aeap/transaction/ - transaction_exec_timeout 322s END /res/aeap/transaction/ - transaction_exec_timeout Time: 99ms Result: PASS 322s START /res/aeap/transaction/ - transaction_exec 323s END /res/aeap/transaction/ - transaction_exec Time: 1000ms Result: PASS 323s START /res/aeap/transport/ - transport_create_invalid 323s END /res/aeap/transport/ - transport_create_invalid Time: <1ms Result: PASS 323s START /res/aeap/transport/ - transport_create 323s END /res/aeap/transport/ - transport_create Time: <1ms Result: PASS 323s START /res/aeap/transport/ - transport_connect 323s END /res/aeap/transport/ - transport_connect Time: <1ms Result: PASS 323s START /res/aeap/transport/ - transport_connect_fail 323s END /res/aeap/transport/ - transport_connect_fail Time: 1ms Result: PASS 323s START /res/aeap/transport/ - transport_binary 323s END /res/aeap/transport/ - transport_binary Time: <1ms Result: PASS 323s START /res/aeap/transport/ - transport_string 323s END /res/aeap/transport/ - transport_string Time: 1ms Result: PASS 323s START /res/agi/ - agi_loaded_test 323s END /res/agi/ - agi_loaded_test Time: 3ms Result: PASS 323s START /res/agi/ - null_agi_docs 323s END /res/agi/ - null_agi_docs Time: <1ms Result: PASS 323s START /res/ari/ - invoke_not_found 323s END /res/ari/ - invoke_not_found Time: <1ms Result: PASS 323s START /res/ari/ - invoke_bad_post 323s END /res/ari/ - invoke_bad_post Time: <1ms Result: PASS 323s START /res/ari/ - invoke_post 323s END /res/ari/ - invoke_post Time: <1ms Result: PASS 323s START /res/ari/ - invoke_delete 323s END /res/ari/ - invoke_delete Time: <1ms Result: PASS 323s START /res/ari/ - invoke_wildcard 323s END /res/ari/ - invoke_wildcard Time: <1ms Result: PASS 323s START /res/ari/ - invoke_get 323s END /res/ari/ - invoke_get Time: <1ms Result: PASS 323s START /res/ari/ - get_docs_hackerz 323s END /res/ari/ - get_docs_hackerz Time: <1ms Result: PASS 323s START /res/ari/ - get_docs_notfound 323s END /res/ari/ - get_docs_notfound Time: <1ms Result: PASS 323s START /res/ari/ - get_docs_nohost 323s END /res/ari/ - get_docs_nohost Time: <1ms Result: PASS 323s START /res/ari/ - get_docs 323s END /res/ari/ - get_docs Time: <1ms Result: PASS 323s START /res/crypto/ - crypto_loaded_test 323s END /res/crypto/ - crypto_loaded_test Time: <1ms Result: PASS 323s START /res/http_media_cache/ - retrieve_content_type 323s END /res/http_media_cache/ - retrieve_content_type Time: 6ms Result: PASS 323s START /res/http_media_cache/ - retrieve_parsed_uri 323s END /res/http_media_cache/ - retrieve_parsed_uri Time: 1ms Result: PASS 323s START /res/http_media_cache/ - retrieve_cache_control_directives 323s [test_http_media_cache.c:retrieve_cache_control_directives:322]: Testing no-cache... 323s [test_http_media_cache.c:retrieve_cache_control_directives:329]: Testing no-cache with ETag... 323s [test_http_media_cache.c:retrieve_cache_control_directives:339]: Testing no-cache with max-age... 323s [test_http_media_cache.c:retrieve_cache_control_directives:344]: Checking 1730456383 >= 1730456380 and 1730456377 <= 1730456380 323s [test_http_media_cache.c:retrieve_cache_control_directives:351]: Testing must-revalidate... 323s [test_http_media_cache.c:retrieve_cache_control_directives:358]: Testing must-revalidate with ETag... 323s [test_http_media_cache.c:retrieve_cache_control_directives:368]: Testing must-revalidate with max-age... 323s [test_http_media_cache.c:retrieve_cache_control_directives:373]: Checking 1730456383 >= 1730456380 and 1730456377 <= 1730456380 323s END /res/http_media_cache/ - retrieve_cache_control_directives Time: 10ms Result: PASS 323s START /res/http_media_cache/ - retrieve_cache_control_age 323s [test_http_media_cache.c:retrieve_cache_control_age:406]: Testing max-age... 323s [test_http_media_cache.c:retrieve_cache_control_age:410]: Checking 1730456383 >= 1730456380 and 1730456377 <= 1730456380 323s [test_http_media_cache.c:retrieve_cache_control_age:414]: Testing s-maxage... 323s [test_http_media_cache.c:retrieve_cache_control_age:420]: Checking 1730456383 >= 1730456380 and 1730456377 <= 1730456380 323s [test_http_media_cache.c:retrieve_cache_control_age:424]: Testing max-age and s-maxage... 323s [test_http_media_cache.c:retrieve_cache_control_age:430]: Checking 1730456683 >= 1730456680 and 1730456677 <= 1730456680 323s [test_http_media_cache.c:retrieve_cache_control_age:434]: Testing max-age and Expires... 323s [test_http_media_cache.c:retrieve_cache_control_age:441]: Checking 1730456383 >= 1730456380 and 1730456377 <= 1730456380 323s [test_http_media_cache.c:retrieve_cache_control_age:445]: Testing s-maxage and Expires... 323s [test_http_media_cache.c:retrieve_cache_control_age:452]: Checking 1730456383 >= 1730456380 and 1730456377 <= 1730456380 323s [test_http_media_cache.c:retrieve_cache_control_age:456]: Testing s-maxage and Expires... 323s [test_http_media_cache.c:retrieve_cache_control_age:463]: Checking 1730456383 >= 1730456380 and 1730456377 <= 1730456380 323s [test_http_media_cache.c:retrieve_cache_control_age:467]: Testing max-age, s-maxage, and Expires... 323s [test_http_media_cache.c:retrieve_cache_control_age:474]: Checking 1730456683 >= 1730456680 and 1730456677 <= 1730456680 323s END /res/http_media_cache/ - retrieve_cache_control_age Time: 10ms Result: PASS 323s START /res/http_media_cache/ - retrieve_etag_expired 323s [test_http_media_cache.c:retrieve_etag_expired:514]: Checking 1730456082 >= 1730456079 and 1730456076 <= 1730456079 323s END /res/http_media_cache/ - retrieve_etag_expired Time: 2ms Result: PASS 323s START /res/http_media_cache/ - retrieve_expires 323s [test_http_media_cache.c:retrieve_expires:554]: Checking 1730459083 >= 1730459080 and 1730459077 <= 1730459080 323s [test_http_media_cache.c:retrieve_expires:564]: Checking 1730456082 >= 1730456079 and 1730456076 <= 1730456079 323s END /res/http_media_cache/ - retrieve_expires Time: 2ms Result: PASS 323s START /res/http_media_cache/ - retrieve_etag 323s [test_http_media_cache.c:retrieve_etag:604]: Checking 1730456083 >= 1730456080 and 1730456077 <= 1730456080 323s END /res/http_media_cache/ - retrieve_etag Time: 2ms Result: PASS 323s START /res/http_media_cache/ - retrieve_nominal 323s [test_http_media_cache.c:retrieve_nominal:642]: Checking 1730456083 >= 1730456080 and 1730456077 <= 1730456080 323s END /res/http_media_cache/ - retrieve_nominal Time: 1ms Result: PASS 323s START /res/http_media_cache/ - create_nominal 323s [test_http_media_cache.c:create_nominal:675]: Checking 1730456083 >= 1730456080 and 1730456077 <= 1730456080 323s END /res/http_media_cache/ - create_nominal Time: 1ms Result: PASS 323s START /res/parking/ - dynamic_parking_variables 323s [parking/parking_tests.c:dynamic_parking_variables:756]: Creating expected configuration for dynamic parking lot 323s [parking/parking_tests.c:dynamic_parking_variables:775]: Creating template lot 323s [parking/parking_tests.c:dynamic_parking_variables:784]: Creating Alice channel to test dynamic parking lot creation. 323s [parking/parking_tests.c:dynamic_parking_variables:794]: Setting Dynamic Parking channel variables on Alice. 323s [parking/parking_tests.c:dynamic_parking_variables:802]: Generating dynamic parking lot based on Alice's channel variables. 323s [parking/parking_tests.c:dynamic_parking_variables:819]: Dynamic parking lot created successfully and matches expectations. Test passed. 323s END /res/parking/ - dynamic_parking_variables Time: <1ms Result: PASS 323s START /res/parking/ - extension_conflicts 323s [parking/parking_tests.c:extension_conflicts:597]: Creating the base lot. This should pass. 323s [parking/parking_tests.c:extension_conflicts:607]: Creating a test lot which will overlap. 323s [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. 323s [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. 323s [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. 323s [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. 323s END /res/parking/ - extension_conflicts Time: <1ms Result: PASS 323s START /res/parking/ - park_extensions 323s [parking/parking_tests.c:park_extensions:551]: Extensions for the test parking lot were verified. Cleaning up and verifying their removal. 323s [parking/parking_tests.c:park_extensions:565]: Extensions for the test parking lot verified as removed. Test completed successfully. 323s END /res/parking/ - park_extensions Time: <1ms Result: PASS 323s START /res/parking/ - park_retrieve 323s [parking/parking_tests.c:retrieve_call:405]: Creating test parking lot 'unit_tests_res_parking_test_lot' 324s [parking/parking_tests.c:retrieve_call:446]: Successfully retrieved parked user from the parking lot. Validating user data. 324s END /res/parking/ - park_retrieve Time: 1001ms Result: PASS 324s START /res/parking/ - park_channel 324s [parking/parking_tests.c:park_call:254]: Creating test parking lot 'unit_tests_res_parking_test_lot' 325s END /res/parking/ - park_channel Time: 1001ms Result: PASS 325s START /res/parking/ - create_lot 325s [parking/parking_tests.c:create_lot:206]: Creating test parking lot 'unit_tests_res_parking_test_lot' 325s [parking/parking_tests.c:create_lot:214]: Successfully created parking lot. Retrieving test parking lot from container. 325s [parking/parking_tests.c:create_lot:223]: Successfully retrieved parking lot. Removing test parking lot from container. 325s [parking/parking_tests.c:create_lot:229]: Parking lot was successfully removed from the container. Test complete. 325s END /res/parking/ - create_lot Time: <1ms Result: PASS 325s START /res/prometheus/ - bridge_to_string 325s [test_res_prometheus.c:bridge_to_string:760]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 325s # TYPE asterisk_channels_count gauge 325s asterisk_channels_count{eid="fa:16:3e:2b:1a:0c"} 0 325s # HELP asterisk_calls_sum Total call count. 325s # TYPE asterisk_calls_sum counter 325s asterisk_calls_sum{eid="fa:16:3e:2b:1a:0c"} 0 325s # HELP asterisk_calls_count Current call count. 325s # TYPE asterisk_calls_count gauge 325s asterisk_calls_count{eid="fa:16:3e:2b:1a:0c"} 0 325s # HELP asterisk_endpoints_count Current endpoint count. 325s # TYPE asterisk_endpoints_count gauge 325s asterisk_endpoints_count{eid="fa:16:3e:2b:1a:0c"} 0 325s # HELP asterisk_bridges_count Current bridge count. 325s # TYPE asterisk_bridges_count gauge 325s asterisk_bridges_count{eid="fa:16:3e:2b:1a:0c"} 3 325s # HELP asterisk_bridges_channels_count Number of channels in the bridge. 325s # TYPE asterisk_bridges_channels_count gauge 325s asterisk_bridges_channels_count{eid="fa:16:3e:2b:1a:0c",id="a1a14777-9ccb-4293-8997-f5aba7d23f25",tech="simple_bridge",subclass="basic",creator="",name=""} 0 325s asterisk_bridges_channels_count{eid="fa:16:3e:2b:1a:0c",id="cf82da98-41fa-4bc3-bf4f-f06a358f7de3",tech="simple_bridge",subclass="basic",creator="",name=""} 0 325s 325s END /res/prometheus/ - bridge_to_string Time: <1ms Result: PASS 325s START /res/prometheus/ - config_general_core_metrics 325s [test_res_prometheus.c:config_general_core_metrics:680]: -> CURLing request... 325s [test_res_prometheus.c:config_general_core_metrics:688]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 325s # TYPE asterisk_channels_count gauge 325s asterisk_channels_count{eid="fa:16:3e:2b:1a:0c"} 0 325s # HELP asterisk_calls_sum Total call count. 325s # TYPE asterisk_calls_sum counter 325s asterisk_calls_sum{eid="fa:16:3e:2b:1a:0c"} 0 325s # HELP asterisk_calls_count Current call count. 325s # TYPE asterisk_calls_count gauge 325s asterisk_calls_count{eid="fa:16:3e:2b:1a:0c"} 0 325s # HELP asterisk_endpoints_count Current endpoint count. 325s # TYPE asterisk_endpoints_count gauge 325s asterisk_endpoints_count{eid="fa:16:3e:2b:1a:0c"} 0 325s # HELP asterisk_bridges_count Current bridge count. 325s # TYPE asterisk_bridges_count gauge 325s asterisk_bridges_count{eid="fa:16:3e:2b:1a:0c"} 0 325s # HELP asterisk_core_properties Asterisk instance properties. The value of this will always be 1. 325s # TYPE asterisk_core_properties counter 325s asterisk_core_properties{eid="fa:16:3e:2b:1a:0c",version="20.8.1~dfsg+~cs6.14.40431414-1",build_options="OPTIONAL_API, TEST_FRAMEWORK",build_date="2024-06-07 12:10:19 UTC",build_os="Linux",build_kernel="unknown",build_host="buildd.debian.org"} 1 325s # HELP asterisk_core_uptime_seconds Asterisk instance uptime in seconds. 325s # TYPE asterisk_core_uptime_seconds counter 325s asterisk_core_uptime_seconds{eid="fa:16:3e:2b:1a:0c"} 175 325s # HELP asterisk_core_last_reload_seconds Time since last Asterisk reload in seconds. 325s # TYPE asterisk_core_last_reload_seconds counter 325s asterisk_core_last_reload_seconds{eid="fa:16:3e:2b:1a:0c"} 175 325s # HELP asterisk_core_scrape_time_ms Total time taken to collect metrics, in milliseconds 325s # TYPE asterisk_core_scrape_time_ms counter 325s asterisk_core_scrape_time_ms{eid="fa:16:3e:2b:1a:0c"} 0 325s 325s [test_res_prometheus.c:config_general_core_metrics:690]: -> Checking for core properties 325s [test_res_prometheus.c:config_general_core_metrics:693]: -> Checking for uptime 325s [test_res_prometheus.c:config_general_core_metrics:696]: -> Checking for last reload 325s [test_res_prometheus.c:config_general_core_metrics:699]: -> Checking for scrape time 325s END /res/prometheus/ - config_general_core_metrics Time: 1ms Result: PASS 325s START /res/prometheus/ - config_general_basic_auth 325s [test_res_prometheus.c:config_general_basic_auth:555]: Testing without auth credentials 325s [test_res_prometheus.c:config_general_basic_auth:556]: -> CURLing request... 325s [test_res_prometheus.c:config_general_basic_auth:563]: -> CURL returned 401 325s [test_res_prometheus.c:config_general_basic_auth:566]: Testing with invalid auth credentials 325s [test_res_prometheus.c:config_general_basic_auth:567]: -> CURLing request... 325s [test_res_prometheus.c:config_general_basic_auth:576]: -> CURL returned 401 325s [test_res_prometheus.c:config_general_basic_auth:579]: Testing with valid auth credentials 325s [test_res_prometheus.c:config_general_basic_auth:580]: -> CURLing request... 325s [test_res_prometheus.c:config_general_basic_auth:588]: -> CURL returned 200 325s END /res/prometheus/ - config_general_basic_auth Time: 1ms Result: PASS 325s START /res/prometheus/ - config_general_enabled 325s [test_res_prometheus.c:config_general_enabled:628]: -> CURLing request... 325s [test_res_prometheus.c:config_general_enabled:635]: -> CURL returned 503 325s END /res/prometheus/ - config_general_enabled Time: 1ms Result: PASS 325s START /res/prometheus/ - gauge_create 325s END /res/prometheus/ - gauge_create Time: <1ms Result: PASS 325s START /res/prometheus/ - gauge_to_string 325s END /res/prometheus/ - gauge_to_string Time: <1ms Result: PASS 325s START /res/prometheus/ - counter_create 325s END /res/prometheus/ - counter_create Time: <1ms Result: PASS 325s START /res/prometheus/ - counter_to_string 325s END /res/prometheus/ - counter_to_string Time: <1ms Result: PASS 325s START /res/prometheus/ - metric_register 325s [test_res_prometheus.c:metric_register:291]: Testing nominal registration 325s [test_res_prometheus.c:metric_register:292]: -> Static metric 325s [test_res_prometheus.c:metric_register:294]: -> Malloc'd metric 325s [test_res_prometheus.c:metric_register:300]: Testing nominal registration of child metrics 325s [test_res_prometheus.c:metric_register:315]: Testing name collisions 325s [test_res_prometheus.c:metric_register:322]: Testing label collisions 325s [test_res_prometheus.c:metric_register:331]: Testing removal of metrics 325s END /res/prometheus/ - metric_register Time: <1ms Result: PASS 325s START /res/prometheus/ - metric_callback_register 325s [test_res_prometheus.c:metric_callback_register:241]: -> CURLing request... 325s [test_res_prometheus.c:metric_callback_register:250]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 325s # TYPE asterisk_channels_count gauge 325s asterisk_channels_count{eid="fa:16:3e:2b:1a:0c"} 0 325s # HELP asterisk_calls_sum Total call count. 325s # TYPE asterisk_calls_sum counter 325s asterisk_calls_sum{eid="fa:16:3e:2b:1a:0c"} 0 325s # HELP asterisk_calls_count Current call count. 325s # TYPE asterisk_calls_count gauge 325s asterisk_calls_count{eid="fa:16:3e:2b:1a:0c"} 0 325s # HELP asterisk_endpoints_count Current endpoint count. 325s # TYPE asterisk_endpoints_count gauge 325s asterisk_endpoints_count{eid="fa:16:3e:2b:1a:0c"} 0 325s # HELP asterisk_bridges_count Current bridge count. 325s # TYPE asterisk_bridges_count gauge 325s asterisk_bridges_count{eid="fa:16:3e:2b:1a:0c"} 0 325s # HELP test_counter A test counter 325s # TYPE test_counter counter 325s test_counter 0 325s 325s END /res/prometheus/ - metric_callback_register Time: 1ms Result: PASS 325s START /res/prometheus/ - metric_values 325s [test_res_prometheus.c:metric_values:166]: -> CURLing request... 325s [test_res_prometheus.c:metric_values:176]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 325s # TYPE asterisk_channels_count gauge 325s asterisk_channels_count{eid="fa:16:3e:2b:1a:0c"} 0 325s # HELP asterisk_calls_sum Total call count. 325s # TYPE asterisk_calls_sum counter 325s asterisk_calls_sum{eid="fa:16:3e:2b:1a:0c"} 0 325s # HELP asterisk_calls_count Current call count. 325s # TYPE asterisk_calls_count gauge 325s asterisk_calls_count{eid="fa:16:3e:2b:1a:0c"} 0 325s # HELP asterisk_endpoints_count Current endpoint count. 325s # TYPE asterisk_endpoints_count gauge 325s asterisk_endpoints_count{eid="fa:16:3e:2b:1a:0c"} 0 325s # HELP asterisk_bridges_count Current bridge count. 325s # TYPE asterisk_bridges_count gauge 325s asterisk_bridges_count{eid="fa:16:3e:2b:1a:0c"} 0 325s # HELP test_counter_one A test counter 325s # TYPE test_counter_one counter 325s test_counter_one 1 325s # HELP test_counter_two A test counter 325s # TYPE test_counter_two counter 325s test_counter_two 2 325s 325s END /res/prometheus/ - metric_values Time: <1ms Result: PASS 325s START /res/res_crypto/ - crypto_aes_decrypt 325s [test_crypto.c:crypto_aes_decrypt:607]: Executing AES-ECB decryption test 325s END /res/res_crypto/ - crypto_aes_decrypt Time: 37ms Result: PASS 325s START /res/res_crypto/ - crypto_aes_encrypt 325s [test_crypto.c:crypto_aes_encrypt:531]: Executing AES-ECB encryption test 325s END /res/res_crypto/ - crypto_aes_encrypt Time: 26ms Result: PASS 325s START /res/res_crypto/ - crypto_verify 325s [test_crypto.c:crypto_verify:425]: Executing RSA signature verification test 325s [test_crypto.c:crypto_verify:456]: Couldn't read key: rsa_key1 325s END /res/res_crypto/ - crypto_verify Time: <1ms Result: FAIL 325s START /res/res_crypto/ - crypto_sign 325s [test_crypto.c:crypto_sign:306]: Executing RSA signing test 325s [test_crypto.c:crypto_sign:341]: Couldn't read key: rsa_key1 325s END /res/res_crypto/ - crypto_sign Time: 3ms Result: FAIL 325s START /res/res_crypto/ - crypto_decrypt_pub_key 325s [test_crypto.c:crypto_rsa_decrypt:203]: Executing RSA decryption test 325s [test_crypto.c:crypto_rsa_decrypt:231]: Couldn't read key: rsa_key1 325s END /res/res_crypto/ - crypto_decrypt_pub_key Time: <1ms Result: FAIL 325s START /res/res_crypto/ - crypto_rsa_encrypt 325s [test_crypto.c:crypto_rsa_encrypt:107]: Executing RSA encryption test 325s [test_crypto.c:crypto_rsa_encrypt:138]: Couldn't read key: rsa_key1 325s END /res/res_crypto/ - crypto_rsa_encrypt Time: <1ms Result: FAIL 325s START /res/res_pjproject/ - ast_sockaddr_from_pj_sockaddr_test 325s END /res/res_pjproject/ - ast_sockaddr_from_pj_sockaddr_test Time: <1ms Result: PASS 325s START /res/res_pjproject/ - ast_sockaddr_to_pj_sockaddr_test 325s END /res/res_pjproject/ - ast_sockaddr_to_pj_sockaddr_test Time: <1ms Result: PASS 325s START /res/res_pjsip/ - xml_sanitization_exceeds_buffer 325s END /res/res_pjsip/ - xml_sanitization_exceeds_buffer Time: <1ms Result: PASS 325s START /res/res_pjsip/ - xml_sanitization_end_null 325s END /res/res_pjsip/ - xml_sanitization_end_null Time: <1ms Result: PASS 325s START /res/res_pjsip/scheduler/ - scheduler_policy 325s [test_res_pjsip_scheduler.c:scheduler_policy:355]: This test will take about 4.5 seconds 330s END /res/res_pjsip/scheduler/ - scheduler_policy Time: 4499ms Result: PASS 330s START /res/res_pjsip/scheduler/ - scheduler_cancel 330s [test_res_pjsip_scheduler.c:scheduler_cancel:301]: This test will take about 1.5 seconds 331s END /res/res_pjsip/scheduler/ - scheduler_cancel Time: 1500ms Result: PASS 331s START /res/res_pjsip/scheduler/ - scheduler_cleanup 331s [test_res_pjsip_scheduler.c:scheduler_cleanup:250]: This test will take about 1.6 seconds 333s END /res/res_pjsip/scheduler/ - scheduler_cleanup Time: 1600ms Result: PASS 333s START /res/res_pjsip/scheduler/ - unserialized_scheduler 333s [test_res_pjsip_scheduler.c:scheduler:136]: This test will take about 3.0 seconds 336s END /res/res_pjsip/scheduler/ - unserialized_scheduler Time: 2999ms Result: PASS 336s START /res/res_pjsip/scheduler/ - serialized_scheduler 336s [test_res_pjsip_scheduler.c:scheduler:131]: This test will take about 4.0 seconds 340s END /res/res_pjsip/scheduler/ - serialized_scheduler Time: 4000ms Result: PASS 340s START /res/res_pjsip_pubsub/ - bad_event 340s END /res/res_pjsip_pubsub/ - bad_event Time: <1ms Result: PASS 340s START /res/res_pjsip_pubsub/ - loop 340s END /res/res_pjsip_pubsub/ - loop Time: <1ms Result: PASS 340s START /res/res_pjsip_pubsub/ - duplicate_resource 340s END /res/res_pjsip_pubsub/ - duplicate_resource Time: <1ms Result: PASS 340s START /res/res_pjsip_pubsub/ - bad_branch 340s END /res/res_pjsip_pubsub/ - bad_branch Time: <1ms Result: PASS 340s START /res/res_pjsip_pubsub/ - bad_resource 340s END /res/res_pjsip_pubsub/ - bad_resource Time: <1ms Result: PASS 340s START /res/res_pjsip_pubsub/ - complex_resource_tree 340s END /res/res_pjsip_pubsub/ - complex_resource_tree Time: <1ms Result: PASS 340s START /res/res_pjsip_pubsub/ - resource_tree 340s END /res/res_pjsip_pubsub/ - resource_tree Time: <1ms Result: PASS 340s START /res/res_pjsip_session/ - merge_refresh_topologies 340s [res_pjsip_session.c:test_resolve_refresh_media_states:5892]: Test 1 passed 340s [res_pjsip_session.c:test_resolve_refresh_media_states:5912]: Test 2 passed 340s [res_pjsip_session.c:test_resolve_refresh_media_states:5936]: Test 3 passed 340s [res_pjsip_session.c:test_resolve_refresh_media_states:5955]: Test 4 passed 340s [res_pjsip_session.c:test_resolve_refresh_media_states:5973]: Test 5 passed 340s [res_pjsip_session.c:test_resolve_refresh_media_states:5994]: Test 6 passed 340s [res_pjsip_session.c:test_resolve_refresh_media_states:6020]: Test 7 passed 340s [res_pjsip_session.c:test_resolve_refresh_media_states:6041]: Test 8 passed 340s [res_pjsip_session.c:test_resolve_refresh_media_states:6061]: Test 9 passed 340s [res_pjsip_session.c:test_resolve_refresh_media_states:6081]: Test 10 passed 340s [res_pjsip_session.c:test_resolve_refresh_media_states:6104]: Test 11 passed 340s [res_pjsip_session.c:test_resolve_refresh_media_states:6129]: Test 12 passed 340s [res_pjsip_session.c:test_resolve_refresh_media_states:6163]: Test 13 passed 340s [res_pjsip_session.c:test_resolve_refresh_media_states:6187]: Test 14 passed 340s [res_pjsip_session.c:test_resolve_refresh_media_states:6211]: Test 15 passed 340s END /res/res_pjsip_session/ - merge_refresh_topologies Time: <1ms Result: PASS 340s START /res/res_pjsip_session/caps/ - low_level 340s [test_res_pjsip_session_caps.c:low_level:134]: Testing incoming expected pass 340s [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) 340s [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) 340s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (slin), remote: (all), pref: (local ), outgoing: (no ), expected: (slin) expected result: (PASS) 340s [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) 340s [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) 340s [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) 340s [test_res_pjsip_session_caps.c:low_level:142]: Testing incoming expected fail 340s [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) 340s [test_res_pjsip_session_caps.c:test_create_joint:102]: Expected Failure: Expected: () Actual: (nothing) 340s [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) 340s [test_res_pjsip_session_caps.c:test_create_joint:81]: Expected Failure: Invalid preference string incoming/outgoing combination. 340s [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) 340s [test_res_pjsip_session_caps.c:test_create_joint:81]: Expected Failure: Invalid preference string incoming/outgoing combination. 340s [test_res_pjsip_session_caps.c:low_level:147]: Testing outgoing expected pass 340s [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) 340s [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) 340s [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) 340s [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) 340s [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) 340s [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) 340s [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) 340s END /res/res_pjsip_session/caps/ - low_level Time: 1ms Result: PASS 340s START /res/res_resolver_unbound/ - resolve_srv 340s END /res/res_resolver_unbound/ - resolve_srv Time: 5ms Result: PASS 340s START /res/res_resolver_unbound/ - resolve_naptr 340s END /res/res_resolver_unbound/ - resolve_naptr Time: <1ms Result: PASS 340s START /res/res_resolver_unbound/ - resolve_cancel_off_nominal 340s END /res/res_resolver_unbound/ - resolve_cancel_off_nominal Time: 5ms Result: PASS 340s START /res/res_resolver_unbound/ - resolve_async_off_nominal 340s [res_resolver_unbound.c:off_nominal_async_run:995]: Performing DNS query 'duck.feathers', type 1 340s [res_resolver_unbound.c:off_nominal_async_run:995]: Performing DNS query 'goose.feathers', type 28 340s [res_resolver_unbound.c:off_nominal_async_run:995]: Performing DNS query 'goose.feathers', type 1 340s END /res/res_resolver_unbound/ - resolve_async_off_nominal Time: <1ms Result: PASS 340s START /res/res_resolver_unbound/ - resolve_sync_off_nominal 340s END /res/res_resolver_unbound/ - resolve_sync_off_nominal Time: <1ms Result: PASS 340s START /res/res_resolver_unbound/ - resolve_async 340s [res_resolver_unbound.c:nominal_async_run:713]: Performing DNS query 'goose.feathers', type 1 340s [res_resolver_unbound.c:nominal_async_run:713]: Performing DNS query 'goose.feathers', type 28 340s [res_resolver_unbound.c:nominal_async_run:713]: Performing DNS query 'duck.feathers', type 1 340s END /res/res_resolver_unbound/ - resolve_async Time: <1ms Result: PASS 340s START /res/res_resolver_unbound/ - resolve_sync 340s [res_resolver_unbound.c:nominal_sync_run:563]: Performing DNS query 'goose.feathers', type 1 340s [res_resolver_unbound.c:nominal_sync_run:563]: Performing DNS query 'goose.feathers', type 28 340s [res_resolver_unbound.c:nominal_sync_run:563]: Performing DNS query 'duck.feathers', type 1 340s END /res/res_resolver_unbound/ - resolve_sync Time: <1ms Result: PASS 340s START /res/res_rtp/ - fir_nominal 340s END /res/res_rtp/ - fir_nominal Time: 2ms Result: PASS 340s START /res/res_rtp/ - sr_rr_nominal 340s END /res/res_rtp/ - sr_rr_nominal Time: 1ms Result: PASS 340s START /res/res_rtp/ - remb_nominal 340s END /res/res_rtp/ - remb_nominal Time: 1ms Result: PASS 340s START /res/res_rtp/ - lost_packet_stats_nominal 340s END /res/res_rtp/ - lost_packet_stats_nominal Time: <1ms Result: PASS 340s START /res/res_rtp/ - nack_overflow 340s END /res/res_rtp/ - nack_overflow Time: 2ms Result: PASS 340s START /res/res_rtp/ - nack_nominal 340s END /res/res_rtp/ - nack_nominal Time: 2ms Result: PASS 340s START /res/res_rtp/ - nack_no_packet_loss 340s END /res/res_rtp/ - nack_no_packet_loss Time: 2ms Result: PASS 340s START /res/res_sorcery_memory_cache/ - full_backend_cache_stale 355s END /res/res_sorcery_memory_cache/ - full_backend_cache_stale Time: 15001ms Result: PASS 355s START /res/res_sorcery_memory_cache/ - full_backend_cache_expiration 360s END /res/res_sorcery_memory_cache/ - full_backend_cache_expiration Time: 5000ms Result: PASS 360s START /res/res_sorcery_memory_cache/ - expiration 365s END /res/res_sorcery_memory_cache/ - expiration Time: 4999ms Result: PASS 365s START /res/res_sorcery_memory_cache/ - maximum_objects 365s END /res/res_sorcery_memory_cache/ - maximum_objects Time: 5ms Result: PASS 365s START /res/res_sorcery_memory_cache/ - delete 365s END /res/res_sorcery_memory_cache/ - delete Time: <1ms Result: PASS 365s START /res/res_sorcery_memory_cache/ - create 365s END /res/res_sorcery_memory_cache/ - create Time: <1ms Result: PASS 365s START /res/res_sorcery_memory_cache/ - create 365s END /res/res_sorcery_memory_cache/ - create Time: <1ms Result: PASS 365s START /res/res_sorcery_memory_cache/ - open_with_invalid_options 365s END /res/res_sorcery_memory_cache/ - open_with_invalid_options Time: <1ms Result: PASS 365s START /res/res_sorcery_memory_cache/ - open_with_valid_options 365s END /res/res_sorcery_memory_cache/ - open_with_valid_options Time: <1ms Result: PASS 365s START /res/res_sorcery_memory_cache/ - stale 365s [res_sorcery_memory_cache.c:stale:3189]: Begininning iteration 0 370s [res_sorcery_memory_cache.c:stale:3189]: Begininning iteration 1 375s [res_sorcery_memory_cache.c:stale:3189]: Begininning iteration 2 380s END /res/res_sorcery_memory_cache/ - stale Time: 15001ms Result: PASS 380s START /res/res_sorcery_memory_cache/thrash/ - high_object_count_without_expiration 383s END /res/res_sorcery_memory_cache/thrash/ - high_object_count_without_expiration Time: 3025ms Result: PASS 383s START /res/res_sorcery_memory_cache/thrash/ - conflicting_expire_and_stale 389s END /res/res_sorcery_memory_cache/thrash/ - conflicting_expire_and_stale Time: 6027ms Result: PASS 389s START /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum_with_expire_and_stale 395s END /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum_with_expire_and_stale Time: 6002ms Result: PASS 395s START /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum 398s END /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum Time: 3016ms Result: PASS 398s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_high_concurrent_updates 401s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_high_concurrent_updates Time: 3007ms Result: PASS 401s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_expire 404s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_expire Time: 3017ms Result: PASS 404s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_stale 407s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_stale Time: 3021ms Result: PASS 407s START /res/sorcery_astdb/ - object_delete_uncreated 407s END /res/sorcery_astdb/ - object_delete_uncreated Time: 3ms Result: PASS 407s START /res/sorcery_astdb/ - object_delete 407s END /res/sorcery_astdb/ - object_delete Time: <1ms Result: PASS 407s START /res/sorcery_astdb/ - object_update_uncreated 407s END /res/sorcery_astdb/ - object_update_uncreated Time: <1ms Result: PASS 407s START /res/sorcery_astdb/ - object_update 407s END /res/sorcery_astdb/ - object_update Time: <1ms Result: PASS 407s START /res/sorcery_astdb/ - object_retrieve_regex 407s END /res/sorcery_astdb/ - object_retrieve_regex Time: <1ms Result: PASS 407s START /res/sorcery_astdb/ - object_retrieve_multiple_field 407s END /res/sorcery_astdb/ - object_retrieve_multiple_field Time: <1ms Result: PASS 407s START /res/sorcery_astdb/ - object_retrieve_multiple_all 407s END /res/sorcery_astdb/ - object_retrieve_multiple_all Time: <1ms Result: PASS 407s START /res/sorcery_astdb/ - object_retrieve_field 407s END /res/sorcery_astdb/ - object_retrieve_field Time: <1ms Result: PASS 407s START /res/sorcery_astdb/ - object_retrieve_id 407s END /res/sorcery_astdb/ - object_retrieve_id Time: <1ms Result: PASS 407s START /res/sorcery_astdb/ - object_create 407s END /res/sorcery_astdb/ - object_create Time: <1ms Result: PASS 407s START /res/sorcery_realtime/ - object_filter 407s END /res/sorcery_realtime/ - object_filter Time: <1ms Result: PASS 407s START /res/sorcery_realtime/ - object_allocate_on_retrieval 407s END /res/sorcery_realtime/ - object_allocate_on_retrieval Time: <1ms Result: PASS 407s START /res/sorcery_realtime/ - object_delete_uncreated 407s END /res/sorcery_realtime/ - object_delete_uncreated Time: <1ms Result: PASS 407s START /res/sorcery_realtime/ - object_delete 407s END /res/sorcery_realtime/ - object_delete Time: <1ms Result: PASS 407s START /res/sorcery_realtime/ - object_update 407s END /res/sorcery_realtime/ - object_update Time: <1ms Result: PASS 407s START /res/sorcery_realtime/ - object_retrieve_regex_nofetch 407s END /res/sorcery_realtime/ - object_retrieve_regex_nofetch Time: <1ms Result: PASS 407s START /res/sorcery_realtime/ - object_retrieve_regex 407s END /res/sorcery_realtime/ - object_retrieve_regex Time: <1ms Result: PASS 407s START /res/sorcery_realtime/ - object_retrieve_multiple_field 407s END /res/sorcery_realtime/ - object_retrieve_multiple_field Time: <1ms Result: PASS 407s START /res/sorcery_realtime/ - object_retrieve_multiple_all_nofetch 407s END /res/sorcery_realtime/ - object_retrieve_multiple_all_nofetch Time: <1ms Result: PASS 407s START /res/sorcery_realtime/ - object_retrieve_multiple_all 407s END /res/sorcery_realtime/ - object_retrieve_multiple_all Time: <1ms Result: PASS 407s START /res/sorcery_realtime/ - object_retrieve_field 407s END /res/sorcery_realtime/ - object_retrieve_field Time: <1ms Result: PASS 407s START /res/sorcery_realtime/ - object_retrieve_id 407s END /res/sorcery_realtime/ - object_retrieve_id Time: <1ms Result: PASS 407s START /res/sorcery_realtime/ - object_create 407s END /res/sorcery_realtime/ - object_create Time: <1ms Result: PASS 407s START /res/websocket/ - websocket_client_multiple_protocols 407s END /res/websocket/ - websocket_client_multiple_protocols Time: 1ms Result: PASS 407s START /res/websocket/ - websocket_client_unsupported_protocol 407s END /res/websocket/ - websocket_client_unsupported_protocol Time: <1ms Result: PASS 407s START /res/websocket/ - websocket_client_bad_url 407s END /res/websocket/ - websocket_client_bad_url Time: <1ms Result: PASS 407s START /stasis/channels/ - channel_redirect_snapshot_json 407s END /stasis/channels/ - channel_redirect_snapshot_json Time: 2ms Result: PASS 407s START /stasis/channels/ - channel_snapshot_json 407s END /stasis/channels/ - channel_snapshot_json Time: <1ms Result: PASS 407s START /stasis/channels/ - multi_channel_blob_snapshots 407s END /stasis/channels/ - multi_channel_blob_snapshots Time: <1ms Result: PASS 407s START /stasis/channels/ - multi_channel_blob_create 407s END /stasis/channels/ - multi_channel_blob_create Time: <1ms Result: PASS 407s START /stasis/channels/ - null_blob 407s END /stasis/channels/ - null_blob Time: <1ms Result: PASS 407s START /stasis/channels/ - channel_blob_create 407s END /stasis/channels/ - channel_blob_create Time: <1ms Result: PASS 407s START /stasis/core/ - caching_dtor_order 407s END /stasis/core/ - caching_dtor_order Time: <1ms Result: PASS 407s START /stasis/core/ - dtor_order 407s END /stasis/core/ - dtor_order Time: <1ms Result: PASS 407s START /stasis/core/ - to_ami 407s END /stasis/core/ - to_ami Time: <1ms Result: PASS 407s START /stasis/core/ - no_to_ami 407s END /stasis/core/ - no_to_ami Time: <1ms Result: PASS 407s START /stasis/core/ - to_json 407s END /stasis/core/ - to_json Time: <1ms Result: PASS 407s START /stasis/core/ - no_to_json 407s END /stasis/core/ - no_to_json Time: <1ms Result: PASS 407s START /stasis/core/ - subscription_interleaving 407s END /stasis/core/ - subscription_interleaving Time: <1ms Result: PASS 407s START /stasis/core/ - interleaving 407s END /stasis/core/ - interleaving Time: <1ms Result: PASS 407s START /stasis/core/ - router_cache_updates 407s END /stasis/core/ - router_cache_updates Time: 100ms Result: PASS 407s START /stasis/core/ - router_pool 407s END /stasis/core/ - router_pool Time: <1ms Result: PASS 407s START /stasis/core/ - router 407s END /stasis/core/ - router Time: <1ms Result: PASS 407s START /stasis/core/ - cache_eid_aggregate 407s END /stasis/core/ - cache_eid_aggregate Time: <1ms Result: PASS 407s START /stasis/core/ - cache_dump 407s END /stasis/core/ - cache_dump Time: <1ms Result: PASS 407s START /stasis/core/ - cache 407s END /stasis/core/ - cache Time: <1ms Result: PASS 407s START /stasis/core/ - cache_filter 407s END /stasis/core/ - cache_filter Time: 100ms Result: PASS 407s START /stasis/core/ - forward 407s END /stasis/core/ - forward Time: <1ms Result: PASS 407s START /stasis/core/ - unsubscribe_stops_messages 408s END /stasis/core/ - unsubscribe_stops_messages Time: 100ms Result: PASS 408s START /stasis/core/ - publish_pool 408s END /stasis/core/ - publish_pool Time: <1ms Result: PASS 408s START /stasis/core/ - publish_sync 408s END /stasis/core/ - publish_sync Time: <1ms Result: PASS 408s START /stasis/core/ - publish 408s END /stasis/core/ - publish Time: <1ms Result: PASS 408s START /stasis/core/ - subscription_pool_messages 408s END /stasis/core/ - subscription_pool_messages Time: <1ms Result: PASS 408s START /stasis/core/ - subscription_messages 408s END /stasis/core/ - subscription_messages Time: <1ms Result: PASS 408s START /stasis/core/ - message 408s END /stasis/core/ - message Time: <1ms Result: PASS 408s START /stasis/core/ - message_type 408s END /stasis/core/ - message_type Time: <1ms Result: PASS 408s START /stasis/core/filtering/ - combo_filters 408s [test_stasis.c:dump_consumer:2198]: Messages received: 7 Final? yes 408s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 408s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType1 Pass 408s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass 408s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMI Pass 408s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass 408s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageJSON Pass 408s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 408s END /stasis/core/filtering/ - combo_filters Time: <1ms Result: PASS 408s START /stasis/core/filtering/ - formatter_filters 408s [test_stasis.c:dump_consumer:2198]: Messages received: 7 Final? yes 408s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 408s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMI Pass 408s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageJSON Pass 408s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass 408s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass2 408s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageEVENT Pass 408s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 408s END /stasis/core/filtering/ - formatter_filters Time: 1ms Result: PASS 408s START /stasis/core/filtering/ - type_filters 408s [test_stasis.c:dump_consumer:2198]: Messages received: 5 Final? yes 408s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 408s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType1 Pass 408s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass 408s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass2 408s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 408s END /stasis/core/filtering/ - type_filters Time: <1ms Result: PASS 408s START /stasis/core/state/ - explicit_publish 408s END /stasis/core/state/ - explicit_publish Time: 35ms Result: PASS 408s START /stasis/core/state/ - implicit_publish 408s END /stasis/core/state/ - implicit_publish Time: 37ms Result: PASS 408s START /stasis/endpoints/ - channel_messages 408s END /stasis/endpoints/ - channel_messages Time: 1ms Result: PASS 408s START /stasis/endpoints/ - cache_clear 408s END /stasis/endpoints/ - cache_clear Time: <1ms Result: PASS 408s START /stasis/endpoints/ - state_changes 408s END /stasis/endpoints/ - state_changes Time: <1ms Result: PASS 408s START /stasis/res/ - app_invoke_dne 408s END /stasis/res/ - app_invoke_dne Time: <1ms Result: PASS 408s START /stasis/res/ - app_invoke_one 408s END /stasis/res/ - app_invoke_one Time: <1ms Result: PASS 408s START /stasis/res/ - app_replaced 408s END /stasis/res/ - app_replaced Time: <1ms Result: PASS 408s 408s 656 Test(s) Executed 652 Passed 4 Failed 408s Results Generated Successfully: /tmp/autopkgtest.0TqZbv/build.6hO/src/debian/tests/testmods/output/results.txt 408s 'U' option is not compatible with remote console mode and has no effect. 408s 408s 'U' option is not compatible with remote console mode and has no effect. 408s 408s Some test modules were not loaded: 408s 20a21 408s > test_cel.so 408s 53a55 408s > test_message.so 408s Manually disabled: 408s test_message 408s test_cel 408s 408s 'U' option is not compatible with remote console mode and has no effect. 408s 409s autopkgtest [10:16:06]: test asttestmods: -----------------------] 410s autopkgtest [10:16:07]: test asttestmods: - - - - - - - - - - results - - - - - - - - - - 410s asttestmods PASS 410s autopkgtest [10:16:07]: test amr: preparing testbed 518s autopkgtest [10:17:55]: testbed dpkg architecture: arm64 518s autopkgtest [10:17:55]: testbed apt version: 2.9.8 518s autopkgtest [10:17:55]: @@@@@@@@@@@@@@@@@@@@ test bed setup 519s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [73.9 kB] 519s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [3094 kB] 520s Get:3 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [194 kB] 520s Get:4 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [51.2 kB] 520s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/restricted Sources [7016 B] 520s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 Packages [247 kB] 520s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/restricted arm64 Packages [50.3 kB] 520s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/universe arm64 Packages [2058 kB] 520s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse arm64 Packages [39.5 kB] 520s Fetched 5816 kB in 1s (4393 kB/s) 520s Reading package lists... 523s Reading package lists... 523s Building dependency tree... 523s Reading state information... 524s Calculating upgrade... 524s The following packages will be upgraded: 524s libcrypt-dev libcrypt1 524s 2 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 524s Need to get 206 kB of archives. 524s After this operation, 0 B of additional disk space will be used. 524s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 libcrypt-dev arm64 1:4.4.36-5 [119 kB] 525s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/main arm64 libcrypt1 arm64 1:4.4.36-5 [86.7 kB] 525s Fetched 206 kB in 0s (496 kB/s) 525s (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 ... 79705 files and directories currently installed.) 525s Preparing to unpack .../libcrypt-dev_1%3a4.4.36-5_arm64.deb ... 525s Unpacking libcrypt-dev:arm64 (1:4.4.36-5) over (1:4.4.36-4build1) ... 526s Preparing to unpack .../libcrypt1_1%3a4.4.36-5_arm64.deb ... 526s Unpacking libcrypt1:arm64 (1:4.4.36-5) over (1:4.4.36-4build1) ... 526s Setting up libcrypt1:arm64 (1:4.4.36-5) ... 526s Setting up libcrypt-dev:arm64 (1:4.4.36-5) ... 526s Processing triggers for man-db (2.12.1-3) ... 526s Processing triggers for libc-bin (2.40-1ubuntu3) ... 526s Reading package lists... 526s Building dependency tree... 526s Reading state information... 527s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 528s Hit:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease 528s Hit:2 http://ftpmaster.internal/ubuntu plucky InRelease 528s Hit:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease 528s Hit:4 http://ftpmaster.internal/ubuntu plucky-security InRelease 529s Reading package lists... 529s Reading package lists... 529s Building dependency tree... 529s Reading state information... 530s Calculating upgrade... 530s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 530s Reading package lists... 531s Building dependency tree... 531s Reading state information... 531s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 536s Reading package lists... 537s Building dependency tree... 537s Reading state information... 537s Starting pkgProblemResolver with broken count: 0 538s Starting 2 pkgProblemResolver with broken count: 0 538s Done 538s The following additional packages will be installed: 538s asterisk asterisk-config asterisk-core-sounds-en asterisk-core-sounds-en-gsm 538s asterisk-modules freetds-common libasound2-data libasound2t64 libb64-0d 538s libc-client2007e libcodec2-1.2 libdeflate0 libevent-2.1-7t64 538s libgmime-3.0-0t64 libgsm1 libical3t64 libiksemel3 libjack-jackd2-0 libjbig0 538s libjpeg-turbo8 libjpeg8 libjwt2 liblerc4 libltdl7 liblua5.1-0 libneon27t64 538s libodbc2 libogg0 libopencore-amrnb0 libopencore-amrwb0 libopus0 libopusenc0 538s libopusfile0 libportaudio2 libpq5 libradcli4 libresample1 libsamplerate0 538s libsharpyuv0 libsnmp-base libsnmp40t64 libspandsp2t64 libspeex1 libspeexdsp1 538s libsrtp2-1 libsybdb5 libtiff6 libunbound8 liburiparser1 libvo-amrwbenc0 538s libvorbis0a libvorbisenc2 libvorbisfile3 libwebp7 libxslt1.1 mlock 538s Suggested packages: 538s asterisk-dahdi asterisk-dev asterisk-doc asterisk-ooh323 asterisk-opus 538s alsa-utils libasound2-plugins uw-mailutils jackd2 odbc-postgresql tdsodbc 538s opus-tools snmp-mibs-downloader speex 538s Recommended packages: 538s asterisk-moh-opsound-gsm sox alsa-ucm-conf alsa-topology-conf 538s The following NEW packages will be installed: 538s asterisk asterisk-config asterisk-core-sounds-en asterisk-core-sounds-en-gsm 538s asterisk-modules autopkgtest-satdep freetds-common libasound2-data 538s libasound2t64 libb64-0d libc-client2007e libcodec2-1.2 libdeflate0 538s libevent-2.1-7t64 libgmime-3.0-0t64 libgsm1 libical3t64 libiksemel3 538s libjack-jackd2-0 libjbig0 libjpeg-turbo8 libjpeg8 libjwt2 liblerc4 libltdl7 538s liblua5.1-0 libneon27t64 libodbc2 libogg0 libopencore-amrnb0 538s libopencore-amrwb0 libopus0 libopusenc0 libopusfile0 libportaudio2 libpq5 538s libradcli4 libresample1 libsamplerate0 libsharpyuv0 libsnmp-base 538s libsnmp40t64 libspandsp2t64 libspeex1 libspeexdsp1 libsrtp2-1 libsybdb5 538s libtiff6 libunbound8 liburiparser1 libvo-amrwbenc0 libvorbis0a libvorbisenc2 538s libvorbisfile3 libwebp7 libxslt1.1 mlock 538s 0 upgraded, 57 newly installed, 0 to remove and 0 not upgraded. 538s Need to get 28.4 MB/28.4 MB of archives. 538s After this operation, 87.9 MB of additional disk space will be used. 538s Get:1 /tmp/autopkgtest.0TqZbv/2-autopkgtest-satdep.deb autopkgtest-satdep arm64 0 [716 B] 539s Get:2 http://ftpmaster.internal/ubuntu plucky/universe arm64 asterisk-config all 1:20.8.1~dfsg+~cs6.14.40431414-1 [245 kB] 539s Get:3 http://ftpmaster.internal/ubuntu plucky/universe arm64 asterisk-core-sounds-en-gsm all 1.6.1-1 [2417 kB] 539s Get:4 http://ftpmaster.internal/ubuntu plucky/universe arm64 asterisk-core-sounds-en all 1.6.1-1 [20.6 kB] 539s Get:5 http://ftpmaster.internal/ubuntu plucky/universe arm64 mlock arm64 8:2007f~dfsg-7build3 [7918 B] 539s Get:6 http://ftpmaster.internal/ubuntu plucky/universe arm64 libc-client2007e arm64 8:2007f~dfsg-7build3 [628 kB] 539s Get:7 http://ftpmaster.internal/ubuntu plucky/universe arm64 libcodec2-1.2 arm64 1.2.0-2build1 [8996 kB] 540s Get:8 http://ftpmaster.internal/ubuntu plucky/universe arm64 libgmime-3.0-0t64 arm64 3.2.15+dfsg-1 [173 kB] 540s Get:9 http://ftpmaster.internal/ubuntu plucky/universe arm64 libgsm1 arm64 1.0.22-1build1 [27.0 kB] 540s Get:10 http://ftpmaster.internal/ubuntu plucky/main arm64 libical3t64 arm64 3.0.18-1 [299 kB] 540s Get:11 http://ftpmaster.internal/ubuntu plucky/universe arm64 libiksemel3 arm64 1.4-4build2 [27.6 kB] 540s Get:12 http://ftpmaster.internal/ubuntu plucky/main arm64 libopus0 arm64 1.5.2-2 [2891 kB] 540s Get:13 http://ftpmaster.internal/ubuntu plucky/main arm64 libsamplerate0 arm64 0.2.2-4build1 [1343 kB] 540s Get:14 http://ftpmaster.internal/ubuntu plucky/main arm64 libjack-jackd2-0 arm64 1.9.21~dfsg-3ubuntu3 [285 kB] 540s Get:15 http://ftpmaster.internal/ubuntu plucky/universe arm64 libb64-0d arm64 1.2-5build1 [9590 B] 540s Get:16 http://ftpmaster.internal/ubuntu plucky/universe arm64 libjwt2 arm64 1.17.0-2build2 [17.4 kB] 540s Get:17 http://ftpmaster.internal/ubuntu plucky/universe arm64 liblua5.1-0 arm64 5.1.5-9build2 [115 kB] 540s Get:18 http://ftpmaster.internal/ubuntu plucky/universe arm64 libneon27t64 arm64 0.33.0-1.1build3 [101 kB] 540s Get:19 http://ftpmaster.internal/ubuntu plucky/main arm64 libltdl7 arm64 2.4.7-7build1 [40.4 kB] 540s Get:20 http://ftpmaster.internal/ubuntu plucky/main arm64 libodbc2 arm64 2.3.12-1ubuntu1 [145 kB] 540s Get:21 http://ftpmaster.internal/ubuntu plucky/main arm64 libogg0 arm64 1.3.5-3build1 [22.6 kB] 540s Get:22 http://ftpmaster.internal/ubuntu plucky/universe arm64 libopencore-amrnb0 arm64 0.1.6-1build1 [97.0 kB] 540s Get:23 http://ftpmaster.internal/ubuntu plucky/universe arm64 libopencore-amrwb0 arm64 0.1.6-1build1 [50.3 kB] 540s Get:24 http://ftpmaster.internal/ubuntu plucky/universe arm64 libopusenc0 arm64 0.2.1-2build1 [25.6 kB] 540s Get:25 http://ftpmaster.internal/ubuntu plucky/universe arm64 libopusfile0 arm64 0.12-4build3 [44.7 kB] 540s Get:26 http://ftpmaster.internal/ubuntu plucky/main arm64 libasound2-data all 1.2.12-1 [21.0 kB] 540s Get:27 http://ftpmaster.internal/ubuntu plucky/main arm64 libasound2t64 arm64 1.2.12-1 [384 kB] 540s Get:28 http://ftpmaster.internal/ubuntu plucky/universe arm64 libportaudio2 arm64 19.6.0-1.2build3 [65.4 kB] 540s Get:29 http://ftpmaster.internal/ubuntu plucky/main arm64 libpq5 arm64 17.0-1 [248 kB] 540s Get:30 http://ftpmaster.internal/ubuntu plucky/universe arm64 libradcli4 arm64 1.2.11-1build3 [40.2 kB] 540s Get:31 http://ftpmaster.internal/ubuntu plucky/universe arm64 libresample1 arm64 0.1.3-8 [8668 B] 540s Get:32 http://ftpmaster.internal/ubuntu plucky/main arm64 libsnmp-base all 5.9.4+dfsg-1.1ubuntu5 [206 kB] 540s Get:33 http://ftpmaster.internal/ubuntu plucky/main arm64 libsnmp40t64 arm64 5.9.4+dfsg-1.1ubuntu5 [1053 kB] 540s Get:34 http://ftpmaster.internal/ubuntu plucky/main arm64 libdeflate0 arm64 1.21-1 [46.2 kB] 540s Get:35 http://ftpmaster.internal/ubuntu plucky/main arm64 libjbig0 arm64 2.1-6.1ubuntu2 [29.3 kB] 540s Get:36 http://ftpmaster.internal/ubuntu plucky/main arm64 libjpeg-turbo8 arm64 2.1.5-2ubuntu2 [163 kB] 540s Get:37 http://ftpmaster.internal/ubuntu plucky/main arm64 libjpeg8 arm64 8c-2ubuntu11 [2148 B] 540s Get:38 http://ftpmaster.internal/ubuntu plucky/main arm64 liblerc4 arm64 4.0.0+ds-4ubuntu2 [154 kB] 540s Get:39 http://ftpmaster.internal/ubuntu plucky/main arm64 libsharpyuv0 arm64 1.4.0-0.1 [16.3 kB] 540s Get:40 http://ftpmaster.internal/ubuntu plucky/main arm64 libwebp7 arm64 1.4.0-0.1 [192 kB] 540s Get:41 http://ftpmaster.internal/ubuntu plucky/main arm64 libtiff6 arm64 4.5.1+git230720-4ubuntu4 [193 kB] 540s Get:42 http://ftpmaster.internal/ubuntu plucky/universe arm64 libspandsp2t64 arm64 0.0.6+dfsg-2.1build1 [313 kB] 540s Get:43 http://ftpmaster.internal/ubuntu plucky/main arm64 libspeex1 arm64 1.2.1-2ubuntu3 [57.4 kB] 540s Get:44 http://ftpmaster.internal/ubuntu plucky/main arm64 libspeexdsp1 arm64 1.2.1-1ubuntu3 [40.2 kB] 540s Get:45 http://ftpmaster.internal/ubuntu plucky/universe arm64 libsrtp2-1 arm64 2.5.0-3build1 [42.9 kB] 540s Get:46 http://ftpmaster.internal/ubuntu plucky/main arm64 freetds-common all 1.3.17+ds-2build3 [26.9 kB] 540s Get:47 http://ftpmaster.internal/ubuntu plucky/main arm64 libsybdb5 arm64 1.3.17+ds-2build3 [186 kB] 540s Get:48 http://ftpmaster.internal/ubuntu plucky/main arm64 libevent-2.1-7t64 arm64 2.1.12-stable-10 [140 kB] 540s Get:49 http://ftpmaster.internal/ubuntu plucky/main arm64 libunbound8 arm64 1.20.0-1ubuntu2.1 [431 kB] 540s Get:50 http://ftpmaster.internal/ubuntu plucky/universe arm64 libvo-amrwbenc0 arm64 0.1.3-2build1 [73.2 kB] 540s Get:51 http://ftpmaster.internal/ubuntu plucky/main arm64 libvorbis0a arm64 1.3.7-2 [95.0 kB] 540s Get:52 http://ftpmaster.internal/ubuntu plucky/main arm64 libvorbisenc2 arm64 1.3.7-2 [80.0 kB] 540s Get:53 http://ftpmaster.internal/ubuntu plucky/main arm64 libvorbisfile3 arm64 1.3.7-2 [17.1 kB] 540s Get:54 http://ftpmaster.internal/ubuntu plucky/universe arm64 asterisk-modules arm64 1:20.8.1~dfsg+~cs6.14.40431414-1 [3254 kB] 541s Get:55 http://ftpmaster.internal/ubuntu plucky/universe arm64 liburiparser1 arm64 0.9.8+dfsg-1 [35.4 kB] 541s Get:56 http://ftpmaster.internal/ubuntu plucky/main arm64 libxslt1.1 arm64 1.1.39-0exp1ubuntu1 [167 kB] 541s Get:57 http://ftpmaster.internal/ubuntu plucky/universe arm64 asterisk arm64 1:20.8.1~dfsg+~cs6.14.40431414-1 [2607 kB] 541s Fetched 28.4 MB in 2s (12.8 MB/s) 541s Selecting previously unselected package asterisk-config. 541s (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 ... 79705 files and directories currently installed.) 541s Preparing to unpack .../00-asterisk-config_1%3a20.8.1~dfsg+~cs6.14.40431414-1_all.deb ... 541s Unpacking asterisk-config (1:20.8.1~dfsg+~cs6.14.40431414-1) ... 541s Selecting previously unselected package asterisk-core-sounds-en-gsm. 541s Preparing to unpack .../01-asterisk-core-sounds-en-gsm_1.6.1-1_all.deb ... 541s Unpacking asterisk-core-sounds-en-gsm (1.6.1-1) ... 541s Selecting previously unselected package asterisk-core-sounds-en. 541s Preparing to unpack .../02-asterisk-core-sounds-en_1.6.1-1_all.deb ... 541s Unpacking asterisk-core-sounds-en (1.6.1-1) ... 541s Selecting previously unselected package mlock. 541s Preparing to unpack .../03-mlock_8%3a2007f~dfsg-7build3_arm64.deb ... 541s Unpacking mlock (8:2007f~dfsg-7build3) ... 542s Selecting previously unselected package libc-client2007e. 542s Preparing to unpack .../04-libc-client2007e_8%3a2007f~dfsg-7build3_arm64.deb ... 542s Unpacking libc-client2007e (8:2007f~dfsg-7build3) ... 542s Selecting previously unselected package libcodec2-1.2:arm64. 542s Preparing to unpack .../05-libcodec2-1.2_1.2.0-2build1_arm64.deb ... 542s Unpacking libcodec2-1.2:arm64 (1.2.0-2build1) ... 542s Selecting previously unselected package libgmime-3.0-0t64:arm64. 542s Preparing to unpack .../06-libgmime-3.0-0t64_3.2.15+dfsg-1_arm64.deb ... 542s Unpacking libgmime-3.0-0t64:arm64 (3.2.15+dfsg-1) ... 542s Selecting previously unselected package libgsm1:arm64. 542s Preparing to unpack .../07-libgsm1_1.0.22-1build1_arm64.deb ... 542s Unpacking libgsm1:arm64 (1.0.22-1build1) ... 542s Selecting previously unselected package libical3t64:arm64. 542s Preparing to unpack .../08-libical3t64_3.0.18-1_arm64.deb ... 542s Unpacking libical3t64:arm64 (3.0.18-1) ... 542s Selecting previously unselected package libiksemel3:arm64. 542s Preparing to unpack .../09-libiksemel3_1.4-4build2_arm64.deb ... 542s Unpacking libiksemel3:arm64 (1.4-4build2) ... 542s Selecting previously unselected package libopus0:arm64. 542s Preparing to unpack .../10-libopus0_1.5.2-2_arm64.deb ... 542s Unpacking libopus0:arm64 (1.5.2-2) ... 542s Selecting previously unselected package libsamplerate0:arm64. 542s Preparing to unpack .../11-libsamplerate0_0.2.2-4build1_arm64.deb ... 542s Unpacking libsamplerate0:arm64 (0.2.2-4build1) ... 542s Selecting previously unselected package libjack-jackd2-0:arm64. 542s Preparing to unpack .../12-libjack-jackd2-0_1.9.21~dfsg-3ubuntu3_arm64.deb ... 542s Unpacking libjack-jackd2-0:arm64 (1.9.21~dfsg-3ubuntu3) ... 542s Selecting previously unselected package libb64-0d:arm64. 542s Preparing to unpack .../13-libb64-0d_1.2-5build1_arm64.deb ... 542s Unpacking libb64-0d:arm64 (1.2-5build1) ... 542s Selecting previously unselected package libjwt2:arm64. 542s Preparing to unpack .../14-libjwt2_1.17.0-2build2_arm64.deb ... 542s Unpacking libjwt2:arm64 (1.17.0-2build2) ... 542s Selecting previously unselected package liblua5.1-0:arm64. 542s Preparing to unpack .../15-liblua5.1-0_5.1.5-9build2_arm64.deb ... 542s Unpacking liblua5.1-0:arm64 (5.1.5-9build2) ... 542s Selecting previously unselected package libneon27t64:arm64. 542s Preparing to unpack .../16-libneon27t64_0.33.0-1.1build3_arm64.deb ... 542s Unpacking libneon27t64:arm64 (0.33.0-1.1build3) ... 542s Selecting previously unselected package libltdl7:arm64. 542s Preparing to unpack .../17-libltdl7_2.4.7-7build1_arm64.deb ... 542s Unpacking libltdl7:arm64 (2.4.7-7build1) ... 542s Selecting previously unselected package libodbc2:arm64. 542s Preparing to unpack .../18-libodbc2_2.3.12-1ubuntu1_arm64.deb ... 542s Unpacking libodbc2:arm64 (2.3.12-1ubuntu1) ... 542s Selecting previously unselected package libogg0:arm64. 542s Preparing to unpack .../19-libogg0_1.3.5-3build1_arm64.deb ... 542s Unpacking libogg0:arm64 (1.3.5-3build1) ... 542s Selecting previously unselected package libopencore-amrnb0:arm64. 542s Preparing to unpack .../20-libopencore-amrnb0_0.1.6-1build1_arm64.deb ... 542s Unpacking libopencore-amrnb0:arm64 (0.1.6-1build1) ... 542s Selecting previously unselected package libopencore-amrwb0:arm64. 542s Preparing to unpack .../21-libopencore-amrwb0_0.1.6-1build1_arm64.deb ... 542s Unpacking libopencore-amrwb0:arm64 (0.1.6-1build1) ... 542s Selecting previously unselected package libopusenc0:arm64. 543s Preparing to unpack .../22-libopusenc0_0.2.1-2build1_arm64.deb ... 543s Unpacking libopusenc0:arm64 (0.2.1-2build1) ... 543s Selecting previously unselected package libopusfile0:arm64. 543s Preparing to unpack .../23-libopusfile0_0.12-4build3_arm64.deb ... 543s Unpacking libopusfile0:arm64 (0.12-4build3) ... 543s Selecting previously unselected package libasound2-data. 543s Preparing to unpack .../24-libasound2-data_1.2.12-1_all.deb ... 543s Unpacking libasound2-data (1.2.12-1) ... 543s Selecting previously unselected package libasound2t64:arm64. 543s Preparing to unpack .../25-libasound2t64_1.2.12-1_arm64.deb ... 543s Unpacking libasound2t64:arm64 (1.2.12-1) ... 543s Selecting previously unselected package libportaudio2:arm64. 543s Preparing to unpack .../26-libportaudio2_19.6.0-1.2build3_arm64.deb ... 543s Unpacking libportaudio2:arm64 (19.6.0-1.2build3) ... 543s Selecting previously unselected package libpq5:arm64. 543s Preparing to unpack .../27-libpq5_17.0-1_arm64.deb ... 543s Unpacking libpq5:arm64 (17.0-1) ... 543s Selecting previously unselected package libradcli4. 543s Preparing to unpack .../28-libradcli4_1.2.11-1build3_arm64.deb ... 543s Unpacking libradcli4 (1.2.11-1build3) ... 543s Selecting previously unselected package libresample1. 543s Preparing to unpack .../29-libresample1_0.1.3-8_arm64.deb ... 543s Unpacking libresample1 (0.1.3-8) ... 543s Selecting previously unselected package libsnmp-base. 543s Preparing to unpack .../30-libsnmp-base_5.9.4+dfsg-1.1ubuntu5_all.deb ... 543s Unpacking libsnmp-base (5.9.4+dfsg-1.1ubuntu5) ... 543s Selecting previously unselected package libsnmp40t64:arm64. 543s Preparing to unpack .../31-libsnmp40t64_5.9.4+dfsg-1.1ubuntu5_arm64.deb ... 543s Unpacking libsnmp40t64:arm64 (5.9.4+dfsg-1.1ubuntu5) ... 543s Selecting previously unselected package libdeflate0:arm64. 543s Preparing to unpack .../32-libdeflate0_1.21-1_arm64.deb ... 543s Unpacking libdeflate0:arm64 (1.21-1) ... 543s Selecting previously unselected package libjbig0:arm64. 543s Preparing to unpack .../33-libjbig0_2.1-6.1ubuntu2_arm64.deb ... 543s Unpacking libjbig0:arm64 (2.1-6.1ubuntu2) ... 543s Selecting previously unselected package libjpeg-turbo8:arm64. 543s Preparing to unpack .../34-libjpeg-turbo8_2.1.5-2ubuntu2_arm64.deb ... 543s Unpacking libjpeg-turbo8:arm64 (2.1.5-2ubuntu2) ... 543s Selecting previously unselected package libjpeg8:arm64. 543s Preparing to unpack .../35-libjpeg8_8c-2ubuntu11_arm64.deb ... 543s Unpacking libjpeg8:arm64 (8c-2ubuntu11) ... 543s Selecting previously unselected package liblerc4:arm64. 543s Preparing to unpack .../36-liblerc4_4.0.0+ds-4ubuntu2_arm64.deb ... 543s Unpacking liblerc4:arm64 (4.0.0+ds-4ubuntu2) ... 543s Selecting previously unselected package libsharpyuv0:arm64. 543s Preparing to unpack .../37-libsharpyuv0_1.4.0-0.1_arm64.deb ... 543s Unpacking libsharpyuv0:arm64 (1.4.0-0.1) ... 543s Selecting previously unselected package libwebp7:arm64. 543s Preparing to unpack .../38-libwebp7_1.4.0-0.1_arm64.deb ... 543s Unpacking libwebp7:arm64 (1.4.0-0.1) ... 543s Selecting previously unselected package libtiff6:arm64. 543s Preparing to unpack .../39-libtiff6_4.5.1+git230720-4ubuntu4_arm64.deb ... 543s Unpacking libtiff6:arm64 (4.5.1+git230720-4ubuntu4) ... 543s Selecting previously unselected package libspandsp2t64:arm64. 543s Preparing to unpack .../40-libspandsp2t64_0.0.6+dfsg-2.1build1_arm64.deb ... 543s Unpacking libspandsp2t64:arm64 (0.0.6+dfsg-2.1build1) ... 543s Selecting previously unselected package libspeex1:arm64. 543s Preparing to unpack .../41-libspeex1_1.2.1-2ubuntu3_arm64.deb ... 543s Unpacking libspeex1:arm64 (1.2.1-2ubuntu3) ... 543s Selecting previously unselected package libspeexdsp1:arm64. 543s Preparing to unpack .../42-libspeexdsp1_1.2.1-1ubuntu3_arm64.deb ... 543s Unpacking libspeexdsp1:arm64 (1.2.1-1ubuntu3) ... 543s Selecting previously unselected package libsrtp2-1:arm64. 543s Preparing to unpack .../43-libsrtp2-1_2.5.0-3build1_arm64.deb ... 543s Unpacking libsrtp2-1:arm64 (2.5.0-3build1) ... 544s Selecting previously unselected package freetds-common. 544s Preparing to unpack .../44-freetds-common_1.3.17+ds-2build3_all.deb ... 544s Unpacking freetds-common (1.3.17+ds-2build3) ... 544s Selecting previously unselected package libsybdb5:arm64. 544s Preparing to unpack .../45-libsybdb5_1.3.17+ds-2build3_arm64.deb ... 544s Unpacking libsybdb5:arm64 (1.3.17+ds-2build3) ... 544s Selecting previously unselected package libevent-2.1-7t64:arm64. 544s Preparing to unpack .../46-libevent-2.1-7t64_2.1.12-stable-10_arm64.deb ... 544s Unpacking libevent-2.1-7t64:arm64 (2.1.12-stable-10) ... 544s Selecting previously unselected package libunbound8:arm64. 544s Preparing to unpack .../47-libunbound8_1.20.0-1ubuntu2.1_arm64.deb ... 544s Unpacking libunbound8:arm64 (1.20.0-1ubuntu2.1) ... 544s Selecting previously unselected package libvo-amrwbenc0:arm64. 544s Preparing to unpack .../48-libvo-amrwbenc0_0.1.3-2build1_arm64.deb ... 544s Unpacking libvo-amrwbenc0:arm64 (0.1.3-2build1) ... 544s Selecting previously unselected package libvorbis0a:arm64. 544s Preparing to unpack .../49-libvorbis0a_1.3.7-2_arm64.deb ... 544s Unpacking libvorbis0a:arm64 (1.3.7-2) ... 544s Selecting previously unselected package libvorbisenc2:arm64. 544s Preparing to unpack .../50-libvorbisenc2_1.3.7-2_arm64.deb ... 544s Unpacking libvorbisenc2:arm64 (1.3.7-2) ... 544s Selecting previously unselected package libvorbisfile3:arm64. 544s Preparing to unpack .../51-libvorbisfile3_1.3.7-2_arm64.deb ... 544s Unpacking libvorbisfile3:arm64 (1.3.7-2) ... 544s Selecting previously unselected package asterisk-modules. 544s Preparing to unpack .../52-asterisk-modules_1%3a20.8.1~dfsg+~cs6.14.40431414-1_arm64.deb ... 544s Unpacking asterisk-modules (1:20.8.1~dfsg+~cs6.14.40431414-1) ... 544s Selecting previously unselected package liburiparser1:arm64. 544s Preparing to unpack .../53-liburiparser1_0.9.8+dfsg-1_arm64.deb ... 544s Unpacking liburiparser1:arm64 (0.9.8+dfsg-1) ... 544s Selecting previously unselected package libxslt1.1:arm64. 544s Preparing to unpack .../54-libxslt1.1_1.1.39-0exp1ubuntu1_arm64.deb ... 544s Unpacking libxslt1.1:arm64 (1.1.39-0exp1ubuntu1) ... 544s Selecting previously unselected package asterisk. 544s Preparing to unpack .../55-asterisk_1%3a20.8.1~dfsg+~cs6.14.40431414-1_arm64.deb ... 544s Unpacking asterisk (1:20.8.1~dfsg+~cs6.14.40431414-1) ... 544s Selecting previously unselected package autopkgtest-satdep. 544s Preparing to unpack .../56-2-autopkgtest-satdep.deb ... 544s Unpacking autopkgtest-satdep (0) ... 544s Setting up libsharpyuv0:arm64 (1.4.0-0.1) ... 544s Setting up libvo-amrwbenc0:arm64 (0.1.3-2build1) ... 544s Setting up libneon27t64:arm64 (0.33.0-1.1build3) ... 544s Setting up libogg0:arm64 (1.3.5-3build1) ... 544s Setting up liblerc4:arm64 (4.0.0+ds-4ubuntu2) ... 544s Setting up libspeex1:arm64 (1.2.1-2ubuntu3) ... 544s Setting up libgsm1:arm64 (1.0.22-1build1) ... 544s Setting up asterisk-core-sounds-en-gsm (1.6.1-1) ... 544s Setting up libsnmp-base (5.9.4+dfsg-1.1ubuntu5) ... 544s Setting up libcodec2-1.2:arm64 (1.2.0-2build1) ... 544s Setting up mlock (8:2007f~dfsg-7build3) ... 544s Setting up libsrtp2-1:arm64 (2.5.0-3build1) ... 544s Setting up libpq5:arm64 (17.0-1) ... 544s Setting up libdeflate0:arm64 (1.21-1) ... 544s Setting up libevent-2.1-7t64:arm64 (2.1.12-stable-10) ... 544s Setting up libb64-0d:arm64 (1.2-5build1) ... 544s Setting up libjwt2:arm64 (1.17.0-2build2) ... 544s Setting up libjbig0:arm64 (2.1-6.1ubuntu2) ... 544s Setting up libasound2-data (1.2.12-1) ... 544s Setting up libopencore-amrwb0:arm64 (0.1.6-1build1) ... 544s Setting up libunbound8:arm64 (1.20.0-1ubuntu2.1) ... 544s Setting up libasound2t64:arm64 (1.2.12-1) ... 544s Setting up libradcli4 (1.2.11-1build3) ... 544s Setting up libopus0:arm64 (1.5.2-2) ... 544s Setting up asterisk-config (1:20.8.1~dfsg+~cs6.14.40431414-1) ... 545s Setting up libvorbis0a:arm64 (1.3.7-2) ... 545s Setting up libical3t64:arm64 (3.0.18-1) ... 545s Setting up libjpeg-turbo8:arm64 (2.1.5-2ubuntu2) ... 545s Setting up libltdl7:arm64 (2.4.7-7build1) ... 545s Setting up asterisk-core-sounds-en (1.6.1-1) ... 545s update-alternatives: using /usr/share/asterisk/sounds/en_US_f_Allison to provide /usr/share/asterisk/sounds/en (asterisk-prompt-en) in auto mode 545s 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 545s Setting up libwebp7:arm64 (1.4.0-0.1) ... 545s Setting up libiksemel3:arm64 (1.4-4build2) ... 545s Setting up libodbc2:arm64 (2.3.12-1ubuntu1) ... 545s Setting up liburiparser1:arm64 (0.9.8+dfsg-1) ... 545s Setting up libspeexdsp1:arm64 (1.2.1-1ubuntu3) ... 545s Setting up liblua5.1-0:arm64 (5.1.5-9build2) ... 545s Setting up libxslt1.1:arm64 (1.1.39-0exp1ubuntu1) ... 545s Setting up libopencore-amrnb0:arm64 (0.1.6-1build1) ... 545s Setting up libc-client2007e (8:2007f~dfsg-7build3) ... 545s Setting up libresample1 (0.1.3-8) ... 545s Setting up freetds-common (1.3.17+ds-2build3) ... 545s Setting up libgmime-3.0-0t64:arm64 (3.2.15+dfsg-1) ... 545s Setting up libsamplerate0:arm64 (0.2.2-4build1) ... 545s Setting up libopusfile0:arm64 (0.12-4build3) ... 545s Setting up libvorbisenc2:arm64 (1.3.7-2) ... 545s Setting up libjpeg8:arm64 (8c-2ubuntu11) ... 545s Setting up libopusenc0:arm64 (0.2.1-2build1) ... 545s Setting up libsnmp40t64:arm64 (5.9.4+dfsg-1.1ubuntu5) ... 545s Setting up libsybdb5:arm64 (1.3.17+ds-2build3) ... 545s Setting up libvorbisfile3:arm64 (1.3.7-2) ... 545s Setting up libjack-jackd2-0:arm64 (1.9.21~dfsg-3ubuntu3) ... 545s Setting up libtiff6:arm64 (4.5.1+git230720-4ubuntu4) ... 545s Setting up libportaudio2:arm64 (19.6.0-1.2build3) ... 545s Setting up libspandsp2t64:arm64 (0.0.6+dfsg-2.1build1) ... 545s Setting up asterisk-modules (1:20.8.1~dfsg+~cs6.14.40431414-1) ... 545s Setting up asterisk (1:20.8.1~dfsg+~cs6.14.40431414-1) ... 545s Adding system user for Asterisk 545s info: Adding user `asterisk' to group `dialout' ... 545s info: Adding user `asterisk' to group `audio' ... 546s Created symlink '/etc/systemd/system/multi-user.target.wants/asterisk.service' → '/usr/lib/systemd/system/asterisk.service'. 547s Setting up autopkgtest-satdep (0) ... 547s Processing triggers for man-db (2.12.1-3) ... 548s Processing triggers for libc-bin (2.40-1ubuntu3) ... 554s (Reading database ... 81693 files and directories currently installed.) 554s Removing autopkgtest-satdep (0) ... 572s autopkgtest [10:18:49]: test amr: [----------------------- 573s 1 audio amr amr (AMR) 573s 2 audio amrwb amrwb (AMR-WB) 573s amr amrwb codec2 ulaw alaw gsm g726 g726aal2 adpcm slin8 slin12 slin16 slin24 slin32 slin44 slin48 slin96 slin192 lpc10 speex8 speex16 speex32 g722 opus 573s amr - 23000 15000 15000 15000 15000 15000 15000 15000 9000 17000 17000 17000 17000 17000 17000 17000 17000 15000 15000 23000 23000 17250 15000 573s amr amrwb codec2 ulaw alaw gsm g726 g726aal2 adpcm slin8 slin12 slin16 slin24 slin32 slin44 slin48 slin96 slin192 lpc10 speex8 speex16 speex32 g722 opus 573s amrwb 23500 - 23500 23500 23500 23500 23500 23500 23500 17500 17500 9000 17000 17000 17000 17000 17000 17000 23500 23500 15000 23000 15000 14999 573s autopkgtest [10:18:50]: test amr: -----------------------] 574s amr PASS 574s autopkgtest [10:18:51]: test amr: - - - - - - - - - - results - - - - - - - - - - 574s autopkgtest [10:18:51]: @@@@@@@@@@@@@@@@@@@@ summary 574s asttestmods PASS 574s amr PASS 590s nova [W] Skipping flock in bos03-arm64 590s Creating nova instance adt-plucky-arm64-asterisk-20241101-100917-juju-7f2275-prod-proposed-migration-environment-2-de71e4d2-0f5b-4d64-ae7d-32da51644ac5 from image adt/ubuntu-plucky-arm64-server-20241101.img (UUID 520a937f-514a-4e80-b76b-163a8c247e3e)... 590s nova [W] Skipping flock in bos03-arm64 590s Creating nova instance adt-plucky-arm64-asterisk-20241101-100917-juju-7f2275-prod-proposed-migration-environment-2-de71e4d2-0f5b-4d64-ae7d-32da51644ac5 from image adt/ubuntu-plucky-arm64-server-20241101.img (UUID 520a937f-514a-4e80-b76b-163a8c247e3e)...