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