1s autopkgtest [13:08:38]: starting date and time: 2025-03-14 13:08:38+0000 1s autopkgtest [13:08:38]: git checkout: 325255d2 Merge branch 'pin-any-arch' into 'ubuntu/production' 1s autopkgtest [13:08:38]: host juju-7f2275-prod-proposed-migration-environment-20; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.3tudxp9r/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:net-snmp --apt-upgrade asterisk --timeout-short=300 --timeout-copy=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=net-snmp/5.9.1+dfsg-1ubuntu2.8 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor builder-cpu2-ram4-disk20 --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-20@bos03-30.secgroup --name adt-jammy-amd64-asterisk-20250314-130237-juju-7f2275-prod-proposed-migration-environment-20-9ea724a9-8509-453e-888a-4cba7fc6cc57 --image adt/ubuntu-jammy-amd64-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-20 --net-id=net_prod-proposed-migration-amd64 -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com,radosgw.ps5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 59s autopkgtest [13:09:36]: testbed dpkg architecture: amd64 59s autopkgtest [13:09:36]: testbed apt version: 2.4.13 60s autopkgtest [13:09:37]: @@@@@@@@@@@@@@@@@@@@ test bed setup 60s autopkgtest [13:09:37]: testbed release detected to be: None 61s autopkgtest [13:09:38]: updating testbed package index (apt update) 61s Hit:1 http://ftpmaster.internal/ubuntu jammy InRelease 61s Hit:2 http://ftpmaster.internal/ubuntu jammy-updates InRelease 61s Hit:3 http://ftpmaster.internal/ubuntu jammy-security InRelease 61s Get:4 http://ftpmaster.internal/ubuntu jammy-proposed InRelease [279 kB] 62s Get:5 http://ftpmaster.internal/ubuntu jammy-proposed/restricted Sources [24.7 kB] 62s Get:6 http://ftpmaster.internal/ubuntu jammy-proposed/main Sources [113 kB] 62s Get:7 http://ftpmaster.internal/ubuntu jammy-proposed/universe Sources [29.3 kB] 62s Get:8 http://ftpmaster.internal/ubuntu jammy-proposed/main i386 Packages [103 kB] 62s Get:9 http://ftpmaster.internal/ubuntu jammy-proposed/main amd64 Packages [378 kB] 62s Get:10 http://ftpmaster.internal/ubuntu jammy-proposed/main amd64 c-n-f Metadata [2204 B] 62s Get:11 http://ftpmaster.internal/ubuntu jammy-proposed/restricted amd64 Packages [593 kB] 62s Get:12 http://ftpmaster.internal/ubuntu jammy-proposed/restricted i386 Packages [1704 B] 62s Get:13 http://ftpmaster.internal/ubuntu jammy-proposed/restricted amd64 c-n-f Metadata [116 B] 62s Get:14 http://ftpmaster.internal/ubuntu jammy-proposed/universe i386 Packages [34.8 kB] 62s Get:15 http://ftpmaster.internal/ubuntu jammy-proposed/universe amd64 Packages [89.5 kB] 62s Get:16 http://ftpmaster.internal/ubuntu jammy-proposed/universe amd64 c-n-f Metadata [1852 B] 62s Get:17 http://ftpmaster.internal/ubuntu jammy-proposed/multiverse amd64 c-n-f Metadata [116 B] 63s Fetched 1651 kB in 1s (1553 kB/s) 65s Reading package lists... 65s Reading package lists... 66s Building dependency tree... 66s Reading state information... 66s Calculating upgrade... 66s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 66s Reading package lists... 66s Building dependency tree... 66s Reading state information... 67s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 67s autopkgtest [13:09:44]: upgrading testbed (apt dist-upgrade and autopurge) 67s Reading package lists... 67s Building dependency tree... 67s Reading state information... 68s Calculating upgrade...Starting pkgProblemResolver with broken count: 0 68s Starting 2 pkgProblemResolver with broken count: 0 68s Done 68s Entering ResolveByKeep 69s 69s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 69s Reading package lists... 69s Building dependency tree... 69s Reading state information... 70s Starting pkgProblemResolver with broken count: 0 70s Starting 2 pkgProblemResolver with broken count: 0 70s Done 70s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 73s autopkgtest [13:09:50]: testbed running kernel: Linux 5.15.0-134-generic #145-Ubuntu SMP Wed Feb 12 20:08:39 UTC 2025 73s autopkgtest [13:09:50]: @@@@@@@@@@@@@@@@@@@@ apt-source asterisk 84s Get:1 http://ftpmaster.internal/ubuntu jammy/universe asterisk 1:18.10.0~dfsg+~cs6.10.40431411-2 (dsc) [5428 B] 84s Get:2 http://ftpmaster.internal/ubuntu jammy/universe asterisk 1:18.10.0~dfsg+~cs6.10.40431411-2 (tar) [11.3 kB] 84s Get:3 http://ftpmaster.internal/ubuntu jammy/universe asterisk 1:18.10.0~dfsg+~cs6.10.40431411-2 (tar) [21.9 kB] 84s Get:4 http://ftpmaster.internal/ubuntu jammy/universe asterisk 1:18.10.0~dfsg+~cs6.10.40431411-2 (tar) [22.5 kB] 84s Get:5 http://ftpmaster.internal/ubuntu jammy/universe asterisk 1:18.10.0~dfsg+~cs6.10.40431411-2 (tar) [5134 kB] 84s Get:6 http://ftpmaster.internal/ubuntu jammy/universe asterisk 1:18.10.0~dfsg+~cs6.10.40431411-2 (tar) [7238 kB] 84s Get:7 http://ftpmaster.internal/ubuntu jammy/universe asterisk 1:18.10.0~dfsg+~cs6.10.40431411-2 (diff) [129 kB] 84s gpgv: Signature made Sat Feb 12 18:51:03 2022 UTC 84s gpgv: using RSA key 9FE3E9C36691A69FF53CC6842C7C3146C1A00121 84s gpgv: Can't check signature: No public key 84s dpkg-source: warning: cannot verify signature ./asterisk_18.10.0~dfsg+~cs6.10.40431411-2.dsc 84s autopkgtest [13:10:00]: testing package asterisk version 1:18.10.0~dfsg+~cs6.10.40431411-2 85s autopkgtest [13:10:02]: build not needed 93s autopkgtest [13:10:10]: test asttestmods: preparing testbed 94s Reading package lists... 94s Building dependency tree... 94s Reading state information... 94s Starting pkgProblemResolver with broken count: 0 94s Starting 2 pkgProblemResolver with broken count: 0 94s Done 95s The following NEW packages will be installed: 95s asterisk asterisk-config asterisk-core-sounds-en asterisk-core-sounds-en-gsm 95s asterisk-modules asterisk-tests freetds-common libasound2 libasound2-data 95s libc-client2007e libcodec2-1.0 libdeflate0 libevent-2.1-7 libgmime-3.0-0 95s libgsm1 libical3 libiksemel3 libjack-jackd2-0 libjbig0 libjpeg-turbo8 95s libjpeg8 libltdl7 liblua5.2-0 libneon27 libodbc2 libogg0 libopencore-amrnb0 95s libopencore-amrwb0 libopus0 libopusfile0 libportaudio2 libpq5 libradcli4 95s libresample1 libsamplerate0 libsensors-config libsensors5 libsnmp-base 95s libsnmp40 libspandsp2 libspeex1 libspeexdsp1 libsrtp2-1 libsybdb5 libtiff5 95s libunbound8 liburiparser1 libvo-amrwbenc0 libvorbis0a libvorbisenc2 95s libvorbisfile3 libwebp7 libxml2-utils libxslt1.1 mlock 95s 0 upgraded, 55 newly installed, 0 to remove and 0 not upgraded. 95s Need to get 25.5 MB of archives. 95s After this operation, 68.7 MB of additional disk space will be used. 95s Get:1 http://ftpmaster.internal/ubuntu jammy/universe amd64 asterisk-config all 1:18.10.0~dfsg+~cs6.10.40431411-2 [234 kB] 95s Get:2 http://ftpmaster.internal/ubuntu jammy/universe amd64 asterisk-core-sounds-en-gsm all 1.6.1-1 [2417 kB] 95s Get:3 http://ftpmaster.internal/ubuntu jammy/universe amd64 asterisk-core-sounds-en all 1.6.1-1 [20.6 kB] 95s Get:4 http://ftpmaster.internal/ubuntu jammy/main amd64 libasound2-data all 1.2.6.1-1ubuntu1 [19.1 kB] 95s Get:5 http://ftpmaster.internal/ubuntu jammy/main amd64 libasound2 amd64 1.2.6.1-1ubuntu1 [390 kB] 95s Get:6 http://ftpmaster.internal/ubuntu jammy/universe amd64 mlock amd64 8:2007f~dfsg-7build1 [12.2 kB] 95s Get:7 http://ftpmaster.internal/ubuntu jammy/universe amd64 libc-client2007e amd64 8:2007f~dfsg-7build1 [645 kB] 95s Get:8 http://ftpmaster.internal/ubuntu jammy/universe amd64 libcodec2-1.0 amd64 1.0.1-3 [8435 kB] 96s Get:9 http://ftpmaster.internal/ubuntu jammy/universe amd64 libgmime-3.0-0 amd64 3.2.7-1 [157 kB] 96s Get:10 http://ftpmaster.internal/ubuntu jammy/universe amd64 libgsm1 amd64 1.0.19-1 [27.7 kB] 96s Get:11 http://ftpmaster.internal/ubuntu jammy/main amd64 libical3 amd64 3.0.14-1build1 [327 kB] 96s Get:12 http://ftpmaster.internal/ubuntu jammy/universe amd64 libiksemel3 amd64 1.4-4 [29.2 kB] 96s Get:13 http://ftpmaster.internal/ubuntu jammy/main amd64 libsamplerate0 amd64 0.2.2-1build1 [1359 kB] 96s Get:14 http://ftpmaster.internal/ubuntu jammy/main amd64 libjack-jackd2-0 amd64 1.9.20~dfsg-1 [293 kB] 96s Get:15 http://ftpmaster.internal/ubuntu jammy/universe amd64 liblua5.2-0 amd64 5.2.4-2 [125 kB] 96s Get:16 http://ftpmaster.internal/ubuntu jammy/universe amd64 libneon27 amd64 0.32.2-1 [102 kB] 96s Get:17 http://ftpmaster.internal/ubuntu jammy/main amd64 libltdl7 amd64 2.4.6-15build2 [39.6 kB] 96s Get:18 http://ftpmaster.internal/ubuntu jammy-updates/main amd64 libodbc2 amd64 2.3.9-5ubuntu0.1 [159 kB] 96s Get:19 http://ftpmaster.internal/ubuntu jammy/main amd64 libogg0 amd64 1.3.5-0ubuntu3 [22.9 kB] 96s Get:20 http://ftpmaster.internal/ubuntu jammy/universe amd64 libopencore-amrnb0 amd64 0.1.5-1 [94.8 kB] 96s Get:21 http://ftpmaster.internal/ubuntu jammy/universe amd64 libopencore-amrwb0 amd64 0.1.5-1 [49.1 kB] 96s Get:22 http://ftpmaster.internal/ubuntu jammy/main amd64 libopus0 amd64 1.3.1-0.1build2 [203 kB] 96s Get:23 http://ftpmaster.internal/ubuntu jammy/universe amd64 libopusfile0 amd64 0.9+20170913-1.1build1 [43.2 kB] 96s Get:24 http://ftpmaster.internal/ubuntu jammy/universe amd64 libportaudio2 amd64 19.6.0-1.1 [65.3 kB] 96s Get:25 http://ftpmaster.internal/ubuntu jammy-updates/main amd64 libpq5 amd64 14.17-0ubuntu0.22.04.1 [152 kB] 96s Get:26 http://ftpmaster.internal/ubuntu jammy/universe amd64 libradcli4 amd64 1.2.11-1build1 [40.0 kB] 96s Get:27 http://ftpmaster.internal/ubuntu jammy/universe amd64 libresample1 amd64 0.1.3-5 [9548 B] 96s Get:28 http://ftpmaster.internal/ubuntu jammy/main amd64 libsensors-config all 1:3.6.0-7ubuntu1 [5274 B] 96s Get:29 http://ftpmaster.internal/ubuntu jammy/main amd64 libsensors5 amd64 1:3.6.0-7ubuntu1 [26.3 kB] 96s Get:30 http://ftpmaster.internal/ubuntu jammy-proposed/main amd64 libsnmp-base all 5.9.1+dfsg-1ubuntu2.8 [201 kB] 96s Get:31 http://ftpmaster.internal/ubuntu jammy-proposed/main amd64 libsnmp40 amd64 5.9.1+dfsg-1ubuntu2.8 [1070 kB] 96s Get:32 http://ftpmaster.internal/ubuntu jammy/main amd64 libdeflate0 amd64 1.10-2 [70.9 kB] 96s Get:33 http://ftpmaster.internal/ubuntu jammy-updates/main amd64 libjbig0 amd64 2.1-3.1ubuntu0.22.04.1 [29.2 kB] 96s Get:34 http://ftpmaster.internal/ubuntu jammy/main amd64 libjpeg-turbo8 amd64 2.1.2-0ubuntu1 [134 kB] 96s Get:35 http://ftpmaster.internal/ubuntu jammy/main amd64 libjpeg8 amd64 8c-2ubuntu10 [2264 B] 96s Get:36 http://ftpmaster.internal/ubuntu jammy-updates/main amd64 libwebp7 amd64 1.2.2-2ubuntu0.22.04.2 [206 kB] 96s Get:37 http://ftpmaster.internal/ubuntu jammy-updates/main amd64 libtiff5 amd64 4.3.0-6ubuntu0.10 [185 kB] 96s Get:38 http://ftpmaster.internal/ubuntu jammy/universe amd64 libspandsp2 amd64 0.0.6+dfsg-2 [272 kB] 96s Get:39 http://ftpmaster.internal/ubuntu jammy/main amd64 libspeex1 amd64 1.2~rc1.2-1.1ubuntu3 [57.9 kB] 96s Get:40 http://ftpmaster.internal/ubuntu jammy/main amd64 libspeexdsp1 amd64 1.2~rc1.2-1.1ubuntu3 [42.5 kB] 96s Get:41 http://ftpmaster.internal/ubuntu jammy/universe amd64 libsrtp2-1 amd64 2.4.2-2 [40.7 kB] 96s Get:42 http://ftpmaster.internal/ubuntu jammy/main amd64 freetds-common all 1.3.6-1 [26.3 kB] 96s Get:43 http://ftpmaster.internal/ubuntu jammy/main amd64 libsybdb5 amd64 1.3.6-1 [194 kB] 96s Get:44 http://ftpmaster.internal/ubuntu jammy/main amd64 libevent-2.1-7 amd64 2.1.12-stable-1build3 [148 kB] 96s Get:45 http://ftpmaster.internal/ubuntu jammy-updates/main amd64 libunbound8 amd64 1.13.1-1ubuntu5.8 [400 kB] 96s Get:46 http://ftpmaster.internal/ubuntu jammy/universe amd64 libvo-amrwbenc0 amd64 0.1.3-2 [68.2 kB] 96s Get:47 http://ftpmaster.internal/ubuntu jammy/main amd64 libvorbis0a amd64 1.3.7-1build2 [99.2 kB] 96s Get:48 http://ftpmaster.internal/ubuntu jammy/main amd64 libvorbisenc2 amd64 1.3.7-1build2 [82.6 kB] 96s Get:49 http://ftpmaster.internal/ubuntu jammy/main amd64 libvorbisfile3 amd64 1.3.7-1build2 [17.1 kB] 96s Get:50 http://ftpmaster.internal/ubuntu jammy/universe amd64 asterisk-modules amd64 1:18.10.0~dfsg+~cs6.10.40431411-2 [3232 kB] 96s Get:51 http://ftpmaster.internal/ubuntu jammy/universe amd64 liburiparser1 amd64 0.9.6+dfsg-1 [36.4 kB] 96s Get:52 http://ftpmaster.internal/ubuntu jammy-updates/main amd64 libxslt1.1 amd64 1.1.34-4ubuntu0.22.04.1 [164 kB] 96s Get:53 http://ftpmaster.internal/ubuntu jammy/universe amd64 asterisk amd64 1:18.10.0~dfsg+~cs6.10.40431411-2 [2608 kB] 96s Get:54 http://ftpmaster.internal/ubuntu jammy/universe amd64 asterisk-tests amd64 1:18.10.0~dfsg+~cs6.10.40431411-2 [554 kB] 96s Get:55 http://ftpmaster.internal/ubuntu jammy-updates/main amd64 libxml2-utils amd64 2.9.13+dfsg-1ubuntu0.6 [40.2 kB] 97s Fetched 25.5 MB in 2s (14.5 MB/s) 97s Selecting previously unselected package asterisk-config. 97s (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 ... 67962 files and directories currently installed.) 97s Preparing to unpack .../00-asterisk-config_1%3a18.10.0~dfsg+~cs6.10.40431411-2_all.deb ... 97s Unpacking asterisk-config (1:18.10.0~dfsg+~cs6.10.40431411-2) ... 97s Selecting previously unselected package asterisk-core-sounds-en-gsm. 97s Preparing to unpack .../01-asterisk-core-sounds-en-gsm_1.6.1-1_all.deb ... 97s Unpacking asterisk-core-sounds-en-gsm (1.6.1-1) ... 97s Selecting previously unselected package asterisk-core-sounds-en. 97s Preparing to unpack .../02-asterisk-core-sounds-en_1.6.1-1_all.deb ... 97s Unpacking asterisk-core-sounds-en (1.6.1-1) ... 97s Selecting previously unselected package libasound2-data. 97s Preparing to unpack .../03-libasound2-data_1.2.6.1-1ubuntu1_all.deb ... 97s Unpacking libasound2-data (1.2.6.1-1ubuntu1) ... 97s Selecting previously unselected package libasound2:amd64. 97s Preparing to unpack .../04-libasound2_1.2.6.1-1ubuntu1_amd64.deb ... 97s Unpacking libasound2:amd64 (1.2.6.1-1ubuntu1) ... 97s Selecting previously unselected package mlock. 97s Preparing to unpack .../05-mlock_8%3a2007f~dfsg-7build1_amd64.deb ... 97s Unpacking mlock (8:2007f~dfsg-7build1) ... 97s Selecting previously unselected package libc-client2007e. 97s Preparing to unpack .../06-libc-client2007e_8%3a2007f~dfsg-7build1_amd64.deb ... 97s Unpacking libc-client2007e (8:2007f~dfsg-7build1) ... 97s Selecting previously unselected package libcodec2-1.0:amd64. 97s Preparing to unpack .../07-libcodec2-1.0_1.0.1-3_amd64.deb ... 97s Unpacking libcodec2-1.0:amd64 (1.0.1-3) ... 97s Selecting previously unselected package libgmime-3.0-0:amd64. 97s Preparing to unpack .../08-libgmime-3.0-0_3.2.7-1_amd64.deb ... 97s Unpacking libgmime-3.0-0:amd64 (3.2.7-1) ... 97s Selecting previously unselected package libgsm1:amd64. 97s Preparing to unpack .../09-libgsm1_1.0.19-1_amd64.deb ... 97s Unpacking libgsm1:amd64 (1.0.19-1) ... 97s Selecting previously unselected package libical3:amd64. 97s Preparing to unpack .../10-libical3_3.0.14-1build1_amd64.deb ... 97s Unpacking libical3:amd64 (3.0.14-1build1) ... 97s Selecting previously unselected package libiksemel3:amd64. 97s Preparing to unpack .../11-libiksemel3_1.4-4_amd64.deb ... 97s Unpacking libiksemel3:amd64 (1.4-4) ... 97s Selecting previously unselected package libsamplerate0:amd64. 97s Preparing to unpack .../12-libsamplerate0_0.2.2-1build1_amd64.deb ... 97s Unpacking libsamplerate0:amd64 (0.2.2-1build1) ... 97s Selecting previously unselected package libjack-jackd2-0:amd64. 97s Preparing to unpack .../13-libjack-jackd2-0_1.9.20~dfsg-1_amd64.deb ... 97s Unpacking libjack-jackd2-0:amd64 (1.9.20~dfsg-1) ... 98s Selecting previously unselected package liblua5.2-0:amd64. 98s Preparing to unpack .../14-liblua5.2-0_5.2.4-2_amd64.deb ... 98s Unpacking liblua5.2-0:amd64 (5.2.4-2) ... 98s Selecting previously unselected package libneon27:amd64. 98s Preparing to unpack .../15-libneon27_0.32.2-1_amd64.deb ... 98s Unpacking libneon27:amd64 (0.32.2-1) ... 98s Selecting previously unselected package libltdl7:amd64. 98s Preparing to unpack .../16-libltdl7_2.4.6-15build2_amd64.deb ... 98s Unpacking libltdl7:amd64 (2.4.6-15build2) ... 98s Selecting previously unselected package libodbc2:amd64. 98s Preparing to unpack .../17-libodbc2_2.3.9-5ubuntu0.1_amd64.deb ... 98s Unpacking libodbc2:amd64 (2.3.9-5ubuntu0.1) ... 98s Selecting previously unselected package libogg0:amd64. 98s Preparing to unpack .../18-libogg0_1.3.5-0ubuntu3_amd64.deb ... 98s Unpacking libogg0:amd64 (1.3.5-0ubuntu3) ... 98s Selecting previously unselected package libopencore-amrnb0:amd64. 98s Preparing to unpack .../19-libopencore-amrnb0_0.1.5-1_amd64.deb ... 98s Unpacking libopencore-amrnb0:amd64 (0.1.5-1) ... 98s Selecting previously unselected package libopencore-amrwb0:amd64. 98s Preparing to unpack .../20-libopencore-amrwb0_0.1.5-1_amd64.deb ... 98s Unpacking libopencore-amrwb0:amd64 (0.1.5-1) ... 98s Selecting previously unselected package libopus0:amd64. 98s Preparing to unpack .../21-libopus0_1.3.1-0.1build2_amd64.deb ... 98s Unpacking libopus0:amd64 (1.3.1-0.1build2) ... 98s Selecting previously unselected package libopusfile0. 98s Preparing to unpack .../22-libopusfile0_0.9+20170913-1.1build1_amd64.deb ... 98s Unpacking libopusfile0 (0.9+20170913-1.1build1) ... 98s Selecting previously unselected package libportaudio2:amd64. 98s Preparing to unpack .../23-libportaudio2_19.6.0-1.1_amd64.deb ... 98s Unpacking libportaudio2:amd64 (19.6.0-1.1) ... 98s Selecting previously unselected package libpq5:amd64. 98s Preparing to unpack .../24-libpq5_14.17-0ubuntu0.22.04.1_amd64.deb ... 98s Unpacking libpq5:amd64 (14.17-0ubuntu0.22.04.1) ... 98s Selecting previously unselected package libradcli4. 98s Preparing to unpack .../25-libradcli4_1.2.11-1build1_amd64.deb ... 98s Unpacking libradcli4 (1.2.11-1build1) ... 98s Selecting previously unselected package libresample1. 98s Preparing to unpack .../26-libresample1_0.1.3-5_amd64.deb ... 98s Unpacking libresample1 (0.1.3-5) ... 98s Selecting previously unselected package libsensors-config. 98s Preparing to unpack .../27-libsensors-config_1%3a3.6.0-7ubuntu1_all.deb ... 98s Unpacking libsensors-config (1:3.6.0-7ubuntu1) ... 98s Selecting previously unselected package libsensors5:amd64. 98s Preparing to unpack .../28-libsensors5_1%3a3.6.0-7ubuntu1_amd64.deb ... 98s Unpacking libsensors5:amd64 (1:3.6.0-7ubuntu1) ... 98s Selecting previously unselected package libsnmp-base. 98s Preparing to unpack .../29-libsnmp-base_5.9.1+dfsg-1ubuntu2.8_all.deb ... 98s Unpacking libsnmp-base (5.9.1+dfsg-1ubuntu2.8) ... 98s Selecting previously unselected package libsnmp40:amd64. 98s Preparing to unpack .../30-libsnmp40_5.9.1+dfsg-1ubuntu2.8_amd64.deb ... 98s Unpacking libsnmp40:amd64 (5.9.1+dfsg-1ubuntu2.8) ... 98s Selecting previously unselected package libdeflate0:amd64. 98s Preparing to unpack .../31-libdeflate0_1.10-2_amd64.deb ... 98s Unpacking libdeflate0:amd64 (1.10-2) ... 98s Selecting previously unselected package libjbig0:amd64. 98s Preparing to unpack .../32-libjbig0_2.1-3.1ubuntu0.22.04.1_amd64.deb ... 98s Unpacking libjbig0:amd64 (2.1-3.1ubuntu0.22.04.1) ... 98s Selecting previously unselected package libjpeg-turbo8:amd64. 98s Preparing to unpack .../33-libjpeg-turbo8_2.1.2-0ubuntu1_amd64.deb ... 98s Unpacking libjpeg-turbo8:amd64 (2.1.2-0ubuntu1) ... 98s Selecting previously unselected package libjpeg8:amd64. 98s Preparing to unpack .../34-libjpeg8_8c-2ubuntu10_amd64.deb ... 98s Unpacking libjpeg8:amd64 (8c-2ubuntu10) ... 98s Selecting previously unselected package libwebp7:amd64. 98s Preparing to unpack .../35-libwebp7_1.2.2-2ubuntu0.22.04.2_amd64.deb ... 98s Unpacking libwebp7:amd64 (1.2.2-2ubuntu0.22.04.2) ... 98s Selecting previously unselected package libtiff5:amd64. 98s Preparing to unpack .../36-libtiff5_4.3.0-6ubuntu0.10_amd64.deb ... 98s Unpacking libtiff5:amd64 (4.3.0-6ubuntu0.10) ... 98s Selecting previously unselected package libspandsp2:amd64. 98s Preparing to unpack .../37-libspandsp2_0.0.6+dfsg-2_amd64.deb ... 98s Unpacking libspandsp2:amd64 (0.0.6+dfsg-2) ... 98s Selecting previously unselected package libspeex1:amd64. 98s Preparing to unpack .../38-libspeex1_1.2~rc1.2-1.1ubuntu3_amd64.deb ... 98s Unpacking libspeex1:amd64 (1.2~rc1.2-1.1ubuntu3) ... 98s Selecting previously unselected package libspeexdsp1:amd64. 98s Preparing to unpack .../39-libspeexdsp1_1.2~rc1.2-1.1ubuntu3_amd64.deb ... 98s Unpacking libspeexdsp1:amd64 (1.2~rc1.2-1.1ubuntu3) ... 98s Selecting previously unselected package libsrtp2-1:amd64. 98s Preparing to unpack .../40-libsrtp2-1_2.4.2-2_amd64.deb ... 98s Unpacking libsrtp2-1:amd64 (2.4.2-2) ... 98s Selecting previously unselected package freetds-common. 98s Preparing to unpack .../41-freetds-common_1.3.6-1_all.deb ... 98s Unpacking freetds-common (1.3.6-1) ... 98s Selecting previously unselected package libsybdb5:amd64. 98s Preparing to unpack .../42-libsybdb5_1.3.6-1_amd64.deb ... 98s Unpacking libsybdb5:amd64 (1.3.6-1) ... 98s Selecting previously unselected package libevent-2.1-7:amd64. 98s Preparing to unpack .../43-libevent-2.1-7_2.1.12-stable-1build3_amd64.deb ... 98s Unpacking libevent-2.1-7:amd64 (2.1.12-stable-1build3) ... 98s Selecting previously unselected package libunbound8:amd64. 98s Preparing to unpack .../44-libunbound8_1.13.1-1ubuntu5.8_amd64.deb ... 98s Unpacking libunbound8:amd64 (1.13.1-1ubuntu5.8) ... 98s Selecting previously unselected package libvo-amrwbenc0:amd64. 98s Preparing to unpack .../45-libvo-amrwbenc0_0.1.3-2_amd64.deb ... 98s Unpacking libvo-amrwbenc0:amd64 (0.1.3-2) ... 98s Selecting previously unselected package libvorbis0a:amd64. 98s Preparing to unpack .../46-libvorbis0a_1.3.7-1build2_amd64.deb ... 98s Unpacking libvorbis0a:amd64 (1.3.7-1build2) ... 98s Selecting previously unselected package libvorbisenc2:amd64. 98s Preparing to unpack .../47-libvorbisenc2_1.3.7-1build2_amd64.deb ... 98s Unpacking libvorbisenc2:amd64 (1.3.7-1build2) ... 98s Selecting previously unselected package libvorbisfile3:amd64. 98s Preparing to unpack .../48-libvorbisfile3_1.3.7-1build2_amd64.deb ... 98s Unpacking libvorbisfile3:amd64 (1.3.7-1build2) ... 98s Selecting previously unselected package asterisk-modules. 98s Preparing to unpack .../49-asterisk-modules_1%3a18.10.0~dfsg+~cs6.10.40431411-2_amd64.deb ... 98s Unpacking asterisk-modules (1:18.10.0~dfsg+~cs6.10.40431411-2) ... 98s Selecting previously unselected package liburiparser1:amd64. 98s Preparing to unpack .../50-liburiparser1_0.9.6+dfsg-1_amd64.deb ... 98s Unpacking liburiparser1:amd64 (0.9.6+dfsg-1) ... 98s Selecting previously unselected package libxslt1.1:amd64. 98s Preparing to unpack .../51-libxslt1.1_1.1.34-4ubuntu0.22.04.1_amd64.deb ... 98s Unpacking libxslt1.1:amd64 (1.1.34-4ubuntu0.22.04.1) ... 98s Selecting previously unselected package asterisk. 98s Preparing to unpack .../52-asterisk_1%3a18.10.0~dfsg+~cs6.10.40431411-2_amd64.deb ... 98s Unpacking asterisk (1:18.10.0~dfsg+~cs6.10.40431411-2) ... 98s Selecting previously unselected package asterisk-tests. 98s Preparing to unpack .../53-asterisk-tests_1%3a18.10.0~dfsg+~cs6.10.40431411-2_amd64.deb ... 98s Unpacking asterisk-tests (1:18.10.0~dfsg+~cs6.10.40431411-2) ... 98s Selecting previously unselected package libxml2-utils. 98s Preparing to unpack .../54-libxml2-utils_2.9.13+dfsg-1ubuntu0.6_amd64.deb ... 98s Unpacking libxml2-utils (2.9.13+dfsg-1ubuntu0.6) ... 98s Setting up libgmime-3.0-0:amd64 (3.2.7-1) ... 98s Setting up libvo-amrwbenc0:amd64 (0.1.3-2) ... 98s Setting up libcodec2-1.0:amd64 (1.0.1-3) ... 98s Setting up libogg0:amd64 (1.3.5-0ubuntu3) ... 98s Setting up libspeex1:amd64 (1.2~rc1.2-1.1ubuntu3) ... 98s Setting up libgsm1:amd64 (1.0.19-1) ... 98s Setting up asterisk-core-sounds-en-gsm (1.6.1-1) ... 98s Setting up libsnmp-base (5.9.1+dfsg-1ubuntu2.8) ... 98s Setting up mlock (8:2007f~dfsg-7build1) ... 98s Setting up libsrtp2-1:amd64 (2.4.2-2) ... 98s Setting up libsensors-config (1:3.6.0-7ubuntu1) ... 98s Setting up libpq5:amd64 (14.17-0ubuntu0.22.04.1) ... 98s Setting up libdeflate0:amd64 (1.10-2) ... 98s Setting up libjbig0:amd64 (2.1-3.1ubuntu0.22.04.1) ... 98s Setting up libasound2-data (1.2.6.1-1ubuntu1) ... 98s Setting up libopencore-amrwb0:amd64 (0.1.5-1) ... 98s Setting up libradcli4 (1.2.11-1build1) ... 98s Setting up libopus0:amd64 (1.3.1-0.1build2) ... 98s Setting up asterisk-config (1:18.10.0~dfsg+~cs6.10.40431411-2) ... 98s Setting up libvorbis0a:amd64 (1.3.7-1build2) ... 98s Setting up libevent-2.1-7:amd64 (2.1.12-stable-1build3) ... 98s Setting up libsensors5:amd64 (1:3.6.0-7ubuntu1) ... 98s Setting up libjpeg-turbo8:amd64 (2.1.2-0ubuntu1) ... 98s Setting up libltdl7:amd64 (2.4.6-15build2) ... 98s Setting up asterisk-core-sounds-en (1.6.1-1) ... 98s update-alternatives: using /usr/share/asterisk/sounds/en_US_f_Allison to provide /usr/share/asterisk/sounds/en (asterisk-prompt-en) in auto mode 98s 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 98s Setting up libwebp7:amd64 (1.2.2-2ubuntu0.22.04.2) ... 98s Setting up libiksemel3:amd64 (1.4-4) ... 98s Setting up libodbc2:amd64 (2.3.9-5ubuntu0.1) ... 98s Setting up liburiparser1:amd64 (0.9.6+dfsg-1) ... 98s Setting up liblua5.2-0:amd64 (5.2.4-2) ... 98s Setting up libneon27:amd64 (0.32.2-1) ... 98s Setting up libspeexdsp1:amd64 (1.2~rc1.2-1.1ubuntu3) ... 98s Setting up libasound2:amd64 (1.2.6.1-1ubuntu1) ... 98s Setting up libxslt1.1:amd64 (1.1.34-4ubuntu0.22.04.1) ... 98s Setting up libopencore-amrnb0:amd64 (0.1.5-1) ... 98s Setting up libical3:amd64 (3.0.14-1build1) ... 98s Setting up libc-client2007e (8:2007f~dfsg-7build1) ... 98s Setting up libresample1 (0.1.3-5) ... 98s Setting up freetds-common (1.3.6-1) ... 98s Setting up libxml2-utils (2.9.13+dfsg-1ubuntu0.6) ... 98s Setting up libsamplerate0:amd64 (0.2.2-1build1) ... 98s Setting up libopusfile0 (0.9+20170913-1.1build1) ... 98s Setting up libvorbisenc2:amd64 (1.3.7-1build2) ... 98s Setting up libjpeg8:amd64 (8c-2ubuntu10) ... 98s Setting up libsybdb5:amd64 (1.3.6-1) ... 99s Setting up libvorbisfile3:amd64 (1.3.7-1build2) ... 99s Setting up libsnmp40:amd64 (5.9.1+dfsg-1ubuntu2.8) ... 99s Setting up libunbound8:amd64 (1.13.1-1ubuntu5.8) ... 99s Setting up libjack-jackd2-0:amd64 (1.9.20~dfsg-1) ... 99s Setting up libtiff5:amd64 (4.3.0-6ubuntu0.10) ... 99s Setting up libportaudio2:amd64 (19.6.0-1.1) ... 99s Setting up libspandsp2:amd64 (0.0.6+dfsg-2) ... 99s Setting up asterisk-modules (1:18.10.0~dfsg+~cs6.10.40431411-2) ... 99s Setting up asterisk (1:18.10.0~dfsg+~cs6.10.40431411-2) ... 99s Adding system user for Asterisk 99s ERROR: ld.so: object 'libeatmydata.so' from LD_PRELOAD cannot be preloaded (cannot open shared object file): ignored. 99s Adding user `asterisk' to group `dialout' ... 99s Adding user asterisk to group dialout 99s Done. 99s Adding user `asterisk' to group `audio' ... 99s Adding user asterisk to group audio 99s Done. 99s Created symlink /etc/systemd/system/multi-user.target.wants/asterisk.service → /lib/systemd/system/asterisk.service. 100s Setting up asterisk-tests (1:18.10.0~dfsg+~cs6.10.40431411-2) ... 100s Processing triggers for libc-bin (2.35-0ubuntu3.9) ... 100s Processing triggers for man-db (2.10.2-1) ... 101s autopkgtest [13:10:18]: test asttestmods: [----------------------- 102s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 103s Asterisk has fully booted. 103s Running all available tests... 103s 103s START /apps/app_gosub/ - gosub application 103s END /apps/app_gosub/ - gosub application Time: <1ms Result: PASS 103s START /apps/app_voicemail/ - test_voicemail_vm_info 103s END /apps/app_voicemail/ - test_voicemail_vm_info Time: <1ms Result: PASS 103s START /apps/app_voicemail/ - test_voicemail_load_config 103s END /apps/app_voicemail/ - test_voicemail_load_config Time: <1ms Result: PASS 103s START /apps/app_voicemail/ - test_voicemail_notify_endl 103s END /apps/app_voicemail/ - test_voicemail_notify_endl Time: 2ms Result: PASS 103s START /apps/app_voicemail/ - vmuser 103s END /apps/app_voicemail/ - vmuser Time: <1ms Result: PASS 103s START /apps/app_voicemail/ - test_voicemail_msgcount 103s END /apps/app_voicemail/ - test_voicemail_msgcount Time: 37ms Result: PASS 103s START /apps/app_voicemail/ - vmsayname_exec 103s [app_voicemail.c:test_voicemail_vmsayname:14433]: Test playing of extension when greeting is not available... 108s [app_voicemail.c:test_voicemail_vmsayname:14454]: Test playing created mailbox greeting... 112s END /apps/app_voicemail/ - vmsayname_exec Time: 8885ms Result: PASS 112s START /ari/validators/ - validate_list 112s END /ari/validators/ - validate_list Time: <1ms Result: PASS 112s START /ari/validators/ - validate_date 112s END /ari/validators/ - validate_date Time: <1ms Result: PASS 112s START /ari/validators/ - validate_string 112s END /ari/validators/ - validate_string Time: <1ms Result: PASS 112s START /ari/validators/ - validate_long 112s END /ari/validators/ - validate_long Time: <1ms Result: PASS 112s START /ari/validators/ - validate_int 112s END /ari/validators/ - validate_int Time: <1ms Result: PASS 112s START /ari/validators/ - validate_boolean 112s END /ari/validators/ - validate_boolean Time: <1ms Result: PASS 112s START /ari/validators/ - validate_byte 112s END /ari/validators/ - validate_byte Time: <1ms Result: PASS 112s START /bridges/bridge_softmix/ - sfu_remove_destination_streams 112s END /bridges/bridge_softmix/ - sfu_remove_destination_streams Time: <1ms Result: PASS 112s START /bridges/bridge_softmix/ - sfu_append_source_streams 112s END /bridges/bridge_softmix/ - sfu_append_source_streams Time: <1ms Result: PASS 112s START /channels/features/ - test_features_channel_interval 115s END /channels/features/ - test_features_channel_interval Time: 3002ms Result: PASS 115s START /channels/features/ - test_features_channel_dtmf 117s END /channels/features/ - test_features_channel_dtmf Time: 2014ms Result: PASS 117s START /config/ - config_options_test 117s END /config/ - config_options_test Time: <1ms Result: PASS 117s START /config/ - ast_parse_arg 117s END /config/ - ast_parse_arg Time: <1ms Result: PASS 117s START /core/endpoints/ - setters 117s END /core/endpoints/ - setters Time: <1ms Result: PASS 117s START /core/endpoints/ - defaults 117s END /core/endpoints/ - defaults Time: <1ms Result: PASS 117s START /core/endpoints/ - create 117s END /core/endpoints/ - create Time: <1ms Result: PASS 117s START /funcs/func_curl/ - vulnerable_url 117s END /funcs/func_curl/ - vulnerable_url Time: <1ms Result: PASS 117s START /funcs/func_env/ - func_file 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=a'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,1)=a'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-8)=a'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-8)=a'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5,1)=b'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4,1)=b'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5,-3)=b'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4,-3)=b'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2)=c'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,2)=c'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-7)=c'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-7)=c'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,4,2)=d'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-5,2)=d'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,4,-3)=d'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-5,-3)=d'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5)=e'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5)='... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4)=e'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4)='... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=fg'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-8)=fg'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,1)=fg'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-8)=fg'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,)=h'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,,)=h'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,l)=h'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,ld)=h'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abc'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=abc'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=abc'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=abc'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=abc'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=abc'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=abc'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=abc'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=ab'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=ab'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=ab'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=ab'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=ab'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=ab'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=ab'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=ab'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcdefg'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcdefg'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcdefg'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcdefg'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcdefg'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcdefg'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcdefg'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcdefg'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcdefghijklmnop'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcdefghijklmnop'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcdefghijklmnop'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcdefghijklmnop'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcdefghijklmnop'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcdefghijklmnop'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcdefghijklmnop'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcdefghijklmnop'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,0,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,0,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,0,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,0,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,2,0,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-1,0,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,3,0,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,la)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)='... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)='... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)='... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)='... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)='... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)='... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)='... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)='... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,ld)='... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,ld)='... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,ld)='... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,ld)='... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,ld)='... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,ld)='... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,ld)='... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,ld)='... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=a'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,10)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 117s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=a'... OK! 117s END /funcs/func_env/ - func_file Time: 39ms Result: PASS 117s START /funcs/func_json/ - func_JSON_DECODE 117s END /funcs/func_json/ - func_JSON_DECODE Time: <1ms Result: PASS 117s START /funcs/func_presence/ - test_presence_state_base64_encode 117s END /funcs/func_presence/ - test_presence_state_base64_encode Time: 7ms Result: PASS 117s START /funcs/func_presence/ - test_presence_state_change 117s END /funcs/func_presence/ - test_presence_state_change Time: <1ms Result: PASS 117s START /funcs/func_presence/ - parse_invalid_presence_data 117s END /funcs/func_presence/ - parse_invalid_presence_data Time: <1ms Result: PASS 117s START /funcs/func_presence/ - parse_valid_presence_data 117s END /funcs/func_presence/ - parse_valid_presence_data Time: <1ms Result: PASS 117s START /funcs/func_sayfiles/ - test_SAYFILES_function 117s [func_sayfiles.c:test_SAYFILES_function:175]: Testing SAYFILES() substitution ... 117s END /funcs/func_sayfiles/ - test_SAYFILES_function Time: 2ms Result: PASS 117s START /funcs/func_strings/ - func_STRBETWEEN 117s END /funcs/func_strings/ - func_STRBETWEEN Time: <1ms Result: PASS 117s START /funcs/func_strings/ - func_STRREPLACE_test 117s END /funcs/func_strings/ - func_STRREPLACE_test Time: <1ms Result: PASS 117s START /funcs/func_strings/ - func_FILTER_test 117s END /funcs/func_strings/ - func_FILTER_test Time: <1ms Result: PASS 117s START /funcs/func_strings/ - func_REPLACE_test 117s END /funcs/func_strings/ - func_REPLACE_test Time: <1ms Result: PASS 117s START /funcs/func_strings/ - func_FIELDNUM_test 117s END /funcs/func_strings/ - func_FIELDNUM_test Time: <1ms Result: PASS 117s START /main/abstract_jb/ - AST_JB_FIXED_put_out_of_order 117s [test_abstract_jb.c:AST_JB_FIXED_put_out_of_order:531]: Executing AST_JB_FIXED_put_out_of_order... 117s END /main/abstract_jb/ - AST_JB_FIXED_put_out_of_order Time: <1ms Result: PASS 117s START /main/abstract_jb/ - AST_JB_FIXED_put_overflow 117s [test_abstract_jb.c:AST_JB_FIXED_put_overflow:529]: Executing AST_JB_FIXED_put_overflow... 117s END /main/abstract_jb/ - AST_JB_FIXED_put_overflow Time: <1ms Result: PASS 117s START /main/abstract_jb/ - AST_JB_FIXED_put 117s [test_abstract_jb.c:AST_JB_FIXED_put:527]: Executing AST_JB_FIXED_put... 117s END /main/abstract_jb/ - AST_JB_FIXED_put Time: <1ms Result: PASS 117s START /main/abstract_jb/ - AST_JB_FIXED_put_first 117s [test_abstract_jb.c:AST_JB_FIXED_put_first:525]: Executing AST_JB_FIXED_create... 117s END /main/abstract_jb/ - AST_JB_FIXED_put_first Time: <1ms Result: PASS 117s START /main/abstract_jb/ - AST_JB_FIXED_create 117s [test_abstract_jb.c:AST_JB_FIXED_create:523]: Executing AST_JB_FIXED_create... 117s END /main/abstract_jb/ - AST_JB_FIXED_create Time: <1ms Result: PASS 117s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_out_of_order 117s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_out_of_order:521]: Executing AST_JB_ADAPTIVE_put_out_of_order... 117s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_out_of_order Time: <1ms Result: PASS 117s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_overflow 117s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_overflow:519]: Executing AST_JB_ADAPTIVE_put_overflow... 117s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_overflow Time: <1ms Result: PASS 117s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put 117s [test_abstract_jb.c:AST_JB_ADAPTIVE_put:517]: Executing AST_JB_ADAPTIVE_put... 117s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put Time: <1ms Result: PASS 117s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_first 117s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_first:515]: Executing AST_JB_ADAPTIVE_create... 117s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_first Time: <1ms Result: PASS 117s START /main/abstract_jb/ - AST_JB_ADAPTIVE_create 117s [test_abstract_jb.c:AST_JB_ADAPTIVE_create:513]: Executing AST_JB_ADAPTIVE_create... 117s END /main/abstract_jb/ - AST_JB_ADAPTIVE_create Time: <1ms Result: PASS 117s START /main/acl/ - acl 117s END /main/acl/ - acl Time: <1ms Result: PASS 117s START /main/acl/ - invalid_acl 117s END /main/acl/ - invalid_acl Time: <1ms Result: PASS 117s START /main/amihooks/ - amihook_cli_send 117s END /main/amihooks/ - amihook_cli_send Time: <1ms Result: PASS 117s START /main/aoc/ - aoc_event_test 117s END /main/aoc/ - aoc_event_test Time: <1ms Result: PASS 117s START /main/aoc/ - aoc_encode_decode_test 117s END /main/aoc/ - aoc_encode_decode_test Time: <1ms Result: PASS 117s START /main/app/ - options_parsing 117s END /main/app/ - options_parsing Time: <1ms Result: PASS 117s START /main/app/ - app_group 117s [test_app.c:app_group:172]: Creating test channels with the following groups: 117s 'a groupgroupgroup', 'a groupGroupgroup', 'a group@a_category', 'a group@another!Category' 117s [test_app.c:app_group:211]: (Subtest 1) Found 4 matches as expected when examining group:'gr' category:'' 117s [test_app.c:app_group:211]: (Subtest 2) Found 1 matches as expected when examining group:'(group){2}$' category:'' 117s [test_app.c:app_group:211]: (Subtest 3) Found 4 matches as expected when examining group:'[:ascii:]' category:'' 117s [test_app.c:app_group:211]: (Subtest 4) Found 0 matches as expected when examining group:'^(NOMATCH)' category:'' 117s [test_app.c:app_group:211]: (Subtest 5) Found 2 matches as expected when examining group:'a group' category:'(gory)$' 117s [test_app.c:app_group:211]: (Subtest 6) Found 1 matches as expected when examining group:'a group' category:'[A-Z]+' 117s [test_app.c:app_group:211]: (Subtest 7) Found 0 matches as expected when examining group:'a group' category:'[[' 117s END /main/app/ - app_group Time: <1ms Result: PASS 117s START /main/ast_expr/ - expr_test 117s END /main/ast_expr/ - expr_test Time: <1ms Result: PASS 117s START /main/astdb/ - put_get_long 117s END /main/astdb/ - put_get_long Time: 80ms Result: PASS 117s START /main/astdb/ - perftest 118s END /main/astdb/ - perftest Time: 276ms Result: PASS 118s START /main/astdb/ - gettree_deltree 118s END /main/astdb/ - gettree_deltree Time: <1ms Result: PASS 118s START /main/astdb/ - put_get_del 118s END /main/astdb/ - put_get_del Time: <1ms Result: PASS 118s START /main/astobj2/ - thrash 118s [test_astobj2_thrash.c:hash_test:266]: Executing hash concurrency test... 118s END /main/astobj2/ - thrash Time: 17ms Result: PASS 118s START /main/astobj2/ - astobj2_weak_container 118s END /main/astobj2/ - astobj2_weak_container Time: <1ms Result: PASS 118s START /main/astobj2/ - astobj2_weak1 118s END /main/astobj2/ - astobj2_weak1 Time: <1ms Result: PASS 118s START /main/astobj2/ - astobj2_test4 118s [test_astobj2.c:test_traversal_nonsorted:1389]: Test 1, List containers. 118s [test_astobj2.c:test_traversal_nonsorted:1389]: Test 2, Hash containers. 118s [test_astobj2.c:test_traversal_sorted:1615]: Test 3, List containers. 118s [test_astobj2.c:test_traversal_sorted:1615]: Test 4, Hash containers. 118s [test_astobj2.c:test_traversal_sorted:1615]: Test 5, RBTree containers. 118s END /main/astobj2/ - astobj2_test4 Time: <1ms Result: PASS 118s START /main/astobj2/ - astobj2_test3 118s END /main/astobj2/ - astobj2_test3 Time: <1ms Result: PASS 118s START /main/astobj2/ - astobj2_test2 118s END /main/astobj2/ - astobj2_test2 Time: <1ms Result: PASS 118s START /main/astobj2/ - astobj2_test1 118s [test_astobj2.c:astobj2_test_1_helper:434]: Test 1, List containers (non-sorted). 118s [test_astobj2.c:astobj2_test_1_helper:488]: List container created: buckets: 1, items: 50 118s [test_astobj2.c:astobj2_test_1_helper:434]: Test 2, List containers (sorted). 118s [test_astobj2.c:astobj2_test_1_helper:488]: List container created: buckets: 1, items: 50 118s [test_astobj2.c:astobj2_test_1_helper:434]: Test 3, Hash containers (non-sorted). 118s [test_astobj2.c:astobj2_test_1_helper:488]: Hash container created: buckets: 148, items: 1000 118s [test_astobj2.c:astobj2_test_1_helper:434]: Test 4, Hash containers (sorted). 118s [test_astobj2.c:astobj2_test_1_helper:488]: Hash container created: buckets: 31, items: 1000 118s [test_astobj2.c:astobj2_test_1_helper:434]: Test 4, RBTree containers (sorted). 118s [test_astobj2.c:astobj2_test_1_helper:488]: RBTree container created: buckets: 1, items: 1000 118s END /main/astobj2/ - astobj2_test1 Time: 11ms Result: PASS 118s START /main/astobj2/perf/ - astobj2_test_perf 118s [test_astobj2.c:testloop:2001]: 20.00K traversals, List 119s [test_astobj2.c:testloop:2001]: 40.00K traversals, List 120s [test_astobj2.c:testloop:2001]: 60.00K traversals, List 120s [test_astobj2.c:testloop:2001]: 80.00K traversals, List 121s [test_astobj2.c:testloop:2006]: 100.00K traversals, List : 3680 ms 122s [test_astobj2.c:testloop:2001]: 20.00K traversals, Hash 122s [test_astobj2.c:testloop:2001]: 40.00K traversals, Hash 123s [test_astobj2.c:testloop:2001]: 60.00K traversals, Hash 123s [test_astobj2.c:testloop:2001]: 80.00K traversals, Hash 124s [test_astobj2.c:testloop:2006]: 100.00K traversals, Hash : 2232 ms 124s [test_astobj2.c:testloop:2001]: 20.00K traversals, RBTree 125s [test_astobj2.c:testloop:2001]: 40.00K traversals, RBTree 125s [test_astobj2.c:testloop:2001]: 60.00K traversals, RBTree 126s [test_astobj2.c:testloop:2001]: 80.00K traversals, RBTree 126s [test_astobj2.c:testloop:2006]: 100.00K traversals, RBTree : 2734 ms 126s END /main/astobj2/perf/ - astobj2_test_perf Time: 8648ms Result: PASS 126s START /main/bridging/ - test_bridging_deferred_queue 127s END /main/bridging/ - test_bridging_deferred_queue Time: 1013ms Result: PASS 127s START /main/bucket/ - bucket_file_json 127s END /main/bucket/ - bucket_file_json Time: 2ms Result: PASS 127s START /main/bucket/ - bucket_file_metadata_get 127s END /main/bucket/ - bucket_file_metadata_get Time: <1ms Result: PASS 127s START /main/bucket/ - bucket_file_metadata_unset 127s END /main/bucket/ - bucket_file_metadata_unset Time: <1ms Result: PASS 127s START /main/bucket/ - bucket_file_metadata_set 127s END /main/bucket/ - bucket_file_metadata_set Time: <1ms Result: PASS 127s START /main/bucket/ - bucket_file_is_stale 127s END /main/bucket/ - bucket_file_is_stale Time: <1ms Result: PASS 127s START /main/bucket/ - bucket_file_delete 127s END /main/bucket/ - bucket_file_delete Time: <1ms Result: PASS 127s START /main/bucket/ - bucket_file_update 127s END /main/bucket/ - bucket_file_update Time: <1ms Result: PASS 127s START /main/bucket/ - bucket_file_retrieve 127s END /main/bucket/ - bucket_file_retrieve Time: <1ms Result: PASS 127s START /main/bucket/ - bucket_file_copy 127s END /main/bucket/ - bucket_file_copy Time: <1ms Result: PASS 127s START /main/bucket/ - bucket_file_clone 127s END /main/bucket/ - bucket_file_clone Time: <1ms Result: PASS 127s START /main/bucket/ - bucket_file_create 127s END /main/bucket/ - bucket_file_create Time: <1ms Result: PASS 127s START /main/bucket/ - bucket_file_alloc 127s END /main/bucket/ - bucket_file_alloc Time: <1ms Result: PASS 127s START /main/bucket/ - bucket_json 127s END /main/bucket/ - bucket_json Time: <1ms Result: PASS 127s START /main/bucket/ - bucket_is_stale 127s END /main/bucket/ - bucket_is_stale Time: <1ms Result: PASS 127s START /main/bucket/ - bucket_retrieve 127s END /main/bucket/ - bucket_retrieve Time: <1ms Result: PASS 127s START /main/bucket/ - bucket_delete 127s END /main/bucket/ - bucket_delete Time: <1ms Result: PASS 127s START /main/bucket/ - bucket_clone 127s END /main/bucket/ - bucket_clone Time: <1ms Result: PASS 127s START /main/bucket/ - bucket_create 127s END /main/bucket/ - bucket_create Time: <1ms Result: PASS 127s START /main/bucket/ - bucket_alloc 127s END /main/bucket/ - bucket_alloc Time: <1ms Result: PASS 127s START /main/bucket/ - bucket_scheme_register_unregister 127s END /main/bucket/ - bucket_scheme_register_unregister Time: <1ms Result: PASS 127s START /main/callerid/ - parse_off_nominal 127s END /main/callerid/ - parse_off_nominal Time: <1ms Result: PASS 127s START /main/callerid/ - parse_nominal 127s END /main/callerid/ - parse_nominal Time: <1ms Result: PASS 127s START /main/cdr/ - test_cdr_fork_cdr 129s Verifying expected record CDRTestChannel/Alice, 129s Finished expected record CDRTestChannel/Alice, 129s Verifying expected record CDRTestChannel/Alice, 129s Finished expected record CDRTestChannel/Alice, 129s Verifying expected record CDRTestChannel/Alice, 129s Finished expected record CDRTestChannel/Alice, 129s END /main/cdr/ - test_cdr_fork_cdr Time: 2002ms Result: PASS 129s START /main/cdr/ - test_cdr_no_reset_cdr 130s Verifying expected record CDRTestChannel/Alice, 130s Finished expected record CDRTestChannel/Alice, 130s END /main/cdr/ - test_cdr_no_reset_cdr Time: 1000ms Result: PASS 130s START /main/cdr/ - test_cdr_fields 132s Verifying expected record CDRTestChannel/Alice, 132s Finished expected record CDRTestChannel/Alice, 132s Verifying expected record CDRTestChannel/Alice, 132s Finished expected record CDRTestChannel/Alice, 132s Verifying expected record CDRTestChannel/Alice, 132s Finished expected record CDRTestChannel/Alice, 132s END /main/cdr/ - test_cdr_fields Time: 2001ms Result: PASS 132s START /main/cdr/ - test_cdr_park 135s Verifying expected record CDRTestChannel/Alice, 135s Finished expected record CDRTestChannel/Alice, 135s Verifying expected record CDRTestChannel/Bob, 135s Finished expected record CDRTestChannel/Bob, 135s END /main/cdr/ - test_cdr_park Time: 3002ms Result: PASS 135s START /main/cdr/ - test_cdr_dial_answer_multiparty 140s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 140s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 140s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 140s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 140s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/David 140s Finished expected record CDRTestChannel/Alice, CDRTestChannel/David 140s Verifying expected record CDRTestChannel/Bob, CDRTestChannel/David 140s Finished expected record CDRTestChannel/Bob, CDRTestChannel/David 140s Verifying expected record CDRTestChannel/Charlie, CDRTestChannel/David 140s Finished expected record CDRTestChannel/Charlie, CDRTestChannel/David 140s Verifying expected record CDRTestChannel/Charlie, CDRTestChannel/Bob 140s Finished expected record CDRTestChannel/Charlie, CDRTestChannel/Bob 140s END /main/cdr/ - test_cdr_dial_answer_multiparty Time: 5004ms Result: PASS 140s START /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_b 143s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 143s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 143s END /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_b Time: 3002ms Result: PASS 143s START /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_a 145s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 145s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 145s END /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_a Time: 2005ms Result: PASS 145s START /main/cdr/ - test_cdr_dial_answer_no_bridge 145s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 145s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 145s Verifying expected record CDRTestChannel/Alice, 145s Finished expected record CDRTestChannel/Alice, 145s Verifying expected record CDRTestChannel/Bob, 145s Finished expected record CDRTestChannel/Bob, 145s END /main/cdr/ - test_cdr_dial_answer_no_bridge Time: <1ms Result: PASS 145s START /main/cdr/ - test_cdr_dial_parallel_failed 145s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 145s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 145s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 145s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 145s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/David 145s Finished expected record CDRTestChannel/Alice, CDRTestChannel/David 145s END /main/cdr/ - test_cdr_dial_parallel_failed Time: 1ms Result: PASS 145s START /main/cdr/ - test_cdr_dial_caller_cancel 145s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 145s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 145s END /main/cdr/ - test_cdr_dial_caller_cancel Time: <1ms Result: PASS 145s START /main/cdr/ - test_cdr_dial_unavailable 145s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 145s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 145s END /main/cdr/ - test_cdr_dial_unavailable Time: <1ms Result: PASS 145s START /main/cdr/ - test_cdr_dial_busy 145s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 145s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 145s END /main/cdr/ - test_cdr_dial_busy Time: <1ms Result: PASS 145s START /main/cdr/ - test_cdr_dial_congestion 145s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 145s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 145s END /main/cdr/ - test_cdr_dial_congestion Time: <1ms Result: PASS 145s START /main/cdr/ - test_cdr_dial_unanswered 145s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 145s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 145s END /main/cdr/ - test_cdr_dial_unanswered Time: <1ms Result: PASS 145s START /main/cdr/ - test_cdr_outbound_bridged_call 148s Verifying expected record CDRTestChannel/Bob, 148s Finished expected record CDRTestChannel/Bob, 148s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 148s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 148s END /main/cdr/ - test_cdr_outbound_bridged_call Time: 3002ms Result: PASS 148s START /main/cdr/ - test_cdr_single_multiparty_bridge 152s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 152s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 152s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 152s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 152s Verifying expected record CDRTestChannel/Bob, CDRTestChannel/Charlie 152s Finished expected record CDRTestChannel/Bob, CDRTestChannel/Charlie 152s Verifying expected record CDRTestChannel/Charlie, 152s Finished expected record CDRTestChannel/Charlie, 152s END /main/cdr/ - test_cdr_single_multiparty_bridge Time: 4003ms Result: PASS 152s START /main/cdr/ - test_cdr_single_twoparty_bridge_b 155s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 155s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 155s Verifying expected record CDRTestChannel/Bob, 155s Finished expected record CDRTestChannel/Bob, 155s END /main/cdr/ - test_cdr_single_twoparty_bridge_b Time: 3001ms Result: PASS 155s START /main/cdr/ - test_cdr_single_twoparty_bridge_a 157s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 157s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 157s Verifying expected record CDRTestChannel/Bob, 157s Finished expected record CDRTestChannel/Bob, 157s END /main/cdr/ - test_cdr_single_twoparty_bridge_a Time: 2001ms Result: PASS 157s START /main/cdr/ - test_cdr_single_bridge_continue 159s Verifying expected record CDRTestChannel/Alice, 159s Finished expected record CDRTestChannel/Alice, 159s Verifying expected record CDRTestChannel/Alice, 159s Finished expected record CDRTestChannel/Alice, 159s END /main/cdr/ - test_cdr_single_bridge_continue Time: 2001ms Result: PASS 159s START /main/cdr/ - test_cdr_single_bridge 161s Verifying expected record CDRTestChannel/Alice, 161s Finished expected record CDRTestChannel/Alice, 161s END /main/cdr/ - test_cdr_single_bridge Time: 2001ms Result: PASS 161s START /main/cdr/ - test_cdr_single_party 161s Verifying expected record CDRTestChannel/Alice, 161s Finished expected record CDRTestChannel/Alice, 161s END /main/cdr/ - test_cdr_single_party Time: <1ms Result: PASS 161s START /main/cdr/ - test_cdr_unanswered_outbound_call 161s Verifying expected record CDRTestChannel/Alice, 161s Finished expected record CDRTestChannel/Alice, 161s END /main/cdr/ - test_cdr_unanswered_outbound_call Time: <1ms Result: PASS 161s START /main/cdr/ - test_cdr_unanswered_inbound_call 161s Verifying expected record CDRTestChannel/Alice, 161s Finished expected record CDRTestChannel/Alice, 161s END /main/cdr/ - test_cdr_unanswered_inbound_call Time: <1ms Result: PASS 161s START /main/cdr/ - test_cdr_channel_creation 161s Verifying expected record CDRTestChannel/Alice, 161s Finished expected record CDRTestChannel/Alice, 161s END /main/cdr/ - test_cdr_channel_creation Time: <1ms Result: PASS 161s START /main/channel/ - add_fd 161s END /main/channel/ - add_fd Time: <1ms Result: PASS 161s START /main/channel/ - set_fd_grow 161s END /main/channel/ - set_fd_grow Time: <1ms Result: PASS 161s START /main/config/ - variable_lists_match 161s END /main/config/ - variable_lists_match Time: <1ms Result: PASS 161s START /main/config/ - config_dialplan_function 161s END /main/config/ - config_dialplan_function Time: <1ms Result: PASS 161s START /main/config/ - config_hook 161s END /main/config/ - config_hook Time: <1ms Result: PASS 161s START /main/config/ - copy_config 161s END /main/config/ - copy_config Time: <1ms Result: PASS 161s START /main/config/ - config_template_ops 161s END /main/config/ - config_template_ops Time: <1ms Result: PASS 161s START /main/config/ - config_filtered_ops 161s END /main/config/ - config_filtered_ops Time: <1ms Result: PASS 161s START /main/config/ - config_basic_ops 161s END /main/config/ - config_basic_ops Time: <1ms Result: PASS 161s START /main/config/ - config_save 161s END /main/config/ - config_save Time: <1ms Result: PASS 161s START /main/conversions/ - str_to_umax 161s END /main/conversions/ - str_to_umax Time: <1ms Result: PASS 161s START /main/conversions/ - str_to_imax 161s END /main/conversions/ - str_to_imax Time: <1ms Result: PASS 161s START /main/conversions/ - str_to_ulong 161s END /main/conversions/ - str_to_ulong Time: <1ms Result: PASS 161s START /main/conversions/ - str_to_long 161s END /main/conversions/ - str_to_long Time: <1ms Result: PASS 161s START /main/conversions/ - str_to_uint 161s END /main/conversions/ - str_to_uint Time: <1ms Result: PASS 161s START /main/conversions/ - str_to_int 161s END /main/conversions/ - str_to_int Time: <1ms Result: PASS 161s START /main/core_codec/ - codec_get_unknown 161s END /main/core_codec/ - codec_get_unknown Time: <1ms Result: PASS 161s START /main/core_codec/ - codec_get_unknown 161s END /main/core_codec/ - codec_get_unknown Time: <1ms Result: PASS 161s START /main/core_codec/ - codec_get_unregistered 161s END /main/core_codec/ - codec_get_unregistered Time: <1ms Result: PASS 161s START /main/core_codec/ - codec_get 161s END /main/core_codec/ - codec_get Time: <1ms Result: PASS 161s START /main/core_codec/ - codec_register_audio_no_sample_rate 161s END /main/core_codec/ - codec_register_audio_no_sample_rate Time: <1ms Result: PASS 161s START /main/core_codec/ - codec_register_unknown 161s END /main/core_codec/ - codec_register_unknown Time: <1ms Result: PASS 161s START /main/core_codec/ - codec_register_twice 161s END /main/core_codec/ - codec_register_twice Time: <1ms Result: PASS 161s START /main/core_codec/ - codec_register 161s END /main/core_codec/ - codec_register Time: <1ms Result: PASS 161s START /main/core_format/ - format_parse_and_generate_sdp_fmtp 161s END /main/core_format/ - format_parse_and_generate_sdp_fmtp Time: <1ms Result: PASS 161s START /main/core_format/ - format_parse_sdp_fmtp_without_interface 161s END /main/core_format/ - format_parse_sdp_fmtp_without_interface Time: <1ms Result: PASS 161s START /main/core_format/ - format_attribute_get_without_interface 161s END /main/core_format/ - format_attribute_get_without_interface Time: <1ms Result: PASS 161s START /main/core_format/ - format_attribute_set_without_interface 161s END /main/core_format/ - format_attribute_set_without_interface Time: <1ms Result: PASS 161s START /main/core_format/ - format_copy 161s END /main/core_format/ - format_copy Time: <1ms Result: PASS 161s START /main/core_format/ - format_joint_different_codec 161s END /main/core_format/ - format_joint_different_codec Time: <1ms Result: PASS 161s START /main/core_format/ - format_attr_joint_same_codec 161s END /main/core_format/ - format_attr_joint_same_codec Time: <1ms Result: PASS 161s START /main/core_format/ - format_joint_same_codec 161s END /main/core_format/ - format_joint_same_codec Time: <1ms Result: PASS 161s START /main/core_format/ - format_cmp_different_codec 161s END /main/core_format/ - format_cmp_different_codec Time: <1ms Result: PASS 161s START /main/core_format/ - format_attr_cmp_same_codec 161s END /main/core_format/ - format_attr_cmp_same_codec Time: <1ms Result: PASS 161s START /main/core_format/ - format_cmp_same_codec 161s END /main/core_format/ - format_cmp_same_codec Time: <1ms Result: PASS 161s START /main/core_format/ - format_clone 161s END /main/core_format/ - format_clone Time: <1ms Result: PASS 161s START /main/core_format/ - format_retrieve_attr 161s END /main/core_format/ - format_retrieve_attr Time: <1ms Result: PASS 161s START /main/core_format/ - format_create_attr 161s END /main/core_format/ - format_create_attr Time: <1ms Result: PASS 161s START /main/core_format/ - format_create 161s END /main/core_format/ - format_create Time: <1ms Result: PASS 161s START /main/data_buffer/ - buffer_nominal 161s END /main/data_buffer/ - buffer_nominal Time: <1ms Result: PASS 161s START /main/data_buffer/ - buffer_resize 161s END /main/data_buffer/ - buffer_resize Time: <1ms Result: PASS 161s START /main/data_buffer/ - buffer_put 161s END /main/data_buffer/ - buffer_put Time: <1ms Result: PASS 161s START /main/data_buffer/ - buffer_create 161s END /main/data_buffer/ - buffer_create Time: <1ms Result: PASS 161s START /main/devicestate/ - devstate_channels 161s END /main/devicestate/ - devstate_channels Time: <1ms Result: PASS 161s START /main/devicestate/ - devstate_conversions 161s END /main/devicestate/ - devstate_conversions Time: <1ms Result: PASS 161s START /main/devicestate/ - devstate_changed 161s [test_devicestate.c:wait_for_device_state_updates:308]: Received 8 of 8 updates 161s [test_devicestate.c:devstate_changed:716]: Testing update 0: actual is 1; expected is 1 161s [test_devicestate.c:devstate_changed:716]: Testing update 1: actual is 2; expected is 2 161s [test_devicestate.c:devstate_changed:716]: Testing update 2: actual is 3; expected is 3 161s [test_devicestate.c:devstate_changed:716]: Testing update 3: actual is 4; expected is 4 161s [test_devicestate.c:devstate_changed:716]: Testing update 4: actual is 5; expected is 5 161s [test_devicestate.c:devstate_changed:716]: Testing update 5: actual is 6; expected is 6 161s [test_devicestate.c:devstate_changed:716]: Testing update 6: actual is 7; expected is 7 161s [test_devicestate.c:devstate_changed:716]: Testing update 7: actual is 8; expected is 8 161s [test_devicestate.c:wait_for_device_state_updates:308]: Received 1 of 1 updates 161s [test_devicestate.c:wait_for_device_state_updates:308]: Received 8 of 8 updates 161s [test_devicestate.c:devstate_changed:754]: Testing update 0: actual is 1; expected is 1 161s [test_devicestate.c:devstate_changed:754]: Testing update 1: actual is 2; expected is 2 161s [test_devicestate.c:devstate_changed:754]: Testing update 2: actual is 3; expected is 3 161s [test_devicestate.c:devstate_changed:754]: Testing update 3: actual is 4; expected is 4 161s [test_devicestate.c:devstate_changed:754]: Testing update 4: actual is 5; expected is 5 161s [test_devicestate.c:devstate_changed:754]: Testing update 5: actual is 6; expected is 6 161s [test_devicestate.c:devstate_changed:754]: Testing update 6: actual is 7; expected is 7 161s [test_devicestate.c:devstate_changed:754]: Testing update 7: actual is 8; expected is 8 161s END /main/devicestate/ - devstate_changed Time: <1ms Result: PASS 161s START /main/devicestate/ - devstate_prov_del 161s END /main/devicestate/ - devstate_prov_del Time: <1ms Result: PASS 161s START /main/devicestate/ - devstate_prov_add 161s END /main/devicestate/ - devstate_prov_add Time: <1ms Result: PASS 161s START /main/devicestate/ - device2extenstate_test 161s END /main/devicestate/ - device2extenstate_test Time: <1ms Result: PASS 161s START /main/devicestate/ - device_state_aggregation_test 161s END /main/devicestate/ - device_state_aggregation_test Time: <1ms Result: PASS 161s START /main/dns/ - resolver_resolve_async_cancel 161s END /main/dns/ - resolver_resolve_async_cancel Time: <1ms Result: PASS 161s START /main/dns/ - resolver_resolve_async_off_nominal 161s END /main/dns/ - resolver_resolve_async_off_nominal Time: <1ms Result: PASS 161s START /main/dns/ - resolver_resolve_async 166s END /main/dns/ - resolver_resolve_async Time: 5000ms Result: PASS 166s START /main/dns/ - resolver_resolve_sync_off_nominal 166s END /main/dns/ - resolver_resolve_sync_off_nominal Time: <1ms Result: PASS 166s START /main/dns/ - resolver_resolve_sync 171s END /main/dns/ - resolver_resolve_sync Time: 5000ms Result: PASS 171s START /main/dns/ - resolver_add_record_off_nominal 171s END /main/dns/ - resolver_add_record_off_nominal Time: <1ms Result: PASS 171s START /main/dns/ - resolver_add_record 171s END /main/dns/ - resolver_add_record Time: <1ms Result: PASS 171s START /main/dns/ - resolver_set_result_off_nominal 171s END /main/dns/ - resolver_set_result_off_nominal Time: <1ms Result: PASS 171s START /main/dns/ - resolver_set_result 171s END /main/dns/ - resolver_set_result Time: <1ms Result: PASS 171s START /main/dns/ - resolver_data 171s END /main/dns/ - resolver_data Time: <1ms Result: PASS 171s START /main/dns/ - resolver_unregister_off_nominal 171s END /main/dns/ - resolver_unregister_off_nominal Time: <1ms Result: PASS 171s START /main/dns/ - resolver_register_off_nominal 171s END /main/dns/ - resolver_register_off_nominal Time: <1ms Result: PASS 171s START /main/dns/ - resolver_register_unregister 171s END /main/dns/ - resolver_register_unregister Time: <1ms Result: PASS 171s START /main/dns/naptr/ - naptr_resolve_off_nominal_interactions 171s END /main/dns/naptr/ - naptr_resolve_off_nominal_interactions Time: <1ms Result: PASS 171s START /main/dns/naptr/ - naptr_resolve_off_nominal_regexp 171s END /main/dns/naptr/ - naptr_resolve_off_nominal_regexp Time: <1ms Result: PASS 171s START /main/dns/naptr/ - naptr_resolve_off_nominal_services 171s END /main/dns/naptr/ - naptr_resolve_off_nominal_services Time: <1ms Result: PASS 171s START /main/dns/naptr/ - naptr_resolve_off_nominal_flags 171s END /main/dns/naptr/ - naptr_resolve_off_nominal_flags Time: <1ms Result: PASS 171s START /main/dns/naptr/ - naptr_resolve_off_nominal_length 171s END /main/dns/naptr/ - naptr_resolve_off_nominal_length Time: <1ms Result: PASS 171s START /main/dns/naptr/ - naptr_resolve 171s END /main/dns/naptr/ - naptr_resolve Time: <1ms Result: PASS 171s START /main/dns/query_set/ - query_set_off_nominal_cancel 171s END /main/dns/query_set/ - query_set_off_nominal_cancel Time: <1ms Result: PASS 171s START /main/dns/query_set/ - query_set_nominal_cancel 171s END /main/dns/query_set/ - query_set_nominal_cancel Time: <1ms Result: PASS 171s START /main/dns/query_set/ - query_set_empty 171s END /main/dns/query_set/ - query_set_empty Time: <1ms Result: PASS 171s START /main/dns/query_set/ - query_set 171s END /main/dns/query_set/ - query_set Time: <1ms Result: PASS 171s START /main/dns/recurring/ - recurring_query_cancel_during 171s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 178s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 188s END /main/dns/recurring/ - recurring_query_cancel_during Time: 17002ms Result: PASS 188s START /main/dns/recurring/ - recurring_query_cancel_between 188s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 199s END /main/dns/recurring/ - recurring_query_cancel_between Time: 10001ms Result: PASS 199s START /main/dns/recurring/ - recurring_query_off_nominal 199s END /main/dns/recurring/ - recurring_query_off_nominal Time: <1ms Result: PASS 199s START /main/dns/recurring/ - recurring_query 199s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 205s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 217s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 217s END /main/dns/recurring/ - recurring_query Time: 18999ms Result: PASS 217s START /main/dns/srv/ - srv_resolve_record_missing_host 217s END /main/dns/srv/ - srv_resolve_record_missing_host Time: <1ms Result: PASS 217s START /main/dns/srv/ - srv_resolve_record_missing_port_host 217s END /main/dns/srv/ - srv_resolve_record_missing_port_host Time: <1ms Result: PASS 217s START /main/dns/srv/ - srv_resolve_record_missing_weight_port_host 217s END /main/dns/srv/ - srv_resolve_record_missing_weight_port_host Time: <1ms Result: PASS 217s START /main/dns/srv/ - srv_resolve_different_priorities_different_weights 217s END /main/dns/srv/ - srv_resolve_different_priorities_different_weights Time: 3ms Result: PASS 217s START /main/dns/srv/ - srv_resolve_same_priority_different_weights 217s END /main/dns/srv/ - srv_resolve_same_priority_different_weights Time: 2ms Result: PASS 217s START /main/dns/srv/ - srv_resolve_same_priority_zero_weight 217s END /main/dns/srv/ - srv_resolve_same_priority_zero_weight Time: <1ms Result: PASS 217s START /main/dns/srv/ - srv_resolve_sort_priority 217s END /main/dns/srv/ - srv_resolve_sort_priority Time: <1ms Result: PASS 217s START /main/dns/srv/ - srv_resolve_single_record 217s END /main/dns/srv/ - srv_resolve_single_record Time: <1ms Result: PASS 217s START /main/dsp/ - dtmf 217s END /main/dsp/ - dtmf Time: 2ms Result: PASS 217s START /main/dsp/ - fax 218s END /main/dsp/ - fax Time: 351ms Result: PASS 218s START /main/event/ - ast_event_new_test 218s [test_event.c:event_new_test:125]: First, test dynamic event creation... 218s [test_event.c:check_event:88]: Event looks good. 218s [test_event.c:check_event:88]: Event looks good. 218s END /main/event/ - ast_event_new_test Time: <1ms Result: PASS 218s START /main/file/ - ast_format_str_reduce_test_1 218s END /main/file/ - ast_format_str_reduce_test_1 Time: <1ms Result: PASS 218s START /main/file/ - read_dir_test 218s END /main/file/ - read_dir_test Time: <1ms Result: PASS 218s START /main/format_cache/ - format_cache_get_nonxistent 218s END /main/format_cache/ - format_cache_get_nonxistent Time: <1ms Result: PASS 218s START /main/format_cache/ - format_cache_get 218s END /main/format_cache/ - format_cache_get Time: <1ms Result: PASS 218s START /main/format_cache/ - format_cache_set_null 218s END /main/format_cache/ - format_cache_set_null Time: <1ms Result: PASS 218s START /main/format_cache/ - format_cache_set_duplicate 218s END /main/format_cache/ - format_cache_set_duplicate Time: <1ms Result: PASS 218s START /main/format_cache/ - format_cache_set 218s END /main/format_cache/ - format_cache_set Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_replace_from_cap 218s END /main/format_cap/ - format_cap_replace_from_cap Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_best_by_type 218s END /main/format_cap/ - format_cap_best_by_type Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_iscompatible 218s END /main/format_cap/ - format_cap_iscompatible Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_get_compatible 218s END /main/format_cap/ - format_cap_get_compatible Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_iscompatible_format 218s END /main/format_cap/ - format_cap_iscompatible_format Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_get_compatible_format 218s END /main/format_cap/ - format_cap_get_compatible_format Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_get_names 218s END /main/format_cap/ - format_cap_get_names Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_remove_all 218s END /main/format_cap/ - format_cap_remove_all Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_remove_bytype 218s END /main/format_cap/ - format_cap_remove_bytype Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_remove_multiple 218s END /main/format_cap/ - format_cap_remove_multiple Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_remove_single 218s END /main/format_cap/ - format_cap_remove_single Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_set_framing 218s END /main/format_cap/ - format_cap_set_framing Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_append_from_cap_duplicate 218s END /main/format_cap/ - format_cap_append_from_cap_duplicate Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_append_from_cap 218s END /main/format_cap/ - format_cap_append_from_cap Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_append_duplicate 218s END /main/format_cap/ - format_cap_append_duplicate Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_append_all_audio 218s END /main/format_cap/ - format_cap_append_all_audio Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_append_all_unknown 218s END /main/format_cap/ - format_cap_append_all_unknown Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_append_multiple 218s END /main/format_cap/ - format_cap_append_multiple Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_append_single 218s END /main/format_cap/ - format_cap_append_single Time: <1ms Result: PASS 218s START /main/format_cap/ - format_cap_alloc 218s END /main/format_cap/ - format_cap_alloc Time: <1ms Result: PASS 218s START /main/hashtab/ - thrash 218s [test_hashtab_thrash.c:hash_test:246]: Executing hash concurrency test... 218s END /main/hashtab/ - thrash Time: 17ms Result: PASS 218s START /main/heap/ - heap_test_3 218s END /main/heap/ - heap_test_3 Time: 84ms Result: PASS 218s START /main/heap/ - heap_test_2 218s END /main/heap/ - heap_test_2 Time: 79ms Result: PASS 218s START /main/heap/ - heap_test_1 218s END /main/heap/ - heap_test_1 Time: <1ms Result: PASS 218s START /main/jitterbuf/ - jitterbuffer_resynch_control 218s END /main/jitterbuf/ - jitterbuffer_resynch_control Time: <1ms Result: PASS 218s START /main/jitterbuf/ - jitterbuffer_resynch_voice 218s END /main/jitterbuf/ - jitterbuffer_resynch_voice Time: <1ms Result: PASS 218s START /main/jitterbuf/ - jitterbuffer_overflow_control 218s END /main/jitterbuf/ - jitterbuffer_overflow_control Time: <1ms Result: PASS 218s START /main/jitterbuf/ - jitterbuffer_overflow_voice 218s END /main/jitterbuf/ - jitterbuffer_overflow_voice Time: <1ms Result: PASS 218s START /main/jitterbuf/ - jitterbuffer_late_control 218s END /main/jitterbuf/ - jitterbuffer_late_control Time: <1ms Result: PASS 218s START /main/jitterbuf/ - jitterbuffer_late_voice 218s END /main/jitterbuf/ - jitterbuffer_late_voice Time: <1ms Result: PASS 218s START /main/jitterbuf/ - jitterbuffer_lost_control 218s END /main/jitterbuf/ - jitterbuffer_lost_control Time: <1ms Result: PASS 218s START /main/jitterbuf/ - jitterbuffer_lost_voice 218s END /main/jitterbuf/ - jitterbuffer_lost_voice Time: <1ms Result: PASS 218s START /main/jitterbuf/ - jitterbuffer_out_of_order_voice 218s END /main/jitterbuf/ - jitterbuffer_out_of_order_voice Time: <1ms Result: PASS 218s START /main/jitterbuf/ - jitterbuffer_out_of_order_voice 218s END /main/jitterbuf/ - jitterbuffer_out_of_order_voice Time: <1ms Result: PASS 218s START /main/jitterbuf/ - jitterbuffer_nominal_control_frames 218s END /main/jitterbuf/ - jitterbuffer_nominal_control_frames Time: <1ms Result: PASS 218s START /main/jitterbuf/ - jitterbuffer_nominal_voice_frames 218s END /main/jitterbuf/ - jitterbuffer_nominal_voice_frames Time: <1ms Result: PASS 218s START /main/json/ - cep 218s END /main/json/ - cep Time: <1ms Result: PASS 218s START /main/json/ - type_timeval 218s END /main/json/ - type_timeval Time: <1ms Result: PASS 218s START /main/json/ - name_number 218s END /main/json/ - name_number Time: <1ms Result: PASS 218s START /main/json/ - clever_circle 218s END /main/json/ - clever_circle Time: <1ms Result: PASS 218s START /main/json/ - circular_array 218s END /main/json/ - circular_array Time: <1ms Result: PASS 218s START /main/json/ - circular_object 218s END /main/json/ - circular_object Time: <1ms Result: PASS 218s START /main/json/ - copy_null 218s END /main/json/ - copy_null Time: <1ms Result: PASS 218s START /main/json/ - deep_copy 218s END /main/json/ - deep_copy Time: <1ms Result: PASS 218s START /main/json/ - copy 218s END /main/json/ - copy Time: <1ms Result: PASS 218s START /main/json/ - object_alloc 218s END /main/json/ - object_alloc Time: 1ms Result: PASS 218s START /main/json/ - pack_ownership 218s END /main/json/ - pack_ownership Time: <1ms Result: PASS 218s START /main/json/ - pack 218s END /main/json/ - pack Time: <1ms Result: PASS 218s START /main/json/ - parse_errors 218s END /main/json/ - parse_errors Time: <1ms Result: PASS 218s START /main/json/ - dump_load_null 218s END /main/json/ - dump_load_null Time: <1ms Result: PASS 218s START /main/json/ - dump_load_new_file 218s END /main/json/ - dump_load_new_file Time: <1ms Result: PASS 218s START /main/json/ - dump_load_file 218s END /main/json/ - dump_load_file Time: <1ms Result: PASS 218s START /main/json/ - load_buffer 218s END /main/json/ - load_buffer Time: <1ms Result: PASS 218s START /main/json/ - dump_str_fail 218s END /main/json/ - dump_str_fail Time: <1ms Result: PASS 218s START /main/json/ - dump_load_str 218s END /main/json/ - dump_load_str Time: <1ms Result: PASS 218s START /main/json/ - dump_load_string 218s END /main/json/ - dump_load_string Time: <1ms Result: PASS 218s START /main/json/ - object_create_vars 218s END /main/json/ - object_create_vars Time: <1ms Result: PASS 218s START /main/json/ - object_iter_null 218s END /main/json/ - object_iter_null Time: <1ms Result: PASS 218s START /main/json/ - object_iter 218s END /main/json/ - object_iter Time: <1ms Result: PASS 218s START /main/json/ - object_null 218s END /main/json/ - object_null Time: <1ms Result: PASS 218s START /main/json/ - object_merge_missing 218s END /main/json/ - object_merge_missing Time: <1ms Result: PASS 218s START /main/json/ - object_alloc 218s END /main/json/ - object_alloc Time: <1ms Result: PASS 218s START /main/json/ - object_alloc 218s END /main/json/ - object_alloc Time: <1ms Result: PASS 218s START /main/json/ - object_clear 218s END /main/json/ - object_clear Time: <1ms Result: PASS 218s START /main/json/ - object_del 218s END /main/json/ - object_del Time: <1ms Result: PASS 218s START /main/json/ - object_get 218s END /main/json/ - object_get Time: <1ms Result: PASS 218s START /main/json/ - object_set_overwriting 218s END /main/json/ - object_set_overwriting Time: <1ms Result: PASS 218s START /main/json/ - object_set 218s END /main/json/ - object_set Time: <1ms Result: PASS 218s START /main/json/ - object_alloc 218s END /main/json/ - object_alloc Time: <1ms Result: PASS 218s START /main/json/ - array_null 218s END /main/json/ - array_null Time: <1ms Result: PASS 218s START /main/json/ - array_extend 218s END /main/json/ - array_extend Time: <1ms Result: PASS 218s START /main/json/ - array_clear 218s END /main/json/ - array_clear Time: <1ms Result: PASS 218s START /main/json/ - array_remove 218s END /main/json/ - array_remove Time: <1ms Result: PASS 218s START /main/json/ - array_set 218s END /main/json/ - array_set Time: <1ms Result: PASS 218s START /main/json/ - array_insert 218s END /main/json/ - array_insert Time: <1ms Result: PASS 218s START /main/json/ - array_append 218s END /main/json/ - array_append Time: <1ms Result: PASS 218s START /main/json/ - array_create 218s END /main/json/ - array_create Time: <1ms Result: PASS 218s START /main/json/ - non_int 218s END /main/json/ - non_int Time: <1ms Result: PASS 218s START /main/json/ - type_int 218s END /main/json/ - type_int Time: <1ms Result: PASS 218s START /main/json/ - stringf 218s END /main/json/ - stringf Time: <1ms Result: PASS 218s START /main/json/ - string_null 218s END /main/json/ - string_null Time: <1ms Result: PASS 218s START /main/json/ - type_string 218s END /main/json/ - type_string Time: <1ms Result: PASS 218s START /main/json/ - null_val 218s END /main/json/ - null_val Time: <1ms Result: PASS 218s START /main/json/ - type_null 218s END /main/json/ - type_null Time: <1ms Result: PASS 218s START /main/json/ - type_bool1 218s END /main/json/ - type_bool1 Time: <1ms Result: PASS 218s START /main/json/ - type_bool0 218s END /main/json/ - type_bool0 Time: <1ms Result: PASS 218s START /main/json/ - type_true 218s END /main/json/ - type_true Time: <1ms Result: PASS 218s START /main/json/ - type_false 218s END /main/json/ - type_false Time: <1ms Result: PASS 218s START /main/linkedlists/ - double_ll_tests 218s END /main/linkedlists/ - double_ll_tests Time: <1ms Result: PASS 218s START /main/linkedlists/ - ll_tests 218s END /main/linkedlists/ - ll_tests Time: <1ms Result: PASS 218s START /main/lock/ - named_lock_test 218s [test_named_lock.c:named_lock_test:80]: This test should take about 3 seconds 221s END /main/lock/ - named_lock_test Time: 3000ms Result: PASS 221s START /main/lock/ - cleanup_order_test 221s [test_scoped_lock.c:test_ref:149]: Ref is occurring 221s [test_scoped_lock.c:test_lock:117]: Lock is occurring 221s [test_scoped_lock.c:test_unlock:133]: Unlock is occurring 221s [test_scoped_lock.c:test_unref:166]: Unref is occurring 221s [test_scoped_lock.c:test_ref:149]: Ref is occurring 221s [test_scoped_lock.c:test_lock:117]: Lock is occurring 221s [test_scoped_lock.c:test_unlock:133]: Unlock is occurring 221s [test_scoped_lock.c:test_unref:166]: Unref is occurring 221s END /main/lock/ - cleanup_order_test Time: <1ms Result: PASS 221s START /main/lock/ - lock_test 221s END /main/lock/ - lock_test Time: <1ms Result: PASS 221s START /main/logging/ - scope_test 221s END /main/logging/ - scope_test Time: <1ms Result: PASS 221s START /main/media_cache/ - create_update_off_nominal 221s END /main/media_cache/ - create_update_off_nominal Time: <1ms Result: PASS 221s START /main/media_cache/ - create_update_metadata 221s [test_media_cache.c:create_update_metadata:364]: Got /tmp/test-media-cache-GmIrsF for second file path 221s END /main/media_cache/ - create_update_metadata Time: 4ms Result: PASS 221s START /main/media_cache/ - create_update_nominal 221s [test_media_cache.c:create_update_nominal:235]: Creating resource with /tmp/test-media-cache-Zcd7gR 221s [test_media_cache.c:create_update_nominal:240]: Got /tmp/test-media-cache-Zcd7gR for first file path 221s [test_media_cache.c:create_update_nominal:244]: Creating resource with /tmp/test-media-cache-EimieZ 221s [test_media_cache.c:create_update_nominal:249]: Got /tmp/test-media-cache-EimieZ for second file path 221s END /main/media_cache/ - create_update_nominal Time: <1ms Result: PASS 221s START /main/media_cache/ - exists_off_nominal 221s END /main/media_cache/ - exists_off_nominal Time: <1ms Result: PASS 221s START /main/media_cache/ - exists_nominal 221s END /main/media_cache/ - exists_nominal Time: <1ms Result: PASS 221s START /main/netsock2/ - split_hostport 221s END /main/netsock2/ - split_hostport Time: <1ms Result: PASS 221s START /main/netsock2/ - parsing 221s END /main/netsock2/ - parsing Time: <1ms Result: PASS 221s START /main/optional_api/ - test_provide_last 221s END /main/optional_api/ - test_provide_last Time: <1ms Result: PASS 221s START /main/optional_api/ - test_provide_first 221s END /main/optional_api/ - test_provide_first Time: <1ms Result: PASS 221s START /main/pbx/ - pattern_match_test 221s [test_pbx.c:test_exten:183]: Successfully matched 200 to exten _2. in context test_pattern with the old pattern match engine 221s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the old pattern match engine 221s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the old pattern match engine 221s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern_include with the old pattern match engine 221s [test_pbx.c:test_exten:183]: Successfully matched 200 to exten _2. in context test_pattern with the new pattern match engine 221s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the new pattern match engine 221s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the new pattern match engine 221s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern_include with the new pattern match engine 221s END /main/pbx/ - pattern_match_test Time: <1ms Result: PASS 221s START /main/pbx/ - test_substitution 221s [test_substitution.c:test_substitution:244]: Testing variable substitution ... 221s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGANI2}' . . . . . passed 221s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGTON}' . . . . . passed 221s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGTNS}' . . . . . passed 221s [test_substitution.c:test_chan_integer_accessor:89]: Tested '${HANGUPCAUSE}' . . . . . passed 221s [test_substitution.c:test_chan_integer_accessor:89]: Tested '${PRIORITY}' . . . . . passed 221s [test_substitution.c:test_chan_string:115]: Tested '${CONTEXT}' . . . . . passed 221s [test_substitution.c:test_chan_string:115]: Tested '${EXTEN}' . . . . . passed 221s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(language)}' . . . . . passed 221s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(musicclass)}' . . . . . passed 221s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(parkinglot)}' . . . . . passed 221s [test_substitution.c:test_chan_variable:144]: Tested '${CALLERID(name)}' . . . . . passed 221s [test_substitution.c:test_chan_variable:144]: Tested '${CURLOPT(proxyuserpwd)}' . . . . . passed 221s [test_substitution.c:test_chan_variable:144]: Tested '${CDR(foo)}' . . . . . passed 221s [test_substitution.c:test_chan_variable:144]: Tested '${ENV(foo)}' . . . . . passed 221s [test_substitution.c:test_chan_variable:144]: Tested '${GLOBAL(foo)}' . . . . . passed 221s [test_substitution.c:test_chan_variable:144]: Tested '${GROUP()}' . . . . . passed 221s [test_substitution.c:test_2way_function:193]: Tested '${AES_ENCRYPT(abcdefghijklmnop,)}' and '${AES_DECRYPT(abcdefghijklmnop,)}' . . . . . passed 221s [test_substitution.c:test_2way_function:193]: Tested '${BASE64_ENCODE()}' and '${BASE64_DECODE()}' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested '123123' ('${foo}${foo}') == '123123' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested 'A123A123A' ('A${foo}A${foo}A') == 'A123A123A' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested 'A123A' ('A${${bar}}A') == 'A123A' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested 'A123A' ('A${${baz}o}A') == 'A123A' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested 'A23A' ('A${${baz}o:1}A') == 'A23A' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:1:1}A') == 'A2A' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:1:-1}A') == 'A2A' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested 'A3A' ('A${${baz}o:-1:1}A') == 'A3A' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:-2:1}A') == 'A2A' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:-2:-1}A') == 'A2A' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested 'cd&ef' ('${LISTFILTER(list1,&,ab)}') == 'cd&ef' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested 'ab&ef' ('${LISTFILTER(list1,&,cd)}') == 'ab&ef' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd' ('${LISTFILTER(list1,&,ef)}') == 'ab&cd' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,gh)}') == 'ab&cd&ef' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,c)}') == 'ab&cd&ef' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,d)}') == 'ab&cd&ef' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested '' ('${LISTFILTER(list2,&,ab)}') == '' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested '' ('${LISTFILTER(list_empty,&,ab)}') == '' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested '123,456' ('${SHELL(printf '%d' 123)},${SHELL(printf '%d' 456)}') == '123,456' . . . . . passed 221s [test_substitution.c:test_expected_result:215]: Tested '123,,456' ('${foo},${CDR(answer)},${SHELL(printf '%d' 456)}') == '123,,456' . . . . . passed 221s [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 221s [test_substitution.c:test_expected_result:215]: Tested '123,,' ('${foo},${this_does_not_exist},${THIS_DOES_NOT_EXIST(either)}') == '123,,' . . . . . passed 221s [test_substitution.c:test_chan_function:168]: Tested '${BLACKLIST(foo)}' . . . . . passed 221s [test_substitution.c:test_chan_function:168]: Tested '${EVAL(foo)}' . . . . . passed 221s [test_substitution.c:test_chan_function:168]: Tested '${FIELDNUM(foo)}' . . . . . passed 221s [test_substitution.c:test_chan_function:168]: Tested '${FIELDQTY(foo)}' . . . . . passed 221s [test_substitution.c:test_chan_function:168]: Tested '${HASHKEYS(foo)}' . . . . . passed 221s [test_substitution.c:test_chan_function:168]: Tested '${IMPORT(foo)}' . . . . . passed 221s [test_substitution.c:test_chan_function:168]: Tested '${PP_EACH_USER(foo)}' . . . . . passed 221s [test_substitution.c:test_chan_function:168]: Tested '${TOLOWER(foo)}' . . . . . passed 221s [test_substitution.c:test_chan_function:168]: Tested '${TOUPPER(foo)}' . . . . . passed 221s END /main/pbx/ - test_substitution Time: 12ms Result: PASS 221s START /main/pbx/ - test_MATH_function 221s [func_math.c:test_MATH_function:660]: Testing MATH() substitution ... 221s END /main/pbx/ - test_MATH_function Time: <1ms Result: PASS 221s START /main/poll/ - poll_test 221s [test_poll.c:poll_test:95]: Creating handle that should NEVER block on write 221s [test_poll.c:poll_test:101]: Creating handle that should NEVER block on read 221s [test_poll.c:poll_test:108]: Creating handle that should block on read 221s [test_poll.c:poll_test:168]: Starting thread to ensure we don't block forever 221s [test_poll.c:poll_test:194]: Cancelling failsafe thread. 221s END /main/poll/ - poll_test Time: <1ms Result: PASS 221s START /main/presence/ - channel_presence 221s END /main/presence/ - channel_presence Time: <1ms Result: PASS 221s START /main/sample/ - sample_test 221s [test_skel.c:sample_test:57]: Executing sample test... 221s END /main/sample/ - sample_test Time: <1ms Result: PASS 221s START /main/sched/ - sched_test_freebird 221s [test_sched.c:sched_test_freebird:440]: Received signal, calling Scedule and UNREF 221s [test_sched.c:sched_test_freebird:441]: ID: 1 224s [test_sched.c:sched_test_freebird:448]: Correct number of references '2' 224s END /main/sched/ - sched_test_freebird Time: 3002ms Result: PASS 224s START /main/sched/ - sched_test_order 224s END /main/sched/ - sched_test_order Time: 400ms Result: PASS 224s START /main/sorcery/ - wizard_read_only 224s END /main/sorcery/ - wizard_read_only Time: <1ms Result: PASS 224s START /main/sorcery/ - wizard_observation 224s END /main/sorcery/ - wizard_observation Time: <1ms Result: PASS 224s START /main/sorcery/ - instance_observation 224s END /main/sorcery/ - instance_observation Time: <1ms Result: PASS 224s START /main/sorcery/ - global_observation 224s END /main/sorcery/ - global_observation Time: <1ms Result: PASS 224s START /main/sorcery/ - object_field_registered 224s END /main/sorcery/ - object_field_registered Time: <1ms Result: PASS 224s START /main/sorcery/ - dialplan_function 224s END /main/sorcery/ - dialplan_function Time: <1ms Result: PASS 224s START /main/sorcery/ - configuration_file_wizard_retrieve_multiple_all 224s END /main/sorcery/ - configuration_file_wizard_retrieve_multiple_all Time: <1ms Result: PASS 224s START /main/sorcery/ - configuration_file_wizard_retrieve_multiple 224s END /main/sorcery/ - configuration_file_wizard_retrieve_multiple Time: <1ms Result: PASS 224s START /main/sorcery/ - configuration_file_wizard_retrieve_field 224s END /main/sorcery/ - configuration_file_wizard_retrieve_field Time: <1ms Result: PASS 224s START /main/sorcery/ - configuration_file_wizard_with_criteria 224s END /main/sorcery/ - configuration_file_wizard_with_criteria Time: <1ms Result: PASS 224s START /main/sorcery/ - configuration_file_wizard_with_file_integrity 224s END /main/sorcery/ - configuration_file_wizard_with_file_integrity Time: <1ms Result: PASS 224s START /main/sorcery/ - configuration_file_wizard 224s END /main/sorcery/ - configuration_file_wizard Time: <1ms Result: PASS 224s START /main/sorcery/ - object_type_observer 224s END /main/sorcery/ - object_type_observer Time: <1ms Result: PASS 224s START /main/sorcery/ - caching_wizard_behavior 224s END /main/sorcery/ - caching_wizard_behavior Time: <1ms Result: PASS 224s START /main/sorcery/ - object_is_stale 224s END /main/sorcery/ - object_is_stale Time: <1ms Result: PASS 224s START /main/sorcery/ - object_delete_uncreated 224s END /main/sorcery/ - object_delete_uncreated Time: <1ms Result: PASS 224s START /main/sorcery/ - object_delete 224s END /main/sorcery/ - object_delete Time: <1ms Result: PASS 224s START /main/sorcery/ - object_update_uncreated 224s END /main/sorcery/ - object_update_uncreated Time: <1ms Result: PASS 224s START /main/sorcery/ - object_update 224s END /main/sorcery/ - object_update Time: <1ms Result: PASS 224s START /main/sorcery/ - object_retrieve_regex 224s END /main/sorcery/ - object_retrieve_regex Time: <1ms Result: PASS 224s START /main/sorcery/ - object_retrieve_multiple_field 224s END /main/sorcery/ - object_retrieve_multiple_field Time: <1ms Result: PASS 224s START /main/sorcery/ - object_retrieve_multiple_all 224s END /main/sorcery/ - object_retrieve_multiple_all Time: <1ms Result: PASS 224s START /main/sorcery/ - object_retrieve_field 224s END /main/sorcery/ - object_retrieve_field Time: <1ms Result: PASS 224s START /main/sorcery/ - object_retrieve_id 224s END /main/sorcery/ - object_retrieve_id Time: <1ms Result: PASS 224s START /main/sorcery/ - object_create 224s END /main/sorcery/ - object_create Time: <1ms Result: PASS 224s START /main/sorcery/ - changeset_create_unchanged 224s END /main/sorcery/ - changeset_create_unchanged Time: <1ms Result: PASS 224s START /main/sorcery/ - changeset_create 224s END /main/sorcery/ - changeset_create Time: <1ms Result: PASS 224s START /main/sorcery/ - extended_fields 224s END /main/sorcery/ - extended_fields Time: <1ms Result: PASS 224s START /main/sorcery/ - objectset_apply_fields 224s END /main/sorcery/ - objectset_apply_fields Time: <1ms Result: PASS 224s START /main/sorcery/ - objectset_transform 224s END /main/sorcery/ - objectset_transform Time: <1ms Result: PASS 224s START /main/sorcery/ - objectset_apply_invalid 224s END /main/sorcery/ - objectset_apply_invalid Time: <1ms Result: PASS 224s START /main/sorcery/ - objectset_apply_handler 224s END /main/sorcery/ - objectset_apply_handler Time: <1ms Result: PASS 224s START /main/sorcery/ - objectset_apply 224s END /main/sorcery/ - objectset_apply Time: <1ms Result: PASS 224s START /main/sorcery/ - objectset_create_regex 224s END /main/sorcery/ - objectset_create_regex Time: <1ms Result: PASS 224s START /main/sorcery/ - objectset_json_create 224s END /main/sorcery/ - objectset_json_create Time: <1ms Result: PASS 224s START /main/sorcery/ - objectset_create 224s END /main/sorcery/ - objectset_create Time: <1ms Result: PASS 224s START /main/sorcery/ - object_diff_native 224s END /main/sorcery/ - object_diff_native Time: <1ms Result: PASS 224s START /main/sorcery/ - object_diff 224s END /main/sorcery/ - object_diff Time: <1ms Result: PASS 224s START /main/sorcery/ - object_copy_native 224s END /main/sorcery/ - object_copy_native Time: <1ms Result: PASS 224s START /main/sorcery/ - object_copy 224s END /main/sorcery/ - object_copy Time: <1ms Result: PASS 224s START /main/sorcery/ - object_alloc_without_id 224s END /main/sorcery/ - object_alloc_without_id Time: <1ms Result: PASS 224s START /main/sorcery/ - object_alloc_with_id 224s END /main/sorcery/ - object_alloc_with_id Time: <1ms Result: PASS 224s START /main/sorcery/ - object_fields_register 224s END /main/sorcery/ - object_fields_register Time: <1ms Result: PASS 224s START /main/sorcery/ - object_field_register 224s END /main/sorcery/ - object_field_register Time: <1ms Result: PASS 224s START /main/sorcery/ - object_register_without_mapping 224s END /main/sorcery/ - object_register_without_mapping Time: <1ms Result: PASS 224s START /main/sorcery/ - object_register 224s END /main/sorcery/ - object_register Time: <1ms Result: PASS 224s START /main/sorcery/ - apply_config 224s END /main/sorcery/ - apply_config Time: <1ms Result: PASS 224s START /main/sorcery/ - apply_default 224s END /main/sorcery/ - apply_default Time: <1ms Result: PASS 224s START /main/sorcery/ - open 224s END /main/sorcery/ - open Time: <1ms Result: PASS 224s START /main/sorcery/ - wizard_registration 224s END /main/sorcery/ - wizard_registration Time: <1ms Result: PASS 224s START /main/sorcery/ - wizard_apply_and_insert 224s END /main/sorcery/ - wizard_apply_and_insert Time: <1ms Result: PASS 224s START /main/stdtime/ - time_create_by_unit_str 224s END /main/stdtime/ - time_create_by_unit_str Time: <1ms Result: PASS 224s START /main/stdtime/ - time_create_by_unit 224s END /main/stdtime/ - time_create_by_unit Time: <1ms Result: PASS 224s START /main/stdtime/ - time_str_to_unit 224s END /main/stdtime/ - time_str_to_unit Time: <1ms Result: PASS 224s START /main/stdtime/ - time_tv_to_usec 224s END /main/stdtime/ - time_tv_to_usec Time: <1ms Result: PASS 224s START /main/stdtime/ - timezone_watch 224s [test_time.c:test_timezone_watch:82]: Executing deletion test... 224s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.zKE0D5/test 225s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.zKE0D5/test 225s [test_time.c:test_timezone_watch:82]: Executing symlink test... 225s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.zKE0D5/test 227s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.zKE0D5/test 227s END /main/stdtime/ - timezone_watch Time: 2240ms Result: PASS 227s START /main/stream/ - stream_topology_map_create 227s END /main/stream/ - stream_topology_map_create Time: <1ms Result: PASS 227s START /main/stream/ - format_cap_from_stream_topology 227s END /main/stream/ - format_cap_from_stream_topology Time: <1ms Result: PASS 227s START /main/stream/ - stream_topology_change_request_from_channel 227s END /main/stream/ - stream_topology_change_request_from_channel Time: <1ms Result: PASS 227s START /main/stream/ - stream_topology_change_request_from_application 227s END /main/stream/ - stream_topology_change_request_from_application Time: <1ms Result: PASS 227s START /main/stream/ - stream_topology_change_request_from_channel_non_multistream 227s END /main/stream/ - stream_topology_change_request_from_channel_non_multistream Time: <1ms Result: PASS 227s START /main/stream/ - stream_topology_change_request_from_application_non_multistream 227s END /main/stream/ - stream_topology_change_request_from_application_non_multistream Time: <1ms Result: PASS 227s START /main/stream/ - stream_read_multistream 227s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 227s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 227s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 227s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 227s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 4 Frames: 16 Frames per read: 1 Expected Nulls: 8 227s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 8 227s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 4 Frames: 16 Frames per read: 1 Expected Nulls: 0 227s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 227s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 227s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 227s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 227s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 227s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 4 Frames: 16 Frames per read: 3 Expected Nulls: 8 227s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 8 227s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 4 Frames: 16 Frames per read: 3 Expected Nulls: 0 227s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 227s END /main/stream/ - stream_read_multistream Time: 1ms Result: PASS 227s START /main/stream/ - stream_read_non_multistream 227s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 227s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 227s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 227s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 227s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 227s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 227s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 227s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 227s END /main/stream/ - stream_read_non_multistream Time: <1ms Result: PASS 227s START /main/stream/ - stream_write_multistream 227s END /main/stream/ - stream_write_multistream Time: <1ms Result: PASS 227s START /main/stream/ - stream_write_non_multistream 227s END /main/stream/ - stream_write_non_multistream Time: <1ms Result: PASS 227s START /main/stream/ - stream_topology_channel_set 227s END /main/stream/ - stream_topology_channel_set Time: <1ms Result: PASS 227s START /main/stream/ - stream_topology_create_from_channel_nativeformats 227s END /main/stream/ - stream_topology_create_from_channel_nativeformats Time: <1ms Result: PASS 227s START /main/stream/ - stream_topology_get_first_stream_by_type 227s END /main/stream/ - stream_topology_get_first_stream_by_type Time: <1ms Result: PASS 227s START /main/stream/ - stream_topology_create_from_format_cap 227s END /main/stream/ - stream_topology_create_from_format_cap Time: <1ms Result: PASS 227s START /main/stream/ - stream_topology_del_stream 227s END /main/stream/ - stream_topology_del_stream Time: <1ms Result: PASS 227s START /main/stream/ - stream_topology_set_stream 227s END /main/stream/ - stream_topology_set_stream Time: <1ms Result: PASS 227s START /main/stream/ - stream_topology_append_stream 227s END /main/stream/ - stream_topology_append_stream Time: <1ms Result: PASS 227s START /main/stream/ - stream_topology_clone 227s END /main/stream/ - stream_topology_clone Time: <1ms Result: PASS 227s START /main/stream/ - stream_topology_create 227s END /main/stream/ - stream_topology_create Time: <1ms Result: PASS 227s START /main/stream/ - stream_metadata 227s END /main/stream/ - stream_metadata Time: <1ms Result: PASS 227s START /main/stream/ - stream_set_state 227s END /main/stream/ - stream_set_state Time: <1ms Result: PASS 227s START /main/stream/ - stream_set_formats 227s END /main/stream/ - stream_set_formats Time: <1ms Result: PASS 227s START /main/stream/ - stream_set_type 227s END /main/stream/ - stream_set_type Time: <1ms Result: PASS 227s START /main/stream/ - stream_create_no_name 227s END /main/stream/ - stream_create_no_name Time: <1ms Result: PASS 227s START /main/stream/ - stream_create 227s END /main/stream/ - stream_create Time: <1ms Result: PASS 227s START /main/strings/ - in_delimited_string 227s END /main/strings/ - in_delimited_string Time: <1ms Result: PASS 227s START /main/strings/ - temp_strings 227s END /main/strings/ - temp_strings Time: <1ms Result: PASS 227s START /main/strings/ - strings_match 227s END /main/strings/ - strings_match Time: <1ms Result: PASS 227s START /main/strings/ - escape 227s END /main/strings/ - escape Time: <1ms Result: PASS 227s START /main/strings/ - escape_semicolons 227s END /main/strings/ - escape_semicolons Time: <1ms Result: PASS 227s START /main/strings/ - strsep 227s END /main/strings/ - strsep Time: <1ms Result: PASS 227s START /main/strings/ - ends_with 227s END /main/strings/ - ends_with Time: <1ms Result: PASS 227s START /main/strings/ - begins_with 227s END /main/strings/ - begins_with Time: <1ms Result: PASS 227s START /main/strings/ - str_test 227s END /main/strings/ - str_test Time: <1ms Result: PASS 227s START /main/taskprocessor/ - serializer_pool 231s END /main/taskprocessor/ - serializer_pool Time: 4000ms Result: PASS 231s START /main/taskprocessor/ - taskprocessor_push_local 231s END /main/taskprocessor/ - taskprocessor_push_local Time: <1ms Result: PASS 231s START /main/taskprocessor/ - taskprocessor_shutdown 231s END /main/taskprocessor/ - taskprocessor_shutdown Time: <1ms Result: PASS 231s START /main/taskprocessor/ - taskprocessor_listener 231s END /main/taskprocessor/ - taskprocessor_listener Time: <1ms Result: PASS 231s START /main/taskprocessor/ - subsystem_alert 231s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 1 231s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 2 231s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 3 231s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 4 231s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 5 231s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 6 231s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 7 231s [test_taskprocessor.c:subsystem_alert:237]: Subsystem alert triggered correctly at 6 231s [test_taskprocessor.c:subsystem_alert:240]: Global alert triggered correctly at 6 231s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 8 231s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 9 231s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 10 231s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 1 231s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 2 232s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 3 232s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 4 233s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 5 233s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 6 234s [test_taskprocessor.c:subsystem_alert:279]: Subsystem alert cleared correctly at 3 234s [test_taskprocessor.c:subsystem_alert:282]: Global alert cleared correctly at 3 234s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 7 234s [test_taskprocessor.c:subsystem_alert:279]: Subsystem alert cleared correctly at 3 234s [test_taskprocessor.c:subsystem_alert:282]: Global alert cleared correctly at 3 234s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 8 235s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 9 235s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 10 236s END /main/taskprocessor/ - subsystem_alert Time: 5004ms Result: PASS 236s START /main/taskprocessor/ - default_taskprocessor_load 236s END /main/taskprocessor/ - default_taskprocessor_load Time: 44ms Result: PASS 236s START /main/taskprocessor/ - default_taskprocessor 236s END /main/taskprocessor/ - default_taskprocessor Time: <1ms Result: PASS 236s START /main/test/ - registrations 236s END /main/test/ - registrations Time: <1ms Result: PASS 236s START /main/threadpool/ - threadpool_serializer_dupe 236s END /main/threadpool/ - threadpool_serializer_dupe Time: <1ms Result: PASS 236s START /main/threadpool/ - threadpool_serializer 237s END /main/threadpool/ - threadpool_serializer Time: 1000ms Result: PASS 237s START /main/threadpool/ - more_destruction 237s END /main/threadpool/ - more_destruction Time: <1ms Result: PASS 237s START /main/threadpool/ - task_distribution 237s END /main/threadpool/ - task_distribution Time: <1ms Result: PASS 237s START /main/threadpool/ - reactivation 237s END /main/threadpool/ - reactivation Time: <1ms Result: PASS 237s START /main/threadpool/ - max_size 237s END /main/threadpool/ - max_size Time: <1ms Result: PASS 237s START /main/threadpool/ - auto_increment 237s END /main/threadpool/ - auto_increment Time: <1ms Result: PASS 237s START /main/threadpool/ - one_thread_multiple_tasks 237s END /main/threadpool/ - one_thread_multiple_tasks Time: <1ms Result: PASS 237s START /main/threadpool/ - one_thread_one_task 237s END /main/threadpool/ - one_thread_one_task Time: <1ms Result: PASS 237s START /main/threadpool/ - one_task_one_thread 237s END /main/threadpool/ - one_task_one_thread Time: <1ms Result: PASS 237s START /main/threadpool/ - thread_timeout_thrash 268s END /main/threadpool/ - thread_timeout_thrash Time: 31010ms Result: PASS 268s START /main/threadpool/ - thread_timeout 270s END /main/threadpool/ - thread_timeout Time: 2000ms Result: PASS 270s START /main/threadpool/ - thread_destruction 270s END /main/threadpool/ - thread_destruction Time: <1ms Result: PASS 270s START /main/threadpool/ - thread_creation 270s END /main/threadpool/ - thread_creation Time: <1ms Result: PASS 270s START /main/threadpool/ - initial_threads 270s END /main/threadpool/ - initial_threads Time: <1ms Result: PASS 270s START /main/threadpool/ - push 270s END /main/threadpool/ - push Time: <1ms Result: PASS 270s START /main/uri/ - uri_default_http_secure 270s END /main/uri/ - uri_default_http_secure Time: <1ms Result: PASS 270s START /main/uri/ - uri_default_http 270s END /main/uri/ - uri_default_http Time: <1ms Result: PASS 270s START /main/uri/ - uri_parse 270s END /main/uri/ - uri_parse Time: <1ms Result: PASS 270s START /main/utf8/ - utf8_validator 270s END /main/utf8/ - utf8_validator Time: <1ms Result: PASS 270s START /main/utf8/ - copy_string 270s END /main/utf8/ - copy_string Time: <1ms Result: PASS 270s START /main/utf8/ - is_valid 270s END /main/utf8/ - is_valid Time: <1ms Result: PASS 270s START /main/utils/ - string_field_aggregate_test 270s [test_stringfields.c:string_field_aggregate_test:392]: Structures 3 embedded pool initialized successfully. 270s [test_stringfields.c:string_field_aggregate_test:410]: Structures 3 additional pool initialized successfully. 270s [test_stringfields.c:string_field_aggregate_test:422]: Structures 1/2 are equal as expected. 270s [test_stringfields.c:string_field_aggregate_test:430]: Structures 1/3 are different as expected. 270s [test_stringfields.c:string_field_aggregate_test:438]: Structures 2/3 are different as expected. 270s [test_stringfields.c:string_field_aggregate_test:446]: Structures 3/4 are different as expected. 270s [test_stringfields.c:string_field_aggregate_test:454]: Copying from structure 3 to structure 1 succeeded! 270s [test_stringfields.c:string_field_aggregate_test:463]: Structures 1/3 are equal as expected. 270s [test_stringfields.c:string_field_aggregate_test:470]: Structures 1/2 are different as expected. 270s [test_stringfields.c:string_field_aggregate_test:473]: Reset but don't free. 270s [test_stringfields.c:string_field_aggregate_test:484]: Structures 1/2 are the same (empty) as expected. 270s [test_stringfields.c:string_field_aggregate_test:492]: Structure 4 embedded pool is the current pool as expected. 270s [test_stringfields.c:string_field_aggregate_test:500]: Structure 4 embedded pool does not have a previous as expected. 270s END /main/utils/ - string_field_aggregate_test Time: <1ms Result: PASS 270s START /main/utils/ - string_field_test 270s [test_stringfields.c:string_field_test:79]: First things first. Let's see if we can actually allocate string fields 270s [test_stringfields.c:string_field_test:85]: All right! Successfully allocated! Now let's get down to business 270s [test_stringfields.c:string_field_test:89]: We're going to set some string fields and perform some checks 270s [test_stringfields.c:string_field_test:94]: First we're going to make sure that the strings are actually set to what we expect 270s [test_stringfields.c:string_field_test:100]: test_struct.string1 appears to be all clear. It has 'elephant' and that's what we expect 270s [test_stringfields.c:string_field_test:107]: test_struct.string2 appears to be all clear. It has 'hippopotamus' and that's what we expect 270s [test_stringfields.c:string_field_test:110]: Now let's make sure that our recorded capacities for these strings is what we expect 270s [test_stringfields.c:string_field_test:117]: string1 has the allocation area we expect: 9 270s [test_stringfields.c:string_field_test:125]: string2 has the allocation area we expect: 13 270s [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 270s [test_stringfields.c:string_field_test:137]: string1 successfully was changed to 'rhino' 270s [test_stringfields.c:string_field_test:144]: Shrinking string1 allowed it to stay in the same place in memory 270s [test_stringfields.c:string_field_test:151]: Shrinking string1 did not change its allocation area (This is a good thing) 270s [test_stringfields.c:string_field_test:154]: Next, let's increase it a little but not all the way to its original size 270s [test_stringfields.c:string_field_test:163]: string1 successfully was changed to 'mammoth' 270s [test_stringfields.c:string_field_test:170]: Expanding string1 allowed it to stay in the same place in memory 270s [test_stringfields.c:string_field_test:177]: Expanding string1 did not change its allocation area (This is a good thing) 270s [test_stringfields.c:string_field_test:180]: Cool, now let's bring it back to its original size and see what happens 270s [test_stringfields.c:string_field_test:188]: string1 successfully changed to 'elephant' 270s [test_stringfields.c:string_field_test:195]: Restoring string1 did not cause it to move (This is a good thing) 270s [test_stringfields.c:string_field_test:202]: The allocation amount for string1 is still holding steady 270s [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 270s [test_stringfields.c:string_field_test:214]: string2 successfully changed to 'hippopotamus face' 270s [test_stringfields.c:string_field_test:222]: The allocation amount successfully increased for string2 when it grew 270s [test_stringfields.c:string_field_test:229]: string2 stayed in place when it grew. Good job! 270s [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 270s [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' 270s [test_stringfields.c:string_field_test:248]: Good. Setting string1 to a long value caused it to change addresses 270s [test_stringfields.c:string_field_test:256]: The stored allocation size of string1 is what we expect 270s [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 270s [test_stringfields.c:string_field_test:281]: Three different pools are linked as expected. 270s [test_stringfields.c:string_field_test:289]: After removing a pool the remaining two are linked as expected. 270s END /main/utils/ - string_field_test Time: <1ms Result: PASS 270s START /main/utils/ - quote_unescaping 270s END /main/utils/ - quote_unescaping Time: <1ms Result: PASS 270s START /main/utils/ - quote_mutation 270s END /main/utils/ - quote_mutation Time: <1ms Result: PASS 270s START /main/utils/ - crypt_test 270s END /main/utils/ - crypt_test Time: 10ms Result: PASS 270s START /main/utils/ - safe_mkdir_test 270s END /main/utils/ - safe_mkdir_test Time: <1ms Result: PASS 270s START /main/utils/ - base64_test 270s END /main/utils/ - base64_test Time: <1ms Result: PASS 270s START /main/utils/ - sha1_test 270s [test_utils.c:sha1_test:248]: Testing SHA1 ... 270s END /main/utils/ - sha1_test Time: <1ms Result: PASS 270s START /main/utils/ - md5_test 270s [test_utils.c:md5_test:203]: Testing MD5 ... 270s END /main/utils/ - md5_test Time: <1ms Result: PASS 270s START /main/utils/ - quoted_escape_test 270s END /main/utils/ - quoted_escape_test Time: <1ms Result: PASS 270s START /main/utils/ - uri_encode_decode_test 270s END /main/utils/ - uri_encode_decode_test Time: <1ms Result: PASS 270s START /main/uuid/ - uuid 270s [test_uuid.c:uuid:59]: Generate UUID direct to string, got 961cadc4-877d-4d96-92b2-6076d723fb7f 270s [test_uuid.c:uuid:90]: Second generated UUID converted to string, got 3a40597b-6d37-4868-889c-2efe21be8a62 270s END /main/uuid/ - uuid Time: <1ms Result: PASS 270s START /main/vector/ - basic 270s END /main/vector/ - basic Time: <1ms Result: PASS 270s START /main/vector/ - basic_integer 270s END /main/vector/ - basic_integer Time: <1ms Result: PASS 270s START /main/vector/ - callbacks 270s END /main/vector/ - callbacks Time: <1ms Result: PASS 270s START /main/vector/ - locks 270s END /main/vector/ - locks Time: <1ms Result: PASS 270s START /main/voicemail_api/ - off_nominal_msg_playback 270s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1495]: Created message in test_vm_api_1234/Old with ID 1741957987-909401725 270s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1495]: Created message in test_vm_api_1234/INBOX with ID 1741957987-960311778 270s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1495]: Created message in test_vm_api_2345/INBOX with ID 1741957987-1500739833 270s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1495]: Created message in test_vm_api_2345/INBOX with ID 1741957987-719848782 270s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1504]: Playing back message from invalid mailbox 270s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1507]: Playing back message from NULL mailbox 270s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1510]: Playing back message from invalid context 270s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1513]: Playing back message from invalid folder 270s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1516]: Playing back message from NULL folder 270s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1519]: Playing back message with invalid message specifier 270s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1522]: Playing back message with NULL message specifier 270s END /main/voicemail_api/ - off_nominal_msg_playback Time: 5ms Result: PASS 270s START /main/voicemail_api/ - nominal_msg_playback 270s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1433]: Created message in test_vm_api_1234/Old with ID 1741957987-909401725 270s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1433]: Created message in test_vm_api_1234/INBOX with ID 1741957987-960311778 270s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1433]: Created message in test_vm_api_2345/INBOX with ID 1741957987-1500739833 270s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1433]: Created message in test_vm_api_2345/INBOX with ID 1741957987-719848782 270s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1445]: Playing back message from test_vm_api_1234 to mock channel 270s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1448]: Playing back message from test_vm_api_2345 to callback function 270s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1453]: Playing back message from test_vm_api_2345 to callback function with default context 270s END /main/voicemail_api/ - nominal_msg_playback Time: 451ms Result: PASS 270s START /main/voicemail_api/ - off_nominal_forward 270s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1355]: Created message in test_vm_api_1234/Old with ID 1741957987-909401725 270s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1355]: Created message in test_vm_api_1234/INBOX with ID 1741957987-960311778 270s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1355]: Created message in test_vm_api_2345/INBOX with ID 1741957987-1500739833 270s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1355]: Created message in test_vm_api_2345/INBOX with ID 1741957987-719848782 270s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1364]: Test forwarding from an invalid mailbox 270s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1367]: Test forwarding from a NULL mailbox 270s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1370]: Test forwarding from an invalid context 270s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1373]: Test forwarding from an invalid folder 270s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1376]: Test forwarding from a NULL folder 270s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1379]: Test forwarding to an invalid mailbox 270s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1382]: Test forwarding to a NULL mailbox 270s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1385]: Test forwarding to an invalid context 270s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1388]: Test forwarding to an invalid folder 270s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1392]: Test forwarding to a NULL folder 270s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1395]: Test forwarding when no messages are select 270s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1398]: Test forwarding a message that doesn't exist 270s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1402]: Test forwarding multiple messages, where some messages don't exist 270s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1405]: Test forwarding a message with an invalid size specifier 270s END /main/voicemail_api/ - off_nominal_forward Time: 4ms Result: PASS 270s START /main/voicemail_api/ - nominal_forward 270s [test_voicemail_api.c:voicemail_api_nominal_forward:1239]: Created message in test_vm_api_1234/Old with ID 1741957987-909401725 270s [test_voicemail_api.c:voicemail_api_nominal_forward:1239]: Created message in test_vm_api_1234/INBOX with ID 1741957987-960311778 270s [test_voicemail_api.c:voicemail_api_nominal_forward:1239]: Created message in test_vm_api_2345/INBOX with ID 1741957987-1500739833 270s [test_voicemail_api.c:voicemail_api_nominal_forward:1239]: Created message in test_vm_api_2345/INBOX with ID 1741957987-719848782 270s [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 270s [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 270s [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 270s [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 270s [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 270s END /main/voicemail_api/ - nominal_forward Time: 14ms Result: PASS 270s START /main/voicemail_api/ - off_nominal_remove 270s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1180]: Created message in test_vm_api_1234/Old with ID 1741957987-909401725 270s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1180]: Created message in test_vm_api_1234/INBOX with ID 1741957987-960311778 270s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1180]: Created message in test_vm_api_2345/INBOX with ID 1741957987-1500739833 270s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1180]: Created message in test_vm_api_2345/INBOX with ID 1741957987-719848782 270s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1186]: Test removing a single message with an invalid mailbox 270s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1189]: Test removing a single message with a NULL mailbox 270s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1192]: Test removing a single message with an invalid context 270s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1195]: Test removing a single message with an invalid folder 270s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1198]: Test removing a single message with a NULL folder 270s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1201]: Test removing a single message with an invalid message number 270s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1205]: Test removing multiple messages with a single invalid message number 270s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1209]: Test removing no messages with no message numbers 270s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1212]: Test removing multiple messages with an invalid size specifier 270s END /main/voicemail_api/ - off_nominal_remove Time: 4ms Result: PASS 270s START /main/voicemail_api/ - nominal_remove 270s [test_voicemail_api.c:voicemail_api_nominal_remove:1133]: Created message in test_vm_api_1234/Old with ID 1741957987-909401725 270s [test_voicemail_api.c:voicemail_api_nominal_remove:1133]: Created message in test_vm_api_1234/INBOX with ID 1741957987-960311778 270s [test_voicemail_api.c:voicemail_api_nominal_remove:1133]: Created message in test_vm_api_2345/INBOX with ID 1741957987-1500739833 270s [test_voicemail_api.c:voicemail_api_nominal_remove:1133]: Created message in test_vm_api_2345/INBOX with ID 1741957987-719848782 270s [test_voicemail_api.c:voicemail_api_nominal_remove:1141]: Test removing a single message from INBOX 270s [test_voicemail_api.c:voicemail_api_nominal_remove:1144]: Test removing a single message from Old 270s [test_voicemail_api.c:voicemail_api_nominal_remove:1147]: Test removing multiple messages from INBOX 270s END /main/voicemail_api/ - nominal_remove Time: 5ms Result: PASS 270s START /main/voicemail_api/ - off_nominal_move 270s [test_voicemail_api.c:voicemail_api_off_nominal_move:1061]: Created message in test_vm_api_1234/Old with ID 1741957987-909401725 270s [test_voicemail_api.c:voicemail_api_off_nominal_move:1061]: Created message in test_vm_api_1234/INBOX with ID 1741957987-960311778 270s [test_voicemail_api.c:voicemail_api_off_nominal_move:1061]: Created message in test_vm_api_2345/INBOX with ID 1741957987-1500739833 270s [test_voicemail_api.c:voicemail_api_off_nominal_move:1061]: Created message in test_vm_api_2345/INBOX with ID 1741957987-719848782 270s [test_voicemail_api.c:voicemail_api_off_nominal_move:1070]: Test move attempt for invalid mailbox test_vm_3456 270s [test_voicemail_api.c:voicemail_api_off_nominal_move:1075]: Test move attempt for invalid context test_vm_api_defunct 270s [test_voicemail_api.c:voicemail_api_off_nominal_move:1078]: Test move attempt to invalid folder 270s [test_voicemail_api.c:voicemail_api_off_nominal_move:1081]: Test move attempt from invalid folder 270s [test_voicemail_api.c:voicemail_api_off_nominal_move:1084]: Test move attempt to NULL folder 270s [test_voicemail_api.c:voicemail_api_off_nominal_move:1087]: Test move attempt from NULL folder 270s [test_voicemail_api.c:voicemail_api_off_nominal_move:1090]: Test move attempt with non-existent message number 270s [test_voicemail_api.c:voicemail_api_off_nominal_move:1094]: Test move attempt with invalid message number 270s [test_voicemail_api.c:voicemail_api_off_nominal_move:1098]: Test move attempt with 0 number of messages 270s [test_voicemail_api.c:voicemail_api_off_nominal_move:1102]: Test move attempt with invalid number of messages 270s [test_voicemail_api.c:voicemail_api_off_nominal_move:1105]: Test move attempt with non-existent multiple messages, where some messages exist 270s END /main/voicemail_api/ - off_nominal_move Time: 5ms Result: PASS 270s START /main/voicemail_api/ - nominal_move 270s [test_voicemail_api.c:voicemail_api_nominal_move:987]: Created message in test_vm_api_1234/Old with ID 1741957987-909401725 270s [test_voicemail_api.c:voicemail_api_nominal_move:987]: Created message in test_vm_api_1234/INBOX with ID 1741957987-960311778 270s [test_voicemail_api.c:voicemail_api_nominal_move:987]: Created message in test_vm_api_2345/INBOX with ID 1741957987-1500739833 270s [test_voicemail_api.c:voicemail_api_nominal_move:987]: Created message in test_vm_api_2345/INBOX with ID 1741957987-719848782 270s [test_voicemail_api.c:voicemail_api_nominal_move:994]: Test move of test_vm_api_1234 message from INBOX to Family 270s [test_voicemail_api.c:voicemail_api_nominal_move:997]: Test move of test_vm_api_1234 message from Old to Family 270s [test_voicemail_api.c:voicemail_api_nominal_move:1011]: Test move of test_vm_api_2345 messages from Inbox to Family 270s [test_voicemail_api.c:voicemail_api_nominal_move:1022]: Test move of test_vm_api_2345 message from Family to INBOX 270s END /main/voicemail_api/ - nominal_move Time: 7ms Result: PASS 270s START /main/voicemail_api/ - off_nominal_snapshot 270s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:947]: Created message in test_vm_api_1234/Old with ID 1741957987-909401725 270s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:947]: Created message in test_vm_api_1234/INBOX with ID 1741957987-960311778 270s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:947]: Created message in test_vm_api_2345/INBOX with ID 1741957987-1500739833 270s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:947]: Created message in test_vm_api_2345/INBOX with ID 1741957987-719848782 270s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:949]: Test access to non-existent mailbox test_vm_api_3456 270s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:952]: Test access to null mailbox 270s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:955]: Test access non-existent context test_vm_api_defunct 270s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:958]: Test non-existent folder test_vm_api_platypus 270s END /main/voicemail_api/ - off_nominal_snapshot Time: 4ms Result: PASS 270s START /main/voicemail_api/ - nominal_snapshot 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:856]: Created message in test_vm_api_1234/Old with ID 1741957987-909401725 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:856]: Created message in test_vm_api_1234/INBOX with ID 1741957987-960311778 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:856]: Created message in test_vm_api_2345/INBOX with ID 1741957987-1500739833 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:856]: Created message in test_vm_api_2345/INBOX with ID 1741957987-719848782 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:858]: Test retrieving message 1 from INBOX of test_vm_1234 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:861]: Found message 1741957987-960311778 in snapshot 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:864]: Test retrieving message 0 from Old of test_vm_1234 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:867]: Found message 1741957987-909401725 in snapshot 270s [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 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:873]: Found message 1741957987-909401725 in snapshot 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:874]: Found message 1741957987-960311778 in snapshot 270s [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 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:880]: Found message 1741957987-960311778 in snapshot 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:881]: Found message 1741957987-909401725 in snapshot 270s [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 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:887]: Found message 1741957987-960311778 in snapshot 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:888]: Found message 1741957987-909401725 in snapshot 270s [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 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:894]: Found message 1741957987-909401725 in snapshot 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:895]: Found message 1741957987-960311778 in snapshot 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:898]: Test retrieving message 0, 1 from all folders of test_vm_1234 ordered by id 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:901]: Found message 1741957987-909401725 in snapshot 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:902]: Found message 1741957987-960311778 in snapshot 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:905]: Test retrieving message 0, 1 from all folders of test_vm_1234 ordered by time 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:908]: Found message 1741957987-909401725 in snapshot 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:909]: Found message 1741957987-960311778 in snapshot 270s [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 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:915]: Found message 1741957987-909401725 in snapshot 270s [test_voicemail_api.c:voicemail_api_nominal_snapshot:916]: Found message 1741957987-960311778 in snapshot 270s END /main/voicemail_api/ - nominal_snapshot Time: 9ms Result: PASS 270s START /main/xml_escape/ - xml_escape_test 270s END /main/xml_escape/ - xml_escape_test Time: <1ms Result: PASS 270s START /mwi/ - explicit_publish 270s END /mwi/ - explicit_publish Time: 75ms Result: PASS 270s START /mwi/ - implicit_publish 270s END /mwi/ - implicit_publish Time: 67ms Result: PASS 270s START /res/adsi/ - adsi_loaded_test 270s END /res/adsi/ - adsi_loaded_test Time: <1ms Result: PASS 270s START /res/agi/ - agi_loaded_test 270s END /res/agi/ - agi_loaded_test Time: <1ms Result: PASS 270s START /res/agi/ - null_agi_docs 270s END /res/agi/ - null_agi_docs Time: <1ms Result: PASS 270s START /res/ari/ - invoke_not_found 270s END /res/ari/ - invoke_not_found Time: <1ms Result: PASS 270s START /res/ari/ - invoke_bad_post 270s END /res/ari/ - invoke_bad_post Time: <1ms Result: PASS 270s START /res/ari/ - invoke_post 270s END /res/ari/ - invoke_post Time: <1ms Result: PASS 270s START /res/ari/ - invoke_delete 270s END /res/ari/ - invoke_delete Time: <1ms Result: PASS 270s START /res/ari/ - invoke_wildcard 270s END /res/ari/ - invoke_wildcard Time: <1ms Result: PASS 270s START /res/ari/ - invoke_get 270s END /res/ari/ - invoke_get Time: <1ms Result: PASS 270s START /res/ari/ - get_docs_hackerz 270s END /res/ari/ - get_docs_hackerz Time: <1ms Result: PASS 270s START /res/ari/ - get_docs_notfound 270s END /res/ari/ - get_docs_notfound Time: <1ms Result: PASS 270s START /res/ari/ - get_docs_nohost 270s END /res/ari/ - get_docs_nohost Time: <1ms Result: PASS 270s START /res/ari/ - get_docs 270s END /res/ari/ - get_docs Time: <1ms Result: PASS 270s START /res/crypto/ - crypto_loaded_test 270s END /res/crypto/ - crypto_loaded_test Time: <1ms Result: PASS 270s START /res/http_media_cache/ - retrieve_content_type 270s END /res/http_media_cache/ - retrieve_content_type Time: 3ms Result: PASS 270s START /res/http_media_cache/ - retrieve_parsed_uri 270s END /res/http_media_cache/ - retrieve_parsed_uri Time: <1ms Result: PASS 270s START /res/http_media_cache/ - retrieve_cache_control_directives 270s [test_http_media_cache.c:retrieve_cache_control_directives:322]: Testing no-cache... 270s [test_http_media_cache.c:retrieve_cache_control_directives:329]: Testing no-cache with ETag... 270s [test_http_media_cache.c:retrieve_cache_control_directives:339]: Testing no-cache with max-age... 270s [test_http_media_cache.c:retrieve_cache_control_directives:344]: Checking 1741958290 >= 1741958287 and 1741958284 <= 1741958287 270s [test_http_media_cache.c:retrieve_cache_control_directives:351]: Testing must-revalidate... 270s [test_http_media_cache.c:retrieve_cache_control_directives:358]: Testing must-revalidate with ETag... 270s [test_http_media_cache.c:retrieve_cache_control_directives:368]: Testing must-revalidate with max-age... 270s [test_http_media_cache.c:retrieve_cache_control_directives:373]: Checking 1741958290 >= 1741958287 and 1741958284 <= 1741958287 270s END /res/http_media_cache/ - retrieve_cache_control_directives Time: 5ms Result: PASS 270s START /res/http_media_cache/ - retrieve_cache_control_age 270s [test_http_media_cache.c:retrieve_cache_control_age:406]: Testing max-age... 270s [test_http_media_cache.c:retrieve_cache_control_age:410]: Checking 1741958290 >= 1741958287 and 1741958284 <= 1741958287 270s [test_http_media_cache.c:retrieve_cache_control_age:414]: Testing s-maxage... 270s [test_http_media_cache.c:retrieve_cache_control_age:420]: Checking 1741958290 >= 1741958287 and 1741958284 <= 1741958287 270s [test_http_media_cache.c:retrieve_cache_control_age:424]: Testing max-age and s-maxage... 270s [test_http_media_cache.c:retrieve_cache_control_age:430]: Checking 1741958590 >= 1741958587 and 1741958584 <= 1741958587 270s [test_http_media_cache.c:retrieve_cache_control_age:434]: Testing max-age and Expires... 270s [test_http_media_cache.c:retrieve_cache_control_age:441]: Checking 1741958290 >= 1741958287 and 1741958284 <= 1741958287 270s [test_http_media_cache.c:retrieve_cache_control_age:445]: Testing s-maxage and Expires... 270s [test_http_media_cache.c:retrieve_cache_control_age:452]: Checking 1741958290 >= 1741958287 and 1741958284 <= 1741958287 270s [test_http_media_cache.c:retrieve_cache_control_age:456]: Testing s-maxage and Expires... 270s [test_http_media_cache.c:retrieve_cache_control_age:463]: Checking 1741958290 >= 1741958287 and 1741958284 <= 1741958287 270s [test_http_media_cache.c:retrieve_cache_control_age:467]: Testing max-age, s-maxage, and Expires... 270s [test_http_media_cache.c:retrieve_cache_control_age:474]: Checking 1741958590 >= 1741958587 and 1741958584 <= 1741958587 270s END /res/http_media_cache/ - retrieve_cache_control_age Time: 5ms Result: PASS 270s START /res/http_media_cache/ - retrieve_etag_expired 270s [test_http_media_cache.c:retrieve_etag_expired:514]: Checking 1741957989 >= 1741957986 and 1741957983 <= 1741957986 270s END /res/http_media_cache/ - retrieve_etag_expired Time: 1ms Result: PASS 270s START /res/http_media_cache/ - retrieve_expires 270s [test_http_media_cache.c:retrieve_expires:554]: Checking 1741960990 >= 1741960987 and 1741960984 <= 1741960987 270s [test_http_media_cache.c:retrieve_expires:564]: Checking 1741957989 >= 1741957986 and 1741957983 <= 1741957986 270s END /res/http_media_cache/ - retrieve_expires Time: 1ms Result: PASS 270s START /res/http_media_cache/ - retrieve_etag 270s [test_http_media_cache.c:retrieve_etag:604]: Checking 1741957990 >= 1741957987 and 1741957984 <= 1741957987 270s END /res/http_media_cache/ - retrieve_etag Time: <1ms Result: PASS 270s START /res/http_media_cache/ - retrieve_nominal 270s [test_http_media_cache.c:retrieve_nominal:642]: Checking 1741957990 >= 1741957987 and 1741957984 <= 1741957987 270s END /res/http_media_cache/ - retrieve_nominal Time: <1ms Result: PASS 270s START /res/http_media_cache/ - create_nominal 270s [test_http_media_cache.c:create_nominal:675]: Checking 1741957990 >= 1741957987 and 1741957984 <= 1741957987 270s END /res/http_media_cache/ - create_nominal Time: <1ms Result: PASS 270s START /res/parking/ - dynamic_parking_variables 270s [parking/parking_tests.c:dynamic_parking_variables:756]: Creating expected configuration for dynamic parking lot 270s [parking/parking_tests.c:dynamic_parking_variables:775]: Creating template lot 270s [parking/parking_tests.c:dynamic_parking_variables:784]: Creating Alice channel to test dynamic parking lot creation. 270s [parking/parking_tests.c:dynamic_parking_variables:794]: Setting Dynamic Parking channel variables on Alice. 270s [parking/parking_tests.c:dynamic_parking_variables:802]: Generating dynamic parking lot based on Alice's channel variables. 270s [parking/parking_tests.c:dynamic_parking_variables:819]: Dynamic parking lot created successfully and matches expectations. Test passed. 270s END /res/parking/ - dynamic_parking_variables Time: <1ms Result: PASS 270s START /res/parking/ - extension_conflicts 270s [parking/parking_tests.c:extension_conflicts:597]: Creating the base lot. This should pass. 270s [parking/parking_tests.c:extension_conflicts:607]: Creating a test lot which will overlap. 270s [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. 270s [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. 270s [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. 270s [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. 270s END /res/parking/ - extension_conflicts Time: <1ms Result: PASS 270s START /res/parking/ - park_extensions 270s [parking/parking_tests.c:park_extensions:551]: Extensions for the test parking lot were verified. Cleaning up and verifying their removal. 270s [parking/parking_tests.c:park_extensions:565]: Extensions for the test parking lot verified as removed. Test completed successfully. 270s END /res/parking/ - park_extensions Time: <1ms Result: PASS 270s START /res/parking/ - park_retrieve 270s [parking/parking_tests.c:retrieve_call:405]: Creating test parking lot 'unit_tests_res_parking_test_lot' 271s [parking/parking_tests.c:retrieve_call:446]: Successfully retrieved parked user from the parking lot. Validating user data. 271s END /res/parking/ - park_retrieve Time: 1003ms Result: PASS 271s START /res/parking/ - park_channel 271s [parking/parking_tests.c:park_call:254]: Creating test parking lot 'unit_tests_res_parking_test_lot' 272s END /res/parking/ - park_channel Time: 1001ms Result: PASS 272s START /res/parking/ - create_lot 272s [parking/parking_tests.c:create_lot:206]: Creating test parking lot 'unit_tests_res_parking_test_lot' 272s [parking/parking_tests.c:create_lot:214]: Successfully created parking lot. Retrieving test parking lot from container. 272s [parking/parking_tests.c:create_lot:223]: Successfully retrieved parking lot. Removing test parking lot from container. 272s [parking/parking_tests.c:create_lot:229]: Parking lot was successfully removed from the container. Test complete. 272s END /res/parking/ - create_lot Time: <1ms Result: PASS 272s START /res/prometheus/ - config_general_core_metrics 272s [test_res_prometheus.c:config_general_core_metrics:679]: -> CURLing request... 272s [test_res_prometheus.c:config_general_core_metrics:687]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 272s # TYPE asterisk_channels_count gauge 272s asterisk_channels_count{eid="fa:16:3e:40:0b:25"} 0 272s # HELP asterisk_calls_sum Total call count. 272s # TYPE asterisk_calls_sum counter 272s asterisk_calls_sum{eid="fa:16:3e:40:0b:25"} 0 272s # HELP asterisk_calls_count Current call count. 272s # TYPE asterisk_calls_count gauge 272s asterisk_calls_count{eid="fa:16:3e:40:0b:25"} 0 272s # HELP asterisk_endpoints_count Current endpoint count. 272s # TYPE asterisk_endpoints_count gauge 272s asterisk_endpoints_count{eid="fa:16:3e:40:0b:25"} 0 272s # HELP asterisk_bridges_count Current bridge count. 272s # TYPE asterisk_bridges_count gauge 272s asterisk_bridges_count{eid="fa:16:3e:40:0b:25"} 0 272s # HELP asterisk_core_properties Asterisk instance properties. The value of this will always be 1. 272s # TYPE asterisk_core_properties counter 272s asterisk_core_properties{eid="fa:16:3e:40:0b:25",version="18.10.0~dfsg+~cs6.10.40431411-2",build_options="OPTIONAL_API, TEST_FRAMEWORK",build_date="2022-02-12 18:24:51 UTC",build_os="Linux",build_kernel="unknown",build_host="buildd.debian.org"} 1 272s # HELP asterisk_core_uptime_seconds Asterisk instance uptime in seconds. 272s # TYPE asterisk_core_uptime_seconds counter 272s asterisk_core_uptime_seconds{eid="fa:16:3e:40:0b:25"} 170 272s # HELP asterisk_core_last_reload_seconds Time since last Asterisk reload in seconds. 272s # TYPE asterisk_core_last_reload_seconds counter 272s asterisk_core_last_reload_seconds{eid="fa:16:3e:40:0b:25"} 170 272s # HELP asterisk_core_scrape_time_ms Total time taken to collect metrics, in milliseconds 272s # TYPE asterisk_core_scrape_time_ms counter 272s asterisk_core_scrape_time_ms{eid="fa:16:3e:40:0b:25"} 0 272s 272s [test_res_prometheus.c:config_general_core_metrics:689]: -> Checking for core properties 272s [test_res_prometheus.c:config_general_core_metrics:692]: -> Checking for uptime 272s [test_res_prometheus.c:config_general_core_metrics:695]: -> Checking for last reload 272s [test_res_prometheus.c:config_general_core_metrics:698]: -> Checking for scrape time 272s END /res/prometheus/ - config_general_core_metrics Time: 1ms Result: PASS 272s START /res/prometheus/ - config_general_basic_auth 272s [test_res_prometheus.c:config_general_basic_auth:554]: Testing without auth credentials 272s [test_res_prometheus.c:config_general_basic_auth:555]: -> CURLing request... 272s [test_res_prometheus.c:config_general_basic_auth:562]: -> CURL returned 401 272s [test_res_prometheus.c:config_general_basic_auth:565]: Testing with invalid auth credentials 272s [test_res_prometheus.c:config_general_basic_auth:566]: -> CURLing request... 272s [test_res_prometheus.c:config_general_basic_auth:575]: -> CURL returned 401 272s [test_res_prometheus.c:config_general_basic_auth:578]: Testing with valid auth credentials 272s [test_res_prometheus.c:config_general_basic_auth:579]: -> CURLing request... 272s [test_res_prometheus.c:config_general_basic_auth:587]: -> CURL returned 200 272s END /res/prometheus/ - config_general_basic_auth Time: 1ms Result: PASS 272s START /res/prometheus/ - config_general_enabled 272s [test_res_prometheus.c:config_general_enabled:627]: -> CURLing request... 272s [test_res_prometheus.c:config_general_enabled:634]: -> CURL returned 503 272s END /res/prometheus/ - config_general_enabled Time: <1ms Result: PASS 272s START /res/prometheus/ - gauge_create 272s END /res/prometheus/ - gauge_create Time: <1ms Result: PASS 272s START /res/prometheus/ - gauge_to_string 272s END /res/prometheus/ - gauge_to_string Time: <1ms Result: PASS 272s START /res/prometheus/ - counter_create 272s END /res/prometheus/ - counter_create Time: <1ms Result: PASS 272s START /res/prometheus/ - counter_to_string 272s END /res/prometheus/ - counter_to_string Time: <1ms Result: PASS 272s START /res/prometheus/ - metric_register 272s [test_res_prometheus.c:metric_register:290]: Testing nominal registration 272s [test_res_prometheus.c:metric_register:291]: -> Static metric 272s [test_res_prometheus.c:metric_register:293]: -> Malloc'd metric 272s [test_res_prometheus.c:metric_register:299]: Testing nominal registration of child metrics 272s [test_res_prometheus.c:metric_register:314]: Testing name collisions 272s [test_res_prometheus.c:metric_register:321]: Testing label collisions 272s [test_res_prometheus.c:metric_register:330]: Testing removal of metrics 272s END /res/prometheus/ - metric_register Time: <1ms Result: PASS 272s START /res/prometheus/ - metric_callback_register 272s [test_res_prometheus.c:metric_callback_register:240]: -> CURLing request... 272s [test_res_prometheus.c:metric_callback_register:249]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 272s # TYPE asterisk_channels_count gauge 272s asterisk_channels_count{eid="fa:16:3e:40:0b:25"} 0 272s # HELP asterisk_calls_sum Total call count. 272s # TYPE asterisk_calls_sum counter 272s asterisk_calls_sum{eid="fa:16:3e:40:0b:25"} 0 272s # HELP asterisk_calls_count Current call count. 272s # TYPE asterisk_calls_count gauge 272s asterisk_calls_count{eid="fa:16:3e:40:0b:25"} 0 272s # HELP asterisk_endpoints_count Current endpoint count. 272s # TYPE asterisk_endpoints_count gauge 272s asterisk_endpoints_count{eid="fa:16:3e:40:0b:25"} 0 272s # HELP asterisk_bridges_count Current bridge count. 272s # TYPE asterisk_bridges_count gauge 272s asterisk_bridges_count{eid="fa:16:3e:40:0b:25"} 0 272s # HELP test_counter A test counter 272s # TYPE test_counter counter 272s test_counter 0 272s 272s END /res/prometheus/ - metric_callback_register Time: <1ms Result: PASS 272s START /res/prometheus/ - metric_values 272s [test_res_prometheus.c:metric_values:165]: -> CURLing request... 272s [test_res_prometheus.c:metric_values:175]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 272s # TYPE asterisk_channels_count gauge 272s asterisk_channels_count{eid="fa:16:3e:40:0b:25"} 0 272s # HELP asterisk_calls_sum Total call count. 272s # TYPE asterisk_calls_sum counter 272s asterisk_calls_sum{eid="fa:16:3e:40:0b:25"} 0 272s # HELP asterisk_calls_count Current call count. 272s # TYPE asterisk_calls_count gauge 272s asterisk_calls_count{eid="fa:16:3e:40:0b:25"} 0 272s # HELP asterisk_endpoints_count Current endpoint count. 272s # TYPE asterisk_endpoints_count gauge 272s asterisk_endpoints_count{eid="fa:16:3e:40:0b:25"} 0 272s # HELP asterisk_bridges_count Current bridge count. 272s # TYPE asterisk_bridges_count gauge 272s asterisk_bridges_count{eid="fa:16:3e:40:0b:25"} 0 272s # HELP test_counter_one A test counter 272s # TYPE test_counter_one counter 272s test_counter_one 1 272s # HELP test_counter_two A test counter 272s # TYPE test_counter_two counter 272s test_counter_two 2 272s 272s END /res/prometheus/ - metric_values Time: <1ms Result: PASS 272s START /res/res_pjproject/ - ast_sockaddr_from_pj_sockaddr_test 272s END /res/res_pjproject/ - ast_sockaddr_from_pj_sockaddr_test Time: <1ms Result: PASS 272s START /res/res_pjproject/ - ast_sockaddr_to_pj_sockaddr_test 272s END /res/res_pjproject/ - ast_sockaddr_to_pj_sockaddr_test Time: <1ms Result: PASS 272s START /res/res_pjsip/ - xml_sanitization_exceeds_buffer 272s END /res/res_pjsip/ - xml_sanitization_exceeds_buffer Time: <1ms Result: PASS 272s START /res/res_pjsip/ - xml_sanitization_end_null 272s END /res/res_pjsip/ - xml_sanitization_end_null Time: <1ms Result: PASS 272s START /res/res_pjsip/scheduler/ - scheduler_policy 272s [test_res_pjsip_scheduler.c:scheduler_policy:355]: This test will take about 4.5 seconds 277s END /res/res_pjsip/scheduler/ - scheduler_policy Time: 4499ms Result: PASS 277s START /res/res_pjsip/scheduler/ - scheduler_cancel 277s [test_res_pjsip_scheduler.c:scheduler_cancel:301]: This test will take about 1.5 seconds 278s END /res/res_pjsip/scheduler/ - scheduler_cancel Time: 1500ms Result: PASS 278s START /res/res_pjsip/scheduler/ - scheduler_cleanup 278s [test_res_pjsip_scheduler.c:scheduler_cleanup:250]: This test will take about 1.6 seconds 280s END /res/res_pjsip/scheduler/ - scheduler_cleanup Time: 1600ms Result: PASS 280s START /res/res_pjsip/scheduler/ - unserialized_scheduler 280s [test_res_pjsip_scheduler.c:scheduler:136]: This test will take about 3.0 seconds 283s END /res/res_pjsip/scheduler/ - unserialized_scheduler Time: 2999ms Result: PASS 283s START /res/res_pjsip/scheduler/ - serialized_scheduler 283s [test_res_pjsip_scheduler.c:scheduler:131]: This test will take about 4.0 seconds 287s END /res/res_pjsip/scheduler/ - serialized_scheduler Time: 3999ms Result: PASS 287s START /res/res_pjsip_pubsub/ - bad_event 287s END /res/res_pjsip_pubsub/ - bad_event Time: <1ms Result: PASS 287s START /res/res_pjsip_pubsub/ - loop 287s END /res/res_pjsip_pubsub/ - loop Time: <1ms Result: PASS 287s START /res/res_pjsip_pubsub/ - duplicate_resource 287s END /res/res_pjsip_pubsub/ - duplicate_resource Time: <1ms Result: PASS 287s START /res/res_pjsip_pubsub/ - bad_branch 287s END /res/res_pjsip_pubsub/ - bad_branch Time: <1ms Result: PASS 287s START /res/res_pjsip_pubsub/ - bad_resource 287s END /res/res_pjsip_pubsub/ - bad_resource Time: <1ms Result: PASS 287s START /res/res_pjsip_pubsub/ - complex_resource_tree 287s END /res/res_pjsip_pubsub/ - complex_resource_tree Time: <1ms Result: PASS 287s START /res/res_pjsip_pubsub/ - resource_tree 287s END /res/res_pjsip_pubsub/ - resource_tree Time: <1ms Result: PASS 287s START /res/res_pjsip_session/ - merge_refresh_topologies 287s [res_pjsip_session.c:test_resolve_refresh_media_states:5776]: Test 1 passed 287s [res_pjsip_session.c:test_resolve_refresh_media_states:5796]: Test 2 passed 287s [res_pjsip_session.c:test_resolve_refresh_media_states:5820]: Test 3 passed 287s [res_pjsip_session.c:test_resolve_refresh_media_states:5839]: Test 4 passed 287s [res_pjsip_session.c:test_resolve_refresh_media_states:5857]: Test 5 passed 287s [res_pjsip_session.c:test_resolve_refresh_media_states:5878]: Test 6 passed 287s [res_pjsip_session.c:test_resolve_refresh_media_states:5904]: Test 7 passed 287s [res_pjsip_session.c:test_resolve_refresh_media_states:5925]: Test 8 passed 287s [res_pjsip_session.c:test_resolve_refresh_media_states:5945]: Test 9 passed 287s [res_pjsip_session.c:test_resolve_refresh_media_states:5965]: Test 10 passed 287s [res_pjsip_session.c:test_resolve_refresh_media_states:5988]: Test 11 passed 287s [res_pjsip_session.c:test_resolve_refresh_media_states:6013]: Test 12 passed 287s [res_pjsip_session.c:test_resolve_refresh_media_states:6047]: Test 13 passed 287s [res_pjsip_session.c:test_resolve_refresh_media_states:6071]: Test 14 passed 287s [res_pjsip_session.c:test_resolve_refresh_media_states:6095]: Test 15 passed 287s END /res/res_pjsip_session/ - merge_refresh_topologies Time: <1ms Result: PASS 287s START /res/res_pjsip_session/caps/ - low_level 287s [test_res_pjsip_session_caps.c:low_level:134]: Testing incoming expected pass 287s [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) 287s [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) 287s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (slin), remote: (all), pref: (local ), outgoing: (no ), expected: (slin) expected result: (PASS) 287s [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) 287s [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) 287s [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) 287s [test_res_pjsip_session_caps.c:low_level:142]: Testing incoming expected fail 287s [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) 287s [test_res_pjsip_session_caps.c:test_create_joint:102]: Expected Failure: Expected: () Actual: (nothing) 287s [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) 287s [test_res_pjsip_session_caps.c:test_create_joint:81]: Expected Failure: Invalid preference string incoming/outgoing combination. 287s [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) 287s [test_res_pjsip_session_caps.c:test_create_joint:81]: Expected Failure: Invalid preference string incoming/outgoing combination. 287s [test_res_pjsip_session_caps.c:low_level:147]: Testing outgoing expected pass 287s [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) 287s [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) 287s [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) 287s [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) 287s [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) 287s [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) 287s [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) 287s END /res/res_pjsip_session/caps/ - low_level Time: <1ms Result: PASS 287s START /res/res_resolver_unbound/ - resolve_srv 287s END /res/res_resolver_unbound/ - resolve_srv Time: 1ms Result: PASS 287s START /res/res_resolver_unbound/ - resolve_naptr 287s END /res/res_resolver_unbound/ - resolve_naptr Time: <1ms Result: PASS 287s START /res/res_resolver_unbound/ - resolve_cancel_off_nominal 287s END /res/res_resolver_unbound/ - resolve_cancel_off_nominal Time: 4ms Result: PASS 287s START /res/res_resolver_unbound/ - resolve_async_off_nominal 287s [res_resolver_unbound.c:off_nominal_async_run:995]: Performing DNS query 'duck.feathers', type 1 287s [res_resolver_unbound.c:off_nominal_async_run:995]: Performing DNS query 'goose.feathers', type 28 287s [res_resolver_unbound.c:off_nominal_async_run:995]: Performing DNS query 'goose.feathers', type 1 287s END /res/res_resolver_unbound/ - resolve_async_off_nominal Time: <1ms Result: PASS 287s START /res/res_resolver_unbound/ - resolve_sync_off_nominal 287s END /res/res_resolver_unbound/ - resolve_sync_off_nominal Time: <1ms Result: PASS 287s START /res/res_resolver_unbound/ - resolve_async 287s [res_resolver_unbound.c:nominal_async_run:713]: Performing DNS query 'goose.feathers', type 1 287s [res_resolver_unbound.c:nominal_async_run:713]: Performing DNS query 'goose.feathers', type 28 287s [res_resolver_unbound.c:nominal_async_run:713]: Performing DNS query 'duck.feathers', type 1 287s END /res/res_resolver_unbound/ - resolve_async Time: <1ms Result: PASS 287s START /res/res_resolver_unbound/ - resolve_sync 287s [res_resolver_unbound.c:nominal_sync_run:563]: Performing DNS query 'goose.feathers', type 1 287s [res_resolver_unbound.c:nominal_sync_run:563]: Performing DNS query 'goose.feathers', type 28 287s [res_resolver_unbound.c:nominal_sync_run:563]: Performing DNS query 'duck.feathers', type 1 287s END /res/res_resolver_unbound/ - resolve_sync Time: <1ms Result: PASS 287s START /res/res_rtp/ - fir_nominal 287s END /res/res_rtp/ - fir_nominal Time: <1ms Result: PASS 287s START /res/res_rtp/ - sr_rr_nominal 287s END /res/res_rtp/ - sr_rr_nominal Time: <1ms Result: PASS 287s START /res/res_rtp/ - remb_nominal 287s END /res/res_rtp/ - remb_nominal Time: <1ms Result: PASS 287s START /res/res_rtp/ - lost_packet_stats_nominal 287s END /res/res_rtp/ - lost_packet_stats_nominal Time: <1ms Result: PASS 287s START /res/res_rtp/ - nack_overflow 287s END /res/res_rtp/ - nack_overflow Time: <1ms Result: PASS 287s START /res/res_rtp/ - nack_nominal 287s END /res/res_rtp/ - nack_nominal Time: <1ms Result: PASS 287s START /res/res_rtp/ - nack_no_packet_loss 287s END /res/res_rtp/ - nack_no_packet_loss Time: <1ms Result: PASS 287s START /res/res_sorcery_memory_cache/ - full_backend_cache_stale 302s END /res/res_sorcery_memory_cache/ - full_backend_cache_stale Time: 15000ms Result: PASS 302s START /res/res_sorcery_memory_cache/ - full_backend_cache_expiration 307s END /res/res_sorcery_memory_cache/ - full_backend_cache_expiration Time: 5000ms Result: PASS 307s START /res/res_sorcery_memory_cache/ - expiration 312s END /res/res_sorcery_memory_cache/ - expiration Time: 4999ms Result: PASS 312s START /res/res_sorcery_memory_cache/ - maximum_objects 312s END /res/res_sorcery_memory_cache/ - maximum_objects Time: 4ms Result: PASS 312s START /res/res_sorcery_memory_cache/ - delete 312s END /res/res_sorcery_memory_cache/ - delete Time: <1ms Result: PASS 312s START /res/res_sorcery_memory_cache/ - create 312s END /res/res_sorcery_memory_cache/ - create Time: <1ms Result: PASS 312s START /res/res_sorcery_memory_cache/ - create 312s END /res/res_sorcery_memory_cache/ - create Time: <1ms Result: PASS 312s START /res/res_sorcery_memory_cache/ - open_with_invalid_options 312s END /res/res_sorcery_memory_cache/ - open_with_invalid_options Time: <1ms Result: PASS 312s START /res/res_sorcery_memory_cache/ - open_with_valid_options 312s END /res/res_sorcery_memory_cache/ - open_with_valid_options Time: <1ms Result: PASS 312s START /res/res_sorcery_memory_cache/ - stale 312s [res_sorcery_memory_cache.c:stale:3189]: Begininning iteration 0 317s [res_sorcery_memory_cache.c:stale:3189]: Begininning iteration 1 322s [res_sorcery_memory_cache.c:stale:3189]: Begininning iteration 2 327s END /res/res_sorcery_memory_cache/ - stale Time: 15008ms Result: PASS 327s START /res/res_sorcery_memory_cache/thrash/ - high_object_count_without_expiration 330s END /res/res_sorcery_memory_cache/thrash/ - high_object_count_without_expiration Time: 3007ms Result: PASS 330s START /res/res_sorcery_memory_cache/thrash/ - conflicting_expire_and_stale 336s END /res/res_sorcery_memory_cache/thrash/ - conflicting_expire_and_stale Time: 6003ms Result: PASS 336s START /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum_with_expire_and_stale 342s END /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum_with_expire_and_stale Time: 6002ms Result: PASS 342s START /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum 345s END /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum Time: 3002ms Result: PASS 345s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_high_concurrent_updates 348s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_high_concurrent_updates Time: 3005ms Result: PASS 348s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_expire 351s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_expire Time: 3001ms Result: PASS 351s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_stale 354s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_stale Time: 3000ms Result: PASS 354s START /res/res_stir_shaken/ - stir_shaken_verify 354s END /res/res_stir_shaken/ - stir_shaken_verify Time: 8ms Result: PASS 354s START /res/res_stir_shaken/ - stir_shaken_sign 354s END /res/res_stir_shaken/ - stir_shaken_sign Time: <1ms Result: PASS 354s START /res/sorcery_astdb/ - object_delete_uncreated 354s END /res/sorcery_astdb/ - object_delete_uncreated Time: <1ms Result: PASS 354s START /res/sorcery_astdb/ - object_delete 354s END /res/sorcery_astdb/ - object_delete Time: <1ms Result: PASS 354s START /res/sorcery_astdb/ - object_update_uncreated 354s END /res/sorcery_astdb/ - object_update_uncreated Time: <1ms Result: PASS 354s START /res/sorcery_astdb/ - object_update 354s END /res/sorcery_astdb/ - object_update Time: <1ms Result: PASS 354s START /res/sorcery_astdb/ - object_retrieve_regex 354s END /res/sorcery_astdb/ - object_retrieve_regex Time: <1ms Result: PASS 354s START /res/sorcery_astdb/ - object_retrieve_multiple_field 354s END /res/sorcery_astdb/ - object_retrieve_multiple_field Time: <1ms Result: PASS 354s START /res/sorcery_astdb/ - object_retrieve_multiple_all 354s END /res/sorcery_astdb/ - object_retrieve_multiple_all Time: <1ms Result: PASS 354s START /res/sorcery_astdb/ - object_retrieve_field 354s END /res/sorcery_astdb/ - object_retrieve_field Time: <1ms Result: PASS 354s START /res/sorcery_astdb/ - object_retrieve_id 354s END /res/sorcery_astdb/ - object_retrieve_id Time: <1ms Result: PASS 354s START /res/sorcery_astdb/ - object_create 354s END /res/sorcery_astdb/ - object_create Time: <1ms Result: PASS 354s START /res/sorcery_realtime/ - object_filter 354s END /res/sorcery_realtime/ - object_filter Time: <1ms Result: PASS 354s START /res/sorcery_realtime/ - object_allocate_on_retrieval 354s END /res/sorcery_realtime/ - object_allocate_on_retrieval Time: <1ms Result: PASS 354s START /res/sorcery_realtime/ - object_delete_uncreated 354s END /res/sorcery_realtime/ - object_delete_uncreated Time: <1ms Result: PASS 354s START /res/sorcery_realtime/ - object_delete 354s END /res/sorcery_realtime/ - object_delete Time: <1ms Result: PASS 354s START /res/sorcery_realtime/ - object_update 354s END /res/sorcery_realtime/ - object_update Time: <1ms Result: PASS 354s START /res/sorcery_realtime/ - object_retrieve_regex_nofetch 354s END /res/sorcery_realtime/ - object_retrieve_regex_nofetch Time: <1ms Result: PASS 354s START /res/sorcery_realtime/ - object_retrieve_regex 354s END /res/sorcery_realtime/ - object_retrieve_regex Time: <1ms Result: PASS 354s START /res/sorcery_realtime/ - object_retrieve_multiple_field 354s END /res/sorcery_realtime/ - object_retrieve_multiple_field Time: <1ms Result: PASS 354s START /res/sorcery_realtime/ - object_retrieve_multiple_all_nofetch 354s END /res/sorcery_realtime/ - object_retrieve_multiple_all_nofetch Time: <1ms Result: PASS 354s START /res/sorcery_realtime/ - object_retrieve_multiple_all 354s END /res/sorcery_realtime/ - object_retrieve_multiple_all Time: <1ms Result: PASS 354s START /res/sorcery_realtime/ - object_retrieve_field 354s END /res/sorcery_realtime/ - object_retrieve_field Time: <1ms Result: PASS 354s START /res/sorcery_realtime/ - object_retrieve_id 354s END /res/sorcery_realtime/ - object_retrieve_id Time: <1ms Result: PASS 354s START /res/sorcery_realtime/ - object_create 354s END /res/sorcery_realtime/ - object_create Time: <1ms Result: PASS 354s START /res/websocket/ - websocket_client_multiple_protocols 354s END /res/websocket/ - websocket_client_multiple_protocols Time: 1ms Result: PASS 354s START /res/websocket/ - websocket_client_unsupported_protocol 354s END /res/websocket/ - websocket_client_unsupported_protocol Time: <1ms Result: PASS 354s START /res/websocket/ - websocket_client_bad_url 354s END /res/websocket/ - websocket_client_bad_url Time: <1ms Result: PASS 354s START /stasis/channels/ - channel_snapshot_json 354s END /stasis/channels/ - channel_snapshot_json Time: <1ms Result: PASS 354s START /stasis/channels/ - multi_channel_blob_snapshots 354s END /stasis/channels/ - multi_channel_blob_snapshots Time: <1ms Result: PASS 354s START /stasis/channels/ - multi_channel_blob_create 354s END /stasis/channels/ - multi_channel_blob_create Time: <1ms Result: PASS 354s START /stasis/channels/ - null_blob 354s END /stasis/channels/ - null_blob Time: <1ms Result: PASS 354s START /stasis/channels/ - channel_blob_create 354s END /stasis/channels/ - channel_blob_create Time: <1ms Result: PASS 354s START /stasis/core/ - caching_dtor_order 354s END /stasis/core/ - caching_dtor_order Time: <1ms Result: PASS 354s START /stasis/core/ - dtor_order 354s END /stasis/core/ - dtor_order Time: <1ms Result: PASS 354s START /stasis/core/ - to_ami 354s END /stasis/core/ - to_ami Time: <1ms Result: PASS 354s START /stasis/core/ - no_to_ami 354s END /stasis/core/ - no_to_ami Time: <1ms Result: PASS 354s START /stasis/core/ - to_json 354s END /stasis/core/ - to_json Time: <1ms Result: PASS 354s START /stasis/core/ - no_to_json 354s END /stasis/core/ - no_to_json Time: <1ms Result: PASS 354s START /stasis/core/ - subscription_interleaving 354s END /stasis/core/ - subscription_interleaving Time: 1ms Result: PASS 354s START /stasis/core/ - interleaving 354s END /stasis/core/ - interleaving Time: <1ms Result: PASS 354s START /stasis/core/ - router_cache_updates 354s END /stasis/core/ - router_cache_updates Time: 100ms Result: PASS 354s START /stasis/core/ - router_pool 354s END /stasis/core/ - router_pool Time: <1ms Result: PASS 354s START /stasis/core/ - router 354s END /stasis/core/ - router Time: <1ms Result: PASS 354s START /stasis/core/ - cache_eid_aggregate 354s END /stasis/core/ - cache_eid_aggregate Time: <1ms Result: PASS 354s START /stasis/core/ - cache_dump 354s END /stasis/core/ - cache_dump Time: <1ms Result: PASS 354s START /stasis/core/ - cache 354s END /stasis/core/ - cache Time: <1ms Result: PASS 354s START /stasis/core/ - cache_filter 354s END /stasis/core/ - cache_filter Time: 100ms Result: PASS 354s START /stasis/core/ - forward 354s END /stasis/core/ - forward Time: <1ms Result: PASS 354s START /stasis/core/ - unsubscribe_stops_messages 354s END /stasis/core/ - unsubscribe_stops_messages Time: 100ms Result: PASS 354s START /stasis/core/ - publish_pool 354s END /stasis/core/ - publish_pool Time: <1ms Result: PASS 354s START /stasis/core/ - publish_sync 354s END /stasis/core/ - publish_sync Time: <1ms Result: PASS 354s START /stasis/core/ - publish 354s END /stasis/core/ - publish Time: <1ms Result: PASS 354s START /stasis/core/ - subscription_pool_messages 354s END /stasis/core/ - subscription_pool_messages Time: <1ms Result: PASS 354s START /stasis/core/ - subscription_messages 354s END /stasis/core/ - subscription_messages Time: <1ms Result: PASS 354s START /stasis/core/ - message 354s END /stasis/core/ - message Time: <1ms Result: PASS 354s START /stasis/core/ - message_type 354s END /stasis/core/ - message_type Time: <1ms Result: PASS 354s START /stasis/core/filtering/ - combo_filters 354s [test_stasis.c:dump_consumer:2198]: Messages received: 7 Final? yes 354s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 354s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType1 Pass 354s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass 354s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMI Pass 354s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass 354s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageJSON Pass 354s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 354s END /stasis/core/filtering/ - combo_filters Time: <1ms Result: PASS 354s START /stasis/core/filtering/ - formatter_filters 354s [test_stasis.c:dump_consumer:2198]: Messages received: 7 Final? yes 354s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 354s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMI Pass 354s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageJSON Pass 354s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass 354s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass2 354s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageEVENT Pass 354s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 354s END /stasis/core/filtering/ - formatter_filters Time: <1ms Result: PASS 354s START /stasis/core/filtering/ - type_filters 354s [test_stasis.c:dump_consumer:2198]: Messages received: 5 Final? yes 354s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 354s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType1 Pass 354s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass 354s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass2 354s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 354s END /stasis/core/filtering/ - type_filters Time: <1ms Result: PASS 354s START /stasis/core/state/ - explicit_publish 354s END /stasis/core/state/ - explicit_publish Time: 18ms Result: PASS 354s START /stasis/core/state/ - implicit_publish 354s END /stasis/core/state/ - implicit_publish Time: 23ms Result: PASS 354s START /stasis/endpoints/ - channel_messages 354s END /stasis/endpoints/ - channel_messages Time: <1ms Result: PASS 354s START /stasis/endpoints/ - cache_clear 354s END /stasis/endpoints/ - cache_clear Time: <1ms Result: PASS 354s START /stasis/endpoints/ - state_changes 354s END /stasis/endpoints/ - state_changes Time: <1ms Result: PASS 354s START /stasis/res/ - app_invoke_dne 354s END /stasis/res/ - app_invoke_dne Time: <1ms Result: PASS 354s START /stasis/res/ - app_invoke_one 354s END /stasis/res/ - app_invoke_one Time: <1ms Result: PASS 354s START /stasis/res/ - app_replaced 354s END /stasis/res/ - app_replaced Time: <1ms Result: PASS 354s 354s 624 Test(s) Executed 624 Passed 0 Failed 354s Results Generated Successfully: /tmp/autopkgtest.zyKW5F/build.HFt/src/debian/tests/testmods/output/results.txt 354s Some test modules were not loaded: 354s 15a16 354s > test_cel.so 354s 47a49 354s > test_message.so 354s Manually disabled: 354s test_message 354s test_cel 354s 356s autopkgtest [13:14:33]: test asttestmods: -----------------------] 356s autopkgtest [13:14:33]: test asttestmods: - - - - - - - - - - results - - - - - - - - - - 356s asttestmods PASS 357s autopkgtest [13:14:34]: test amr: preparing testbed 483s autopkgtest [13:16:40]: testbed dpkg architecture: amd64 483s autopkgtest [13:16:40]: testbed apt version: 2.4.13 483s autopkgtest [13:16:40]: @@@@@@@@@@@@@@@@@@@@ test bed setup 483s autopkgtest [13:16:40]: testbed release detected to be: jammy 484s autopkgtest [13:16:41]: updating testbed package index (apt update) 485s Hit:1 http://ftpmaster.internal/ubuntu jammy InRelease 485s Hit:2 http://ftpmaster.internal/ubuntu jammy-updates InRelease 485s Hit:3 http://ftpmaster.internal/ubuntu jammy-security InRelease 485s Get:4 http://ftpmaster.internal/ubuntu jammy-proposed InRelease [279 kB] 485s Get:5 http://ftpmaster.internal/ubuntu jammy-proposed/restricted Sources [24.7 kB] 485s Get:6 http://ftpmaster.internal/ubuntu jammy-proposed/universe Sources [29.3 kB] 485s Get:7 http://ftpmaster.internal/ubuntu jammy-proposed/main Sources [113 kB] 485s Get:8 http://ftpmaster.internal/ubuntu jammy-proposed/main i386 Packages [103 kB] 485s Get:9 http://ftpmaster.internal/ubuntu jammy-proposed/main amd64 Packages [378 kB] 486s Get:10 http://ftpmaster.internal/ubuntu jammy-proposed/main amd64 c-n-f Metadata [2204 B] 486s Get:11 http://ftpmaster.internal/ubuntu jammy-proposed/restricted amd64 Packages [593 kB] 486s Get:12 http://ftpmaster.internal/ubuntu jammy-proposed/restricted i386 Packages [1704 B] 486s Get:13 http://ftpmaster.internal/ubuntu jammy-proposed/restricted amd64 c-n-f Metadata [116 B] 486s Get:14 http://ftpmaster.internal/ubuntu jammy-proposed/universe i386 Packages [34.8 kB] 486s Get:15 http://ftpmaster.internal/ubuntu jammy-proposed/universe amd64 Packages [89.5 kB] 486s Get:16 http://ftpmaster.internal/ubuntu jammy-proposed/universe amd64 c-n-f Metadata [1852 B] 486s Get:17 http://ftpmaster.internal/ubuntu jammy-proposed/multiverse amd64 c-n-f Metadata [116 B] 488s Fetched 1651 kB in 1s (1506 kB/s) 489s Reading package lists... 490s Reading package lists... 490s Building dependency tree... 490s Reading state information... 490s Calculating upgrade... 490s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 491s Reading package lists... 491s Building dependency tree... 491s Reading state information... 491s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 491s autopkgtest [13:16:48]: upgrading testbed (apt dist-upgrade and autopurge) 491s Reading package lists... 492s Building dependency tree... 492s Reading state information... 492s Calculating upgrade...Starting pkgProblemResolver with broken count: 0 492s Starting 2 pkgProblemResolver with broken count: 0 492s Done 493s Entering ResolveByKeep 493s 493s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 494s Reading package lists... 494s Building dependency tree... 494s Reading state information... 494s Starting pkgProblemResolver with broken count: 0 494s Starting 2 pkgProblemResolver with broken count: 0 494s Done 495s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 498s Reading package lists... 498s Building dependency tree... 498s Reading state information... 498s Starting pkgProblemResolver with broken count: 0 498s Starting 2 pkgProblemResolver with broken count: 0 498s Done 499s The following NEW packages will be installed: 499s asterisk asterisk-config asterisk-core-sounds-en asterisk-core-sounds-en-gsm 499s asterisk-modules freetds-common libasound2 libasound2-data libc-client2007e 499s libcodec2-1.0 libdeflate0 libevent-2.1-7 libgmime-3.0-0 libgsm1 libical3 499s libiksemel3 libjack-jackd2-0 libjbig0 libjpeg-turbo8 libjpeg8 libltdl7 499s liblua5.2-0 libneon27 libodbc2 libogg0 libopencore-amrnb0 libopencore-amrwb0 499s libopus0 libopusfile0 libportaudio2 libpq5 libradcli4 libresample1 499s libsamplerate0 libsensors-config libsensors5 libsnmp-base libsnmp40 499s libspandsp2 libspeex1 libspeexdsp1 libsrtp2-1 libsybdb5 libtiff5 libunbound8 499s liburiparser1 libvo-amrwbenc0 libvorbis0a libvorbisenc2 libvorbisfile3 499s libwebp7 libxslt1.1 mlock 499s 0 upgraded, 53 newly installed, 0 to remove and 0 not upgraded. 499s Need to get 24.9 MB of archives. 499s After this operation, 65.5 MB of additional disk space will be used. 499s Get:1 http://ftpmaster.internal/ubuntu jammy/universe amd64 asterisk-config all 1:18.10.0~dfsg+~cs6.10.40431411-2 [234 kB] 500s Get:2 http://ftpmaster.internal/ubuntu jammy/universe amd64 asterisk-core-sounds-en-gsm all 1.6.1-1 [2417 kB] 500s Get:3 http://ftpmaster.internal/ubuntu jammy/universe amd64 asterisk-core-sounds-en all 1.6.1-1 [20.6 kB] 500s Get:4 http://ftpmaster.internal/ubuntu jammy/main amd64 libasound2-data all 1.2.6.1-1ubuntu1 [19.1 kB] 500s Get:5 http://ftpmaster.internal/ubuntu jammy/main amd64 libasound2 amd64 1.2.6.1-1ubuntu1 [390 kB] 500s Get:6 http://ftpmaster.internal/ubuntu jammy/universe amd64 mlock amd64 8:2007f~dfsg-7build1 [12.2 kB] 500s Get:7 http://ftpmaster.internal/ubuntu jammy/universe amd64 libc-client2007e amd64 8:2007f~dfsg-7build1 [645 kB] 500s Get:8 http://ftpmaster.internal/ubuntu jammy/universe amd64 libcodec2-1.0 amd64 1.0.1-3 [8435 kB] 500s Get:9 http://ftpmaster.internal/ubuntu jammy/universe amd64 libgmime-3.0-0 amd64 3.2.7-1 [157 kB] 500s Get:10 http://ftpmaster.internal/ubuntu jammy/universe amd64 libgsm1 amd64 1.0.19-1 [27.7 kB] 500s Get:11 http://ftpmaster.internal/ubuntu jammy/main amd64 libical3 amd64 3.0.14-1build1 [327 kB] 500s Get:12 http://ftpmaster.internal/ubuntu jammy/universe amd64 libiksemel3 amd64 1.4-4 [29.2 kB] 500s Get:13 http://ftpmaster.internal/ubuntu jammy/main amd64 libsamplerate0 amd64 0.2.2-1build1 [1359 kB] 500s Get:14 http://ftpmaster.internal/ubuntu jammy/main amd64 libjack-jackd2-0 amd64 1.9.20~dfsg-1 [293 kB] 500s Get:15 http://ftpmaster.internal/ubuntu jammy/universe amd64 liblua5.2-0 amd64 5.2.4-2 [125 kB] 500s Get:16 http://ftpmaster.internal/ubuntu jammy/universe amd64 libneon27 amd64 0.32.2-1 [102 kB] 500s Get:17 http://ftpmaster.internal/ubuntu jammy/main amd64 libltdl7 amd64 2.4.6-15build2 [39.6 kB] 500s Get:18 http://ftpmaster.internal/ubuntu jammy-updates/main amd64 libodbc2 amd64 2.3.9-5ubuntu0.1 [159 kB] 500s Get:19 http://ftpmaster.internal/ubuntu jammy/main amd64 libogg0 amd64 1.3.5-0ubuntu3 [22.9 kB] 500s Get:20 http://ftpmaster.internal/ubuntu jammy/universe amd64 libopencore-amrnb0 amd64 0.1.5-1 [94.8 kB] 500s Get:21 http://ftpmaster.internal/ubuntu jammy/universe amd64 libopencore-amrwb0 amd64 0.1.5-1 [49.1 kB] 500s Get:22 http://ftpmaster.internal/ubuntu jammy/main amd64 libopus0 amd64 1.3.1-0.1build2 [203 kB] 500s Get:23 http://ftpmaster.internal/ubuntu jammy/universe amd64 libopusfile0 amd64 0.9+20170913-1.1build1 [43.2 kB] 500s Get:24 http://ftpmaster.internal/ubuntu jammy/universe amd64 libportaudio2 amd64 19.6.0-1.1 [65.3 kB] 500s Get:25 http://ftpmaster.internal/ubuntu jammy-updates/main amd64 libpq5 amd64 14.17-0ubuntu0.22.04.1 [152 kB] 500s Get:26 http://ftpmaster.internal/ubuntu jammy/universe amd64 libradcli4 amd64 1.2.11-1build1 [40.0 kB] 500s Get:27 http://ftpmaster.internal/ubuntu jammy/universe amd64 libresample1 amd64 0.1.3-5 [9548 B] 500s Get:28 http://ftpmaster.internal/ubuntu jammy/main amd64 libsensors-config all 1:3.6.0-7ubuntu1 [5274 B] 500s Get:29 http://ftpmaster.internal/ubuntu jammy/main amd64 libsensors5 amd64 1:3.6.0-7ubuntu1 [26.3 kB] 500s Get:30 http://ftpmaster.internal/ubuntu jammy-proposed/main amd64 libsnmp-base all 5.9.1+dfsg-1ubuntu2.8 [201 kB] 500s Get:31 http://ftpmaster.internal/ubuntu jammy-proposed/main amd64 libsnmp40 amd64 5.9.1+dfsg-1ubuntu2.8 [1070 kB] 500s Get:32 http://ftpmaster.internal/ubuntu jammy/main amd64 libdeflate0 amd64 1.10-2 [70.9 kB] 500s Get:33 http://ftpmaster.internal/ubuntu jammy-updates/main amd64 libjbig0 amd64 2.1-3.1ubuntu0.22.04.1 [29.2 kB] 500s Get:34 http://ftpmaster.internal/ubuntu jammy/main amd64 libjpeg-turbo8 amd64 2.1.2-0ubuntu1 [134 kB] 500s Get:35 http://ftpmaster.internal/ubuntu jammy/main amd64 libjpeg8 amd64 8c-2ubuntu10 [2264 B] 500s Get:36 http://ftpmaster.internal/ubuntu jammy-updates/main amd64 libwebp7 amd64 1.2.2-2ubuntu0.22.04.2 [206 kB] 500s Get:37 http://ftpmaster.internal/ubuntu jammy-updates/main amd64 libtiff5 amd64 4.3.0-6ubuntu0.10 [185 kB] 500s Get:38 http://ftpmaster.internal/ubuntu jammy/universe amd64 libspandsp2 amd64 0.0.6+dfsg-2 [272 kB] 500s Get:39 http://ftpmaster.internal/ubuntu jammy/main amd64 libspeex1 amd64 1.2~rc1.2-1.1ubuntu3 [57.9 kB] 500s Get:40 http://ftpmaster.internal/ubuntu jammy/main amd64 libspeexdsp1 amd64 1.2~rc1.2-1.1ubuntu3 [42.5 kB] 500s Get:41 http://ftpmaster.internal/ubuntu jammy/universe amd64 libsrtp2-1 amd64 2.4.2-2 [40.7 kB] 501s Get:42 http://ftpmaster.internal/ubuntu jammy/main amd64 freetds-common all 1.3.6-1 [26.3 kB] 501s Get:43 http://ftpmaster.internal/ubuntu jammy/main amd64 libsybdb5 amd64 1.3.6-1 [194 kB] 501s Get:44 http://ftpmaster.internal/ubuntu jammy/main amd64 libevent-2.1-7 amd64 2.1.12-stable-1build3 [148 kB] 501s Get:45 http://ftpmaster.internal/ubuntu jammy-updates/main amd64 libunbound8 amd64 1.13.1-1ubuntu5.8 [400 kB] 501s Get:46 http://ftpmaster.internal/ubuntu jammy/universe amd64 libvo-amrwbenc0 amd64 0.1.3-2 [68.2 kB] 501s Get:47 http://ftpmaster.internal/ubuntu jammy/main amd64 libvorbis0a amd64 1.3.7-1build2 [99.2 kB] 501s Get:48 http://ftpmaster.internal/ubuntu jammy/main amd64 libvorbisenc2 amd64 1.3.7-1build2 [82.6 kB] 501s Get:49 http://ftpmaster.internal/ubuntu jammy/main amd64 libvorbisfile3 amd64 1.3.7-1build2 [17.1 kB] 501s Get:50 http://ftpmaster.internal/ubuntu jammy/universe amd64 asterisk-modules amd64 1:18.10.0~dfsg+~cs6.10.40431411-2 [3232 kB] 501s Get:51 http://ftpmaster.internal/ubuntu jammy/universe amd64 liburiparser1 amd64 0.9.6+dfsg-1 [36.4 kB] 501s Get:52 http://ftpmaster.internal/ubuntu jammy-updates/main amd64 libxslt1.1 amd64 1.1.34-4ubuntu0.22.04.1 [164 kB] 501s Get:53 http://ftpmaster.internal/ubuntu jammy/universe amd64 asterisk amd64 1:18.10.0~dfsg+~cs6.10.40431411-2 [2608 kB] 501s Fetched 24.9 MB in 2s (14.5 MB/s) 501s Selecting previously unselected package asterisk-config. 502s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 67962 files and directories currently installed.) 502s Preparing to unpack .../00-asterisk-config_1%3a18.10.0~dfsg+~cs6.10.40431411-2_all.deb ... 502s Unpacking asterisk-config (1:18.10.0~dfsg+~cs6.10.40431411-2) ... 502s Selecting previously unselected package asterisk-core-sounds-en-gsm. 502s Preparing to unpack .../01-asterisk-core-sounds-en-gsm_1.6.1-1_all.deb ... 502s Unpacking asterisk-core-sounds-en-gsm (1.6.1-1) ... 502s Selecting previously unselected package asterisk-core-sounds-en. 502s Preparing to unpack .../02-asterisk-core-sounds-en_1.6.1-1_all.deb ... 502s Unpacking asterisk-core-sounds-en (1.6.1-1) ... 502s Selecting previously unselected package libasound2-data. 502s Preparing to unpack .../03-libasound2-data_1.2.6.1-1ubuntu1_all.deb ... 502s Unpacking libasound2-data (1.2.6.1-1ubuntu1) ... 502s Selecting previously unselected package libasound2:amd64. 502s Preparing to unpack .../04-libasound2_1.2.6.1-1ubuntu1_amd64.deb ... 502s Unpacking libasound2:amd64 (1.2.6.1-1ubuntu1) ... 502s Selecting previously unselected package mlock. 502s Preparing to unpack .../05-mlock_8%3a2007f~dfsg-7build1_amd64.deb ... 502s Unpacking mlock (8:2007f~dfsg-7build1) ... 502s Selecting previously unselected package libc-client2007e. 502s Preparing to unpack .../06-libc-client2007e_8%3a2007f~dfsg-7build1_amd64.deb ... 502s Unpacking libc-client2007e (8:2007f~dfsg-7build1) ... 502s Selecting previously unselected package libcodec2-1.0:amd64. 502s Preparing to unpack .../07-libcodec2-1.0_1.0.1-3_amd64.deb ... 502s Unpacking libcodec2-1.0:amd64 (1.0.1-3) ... 502s Selecting previously unselected package libgmime-3.0-0:amd64. 502s Preparing to unpack .../08-libgmime-3.0-0_3.2.7-1_amd64.deb ... 502s Unpacking libgmime-3.0-0:amd64 (3.2.7-1) ... 502s Selecting previously unselected package libgsm1:amd64. 502s Preparing to unpack .../09-libgsm1_1.0.19-1_amd64.deb ... 502s Unpacking libgsm1:amd64 (1.0.19-1) ... 502s Selecting previously unselected package libical3:amd64. 502s Preparing to unpack .../10-libical3_3.0.14-1build1_amd64.deb ... 502s Unpacking libical3:amd64 (3.0.14-1build1) ... 502s Selecting previously unselected package libiksemel3:amd64. 502s Preparing to unpack .../11-libiksemel3_1.4-4_amd64.deb ... 502s Unpacking libiksemel3:amd64 (1.4-4) ... 502s Selecting previously unselected package libsamplerate0:amd64. 502s Preparing to unpack .../12-libsamplerate0_0.2.2-1build1_amd64.deb ... 502s Unpacking libsamplerate0:amd64 (0.2.2-1build1) ... 502s Selecting previously unselected package libjack-jackd2-0:amd64. 502s Preparing to unpack .../13-libjack-jackd2-0_1.9.20~dfsg-1_amd64.deb ... 502s Unpacking libjack-jackd2-0:amd64 (1.9.20~dfsg-1) ... 502s Selecting previously unselected package liblua5.2-0:amd64. 502s Preparing to unpack .../14-liblua5.2-0_5.2.4-2_amd64.deb ... 502s Unpacking liblua5.2-0:amd64 (5.2.4-2) ... 502s Selecting previously unselected package libneon27:amd64. 502s Preparing to unpack .../15-libneon27_0.32.2-1_amd64.deb ... 502s Unpacking libneon27:amd64 (0.32.2-1) ... 502s Selecting previously unselected package libltdl7:amd64. 502s Preparing to unpack .../16-libltdl7_2.4.6-15build2_amd64.deb ... 502s Unpacking libltdl7:amd64 (2.4.6-15build2) ... 502s Selecting previously unselected package libodbc2:amd64. 502s Preparing to unpack .../17-libodbc2_2.3.9-5ubuntu0.1_amd64.deb ... 502s Unpacking libodbc2:amd64 (2.3.9-5ubuntu0.1) ... 502s Selecting previously unselected package libogg0:amd64. 502s Preparing to unpack .../18-libogg0_1.3.5-0ubuntu3_amd64.deb ... 502s Unpacking libogg0:amd64 (1.3.5-0ubuntu3) ... 502s Selecting previously unselected package libopencore-amrnb0:amd64. 502s Preparing to unpack .../19-libopencore-amrnb0_0.1.5-1_amd64.deb ... 502s Unpacking libopencore-amrnb0:amd64 (0.1.5-1) ... 502s Selecting previously unselected package libopencore-amrwb0:amd64. 502s Preparing to unpack .../20-libopencore-amrwb0_0.1.5-1_amd64.deb ... 502s Unpacking libopencore-amrwb0:amd64 (0.1.5-1) ... 502s Selecting previously unselected package libopus0:amd64. 502s Preparing to unpack .../21-libopus0_1.3.1-0.1build2_amd64.deb ... 502s Unpacking libopus0:amd64 (1.3.1-0.1build2) ... 502s Selecting previously unselected package libopusfile0. 502s Preparing to unpack .../22-libopusfile0_0.9+20170913-1.1build1_amd64.deb ... 502s Unpacking libopusfile0 (0.9+20170913-1.1build1) ... 502s Selecting previously unselected package libportaudio2:amd64. 503s Preparing to unpack .../23-libportaudio2_19.6.0-1.1_amd64.deb ... 503s Unpacking libportaudio2:amd64 (19.6.0-1.1) ... 503s Selecting previously unselected package libpq5:amd64. 503s Preparing to unpack .../24-libpq5_14.17-0ubuntu0.22.04.1_amd64.deb ... 503s Unpacking libpq5:amd64 (14.17-0ubuntu0.22.04.1) ... 503s Selecting previously unselected package libradcli4. 503s Preparing to unpack .../25-libradcli4_1.2.11-1build1_amd64.deb ... 503s Unpacking libradcli4 (1.2.11-1build1) ... 503s Selecting previously unselected package libresample1. 503s Preparing to unpack .../26-libresample1_0.1.3-5_amd64.deb ... 503s Unpacking libresample1 (0.1.3-5) ... 503s Selecting previously unselected package libsensors-config. 503s Preparing to unpack .../27-libsensors-config_1%3a3.6.0-7ubuntu1_all.deb ... 503s Unpacking libsensors-config (1:3.6.0-7ubuntu1) ... 503s Selecting previously unselected package libsensors5:amd64. 503s Preparing to unpack .../28-libsensors5_1%3a3.6.0-7ubuntu1_amd64.deb ... 503s Unpacking libsensors5:amd64 (1:3.6.0-7ubuntu1) ... 503s Selecting previously unselected package libsnmp-base. 503s Preparing to unpack .../29-libsnmp-base_5.9.1+dfsg-1ubuntu2.8_all.deb ... 503s Unpacking libsnmp-base (5.9.1+dfsg-1ubuntu2.8) ... 503s Selecting previously unselected package libsnmp40:amd64. 503s Preparing to unpack .../30-libsnmp40_5.9.1+dfsg-1ubuntu2.8_amd64.deb ... 503s Unpacking libsnmp40:amd64 (5.9.1+dfsg-1ubuntu2.8) ... 503s Selecting previously unselected package libdeflate0:amd64. 503s Preparing to unpack .../31-libdeflate0_1.10-2_amd64.deb ... 503s Unpacking libdeflate0:amd64 (1.10-2) ... 503s Selecting previously unselected package libjbig0:amd64. 503s Preparing to unpack .../32-libjbig0_2.1-3.1ubuntu0.22.04.1_amd64.deb ... 503s Unpacking libjbig0:amd64 (2.1-3.1ubuntu0.22.04.1) ... 503s Selecting previously unselected package libjpeg-turbo8:amd64. 503s Preparing to unpack .../33-libjpeg-turbo8_2.1.2-0ubuntu1_amd64.deb ... 503s Unpacking libjpeg-turbo8:amd64 (2.1.2-0ubuntu1) ... 503s Selecting previously unselected package libjpeg8:amd64. 503s Preparing to unpack .../34-libjpeg8_8c-2ubuntu10_amd64.deb ... 503s Unpacking libjpeg8:amd64 (8c-2ubuntu10) ... 503s Selecting previously unselected package libwebp7:amd64. 503s Preparing to unpack .../35-libwebp7_1.2.2-2ubuntu0.22.04.2_amd64.deb ... 503s Unpacking libwebp7:amd64 (1.2.2-2ubuntu0.22.04.2) ... 503s Selecting previously unselected package libtiff5:amd64. 503s Preparing to unpack .../36-libtiff5_4.3.0-6ubuntu0.10_amd64.deb ... 503s Unpacking libtiff5:amd64 (4.3.0-6ubuntu0.10) ... 503s Selecting previously unselected package libspandsp2:amd64. 503s Preparing to unpack .../37-libspandsp2_0.0.6+dfsg-2_amd64.deb ... 503s Unpacking libspandsp2:amd64 (0.0.6+dfsg-2) ... 503s Selecting previously unselected package libspeex1:amd64. 503s Preparing to unpack .../38-libspeex1_1.2~rc1.2-1.1ubuntu3_amd64.deb ... 503s Unpacking libspeex1:amd64 (1.2~rc1.2-1.1ubuntu3) ... 503s Selecting previously unselected package libspeexdsp1:amd64. 503s Preparing to unpack .../39-libspeexdsp1_1.2~rc1.2-1.1ubuntu3_amd64.deb ... 503s Unpacking libspeexdsp1:amd64 (1.2~rc1.2-1.1ubuntu3) ... 503s Selecting previously unselected package libsrtp2-1:amd64. 503s Preparing to unpack .../40-libsrtp2-1_2.4.2-2_amd64.deb ... 503s Unpacking libsrtp2-1:amd64 (2.4.2-2) ... 503s Selecting previously unselected package freetds-common. 503s Preparing to unpack .../41-freetds-common_1.3.6-1_all.deb ... 503s Unpacking freetds-common (1.3.6-1) ... 503s Selecting previously unselected package libsybdb5:amd64. 503s Preparing to unpack .../42-libsybdb5_1.3.6-1_amd64.deb ... 503s Unpacking libsybdb5:amd64 (1.3.6-1) ... 503s Selecting previously unselected package libevent-2.1-7:amd64. 503s Preparing to unpack .../43-libevent-2.1-7_2.1.12-stable-1build3_amd64.deb ... 503s Unpacking libevent-2.1-7:amd64 (2.1.12-stable-1build3) ... 503s Selecting previously unselected package libunbound8:amd64. 503s Preparing to unpack .../44-libunbound8_1.13.1-1ubuntu5.8_amd64.deb ... 503s Unpacking libunbound8:amd64 (1.13.1-1ubuntu5.8) ... 503s Selecting previously unselected package libvo-amrwbenc0:amd64. 503s Preparing to unpack .../45-libvo-amrwbenc0_0.1.3-2_amd64.deb ... 503s Unpacking libvo-amrwbenc0:amd64 (0.1.3-2) ... 503s Selecting previously unselected package libvorbis0a:amd64. 503s Preparing to unpack .../46-libvorbis0a_1.3.7-1build2_amd64.deb ... 503s Unpacking libvorbis0a:amd64 (1.3.7-1build2) ... 503s Selecting previously unselected package libvorbisenc2:amd64. 503s Preparing to unpack .../47-libvorbisenc2_1.3.7-1build2_amd64.deb ... 503s Unpacking libvorbisenc2:amd64 (1.3.7-1build2) ... 503s Selecting previously unselected package libvorbisfile3:amd64. 503s Preparing to unpack .../48-libvorbisfile3_1.3.7-1build2_amd64.deb ... 503s Unpacking libvorbisfile3:amd64 (1.3.7-1build2) ... 503s Selecting previously unselected package asterisk-modules. 503s Preparing to unpack .../49-asterisk-modules_1%3a18.10.0~dfsg+~cs6.10.40431411-2_amd64.deb ... 503s Unpacking asterisk-modules (1:18.10.0~dfsg+~cs6.10.40431411-2) ... 503s Selecting previously unselected package liburiparser1:amd64. 503s Preparing to unpack .../50-liburiparser1_0.9.6+dfsg-1_amd64.deb ... 503s Unpacking liburiparser1:amd64 (0.9.6+dfsg-1) ... 503s Selecting previously unselected package libxslt1.1:amd64. 503s Preparing to unpack .../51-libxslt1.1_1.1.34-4ubuntu0.22.04.1_amd64.deb ... 503s Unpacking libxslt1.1:amd64 (1.1.34-4ubuntu0.22.04.1) ... 503s Selecting previously unselected package asterisk. 503s Preparing to unpack .../52-asterisk_1%3a18.10.0~dfsg+~cs6.10.40431411-2_amd64.deb ... 503s Unpacking asterisk (1:18.10.0~dfsg+~cs6.10.40431411-2) ... 503s Setting up libgmime-3.0-0:amd64 (3.2.7-1) ... 503s Setting up libvo-amrwbenc0:amd64 (0.1.3-2) ... 503s Setting up libcodec2-1.0:amd64 (1.0.1-3) ... 503s Setting up libogg0:amd64 (1.3.5-0ubuntu3) ... 503s Setting up libspeex1:amd64 (1.2~rc1.2-1.1ubuntu3) ... 503s Setting up libgsm1:amd64 (1.0.19-1) ... 503s Setting up asterisk-core-sounds-en-gsm (1.6.1-1) ... 503s Setting up libsnmp-base (5.9.1+dfsg-1ubuntu2.8) ... 503s Setting up mlock (8:2007f~dfsg-7build1) ... 503s Setting up libsrtp2-1:amd64 (2.4.2-2) ... 503s Setting up libsensors-config (1:3.6.0-7ubuntu1) ... 503s Setting up libpq5:amd64 (14.17-0ubuntu0.22.04.1) ... 503s Setting up libdeflate0:amd64 (1.10-2) ... 503s Setting up libjbig0:amd64 (2.1-3.1ubuntu0.22.04.1) ... 503s Setting up libasound2-data (1.2.6.1-1ubuntu1) ... 503s Setting up libopencore-amrwb0:amd64 (0.1.5-1) ... 503s Setting up libradcli4 (1.2.11-1build1) ... 503s Setting up libopus0:amd64 (1.3.1-0.1build2) ... 503s Setting up asterisk-config (1:18.10.0~dfsg+~cs6.10.40431411-2) ... 504s Setting up libvorbis0a:amd64 (1.3.7-1build2) ... 504s Setting up libevent-2.1-7:amd64 (2.1.12-stable-1build3) ... 504s Setting up libsensors5:amd64 (1:3.6.0-7ubuntu1) ... 504s Setting up libjpeg-turbo8:amd64 (2.1.2-0ubuntu1) ... 504s Setting up libltdl7:amd64 (2.4.6-15build2) ... 504s Setting up asterisk-core-sounds-en (1.6.1-1) ... 504s update-alternatives: using /usr/share/asterisk/sounds/en_US_f_Allison to provide /usr/share/asterisk/sounds/en (asterisk-prompt-en) in auto mode 504s 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 504s Setting up libwebp7:amd64 (1.2.2-2ubuntu0.22.04.2) ... 504s Setting up libiksemel3:amd64 (1.4-4) ... 504s Setting up libodbc2:amd64 (2.3.9-5ubuntu0.1) ... 504s Setting up liburiparser1:amd64 (0.9.6+dfsg-1) ... 504s Setting up liblua5.2-0:amd64 (5.2.4-2) ... 504s Setting up libneon27:amd64 (0.32.2-1) ... 504s Setting up libspeexdsp1:amd64 (1.2~rc1.2-1.1ubuntu3) ... 504s Setting up libasound2:amd64 (1.2.6.1-1ubuntu1) ... 504s Setting up libxslt1.1:amd64 (1.1.34-4ubuntu0.22.04.1) ... 504s Setting up libopencore-amrnb0:amd64 (0.1.5-1) ... 504s Setting up libical3:amd64 (3.0.14-1build1) ... 504s Setting up libc-client2007e (8:2007f~dfsg-7build1) ... 504s Setting up libresample1 (0.1.3-5) ... 504s Setting up freetds-common (1.3.6-1) ... 504s Setting up libsamplerate0:amd64 (0.2.2-1build1) ... 504s Setting up libopusfile0 (0.9+20170913-1.1build1) ... 504s Setting up libvorbisenc2:amd64 (1.3.7-1build2) ... 504s Setting up libjpeg8:amd64 (8c-2ubuntu10) ... 504s Setting up libsybdb5:amd64 (1.3.6-1) ... 504s Setting up libvorbisfile3:amd64 (1.3.7-1build2) ... 504s Setting up libsnmp40:amd64 (5.9.1+dfsg-1ubuntu2.8) ... 504s Setting up libunbound8:amd64 (1.13.1-1ubuntu5.8) ... 504s Setting up libjack-jackd2-0:amd64 (1.9.20~dfsg-1) ... 504s Setting up libtiff5:amd64 (4.3.0-6ubuntu0.10) ... 504s Setting up libportaudio2:amd64 (19.6.0-1.1) ... 504s Setting up libspandsp2:amd64 (0.0.6+dfsg-2) ... 504s Setting up asterisk-modules (1:18.10.0~dfsg+~cs6.10.40431411-2) ... 504s Setting up asterisk (1:18.10.0~dfsg+~cs6.10.40431411-2) ... 504s Adding system user for Asterisk 504s ERROR: ld.so: object 'libeatmydata.so' from LD_PRELOAD cannot be preloaded (cannot open shared object file): ignored. 504s Adding user `asterisk' to group `dialout' ... 504s Adding user asterisk to group dialout 504s Done. 504s Adding user `asterisk' to group `audio' ... 504s Adding user asterisk to group audio 504s Done. 505s Created symlink /etc/systemd/system/multi-user.target.wants/asterisk.service → /lib/systemd/system/asterisk.service. 506s Processing triggers for man-db (2.10.2-1) ... 506s Processing triggers for libc-bin (2.35-0ubuntu3.9) ... 513s cat: write error: No space left