0s autopkgtest [20:34:05]: starting date and time: 2025-05-04 20:34:05+0000 0s autopkgtest [20:34:05]: git checkout: 9986aa8c Merge branch 'skia/fix_network_interface' into 'ubuntu/production' 0s autopkgtest [20:34:05]: host juju-7f2275-prod-proposed-migration-environment-15; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.f0n6cq1o/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:sqlite3 --apt-upgrade asterisk --timeout-short=300 --timeout-copy=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=sqlite3/3.46.1-4 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-15@bos03-arm64-13.secgroup --name adt-questing-arm64-asterisk-20250504-203405-juju-7f2275-prod-proposed-migration-environment-15-3acde24b-113b-4fdd-b834-2687420d6e41 --image adt/ubuntu-questing-arm64-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-15 --net-id=net_prod-proposed-migration -e TERM=linux --mirror=http://ftpmaster.internal/ubuntu/ 93s autopkgtest [20:35:38]: testbed dpkg architecture: arm64 94s autopkgtest [20:35:39]: testbed apt version: 3.0.0 94s autopkgtest [20:35:39]: @@@@@@@@@@@@@@@@@@@@ test bed setup 94s autopkgtest [20:35:39]: testbed release detected to be: None 95s autopkgtest [20:35:40]: updating testbed package index (apt update) 95s Get:1 http://ftpmaster.internal/ubuntu questing-proposed InRelease [110 kB] 95s Hit:2 http://ftpmaster.internal/ubuntu questing InRelease 96s Hit:3 http://ftpmaster.internal/ubuntu questing-updates InRelease 96s Hit:4 http://ftpmaster.internal/ubuntu questing-security InRelease 96s Get:5 http://ftpmaster.internal/ubuntu questing-proposed/universe Sources [1095 kB] 96s Get:6 http://ftpmaster.internal/ubuntu questing-proposed/multiverse Sources [33.9 kB] 96s Get:7 http://ftpmaster.internal/ubuntu questing-proposed/main Sources [111 kB] 96s Get:8 http://ftpmaster.internal/ubuntu questing-proposed/main arm64 Packages [143 kB] 96s Get:9 http://ftpmaster.internal/ubuntu questing-proposed/universe arm64 Packages [1104 kB] 96s Get:10 http://ftpmaster.internal/ubuntu questing-proposed/multiverse arm64 Packages [30.1 kB] 96s Fetched 2627 kB in 1s (2495 kB/s) 97s Reading package lists... 98s autopkgtest [20:35:43]: upgrading testbed (apt dist-upgrade and autopurge) 98s Reading package lists... 98s Building dependency tree... 98s Reading state information... 99s Calculating upgrade...Starting pkgProblemResolver with broken count: 0 99s Starting 2 pkgProblemResolver with broken count: 0 99s Done 99s Entering ResolveByKeep 100s 100s Calculating upgrade... 100s The following packages will be upgraded: 100s base-passwd ethtool libbpf1 libevdev2 libmm-glib0 libnghttp2-14 100s libpython3.12-minimal libpython3.12-stdlib libpython3.12t64 libsqlite3-0 100s libunistring5 libusb-1.0-0 man-db patch usbutils 100s 15 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 100s Need to get 8938 kB of archives. 100s After this operation, 133 kB disk space will be freed. 100s Get:1 http://ftpmaster.internal/ubuntu questing/main arm64 base-passwd arm64 3.6.7 [54.2 kB] 100s Get:2 http://ftpmaster.internal/ubuntu questing/main arm64 libbpf1 arm64 1:1.5.0-3 [182 kB] 100s Get:3 http://ftpmaster.internal/ubuntu questing-proposed/main arm64 libsqlite3-0 arm64 3.46.1-4 [707 kB] 101s Get:4 http://ftpmaster.internal/ubuntu questing/main arm64 libunistring5 arm64 1.3-2 [601 kB] 101s Get:5 http://ftpmaster.internal/ubuntu questing/main arm64 ethtool arm64 1:6.14-2 [242 kB] 101s Get:6 http://ftpmaster.internal/ubuntu questing/main arm64 libevdev2 arm64 1.13.4+dfsg-1 [35.8 kB] 101s Get:7 http://ftpmaster.internal/ubuntu questing/main arm64 libnghttp2-14 arm64 1.64.0-1.1 [74.6 kB] 101s Get:8 http://ftpmaster.internal/ubuntu questing/main arm64 libusb-1.0-0 arm64 2:1.0.28-1 [54.8 kB] 101s Get:9 http://ftpmaster.internal/ubuntu questing/main arm64 man-db arm64 2.13.1-1 [1369 kB] 101s Get:10 http://ftpmaster.internal/ubuntu questing/main arm64 usbutils arm64 1:018-2 [81.5 kB] 101s Get:11 http://ftpmaster.internal/ubuntu questing/main arm64 libmm-glib0 arm64 1.24.0-1 [262 kB] 101s Get:12 http://ftpmaster.internal/ubuntu questing-proposed/universe arm64 libpython3.12t64 arm64 3.12.10-1 [2314 kB] 101s Get:13 http://ftpmaster.internal/ubuntu questing-proposed/universe arm64 libpython3.12-stdlib arm64 3.12.10-1 [2029 kB] 101s Get:14 http://ftpmaster.internal/ubuntu questing-proposed/universe arm64 libpython3.12-minimal arm64 3.12.10-1 [836 kB] 101s Get:15 http://ftpmaster.internal/ubuntu questing/main arm64 patch arm64 2.8-1 [94.0 kB] 102s Preconfiguring packages ... 102s Fetched 8938 kB in 1s (8088 kB/s) 102s (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 ... 117820 files and directories currently installed.) 102s Preparing to unpack .../base-passwd_3.6.7_arm64.deb ... 102s Unpacking base-passwd (3.6.7) over (3.6.6) ... 102s Setting up base-passwd (3.6.7) ... 102s (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 ... 117820 files and directories currently installed.) 102s Preparing to unpack .../00-libbpf1_1%3a1.5.0-3_arm64.deb ... 102s Unpacking libbpf1:arm64 (1:1.5.0-3) over (1:1.5.0-2) ... 102s Preparing to unpack .../01-libsqlite3-0_3.46.1-4_arm64.deb ... 102s Unpacking libsqlite3-0:arm64 (3.46.1-4) over (3.46.1-3) ... 102s Preparing to unpack .../02-libunistring5_1.3-2_arm64.deb ... 102s Unpacking libunistring5:arm64 (1.3-2) over (1.3-1) ... 102s Preparing to unpack .../03-ethtool_1%3a6.14-2_arm64.deb ... 102s Unpacking ethtool (1:6.14-2) over (1:6.11-1) ... 103s Preparing to unpack .../04-libevdev2_1.13.4+dfsg-1_arm64.deb ... 103s Unpacking libevdev2:arm64 (1.13.4+dfsg-1) over (1.13.3+dfsg-1) ... 103s Preparing to unpack .../05-libnghttp2-14_1.64.0-1.1_arm64.deb ... 103s Unpacking libnghttp2-14:arm64 (1.64.0-1.1) over (1.64.0-1ubuntu1) ... 103s Preparing to unpack .../06-libusb-1.0-0_2%3a1.0.28-1_arm64.deb ... 103s Unpacking libusb-1.0-0:arm64 (2:1.0.28-1) over (2:1.0.27-2) ... 103s Preparing to unpack .../07-man-db_2.13.1-1_arm64.deb ... 103s Unpacking man-db (2.13.1-1) over (2.13.0-1) ... 103s Preparing to unpack .../08-usbutils_1%3a018-2_arm64.deb ... 103s Unpacking usbutils (1:018-2) over (1:018-1) ... 103s Preparing to unpack .../09-libmm-glib0_1.24.0-1_arm64.deb ... 103s Unpacking libmm-glib0:arm64 (1.24.0-1) over (1.23.4-0ubuntu3) ... 103s Preparing to unpack .../10-libpython3.12t64_3.12.10-1_arm64.deb ... 103s Unpacking libpython3.12t64:arm64 (3.12.10-1) over (3.12.8-3) ... 103s Preparing to unpack .../11-libpython3.12-stdlib_3.12.10-1_arm64.deb ... 103s Unpacking libpython3.12-stdlib:arm64 (3.12.10-1) over (3.12.8-3) ... 103s Preparing to unpack .../12-libpython3.12-minimal_3.12.10-1_arm64.deb ... 103s Unpacking libpython3.12-minimal:arm64 (3.12.10-1) over (3.12.8-3) ... 103s Preparing to unpack .../13-patch_2.8-1_arm64.deb ... 103s Unpacking patch (2.8-1) over (2.7.6-7build3) ... 103s Setting up libsqlite3-0:arm64 (3.46.1-4) ... 103s Setting up libpython3.12-minimal:arm64 (3.12.10-1) ... 103s Setting up libnghttp2-14:arm64 (1.64.0-1.1) ... 103s Setting up man-db (2.13.1-1) ... 104s Updating database of manual pages ... 106s man-db.service is a disabled or a static unit not running, not starting it. 106s Setting up libunistring5:arm64 (1.3-2) ... 106s Setting up patch (2.8-1) ... 106s Setting up libmm-glib0:arm64 (1.24.0-1) ... 106s Setting up libusb-1.0-0:arm64 (2:1.0.28-1) ... 106s Setting up libevdev2:arm64 (1.13.4+dfsg-1) ... 106s Setting up libbpf1:arm64 (1:1.5.0-3) ... 106s Setting up ethtool (1:6.14-2) ... 106s Setting up libpython3.12-stdlib:arm64 (3.12.10-1) ... 106s Setting up usbutils (1:018-2) ... 106s Setting up libpython3.12t64:arm64 (3.12.10-1) ... 106s Processing triggers for libc-bin (2.41-6ubuntu1) ... 107s Reading package lists... 107s Building dependency tree... 107s Reading state information... 107s Starting pkgProblemResolver with broken count: 0 107s Starting 2 pkgProblemResolver with broken count: 0 107s Done 108s Solving dependencies... 108s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 108s autopkgtest [20:35:53]: rebooting testbed after setup commands that affected boot 132s autopkgtest [20:36:17]: testbed running kernel: Linux 6.14.0-15-generic #15-Ubuntu SMP PREEMPT_DYNAMIC Sun Apr 6 14:37:51 UTC 2025 134s autopkgtest [20:36:19]: @@@@@@@@@@@@@@@@@@@@ apt-source asterisk 142s Get:1 http://ftpmaster.internal/ubuntu questing/universe asterisk 1:22.2.0~dfsg+~cs6.15.60671435-2 (dsc) [5416 B] 142s Get:2 http://ftpmaster.internal/ubuntu questing/universe asterisk 1:22.2.0~dfsg+~cs6.15.60671435-2 (tar) [11.3 kB] 142s Get:3 http://ftpmaster.internal/ubuntu questing/universe asterisk 1:22.2.0~dfsg+~cs6.15.60671435-2 (tar) [22.0 kB] 142s Get:4 http://ftpmaster.internal/ubuntu questing/universe asterisk 1:22.2.0~dfsg+~cs6.15.60671435-2 (tar) [22.6 kB] 142s Get:5 http://ftpmaster.internal/ubuntu questing/universe asterisk 1:22.2.0~dfsg+~cs6.15.60671435-2 (tar) [6402 kB] 142s Get:6 http://ftpmaster.internal/ubuntu questing/universe asterisk 1:22.2.0~dfsg+~cs6.15.60671435-2 (tar) [5977 kB] 142s Get:7 http://ftpmaster.internal/ubuntu questing/universe asterisk 1:22.2.0~dfsg+~cs6.15.60671435-2 (diff) [123 kB] 143s gpgv: Signature made Sat Feb 22 08:00:50 2025 UTC 143s gpgv: using RSA key 9FE3E9C36691A69FF53CC6842C7C3146C1A00121 143s gpgv: Can't check signature: No public key 143s dpkg-source: warning: cannot verify inline signature for ./asterisk_22.2.0~dfsg+~cs6.15.60671435-2.dsc: no acceptable signature found 144s autopkgtest [20:36:29]: testing package asterisk version 1:22.2.0~dfsg+~cs6.15.60671435-2 145s autopkgtest [20:36:30]: build not needed 149s autopkgtest [20:36:34]: test asttestmods: preparing testbed 150s Reading package lists... 150s Building dependency tree... 150s Reading state information... 150s Starting pkgProblemResolver with broken count: 0 150s Starting 2 pkgProblemResolver with broken count: 0 150s Done 151s The following NEW packages will be installed: 151s asterisk asterisk-config asterisk-core-sounds-en asterisk-core-sounds-en-gsm 151s asterisk-modules asterisk-tests freetds-common libasound2-data libasound2t64 151s libb64-0d libc-client2007e libcodec2-1.2 libdeflate0 libevent-2.1-7t64 151s libgmime-3.0-0t64 libgsm1 libical3t64 libiksemel3 libjack-jackd2-0 libjbig0 151s libjpeg-turbo8 libjpeg8 libjwt2 liblerc4 libltdl7 liblua5.1-0 libneon27t64 151s libodbc2 libogg0 libopencore-amrnb0 libopencore-amrwb0 libopus0 libopusenc0 151s libopusfile0 libportaudio2 libpq5 libradcli4 libresample1 libsamplerate0 151s libsharpyuv0 libsnmp-base libsnmp40t64 libspandsp2t64 libspeex1 libspeexdsp1 151s libsrtp2-1 libsybdb5 libtiff6 libunbound8 liburiparser1 libvo-amrwbenc0 151s libvorbis0a libvorbisenc2 libvorbisfile3 libwebp7 libxml2-utils libxslt1.1 151s mlock 151s 0 upgraded, 58 newly installed, 0 to remove and 0 not upgraded. 151s Need to get 28.8 MB of archives. 151s After this operation, 94.0 MB of additional disk space will be used. 151s Get:1 http://ftpmaster.internal/ubuntu questing/universe arm64 asterisk-config all 1:22.2.0~dfsg+~cs6.15.60671435-2 [226 kB] 152s Get:2 http://ftpmaster.internal/ubuntu questing/universe arm64 asterisk-core-sounds-en-gsm all 1.6.1-1 [2417 kB] 152s Get:3 http://ftpmaster.internal/ubuntu questing/universe arm64 asterisk-core-sounds-en all 1.6.1-1 [20.6 kB] 152s Get:4 http://ftpmaster.internal/ubuntu questing/universe arm64 mlock arm64 8:2007f~dfsg-7.1 [8464 B] 152s Get:5 http://ftpmaster.internal/ubuntu questing/universe arm64 libc-client2007e arm64 8:2007f~dfsg-7.1 [626 kB] 152s Get:6 http://ftpmaster.internal/ubuntu questing/universe arm64 libcodec2-1.2 arm64 1.2.0-3 [8999 kB] 152s Get:7 http://ftpmaster.internal/ubuntu questing/universe arm64 libgmime-3.0-0t64 arm64 3.2.15+dfsg-1 [173 kB] 152s Get:8 http://ftpmaster.internal/ubuntu questing/universe arm64 libgsm1 arm64 1.0.22-1build1 [27.0 kB] 152s Get:9 http://ftpmaster.internal/ubuntu questing/main arm64 libical3t64 arm64 3.0.20-1 [305 kB] 152s Get:10 http://ftpmaster.internal/ubuntu questing/universe arm64 libiksemel3 arm64 1.4-4build2 [27.6 kB] 152s Get:11 http://ftpmaster.internal/ubuntu questing/main arm64 libopus0 arm64 1.5.2-2 [2891 kB] 152s Get:12 http://ftpmaster.internal/ubuntu questing/main arm64 libsamplerate0 arm64 0.2.2-4build1 [1343 kB] 152s Get:13 http://ftpmaster.internal/ubuntu questing/main arm64 libjack-jackd2-0 arm64 1.9.22~dfsg-4 [286 kB] 152s Get:14 http://ftpmaster.internal/ubuntu questing/universe arm64 libb64-0d arm64 1.2-5build1 [9590 B] 152s Get:15 http://ftpmaster.internal/ubuntu questing/universe arm64 libjwt2 arm64 1.17.2-1 [17.8 kB] 152s Get:16 http://ftpmaster.internal/ubuntu questing/universe arm64 liblua5.1-0 arm64 5.1.5-11 [118 kB] 152s Get:17 http://ftpmaster.internal/ubuntu questing/universe arm64 libneon27t64 arm64 0.34.2-1 [103 kB] 152s Get:18 http://ftpmaster.internal/ubuntu questing/main arm64 libltdl7 arm64 2.5.4-4 [43.0 kB] 152s Get:19 http://ftpmaster.internal/ubuntu questing/main arm64 libodbc2 arm64 2.3.12-2ubuntu1 [147 kB] 152s Get:20 http://ftpmaster.internal/ubuntu questing/main arm64 libogg0 arm64 1.3.5-3build1 [22.6 kB] 152s Get:21 http://ftpmaster.internal/ubuntu questing/universe arm64 libopencore-amrnb0 arm64 0.1.6-1build1 [97.0 kB] 152s Get:22 http://ftpmaster.internal/ubuntu questing/universe arm64 libopencore-amrwb0 arm64 0.1.6-1build1 [50.3 kB] 152s Get:23 http://ftpmaster.internal/ubuntu questing/universe arm64 libopusenc0 arm64 0.2.1-2build1 [25.6 kB] 152s Get:24 http://ftpmaster.internal/ubuntu questing/universe arm64 libopusfile0 arm64 0.12-4build3 [44.7 kB] 152s Get:25 http://ftpmaster.internal/ubuntu questing/main arm64 libasound2-data all 1.2.13-1build1 [21.1 kB] 152s Get:26 http://ftpmaster.internal/ubuntu questing/main arm64 libasound2t64 arm64 1.2.13-1build1 [390 kB] 152s Get:27 http://ftpmaster.internal/ubuntu questing/universe arm64 libportaudio2 arm64 19.6.0-1.2build3 [65.4 kB] 152s Get:28 http://ftpmaster.internal/ubuntu questing/main arm64 libpq5 arm64 17.4-1 [142 kB] 152s Get:29 http://ftpmaster.internal/ubuntu questing/universe arm64 libradcli4 arm64 1.2.11-1build3 [40.2 kB] 152s Get:30 http://ftpmaster.internal/ubuntu questing/universe arm64 libresample1 arm64 0.1.3-8 [8668 B] 153s Get:31 http://ftpmaster.internal/ubuntu questing/main arm64 libsnmp-base all 5.9.4+dfsg-1.1ubuntu7 [206 kB] 153s Get:32 http://ftpmaster.internal/ubuntu questing/main arm64 libsnmp40t64 arm64 5.9.4+dfsg-1.1ubuntu7 [1053 kB] 153s Get:33 http://ftpmaster.internal/ubuntu questing/main arm64 libdeflate0 arm64 1.23-2 [46.4 kB] 153s Get:34 http://ftpmaster.internal/ubuntu questing/main arm64 libjbig0 arm64 2.1-6.1ubuntu2 [29.3 kB] 153s Get:35 http://ftpmaster.internal/ubuntu questing/main arm64 libjpeg-turbo8 arm64 2.1.5-3ubuntu2 [165 kB] 153s Get:36 http://ftpmaster.internal/ubuntu questing/main arm64 libjpeg8 arm64 8c-2ubuntu11 [2148 B] 153s Get:37 http://ftpmaster.internal/ubuntu questing/main arm64 liblerc4 arm64 4.0.0+ds-5ubuntu1 [167 kB] 153s Get:38 http://ftpmaster.internal/ubuntu questing/main arm64 libsharpyuv0 arm64 1.5.0-0.1 [16.9 kB] 153s Get:39 http://ftpmaster.internal/ubuntu questing/main arm64 libwebp7 arm64 1.5.0-0.1 [194 kB] 153s Get:40 http://ftpmaster.internal/ubuntu questing/main arm64 libtiff6 arm64 4.7.0-3ubuntu1 [197 kB] 153s Get:41 http://ftpmaster.internal/ubuntu questing/universe arm64 libspandsp2t64 arm64 0.0.6+dfsg-2.2 [316 kB] 153s Get:42 http://ftpmaster.internal/ubuntu questing/main arm64 libspeex1 arm64 1.2.1-3 [56.9 kB] 153s Get:43 http://ftpmaster.internal/ubuntu questing/main arm64 libspeexdsp1 arm64 1.2.1-3 [41.5 kB] 153s Get:44 http://ftpmaster.internal/ubuntu questing/universe arm64 libsrtp2-1 arm64 2.7.0-3 [44.3 kB] 153s Get:45 http://ftpmaster.internal/ubuntu questing/main arm64 freetds-common all 1.3.17+ds-2build3 [26.9 kB] 153s Get:46 http://ftpmaster.internal/ubuntu questing/main arm64 libsybdb5 arm64 1.3.17+ds-2build3 [186 kB] 153s Get:47 http://ftpmaster.internal/ubuntu questing/main arm64 libevent-2.1-7t64 arm64 2.1.12-stable-10 [140 kB] 153s Get:48 http://ftpmaster.internal/ubuntu questing/main arm64 libunbound8 arm64 1.22.0-1ubuntu1 [437 kB] 153s Get:49 http://ftpmaster.internal/ubuntu questing/universe arm64 libvo-amrwbenc0 arm64 0.1.3-2build1 [73.2 kB] 153s Get:50 http://ftpmaster.internal/ubuntu questing/main arm64 libvorbis0a arm64 1.3.7-2 [95.0 kB] 153s Get:51 http://ftpmaster.internal/ubuntu questing/main arm64 libvorbisenc2 arm64 1.3.7-2 [80.0 kB] 153s Get:52 http://ftpmaster.internal/ubuntu questing/main arm64 libvorbisfile3 arm64 1.3.7-2 [17.1 kB] 153s Get:53 http://ftpmaster.internal/ubuntu questing/universe arm64 asterisk-modules arm64 1:22.2.0~dfsg+~cs6.15.60671435-2 [3008 kB] 153s Get:54 http://ftpmaster.internal/ubuntu questing/universe arm64 liburiparser1 arm64 0.9.8+dfsg-2 [36.3 kB] 153s Get:55 http://ftpmaster.internal/ubuntu questing/main arm64 libxslt1.1 arm64 1.1.39-0exp1ubuntu4 [168 kB] 153s Get:56 http://ftpmaster.internal/ubuntu questing/universe arm64 asterisk arm64 1:22.2.0~dfsg+~cs6.15.60671435-2 [2714 kB] 153s Get:57 http://ftpmaster.internal/ubuntu questing/universe arm64 asterisk-tests arm64 1:22.2.0~dfsg+~cs6.15.60671435-2 [548 kB] 153s Get:58 http://ftpmaster.internal/ubuntu questing/main arm64 libxml2-utils arm64 2.12.7+dfsg+really2.9.14-0.4 [39.4 kB] 153s Fetched 28.8 MB in 2s (16.3 MB/s) 153s Selecting previously unselected package asterisk-config. 154s (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 ... 117830 files and directories currently installed.) 154s Preparing to unpack .../00-asterisk-config_1%3a22.2.0~dfsg+~cs6.15.60671435-2_all.deb ... 154s Unpacking asterisk-config (1:22.2.0~dfsg+~cs6.15.60671435-2) ... 154s Selecting previously unselected package asterisk-core-sounds-en-gsm. 154s Preparing to unpack .../01-asterisk-core-sounds-en-gsm_1.6.1-1_all.deb ... 154s Unpacking asterisk-core-sounds-en-gsm (1.6.1-1) ... 154s Selecting previously unselected package asterisk-core-sounds-en. 154s Preparing to unpack .../02-asterisk-core-sounds-en_1.6.1-1_all.deb ... 154s Unpacking asterisk-core-sounds-en (1.6.1-1) ... 154s Selecting previously unselected package mlock. 154s Preparing to unpack .../03-mlock_8%3a2007f~dfsg-7.1_arm64.deb ... 154s Unpacking mlock (8:2007f~dfsg-7.1) ... 154s Selecting previously unselected package libc-client2007e. 154s Preparing to unpack .../04-libc-client2007e_8%3a2007f~dfsg-7.1_arm64.deb ... 154s Unpacking libc-client2007e (8:2007f~dfsg-7.1) ... 154s Selecting previously unselected package libcodec2-1.2:arm64. 154s Preparing to unpack .../05-libcodec2-1.2_1.2.0-3_arm64.deb ... 154s Unpacking libcodec2-1.2:arm64 (1.2.0-3) ... 154s Selecting previously unselected package libgmime-3.0-0t64:arm64. 154s Preparing to unpack .../06-libgmime-3.0-0t64_3.2.15+dfsg-1_arm64.deb ... 154s Unpacking libgmime-3.0-0t64:arm64 (3.2.15+dfsg-1) ... 154s Selecting previously unselected package libgsm1:arm64. 154s Preparing to unpack .../07-libgsm1_1.0.22-1build1_arm64.deb ... 154s Unpacking libgsm1:arm64 (1.0.22-1build1) ... 154s Selecting previously unselected package libical3t64:arm64. 154s Preparing to unpack .../08-libical3t64_3.0.20-1_arm64.deb ... 154s Unpacking libical3t64:arm64 (3.0.20-1) ... 154s Selecting previously unselected package libiksemel3:arm64. 154s Preparing to unpack .../09-libiksemel3_1.4-4build2_arm64.deb ... 154s Unpacking libiksemel3:arm64 (1.4-4build2) ... 154s Selecting previously unselected package libopus0:arm64. 154s Preparing to unpack .../10-libopus0_1.5.2-2_arm64.deb ... 154s Unpacking libopus0:arm64 (1.5.2-2) ... 155s Selecting previously unselected package libsamplerate0:arm64. 155s Preparing to unpack .../11-libsamplerate0_0.2.2-4build1_arm64.deb ... 155s Unpacking libsamplerate0:arm64 (0.2.2-4build1) ... 155s Selecting previously unselected package libjack-jackd2-0:arm64. 155s Preparing to unpack .../12-libjack-jackd2-0_1.9.22~dfsg-4_arm64.deb ... 155s Unpacking libjack-jackd2-0:arm64 (1.9.22~dfsg-4) ... 155s Selecting previously unselected package libb64-0d:arm64. 155s Preparing to unpack .../13-libb64-0d_1.2-5build1_arm64.deb ... 155s Unpacking libb64-0d:arm64 (1.2-5build1) ... 155s Selecting previously unselected package libjwt2:arm64. 155s Preparing to unpack .../14-libjwt2_1.17.2-1_arm64.deb ... 155s Unpacking libjwt2:arm64 (1.17.2-1) ... 155s Selecting previously unselected package liblua5.1-0:arm64. 155s Preparing to unpack .../15-liblua5.1-0_5.1.5-11_arm64.deb ... 155s Unpacking liblua5.1-0:arm64 (5.1.5-11) ... 155s Selecting previously unselected package libneon27t64:arm64. 155s Preparing to unpack .../16-libneon27t64_0.34.2-1_arm64.deb ... 155s Unpacking libneon27t64:arm64 (0.34.2-1) ... 155s Selecting previously unselected package libltdl7:arm64. 155s Preparing to unpack .../17-libltdl7_2.5.4-4_arm64.deb ... 155s Unpacking libltdl7:arm64 (2.5.4-4) ... 155s Selecting previously unselected package libodbc2:arm64. 155s Preparing to unpack .../18-libodbc2_2.3.12-2ubuntu1_arm64.deb ... 155s Unpacking libodbc2:arm64 (2.3.12-2ubuntu1) ... 155s Selecting previously unselected package libogg0:arm64. 155s Preparing to unpack .../19-libogg0_1.3.5-3build1_arm64.deb ... 155s Unpacking libogg0:arm64 (1.3.5-3build1) ... 155s Selecting previously unselected package libopencore-amrnb0:arm64. 155s Preparing to unpack .../20-libopencore-amrnb0_0.1.6-1build1_arm64.deb ... 155s Unpacking libopencore-amrnb0:arm64 (0.1.6-1build1) ... 155s Selecting previously unselected package libopencore-amrwb0:arm64. 155s Preparing to unpack .../21-libopencore-amrwb0_0.1.6-1build1_arm64.deb ... 155s Unpacking libopencore-amrwb0:arm64 (0.1.6-1build1) ... 155s Selecting previously unselected package libopusenc0:arm64. 155s Preparing to unpack .../22-libopusenc0_0.2.1-2build1_arm64.deb ... 155s Unpacking libopusenc0:arm64 (0.2.1-2build1) ... 155s Selecting previously unselected package libopusfile0:arm64. 155s Preparing to unpack .../23-libopusfile0_0.12-4build3_arm64.deb ... 155s Unpacking libopusfile0:arm64 (0.12-4build3) ... 155s Selecting previously unselected package libasound2-data. 155s Preparing to unpack .../24-libasound2-data_1.2.13-1build1_all.deb ... 155s Unpacking libasound2-data (1.2.13-1build1) ... 155s Selecting previously unselected package libasound2t64:arm64. 155s Preparing to unpack .../25-libasound2t64_1.2.13-1build1_arm64.deb ... 155s Unpacking libasound2t64:arm64 (1.2.13-1build1) ... 155s Selecting previously unselected package libportaudio2:arm64. 155s Preparing to unpack .../26-libportaudio2_19.6.0-1.2build3_arm64.deb ... 155s Unpacking libportaudio2:arm64 (19.6.0-1.2build3) ... 155s Selecting previously unselected package libpq5:arm64. 155s Preparing to unpack .../27-libpq5_17.4-1_arm64.deb ... 155s Unpacking libpq5:arm64 (17.4-1) ... 156s Selecting previously unselected package libradcli4. 156s Preparing to unpack .../28-libradcli4_1.2.11-1build3_arm64.deb ... 156s Unpacking libradcli4 (1.2.11-1build3) ... 156s Selecting previously unselected package libresample1. 156s Preparing to unpack .../29-libresample1_0.1.3-8_arm64.deb ... 156s Unpacking libresample1 (0.1.3-8) ... 156s Selecting previously unselected package libsnmp-base. 156s Preparing to unpack .../30-libsnmp-base_5.9.4+dfsg-1.1ubuntu7_all.deb ... 156s Unpacking libsnmp-base (5.9.4+dfsg-1.1ubuntu7) ... 156s Selecting previously unselected package libsnmp40t64:arm64. 156s Preparing to unpack .../31-libsnmp40t64_5.9.4+dfsg-1.1ubuntu7_arm64.deb ... 156s Unpacking libsnmp40t64:arm64 (5.9.4+dfsg-1.1ubuntu7) ... 156s Selecting previously unselected package libdeflate0:arm64. 156s Preparing to unpack .../32-libdeflate0_1.23-2_arm64.deb ... 156s Unpacking libdeflate0:arm64 (1.23-2) ... 156s Selecting previously unselected package libjbig0:arm64. 156s Preparing to unpack .../33-libjbig0_2.1-6.1ubuntu2_arm64.deb ... 156s Unpacking libjbig0:arm64 (2.1-6.1ubuntu2) ... 156s Selecting previously unselected package libjpeg-turbo8:arm64. 156s Preparing to unpack .../34-libjpeg-turbo8_2.1.5-3ubuntu2_arm64.deb ... 156s Unpacking libjpeg-turbo8:arm64 (2.1.5-3ubuntu2) ... 156s Selecting previously unselected package libjpeg8:arm64. 156s Preparing to unpack .../35-libjpeg8_8c-2ubuntu11_arm64.deb ... 156s Unpacking libjpeg8:arm64 (8c-2ubuntu11) ... 156s Selecting previously unselected package liblerc4:arm64. 156s Preparing to unpack .../36-liblerc4_4.0.0+ds-5ubuntu1_arm64.deb ... 156s Unpacking liblerc4:arm64 (4.0.0+ds-5ubuntu1) ... 156s Selecting previously unselected package libsharpyuv0:arm64. 156s Preparing to unpack .../37-libsharpyuv0_1.5.0-0.1_arm64.deb ... 156s Unpacking libsharpyuv0:arm64 (1.5.0-0.1) ... 156s Selecting previously unselected package libwebp7:arm64. 156s Preparing to unpack .../38-libwebp7_1.5.0-0.1_arm64.deb ... 156s Unpacking libwebp7:arm64 (1.5.0-0.1) ... 156s Selecting previously unselected package libtiff6:arm64. 156s Preparing to unpack .../39-libtiff6_4.7.0-3ubuntu1_arm64.deb ... 156s Unpacking libtiff6:arm64 (4.7.0-3ubuntu1) ... 156s Selecting previously unselected package libspandsp2t64:arm64. 156s Preparing to unpack .../40-libspandsp2t64_0.0.6+dfsg-2.2_arm64.deb ... 156s Unpacking libspandsp2t64:arm64 (0.0.6+dfsg-2.2) ... 156s Selecting previously unselected package libspeex1:arm64. 156s Preparing to unpack .../41-libspeex1_1.2.1-3_arm64.deb ... 156s Unpacking libspeex1:arm64 (1.2.1-3) ... 156s Selecting previously unselected package libspeexdsp1:arm64. 156s Preparing to unpack .../42-libspeexdsp1_1.2.1-3_arm64.deb ... 156s Unpacking libspeexdsp1:arm64 (1.2.1-3) ... 156s Selecting previously unselected package libsrtp2-1:arm64. 156s Preparing to unpack .../43-libsrtp2-1_2.7.0-3_arm64.deb ... 156s Unpacking libsrtp2-1:arm64 (2.7.0-3) ... 156s Selecting previously unselected package freetds-common. 156s Preparing to unpack .../44-freetds-common_1.3.17+ds-2build3_all.deb ... 156s Unpacking freetds-common (1.3.17+ds-2build3) ... 157s Selecting previously unselected package libsybdb5:arm64. 157s Preparing to unpack .../45-libsybdb5_1.3.17+ds-2build3_arm64.deb ... 157s Unpacking libsybdb5:arm64 (1.3.17+ds-2build3) ... 157s Selecting previously unselected package libevent-2.1-7t64:arm64. 157s Preparing to unpack .../46-libevent-2.1-7t64_2.1.12-stable-10_arm64.deb ... 157s Unpacking libevent-2.1-7t64:arm64 (2.1.12-stable-10) ... 157s Selecting previously unselected package libunbound8:arm64. 157s Preparing to unpack .../47-libunbound8_1.22.0-1ubuntu1_arm64.deb ... 157s Unpacking libunbound8:arm64 (1.22.0-1ubuntu1) ... 157s Selecting previously unselected package libvo-amrwbenc0:arm64. 157s Preparing to unpack .../48-libvo-amrwbenc0_0.1.3-2build1_arm64.deb ... 157s Unpacking libvo-amrwbenc0:arm64 (0.1.3-2build1) ... 157s Selecting previously unselected package libvorbis0a:arm64. 157s Preparing to unpack .../49-libvorbis0a_1.3.7-2_arm64.deb ... 157s Unpacking libvorbis0a:arm64 (1.3.7-2) ... 157s Selecting previously unselected package libvorbisenc2:arm64. 157s Preparing to unpack .../50-libvorbisenc2_1.3.7-2_arm64.deb ... 157s Unpacking libvorbisenc2:arm64 (1.3.7-2) ... 157s Selecting previously unselected package libvorbisfile3:arm64. 157s Preparing to unpack .../51-libvorbisfile3_1.3.7-2_arm64.deb ... 157s Unpacking libvorbisfile3:arm64 (1.3.7-2) ... 157s Selecting previously unselected package asterisk-modules. 157s Preparing to unpack .../52-asterisk-modules_1%3a22.2.0~dfsg+~cs6.15.60671435-2_arm64.deb ... 157s Unpacking asterisk-modules (1:22.2.0~dfsg+~cs6.15.60671435-2) ... 157s Selecting previously unselected package liburiparser1:arm64. 157s Preparing to unpack .../53-liburiparser1_0.9.8+dfsg-2_arm64.deb ... 157s Unpacking liburiparser1:arm64 (0.9.8+dfsg-2) ... 157s Selecting previously unselected package libxslt1.1:arm64. 157s Preparing to unpack .../54-libxslt1.1_1.1.39-0exp1ubuntu4_arm64.deb ... 157s Unpacking libxslt1.1:arm64 (1.1.39-0exp1ubuntu4) ... 157s Selecting previously unselected package asterisk. 157s Preparing to unpack .../55-asterisk_1%3a22.2.0~dfsg+~cs6.15.60671435-2_arm64.deb ... 157s Unpacking asterisk (1:22.2.0~dfsg+~cs6.15.60671435-2) ... 157s Selecting previously unselected package asterisk-tests. 157s Preparing to unpack .../56-asterisk-tests_1%3a22.2.0~dfsg+~cs6.15.60671435-2_arm64.deb ... 157s Unpacking asterisk-tests (1:22.2.0~dfsg+~cs6.15.60671435-2) ... 157s Selecting previously unselected package libxml2-utils. 157s Preparing to unpack .../57-libxml2-utils_2.12.7+dfsg+really2.9.14-0.4_arm64.deb ... 157s Unpacking libxml2-utils (2.12.7+dfsg+really2.9.14-0.4) ... 157s Setting up libsharpyuv0:arm64 (1.5.0-0.1) ... 157s Setting up libvo-amrwbenc0:arm64 (0.1.3-2build1) ... 157s Setting up libneon27t64:arm64 (0.34.2-1) ... 157s Setting up libogg0:arm64 (1.3.5-3build1) ... 157s Setting up liblerc4:arm64 (4.0.0+ds-5ubuntu1) ... 157s Setting up libspeex1:arm64 (1.2.1-3) ... 157s Setting up libgsm1:arm64 (1.0.22-1build1) ... 157s Setting up asterisk-core-sounds-en-gsm (1.6.1-1) ... 157s Setting up libsnmp-base (5.9.4+dfsg-1.1ubuntu7) ... 157s Setting up libcodec2-1.2:arm64 (1.2.0-3) ... 157s Setting up mlock (8:2007f~dfsg-7.1) ... 157s Setting up libsrtp2-1:arm64 (2.7.0-3) ... 157s Setting up libpq5:arm64 (17.4-1) ... 157s Setting up libdeflate0:arm64 (1.23-2) ... 157s Setting up libevent-2.1-7t64:arm64 (2.1.12-stable-10) ... 157s Setting up libb64-0d:arm64 (1.2-5build1) ... 157s Setting up libjwt2:arm64 (1.17.2-1) ... 157s Setting up libjbig0:arm64 (2.1-6.1ubuntu2) ... 157s Setting up libasound2-data (1.2.13-1build1) ... 157s Setting up libopencore-amrwb0:arm64 (0.1.6-1build1) ... 157s Setting up libunbound8:arm64 (1.22.0-1ubuntu1) ... 157s Setting up libasound2t64:arm64 (1.2.13-1build1) ... 157s Setting up libradcli4 (1.2.11-1build3) ... 157s Setting up libopus0:arm64 (1.5.2-2) ... 157s Setting up asterisk-config (1:22.2.0~dfsg+~cs6.15.60671435-2) ... 158s Setting up libvorbis0a:arm64 (1.3.7-2) ... 158s Setting up libical3t64:arm64 (3.0.20-1) ... 158s Setting up libjpeg-turbo8:arm64 (2.1.5-3ubuntu2) ... 158s Setting up libltdl7:arm64 (2.5.4-4) ... 158s Setting up asterisk-core-sounds-en (1.6.1-1) ... 158s update-alternatives: using /usr/share/asterisk/sounds/en_US_f_Allison to provide /usr/share/asterisk/sounds/en (asterisk-prompt-en) in auto mode 158s 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 158s Setting up libwebp7:arm64 (1.5.0-0.1) ... 158s Setting up libiksemel3:arm64 (1.4-4build2) ... 158s Setting up libodbc2:arm64 (2.3.12-2ubuntu1) ... 158s Setting up liburiparser1:arm64 (0.9.8+dfsg-2) ... 158s Setting up libspeexdsp1:arm64 (1.2.1-3) ... 158s Setting up liblua5.1-0:arm64 (5.1.5-11) ... 158s Setting up libxslt1.1:arm64 (1.1.39-0exp1ubuntu4) ... 158s Setting up libopencore-amrnb0:arm64 (0.1.6-1build1) ... 158s Setting up libc-client2007e (8:2007f~dfsg-7.1) ... 158s Setting up libresample1 (0.1.3-8) ... 158s Setting up freetds-common (1.3.17+ds-2build3) ... 158s Setting up libxml2-utils (2.12.7+dfsg+really2.9.14-0.4) ... 158s Setting up libgmime-3.0-0t64:arm64 (3.2.15+dfsg-1) ... 158s Setting up libsamplerate0:arm64 (0.2.2-4build1) ... 158s Setting up libopusfile0:arm64 (0.12-4build3) ... 158s Setting up libvorbisenc2:arm64 (1.3.7-2) ... 158s Setting up libjpeg8:arm64 (8c-2ubuntu11) ... 158s Setting up libopusenc0:arm64 (0.2.1-2build1) ... 158s Setting up libsnmp40t64:arm64 (5.9.4+dfsg-1.1ubuntu7) ... 158s Setting up libsybdb5:arm64 (1.3.17+ds-2build3) ... 158s Setting up libvorbisfile3:arm64 (1.3.7-2) ... 158s Setting up libjack-jackd2-0:arm64 (1.9.22~dfsg-4) ... 158s Setting up libtiff6:arm64 (4.7.0-3ubuntu1) ... 158s Setting up libportaudio2:arm64 (19.6.0-1.2build3) ... 158s Setting up libspandsp2t64:arm64 (0.0.6+dfsg-2.2) ... 158s Setting up asterisk-modules (1:22.2.0~dfsg+~cs6.15.60671435-2) ... 158s Setting up asterisk (1:22.2.0~dfsg+~cs6.15.60671435-2) ... 158s Adding system user for Asterisk 158s info: Adding user `asterisk' to group `dialout' ... 158s info: Adding user `asterisk' to group `audio' ... 159s Created symlink '/etc/systemd/system/multi-user.target.wants/asterisk.service' → '/usr/lib/systemd/system/asterisk.service'. 160s Setting up asterisk-tests (1:22.2.0~dfsg+~cs6.15.60671435-2) ... 160s Processing triggers for libc-bin (2.41-6ubuntu1) ... 160s Processing triggers for man-db (2.13.1-1) ... 163s autopkgtest [20:36:48]: test asttestmods: [----------------------- 163s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 165s 'U' option is not compatible with remote console mode and has no effect. 165s 165s Asterisk has fully booted. 165s 'U' option is not compatible with remote console mode and has no effect. 165s 165s Running all available tests... 165s 165s START /apps/app_gosub/ - gosub application 165s END /apps/app_gosub/ - gosub application Time: <1ms Result: PASS 165s START /apps/app_voicemail/ - test_voicemail_vm_info 165s END /apps/app_voicemail/ - test_voicemail_vm_info Time: <1ms Result: PASS 165s START /apps/app_voicemail/ - test_voicemail_load_config 165s END /apps/app_voicemail/ - test_voicemail_load_config Time: <1ms Result: PASS 165s START /apps/app_voicemail/ - test_voicemail_notify_endl 165s END /apps/app_voicemail/ - test_voicemail_notify_endl Time: 5ms Result: PASS 165s START /apps/app_voicemail/ - vmuser 165s END /apps/app_voicemail/ - vmuser Time: <1ms Result: PASS 165s START /apps/app_voicemail/ - test_voicemail_msgcount 165s END /apps/app_voicemail/ - test_voicemail_msgcount Time: 59ms Result: PASS 165s START /apps/app_voicemail/ - vmsayname_exec 165s [app_voicemail.c:test_voicemail_vmsayname:15733]: Test playing of extension when greeting is not available... 169s [app_voicemail.c:test_voicemail_vmsayname:15754]: Test playing created mailbox greeting... 174s END /apps/app_voicemail/ - vmsayname_exec Time: 8885ms Result: PASS 174s START /ari/validators/ - validate_list 174s END /ari/validators/ - validate_list Time: <1ms Result: PASS 174s START /ari/validators/ - validate_date 174s END /ari/validators/ - validate_date Time: <1ms Result: PASS 174s START /ari/validators/ - validate_string 174s END /ari/validators/ - validate_string Time: <1ms Result: PASS 174s START /ari/validators/ - validate_long 174s END /ari/validators/ - validate_long Time: <1ms Result: PASS 174s START /ari/validators/ - validate_int 174s END /ari/validators/ - validate_int Time: <1ms Result: PASS 174s START /ari/validators/ - validate_boolean 174s END /ari/validators/ - validate_boolean Time: <1ms Result: PASS 174s START /ari/validators/ - validate_byte 174s END /ari/validators/ - validate_byte Time: <1ms Result: PASS 174s START /bridges/bridge_softmix/ - sfu_remove_destination_streams 174s END /bridges/bridge_softmix/ - sfu_remove_destination_streams Time: <1ms Result: PASS 174s START /bridges/bridge_softmix/ - sfu_append_source_streams 174s END /bridges/bridge_softmix/ - sfu_append_source_streams Time: <1ms Result: PASS 174s START /channels/features/ - test_features_channel_interval 177s END /channels/features/ - test_features_channel_interval Time: 3004ms Result: PASS 177s START /channels/features/ - test_features_channel_dtmf 179s END /channels/features/ - test_features_channel_dtmf Time: 2023ms Result: PASS 179s START /config/ - config_options_test 179s END /config/ - config_options_test Time: <1ms Result: PASS 179s START /config/ - ast_parse_arg 179s END /config/ - ast_parse_arg Time: <1ms Result: PASS 179s START /core/endpoints/ - setters 179s END /core/endpoints/ - setters Time: <1ms Result: PASS 179s START /core/endpoints/ - defaults 179s END /core/endpoints/ - defaults Time: <1ms Result: PASS 179s START /core/endpoints/ - create 179s END /core/endpoints/ - create Time: <1ms Result: PASS 179s START /funcs/func_curl/ - vulnerable_url 179s END /funcs/func_curl/ - vulnerable_url Time: <1ms Result: PASS 179s START /funcs/func_env/ - func_file 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=a'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,1)=a'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-8)=a'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-8)=a'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5,1)=b'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4,1)=b'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5,-3)=b'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4,-3)=b'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2)=c'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,2)=c'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-7)=c'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-7)=c'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,4,2)=d'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-5,2)=d'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,4,-3)=d'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-5,-3)=d'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5)=e'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5)='... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4)=e'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4)='... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=fg'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-8)=fg'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,1)=fg'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-8)=fg'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,)=h'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,,)=h'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,l)=h'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,ld)=h'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abc'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=abc'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=abc'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=abc'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=abc'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=abc'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=abc'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=abc'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=ab'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=ab'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=ab'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=ab'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=ab'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=ab'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=ab'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=ab'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcdefg'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcdefg'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcdefg'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcdefg'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcdefg'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcdefg'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcdefg'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcdefg'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcdefghijklmnop'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcdefghijklmnop'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcdefghijklmnop'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcdefghijklmnop'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcdefghijklmnop'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcdefghijklmnop'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcdefghijklmnop'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcdefghijklmnop'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,0,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,0,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,0,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,0,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,2,0,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-1,0,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,3,0,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,la)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)='... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)='... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)='... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)='... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)='... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)='... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)='... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)='... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,ld)='... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,ld)='... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,ld)='... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,ld)='... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,ld)='... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,ld)='... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,ld)='... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,ld)='... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=a'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,10)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 179s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=a'... OK! 179s END /funcs/func_env/ - func_file Time: 76ms Result: PASS 179s START /funcs/func_json/ - func_JSON_DECODE 179s END /funcs/func_json/ - func_JSON_DECODE Time: <1ms Result: PASS 179s START /funcs/func_presence/ - test_presence_state_base64_encode 179s END /funcs/func_presence/ - test_presence_state_base64_encode Time: 14ms Result: PASS 179s START /funcs/func_presence/ - test_presence_state_change 179s END /funcs/func_presence/ - test_presence_state_change Time: <1ms Result: PASS 179s START /funcs/func_presence/ - parse_invalid_presence_data 179s END /funcs/func_presence/ - parse_invalid_presence_data Time: <1ms Result: PASS 179s START /funcs/func_presence/ - parse_valid_presence_data 179s END /funcs/func_presence/ - parse_valid_presence_data Time: <1ms Result: PASS 179s START /funcs/func_sayfiles/ - test_SAYFILES_function 179s [func_sayfiles.c:test_SAYFILES_function:179]: Testing SAYFILES() substitution ... 179s END /funcs/func_sayfiles/ - test_SAYFILES_function Time: 5ms Result: PASS 179s START /funcs/func_strings/ - func_TRIM 179s END /funcs/func_strings/ - func_TRIM Time: <1ms Result: PASS 179s START /funcs/func_strings/ - func_STRBETWEEN 179s END /funcs/func_strings/ - func_STRBETWEEN Time: <1ms Result: PASS 179s START /funcs/func_strings/ - func_STRREPLACE_test 179s END /funcs/func_strings/ - func_STRREPLACE_test Time: <1ms Result: PASS 179s START /funcs/func_strings/ - func_FILTER_test 179s END /funcs/func_strings/ - func_FILTER_test Time: <1ms Result: PASS 179s START /funcs/func_strings/ - func_REPLACE_test 179s END /funcs/func_strings/ - func_REPLACE_test Time: <1ms Result: PASS 179s START /funcs/func_strings/ - func_FIELDNUM_test 179s END /funcs/func_strings/ - func_FIELDNUM_test Time: <1ms Result: PASS 179s START /geoloc/ - create_from_pidf 179s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1274]: ID: 'point-2d' pidf_element: 'tuple' format: 'GML' method: 'Manual' 179s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1286]: location_vars expected: shape=Point,crs=2d,pos=-34.410649 150.87651 179s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1287]: location_vars received: shape=Point,crs=2d,pos=-34.410649 150.87651 179s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1293]: usage_rules expected: retransmission-allowed='no',retention-expiry='2010-11-14T20:00:00Z' 179s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1294]: usage_rules received: retransmission-allowed='no',retention-expiry='2010-11-14T20:00:00Z' 179s END /geoloc/ - create_from_pidf Time: <1ms Result: PASS 179s START /geoloc/ - create_from_uri 179s END /geoloc/ - create_from_uri Time: <1ms Result: PASS 179s START /main/abstract_jb/ - AST_JB_FIXED_put_out_of_order 179s [test_abstract_jb.c:AST_JB_FIXED_put_out_of_order:531]: Executing AST_JB_FIXED_put_out_of_order... 179s END /main/abstract_jb/ - AST_JB_FIXED_put_out_of_order Time: <1ms Result: PASS 179s START /main/abstract_jb/ - AST_JB_FIXED_put_overflow 179s [test_abstract_jb.c:AST_JB_FIXED_put_overflow:529]: Executing AST_JB_FIXED_put_overflow... 179s END /main/abstract_jb/ - AST_JB_FIXED_put_overflow Time: <1ms Result: PASS 179s START /main/abstract_jb/ - AST_JB_FIXED_put 179s [test_abstract_jb.c:AST_JB_FIXED_put:527]: Executing AST_JB_FIXED_put... 179s END /main/abstract_jb/ - AST_JB_FIXED_put Time: <1ms Result: PASS 179s START /main/abstract_jb/ - AST_JB_FIXED_put_first 179s [test_abstract_jb.c:AST_JB_FIXED_put_first:525]: Executing AST_JB_FIXED_create... 179s END /main/abstract_jb/ - AST_JB_FIXED_put_first Time: <1ms Result: PASS 179s START /main/abstract_jb/ - AST_JB_FIXED_create 179s [test_abstract_jb.c:AST_JB_FIXED_create:523]: Executing AST_JB_FIXED_create... 179s END /main/abstract_jb/ - AST_JB_FIXED_create Time: <1ms Result: PASS 179s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_out_of_order 179s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_out_of_order:521]: Executing AST_JB_ADAPTIVE_put_out_of_order... 179s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_out_of_order Time: <1ms Result: PASS 179s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_overflow 179s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_overflow:519]: Executing AST_JB_ADAPTIVE_put_overflow... 179s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_overflow Time: <1ms Result: PASS 179s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put 179s [test_abstract_jb.c:AST_JB_ADAPTIVE_put:517]: Executing AST_JB_ADAPTIVE_put... 179s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put Time: <1ms Result: PASS 179s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_first 179s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_first:515]: Executing AST_JB_ADAPTIVE_create... 179s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_first Time: <1ms Result: PASS 179s START /main/abstract_jb/ - AST_JB_ADAPTIVE_create 179s [test_abstract_jb.c:AST_JB_ADAPTIVE_create:513]: Executing AST_JB_ADAPTIVE_create... 179s END /main/abstract_jb/ - AST_JB_ADAPTIVE_create Time: <1ms Result: PASS 179s START /main/acl/ - acl 179s END /main/acl/ - acl Time: <1ms Result: PASS 179s START /main/acl/ - invalid_acl 179s END /main/acl/ - invalid_acl Time: <1ms Result: PASS 179s START /main/amihooks/ - amihook_cli_send 179s END /main/amihooks/ - amihook_cli_send Time: <1ms Result: PASS 179s START /main/aoc/ - aoc_event_test 179s END /main/aoc/ - aoc_event_test Time: <1ms Result: PASS 179s START /main/aoc/ - aoc_encode_decode_test 179s END /main/aoc/ - aoc_encode_decode_test Time: <1ms Result: PASS 179s START /main/app/ - options_parsing 179s END /main/app/ - options_parsing Time: <1ms Result: PASS 179s START /main/app/ - app_group 179s [test_app.c:app_group:172]: Creating test channels with the following groups: 179s 'a groupgroupgroup', 'a groupGroupgroup', 'a group@a_category', 'a group@another!Category' 179s [test_app.c:app_group:211]: (Subtest 1) Found 4 matches as expected when examining group:'gr' category:'' 179s [test_app.c:app_group:211]: (Subtest 2) Found 1 matches as expected when examining group:'(group){2}$' category:'' 179s [test_app.c:app_group:211]: (Subtest 3) Found 4 matches as expected when examining group:'[:ascii:]' category:'' 179s [test_app.c:app_group:211]: (Subtest 4) Found 0 matches as expected when examining group:'^(NOMATCH)' category:'' 179s [test_app.c:app_group:211]: (Subtest 5) Found 2 matches as expected when examining group:'a group' category:'(gory)$' 179s [test_app.c:app_group:211]: (Subtest 6) Found 1 matches as expected when examining group:'a group' category:'[A-Z]+' 179s [test_app.c:app_group:211]: (Subtest 7) Found 0 matches as expected when examining group:'a group' category:'[[' 179s END /main/app/ - app_group Time: <1ms Result: PASS 179s START /main/ast_expr/ - expr_test 179s END /main/ast_expr/ - expr_test Time: <1ms Result: PASS 179s START /main/astdb/ - put_get_long 179s END /main/astdb/ - put_get_long Time: 96ms Result: PASS 179s START /main/astdb/ - perftest 179s END /main/astdb/ - perftest Time: 275ms Result: PASS 179s START /main/astdb/ - gettree_deltree 179s END /main/astdb/ - gettree_deltree Time: <1ms Result: PASS 179s START /main/astdb/ - put_get_del 179s END /main/astdb/ - put_get_del Time: <1ms Result: PASS 179s START /main/astobj2/ - thrash 179s [test_astobj2_thrash.c:hash_test:266]: Executing hash concurrency test... 179s END /main/astobj2/ - thrash Time: 46ms Result: PASS 179s START /main/astobj2/ - astobj2_weak_container 179s END /main/astobj2/ - astobj2_weak_container Time: <1ms Result: PASS 179s START /main/astobj2/ - astobj2_weak1 179s END /main/astobj2/ - astobj2_weak1 Time: <1ms Result: PASS 179s START /main/astobj2/ - astobj2_test4 179s [test_astobj2.c:test_traversal_nonsorted:1389]: Test 1, List containers. 179s [test_astobj2.c:test_traversal_nonsorted:1389]: Test 2, Hash containers. 179s [test_astobj2.c:test_traversal_sorted:1615]: Test 3, List containers. 179s [test_astobj2.c:test_traversal_sorted:1615]: Test 4, Hash containers. 179s [test_astobj2.c:test_traversal_sorted:1615]: Test 5, RBTree containers. 179s END /main/astobj2/ - astobj2_test4 Time: <1ms Result: PASS 179s START /main/astobj2/ - astobj2_test3 179s END /main/astobj2/ - astobj2_test3 Time: <1ms Result: PASS 179s START /main/astobj2/ - astobj2_test2 179s END /main/astobj2/ - astobj2_test2 Time: <1ms Result: PASS 179s START /main/astobj2/ - astobj2_test1 179s [test_astobj2.c:astobj2_test_1_helper:434]: Test 1, List containers (non-sorted). 179s [test_astobj2.c:astobj2_test_1_helper:488]: List container created: buckets: 1, items: 50 179s [test_astobj2.c:astobj2_test_1_helper:434]: Test 2, List containers (sorted). 179s [test_astobj2.c:astobj2_test_1_helper:488]: List container created: buckets: 1, items: 50 179s [test_astobj2.c:astobj2_test_1_helper:434]: Test 3, Hash containers (non-sorted). 179s [test_astobj2.c:astobj2_test_1_helper:488]: Hash container created: buckets: 202, items: 1000 179s [test_astobj2.c:astobj2_test_1_helper:434]: Test 4, Hash containers (sorted). 179s [test_astobj2.c:astobj2_test_1_helper:488]: Hash container created: buckets: 90, items: 1000 179s [test_astobj2.c:astobj2_test_1_helper:434]: Test 4, RBTree containers (sorted). 179s [test_astobj2.c:astobj2_test_1_helper:488]: RBTree container created: buckets: 1, items: 1000 179s END /main/astobj2/ - astobj2_test1 Time: 10ms Result: PASS 179s START /main/astobj2/perf/ - astobj2_test_perf 180s [test_astobj2.c:testloop:2001]: 20.00K traversals, List 181s [test_astobj2.c:testloop:2001]: 40.00K traversals, List 182s [test_astobj2.c:testloop:2001]: 60.00K traversals, List 183s [test_astobj2.c:testloop:2001]: 80.00K traversals, List 184s [test_astobj2.c:testloop:2006]: 100.00K traversals, List : 4339 ms 184s [test_astobj2.c:testloop:2001]: 20.00K traversals, Hash 185s [test_astobj2.c:testloop:2001]: 40.00K traversals, Hash 185s [test_astobj2.c:testloop:2001]: 60.00K traversals, Hash 186s [test_astobj2.c:testloop:2001]: 80.00K traversals, Hash 186s [test_astobj2.c:testloop:2006]: 100.00K traversals, Hash : 2371 ms 187s [test_astobj2.c:testloop:2001]: 20.00K traversals, RBTree 187s [test_astobj2.c:testloop:2001]: 40.00K traversals, RBTree 188s [test_astobj2.c:testloop:2001]: 60.00K traversals, RBTree 189s [test_astobj2.c:testloop:2001]: 80.00K traversals, RBTree 189s [test_astobj2.c:testloop:2006]: 100.00K traversals, RBTree : 2944 ms 189s END /main/astobj2/perf/ - astobj2_test_perf Time: 9656ms Result: PASS 189s START /main/bridging/ - test_bridging_deferred_queue 190s END /main/bridging/ - test_bridging_deferred_queue Time: 1008ms Result: PASS 190s START /main/bucket/ - bucket_file_json 190s END /main/bucket/ - bucket_file_json Time: <1ms Result: PASS 190s START /main/bucket/ - bucket_file_metadata_get 190s END /main/bucket/ - bucket_file_metadata_get Time: <1ms Result: PASS 190s START /main/bucket/ - bucket_file_metadata_unset 190s END /main/bucket/ - bucket_file_metadata_unset Time: <1ms Result: PASS 190s START /main/bucket/ - bucket_file_metadata_set 190s END /main/bucket/ - bucket_file_metadata_set Time: <1ms Result: PASS 190s START /main/bucket/ - bucket_file_is_stale 190s END /main/bucket/ - bucket_file_is_stale Time: <1ms Result: PASS 190s START /main/bucket/ - bucket_file_delete 190s END /main/bucket/ - bucket_file_delete Time: <1ms Result: PASS 190s START /main/bucket/ - bucket_file_update 190s END /main/bucket/ - bucket_file_update Time: <1ms Result: PASS 190s START /main/bucket/ - bucket_file_retrieve 190s END /main/bucket/ - bucket_file_retrieve Time: <1ms Result: PASS 190s START /main/bucket/ - bucket_file_copy 190s END /main/bucket/ - bucket_file_copy Time: <1ms Result: PASS 190s START /main/bucket/ - bucket_file_clone 190s END /main/bucket/ - bucket_file_clone Time: <1ms Result: PASS 190s START /main/bucket/ - bucket_file_create 190s END /main/bucket/ - bucket_file_create Time: <1ms Result: PASS 190s START /main/bucket/ - bucket_file_alloc 190s END /main/bucket/ - bucket_file_alloc Time: <1ms Result: PASS 190s START /main/bucket/ - bucket_json 190s END /main/bucket/ - bucket_json Time: <1ms Result: PASS 190s START /main/bucket/ - bucket_is_stale 190s END /main/bucket/ - bucket_is_stale Time: <1ms Result: PASS 190s START /main/bucket/ - bucket_retrieve 190s END /main/bucket/ - bucket_retrieve Time: <1ms Result: PASS 190s START /main/bucket/ - bucket_delete 190s END /main/bucket/ - bucket_delete Time: <1ms Result: PASS 190s START /main/bucket/ - bucket_clone 190s END /main/bucket/ - bucket_clone Time: <1ms Result: PASS 190s START /main/bucket/ - bucket_create 190s END /main/bucket/ - bucket_create Time: <1ms Result: PASS 190s START /main/bucket/ - bucket_alloc 190s END /main/bucket/ - bucket_alloc Time: <1ms Result: PASS 190s START /main/bucket/ - bucket_scheme_register_unregister 190s END /main/bucket/ - bucket_scheme_register_unregister Time: <1ms Result: PASS 190s START /main/callerid/ - parse_off_nominal 190s END /main/callerid/ - parse_off_nominal Time: <1ms Result: PASS 190s START /main/callerid/ - parse_nominal 190s END /main/callerid/ - parse_nominal Time: <1ms Result: PASS 190s START /main/cdr/ - test_cdr_fork_cdr 192s Verifying expected record CDRTestChannel/Alice, 192s Finished expected record CDRTestChannel/Alice, 192s Verifying expected record CDRTestChannel/Alice, 192s Finished expected record CDRTestChannel/Alice, 192s Verifying expected record CDRTestChannel/Alice, 192s Finished expected record CDRTestChannel/Alice, 192s END /main/cdr/ - test_cdr_fork_cdr Time: 2001ms Result: PASS 192s START /main/cdr/ - test_cdr_no_reset_cdr 193s Verifying expected record CDRTestChannel/Alice, 193s Finished expected record CDRTestChannel/Alice, 193s END /main/cdr/ - test_cdr_no_reset_cdr Time: 1000ms Result: PASS 193s START /main/cdr/ - test_cdr_fields 195s Verifying expected record CDRTestChannel/Alice, 195s Finished expected record CDRTestChannel/Alice, 195s Verifying expected record CDRTestChannel/Alice, 195s Finished expected record CDRTestChannel/Alice, 195s Verifying expected record CDRTestChannel/Alice, 195s Finished expected record CDRTestChannel/Alice, 195s END /main/cdr/ - test_cdr_fields Time: 2001ms Result: PASS 195s START /main/cdr/ - test_cdr_park 198s Verifying expected record CDRTestChannel/Alice, 198s Finished expected record CDRTestChannel/Alice, 198s Verifying expected record CDRTestChannel/Bob, 198s Finished expected record CDRTestChannel/Bob, 198s END /main/cdr/ - test_cdr_park Time: 3001ms Result: PASS 198s START /main/cdr/ - test_cdr_dial_answer_multiparty 203s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 203s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 203s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 203s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 203s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/David 203s Finished expected record CDRTestChannel/Alice, CDRTestChannel/David 203s Verifying expected record CDRTestChannel/Bob, CDRTestChannel/David 203s Finished expected record CDRTestChannel/Bob, CDRTestChannel/David 203s Verifying expected record CDRTestChannel/Charlie, CDRTestChannel/David 203s Finished expected record CDRTestChannel/Charlie, CDRTestChannel/David 203s Verifying expected record CDRTestChannel/Charlie, CDRTestChannel/Bob 203s Finished expected record CDRTestChannel/Charlie, CDRTestChannel/Bob 203s END /main/cdr/ - test_cdr_dial_answer_multiparty Time: 5003ms Result: PASS 203s START /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_b 206s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 206s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 206s END /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_b Time: 3001ms Result: PASS 206s START /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_a 208s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 208s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 208s END /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_a Time: 2002ms Result: PASS 208s START /main/cdr/ - test_cdr_dial_answer_no_bridge 208s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 208s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 208s Verifying expected record CDRTestChannel/Alice, 208s Finished expected record CDRTestChannel/Alice, 208s Verifying expected record CDRTestChannel/Bob, 208s Finished expected record CDRTestChannel/Bob, 208s END /main/cdr/ - test_cdr_dial_answer_no_bridge Time: <1ms Result: PASS 208s START /main/cdr/ - test_cdr_dial_parallel_failed 208s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 208s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 208s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 208s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 208s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/David 208s Finished expected record CDRTestChannel/Alice, CDRTestChannel/David 208s END /main/cdr/ - test_cdr_dial_parallel_failed Time: <1ms Result: PASS 208s START /main/cdr/ - test_cdr_dial_caller_cancel 208s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 208s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 208s END /main/cdr/ - test_cdr_dial_caller_cancel Time: <1ms Result: PASS 208s START /main/cdr/ - test_cdr_dial_unavailable 208s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 208s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 208s END /main/cdr/ - test_cdr_dial_unavailable Time: <1ms Result: PASS 208s START /main/cdr/ - test_cdr_dial_busy 208s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 208s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 208s END /main/cdr/ - test_cdr_dial_busy Time: <1ms Result: PASS 208s START /main/cdr/ - test_cdr_dial_congestion 208s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 208s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 208s END /main/cdr/ - test_cdr_dial_congestion Time: <1ms Result: PASS 208s START /main/cdr/ - test_cdr_dial_unanswered 208s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 208s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 208s END /main/cdr/ - test_cdr_dial_unanswered Time: <1ms Result: PASS 208s START /main/cdr/ - test_cdr_outbound_bridged_call 211s Verifying expected record CDRTestChannel/Bob, 211s Finished expected record CDRTestChannel/Bob, 211s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 211s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 211s END /main/cdr/ - test_cdr_outbound_bridged_call Time: 3002ms Result: PASS 211s START /main/cdr/ - test_cdr_single_multiparty_bridge 215s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 215s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 215s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 215s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 215s Verifying expected record CDRTestChannel/Bob, CDRTestChannel/Charlie 215s Finished expected record CDRTestChannel/Bob, CDRTestChannel/Charlie 215s Verifying expected record CDRTestChannel/Charlie, 215s Finished expected record CDRTestChannel/Charlie, 215s END /main/cdr/ - test_cdr_single_multiparty_bridge Time: 4003ms Result: PASS 215s START /main/cdr/ - test_cdr_single_twoparty_bridge_b 218s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 218s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 218s Verifying expected record CDRTestChannel/Bob, 218s Finished expected record CDRTestChannel/Bob, 218s END /main/cdr/ - test_cdr_single_twoparty_bridge_b Time: 3001ms Result: PASS 218s START /main/cdr/ - test_cdr_single_twoparty_bridge_a 220s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 220s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 220s Verifying expected record CDRTestChannel/Bob, 220s Finished expected record CDRTestChannel/Bob, 220s END /main/cdr/ - test_cdr_single_twoparty_bridge_a Time: 2001ms Result: PASS 220s START /main/cdr/ - test_cdr_single_bridge_continue 222s Verifying expected record CDRTestChannel/Alice, 222s Finished expected record CDRTestChannel/Alice, 222s Verifying expected record CDRTestChannel/Alice, 222s Finished expected record CDRTestChannel/Alice, 222s END /main/cdr/ - test_cdr_single_bridge_continue Time: 2001ms Result: PASS 222s START /main/cdr/ - test_cdr_single_bridge 224s Verifying expected record CDRTestChannel/Alice, 224s Finished expected record CDRTestChannel/Alice, 224s END /main/cdr/ - test_cdr_single_bridge Time: 2001ms Result: PASS 224s START /main/cdr/ - test_cdr_single_party 224s Verifying expected record CDRTestChannel/Alice, 224s Finished expected record CDRTestChannel/Alice, 224s END /main/cdr/ - test_cdr_single_party Time: <1ms Result: PASS 224s START /main/cdr/ - test_cdr_unanswered_outbound_call 224s Verifying expected record CDRTestChannel/Alice, 224s Finished expected record CDRTestChannel/Alice, 224s END /main/cdr/ - test_cdr_unanswered_outbound_call Time: <1ms Result: PASS 224s START /main/cdr/ - test_cdr_unanswered_inbound_call 224s Verifying expected record CDRTestChannel/Alice, 224s Finished expected record CDRTestChannel/Alice, 224s END /main/cdr/ - test_cdr_unanswered_inbound_call Time: <1ms Result: PASS 224s START /main/cdr/ - test_cdr_channel_creation 224s Verifying expected record CDRTestChannel/Alice, 224s Finished expected record CDRTestChannel/Alice, 224s END /main/cdr/ - test_cdr_channel_creation Time: <1ms Result: PASS 224s START /main/channel/ - add_fd 224s END /main/channel/ - add_fd Time: <1ms Result: PASS 224s START /main/channel/ - set_fd_grow 224s END /main/channel/ - set_fd_grow Time: <1ms Result: PASS 224s START /main/config/ - variable_list_from_quoted_string 224s END /main/config/ - variable_list_from_quoted_string Time: <1ms Result: PASS 224s START /main/config/ - variable_list_join_replace 224s END /main/config/ - variable_list_join_replace Time: <1ms Result: PASS 224s START /main/config/ - variable_lists_match 224s END /main/config/ - variable_lists_match Time: <1ms Result: PASS 224s START /main/config/ - config_dialplan_function 224s END /main/config/ - config_dialplan_function Time: <1ms Result: PASS 224s START /main/config/ - config_hook 224s END /main/config/ - config_hook Time: <1ms Result: PASS 224s START /main/config/ - copy_config 224s END /main/config/ - copy_config Time: <1ms Result: PASS 224s START /main/config/ - config_template_ops 224s END /main/config/ - config_template_ops Time: <1ms Result: PASS 224s START /main/config/ - config_filtered_ops 224s END /main/config/ - config_filtered_ops Time: <1ms Result: PASS 224s START /main/config/ - config_basic_ops 224s END /main/config/ - config_basic_ops Time: <1ms Result: PASS 224s START /main/config/ - config_save 224s END /main/config/ - config_save Time: 1ms Result: PASS 224s START /main/conversions/ - str_to_umax 224s END /main/conversions/ - str_to_umax Time: <1ms Result: PASS 224s START /main/conversions/ - str_to_imax 224s END /main/conversions/ - str_to_imax Time: <1ms Result: PASS 224s START /main/conversions/ - str_to_ulong 224s END /main/conversions/ - str_to_ulong Time: <1ms Result: PASS 224s START /main/conversions/ - str_to_long 224s END /main/conversions/ - str_to_long Time: <1ms Result: PASS 224s START /main/conversions/ - str_to_uint 224s END /main/conversions/ - str_to_uint Time: <1ms Result: PASS 224s START /main/conversions/ - str_to_int 224s END /main/conversions/ - str_to_int Time: <1ms Result: PASS 224s START /main/core_codec/ - codec_get_unknown 224s END /main/core_codec/ - codec_get_unknown Time: <1ms Result: PASS 224s START /main/core_codec/ - codec_get_unknown 224s END /main/core_codec/ - codec_get_unknown Time: <1ms Result: PASS 224s START /main/core_codec/ - codec_get_unregistered 224s END /main/core_codec/ - codec_get_unregistered Time: <1ms Result: PASS 224s START /main/core_codec/ - codec_get 224s END /main/core_codec/ - codec_get Time: <1ms Result: PASS 224s START /main/core_codec/ - codec_register_audio_no_sample_rate 224s END /main/core_codec/ - codec_register_audio_no_sample_rate Time: <1ms Result: PASS 224s START /main/core_codec/ - codec_register_unknown 224s END /main/core_codec/ - codec_register_unknown Time: <1ms Result: PASS 224s START /main/core_codec/ - codec_register_twice 224s END /main/core_codec/ - codec_register_twice Time: <1ms Result: PASS 224s START /main/core_codec/ - codec_register 224s END /main/core_codec/ - codec_register Time: <1ms Result: PASS 224s START /main/core_format/ - format_parse_and_generate_sdp_fmtp 224s END /main/core_format/ - format_parse_and_generate_sdp_fmtp Time: <1ms Result: PASS 224s START /main/core_format/ - format_parse_sdp_fmtp_without_interface 224s END /main/core_format/ - format_parse_sdp_fmtp_without_interface Time: <1ms Result: PASS 224s START /main/core_format/ - format_attribute_get_without_interface 224s END /main/core_format/ - format_attribute_get_without_interface Time: <1ms Result: PASS 224s START /main/core_format/ - format_attribute_set_without_interface 224s END /main/core_format/ - format_attribute_set_without_interface Time: <1ms Result: PASS 224s START /main/core_format/ - format_copy 224s END /main/core_format/ - format_copy Time: <1ms Result: PASS 224s START /main/core_format/ - format_joint_different_codec 224s END /main/core_format/ - format_joint_different_codec Time: <1ms Result: PASS 224s START /main/core_format/ - format_attr_joint_same_codec 224s END /main/core_format/ - format_attr_joint_same_codec Time: <1ms Result: PASS 224s START /main/core_format/ - format_joint_same_codec 224s END /main/core_format/ - format_joint_same_codec Time: <1ms Result: PASS 224s START /main/core_format/ - format_cmp_different_codec 224s END /main/core_format/ - format_cmp_different_codec Time: <1ms Result: PASS 224s START /main/core_format/ - format_attr_cmp_same_codec 224s END /main/core_format/ - format_attr_cmp_same_codec Time: <1ms Result: PASS 224s START /main/core_format/ - format_cmp_same_codec 224s END /main/core_format/ - format_cmp_same_codec Time: <1ms Result: PASS 224s START /main/core_format/ - format_clone 224s END /main/core_format/ - format_clone Time: <1ms Result: PASS 224s START /main/core_format/ - format_retrieve_attr 224s END /main/core_format/ - format_retrieve_attr Time: <1ms Result: PASS 224s START /main/core_format/ - format_create_attr 224s END /main/core_format/ - format_create_attr Time: <1ms Result: PASS 224s START /main/core_format/ - format_create 224s END /main/core_format/ - format_create Time: <1ms Result: PASS 224s START /main/data_buffer/ - buffer_nominal 224s END /main/data_buffer/ - buffer_nominal Time: <1ms Result: PASS 224s START /main/data_buffer/ - buffer_resize 224s END /main/data_buffer/ - buffer_resize Time: <1ms Result: PASS 224s START /main/data_buffer/ - buffer_put 224s END /main/data_buffer/ - buffer_put Time: <1ms Result: PASS 224s START /main/data_buffer/ - buffer_create 224s END /main/data_buffer/ - buffer_create Time: <1ms Result: PASS 224s START /main/devicestate/ - devstate_channels 224s END /main/devicestate/ - devstate_channels Time: <1ms Result: PASS 224s START /main/devicestate/ - devstate_conversions 224s END /main/devicestate/ - devstate_conversions Time: <1ms Result: PASS 224s START /main/devicestate/ - devstate_changed 224s [test_devicestate.c:wait_for_device_state_updates:308]: Received 8 of 8 updates 224s [test_devicestate.c:devstate_changed:716]: Testing update 0: actual is 1; expected is 1 224s [test_devicestate.c:devstate_changed:716]: Testing update 1: actual is 2; expected is 2 224s [test_devicestate.c:devstate_changed:716]: Testing update 2: actual is 3; expected is 3 224s [test_devicestate.c:devstate_changed:716]: Testing update 3: actual is 4; expected is 4 224s [test_devicestate.c:devstate_changed:716]: Testing update 4: actual is 5; expected is 5 224s [test_devicestate.c:devstate_changed:716]: Testing update 5: actual is 6; expected is 6 224s [test_devicestate.c:devstate_changed:716]: Testing update 6: actual is 7; expected is 7 224s [test_devicestate.c:devstate_changed:716]: Testing update 7: actual is 8; expected is 8 224s [test_devicestate.c:wait_for_device_state_updates:308]: Received 1 of 1 updates 224s [test_devicestate.c:wait_for_device_state_updates:308]: Received 8 of 8 updates 224s [test_devicestate.c:devstate_changed:754]: Testing update 0: actual is 1; expected is 1 224s [test_devicestate.c:devstate_changed:754]: Testing update 1: actual is 2; expected is 2 224s [test_devicestate.c:devstate_changed:754]: Testing update 2: actual is 3; expected is 3 224s [test_devicestate.c:devstate_changed:754]: Testing update 3: actual is 4; expected is 4 224s [test_devicestate.c:devstate_changed:754]: Testing update 4: actual is 5; expected is 5 224s [test_devicestate.c:devstate_changed:754]: Testing update 5: actual is 6; expected is 6 224s [test_devicestate.c:devstate_changed:754]: Testing update 6: actual is 7; expected is 7 224s [test_devicestate.c:devstate_changed:754]: Testing update 7: actual is 8; expected is 8 224s END /main/devicestate/ - devstate_changed Time: 1ms Result: PASS 224s START /main/devicestate/ - devstate_prov_del 224s END /main/devicestate/ - devstate_prov_del Time: <1ms Result: PASS 224s START /main/devicestate/ - devstate_prov_add 224s END /main/devicestate/ - devstate_prov_add Time: <1ms Result: PASS 224s START /main/devicestate/ - device2extenstate_test 224s END /main/devicestate/ - device2extenstate_test Time: <1ms Result: PASS 224s START /main/devicestate/ - device_state_aggregation_test 224s END /main/devicestate/ - device_state_aggregation_test Time: <1ms Result: PASS 224s START /main/dns/ - resolver_resolve_async_cancel 224s END /main/dns/ - resolver_resolve_async_cancel Time: <1ms Result: PASS 224s START /main/dns/ - resolver_resolve_async_off_nominal 224s END /main/dns/ - resolver_resolve_async_off_nominal Time: <1ms Result: PASS 224s START /main/dns/ - resolver_resolve_async 229s END /main/dns/ - resolver_resolve_async Time: 5000ms Result: PASS 229s START /main/dns/ - resolver_resolve_sync_off_nominal 229s END /main/dns/ - resolver_resolve_sync_off_nominal Time: <1ms Result: PASS 229s START /main/dns/ - resolver_resolve_sync 234s END /main/dns/ - resolver_resolve_sync Time: 5000ms Result: PASS 234s START /main/dns/ - resolver_add_record_off_nominal 234s END /main/dns/ - resolver_add_record_off_nominal Time: <1ms Result: PASS 234s START /main/dns/ - resolver_add_record 234s END /main/dns/ - resolver_add_record Time: <1ms Result: PASS 234s START /main/dns/ - resolver_set_result_off_nominal 234s END /main/dns/ - resolver_set_result_off_nominal Time: <1ms Result: PASS 234s START /main/dns/ - resolver_set_result 234s END /main/dns/ - resolver_set_result Time: <1ms Result: PASS 234s START /main/dns/ - resolver_data 234s END /main/dns/ - resolver_data Time: <1ms Result: PASS 234s START /main/dns/ - resolver_unregister_off_nominal 234s END /main/dns/ - resolver_unregister_off_nominal Time: <1ms Result: PASS 234s START /main/dns/ - resolver_register_off_nominal 234s END /main/dns/ - resolver_register_off_nominal Time: <1ms Result: PASS 234s START /main/dns/ - resolver_register_unregister 234s END /main/dns/ - resolver_register_unregister Time: <1ms Result: PASS 234s START /main/dns/naptr/ - naptr_resolve_off_nominal_interactions 234s END /main/dns/naptr/ - naptr_resolve_off_nominal_interactions Time: <1ms Result: PASS 234s START /main/dns/naptr/ - naptr_resolve_off_nominal_regexp 234s END /main/dns/naptr/ - naptr_resolve_off_nominal_regexp Time: <1ms Result: PASS 234s START /main/dns/naptr/ - naptr_resolve_off_nominal_services 234s END /main/dns/naptr/ - naptr_resolve_off_nominal_services Time: <1ms Result: PASS 234s START /main/dns/naptr/ - naptr_resolve_off_nominal_flags 234s END /main/dns/naptr/ - naptr_resolve_off_nominal_flags Time: <1ms Result: PASS 234s START /main/dns/naptr/ - naptr_resolve_off_nominal_length 234s END /main/dns/naptr/ - naptr_resolve_off_nominal_length Time: <1ms Result: PASS 234s START /main/dns/naptr/ - naptr_resolve 234s END /main/dns/naptr/ - naptr_resolve Time: <1ms Result: PASS 234s START /main/dns/query_set/ - query_set_off_nominal_cancel 234s END /main/dns/query_set/ - query_set_off_nominal_cancel Time: <1ms Result: PASS 234s START /main/dns/query_set/ - query_set_nominal_cancel 234s END /main/dns/query_set/ - query_set_nominal_cancel Time: <1ms Result: PASS 234s START /main/dns/query_set/ - query_set_empty 234s END /main/dns/query_set/ - query_set_empty Time: <1ms Result: PASS 234s START /main/dns/query_set/ - query_set 234s END /main/dns/query_set/ - query_set Time: <1ms Result: PASS 234s START /main/dns/recurring/ - recurring_query_cancel_during 234s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 241s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 251s END /main/dns/recurring/ - recurring_query_cancel_during Time: 16999ms Result: PASS 251s START /main/dns/recurring/ - recurring_query_cancel_between 251s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 261s END /main/dns/recurring/ - recurring_query_cancel_between Time: 10000ms Result: PASS 261s START /main/dns/recurring/ - recurring_query_off_nominal 261s END /main/dns/recurring/ - recurring_query_off_nominal Time: <1ms Result: PASS 261s START /main/dns/recurring/ - recurring_query 261s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 268s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 280s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 280s END /main/dns/recurring/ - recurring_query Time: 18998ms Result: PASS 280s START /main/dns/srv/ - srv_resolve_record_missing_host 280s END /main/dns/srv/ - srv_resolve_record_missing_host Time: <1ms Result: PASS 280s START /main/dns/srv/ - srv_resolve_record_missing_port_host 280s END /main/dns/srv/ - srv_resolve_record_missing_port_host Time: <1ms Result: PASS 280s START /main/dns/srv/ - srv_resolve_record_missing_weight_port_host 280s END /main/dns/srv/ - srv_resolve_record_missing_weight_port_host Time: <1ms Result: PASS 280s START /main/dns/srv/ - srv_resolve_different_priorities_different_weights 280s END /main/dns/srv/ - srv_resolve_different_priorities_different_weights Time: 5ms Result: PASS 280s START /main/dns/srv/ - srv_resolve_same_priority_different_weights 280s END /main/dns/srv/ - srv_resolve_same_priority_different_weights Time: 5ms Result: PASS 280s START /main/dns/srv/ - srv_resolve_same_priority_zero_weight 280s END /main/dns/srv/ - srv_resolve_same_priority_zero_weight Time: <1ms Result: PASS 280s START /main/dns/srv/ - srv_resolve_sort_priority 280s END /main/dns/srv/ - srv_resolve_sort_priority Time: <1ms Result: PASS 280s START /main/dns/srv/ - srv_resolve_single_record 280s END /main/dns/srv/ - srv_resolve_single_record Time: <1ms Result: PASS 280s START /main/dsp/ - dtmf 280s END /main/dsp/ - dtmf Time: 3ms Result: PASS 280s START /main/dsp/ - fax 281s END /main/dsp/ - fax Time: 342ms Result: PASS 281s START /main/event/ - ast_event_new_test 281s [test_event.c:event_new_test:125]: First, test dynamic event creation... 281s [test_event.c:check_event:88]: Event looks good. 281s [test_event.c:check_event:88]: Event looks good. 281s END /main/event/ - ast_event_new_test Time: <1ms Result: PASS 281s START /main/file/ - read_dir_test 281s END /main/file/ - read_dir_test Time: <1ms Result: PASS 281s START /main/file/ - ast_format_str_reduce_test_1 281s END /main/file/ - ast_format_str_reduce_test_1 Time: <1ms Result: PASS 281s START /main/format_cache/ - format_cache_get_nonxistent 281s END /main/format_cache/ - format_cache_get_nonxistent Time: <1ms Result: PASS 281s START /main/format_cache/ - format_cache_get 281s END /main/format_cache/ - format_cache_get Time: <1ms Result: PASS 281s START /main/format_cache/ - format_cache_set_null 281s END /main/format_cache/ - format_cache_set_null Time: <1ms Result: PASS 281s START /main/format_cache/ - format_cache_set_duplicate 281s END /main/format_cache/ - format_cache_set_duplicate Time: <1ms Result: PASS 281s START /main/format_cache/ - format_cache_set 281s END /main/format_cache/ - format_cache_set Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_replace_from_cap 281s END /main/format_cap/ - format_cap_replace_from_cap Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_best_by_type 281s END /main/format_cap/ - format_cap_best_by_type Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_iscompatible 281s END /main/format_cap/ - format_cap_iscompatible Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_get_compatible 281s END /main/format_cap/ - format_cap_get_compatible Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_iscompatible_format 281s END /main/format_cap/ - format_cap_iscompatible_format Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_get_compatible_format 281s END /main/format_cap/ - format_cap_get_compatible_format Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_get_names 281s END /main/format_cap/ - format_cap_get_names Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_remove_all 281s END /main/format_cap/ - format_cap_remove_all Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_remove_bytype 281s END /main/format_cap/ - format_cap_remove_bytype Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_remove_multiple 281s END /main/format_cap/ - format_cap_remove_multiple Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_remove_single 281s END /main/format_cap/ - format_cap_remove_single Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_set_framing 281s END /main/format_cap/ - format_cap_set_framing Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_append_from_cap_duplicate 281s END /main/format_cap/ - format_cap_append_from_cap_duplicate Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_append_from_cap 281s END /main/format_cap/ - format_cap_append_from_cap Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_append_duplicate 281s END /main/format_cap/ - format_cap_append_duplicate Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_append_all_audio 281s END /main/format_cap/ - format_cap_append_all_audio Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_append_all_unknown 281s END /main/format_cap/ - format_cap_append_all_unknown Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_append_multiple 281s END /main/format_cap/ - format_cap_append_multiple Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_append_single 281s END /main/format_cap/ - format_cap_append_single Time: <1ms Result: PASS 281s START /main/format_cap/ - format_cap_alloc 281s END /main/format_cap/ - format_cap_alloc Time: <1ms Result: PASS 281s START /main/hashtab/ - thrash 281s [test_hashtab_thrash.c:hash_test:246]: Executing hash concurrency test... 281s END /main/hashtab/ - thrash Time: 76ms Result: PASS 281s START /main/heap/ - heap_test_3 281s END /main/heap/ - heap_test_3 Time: 102ms Result: PASS 281s START /main/heap/ - heap_test_2 281s END /main/heap/ - heap_test_2 Time: 95ms Result: PASS 281s START /main/heap/ - heap_test_1 281s END /main/heap/ - heap_test_1 Time: <1ms Result: PASS 281s START /main/jitterbuf/ - jitterbuffer_resynch_control 281s END /main/jitterbuf/ - jitterbuffer_resynch_control Time: <1ms Result: PASS 281s START /main/jitterbuf/ - jitterbuffer_resynch_voice 281s END /main/jitterbuf/ - jitterbuffer_resynch_voice Time: <1ms Result: PASS 281s START /main/jitterbuf/ - jitterbuffer_overflow_control 281s END /main/jitterbuf/ - jitterbuffer_overflow_control Time: <1ms Result: PASS 281s START /main/jitterbuf/ - jitterbuffer_overflow_voice 281s END /main/jitterbuf/ - jitterbuffer_overflow_voice Time: <1ms Result: PASS 281s START /main/jitterbuf/ - jitterbuffer_late_control 281s END /main/jitterbuf/ - jitterbuffer_late_control Time: <1ms Result: PASS 281s START /main/jitterbuf/ - jitterbuffer_late_voice 281s END /main/jitterbuf/ - jitterbuffer_late_voice Time: <1ms Result: PASS 281s START /main/jitterbuf/ - jitterbuffer_lost_control 281s END /main/jitterbuf/ - jitterbuffer_lost_control Time: <1ms Result: PASS 281s START /main/jitterbuf/ - jitterbuffer_lost_voice 281s END /main/jitterbuf/ - jitterbuffer_lost_voice Time: <1ms Result: PASS 281s START /main/jitterbuf/ - jitterbuffer_out_of_order_voice 281s END /main/jitterbuf/ - jitterbuffer_out_of_order_voice Time: <1ms Result: PASS 281s START /main/jitterbuf/ - jitterbuffer_out_of_order_voice 281s END /main/jitterbuf/ - jitterbuffer_out_of_order_voice Time: <1ms Result: PASS 281s START /main/jitterbuf/ - jitterbuffer_nominal_control_frames 281s END /main/jitterbuf/ - jitterbuffer_nominal_control_frames Time: <1ms Result: PASS 281s START /main/jitterbuf/ - jitterbuffer_nominal_voice_frames 281s END /main/jitterbuf/ - jitterbuffer_nominal_voice_frames Time: <1ms Result: PASS 281s START /main/json/ - cep 281s END /main/json/ - cep Time: <1ms Result: PASS 281s START /main/json/ - type_timeval 281s END /main/json/ - type_timeval Time: 1ms Result: PASS 281s START /main/json/ - name_number 281s END /main/json/ - name_number Time: <1ms Result: PASS 281s START /main/json/ - clever_circle 281s END /main/json/ - clever_circle Time: <1ms Result: PASS 281s START /main/json/ - circular_array 281s END /main/json/ - circular_array Time: <1ms Result: PASS 281s START /main/json/ - circular_object 281s END /main/json/ - circular_object Time: <1ms Result: PASS 281s START /main/json/ - copy_null 281s END /main/json/ - copy_null Time: <1ms Result: PASS 281s START /main/json/ - deep_copy 281s END /main/json/ - deep_copy Time: <1ms Result: PASS 281s START /main/json/ - copy 281s END /main/json/ - copy Time: <1ms Result: PASS 281s START /main/json/ - object_alloc 281s END /main/json/ - object_alloc Time: 2ms Result: PASS 281s START /main/json/ - pack_ownership 281s END /main/json/ - pack_ownership Time: <1ms Result: PASS 281s START /main/json/ - pack 281s END /main/json/ - pack Time: <1ms Result: PASS 281s START /main/json/ - parse_errors 281s END /main/json/ - parse_errors Time: <1ms Result: PASS 281s START /main/json/ - dump_load_null 281s END /main/json/ - dump_load_null Time: <1ms Result: PASS 281s START /main/json/ - dump_load_new_file 281s END /main/json/ - dump_load_new_file Time: <1ms Result: PASS 281s START /main/json/ - dump_load_file 281s END /main/json/ - dump_load_file Time: <1ms Result: PASS 281s START /main/json/ - load_buffer 281s END /main/json/ - load_buffer Time: <1ms Result: PASS 281s START /main/json/ - dump_str_fail 281s END /main/json/ - dump_str_fail Time: <1ms Result: PASS 281s START /main/json/ - dump_load_str 281s END /main/json/ - dump_load_str Time: <1ms Result: PASS 281s START /main/json/ - dump_load_string 281s END /main/json/ - dump_load_string Time: <1ms Result: PASS 281s START /main/json/ - object_create_vars 281s END /main/json/ - object_create_vars Time: <1ms Result: PASS 281s START /main/json/ - object_iter_null 281s END /main/json/ - object_iter_null Time: <1ms Result: PASS 281s START /main/json/ - object_iter 281s END /main/json/ - object_iter Time: <1ms Result: PASS 281s START /main/json/ - object_null 281s END /main/json/ - object_null Time: <1ms Result: PASS 281s START /main/json/ - object_merge_missing 281s END /main/json/ - object_merge_missing Time: <1ms Result: PASS 281s START /main/json/ - object_alloc 281s END /main/json/ - object_alloc Time: <1ms Result: PASS 281s START /main/json/ - object_alloc 281s END /main/json/ - object_alloc Time: <1ms Result: PASS 281s START /main/json/ - object_clear 281s END /main/json/ - object_clear Time: <1ms Result: PASS 281s START /main/json/ - object_del 281s END /main/json/ - object_del Time: <1ms Result: PASS 281s START /main/json/ - object_get 281s END /main/json/ - object_get Time: <1ms Result: PASS 281s START /main/json/ - object_set_overwriting 281s END /main/json/ - object_set_overwriting Time: <1ms Result: PASS 281s START /main/json/ - object_set 281s END /main/json/ - object_set Time: <1ms Result: PASS 281s START /main/json/ - object_alloc 281s END /main/json/ - object_alloc Time: <1ms Result: PASS 281s START /main/json/ - array_null 281s END /main/json/ - array_null Time: <1ms Result: PASS 281s START /main/json/ - array_extend 281s END /main/json/ - array_extend Time: <1ms Result: PASS 281s START /main/json/ - array_clear 281s END /main/json/ - array_clear Time: <1ms Result: PASS 281s START /main/json/ - array_remove 281s END /main/json/ - array_remove Time: <1ms Result: PASS 281s START /main/json/ - array_set 281s END /main/json/ - array_set Time: <1ms Result: PASS 281s START /main/json/ - array_insert 281s END /main/json/ - array_insert Time: <1ms Result: PASS 281s START /main/json/ - array_append 281s END /main/json/ - array_append Time: <1ms Result: PASS 281s START /main/json/ - array_create 281s END /main/json/ - array_create Time: <1ms Result: PASS 281s START /main/json/ - non_int 281s END /main/json/ - non_int Time: <1ms Result: PASS 281s START /main/json/ - type_int 281s END /main/json/ - type_int Time: <1ms Result: PASS 281s START /main/json/ - stringf 281s END /main/json/ - stringf Time: <1ms Result: PASS 281s START /main/json/ - string_null 281s END /main/json/ - string_null Time: <1ms Result: PASS 281s START /main/json/ - type_string 281s END /main/json/ - type_string Time: <1ms Result: PASS 281s START /main/json/ - null_val 281s END /main/json/ - null_val Time: <1ms Result: PASS 281s START /main/json/ - type_null 281s END /main/json/ - type_null Time: <1ms Result: PASS 281s START /main/json/ - type_bool1 281s END /main/json/ - type_bool1 Time: <1ms Result: PASS 281s START /main/json/ - type_bool0 281s END /main/json/ - type_bool0 Time: <1ms Result: PASS 281s START /main/json/ - type_true 281s END /main/json/ - type_true Time: <1ms Result: PASS 281s START /main/json/ - type_false 281s END /main/json/ - type_false Time: <1ms Result: PASS 281s START /main/linkedlists/ - double_ll_tests 281s END /main/linkedlists/ - double_ll_tests Time: <1ms Result: PASS 281s START /main/linkedlists/ - ll_tests 281s END /main/linkedlists/ - ll_tests Time: <1ms Result: PASS 281s START /main/lock/ - named_lock_test 281s [test_named_lock.c:named_lock_test:80]: This test should take about 3 seconds 284s END /main/lock/ - named_lock_test Time: 3000ms Result: PASS 284s START /main/lock/ - cleanup_order_test 284s [test_scoped_lock.c:test_ref:149]: Ref is occurring 284s [test_scoped_lock.c:test_lock:117]: Lock is occurring 284s [test_scoped_lock.c:test_unlock:133]: Unlock is occurring 284s [test_scoped_lock.c:test_unref:166]: Unref is occurring 284s [test_scoped_lock.c:test_ref:149]: Ref is occurring 284s [test_scoped_lock.c:test_lock:117]: Lock is occurring 284s [test_scoped_lock.c:test_unlock:133]: Unlock is occurring 284s [test_scoped_lock.c:test_unref:166]: Unref is occurring 284s END /main/lock/ - cleanup_order_test Time: <1ms Result: PASS 284s START /main/lock/ - lock_test 284s END /main/lock/ - lock_test Time: <1ms Result: PASS 284s START /main/logging/ - scope_test 284s END /main/logging/ - scope_test Time: <1ms Result: PASS 284s START /main/manager/ - originate_permissions_test 284s END /main/manager/ - originate_permissions_test Time: <1ms Result: PASS 284s START /main/manager/ - eventfilter_test_matching 284s Loaded 7 filters 284s Tested 9 events 284s END /main/manager/ - eventfilter_test_matching Time: <1ms Result: PASS 284s START /main/manager/ - eventfilter_test_creation 284s [manager.c:eventfilter_test_creation:6215]: Tested 29 filters 284s END /main/manager/ - eventfilter_test_creation Time: <1ms Result: PASS 284s START /main/media_cache/ - create_update_off_nominal 284s END /main/media_cache/ - create_update_off_nominal Time: <1ms Result: PASS 284s START /main/media_cache/ - create_update_metadata 284s [test_media_cache.c:create_update_metadata:367]: Got /tmp/test-media-cache-BYhdff for second file path 284s END /main/media_cache/ - create_update_metadata Time: <1ms Result: PASS 284s START /main/media_cache/ - create_update_nominal 284s [test_media_cache.c:create_update_nominal:236]: Creating resource with /tmp/test-media-cache-W1oSmD 284s [test_media_cache.c:create_update_nominal:241]: Got /tmp/test-media-cache-W1oSmD for first file path 284s [test_media_cache.c:create_update_nominal:245]: Creating resource with /tmp/test-media-cache-B9Ljsx 284s [test_media_cache.c:create_update_nominal:250]: Got /tmp/test-media-cache-B9Ljsx for second file path 284s END /main/media_cache/ - create_update_nominal Time: <1ms Result: PASS 284s START /main/media_cache/ - exists_off_nominal 284s END /main/media_cache/ - exists_off_nominal Time: <1ms Result: PASS 284s START /main/media_cache/ - exists_nominal 284s END /main/media_cache/ - exists_nominal Time: <1ms Result: PASS 284s START /main/netsock2/ - split_hostport 284s END /main/netsock2/ - split_hostport Time: <1ms Result: PASS 284s START /main/netsock2/ - parsing 284s END /main/netsock2/ - parsing Time: <1ms Result: PASS 284s START /main/optional_api/ - test_provide_last 284s END /main/optional_api/ - test_provide_last Time: <1ms Result: PASS 284s START /main/optional_api/ - test_provide_first 284s END /main/optional_api/ - test_provide_first Time: <1ms Result: PASS 284s START /main/pbx/ - test_substitution 284s [test_substitution.c:test_substitution:244]: Testing variable substitution ... 284s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGANI2}' . . . . . passed 284s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGTON}' . . . . . passed 284s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGTNS}' . . . . . passed 284s [test_substitution.c:test_chan_integer_accessor:89]: Tested '${HANGUPCAUSE}' . . . . . passed 284s [test_substitution.c:test_chan_integer_accessor:89]: Tested '${PRIORITY}' . . . . . passed 284s [test_substitution.c:test_chan_string:115]: Tested '${CONTEXT}' . . . . . passed 284s [test_substitution.c:test_chan_string:115]: Tested '${EXTEN}' . . . . . passed 284s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(language)}' . . . . . passed 284s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(musicclass)}' . . . . . passed 284s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(parkinglot)}' . . . . . passed 284s [test_substitution.c:test_chan_variable:144]: Tested '${CALLERID(name)}' . . . . . passed 284s [test_substitution.c:test_chan_variable:144]: Tested '${CURLOPT(proxyuserpwd)}' . . . . . passed 284s [test_substitution.c:test_chan_variable:144]: Tested '${CDR(foo)}' . . . . . passed 284s [test_substitution.c:test_chan_variable:144]: Tested '${ENV(foo)}' . . . . . passed 284s [test_substitution.c:test_chan_variable:144]: Tested '${GLOBAL(foo)}' . . . . . passed 284s [test_substitution.c:test_chan_variable:144]: Tested '${GROUP()}' . . . . . passed 284s [test_substitution.c:test_2way_function:193]: Tested '${AES_ENCRYPT(abcdefghijklmnop,)}' and '${AES_DECRYPT(abcdefghijklmnop,)}' . . . . . passed 284s [test_substitution.c:test_2way_function:193]: Tested '${BASE64_ENCODE()}' and '${BASE64_DECODE()}' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested '123123' ('${foo}${foo}') == '123123' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested 'A123A123A' ('A${foo}A${foo}A') == 'A123A123A' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested 'A123A' ('A${${bar}}A') == 'A123A' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested 'A123A' ('A${${baz}o}A') == 'A123A' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested 'A23A' ('A${${baz}o:1}A') == 'A23A' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:1:1}A') == 'A2A' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:1:-1}A') == 'A2A' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested 'A3A' ('A${${baz}o:-1:1}A') == 'A3A' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:-2:1}A') == 'A2A' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:-2:-1}A') == 'A2A' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested 'cd&ef' ('${LISTFILTER(list1,&,ab)}') == 'cd&ef' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested 'ab&ef' ('${LISTFILTER(list1,&,cd)}') == 'ab&ef' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd' ('${LISTFILTER(list1,&,ef)}') == 'ab&cd' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,gh)}') == 'ab&cd&ef' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,c)}') == 'ab&cd&ef' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,d)}') == 'ab&cd&ef' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested '' ('${LISTFILTER(list2,&,ab)}') == '' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested '' ('${LISTFILTER(list_empty,&,ab)}') == '' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested '123,456' ('${SHELL(printf '%d' 123)},${SHELL(printf '%d' 456)}') == '123,456' . . . . . passed 284s [test_substitution.c:test_expected_result:215]: Tested '123,,456' ('${foo},${CDR(answer)},${SHELL(printf '%d' 456)}') == '123,,456' . . . . . passed 284s [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 284s [test_substitution.c:test_expected_result:215]: Tested '123,,' ('${foo},${this_does_not_exist},${THIS_DOES_NOT_EXIST(either)}') == '123,,' . . . . . passed 284s [test_substitution.c:test_chan_function:168]: Tested '${BLACKLIST(foo)}' . . . . . passed 284s [test_substitution.c:test_chan_function:168]: Tested '${EVAL(foo)}' . . . . . passed 284s [test_substitution.c:test_chan_function:168]: Tested '${FIELDNUM(foo)}' . . . . . passed 284s [test_substitution.c:test_chan_function:168]: Tested '${FIELDQTY(foo)}' . . . . . passed 284s [test_substitution.c:test_chan_function:168]: Tested '${HASHKEYS(foo)}' . . . . . passed 284s [test_substitution.c:test_chan_function:168]: Tested '${IMPORT(foo)}' . . . . . passed 284s [test_substitution.c:test_chan_function:168]: Tested '${PP_EACH_USER(foo)}' . . . . . passed 284s [test_substitution.c:test_chan_function:168]: Tested '${TOLOWER(foo)}' . . . . . passed 284s [test_substitution.c:test_chan_function:168]: Tested '${TOUPPER(foo)}' . . . . . passed 284s END /main/pbx/ - test_substitution Time: 13ms Result: PASS 284s START /main/pbx/ - pattern_match_test 284s [test_pbx.c:test_exten:183]: Successfully matched 200 to exten _2. in context test_pattern with the old pattern match engine 284s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the old pattern match engine 284s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the old pattern match engine 284s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern_include with the old pattern match engine 284s [test_pbx.c:test_exten:183]: Successfully matched 200 to exten _2. in context test_pattern with the new pattern match engine 284s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the new pattern match engine 284s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the new pattern match engine 284s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern_include with the new pattern match engine 284s END /main/pbx/ - pattern_match_test Time: <1ms Result: PASS 284s START /main/pbx/ - test_MATH_function 284s [func_math.c:test_MATH_function:682]: Testing MATH() substitution ... 284s END /main/pbx/ - test_MATH_function Time: <1ms Result: PASS 284s START /main/pbx/ - variable_substrings 284s END /main/pbx/ - variable_substrings Time: <1ms Result: PASS 284s START /main/poll/ - poll_test 284s [test_poll.c:poll_test:95]: Creating handle that should NEVER block on write 284s [test_poll.c:poll_test:101]: Creating handle that should NEVER block on read 284s [test_poll.c:poll_test:108]: Creating handle that should block on read 284s [test_poll.c:poll_test:168]: Starting thread to ensure we don't block forever 284s [test_poll.c:poll_test:194]: Cancelling failsafe thread. 284s END /main/poll/ - poll_test Time: <1ms Result: PASS 284s START /main/presence/ - channel_presence 284s END /main/presence/ - channel_presence Time: <1ms Result: PASS 284s START /main/sample/ - sample_test 284s [test_skel.c:sample_test:93]: Test argument: 0: test 284s [test_skel.c:sample_test:93]: Test argument: 1: execute 284s [test_skel.c:sample_test:93]: Test argument: 2: all 284s [test_skel.c:sample_test:102]: Executing sample test with test-option=999 and test-option2= 284s END /main/sample/ - sample_test Time: <1ms Result: PASS 284s START /main/sched/ - sched_test_freebird 284s [test_sched.c:sched_test_freebird:440]: Received signal, calling Scedule and UNREF 284s [test_sched.c:sched_test_freebird:441]: ID: 1 287s [test_sched.c:sched_test_freebird:448]: Correct number of references '2' 287s END /main/sched/ - sched_test_freebird Time: 3000ms Result: PASS 287s START /main/sched/ - sched_test_order 287s END /main/sched/ - sched_test_order Time: 400ms Result: PASS 287s START /main/sorcery/ - wizard_read_only 287s END /main/sorcery/ - wizard_read_only Time: <1ms Result: PASS 287s START /main/sorcery/ - wizard_observation 287s END /main/sorcery/ - wizard_observation Time: <1ms Result: PASS 287s START /main/sorcery/ - instance_observation 287s END /main/sorcery/ - instance_observation Time: <1ms Result: PASS 287s START /main/sorcery/ - global_observation 287s END /main/sorcery/ - global_observation Time: <1ms Result: PASS 287s START /main/sorcery/ - object_field_registered 287s END /main/sorcery/ - object_field_registered Time: <1ms Result: PASS 287s START /main/sorcery/ - dialplan_function 287s END /main/sorcery/ - dialplan_function Time: <1ms Result: PASS 287s START /main/sorcery/ - configuration_file_wizard_retrieve_multiple_all 287s END /main/sorcery/ - configuration_file_wizard_retrieve_multiple_all Time: <1ms Result: PASS 287s START /main/sorcery/ - configuration_file_wizard_retrieve_multiple 287s END /main/sorcery/ - configuration_file_wizard_retrieve_multiple Time: <1ms Result: PASS 287s START /main/sorcery/ - configuration_file_wizard_retrieve_field 287s END /main/sorcery/ - configuration_file_wizard_retrieve_field Time: <1ms Result: PASS 287s START /main/sorcery/ - configuration_file_wizard_with_criteria 287s END /main/sorcery/ - configuration_file_wizard_with_criteria Time: <1ms Result: PASS 287s START /main/sorcery/ - configuration_file_wizard_with_file_integrity 287s END /main/sorcery/ - configuration_file_wizard_with_file_integrity Time: <1ms Result: PASS 287s START /main/sorcery/ - configuration_file_wizard 287s END /main/sorcery/ - configuration_file_wizard Time: <1ms Result: PASS 287s START /main/sorcery/ - object_type_observer 287s END /main/sorcery/ - object_type_observer Time: <1ms Result: PASS 287s START /main/sorcery/ - caching_wizard_behavior 287s END /main/sorcery/ - caching_wizard_behavior Time: <1ms Result: PASS 287s START /main/sorcery/ - object_is_stale 287s END /main/sorcery/ - object_is_stale Time: <1ms Result: PASS 287s START /main/sorcery/ - object_delete_uncreated 287s END /main/sorcery/ - object_delete_uncreated Time: <1ms Result: PASS 287s START /main/sorcery/ - object_delete 287s END /main/sorcery/ - object_delete Time: <1ms Result: PASS 287s START /main/sorcery/ - object_update_uncreated 287s END /main/sorcery/ - object_update_uncreated Time: <1ms Result: PASS 287s START /main/sorcery/ - object_update 287s END /main/sorcery/ - object_update Time: <1ms Result: PASS 287s START /main/sorcery/ - object_retrieve_regex 287s END /main/sorcery/ - object_retrieve_regex Time: <1ms Result: PASS 287s START /main/sorcery/ - object_retrieve_multiple_field 287s END /main/sorcery/ - object_retrieve_multiple_field Time: <1ms Result: PASS 287s START /main/sorcery/ - object_retrieve_multiple_all 287s END /main/sorcery/ - object_retrieve_multiple_all Time: <1ms Result: PASS 287s START /main/sorcery/ - object_retrieve_field 287s END /main/sorcery/ - object_retrieve_field Time: <1ms Result: PASS 287s START /main/sorcery/ - object_retrieve_id 287s END /main/sorcery/ - object_retrieve_id Time: <1ms Result: PASS 287s START /main/sorcery/ - object_create 287s END /main/sorcery/ - object_create Time: <1ms Result: PASS 287s START /main/sorcery/ - changeset_create_unchanged 287s END /main/sorcery/ - changeset_create_unchanged Time: <1ms Result: PASS 287s START /main/sorcery/ - changeset_create 287s END /main/sorcery/ - changeset_create Time: <1ms Result: PASS 287s START /main/sorcery/ - extended_fields 287s END /main/sorcery/ - extended_fields Time: <1ms Result: PASS 287s START /main/sorcery/ - objectset_apply_fields 287s END /main/sorcery/ - objectset_apply_fields Time: <1ms Result: PASS 287s START /main/sorcery/ - objectset_transform 287s END /main/sorcery/ - objectset_transform Time: <1ms Result: PASS 287s START /main/sorcery/ - objectset_apply_invalid 287s END /main/sorcery/ - objectset_apply_invalid Time: <1ms Result: PASS 287s START /main/sorcery/ - objectset_apply_handler 287s END /main/sorcery/ - objectset_apply_handler Time: <1ms Result: PASS 287s START /main/sorcery/ - objectset_apply 287s END /main/sorcery/ - objectset_apply Time: <1ms Result: PASS 287s START /main/sorcery/ - objectset_create_regex 287s END /main/sorcery/ - objectset_create_regex Time: <1ms Result: PASS 287s START /main/sorcery/ - objectset_json_create 287s END /main/sorcery/ - objectset_json_create Time: <1ms Result: PASS 287s START /main/sorcery/ - objectset_create 287s END /main/sorcery/ - objectset_create Time: <1ms Result: PASS 287s START /main/sorcery/ - object_diff_native 287s END /main/sorcery/ - object_diff_native Time: <1ms Result: PASS 287s START /main/sorcery/ - object_diff 287s END /main/sorcery/ - object_diff Time: <1ms Result: PASS 287s START /main/sorcery/ - object_copy_native 287s END /main/sorcery/ - object_copy_native Time: <1ms Result: PASS 287s START /main/sorcery/ - object_copy 287s END /main/sorcery/ - object_copy Time: <1ms Result: PASS 287s START /main/sorcery/ - object_alloc_without_id 287s END /main/sorcery/ - object_alloc_without_id Time: <1ms Result: PASS 287s START /main/sorcery/ - object_alloc_with_id 287s END /main/sorcery/ - object_alloc_with_id Time: <1ms Result: PASS 287s START /main/sorcery/ - object_fields_register 287s END /main/sorcery/ - object_fields_register Time: <1ms Result: PASS 287s START /main/sorcery/ - object_field_register 287s END /main/sorcery/ - object_field_register Time: <1ms Result: PASS 287s START /main/sorcery/ - object_register_without_mapping 287s END /main/sorcery/ - object_register_without_mapping Time: <1ms Result: PASS 287s START /main/sorcery/ - object_register 287s END /main/sorcery/ - object_register Time: <1ms Result: PASS 287s START /main/sorcery/ - apply_config 287s END /main/sorcery/ - apply_config Time: <1ms Result: PASS 287s START /main/sorcery/ - apply_default 287s END /main/sorcery/ - apply_default Time: <1ms Result: PASS 287s START /main/sorcery/ - open 287s END /main/sorcery/ - open Time: <1ms Result: PASS 287s START /main/sorcery/ - wizard_registration 287s END /main/sorcery/ - wizard_registration Time: <1ms Result: PASS 287s START /main/sorcery/ - wizard_apply_and_insert 287s END /main/sorcery/ - wizard_apply_and_insert Time: <1ms Result: PASS 287s START /main/stdtime/ - time_create_by_unit_str 287s END /main/stdtime/ - time_create_by_unit_str Time: <1ms Result: PASS 287s START /main/stdtime/ - time_create_by_unit 287s END /main/stdtime/ - time_create_by_unit Time: <1ms Result: PASS 287s START /main/stdtime/ - time_str_to_unit 287s END /main/stdtime/ - time_str_to_unit Time: <1ms Result: PASS 287s START /main/stdtime/ - time_tv_to_usec 287s END /main/stdtime/ - time_tv_to_usec Time: <1ms Result: PASS 287s START /main/stdtime/ - timezone_watch 287s [test_time.c:test_timezone_watch:82]: Executing deletion test... 287s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.GNZD1n/test 288s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.GNZD1n/test 288s [test_time.c:test_timezone_watch:82]: Executing symlink test... 288s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.GNZD1n/test 289s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.GNZD1n/test 289s END /main/stdtime/ - timezone_watch Time: 2272ms Result: PASS 289s START /main/stream/ - stream_topology_map_create 289s END /main/stream/ - stream_topology_map_create Time: <1ms Result: PASS 289s START /main/stream/ - format_cap_from_stream_topology 289s END /main/stream/ - format_cap_from_stream_topology Time: <1ms Result: PASS 289s START /main/stream/ - stream_topology_change_request_from_channel 289s END /main/stream/ - stream_topology_change_request_from_channel Time: <1ms Result: PASS 289s START /main/stream/ - stream_topology_change_request_from_application 289s END /main/stream/ - stream_topology_change_request_from_application Time: <1ms Result: PASS 289s START /main/stream/ - stream_topology_change_request_from_channel_non_multistream 289s END /main/stream/ - stream_topology_change_request_from_channel_non_multistream Time: <1ms Result: PASS 289s START /main/stream/ - stream_topology_change_request_from_application_non_multistream 289s END /main/stream/ - stream_topology_change_request_from_application_non_multistream Time: <1ms Result: PASS 289s START /main/stream/ - stream_read_multistream 289s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 289s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 289s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 289s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 290s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 4 Frames: 16 Frames per read: 1 Expected Nulls: 8 290s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 8 290s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 4 Frames: 16 Frames per read: 1 Expected Nulls: 0 290s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 290s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 290s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 290s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 290s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 290s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 4 Frames: 16 Frames per read: 3 Expected Nulls: 8 290s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 8 290s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 4 Frames: 16 Frames per read: 3 Expected Nulls: 0 290s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 290s END /main/stream/ - stream_read_multistream Time: <1ms Result: PASS 290s START /main/stream/ - stream_read_non_multistream 290s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 290s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 290s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 290s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 290s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 290s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 290s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 290s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 290s END /main/stream/ - stream_read_non_multistream Time: <1ms Result: PASS 290s START /main/stream/ - stream_write_multistream 290s END /main/stream/ - stream_write_multistream Time: <1ms Result: PASS 290s START /main/stream/ - stream_write_non_multistream 290s END /main/stream/ - stream_write_non_multistream Time: <1ms Result: PASS 290s START /main/stream/ - stream_topology_channel_set 290s END /main/stream/ - stream_topology_channel_set Time: <1ms Result: PASS 290s START /main/stream/ - stream_topology_create_from_channel_nativeformats 290s END /main/stream/ - stream_topology_create_from_channel_nativeformats Time: <1ms Result: PASS 290s START /main/stream/ - stream_topology_get_first_stream_by_type 290s END /main/stream/ - stream_topology_get_first_stream_by_type Time: <1ms Result: PASS 290s START /main/stream/ - stream_topology_create_from_format_cap 290s END /main/stream/ - stream_topology_create_from_format_cap Time: <1ms Result: PASS 290s START /main/stream/ - stream_topology_del_stream 290s END /main/stream/ - stream_topology_del_stream Time: <1ms Result: PASS 290s START /main/stream/ - stream_topology_set_stream 290s END /main/stream/ - stream_topology_set_stream Time: <1ms Result: PASS 290s START /main/stream/ - stream_topology_append_stream 290s END /main/stream/ - stream_topology_append_stream Time: <1ms Result: PASS 290s START /main/stream/ - stream_topology_clone 290s END /main/stream/ - stream_topology_clone Time: <1ms Result: PASS 290s START /main/stream/ - stream_topology_create 290s END /main/stream/ - stream_topology_create Time: <1ms Result: PASS 290s START /main/stream/ - stream_metadata 290s END /main/stream/ - stream_metadata Time: <1ms Result: PASS 290s START /main/stream/ - stream_set_state 290s END /main/stream/ - stream_set_state Time: <1ms Result: PASS 290s START /main/stream/ - stream_set_formats 290s END /main/stream/ - stream_set_formats Time: <1ms Result: PASS 290s START /main/stream/ - stream_set_type 290s END /main/stream/ - stream_set_type Time: <1ms Result: PASS 290s START /main/stream/ - stream_create_no_name 290s END /main/stream/ - stream_create_no_name Time: <1ms Result: PASS 290s START /main/stream/ - stream_create 290s END /main/stream/ - stream_create Time: <1ms Result: PASS 290s START /main/strings/ - in_delimited_string 290s END /main/strings/ - in_delimited_string Time: <1ms Result: PASS 290s START /main/strings/ - temp_strings 290s END /main/strings/ - temp_strings Time: <1ms Result: PASS 290s START /main/strings/ - strings_match 290s END /main/strings/ - strings_match Time: <1ms Result: PASS 290s START /main/strings/ - escape 290s END /main/strings/ - escape Time: <1ms Result: PASS 290s START /main/strings/ - escape_semicolons 290s END /main/strings/ - escape_semicolons Time: <1ms Result: PASS 290s START /main/strings/ - strsep_quoted 290s END /main/strings/ - strsep_quoted Time: <1ms Result: PASS 290s START /main/strings/ - strsep 290s END /main/strings/ - strsep Time: <1ms Result: PASS 290s START /main/strings/ - ends_with 290s END /main/strings/ - ends_with Time: <1ms Result: PASS 290s START /main/strings/ - begins_with 290s END /main/strings/ - begins_with Time: <1ms Result: PASS 290s START /main/strings/ - str_test 290s END /main/strings/ - str_test Time: <1ms Result: PASS 290s START /main/taskprocessor/ - serializer_pool 293s END /main/taskprocessor/ - serializer_pool Time: 4000ms Result: PASS 293s START /main/taskprocessor/ - taskprocessor_push_local 293s END /main/taskprocessor/ - taskprocessor_push_local Time: <1ms Result: PASS 293s START /main/taskprocessor/ - taskprocessor_shutdown 293s END /main/taskprocessor/ - taskprocessor_shutdown Time: <1ms Result: PASS 293s START /main/taskprocessor/ - taskprocessor_listener 293s END /main/taskprocessor/ - taskprocessor_listener Time: <1ms Result: PASS 293s START /main/taskprocessor/ - subsystem_alert 293s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 1 293s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 2 293s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 3 293s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 4 293s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 5 293s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 6 293s [test_taskprocessor.c:subsystem_alert:237]: Subsystem alert triggered correctly at 6 293s [test_taskprocessor.c:subsystem_alert:240]: Global alert triggered correctly at 6 293s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 7 293s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 8 293s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 9 293s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 10 293s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 1 294s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 2 294s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 3 295s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 4 296s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 5 296s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 6 296s [test_taskprocessor.c:subsystem_alert:279]: Subsystem alert cleared correctly at 3 296s [test_taskprocessor.c:subsystem_alert:282]: Global alert cleared correctly at 3 296s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 7 297s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 8 297s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 9 298s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 10 298s END /main/taskprocessor/ - subsystem_alert Time: 5002ms Result: PASS 298s START /main/taskprocessor/ - default_taskprocessor_load 299s END /main/taskprocessor/ - default_taskprocessor_load Time: 70ms Result: PASS 299s START /main/taskprocessor/ - default_taskprocessor 299s END /main/taskprocessor/ - default_taskprocessor Time: <1ms Result: PASS 299s START /main/test/ - registrations 299s END /main/test/ - registrations Time: <1ms Result: PASS 299s START /main/test_capture/ - test_capture_false 299s [test_capture.c:test_capture_false:120]: Executing false exit test... 299s END /main/test_capture/ - test_capture_false Time: 23ms Result: PASS 299s START /main/test_capture/ - test_capture_true 299s [test_capture.c:test_capture_true:61]: Executing true exit test... 299s END /main/test_capture/ - test_capture_true Time: 15ms Result: PASS 299s START /main/test_capture/ - test_capture_stdout_stderr 299s [test_capture.c:test_capture_stdout_stderr:318]: Executing stdout/stderr test... 299s END /main/test_capture/ - test_capture_stdout_stderr Time: 21ms Result: PASS 299s START /main/test_capture/ - test_capture_with_dynamic 299s [test_capture.c:test_capture_with_dynamic:249]: Executing dynamic argument test... 299s END /main/test_capture/ - test_capture_with_dynamic Time: 11ms Result: PASS 299s START /main/test_capture/ - test_capture_with_stdin 299s [test_capture.c:test_capture_with_stdin:183]: Executing stdin test... 299s END /main/test_capture/ - test_capture_with_stdin Time: 11ms Result: PASS 299s START /main/threadpool/ - threadpool_serializer_dupe 299s END /main/threadpool/ - threadpool_serializer_dupe Time: <1ms Result: PASS 299s START /main/threadpool/ - threadpool_serializer 300s END /main/threadpool/ - threadpool_serializer Time: 1000ms Result: PASS 300s START /main/threadpool/ - more_destruction 300s END /main/threadpool/ - more_destruction Time: <1ms Result: PASS 300s START /main/threadpool/ - task_distribution 300s END /main/threadpool/ - task_distribution Time: <1ms Result: PASS 300s START /main/threadpool/ - reactivation 300s END /main/threadpool/ - reactivation Time: <1ms Result: PASS 300s START /main/threadpool/ - max_size 300s END /main/threadpool/ - max_size Time: <1ms Result: PASS 300s START /main/threadpool/ - auto_increment 300s END /main/threadpool/ - auto_increment Time: <1ms Result: PASS 300s START /main/threadpool/ - one_thread_multiple_tasks 300s END /main/threadpool/ - one_thread_multiple_tasks Time: <1ms Result: PASS 300s START /main/threadpool/ - one_thread_one_task 300s END /main/threadpool/ - one_thread_one_task Time: <1ms Result: PASS 300s START /main/threadpool/ - one_task_one_thread 300s END /main/threadpool/ - one_task_one_thread Time: <1ms Result: PASS 300s START /main/threadpool/ - thread_timeout_thrash 331s END /main/threadpool/ - thread_timeout_thrash Time: 31013ms Result: PASS 331s START /main/threadpool/ - thread_timeout 333s END /main/threadpool/ - thread_timeout Time: 2000ms Result: PASS 333s START /main/threadpool/ - thread_destruction 333s END /main/threadpool/ - thread_destruction Time: <1ms Result: PASS 333s START /main/threadpool/ - thread_creation 333s END /main/threadpool/ - thread_creation Time: <1ms Result: PASS 333s START /main/threadpool/ - initial_threads 333s END /main/threadpool/ - initial_threads Time: <1ms Result: PASS 333s START /main/threadpool/ - push 333s END /main/threadpool/ - push Time: <1ms Result: PASS 333s START /main/uri/ - uri_default_http_secure 333s END /main/uri/ - uri_default_http_secure Time: <1ms Result: PASS 333s START /main/uri/ - uri_default_http 333s END /main/uri/ - uri_default_http Time: <1ms Result: PASS 333s START /main/uri/ - uri_parse 333s END /main/uri/ - uri_parse Time: <1ms Result: PASS 333s START /main/utf8/ - replace_invalid 333s END /main/utf8/ - replace_invalid Time: <1ms Result: PASS 333s START /main/utf8/ - utf8_validator 333s END /main/utf8/ - utf8_validator Time: <1ms Result: PASS 333s START /main/utf8/ - copy_string 333s END /main/utf8/ - copy_string Time: <1ms Result: PASS 333s START /main/utf8/ - is_valid 333s END /main/utf8/ - is_valid Time: <1ms Result: PASS 333s START /main/utils/ - string_field_aggregate_test 333s [test_stringfields.c:string_field_aggregate_test:392]: Structures 3 embedded pool initialized successfully. 333s [test_stringfields.c:string_field_aggregate_test:410]: Structures 3 additional pool initialized successfully. 333s [test_stringfields.c:string_field_aggregate_test:422]: Structures 1/2 are equal as expected. 333s [test_stringfields.c:string_field_aggregate_test:430]: Structures 1/3 are different as expected. 333s [test_stringfields.c:string_field_aggregate_test:438]: Structures 2/3 are different as expected. 333s [test_stringfields.c:string_field_aggregate_test:446]: Structures 3/4 are different as expected. 333s [test_stringfields.c:string_field_aggregate_test:454]: Copying from structure 3 to structure 1 succeeded! 333s [test_stringfields.c:string_field_aggregate_test:463]: Structures 1/3 are equal as expected. 333s [test_stringfields.c:string_field_aggregate_test:470]: Structures 1/2 are different as expected. 333s [test_stringfields.c:string_field_aggregate_test:473]: Reset but don't free. 333s [test_stringfields.c:string_field_aggregate_test:484]: Structures 1/2 are the same (empty) as expected. 333s [test_stringfields.c:string_field_aggregate_test:492]: Structure 4 embedded pool is the current pool as expected. 333s [test_stringfields.c:string_field_aggregate_test:500]: Structure 4 embedded pool does not have a previous as expected. 333s END /main/utils/ - string_field_aggregate_test Time: <1ms Result: PASS 333s START /main/utils/ - string_field_test 333s [test_stringfields.c:string_field_test:79]: First things first. Let's see if we can actually allocate string fields 333s [test_stringfields.c:string_field_test:85]: All right! Successfully allocated! Now let's get down to business 333s [test_stringfields.c:string_field_test:89]: We're going to set some string fields and perform some checks 333s [test_stringfields.c:string_field_test:94]: First we're going to make sure that the strings are actually set to what we expect 333s [test_stringfields.c:string_field_test:100]: test_struct.string1 appears to be all clear. It has 'elephant' and that's what we expect 333s [test_stringfields.c:string_field_test:107]: test_struct.string2 appears to be all clear. It has 'hippopotamus' and that's what we expect 333s [test_stringfields.c:string_field_test:110]: Now let's make sure that our recorded capacities for these strings is what we expect 333s [test_stringfields.c:string_field_test:117]: string1 has the allocation area we expect: 9 333s [test_stringfields.c:string_field_test:125]: string2 has the allocation area we expect: 13 333s [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 333s [test_stringfields.c:string_field_test:137]: string1 successfully was changed to 'rhino' 333s [test_stringfields.c:string_field_test:144]: Shrinking string1 allowed it to stay in the same place in memory 333s [test_stringfields.c:string_field_test:151]: Shrinking string1 did not change its allocation area (This is a good thing) 333s [test_stringfields.c:string_field_test:154]: Next, let's increase it a little but not all the way to its original size 333s [test_stringfields.c:string_field_test:163]: string1 successfully was changed to 'mammoth' 333s [test_stringfields.c:string_field_test:170]: Expanding string1 allowed it to stay in the same place in memory 333s [test_stringfields.c:string_field_test:177]: Expanding string1 did not change its allocation area (This is a good thing) 333s [test_stringfields.c:string_field_test:180]: Cool, now let's bring it back to its original size and see what happens 333s [test_stringfields.c:string_field_test:188]: string1 successfully changed to 'elephant' 333s [test_stringfields.c:string_field_test:195]: Restoring string1 did not cause it to move (This is a good thing) 333s [test_stringfields.c:string_field_test:202]: The allocation amount for string1 is still holding steady 333s [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 333s [test_stringfields.c:string_field_test:214]: string2 successfully changed to 'hippopotamus face' 333s [test_stringfields.c:string_field_test:222]: The allocation amount successfully increased for string2 when it grew 333s [test_stringfields.c:string_field_test:229]: string2 stayed in place when it grew. Good job! 333s [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 333s [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' 333s [test_stringfields.c:string_field_test:248]: Good. Setting string1 to a long value caused it to change addresses 333s [test_stringfields.c:string_field_test:256]: The stored allocation size of string1 is what we expect 333s [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 333s [test_stringfields.c:string_field_test:281]: Three different pools are linked as expected. 333s [test_stringfields.c:string_field_test:289]: After removing a pool the remaining two are linked as expected. 333s END /main/utils/ - string_field_test Time: <1ms Result: PASS 333s START /main/utils/ - quote_unescaping 333s END /main/utils/ - quote_unescaping Time: <1ms Result: PASS 333s START /main/utils/ - quote_mutation 333s END /main/utils/ - quote_mutation Time: <1ms Result: PASS 333s START /main/utils/ - crypt_test 333s END /main/utils/ - crypt_test Time: 10ms Result: PASS 333s START /main/utils/ - safe_mkdir_test 333s END /main/utils/ - safe_mkdir_test Time: <1ms Result: PASS 333s START /main/utils/ - base64_test 333s END /main/utils/ - base64_test Time: <1ms Result: PASS 333s START /main/utils/ - sha1_test 333s [test_utils.c:sha1_test:250]: Testing SHA1 ... 333s END /main/utils/ - sha1_test Time: <1ms Result: PASS 333s START /main/utils/ - md5_test 333s [test_utils.c:md5_test:205]: Testing MD5 ... 333s END /main/utils/ - md5_test Time: <1ms Result: PASS 333s START /main/utils/ - quoted_escape_test 333s END /main/utils/ - quoted_escape_test Time: <1ms Result: PASS 333s START /main/utils/ - uri_encode_decode_test 333s END /main/utils/ - uri_encode_decode_test Time: <1ms Result: PASS 333s START /main/uuid/ - uuid 333s [test_uuid.c:uuid:59]: Generate UUID direct to string, got 9ac1717c-10b9-4f7d-999c-da76531dd1cd 333s [test_uuid.c:uuid:90]: Second generated UUID converted to string, got e3ef1199-f4a1-4e16-afbb-4254994a745c 333s END /main/uuid/ - uuid Time: <1ms Result: PASS 333s START /main/vector/ - basic 333s END /main/vector/ - basic Time: <1ms Result: PASS 333s START /main/vector/ - basic_integer 333s END /main/vector/ - basic_integer Time: <1ms Result: PASS 333s START /main/vector/ - callbacks 333s END /main/vector/ - callbacks Time: <1ms Result: PASS 333s START /main/vector/ - locks 333s END /main/vector/ - locks Time: <1ms Result: PASS 333s START /main/voicemail_api/ - off_nominal_msg_playback 333s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1493]: Created message in test_vm_api_1234/Old with ID 1746391178-909401725 333s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1493]: Created message in test_vm_api_1234/INBOX with ID 1746391178-960311778 333s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1493]: Created message in test_vm_api_2345/INBOX with ID 1746391178-1500739833 333s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1493]: Created message in test_vm_api_2345/INBOX with ID 1746391178-719848782 333s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1502]: Playing back message from invalid mailbox 333s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1505]: Playing back message from NULL mailbox 333s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1508]: Playing back message from invalid context 333s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1511]: Playing back message from invalid folder 333s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1514]: Playing back message from NULL folder 333s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1517]: Playing back message with invalid message specifier 333s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1520]: Playing back message with NULL message specifier 333s END /main/voicemail_api/ - off_nominal_msg_playback Time: 6ms Result: PASS 333s START /main/voicemail_api/ - nominal_msg_playback 333s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1431]: Created message in test_vm_api_1234/Old with ID 1746391178-909401725 333s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1431]: Created message in test_vm_api_1234/INBOX with ID 1746391178-960311778 333s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1431]: Created message in test_vm_api_2345/INBOX with ID 1746391178-1500739833 333s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1431]: Created message in test_vm_api_2345/INBOX with ID 1746391178-719848782 333s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1443]: Playing back message from test_vm_api_1234 to mock channel 333s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1446]: Playing back message from test_vm_api_2345 to callback function 333s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1451]: Playing back message from test_vm_api_2345 to callback function with default context 333s END /main/voicemail_api/ - nominal_msg_playback Time: 450ms Result: PASS 333s START /main/voicemail_api/ - off_nominal_forward 333s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1353]: Created message in test_vm_api_1234/Old with ID 1746391178-909401725 333s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1353]: Created message in test_vm_api_1234/INBOX with ID 1746391178-960311778 333s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1353]: Created message in test_vm_api_2345/INBOX with ID 1746391178-1500739833 333s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1353]: Created message in test_vm_api_2345/INBOX with ID 1746391178-719848782 333s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1362]: Test forwarding from an invalid mailbox 333s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1365]: Test forwarding from a NULL mailbox 333s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1368]: Test forwarding from an invalid context 333s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1371]: Test forwarding from an invalid folder 333s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1374]: Test forwarding from a NULL folder 333s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1377]: Test forwarding to an invalid mailbox 333s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1380]: Test forwarding to a NULL mailbox 333s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1383]: Test forwarding to an invalid context 333s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1386]: Test forwarding to an invalid folder 333s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1390]: Test forwarding to a NULL folder 333s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1393]: Test forwarding when no messages are select 333s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1396]: Test forwarding a message that doesn't exist 333s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1400]: Test forwarding multiple messages, where some messages don't exist 333s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1403]: Test forwarding a message with an invalid size specifier 333s END /main/voicemail_api/ - off_nominal_forward Time: 6ms Result: PASS 333s START /main/voicemail_api/ - nominal_forward 333s [test_voicemail_api.c:voicemail_api_nominal_forward:1237]: Created message in test_vm_api_1234/Old with ID 1746391178-909401725 333s [test_voicemail_api.c:voicemail_api_nominal_forward:1237]: Created message in test_vm_api_1234/INBOX with ID 1746391178-960311778 333s [test_voicemail_api.c:voicemail_api_nominal_forward:1237]: Created message in test_vm_api_2345/INBOX with ID 1746391178-1500739833 333s [test_voicemail_api.c:voicemail_api_nominal_forward:1237]: Created message in test_vm_api_2345/INBOX with ID 1746391178-719848782 333s [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 333s [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 333s [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 333s [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 333s [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 333s END /main/voicemail_api/ - nominal_forward Time: 18ms Result: PASS 333s START /main/voicemail_api/ - off_nominal_remove 333s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1178]: Created message in test_vm_api_1234/Old with ID 1746391178-909401725 333s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1178]: Created message in test_vm_api_1234/INBOX with ID 1746391178-960311778 333s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1178]: Created message in test_vm_api_2345/INBOX with ID 1746391178-1500739833 333s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1178]: Created message in test_vm_api_2345/INBOX with ID 1746391178-719848782 333s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1184]: Test removing a single message with an invalid mailbox 333s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1187]: Test removing a single message with a NULL mailbox 333s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1190]: Test removing a single message with an invalid context 333s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1193]: Test removing a single message with an invalid folder 333s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1196]: Test removing a single message with a NULL folder 333s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1199]: Test removing a single message with an invalid message number 333s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1203]: Test removing multiple messages with a single invalid message number 333s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1207]: Test removing no messages with no message numbers 333s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1210]: Test removing multiple messages with an invalid size specifier 333s END /main/voicemail_api/ - off_nominal_remove Time: 6ms Result: PASS 333s START /main/voicemail_api/ - nominal_remove 333s [test_voicemail_api.c:voicemail_api_nominal_remove:1131]: Created message in test_vm_api_1234/Old with ID 1746391178-909401725 333s [test_voicemail_api.c:voicemail_api_nominal_remove:1131]: Created message in test_vm_api_1234/INBOX with ID 1746391178-960311778 333s [test_voicemail_api.c:voicemail_api_nominal_remove:1131]: Created message in test_vm_api_2345/INBOX with ID 1746391178-1500739833 333s [test_voicemail_api.c:voicemail_api_nominal_remove:1131]: Created message in test_vm_api_2345/INBOX with ID 1746391178-719848782 333s [test_voicemail_api.c:voicemail_api_nominal_remove:1139]: Test removing a single message from INBOX 333s [test_voicemail_api.c:voicemail_api_nominal_remove:1142]: Test removing a single message from Old 333s [test_voicemail_api.c:voicemail_api_nominal_remove:1145]: Test removing multiple messages from INBOX 333s END /main/voicemail_api/ - nominal_remove Time: 6ms Result: PASS 333s START /main/voicemail_api/ - off_nominal_move 333s [test_voicemail_api.c:voicemail_api_off_nominal_move:1059]: Created message in test_vm_api_1234/Old with ID 1746391178-909401725 333s [test_voicemail_api.c:voicemail_api_off_nominal_move:1059]: Created message in test_vm_api_1234/INBOX with ID 1746391178-960311778 333s [test_voicemail_api.c:voicemail_api_off_nominal_move:1059]: Created message in test_vm_api_2345/INBOX with ID 1746391178-1500739833 333s [test_voicemail_api.c:voicemail_api_off_nominal_move:1059]: Created message in test_vm_api_2345/INBOX with ID 1746391178-719848782 333s [test_voicemail_api.c:voicemail_api_off_nominal_move:1068]: Test move attempt for invalid mailbox test_vm_3456 333s [test_voicemail_api.c:voicemail_api_off_nominal_move:1073]: Test move attempt for invalid context test_vm_api_defunct 333s [test_voicemail_api.c:voicemail_api_off_nominal_move:1076]: Test move attempt to invalid folder 333s [test_voicemail_api.c:voicemail_api_off_nominal_move:1079]: Test move attempt from invalid folder 333s [test_voicemail_api.c:voicemail_api_off_nominal_move:1082]: Test move attempt to NULL folder 333s [test_voicemail_api.c:voicemail_api_off_nominal_move:1085]: Test move attempt from NULL folder 333s [test_voicemail_api.c:voicemail_api_off_nominal_move:1088]: Test move attempt with non-existent message number 333s [test_voicemail_api.c:voicemail_api_off_nominal_move:1092]: Test move attempt with invalid message number 333s [test_voicemail_api.c:voicemail_api_off_nominal_move:1096]: Test move attempt with 0 number of messages 333s [test_voicemail_api.c:voicemail_api_off_nominal_move:1100]: Test move attempt with invalid number of messages 333s [test_voicemail_api.c:voicemail_api_off_nominal_move:1103]: Test move attempt with non-existent multiple messages, where some messages exist 333s END /main/voicemail_api/ - off_nominal_move Time: 6ms Result: PASS 333s START /main/voicemail_api/ - nominal_move 333s [test_voicemail_api.c:voicemail_api_nominal_move:985]: Created message in test_vm_api_1234/Old with ID 1746391178-909401725 333s [test_voicemail_api.c:voicemail_api_nominal_move:985]: Created message in test_vm_api_1234/INBOX with ID 1746391178-960311778 333s [test_voicemail_api.c:voicemail_api_nominal_move:985]: Created message in test_vm_api_2345/INBOX with ID 1746391178-1500739833 333s [test_voicemail_api.c:voicemail_api_nominal_move:985]: Created message in test_vm_api_2345/INBOX with ID 1746391178-719848782 333s [test_voicemail_api.c:voicemail_api_nominal_move:992]: Test move of test_vm_api_1234 message from INBOX to Family 333s [test_voicemail_api.c:voicemail_api_nominal_move:995]: Test move of test_vm_api_1234 message from Old to Family 333s [test_voicemail_api.c:voicemail_api_nominal_move:1009]: Test move of test_vm_api_2345 messages from Inbox to Family 333s [test_voicemail_api.c:voicemail_api_nominal_move:1020]: Test move of test_vm_api_2345 message from Family to INBOX 333s END /main/voicemail_api/ - nominal_move Time: 9ms Result: PASS 333s START /main/voicemail_api/ - off_nominal_snapshot 333s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:945]: Created message in test_vm_api_1234/Old with ID 1746391178-909401725 333s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:945]: Created message in test_vm_api_1234/INBOX with ID 1746391178-960311778 333s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:945]: Created message in test_vm_api_2345/INBOX with ID 1746391178-1500739833 333s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:945]: Created message in test_vm_api_2345/INBOX with ID 1746391178-719848782 333s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:947]: Test access to non-existent mailbox test_vm_api_3456 333s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:950]: Test access to null mailbox 333s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:953]: Test access non-existent context test_vm_api_defunct 333s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:956]: Test non-existent folder test_vm_api_platypus 333s END /main/voicemail_api/ - off_nominal_snapshot Time: 4ms Result: PASS 333s START /main/voicemail_api/ - nominal_snapshot 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:854]: Created message in test_vm_api_1234/Old with ID 1746391178-909401725 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:854]: Created message in test_vm_api_1234/INBOX with ID 1746391178-960311778 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:854]: Created message in test_vm_api_2345/INBOX with ID 1746391178-1500739833 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:854]: Created message in test_vm_api_2345/INBOX with ID 1746391178-719848782 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:856]: Test retrieving message 1 from INBOX of test_vm_1234 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:859]: Found message 1746391178-960311778 in snapshot 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:862]: Test retrieving message 0 from Old of test_vm_1234 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:865]: Found message 1746391178-909401725 in snapshot 333s [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 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:871]: Found message 1746391178-909401725 in snapshot 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:872]: Found message 1746391178-960311778 in snapshot 333s [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 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:878]: Found message 1746391178-960311778 in snapshot 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:879]: Found message 1746391178-909401725 in snapshot 333s [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 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:885]: Found message 1746391178-960311778 in snapshot 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:886]: Found message 1746391178-909401725 in snapshot 333s [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 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:892]: Found message 1746391178-909401725 in snapshot 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:893]: Found message 1746391178-960311778 in snapshot 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:896]: Test retrieving message 0, 1 from all folders of test_vm_1234 ordered by id 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:899]: Found message 1746391178-909401725 in snapshot 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:900]: Found message 1746391178-960311778 in snapshot 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:903]: Test retrieving message 0, 1 from all folders of test_vm_1234 ordered by time 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:906]: Found message 1746391178-909401725 in snapshot 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:907]: Found message 1746391178-960311778 in snapshot 333s [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 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:913]: Found message 1746391178-909401725 in snapshot 333s [test_voicemail_api.c:voicemail_api_nominal_snapshot:914]: Found message 1746391178-960311778 in snapshot 333s END /main/voicemail_api/ - nominal_snapshot Time: 11ms Result: PASS 333s START /main/xml_escape/ - xml_escape_test 333s END /main/xml_escape/ - xml_escape_test Time: <1ms Result: PASS 333s START /mwi/ - explicit_publish 333s END /mwi/ - explicit_publish Time: 45ms Result: PASS 333s START /mwi/ - implicit_publish 333s END /mwi/ - implicit_publish Time: 42ms Result: PASS 333s START /res/adsi/ - adsi_loaded_test 333s END /res/adsi/ - adsi_loaded_test Time: <1ms Result: PASS 333s START /res/aeap/ - send_msg_handle_request 333s END /res/aeap/ - send_msg_handle_request Time: 1ms Result: PASS 333s START /res/aeap/ - send_msg_handle_response 333s END /res/aeap/ - send_msg_handle_response Time: <1ms Result: PASS 333s START /res/aeap/ - send_msg_handle_string 335s END /res/aeap/ - send_msg_handle_string Time: 1999ms Result: PASS 335s START /res/aeap/ - create_and_connect 335s END /res/aeap/ - create_and_connect Time: <1ms Result: PASS 335s START /res/aeap/speech/ - res_speech_aeap_test 335s END /res/aeap/speech/ - res_speech_aeap_test Time: 1ms Result: PASS 335s START /res/aeap/transaction/ - transaction_exec_timeout 335s END /res/aeap/transaction/ - transaction_exec_timeout Time: 99ms Result: PASS 335s START /res/aeap/transaction/ - transaction_exec 336s END /res/aeap/transaction/ - transaction_exec Time: 1000ms Result: PASS 336s START /res/aeap/transport/ - transport_create_invalid 336s END /res/aeap/transport/ - transport_create_invalid Time: <1ms Result: PASS 336s START /res/aeap/transport/ - transport_create 336s END /res/aeap/transport/ - transport_create Time: <1ms Result: PASS 336s START /res/aeap/transport/ - transport_connect 336s END /res/aeap/transport/ - transport_connect Time: <1ms Result: PASS 336s START /res/aeap/transport/ - transport_connect_fail 336s END /res/aeap/transport/ - transport_connect_fail Time: <1ms Result: PASS 336s START /res/aeap/transport/ - transport_binary 336s END /res/aeap/transport/ - transport_binary Time: <1ms Result: PASS 336s START /res/aeap/transport/ - transport_string 336s END /res/aeap/transport/ - transport_string Time: <1ms Result: PASS 336s START /res/agi/ - agi_loaded_test 336s END /res/agi/ - agi_loaded_test Time: <1ms Result: PASS 336s START /res/agi/ - null_agi_docs 336s END /res/agi/ - null_agi_docs Time: <1ms Result: PASS 336s START /res/ari/ - invoke_not_found 336s END /res/ari/ - invoke_not_found Time: <1ms Result: PASS 336s START /res/ari/ - invoke_bad_post 336s END /res/ari/ - invoke_bad_post Time: <1ms Result: PASS 336s START /res/ari/ - invoke_post 336s END /res/ari/ - invoke_post Time: <1ms Result: PASS 336s START /res/ari/ - invoke_delete 336s END /res/ari/ - invoke_delete Time: <1ms Result: PASS 336s START /res/ari/ - invoke_wildcard 336s END /res/ari/ - invoke_wildcard Time: <1ms Result: PASS 336s START /res/ari/ - invoke_get 336s END /res/ari/ - invoke_get Time: <1ms Result: PASS 336s START /res/ari/ - get_docs_hackerz 336s END /res/ari/ - get_docs_hackerz Time: <1ms Result: PASS 336s START /res/ari/ - get_docs_notfound 336s END /res/ari/ - get_docs_notfound Time: <1ms Result: PASS 336s START /res/ari/ - get_docs_nohost 336s END /res/ari/ - get_docs_nohost Time: <1ms Result: PASS 336s START /res/ari/ - get_docs 336s END /res/ari/ - get_docs Time: <1ms Result: PASS 336s START /res/crypto/ - crypto_loaded_test 336s END /res/crypto/ - crypto_loaded_test Time: <1ms Result: PASS 336s START /res/http_media_cache/ - retrieve_content_type 336s END /res/http_media_cache/ - retrieve_content_type Time: 5ms Result: PASS 336s START /res/http_media_cache/ - retrieve_parsed_uri 336s END /res/http_media_cache/ - retrieve_parsed_uri Time: <1ms Result: PASS 336s START /res/http_media_cache/ - retrieve_cache_control_directives 336s [test_http_media_cache.c:retrieve_cache_control_directives:322]: Testing no-cache... 336s [test_http_media_cache.c:retrieve_cache_control_directives:329]: Testing no-cache with ETag... 336s [test_http_media_cache.c:retrieve_cache_control_directives:339]: Testing no-cache with max-age... 336s [test_http_media_cache.c:retrieve_cache_control_directives:344]: Checking 1746391484 >= 1746391481 and 1746391478 <= 1746391481 336s [test_http_media_cache.c:retrieve_cache_control_directives:351]: Testing must-revalidate... 336s [test_http_media_cache.c:retrieve_cache_control_directives:358]: Testing must-revalidate with ETag... 336s [test_http_media_cache.c:retrieve_cache_control_directives:368]: Testing must-revalidate with max-age... 336s [test_http_media_cache.c:retrieve_cache_control_directives:373]: Checking 1746391484 >= 1746391481 and 1746391478 <= 1746391481 336s END /res/http_media_cache/ - retrieve_cache_control_directives Time: 5ms Result: PASS 336s START /res/http_media_cache/ - retrieve_cache_control_age 336s [test_http_media_cache.c:retrieve_cache_control_age:406]: Testing max-age... 336s [test_http_media_cache.c:retrieve_cache_control_age:410]: Checking 1746391484 >= 1746391481 and 1746391478 <= 1746391481 336s [test_http_media_cache.c:retrieve_cache_control_age:414]: Testing s-maxage... 336s [test_http_media_cache.c:retrieve_cache_control_age:420]: Checking 1746391484 >= 1746391481 and 1746391478 <= 1746391481 336s [test_http_media_cache.c:retrieve_cache_control_age:424]: Testing max-age and s-maxage... 336s [test_http_media_cache.c:retrieve_cache_control_age:430]: Checking 1746391784 >= 1746391781 and 1746391778 <= 1746391781 336s [test_http_media_cache.c:retrieve_cache_control_age:434]: Testing max-age and Expires... 336s [test_http_media_cache.c:retrieve_cache_control_age:441]: Checking 1746391484 >= 1746391481 and 1746391478 <= 1746391481 336s [test_http_media_cache.c:retrieve_cache_control_age:445]: Testing s-maxage and Expires... 336s [test_http_media_cache.c:retrieve_cache_control_age:452]: Checking 1746391484 >= 1746391481 and 1746391478 <= 1746391481 336s [test_http_media_cache.c:retrieve_cache_control_age:456]: Testing s-maxage and Expires... 336s [test_http_media_cache.c:retrieve_cache_control_age:463]: Checking 1746391484 >= 1746391481 and 1746391478 <= 1746391481 336s [test_http_media_cache.c:retrieve_cache_control_age:467]: Testing max-age, s-maxage, and Expires... 336s [test_http_media_cache.c:retrieve_cache_control_age:474]: Checking 1746391784 >= 1746391781 and 1746391778 <= 1746391781 336s END /res/http_media_cache/ - retrieve_cache_control_age Time: 6ms Result: PASS 336s START /res/http_media_cache/ - retrieve_etag_expired 336s [test_http_media_cache.c:retrieve_etag_expired:514]: Checking 1746391183 >= 1746391180 and 1746391177 <= 1746391180 336s END /res/http_media_cache/ - retrieve_etag_expired Time: 1ms Result: PASS 336s START /res/http_media_cache/ - retrieve_expires 336s [test_http_media_cache.c:retrieve_expires:554]: Checking 1746394184 >= 1746394181 and 1746394178 <= 1746394181 336s [test_http_media_cache.c:retrieve_expires:564]: Checking 1746391183 >= 1746391180 and 1746391177 <= 1746391180 336s END /res/http_media_cache/ - retrieve_expires Time: 1ms Result: PASS 336s START /res/http_media_cache/ - retrieve_etag 336s [test_http_media_cache.c:retrieve_etag:604]: Checking 1746391184 >= 1746391181 and 1746391178 <= 1746391181 336s END /res/http_media_cache/ - retrieve_etag Time: 1ms Result: PASS 336s START /res/http_media_cache/ - retrieve_nominal 336s [test_http_media_cache.c:retrieve_nominal:642]: Checking 1746391184 >= 1746391181 and 1746391178 <= 1746391181 336s END /res/http_media_cache/ - retrieve_nominal Time: <1ms Result: PASS 336s START /res/http_media_cache/ - create_nominal 336s [test_http_media_cache.c:create_nominal:675]: Checking 1746391184 >= 1746391181 and 1746391178 <= 1746391181 336s END /res/http_media_cache/ - create_nominal Time: <1ms Result: PASS 336s START /res/parking/ - dynamic_parking_variables 336s [parking/parking_tests.c:dynamic_parking_variables:756]: Creating expected configuration for dynamic parking lot 336s [parking/parking_tests.c:dynamic_parking_variables:775]: Creating template lot 336s [parking/parking_tests.c:dynamic_parking_variables:784]: Creating Alice channel to test dynamic parking lot creation. 336s [parking/parking_tests.c:dynamic_parking_variables:794]: Setting Dynamic Parking channel variables on Alice. 336s [parking/parking_tests.c:dynamic_parking_variables:802]: Generating dynamic parking lot based on Alice's channel variables. 336s [parking/parking_tests.c:dynamic_parking_variables:819]: Dynamic parking lot created successfully and matches expectations. Test passed. 336s END /res/parking/ - dynamic_parking_variables Time: <1ms Result: PASS 336s START /res/parking/ - extension_conflicts 336s [parking/parking_tests.c:extension_conflicts:597]: Creating the base lot. This should pass. 336s [parking/parking_tests.c:extension_conflicts:607]: Creating a test lot which will overlap. 336s [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. 336s [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. 336s [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. 336s [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. 336s END /res/parking/ - extension_conflicts Time: <1ms Result: PASS 336s START /res/parking/ - park_extensions 336s [parking/parking_tests.c:park_extensions:551]: Extensions for the test parking lot were verified. Cleaning up and verifying their removal. 336s [parking/parking_tests.c:park_extensions:565]: Extensions for the test parking lot verified as removed. Test completed successfully. 336s END /res/parking/ - park_extensions Time: <1ms Result: PASS 336s START /res/parking/ - park_retrieve 336s [parking/parking_tests.c:retrieve_call:405]: Creating test parking lot 'unit_tests_res_parking_test_lot' 337s [parking/parking_tests.c:retrieve_call:446]: Successfully retrieved parked user from the parking lot. Validating user data. 337s END /res/parking/ - park_retrieve Time: 1001ms Result: PASS 337s START /res/parking/ - park_channel 337s [parking/parking_tests.c:park_call:254]: Creating test parking lot 'unit_tests_res_parking_test_lot' 338s END /res/parking/ - park_channel Time: 1000ms Result: PASS 338s START /res/parking/ - create_lot 338s [parking/parking_tests.c:create_lot:206]: Creating test parking lot 'unit_tests_res_parking_test_lot' 338s [parking/parking_tests.c:create_lot:214]: Successfully created parking lot. Retrieving test parking lot from container. 338s [parking/parking_tests.c:create_lot:223]: Successfully retrieved parking lot. Removing test parking lot from container. 338s [parking/parking_tests.c:create_lot:229]: Parking lot was successfully removed from the container. Test complete. 338s END /res/parking/ - create_lot Time: <1ms Result: PASS 338s START /res/prometheus/ - bridge_to_string 338s [test_res_prometheus.c:bridge_to_string:760]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 338s # TYPE asterisk_channels_count gauge 338s asterisk_channels_count{eid="fa:16:3e:b4:18:26"} 0 338s # HELP asterisk_calls_sum Total call count. 338s # TYPE asterisk_calls_sum counter 338s asterisk_calls_sum{eid="fa:16:3e:b4:18:26"} 0 338s # HELP asterisk_calls_count Current call count. 338s # TYPE asterisk_calls_count gauge 338s asterisk_calls_count{eid="fa:16:3e:b4:18:26"} 0 338s # HELP asterisk_endpoints_count Current endpoint count. 338s # TYPE asterisk_endpoints_count gauge 338s asterisk_endpoints_count{eid="fa:16:3e:b4:18:26"} 0 338s # HELP asterisk_bridges_count Current bridge count. 338s # TYPE asterisk_bridges_count gauge 338s asterisk_bridges_count{eid="fa:16:3e:b4:18:26"} 3 338s # HELP asterisk_bridges_channels_count Number of channels in the bridge. 338s # TYPE asterisk_bridges_channels_count gauge 338s asterisk_bridges_channels_count{eid="fa:16:3e:b4:18:26",id="76246270-1872-4d57-af37-6ade219a16a5",tech="simple_bridge",subclass="basic",creator="",name=""} 0 338s asterisk_bridges_channels_count{eid="fa:16:3e:b4:18:26",id="7f8cdf3c-9b28-40c0-a5b0-567ee8b410f9",tech="simple_bridge",subclass="basic",creator="",name=""} 0 338s 338s END /res/prometheus/ - bridge_to_string Time: <1ms Result: PASS 338s START /res/prometheus/ - config_general_core_metrics 338s [test_res_prometheus.c:config_general_core_metrics:680]: -> CURLing request... 338s [test_res_prometheus.c:config_general_core_metrics:688]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 338s # TYPE asterisk_channels_count gauge 338s asterisk_channels_count{eid="fa:16:3e:b4:18:26"} 0 338s # HELP asterisk_calls_sum Total call count. 338s # TYPE asterisk_calls_sum counter 338s asterisk_calls_sum{eid="fa:16:3e:b4:18:26"} 0 338s # HELP asterisk_calls_count Current call count. 338s # TYPE asterisk_calls_count gauge 338s asterisk_calls_count{eid="fa:16:3e:b4:18:26"} 0 338s # HELP asterisk_endpoints_count Current endpoint count. 338s # TYPE asterisk_endpoints_count gauge 338s asterisk_endpoints_count{eid="fa:16:3e:b4:18:26"} 0 338s # HELP asterisk_bridges_count Current bridge count. 338s # TYPE asterisk_bridges_count gauge 338s asterisk_bridges_count{eid="fa:16:3e:b4:18:26"} 0 338s # HELP asterisk_core_properties Asterisk instance properties. The value of this will always be 1. 338s # TYPE asterisk_core_properties counter 338s asterisk_core_properties{eid="fa:16:3e:b4:18:26",version="22.2.0~dfsg+~cs6.15.60671435-2",build_options="OPTIONAL_API, TEST_FRAMEWORK",build_date="2025-02-22 07:54:51 UTC",build_os="Linux",build_kernel="unknown",build_host="buildd.debian.org"} 1 338s # HELP asterisk_core_uptime_seconds Asterisk instance uptime in seconds. 338s # TYPE asterisk_core_uptime_seconds counter 338s asterisk_core_uptime_seconds{eid="fa:16:3e:b4:18:26"} 174 338s # HELP asterisk_core_last_reload_seconds Time since last Asterisk reload in seconds. 338s # TYPE asterisk_core_last_reload_seconds counter 338s asterisk_core_last_reload_seconds{eid="fa:16:3e:b4:18:26"} 174 338s # HELP asterisk_core_scrape_time_ms Total time taken to collect metrics, in milliseconds 338s # TYPE asterisk_core_scrape_time_ms counter 338s asterisk_core_scrape_time_ms{eid="fa:16:3e:b4:18:26"} 0 338s 338s [test_res_prometheus.c:config_general_core_metrics:690]: -> Checking for core properties 338s [test_res_prometheus.c:config_general_core_metrics:693]: -> Checking for uptime 338s [test_res_prometheus.c:config_general_core_metrics:696]: -> Checking for last reload 338s [test_res_prometheus.c:config_general_core_metrics:699]: -> Checking for scrape time 338s END /res/prometheus/ - config_general_core_metrics Time: <1ms Result: PASS 338s START /res/prometheus/ - config_general_basic_auth 338s [test_res_prometheus.c:config_general_basic_auth:555]: Testing without auth credentials 338s [test_res_prometheus.c:config_general_basic_auth:556]: -> CURLing request... 338s [test_res_prometheus.c:config_general_basic_auth:563]: -> CURL returned 401 338s [test_res_prometheus.c:config_general_basic_auth:566]: Testing with invalid auth credentials 338s [test_res_prometheus.c:config_general_basic_auth:567]: -> CURLing request... 338s [test_res_prometheus.c:config_general_basic_auth:576]: -> CURL returned 401 338s [test_res_prometheus.c:config_general_basic_auth:579]: Testing with valid auth credentials 338s [test_res_prometheus.c:config_general_basic_auth:580]: -> CURLing request... 339s [test_res_prometheus.c:config_general_basic_auth:588]: -> CURL returned 200 339s END /res/prometheus/ - config_general_basic_auth Time: <1ms Result: PASS 339s START /res/prometheus/ - config_general_enabled 339s [test_res_prometheus.c:config_general_enabled:628]: -> CURLing request... 339s [test_res_prometheus.c:config_general_enabled:635]: -> CURL returned 503 339s END /res/prometheus/ - config_general_enabled Time: <1ms Result: PASS 339s START /res/prometheus/ - gauge_create 339s END /res/prometheus/ - gauge_create Time: <1ms Result: PASS 339s START /res/prometheus/ - gauge_to_string 339s END /res/prometheus/ - gauge_to_string Time: <1ms Result: PASS 339s START /res/prometheus/ - counter_create 339s END /res/prometheus/ - counter_create Time: <1ms Result: PASS 339s START /res/prometheus/ - counter_to_string 339s END /res/prometheus/ - counter_to_string Time: <1ms Result: PASS 339s START /res/prometheus/ - metric_register 339s [test_res_prometheus.c:metric_register:291]: Testing nominal registration 339s [test_res_prometheus.c:metric_register:292]: -> Static metric 339s [test_res_prometheus.c:metric_register:294]: -> Malloc'd metric 339s [test_res_prometheus.c:metric_register:300]: Testing nominal registration of child metrics 339s [test_res_prometheus.c:metric_register:315]: Testing name collisions 339s [test_res_prometheus.c:metric_register:322]: Testing label collisions 339s [test_res_prometheus.c:metric_register:331]: Testing removal of metrics 339s END /res/prometheus/ - metric_register Time: <1ms Result: PASS 339s START /res/prometheus/ - metric_callback_register 339s [test_res_prometheus.c:metric_callback_register:241]: -> CURLing request... 339s [test_res_prometheus.c:metric_callback_register:250]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 339s # TYPE asterisk_channels_count gauge 339s asterisk_channels_count{eid="fa:16:3e:b4:18:26"} 0 339s # HELP asterisk_calls_sum Total call count. 339s # TYPE asterisk_calls_sum counter 339s asterisk_calls_sum{eid="fa:16:3e:b4:18:26"} 0 339s # HELP asterisk_calls_count Current call count. 339s # TYPE asterisk_calls_count gauge 339s asterisk_calls_count{eid="fa:16:3e:b4:18:26"} 0 339s # HELP asterisk_endpoints_count Current endpoint count. 339s # TYPE asterisk_endpoints_count gauge 339s asterisk_endpoints_count{eid="fa:16:3e:b4:18:26"} 0 339s # HELP asterisk_bridges_count Current bridge count. 339s # TYPE asterisk_bridges_count gauge 339s asterisk_bridges_count{eid="fa:16:3e:b4:18:26"} 0 339s # HELP test_counter A test counter 339s # TYPE test_counter counter 339s test_counter 0 339s 339s END /res/prometheus/ - metric_callback_register Time: <1ms Result: PASS 339s START /res/prometheus/ - metric_values 339s [test_res_prometheus.c:metric_values:166]: -> CURLing request... 339s [test_res_prometheus.c:metric_values:176]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 339s # TYPE asterisk_channels_count gauge 339s asterisk_channels_count{eid="fa:16:3e:b4:18:26"} 0 339s # HELP asterisk_calls_sum Total call count. 339s # TYPE asterisk_calls_sum counter 339s asterisk_calls_sum{eid="fa:16:3e:b4:18:26"} 0 339s # HELP asterisk_calls_count Current call count. 339s # TYPE asterisk_calls_count gauge 339s asterisk_calls_count{eid="fa:16:3e:b4:18:26"} 0 339s # HELP asterisk_endpoints_count Current endpoint count. 339s # TYPE asterisk_endpoints_count gauge 339s asterisk_endpoints_count{eid="fa:16:3e:b4:18:26"} 0 339s # HELP asterisk_bridges_count Current bridge count. 339s # TYPE asterisk_bridges_count gauge 339s asterisk_bridges_count{eid="fa:16:3e:b4:18:26"} 0 339s # HELP test_counter_one A test counter 339s # TYPE test_counter_one counter 339s test_counter_one 1 339s # HELP test_counter_two A test counter 339s # TYPE test_counter_two counter 339s test_counter_two 2 339s 339s END /res/prometheus/ - metric_values Time: <1ms Result: PASS 339s START /res/res_crypto/ - crypto_aes_decrypt 339s [test_crypto.c:crypto_aes_decrypt:607]: Executing AES-ECB decryption test 339s END /res/res_crypto/ - crypto_aes_decrypt Time: 26ms Result: PASS 339s START /res/res_crypto/ - crypto_aes_encrypt 339s [test_crypto.c:crypto_aes_encrypt:531]: Executing AES-ECB encryption test 339s END /res/res_crypto/ - crypto_aes_encrypt Time: 14ms Result: PASS 339s START /res/res_crypto/ - crypto_verify 339s [test_crypto.c:crypto_verify:425]: Executing RSA signature verification test 339s [test_crypto.c:crypto_verify:456]: Couldn't read key: rsa_key1 339s END /res/res_crypto/ - crypto_verify Time: <1ms Result: FAIL 339s START /res/res_crypto/ - crypto_sign 339s [test_crypto.c:crypto_sign:306]: Executing RSA signing test 339s [test_crypto.c:crypto_sign:341]: Couldn't read key: rsa_key1 339s END /res/res_crypto/ - crypto_sign Time: <1ms Result: FAIL 339s START /res/res_crypto/ - crypto_decrypt_pub_key 339s [test_crypto.c:crypto_rsa_decrypt:203]: Executing RSA decryption test 339s [test_crypto.c:crypto_rsa_decrypt:231]: Couldn't read key: rsa_key1 339s END /res/res_crypto/ - crypto_decrypt_pub_key Time: <1ms Result: FAIL 339s START /res/res_crypto/ - crypto_rsa_encrypt 339s [test_crypto.c:crypto_rsa_encrypt:107]: Executing RSA encryption test 339s [test_crypto.c:crypto_rsa_encrypt:138]: Couldn't read key: rsa_key1 339s END /res/res_crypto/ - crypto_rsa_encrypt Time: <1ms Result: FAIL 339s START /res/res_pjproject/ - ast_sockaddr_from_pj_sockaddr_test 339s END /res/res_pjproject/ - ast_sockaddr_from_pj_sockaddr_test Time: <1ms Result: PASS 339s START /res/res_pjproject/ - ast_sockaddr_to_pj_sockaddr_test 339s END /res/res_pjproject/ - ast_sockaddr_to_pj_sockaddr_test Time: <1ms Result: PASS 339s START /res/res_pjsip/ - xml_sanitization_exceeds_buffer 339s END /res/res_pjsip/ - xml_sanitization_exceeds_buffer Time: <1ms Result: PASS 339s START /res/res_pjsip/ - xml_sanitization_end_null 339s END /res/res_pjsip/ - xml_sanitization_end_null Time: <1ms Result: PASS 339s START /res/res_pjsip/scheduler/ - scheduler_policy 339s [test_res_pjsip_scheduler.c:scheduler_policy:355]: This test will take about 4.5 seconds 343s END /res/res_pjsip/scheduler/ - scheduler_policy Time: 4498ms Result: PASS 343s START /res/res_pjsip/scheduler/ - scheduler_cancel 343s [test_res_pjsip_scheduler.c:scheduler_cancel:301]: This test will take about 1.5 seconds 344s END /res/res_pjsip/scheduler/ - scheduler_cancel Time: 1500ms Result: PASS 344s START /res/res_pjsip/scheduler/ - scheduler_cleanup 344s [test_res_pjsip_scheduler.c:scheduler_cleanup:250]: This test will take about 1.6 seconds 346s END /res/res_pjsip/scheduler/ - scheduler_cleanup Time: 1600ms Result: PASS 346s START /res/res_pjsip/scheduler/ - unserialized_scheduler 346s [test_res_pjsip_scheduler.c:scheduler:136]: This test will take about 3.0 seconds 349s END /res/res_pjsip/scheduler/ - unserialized_scheduler Time: 2999ms Result: PASS 349s START /res/res_pjsip/scheduler/ - serialized_scheduler 349s [test_res_pjsip_scheduler.c:scheduler:131]: This test will take about 4.0 seconds 353s END /res/res_pjsip/scheduler/ - serialized_scheduler Time: 3999ms Result: PASS 353s START /res/res_pjsip_pubsub/ - bad_event 353s END /res/res_pjsip_pubsub/ - bad_event Time: <1ms Result: PASS 353s START /res/res_pjsip_pubsub/ - loop 353s END /res/res_pjsip_pubsub/ - loop Time: <1ms Result: PASS 353s START /res/res_pjsip_pubsub/ - duplicate_resource 353s END /res/res_pjsip_pubsub/ - duplicate_resource Time: <1ms Result: PASS 353s START /res/res_pjsip_pubsub/ - bad_branch 353s END /res/res_pjsip_pubsub/ - bad_branch Time: <1ms Result: PASS 353s START /res/res_pjsip_pubsub/ - bad_resource 353s END /res/res_pjsip_pubsub/ - bad_resource Time: <1ms Result: PASS 353s START /res/res_pjsip_pubsub/ - complex_resource_tree 353s END /res/res_pjsip_pubsub/ - complex_resource_tree Time: <1ms Result: PASS 353s START /res/res_pjsip_pubsub/ - resource_tree 353s END /res/res_pjsip_pubsub/ - resource_tree Time: <1ms Result: PASS 353s START /res/res_pjsip_session/ - merge_refresh_topologies 353s [res_pjsip_session.c:test_resolve_refresh_media_states:5892]: Test 1 passed 353s [res_pjsip_session.c:test_resolve_refresh_media_states:5912]: Test 2 passed 353s [res_pjsip_session.c:test_resolve_refresh_media_states:5936]: Test 3 passed 353s [res_pjsip_session.c:test_resolve_refresh_media_states:5955]: Test 4 passed 353s [res_pjsip_session.c:test_resolve_refresh_media_states:5973]: Test 5 passed 353s [res_pjsip_session.c:test_resolve_refresh_media_states:5994]: Test 6 passed 353s [res_pjsip_session.c:test_resolve_refresh_media_states:6020]: Test 7 passed 353s [res_pjsip_session.c:test_resolve_refresh_media_states:6041]: Test 8 passed 353s [res_pjsip_session.c:test_resolve_refresh_media_states:6061]: Test 9 passed 353s [res_pjsip_session.c:test_resolve_refresh_media_states:6081]: Test 10 passed 353s [res_pjsip_session.c:test_resolve_refresh_media_states:6104]: Test 11 passed 353s [res_pjsip_session.c:test_resolve_refresh_media_states:6129]: Test 12 passed 353s [res_pjsip_session.c:test_resolve_refresh_media_states:6163]: Test 13 passed 353s [res_pjsip_session.c:test_resolve_refresh_media_states:6187]: Test 14 passed 353s [res_pjsip_session.c:test_resolve_refresh_media_states:6211]: Test 15 passed 353s END /res/res_pjsip_session/ - merge_refresh_topologies Time: <1ms Result: PASS 353s START /res/res_pjsip_session/caps/ - low_level 353s [test_res_pjsip_session_caps.c:low_level:134]: Testing incoming expected pass 353s [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) 353s [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) 353s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (slin), remote: (all), pref: (local ), outgoing: (no ), expected: (slin) expected result: (PASS) 353s [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) 353s [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) 353s [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) 353s [test_res_pjsip_session_caps.c:low_level:142]: Testing incoming expected fail 353s [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) 353s [test_res_pjsip_session_caps.c:test_create_joint:102]: Expected Failure: Expected: () Actual: (nothing) 353s [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) 353s [test_res_pjsip_session_caps.c:test_create_joint:81]: Expected Failure: Invalid preference string incoming/outgoing combination. 353s [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) 353s [test_res_pjsip_session_caps.c:test_create_joint:81]: Expected Failure: Invalid preference string incoming/outgoing combination. 353s [test_res_pjsip_session_caps.c:low_level:147]: Testing outgoing expected pass 353s [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) 353s [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) 353s [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) 353s [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) 353s [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) 353s [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) 353s [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) 353s END /res/res_pjsip_session/caps/ - low_level Time: 1ms Result: PASS 353s START /res/res_resolver_unbound/ - resolve_srv 353s END /res/res_resolver_unbound/ - resolve_srv Time: 5ms Result: PASS 353s START /res/res_resolver_unbound/ - resolve_naptr 353s END /res/res_resolver_unbound/ - resolve_naptr Time: <1ms Result: PASS 353s START /res/res_resolver_unbound/ - resolve_cancel_off_nominal 353s END /res/res_resolver_unbound/ - resolve_cancel_off_nominal Time: 4ms Result: PASS 353s START /res/res_resolver_unbound/ - resolve_async_off_nominal 353s [res_resolver_unbound.c:off_nominal_async_run:1010]: Performing DNS query 'duck.feathers', type 1 353s [res_resolver_unbound.c:off_nominal_async_run:1010]: Performing DNS query 'goose.feathers', type 28 353s [res_resolver_unbound.c:off_nominal_async_run:1010]: Performing DNS query 'goose.feathers', type 1 353s [res_resolver_unbound.c:off_nominal_async_run:1010]: Performing DNS query '.1', type 1 353s [res_resolver_unbound.c:off_nominal_async_run:1010]: Performing DNS query '.www', type 1 353s [res_resolver_unbound.c:off_nominal_async_run:1010]: Performing DNS query '.1', type 12 353s [res_resolver_unbound.c:off_nominal_async_run:1010]: Performing DNS query '.www', type 12 353s END /res/res_resolver_unbound/ - resolve_async_off_nominal Time: <1ms Result: PASS 353s START /res/res_resolver_unbound/ - resolve_sync_off_nominal 353s END /res/res_resolver_unbound/ - resolve_sync_off_nominal Time: <1ms Result: PASS 353s START /res/res_resolver_unbound/ - resolve_async 353s [res_resolver_unbound.c:nominal_async_run:727]: Performing DNS query 'goose.feathers', type 1 353s [res_resolver_unbound.c:nominal_async_run:727]: Performing DNS query 'goose.feathers', type 28 353s [res_resolver_unbound.c:nominal_async_run:727]: Performing DNS query 'duck.feathers', type 1 353s END /res/res_resolver_unbound/ - resolve_async Time: <1ms Result: PASS 353s START /res/res_resolver_unbound/ - resolve_sync 353s [res_resolver_unbound.c:nominal_sync_run:577]: Performing DNS query 'goose.feathers', type 1 353s [res_resolver_unbound.c:nominal_sync_run:577]: Performing DNS query 'goose.feathers', type 28 353s [res_resolver_unbound.c:nominal_sync_run:577]: Performing DNS query 'duck.feathers', type 1 353s END /res/res_resolver_unbound/ - resolve_sync Time: <1ms Result: PASS 353s START /res/res_rtp/ - fir_nominal 353s END /res/res_rtp/ - fir_nominal Time: 2ms Result: PASS 353s START /res/res_rtp/ - sr_rr_nominal 353s END /res/res_rtp/ - sr_rr_nominal Time: 2ms Result: PASS 353s START /res/res_rtp/ - remb_nominal 353s END /res/res_rtp/ - remb_nominal Time: 1ms Result: PASS 353s START /res/res_rtp/ - lost_packet_stats_nominal 353s END /res/res_rtp/ - lost_packet_stats_nominal Time: <1ms Result: PASS 353s START /res/res_rtp/ - nack_overflow 353s END /res/res_rtp/ - nack_overflow Time: 1ms Result: PASS 353s START /res/res_rtp/ - nack_nominal 353s END /res/res_rtp/ - nack_nominal Time: 2ms Result: PASS 353s START /res/res_rtp/ - nack_no_packet_loss 353s END /res/res_rtp/ - nack_no_packet_loss Time: 2ms Result: PASS 353s START /res/res_sorcery_memory_cache/ - full_backend_cache_stale 368s END /res/res_sorcery_memory_cache/ - full_backend_cache_stale Time: 15000ms Result: PASS 368s START /res/res_sorcery_memory_cache/ - full_backend_cache_expiration 373s END /res/res_sorcery_memory_cache/ - full_backend_cache_expiration Time: 5000ms Result: PASS 373s START /res/res_sorcery_memory_cache/ - expiration 378s END /res/res_sorcery_memory_cache/ - expiration Time: 5000ms Result: PASS 378s START /res/res_sorcery_memory_cache/ - maximum_objects 378s END /res/res_sorcery_memory_cache/ - maximum_objects Time: 4ms Result: PASS 378s START /res/res_sorcery_memory_cache/ - delete 378s END /res/res_sorcery_memory_cache/ - delete Time: <1ms Result: PASS 378s START /res/res_sorcery_memory_cache/ - create 378s END /res/res_sorcery_memory_cache/ - create Time: <1ms Result: PASS 378s START /res/res_sorcery_memory_cache/ - create 378s END /res/res_sorcery_memory_cache/ - create Time: <1ms Result: PASS 378s START /res/res_sorcery_memory_cache/ - open_with_invalid_options 378s END /res/res_sorcery_memory_cache/ - open_with_invalid_options Time: <1ms Result: PASS 378s START /res/res_sorcery_memory_cache/ - open_with_valid_options 378s END /res/res_sorcery_memory_cache/ - open_with_valid_options Time: <1ms Result: PASS 378s START /res/res_sorcery_memory_cache/ - stale 378s [res_sorcery_memory_cache.c:stale:3204]: Begininning iteration 0 383s [res_sorcery_memory_cache.c:stale:3204]: Begininning iteration 1 388s [res_sorcery_memory_cache.c:stale:3204]: Begininning iteration 2 393s END /res/res_sorcery_memory_cache/ - stale Time: 15001ms Result: PASS 393s START /res/res_sorcery_memory_cache/thrash/ - high_object_count_without_expiration 396s END /res/res_sorcery_memory_cache/thrash/ - high_object_count_without_expiration Time: 3013ms Result: PASS 396s START /res/res_sorcery_memory_cache/thrash/ - conflicting_expire_and_stale 402s END /res/res_sorcery_memory_cache/thrash/ - conflicting_expire_and_stale Time: 6011ms Result: PASS 402s START /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum_with_expire_and_stale 408s END /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum_with_expire_and_stale Time: 6003ms Result: PASS 408s START /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum 411s END /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum Time: 3007ms Result: PASS 411s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_high_concurrent_updates 414s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_high_concurrent_updates Time: 3006ms Result: PASS 414s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_expire 417s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_expire Time: 3010ms Result: PASS 417s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_stale 420s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_stale Time: 3001ms Result: PASS 420s START /res/sorcery_astdb/ - object_delete_uncreated 420s END /res/sorcery_astdb/ - object_delete_uncreated Time: <1ms Result: PASS 420s START /res/sorcery_astdb/ - object_delete 420s END /res/sorcery_astdb/ - object_delete Time: <1ms Result: PASS 420s START /res/sorcery_astdb/ - object_update_uncreated 420s END /res/sorcery_astdb/ - object_update_uncreated Time: <1ms Result: PASS 420s START /res/sorcery_astdb/ - object_update 420s END /res/sorcery_astdb/ - object_update Time: <1ms Result: PASS 420s START /res/sorcery_astdb/ - object_retrieve_regex 420s END /res/sorcery_astdb/ - object_retrieve_regex Time: <1ms Result: PASS 420s START /res/sorcery_astdb/ - object_retrieve_multiple_field 420s END /res/sorcery_astdb/ - object_retrieve_multiple_field Time: <1ms Result: PASS 420s START /res/sorcery_astdb/ - object_retrieve_multiple_all 420s END /res/sorcery_astdb/ - object_retrieve_multiple_all Time: <1ms Result: PASS 420s START /res/sorcery_astdb/ - object_retrieve_field 420s END /res/sorcery_astdb/ - object_retrieve_field Time: <1ms Result: PASS 420s START /res/sorcery_astdb/ - object_retrieve_id 420s END /res/sorcery_astdb/ - object_retrieve_id Time: <1ms Result: PASS 420s START /res/sorcery_astdb/ - object_create 420s END /res/sorcery_astdb/ - object_create Time: 8ms Result: PASS 420s START /res/sorcery_realtime/ - object_filter 420s END /res/sorcery_realtime/ - object_filter Time: <1ms Result: PASS 420s START /res/sorcery_realtime/ - object_allocate_on_retrieval 420s END /res/sorcery_realtime/ - object_allocate_on_retrieval Time: <1ms Result: PASS 420s START /res/sorcery_realtime/ - object_delete_uncreated 420s END /res/sorcery_realtime/ - object_delete_uncreated Time: <1ms Result: PASS 420s START /res/sorcery_realtime/ - object_delete 420s END /res/sorcery_realtime/ - object_delete Time: <1ms Result: PASS 420s START /res/sorcery_realtime/ - object_update 420s END /res/sorcery_realtime/ - object_update Time: <1ms Result: PASS 420s START /res/sorcery_realtime/ - object_retrieve_regex_nofetch 420s END /res/sorcery_realtime/ - object_retrieve_regex_nofetch Time: <1ms Result: PASS 420s START /res/sorcery_realtime/ - object_retrieve_regex 420s END /res/sorcery_realtime/ - object_retrieve_regex Time: <1ms Result: PASS 420s START /res/sorcery_realtime/ - object_retrieve_multiple_field 420s END /res/sorcery_realtime/ - object_retrieve_multiple_field Time: <1ms Result: PASS 420s START /res/sorcery_realtime/ - object_retrieve_multiple_all_nofetch 420s END /res/sorcery_realtime/ - object_retrieve_multiple_all_nofetch Time: <1ms Result: PASS 420s START /res/sorcery_realtime/ - object_retrieve_multiple_all 420s END /res/sorcery_realtime/ - object_retrieve_multiple_all Time: <1ms Result: PASS 420s START /res/sorcery_realtime/ - object_retrieve_field 420s END /res/sorcery_realtime/ - object_retrieve_field Time: <1ms Result: PASS 420s START /res/sorcery_realtime/ - object_retrieve_id 420s END /res/sorcery_realtime/ - object_retrieve_id Time: <1ms Result: PASS 420s START /res/sorcery_realtime/ - object_create 420s END /res/sorcery_realtime/ - object_create Time: <1ms Result: PASS 420s START /res/websocket/ - websocket_client_multiple_protocols 420s END /res/websocket/ - websocket_client_multiple_protocols Time: <1ms Result: PASS 420s START /res/websocket/ - websocket_client_unsupported_protocol 420s END /res/websocket/ - websocket_client_unsupported_protocol Time: <1ms Result: PASS 420s START /res/websocket/ - websocket_client_bad_url 420s END /res/websocket/ - websocket_client_bad_url Time: 1ms Result: PASS 420s START /stasis/channels/ - channel_redirect_snapshot_json 420s END /stasis/channels/ - channel_redirect_snapshot_json Time: <1ms Result: PASS 420s START /stasis/channels/ - channel_snapshot_json 420s END /stasis/channels/ - channel_snapshot_json Time: <1ms Result: PASS 420s START /stasis/channels/ - multi_channel_blob_snapshots 420s END /stasis/channels/ - multi_channel_blob_snapshots Time: <1ms Result: PASS 420s START /stasis/channels/ - multi_channel_blob_create 420s END /stasis/channels/ - multi_channel_blob_create Time: <1ms Result: PASS 420s START /stasis/channels/ - null_blob 420s END /stasis/channels/ - null_blob Time: <1ms Result: PASS 420s START /stasis/channels/ - channel_blob_create 420s END /stasis/channels/ - channel_blob_create Time: <1ms Result: PASS 420s START /stasis/core/ - caching_dtor_order 420s END /stasis/core/ - caching_dtor_order Time: <1ms Result: PASS 420s START /stasis/core/ - dtor_order 420s END /stasis/core/ - dtor_order Time: <1ms Result: PASS 420s START /stasis/core/ - to_ami 420s END /stasis/core/ - to_ami Time: <1ms Result: PASS 420s START /stasis/core/ - no_to_ami 420s END /stasis/core/ - no_to_ami Time: <1ms Result: PASS 420s START /stasis/core/ - to_json 420s END /stasis/core/ - to_json Time: <1ms Result: PASS 420s START /stasis/core/ - no_to_json 420s END /stasis/core/ - no_to_json Time: <1ms Result: PASS 420s START /stasis/core/ - subscription_interleaving 420s END /stasis/core/ - subscription_interleaving Time: 1ms Result: PASS 420s START /stasis/core/ - interleaving 420s END /stasis/core/ - interleaving Time: <1ms Result: PASS 420s START /stasis/core/ - router_cache_updates 420s END /stasis/core/ - router_cache_updates Time: 100ms Result: PASS 420s START /stasis/core/ - router_pool 420s END /stasis/core/ - router_pool Time: <1ms Result: PASS 420s START /stasis/core/ - router 420s END /stasis/core/ - router Time: <1ms Result: PASS 420s START /stasis/core/ - cache_eid_aggregate 420s END /stasis/core/ - cache_eid_aggregate Time: <1ms Result: PASS 420s START /stasis/core/ - cache_dump 420s END /stasis/core/ - cache_dump Time: <1ms Result: PASS 420s START /stasis/core/ - cache 420s END /stasis/core/ - cache Time: <1ms Result: PASS 420s START /stasis/core/ - cache_filter 420s END /stasis/core/ - cache_filter Time: 100ms Result: PASS 420s START /stasis/core/ - forward 420s END /stasis/core/ - forward Time: <1ms Result: PASS 420s START /stasis/core/ - unsubscribe_stops_messages 420s END /stasis/core/ - unsubscribe_stops_messages Time: 100ms Result: PASS 420s START /stasis/core/ - publish_pool 420s END /stasis/core/ - publish_pool Time: <1ms Result: PASS 420s START /stasis/core/ - publish_sync 420s END /stasis/core/ - publish_sync Time: <1ms Result: PASS 420s START /stasis/core/ - publish 420s END /stasis/core/ - publish Time: <1ms Result: PASS 420s START /stasis/core/ - subscription_pool_messages 420s END /stasis/core/ - subscription_pool_messages Time: <1ms Result: PASS 420s START /stasis/core/ - subscription_messages 420s END /stasis/core/ - subscription_messages Time: <1ms Result: PASS 420s START /stasis/core/ - message 420s END /stasis/core/ - message Time: <1ms Result: PASS 420s START /stasis/core/ - message_type 420s END /stasis/core/ - message_type Time: <1ms Result: PASS 420s START /stasis/core/filtering/ - combo_filters 420s [test_stasis.c:dump_consumer:2198]: Messages received: 7 Final? yes 420s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 420s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType1 Pass 420s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass 420s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMI Pass 420s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass 420s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageJSON Pass 420s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 420s END /stasis/core/filtering/ - combo_filters Time: <1ms Result: PASS 420s START /stasis/core/filtering/ - formatter_filters 420s [test_stasis.c:dump_consumer:2198]: Messages received: 7 Final? yes 420s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 420s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMI Pass 420s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageJSON Pass 420s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass 420s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass2 420s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageEVENT Pass 420s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 420s END /stasis/core/filtering/ - formatter_filters Time: <1ms Result: PASS 420s START /stasis/core/filtering/ - type_filters 420s [test_stasis.c:dump_consumer:2198]: Messages received: 5 Final? yes 420s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 420s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType1 Pass 420s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass 420s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass2 420s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 420s END /stasis/core/filtering/ - type_filters Time: <1ms Result: PASS 420s START /stasis/core/state/ - explicit_publish 421s END /stasis/core/state/ - explicit_publish Time: 26ms Result: PASS 421s START /stasis/core/state/ - implicit_publish 421s END /stasis/core/state/ - implicit_publish Time: 22ms Result: PASS 421s START /stasis/endpoints/ - channel_messages 421s END /stasis/endpoints/ - channel_messages Time: 1ms Result: PASS 421s START /stasis/endpoints/ - cache_clear 421s END /stasis/endpoints/ - cache_clear Time: <1ms Result: PASS 421s START /stasis/endpoints/ - state_changes 421s END /stasis/endpoints/ - state_changes Time: <1ms Result: PASS 421s START /stasis/res/ - app_invoke_dne 421s END /stasis/res/ - app_invoke_dne Time: <1ms Result: PASS 421s START /stasis/res/ - app_invoke_one 421s END /stasis/res/ - app_invoke_one Time: <1ms Result: PASS 421s START /stasis/res/ - app_replaced 421s END /stasis/res/ - app_replaced Time: <1ms Result: PASS 421s 421s 659 Test(s) Executed 655 Passed 4 Failed 421s 'U' option is not compatible with remote console mode and has no effect. 421s 421s Results Generated Successfully: /tmp/autopkgtest.BlHaM9/build.zyc/src/debian/tests/testmods/output/results.txt 421s 'U' option is not compatible with remote console mode and has no effect. 421s 421s Some test modules were not loaded: 421s 20a21 421s > test_cel.so 421s 53a55 421s > test_message.so 421s Manually disabled: 421s test_message 421s test_cel 421s 421s 'U' option is not compatible with remote console mode and has no effect. 421s 422s autopkgtest [20:41:07]: test asttestmods: -----------------------] 423s autopkgtest [20:41:08]: test asttestmods: - - - - - - - - - - results - - - - - - - - - - 423s asttestmods PASS 423s autopkgtest [20:41:08]: test amr: preparing testbed 558s autopkgtest [20:43:23]: testbed dpkg architecture: arm64 558s autopkgtest [20:43:23]: testbed apt version: 3.0.0 559s autopkgtest [20:43:24]: @@@@@@@@@@@@@@@@@@@@ test bed setup 559s autopkgtest [20:43:24]: testbed release detected to be: questing 560s autopkgtest [20:43:25]: updating testbed package index (apt update) 560s Get:1 http://ftpmaster.internal/ubuntu questing-proposed InRelease [110 kB] 560s Hit:2 http://ftpmaster.internal/ubuntu questing InRelease 560s Hit:3 http://ftpmaster.internal/ubuntu questing-updates InRelease 561s Hit:4 http://ftpmaster.internal/ubuntu questing-security InRelease 561s Get:5 http://ftpmaster.internal/ubuntu questing-proposed/main Sources [111 kB] 561s Get:6 http://ftpmaster.internal/ubuntu questing-proposed/multiverse Sources [33.9 kB] 561s Get:7 http://ftpmaster.internal/ubuntu questing-proposed/universe Sources [1095 kB] 561s Get:8 http://ftpmaster.internal/ubuntu questing-proposed/main arm64 Packages [143 kB] 561s Get:9 http://ftpmaster.internal/ubuntu questing-proposed/universe arm64 Packages [1104 kB] 561s Get:10 http://ftpmaster.internal/ubuntu questing-proposed/multiverse arm64 Packages [30.1 kB] 561s Fetched 2627 kB in 1s (2607 kB/s) 562s Reading package lists... 563s autopkgtest [20:43:28]: upgrading testbed (apt dist-upgrade and autopurge) 563s Reading package lists... 564s Building dependency tree... 564s Reading state information... 565s Calculating upgrade...Starting pkgProblemResolver with broken count: 0 565s Starting 2 pkgProblemResolver with broken count: 0 565s Done 566s Entering ResolveByKeep 566s 566s Calculating upgrade... 567s The following packages will be upgraded: 567s base-passwd ethtool libbpf1 libevdev2 libmm-glib0 libnghttp2-14 567s libpython3.12-minimal libpython3.12-stdlib libpython3.12t64 libsqlite3-0 567s libunistring5 libusb-1.0-0 man-db patch usbutils 567s 15 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 567s Need to get 8938 kB of archives. 567s After this operation, 133 kB disk space will be freed. 567s Get:1 http://ftpmaster.internal/ubuntu questing/main arm64 base-passwd arm64 3.6.7 [54.2 kB] 567s Get:2 http://ftpmaster.internal/ubuntu questing/main arm64 libbpf1 arm64 1:1.5.0-3 [182 kB] 567s Get:3 http://ftpmaster.internal/ubuntu questing-proposed/main arm64 libsqlite3-0 arm64 3.46.1-4 [707 kB] 567s Get:4 http://ftpmaster.internal/ubuntu questing/main arm64 libunistring5 arm64 1.3-2 [601 kB] 568s Get:5 http://ftpmaster.internal/ubuntu questing/main arm64 ethtool arm64 1:6.14-2 [242 kB] 568s Get:6 http://ftpmaster.internal/ubuntu questing/main arm64 libevdev2 arm64 1.13.4+dfsg-1 [35.8 kB] 568s Get:7 http://ftpmaster.internal/ubuntu questing/main arm64 libnghttp2-14 arm64 1.64.0-1.1 [74.6 kB] 568s Get:8 http://ftpmaster.internal/ubuntu questing/main arm64 libusb-1.0-0 arm64 2:1.0.28-1 [54.8 kB] 568s Get:9 http://ftpmaster.internal/ubuntu questing/main arm64 man-db arm64 2.13.1-1 [1369 kB] 568s Get:10 http://ftpmaster.internal/ubuntu questing/main arm64 usbutils arm64 1:018-2 [81.5 kB] 568s Get:11 http://ftpmaster.internal/ubuntu questing/main arm64 libmm-glib0 arm64 1.24.0-1 [262 kB] 568s Get:12 http://ftpmaster.internal/ubuntu questing-proposed/universe arm64 libpython3.12t64 arm64 3.12.10-1 [2314 kB] 568s Get:13 http://ftpmaster.internal/ubuntu questing-proposed/universe arm64 libpython3.12-stdlib arm64 3.12.10-1 [2029 kB] 568s Get:14 http://ftpmaster.internal/ubuntu questing-proposed/universe arm64 libpython3.12-minimal arm64 3.12.10-1 [836 kB] 568s Get:15 http://ftpmaster.internal/ubuntu questing/main arm64 patch arm64 2.8-1 [94.0 kB] 569s Preconfiguring packages ... 569s Fetched 8938 kB in 1s (9761 kB/s) 569s (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 ... 117820 files and directories currently installed.) 569s Preparing to unpack .../base-passwd_3.6.7_arm64.deb ... 569s Unpacking base-passwd (3.6.7) over (3.6.6) ... 569s Setting up base-passwd (3.6.7) ... 569s (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 ... 117820 files and directories currently installed.) 569s Preparing to unpack .../00-libbpf1_1%3a1.5.0-3_arm64.deb ... 570s Unpacking libbpf1:arm64 (1:1.5.0-3) over (1:1.5.0-2) ... 570s Preparing to unpack .../01-libsqlite3-0_3.46.1-4_arm64.deb ... 570s Unpacking libsqlite3-0:arm64 (3.46.1-4) over (3.46.1-3) ... 570s Preparing to unpack .../02-libunistring5_1.3-2_arm64.deb ... 570s Unpacking libunistring5:arm64 (1.3-2) over (1.3-1) ... 570s Preparing to unpack .../03-ethtool_1%3a6.14-2_arm64.deb ... 570s Unpacking ethtool (1:6.14-2) over (1:6.11-1) ... 570s Preparing to unpack .../04-libevdev2_1.13.4+dfsg-1_arm64.deb ... 570s Unpacking libevdev2:arm64 (1.13.4+dfsg-1) over (1.13.3+dfsg-1) ... 570s Preparing to unpack .../05-libnghttp2-14_1.64.0-1.1_arm64.deb ... 570s Unpacking libnghttp2-14:arm64 (1.64.0-1.1) over (1.64.0-1ubuntu1) ... 570s Preparing to unpack .../06-libusb-1.0-0_2%3a1.0.28-1_arm64.deb ... 570s Unpacking libusb-1.0-0:arm64 (2:1.0.28-1) over (2:1.0.27-2) ... 570s Preparing to unpack .../07-man-db_2.13.1-1_arm64.deb ... 570s Unpacking man-db (2.13.1-1) over (2.13.0-1) ... 570s Preparing to unpack .../08-usbutils_1%3a018-2_arm64.deb ... 570s Unpacking usbutils (1:018-2) over (1:018-1) ... 570s Preparing to unpack .../09-libmm-glib0_1.24.0-1_arm64.deb ... 570s Unpacking libmm-glib0:arm64 (1.24.0-1) over (1.23.4-0ubuntu3) ... 570s Preparing to unpack .../10-libpython3.12t64_3.12.10-1_arm64.deb ... 570s Unpacking libpython3.12t64:arm64 (3.12.10-1) over (3.12.8-3) ... 571s Preparing to unpack .../11-libpython3.12-stdlib_3.12.10-1_arm64.deb ... 571s Unpacking libpython3.12-stdlib:arm64 (3.12.10-1) over (3.12.8-3) ... 571s Preparing to unpack .../12-libpython3.12-minimal_3.12.10-1_arm64.deb ... 571s Unpacking libpython3.12-minimal:arm64 (3.12.10-1) over (3.12.8-3) ... 571s Preparing to unpack .../13-patch_2.8-1_arm64.deb ... 571s Unpacking patch (2.8-1) over (2.7.6-7build3) ... 571s Setting up libsqlite3-0:arm64 (3.46.1-4) ... 571s Setting up libpython3.12-minimal:arm64 (3.12.10-1) ... 571s Setting up libnghttp2-14:arm64 (1.64.0-1.1) ... 571s Setting up man-db (2.13.1-1) ... 571s Updating database of manual pages ... 574s man-db.service is a disabled or a static unit not running, not starting it. 574s Setting up libunistring5:arm64 (1.3-2) ... 574s Setting up patch (2.8-1) ... 574s Setting up libmm-glib0:arm64 (1.24.0-1) ... 574s Setting up libusb-1.0-0:arm64 (2:1.0.28-1) ... 574s Setting up libevdev2:arm64 (1.13.4+dfsg-1) ... 574s Setting up libbpf1:arm64 (1:1.5.0-3) ... 574s Setting up ethtool (1:6.14-2) ... 574s Setting up libpython3.12-stdlib:arm64 (3.12.10-1) ... 574s Setting up usbutils (1:018-2) ... 574s Setting up libpython3.12t64:arm64 (3.12.10-1) ... 574s Processing triggers for libc-bin (2.41-6ubuntu1) ... 574s Reading package lists... 574s Building dependency tree... 574s Reading state information... 575s Starting pkgProblemResolver with broken count: 0 575s Starting 2 pkgProblemResolver with broken count: 0 575s Done 575s Solving dependencies... 576s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 576s autopkgtest [20:43:41]: rebooting testbed after setup commands that affected boot 603s Reading package lists... 604s Building dependency tree... 604s Reading state information... 604s Starting pkgProblemResolver with broken count: 0 604s Starting 2 pkgProblemResolver with broken count: 0 604s Done 605s The following NEW packages will be installed: 605s asterisk asterisk-config asterisk-core-sounds-en asterisk-core-sounds-en-gsm 605s asterisk-modules freetds-common libasound2-data libasound2t64 libb64-0d 605s libc-client2007e libcodec2-1.2 libdeflate0 libevent-2.1-7t64 605s libgmime-3.0-0t64 libgsm1 libical3t64 libiksemel3 libjack-jackd2-0 libjbig0 605s libjpeg-turbo8 libjpeg8 libjwt2 liblerc4 libltdl7 liblua5.1-0 libneon27t64 605s libodbc2 libogg0 libopencore-amrnb0 libopencore-amrwb0 libopus0 libopusenc0 605s libopusfile0 libportaudio2 libpq5 libradcli4 libresample1 libsamplerate0 605s libsharpyuv0 libsnmp-base libsnmp40t64 libspandsp2t64 libspeex1 libspeexdsp1 605s libsrtp2-1 libsybdb5 libtiff6 libunbound8 liburiparser1 libvo-amrwbenc0 605s libvorbis0a libvorbisenc2 libvorbisfile3 libwebp7 libxslt1.1 mlock 605s 0 upgraded, 56 newly installed, 0 to remove and 0 not upgraded. 605s Need to get 28.2 MB of archives. 605s After this operation, 86.8 MB of additional disk space will be used. 605s Get:1 http://ftpmaster.internal/ubuntu questing/universe arm64 asterisk-config all 1:22.2.0~dfsg+~cs6.15.60671435-2 [226 kB] 605s Get:2 http://ftpmaster.internal/ubuntu questing/universe arm64 asterisk-core-sounds-en-gsm all 1.6.1-1 [2417 kB] 606s Get:3 http://ftpmaster.internal/ubuntu questing/universe arm64 asterisk-core-sounds-en all 1.6.1-1 [20.6 kB] 606s Get:4 http://ftpmaster.internal/ubuntu questing/universe arm64 mlock arm64 8:2007f~dfsg-7.1 [8464 B] 606s Get:5 http://ftpmaster.internal/ubuntu questing/universe arm64 libc-client2007e arm64 8:2007f~dfsg-7.1 [626 kB] 606s Get:6 http://ftpmaster.internal/ubuntu questing/universe arm64 libcodec2-1.2 arm64 1.2.0-3 [8999 kB] 606s Get:7 http://ftpmaster.internal/ubuntu questing/universe arm64 libgmime-3.0-0t64 arm64 3.2.15+dfsg-1 [173 kB] 606s Get:8 http://ftpmaster.internal/ubuntu questing/universe arm64 libgsm1 arm64 1.0.22-1build1 [27.0 kB] 606s Get:9 http://ftpmaster.internal/ubuntu questing/main arm64 libical3t64 arm64 3.0.20-1 [305 kB] 606s Get:10 http://ftpmaster.internal/ubuntu questing/universe arm64 libiksemel3 arm64 1.4-4build2 [27.6 kB] 606s Get:11 http://ftpmaster.internal/ubuntu questing/main arm64 libopus0 arm64 1.5.2-2 [2891 kB] 606s Get:12 http://ftpmaster.internal/ubuntu questing/main arm64 libsamplerate0 arm64 0.2.2-4build1 [1343 kB] 606s Get:13 http://ftpmaster.internal/ubuntu questing/main arm64 libjack-jackd2-0 arm64 1.9.22~dfsg-4 [286 kB] 606s Get:14 http://ftpmaster.internal/ubuntu questing/universe arm64 libb64-0d arm64 1.2-5build1 [9590 B] 606s Get:15 http://ftpmaster.internal/ubuntu questing/universe arm64 libjwt2 arm64 1.17.2-1 [17.8 kB] 606s Get:16 http://ftpmaster.internal/ubuntu questing/universe arm64 liblua5.1-0 arm64 5.1.5-11 [118 kB] 606s Get:17 http://ftpmaster.internal/ubuntu questing/universe arm64 libneon27t64 arm64 0.34.2-1 [103 kB] 606s Get:18 http://ftpmaster.internal/ubuntu questing/main arm64 libltdl7 arm64 2.5.4-4 [43.0 kB] 606s Get:19 http://ftpmaster.internal/ubuntu questing/main arm64 libodbc2 arm64 2.3.12-2ubuntu1 [147 kB] 606s Get:20 http://ftpmaster.internal/ubuntu questing/main arm64 libogg0 arm64 1.3.5-3build1 [22.6 kB] 606s Get:21 http://ftpmaster.internal/ubuntu questing/universe arm64 libopencore-amrnb0 arm64 0.1.6-1build1 [97.0 kB] 606s Get:22 http://ftpmaster.internal/ubuntu questing/universe arm64 libopencore-amrwb0 arm64 0.1.6-1build1 [50.3 kB] 606s Get:23 http://ftpmaster.internal/ubuntu questing/universe arm64 libopusenc0 arm64 0.2.1-2build1 [25.6 kB] 606s Get:24 http://ftpmaster.internal/ubuntu questing/universe arm64 libopusfile0 arm64 0.12-4build3 [44.7 kB] 606s Get:25 http://ftpmaster.internal/ubuntu questing/main arm64 libasound2-data all 1.2.13-1build1 [21.1 kB] 606s Get:26 http://ftpmaster.internal/ubuntu questing/main arm64 libasound2t64 arm64 1.2.13-1build1 [390 kB] 606s Get:27 http://ftpmaster.internal/ubuntu questing/universe arm64 libportaudio2 arm64 19.6.0-1.2build3 [65.4 kB] 606s Get:28 http://ftpmaster.internal/ubuntu questing/main arm64 libpq5 arm64 17.4-1 [142 kB] 606s Get:29 http://ftpmaster.internal/ubuntu questing/universe arm64 libradcli4 arm64 1.2.11-1build3 [40.2 kB] 606s Get:30 http://ftpmaster.internal/ubuntu questing/universe arm64 libresample1 arm64 0.1.3-8 [8668 B] 606s Get:31 http://ftpmaster.internal/ubuntu questing/main arm64 libsnmp-base all 5.9.4+dfsg-1.1ubuntu7 [206 kB] 607s Get:32 http://ftpmaster.internal/ubuntu questing/main arm64 libsnmp40t64 arm64 5.9.4+dfsg-1.1ubuntu7 [1053 kB] 607s Get:33 http://ftpmaster.internal/ubuntu questing/main arm64 libdeflate0 arm64 1.23-2 [46.4 kB] 607s Get:34 http://ftpmaster.internal/ubuntu questing/main arm64 libjbig0 arm64 2.1-6.1ubuntu2 [29.3 kB] 607s Get:35 http://ftpmaster.internal/ubuntu questing/main arm64 libjpeg-turbo8 arm64 2.1.5-3ubuntu2 [165 kB] 607s Get:36 http://ftpmaster.internal/ubuntu questing/main arm64 libjpeg8 arm64 8c-2ubuntu11 [2148 B] 607s Get:37 http://ftpmaster.internal/ubuntu questing/main arm64 liblerc4 arm64 4.0.0+ds-5ubuntu1 [167 kB] 607s Get:38 http://ftpmaster.internal/ubuntu questing/main arm64 libsharpyuv0 arm64 1.5.0-0.1 [16.9 kB] 607s Get:39 http://ftpmaster.internal/ubuntu questing/main arm64 libwebp7 arm64 1.5.0-0.1 [194 kB] 607s Get:40 http://ftpmaster.internal/ubuntu questing/main arm64 libtiff6 arm64 4.7.0-3ubuntu1 [197 kB] 607s Get:41 http://ftpmaster.internal/ubuntu questing/universe arm64 libspandsp2t64 arm64 0.0.6+dfsg-2.2 [316 kB] 607s Get:42 http://ftpmaster.internal/ubuntu questing/main arm64 libspeex1 arm64 1.2.1-3 [56.9 kB] 607s Get:43 http://ftpmaster.internal/ubuntu questing/main arm64 libspeexdsp1 arm64 1.2.1-3 [41.5 kB] 607s Get:44 http://ftpmaster.internal/ubuntu questing/universe arm64 libsrtp2-1 arm64 2.7.0-3 [44.3 kB] 607s Get:45 http://ftpmaster.internal/ubuntu questing/main arm64 freetds-common all 1.3.17+ds-2build3 [26.9 kB] 607s Get:46 http://ftpmaster.internal/ubuntu questing/main arm64 libsybdb5 arm64 1.3.17+ds-2build3 [186 kB] 607s Get:47 http://ftpmaster.internal/ubuntu questing/main arm64 libevent-2.1-7t64 arm64 2.1.12-stable-10 [140 kB] 607s Get:48 http://ftpmaster.internal/ubuntu questing/main arm64 libunbound8 arm64 1.22.0-1ubuntu1 [437 kB] 607s Get:49 http://ftpmaster.internal/ubuntu questing/universe arm64 libvo-amrwbenc0 arm64 0.1.3-2build1 [73.2 kB] 607s Get:50 http://ftpmaster.internal/ubuntu questing/main arm64 libvorbis0a arm64 1.3.7-2 [95.0 kB] 607s Get:51 http://ftpmaster.internal/ubuntu questing/main arm64 libvorbisenc2 arm64 1.3.7-2 [80.0 kB] 607s Get:52 http://ftpmaster.internal/ubuntu questing/main arm64 libvorbisfile3 arm64 1.3.7-2 [17.1 kB] 607s Get:53 http://ftpmaster.internal/ubuntu questing/universe arm64 asterisk-modules arm64 1:22.2.0~dfsg+~cs6.15.60671435-2 [3008 kB] 607s Get:54 http://ftpmaster.internal/ubuntu questing/universe arm64 liburiparser1 arm64 0.9.8+dfsg-2 [36.3 kB] 607s Get:55 http://ftpmaster.internal/ubuntu questing/main arm64 libxslt1.1 arm64 1.1.39-0exp1ubuntu4 [168 kB] 607s Get:56 http://ftpmaster.internal/ubuntu questing/universe arm64 asterisk arm64 1:22.2.0~dfsg+~cs6.15.60671435-2 [2714 kB] 608s Fetched 28.2 MB in 2s (13.4 MB/s) 608s Selecting previously unselected package asterisk-config. 608s (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 ... 117830 files and directories currently installed.) 608s Preparing to unpack .../00-asterisk-config_1%3a22.2.0~dfsg+~cs6.15.60671435-2_all.deb ... 608s Unpacking asterisk-config (1:22.2.0~dfsg+~cs6.15.60671435-2) ... 608s Selecting previously unselected package asterisk-core-sounds-en-gsm. 608s Preparing to unpack .../01-asterisk-core-sounds-en-gsm_1.6.1-1_all.deb ... 608s Unpacking asterisk-core-sounds-en-gsm (1.6.1-1) ... 608s Selecting previously unselected package asterisk-core-sounds-en. 608s Preparing to unpack .../02-asterisk-core-sounds-en_1.6.1-1_all.deb ... 608s Unpacking asterisk-core-sounds-en (1.6.1-1) ... 608s Selecting previously unselected package mlock. 608s Preparing to unpack .../03-mlock_8%3a2007f~dfsg-7.1_arm64.deb ... 608s Unpacking mlock (8:2007f~dfsg-7.1) ... 608s Selecting previously unselected package libc-client2007e. 608s Preparing to unpack .../04-libc-client2007e_8%3a2007f~dfsg-7.1_arm64.deb ... 608s Unpacking libc-client2007e (8:2007f~dfsg-7.1) ... 608s Selecting previously unselected package libcodec2-1.2:arm64. 608s Preparing to unpack .../05-libcodec2-1.2_1.2.0-3_arm64.deb ... 608s Unpacking libcodec2-1.2:arm64 (1.2.0-3) ... 608s Selecting previously unselected package libgmime-3.0-0t64:arm64. 608s Preparing to unpack .../06-libgmime-3.0-0t64_3.2.15+dfsg-1_arm64.deb ... 608s Unpacking libgmime-3.0-0t64:arm64 (3.2.15+dfsg-1) ... 608s Selecting previously unselected package libgsm1:arm64. 608s Preparing to unpack .../07-libgsm1_1.0.22-1build1_arm64.deb ... 608s Unpacking libgsm1:arm64 (1.0.22-1build1) ... 608s Selecting previously unselected package libical3t64:arm64. 609s Preparing to unpack .../08-libical3t64_3.0.20-1_arm64.deb ... 609s Unpacking libical3t64:arm64 (3.0.20-1) ... 609s Selecting previously unselected package libiksemel3:arm64. 609s Preparing to unpack .../09-libiksemel3_1.4-4build2_arm64.deb ... 609s Unpacking libiksemel3:arm64 (1.4-4build2) ... 609s Selecting previously unselected package libopus0:arm64. 609s Preparing to unpack .../10-libopus0_1.5.2-2_arm64.deb ... 609s Unpacking libopus0:arm64 (1.5.2-2) ... 609s Selecting previously unselected package libsamplerate0:arm64. 609s Preparing to unpack .../11-libsamplerate0_0.2.2-4build1_arm64.deb ... 609s Unpacking libsamplerate0:arm64 (0.2.2-4build1) ... 609s Selecting previously unselected package libjack-jackd2-0:arm64. 609s Preparing to unpack .../12-libjack-jackd2-0_1.9.22~dfsg-4_arm64.deb ... 609s Unpacking libjack-jackd2-0:arm64 (1.9.22~dfsg-4) ... 609s Selecting previously unselected package libb64-0d:arm64. 609s Preparing to unpack .../13-libb64-0d_1.2-5build1_arm64.deb ... 609s Unpacking libb64-0d:arm64 (1.2-5build1) ... 609s Selecting previously unselected package libjwt2:arm64. 609s Preparing to unpack .../14-libjwt2_1.17.2-1_arm64.deb ... 609s Unpacking libjwt2:arm64 (1.17.2-1) ... 609s Selecting previously unselected package liblua5.1-0:arm64. 609s Preparing to unpack .../15-liblua5.1-0_5.1.5-11_arm64.deb ... 609s Unpacking liblua5.1-0:arm64 (5.1.5-11) ... 609s Selecting previously unselected package libneon27t64:arm64. 609s Preparing to unpack .../16-libneon27t64_0.34.2-1_arm64.deb ... 609s Unpacking libneon27t64:arm64 (0.34.2-1) ... 609s Selecting previously unselected package libltdl7:arm64. 609s Preparing to unpack .../17-libltdl7_2.5.4-4_arm64.deb ... 609s Unpacking libltdl7:arm64 (2.5.4-4) ... 609s Selecting previously unselected package libodbc2:arm64. 609s Preparing to unpack .../18-libodbc2_2.3.12-2ubuntu1_arm64.deb ... 609s Unpacking libodbc2:arm64 (2.3.12-2ubuntu1) ... 609s Selecting previously unselected package libogg0:arm64. 609s Preparing to unpack .../19-libogg0_1.3.5-3build1_arm64.deb ... 609s Unpacking libogg0:arm64 (1.3.5-3build1) ... 609s Selecting previously unselected package libopencore-amrnb0:arm64. 609s Preparing to unpack .../20-libopencore-amrnb0_0.1.6-1build1_arm64.deb ... 609s Unpacking libopencore-amrnb0:arm64 (0.1.6-1build1) ... 609s Selecting previously unselected package libopencore-amrwb0:arm64. 609s Preparing to unpack .../21-libopencore-amrwb0_0.1.6-1build1_arm64.deb ... 609s Unpacking libopencore-amrwb0:arm64 (0.1.6-1build1) ... 609s Selecting previously unselected package libopusenc0:arm64. 609s Preparing to unpack .../22-libopusenc0_0.2.1-2build1_arm64.deb ... 609s Unpacking libopusenc0:arm64 (0.2.1-2build1) ... 609s Selecting previously unselected package libopusfile0:arm64. 609s Preparing to unpack .../23-libopusfile0_0.12-4build3_arm64.deb ... 609s Unpacking libopusfile0:arm64 (0.12-4build3) ... 609s Selecting previously unselected package libasound2-data. 609s Preparing to unpack .../24-libasound2-data_1.2.13-1build1_all.deb ... 609s Unpacking libasound2-data (1.2.13-1build1) ... 609s Selecting previously unselected package libasound2t64:arm64. 609s Preparing to unpack .../25-libasound2t64_1.2.13-1build1_arm64.deb ... 609s Unpacking libasound2t64:arm64 (1.2.13-1build1) ... 609s Selecting previously unselected package libportaudio2:arm64. 609s Preparing to unpack .../26-libportaudio2_19.6.0-1.2build3_arm64.deb ... 609s Unpacking libportaudio2:arm64 (19.6.0-1.2build3) ... 609s Selecting previously unselected package libpq5:arm64. 609s Preparing to unpack .../27-libpq5_17.4-1_arm64.deb ... 609s Unpacking libpq5:arm64 (17.4-1) ... 610s Selecting previously unselected package libradcli4. 610s Preparing to unpack .../28-libradcli4_1.2.11-1build3_arm64.deb ... 610s Unpacking libradcli4 (1.2.11-1build3) ... 610s Selecting previously unselected package libresample1. 610s Preparing to unpack .../29-libresample1_0.1.3-8_arm64.deb ... 610s Unpacking libresample1 (0.1.3-8) ... 610s Selecting previously unselected package libsnmp-base. 610s Preparing to unpack .../30-libsnmp-base_5.9.4+dfsg-1.1ubuntu7_all.deb ... 610s Unpacking libsnmp-base (5.9.4+dfsg-1.1ubuntu7) ... 610s Selecting previously unselected package libsnmp40t64:arm64. 610s Preparing to unpack .../31-libsnmp40t64_5.9.4+dfsg-1.1ubuntu7_arm64.deb ... 610s Unpacking libsnmp40t64:arm64 (5.9.4+dfsg-1.1ubuntu7) ... 610s Selecting previously unselected package libdeflate0:arm64. 610s Preparing to unpack .../32-libdeflate0_1.23-2_arm64.deb ... 610s Unpacking libdeflate0:arm64 (1.23-2) ... 610s Selecting previously unselected package libjbig0:arm64. 610s Preparing to unpack .../33-libjbig0_2.1-6.1ubuntu2_arm64.deb ... 610s Unpacking libjbig0:arm64 (2.1-6.1ubuntu2) ... 610s Selecting previously unselected package libjpeg-turbo8:arm64. 610s Preparing to unpack .../34-libjpeg-turbo8_2.1.5-3ubuntu2_arm64.deb ... 610s Unpacking libjpeg-turbo8:arm64 (2.1.5-3ubuntu2) ... 610s Selecting previously unselected package libjpeg8:arm64. 610s Preparing to unpack .../35-libjpeg8_8c-2ubuntu11_arm64.deb ... 610s Unpacking libjpeg8:arm64 (8c-2ubuntu11) ... 610s Selecting previously unselected package liblerc4:arm64. 610s Preparing to unpack .../36-liblerc4_4.0.0+ds-5ubuntu1_arm64.deb ... 610s Unpacking liblerc4:arm64 (4.0.0+ds-5ubuntu1) ... 610s Selecting previously unselected package libsharpyuv0:arm64. 610s Preparing to unpack .../37-libsharpyuv0_1.5.0-0.1_arm64.deb ... 610s Unpacking libsharpyuv0:arm64 (1.5.0-0.1) ... 610s Selecting previously unselected package libwebp7:arm64. 610s Preparing to unpack .../38-libwebp7_1.5.0-0.1_arm64.deb ... 610s Unpacking libwebp7:arm64 (1.5.0-0.1) ... 610s Selecting previously unselected package libtiff6:arm64. 610s Preparing to unpack .../39-libtiff6_4.7.0-3ubuntu1_arm64.deb ... 610s Unpacking libtiff6:arm64 (4.7.0-3ubuntu1) ... 610s Selecting previously unselected package libspandsp2t64:arm64. 610s Preparing to unpack .../40-libspandsp2t64_0.0.6+dfsg-2.2_arm64.deb ... 610s Unpacking libspandsp2t64:arm64 (0.0.6+dfsg-2.2) ... 610s Selecting previously unselected package libspeex1:arm64. 610s Preparing to unpack .../41-libspeex1_1.2.1-3_arm64.deb ... 610s Unpacking libspeex1:arm64 (1.2.1-3) ... 610s Selecting previously unselected package libspeexdsp1:arm64. 611s Preparing to unpack .../42-libspeexdsp1_1.2.1-3_arm64.deb ... 611s Unpacking libspeexdsp1:arm64 (1.2.1-3) ... 611s Selecting previously unselected package libsrtp2-1:arm64. 611s Preparing to unpack .../43-libsrtp2-1_2.7.0-3_arm64.deb ... 611s Unpacking libsrtp2-1:arm64 (2.7.0-3) ... 611s Selecting previously unselected package freetds-common. 611s Preparing to unpack .../44-freetds-common_1.3.17+ds-2build3_all.deb ... 611s Unpacking freetds-common (1.3.17+ds-2build3) ... 611s Selecting previously unselected package libsybdb5:arm64. 611s Preparing to unpack .../45-libsybdb5_1.3.17+ds-2build3_arm64.deb ... 611s Unpacking libsybdb5:arm64 (1.3.17+ds-2build3) ... 611s Selecting previously unselected package libevent-2.1-7t64:arm64. 611s Preparing to unpack .../46-libevent-2.1-7t64_2.1.12-stable-10_arm64.deb ... 611s Unpacking libevent-2.1-7t64:arm64 (2.1.12-stable-10) ... 611s Selecting previously unselected package libunbound8:arm64. 611s Preparing to unpack .../47-libunbound8_1.22.0-1ubuntu1_arm64.deb ... 611s Unpacking libunbound8:arm64 (1.22.0-1ubuntu1) ... 611s Selecting previously unselected package libvo-amrwbenc0:arm64. 611s Preparing to unpack .../48-libvo-amrwbenc0_0.1.3-2build1_arm64.deb ... 611s Unpacking libvo-amrwbenc0:arm64 (0.1.3-2build1) ... 611s Selecting previously unselected package libvorbis0a:arm64. 611s Preparing to unpack .../49-libvorbis0a_1.3.7-2_arm64.deb ... 611s Unpacking libvorbis0a:arm64 (1.3.7-2) ... 611s Selecting previously unselected package libvorbisenc2:arm64. 611s Preparing to unpack .../50-libvorbisenc2_1.3.7-2_arm64.deb ... 611s Unpacking libvorbisenc2:arm64 (1.3.7-2) ... 611s Selecting previously unselected package libvorbisfile3:arm64. 611s Preparing to unpack .../51-libvorbisfile3_1.3.7-2_arm64.deb ... 611s Unpacking libvorbisfile3:arm64 (1.3.7-2) ... 611s Selecting previously unselected package asterisk-modules. 611s Preparing to unpack .../52-asterisk-modules_1%3a22.2.0~dfsg+~cs6.15.60671435-2_arm64.deb ... 611s Unpacking asterisk-modules (1:22.2.0~dfsg+~cs6.15.60671435-2) ... 611s Selecting previously unselected package liburiparser1:arm64. 611s Preparing to unpack .../53-liburiparser1_0.9.8+dfsg-2_arm64.deb ... 611s Unpacking liburiparser1:arm64 (0.9.8+dfsg-2) ... 611s Selecting previously unselected package libxslt1.1:arm64. 612s Preparing to unpack .../54-libxslt1.1_1.1.39-0exp1ubuntu4_arm64.deb ... 612s Unpacking libxslt1.1:arm64 (1.1.39-0exp1ubuntu4) ... 612s Selecting previously unselected package asterisk. 612s Preparing to unpack .../55-asterisk_1%3a22.2.0~dfsg+~cs6.15.60671435-2_arm64.deb ... 612s Unpacking asterisk (1:22.2.0~dfsg+~cs6.15.60671435-2) ... 612s Setting up libsharpyuv0:arm64 (1.5.0-0.1) ... 612s Setting up libvo-amrwbenc0:arm64 (0.1.3-2build1) ... 612s Setting up libneon27t64:arm64 (0.34.2-1) ... 612s Setting up libogg0:arm64 (1.3.5-3build1) ... 612s Setting up liblerc4:arm64 (4.0.0+ds-5ubuntu1) ... 612s Setting up libspeex1:arm64 (1.2.1-3) ... 612s Setting up libgsm1:arm64 (1.0.22-1build1) ... 612s Setting up asterisk-core-sounds-en-gsm (1.6.1-1) ... 612s Setting up libsnmp-base (5.9.4+dfsg-1.1ubuntu7) ... 612s Setting up libcodec2-1.2:arm64 (1.2.0-3) ... 612s Setting up mlock (8:2007f~dfsg-7.1) ... 612s Setting up libsrtp2-1:arm64 (2.7.0-3) ... 612s Setting up libpq5:arm64 (17.4-1) ... 612s Setting up libdeflate0:arm64 (1.23-2) ... 612s Setting up libevent-2.1-7t64:arm64 (2.1.12-stable-10) ... 612s Setting up libb64-0d:arm64 (1.2-5build1) ... 612s Setting up libjwt2:arm64 (1.17.2-1) ... 612s Setting up libjbig0:arm64 (2.1-6.1ubuntu2) ... 612s Setting up libasound2-data (1.2.13-1build1) ... 612s Setting up libopencore-amrwb0:arm64 (0.1.6-1build1) ... 612s Setting up libunbound8:arm64 (1.22.0-1ubuntu1) ... 612s Setting up libasound2t64:arm64 (1.2.13-1build1) ... 612s Setting up libradcli4 (1.2.11-1build3) ... 612s Setting up libopus0:arm64 (1.5.2-2) ... 612s Setting up asterisk-config (1:22.2.0~dfsg+~cs6.15.60671435-2) ... 612s Setting up libvorbis0a:arm64 (1.3.7-2) ... 612s Setting up libical3t64:arm64 (3.0.20-1) ... 612s Setting up libjpeg-turbo8:arm64 (2.1.5-3ubuntu2) ... 612s Setting up libltdl7:arm64 (2.5.4-4) ... 612s Setting up asterisk-core-sounds-en (1.6.1-1) ... 612s update-alternatives: using /usr/share/asterisk/sounds/en_US_f_Allison to provide /usr/share/asterisk/sounds/en (asterisk-prompt-en) in auto mode 612s 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 612s Setting up libwebp7:arm64 (1.5.0-0.1) ... 612s Setting up libiksemel3:arm64 (1.4-4build2) ... 612s Setting up libodbc2:arm64 (2.3.12-2ubuntu1) ... 612s Setting up liburiparser1:arm64 (0.9.8+dfsg-2) ... 612s Setting up libspeexdsp1:arm64 (1.2.1-3) ... 612s Setting up liblua5.1-0:arm64 (5.1.5-11) ... 612s Setting up libxslt1.1:arm64 (1.1.39-0exp1ubuntu4) ... 612s Setting up libopencore-amrnb0:arm64 (0.1.6-1build1) ... 612s Setting up libc-client2007e (8:2007f~dfsg-7.1) ... 612s Setting up libresample1 (0.1.3-8) ... 612s Setting up freetds-common (1.3.17+ds-2build3) ... 612s Setting up libgmime-3.0-0t64:arm64 (3.2.15+dfsg-1) ... 612s Setting up libsamplerate0:arm64 (0.2.2-4build1) ... 612s Setting up libopusfile0:arm64 (0.12-4build3) ... 612s Setting up libvorbisenc2:arm64 (1.3.7-2) ... 612s Setting up libjpeg8:arm64 (8c-2ubuntu11) ... 612s Setting up libopusenc0:arm64 (0.2.1-2build1) ... 612s Setting up libsnmp40t64:arm64 (5.9.4+dfsg-1.1ubuntu7) ... 612s Setting up libsybdb5:arm64 (1.3.17+ds-2build3) ... 612s Setting up libvorbisfile3:arm64 (1.3.7-2) ... 612s Setting up libjack-jackd2-0:arm64 (1.9.22~dfsg-4) ... 612s Setting up libtiff6:arm64 (4.7.0-3ubuntu1) ... 612s Setting up libportaudio2:arm64 (19.6.0-1.2build3) ... 612s Setting up libspandsp2t64:arm64 (0.0.6+dfsg-2.2) ... 612s Setting up asterisk-modules (1:22.2.0~dfsg+~cs6.15.60671435-2) ... 612s Setting up asterisk (1:22.2.0~dfsg+~cs6.15.60671435-2) ... 612s Adding system user for Asterisk 612s info: Adding user `asterisk' to group `dialout' ... 612s info: Adding user `asterisk' to group `audio' ... 613s Created symlink '/etc/systemd/system/multi-user.target.wants/asterisk.service' → '/usr/lib/systemd/system/asterisk.service'. 614s Processing triggers for man-db (2.13.1-1) ... 616s Processing triggers for libc-bin (2.41-6ubuntu1) ... 641s autopkgtest [20:44:46]: test amr: [----------------------- 641s 1 audio amr amr 0 (AMR) 641s 2 audio amrwb amrwb 0 (AMR-WB) 641s amr amrwb codec2 ulaw alaw gsm g726 g726aal2 adpcm slin8 slin12 slin16 slin24 slin32 slin44 slin48 slin96 slin192 lpc10 speex8 speex16 speex32 g722 opus 641s amr - 23000 15000 15000 15000 15000 15000 15000 15000 9000 17000 17000 17000 17000 17000 17000 17000 17000 15000 15000 23000 23000 17250 15000 641s amr amrwb codec2 ulaw alaw gsm g726 g726aal2 adpcm slin8 slin12 slin16 slin24 slin32 slin44 slin48 slin96 slin192 lpc10 speex8 speex16 speex32 g722 opus 641s amrwb 23500 - 23500 23500 23500 23500 23500 23500 23500 17500 17500 9000 17000 17000 17000 17000 17000 17000 23500 23500 15000 23000 15000 14999 642s autopkgtest [20:44:47]: test amr: -----------------------] 642s autopkgtest [20:44:47]: test amr: - - - - - - - - - - results - - - - - - - - - - 642s amr PASS 643s autopkgtest [20:44:48]: @@@@@@@@@@@@@@@@@@@@ summary 643s asttestmods PASS 643s amr PASS 660s nova [W] Using flock in prodstack6-arm64 660s Creating nova instance adt-questing-arm64-asterisk-20250504-203405-juju-7f2275-prod-proposed-migration-environment-15-3acde24b-113b-4fdd-b834-2687420d6e41 from image adt/ubuntu-questing-arm64-server-20250504.img (UUID 3e7dda1a-15da-4805-968a-898260235e53)... 660s nova [W] Timed out waiting for c78371cd-72c9-4336-a919-34ad1505b1bc to get deleted. 660s nova [W] Using flock in prodstack6-arm64 660s flock: timeout while waiting to get lock 660s Creating nova instance adt-questing-arm64-asterisk-20250504-203405-juju-7f2275-prod-proposed-migration-environment-15-3acde24b-113b-4fdd-b834-2687420d6e41 from image adt/ubuntu-questing-arm64-server-20250504.img (UUID 3e7dda1a-15da-4805-968a-898260235e53)... 660s nova [W] Timed out waiting for 4831509d-4977-4d6d-84b7-a8a6f57d1045 to get deleted.