0s autopkgtest [17:57:02]: starting date and time: 2024-04-19 17:57:02+0000 0s autopkgtest [17:57:02]: git checkout: 43bc6cdf gitlab-ci: do not include the salsa pipeline 0s autopkgtest [17:57:02]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.4jwdamu0/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:systemd --apt-upgrade asterisk --timeout-short=300 --timeout-copy=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=systemd/255.4-1ubuntu8 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos02-ppc64el-6.secgroup --name adt-noble-ppc64el-asterisk-20240419-175702-juju-7f2275-prod-proposed-migration-environment-3-909d6297-3272-4708-86ed-9201ea8ff7f9 --image adt/ubuntu-noble-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-3 --net-id=net_prod-proposed-migration -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 152s autopkgtest [17:59:34]: testbed dpkg architecture: ppc64el 152s autopkgtest [17:59:34]: testbed apt version: 2.7.14build2 152s autopkgtest [17:59:34]: @@@@@@@@@@@@@@@@@@@@ test bed setup 153s Get:1 http://ftpmaster.internal/ubuntu noble-proposed InRelease [117 kB] 153s Get:2 http://ftpmaster.internal/ubuntu noble-proposed/universe Sources [263 kB] 153s Get:3 http://ftpmaster.internal/ubuntu noble-proposed/multiverse Sources [2340 B] 153s Get:4 http://ftpmaster.internal/ubuntu noble-proposed/restricted Sources [12.3 kB] 153s Get:5 http://ftpmaster.internal/ubuntu noble-proposed/main Sources [49.3 kB] 153s Get:6 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el Packages [82.1 kB] 153s Get:7 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el c-n-f Metadata [3116 B] 153s Get:8 http://ftpmaster.internal/ubuntu noble-proposed/restricted ppc64el Packages [976 B] 153s Get:9 http://ftpmaster.internal/ubuntu noble-proposed/restricted ppc64el c-n-f Metadata [116 B] 153s Get:10 http://ftpmaster.internal/ubuntu noble-proposed/universe ppc64el Packages [234 kB] 153s Get:11 http://ftpmaster.internal/ubuntu noble-proposed/universe ppc64el c-n-f Metadata [8652 B] 153s Get:12 http://ftpmaster.internal/ubuntu noble-proposed/multiverse ppc64el Packages [1376 B] 153s Get:13 http://ftpmaster.internal/ubuntu noble-proposed/multiverse ppc64el c-n-f Metadata [116 B] 155s Fetched 775 kB in 1s (919 kB/s) 155s Reading package lists... 157s sh: 4: dhclient: not found 157s Reading package lists... 157s Building dependency tree... 157s Reading state information... 158s Calculating upgrade... 158s The following packages will be upgraded: 158s libnss-systemd libpam-systemd libsystemd-shared libsystemd0 libudev1 systemd 158s systemd-dev systemd-resolved systemd-sysv systemd-timesyncd udev 158s 11 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 158s Need to get 9899 kB of archives. 158s After this operation, 6144 B of additional disk space will be used. 158s Get:1 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el systemd-dev all 255.4-1ubuntu8 [104 kB] 158s Get:2 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el systemd-timesyncd ppc64el 255.4-1ubuntu8 [37.9 kB] 158s Get:3 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el systemd-resolved ppc64el 255.4-1ubuntu8 [347 kB] 158s Get:4 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el libsystemd-shared ppc64el 255.4-1ubuntu8 [2351 kB] 159s Get:5 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el libsystemd0 ppc64el 255.4-1ubuntu8 [526 kB] 159s Get:6 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el systemd-sysv ppc64el 255.4-1ubuntu8 [11.9 kB] 159s Get:7 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el libnss-systemd ppc64el 255.4-1ubuntu8 [208 kB] 159s Get:8 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el libpam-systemd ppc64el 255.4-1ubuntu8 [304 kB] 159s Get:9 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el systemd ppc64el 255.4-1ubuntu8 [3771 kB] 159s Get:10 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el udev ppc64el 255.4-1ubuntu8 [2038 kB] 159s Get:11 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el libudev1 ppc64el 255.4-1ubuntu8 [201 kB] 159s Fetched 9899 kB in 1s (8158 kB/s) 159s (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 ... 72009 files and directories currently installed.) 159s Preparing to unpack .../systemd-dev_255.4-1ubuntu8_all.deb ... 159s Unpacking systemd-dev (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 159s Preparing to unpack .../systemd-timesyncd_255.4-1ubuntu8_ppc64el.deb ... 159s Unpacking systemd-timesyncd (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 159s Preparing to unpack .../systemd-resolved_255.4-1ubuntu8_ppc64el.deb ... 159s Unpacking systemd-resolved (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 159s Preparing to unpack .../libsystemd-shared_255.4-1ubuntu8_ppc64el.deb ... 159s Unpacking libsystemd-shared:ppc64el (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 159s Preparing to unpack .../libsystemd0_255.4-1ubuntu8_ppc64el.deb ... 159s Unpacking libsystemd0:ppc64el (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 160s Setting up libsystemd0:ppc64el (255.4-1ubuntu8) ... 160s (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 ... 72009 files and directories currently installed.) 160s Preparing to unpack .../0-systemd-sysv_255.4-1ubuntu8_ppc64el.deb ... 160s Unpacking systemd-sysv (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 160s Preparing to unpack .../1-libnss-systemd_255.4-1ubuntu8_ppc64el.deb ... 160s Unpacking libnss-systemd:ppc64el (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 160s Preparing to unpack .../2-libpam-systemd_255.4-1ubuntu8_ppc64el.deb ... 160s Unpacking libpam-systemd:ppc64el (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 160s Preparing to unpack .../3-systemd_255.4-1ubuntu8_ppc64el.deb ... 160s Unpacking systemd (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 160s Preparing to unpack .../4-udev_255.4-1ubuntu8_ppc64el.deb ... 160s Unpacking udev (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 160s Preparing to unpack .../5-libudev1_255.4-1ubuntu8_ppc64el.deb ... 160s Unpacking libudev1:ppc64el (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 160s Setting up libudev1:ppc64el (255.4-1ubuntu8) ... 160s Setting up systemd-dev (255.4-1ubuntu8) ... 160s Setting up libsystemd-shared:ppc64el (255.4-1ubuntu8) ... 160s Setting up systemd (255.4-1ubuntu8) ... 161s Setting up systemd-timesyncd (255.4-1ubuntu8) ... 161s Setting up udev (255.4-1ubuntu8) ... 162s Setting up systemd-resolved (255.4-1ubuntu8) ... 163s Setting up systemd-sysv (255.4-1ubuntu8) ... 163s Setting up libnss-systemd:ppc64el (255.4-1ubuntu8) ... 163s Setting up libpam-systemd:ppc64el (255.4-1ubuntu8) ... 163s Processing triggers for libc-bin (2.39-0ubuntu8) ... 163s Processing triggers for man-db (2.12.0-4build2) ... 164s Processing triggers for dbus (1.14.10-4ubuntu4) ... 164s Processing triggers for initramfs-tools (0.142ubuntu25) ... 164s update-initramfs: Generating /boot/initrd.img-6.8.0-22-generic 164s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 170s Reading package lists... 170s Building dependency tree... 170s Reading state information... 170s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 171s Hit:1 http://ftpmaster.internal/ubuntu noble-proposed InRelease 171s Hit:2 http://ftpmaster.internal/ubuntu noble InRelease 171s Hit:3 http://ftpmaster.internal/ubuntu noble-updates InRelease 171s Hit:4 http://ftpmaster.internal/ubuntu noble-security InRelease 172s Reading package lists... 172s Reading package lists... 172s Building dependency tree... 172s Reading state information... 172s Calculating upgrade... 172s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 172s Reading package lists... 173s Building dependency tree... 173s Reading state information... 173s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 173s autopkgtest [17:59:55]: rebooting testbed after setup commands that affected boot 211s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 223s autopkgtest [18:00:45]: testbed running kernel: Linux 6.8.0-22-generic #22-Ubuntu SMP Thu Apr 4 22:47:57 UTC 2024 226s autopkgtest [18:00:48]: @@@@@@@@@@@@@@@@@@@@ apt-source asterisk 246s Get:1 http://ftpmaster.internal/ubuntu noble/universe asterisk 1:20.6.0~dfsg+~cs6.13.40431414-2build5 (dsc) [5436 B] 246s Get:2 http://ftpmaster.internal/ubuntu noble/universe asterisk 1:20.6.0~dfsg+~cs6.13.40431414-2build5 (tar) [11.3 kB] 246s Get:3 http://ftpmaster.internal/ubuntu noble/universe asterisk 1:20.6.0~dfsg+~cs6.13.40431414-2build5 (tar) [21.9 kB] 246s Get:4 http://ftpmaster.internal/ubuntu noble/universe asterisk 1:20.6.0~dfsg+~cs6.13.40431414-2build5 (tar) [22.5 kB] 246s Get:5 http://ftpmaster.internal/ubuntu noble/universe asterisk 1:20.6.0~dfsg+~cs6.13.40431414-2build5 (tar) [5841 kB] 246s Get:6 http://ftpmaster.internal/ubuntu noble/universe asterisk 1:20.6.0~dfsg+~cs6.13.40431414-2build5 (tar) [7300 kB] 246s Get:7 http://ftpmaster.internal/ubuntu noble/universe asterisk 1:20.6.0~dfsg+~cs6.13.40431414-2build5 (diff) [135 kB] 246s gpgv: Signature made Mon Apr 15 00:13:34 2024 UTC 246s gpgv: using RSA key AC0A4FF12611B6FCCF01C111393587D97D86500B 246s gpgv: Can't check signature: No public key 246s dpkg-source: warning: cannot verify inline signature for ./asterisk_20.6.0~dfsg+~cs6.13.40431414-2build5.dsc: no acceptable signature found 248s autopkgtest [18:01:10]: testing package asterisk version 1:20.6.0~dfsg+~cs6.13.40431414-2build5 249s autopkgtest [18:01:11]: build not needed 457s autopkgtest [18:04:39]: test asttestmods: preparing testbed 458s Reading package lists... 458s Building dependency tree... 458s Reading state information... 458s Starting pkgProblemResolver with broken count: 0 459s Starting 2 pkgProblemResolver with broken count: 0 459s Done 459s The following additional packages will be installed: 459s asterisk asterisk-config asterisk-core-sounds-en asterisk-core-sounds-en-gsm 459s asterisk-modules asterisk-tests freetds-common libasound2-data libasound2t64 459s libc-client2007e libcodec2-1.2 libevent-2.1-7t64 libgmime-3.0-0t64 libgsm1 459s libical3t64 libiksemel3 libjack-jackd2-0 libltdl7 liblua5.1-0 libneon27t64 459s libodbc2 libogg0 libopencore-amrnb0 libopencore-amrwb0 libopus0 libopusenc0 459s libopusfile0 libportaudio2 libpq5 libradcli4 libresample1 libsamplerate0 459s libsnmp-base libsnmp40t64 libspandsp2t64 libspeex1 libspeexdsp1 libsrtp2-1 459s libsybdb5 libunbound8 liburiparser1 libvo-amrwbenc0 libvorbis0a 459s libvorbisenc2 libvorbisfile3 libxml2-utils libxslt1.1 mlock 459s Suggested packages: 459s asterisk-dahdi asterisk-dev asterisk-doc asterisk-ooh323 asterisk-opus 459s alsa-utils libasound2-plugins uw-mailutils jackd2 odbc-postgresql tdsodbc 459s opus-tools snmp-mibs-downloader speex 459s Recommended packages: 459s asterisk-moh-opsound-gsm sox alsa-ucm-conf alsa-topology-conf 459s The following NEW packages will be installed: 459s asterisk asterisk-config asterisk-core-sounds-en asterisk-core-sounds-en-gsm 459s asterisk-modules asterisk-tests autopkgtest-satdep freetds-common 459s libasound2-data libasound2t64 libc-client2007e libcodec2-1.2 459s libevent-2.1-7t64 libgmime-3.0-0t64 libgsm1 libical3t64 libiksemel3 459s libjack-jackd2-0 libltdl7 liblua5.1-0 libneon27t64 libodbc2 libogg0 459s libopencore-amrnb0 libopencore-amrwb0 libopus0 libopusenc0 libopusfile0 459s libportaudio2 libpq5 libradcli4 libresample1 libsamplerate0 libsnmp-base 459s libsnmp40t64 libspandsp2t64 libspeex1 libspeexdsp1 libsrtp2-1 libsybdb5 459s libunbound8 liburiparser1 libvo-amrwbenc0 libvorbis0a libvorbisenc2 459s libvorbisfile3 libxml2-utils libxslt1.1 mlock 459s 0 upgraded, 49 newly installed, 0 to remove and 0 not upgraded. 459s Need to get 27.3 MB/27.3 MB of archives. 459s After this operation, 97.6 MB of additional disk space will be used. 459s Get:1 /tmp/autopkgtest.Fb03Z3/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [740 B] 459s Get:2 http://ftpmaster.internal/ubuntu noble/universe ppc64el asterisk-config all 1:20.6.0~dfsg+~cs6.13.40431414-2build5 [242 kB] 459s Get:3 http://ftpmaster.internal/ubuntu noble/universe ppc64el asterisk-core-sounds-en-gsm all 1.6.1-1 [2417 kB] 461s Get:4 http://ftpmaster.internal/ubuntu noble/universe ppc64el asterisk-core-sounds-en all 1.6.1-1 [20.6 kB] 461s Get:5 http://ftpmaster.internal/ubuntu noble/universe ppc64el mlock ppc64el 8:2007f~dfsg-7build3 [8082 B] 461s Get:6 http://ftpmaster.internal/ubuntu noble/universe ppc64el libc-client2007e ppc64el 8:2007f~dfsg-7build3 [676 kB] 461s Get:7 http://ftpmaster.internal/ubuntu noble/universe ppc64el libcodec2-1.2 ppc64el 1.2.0-2build1 [9048 kB] 462s Get:8 http://ftpmaster.internal/ubuntu noble/universe ppc64el libgmime-3.0-0t64 ppc64el 3.2.13+dfsg-2.1build2 [207 kB] 462s Get:9 http://ftpmaster.internal/ubuntu noble/universe ppc64el libgsm1 ppc64el 1.0.22-1build1 [41.9 kB] 462s Get:10 http://ftpmaster.internal/ubuntu noble/main ppc64el libical3t64 ppc64el 3.0.17-1.1build3 [349 kB] 462s Get:11 http://ftpmaster.internal/ubuntu noble/universe ppc64el libiksemel3 ppc64el 1.4-4build2 [34.8 kB] 462s Get:12 http://ftpmaster.internal/ubuntu noble/main ppc64el libopus0 ppc64el 1.4-1build1 [322 kB] 462s Get:13 http://ftpmaster.internal/ubuntu noble/main ppc64el libsamplerate0 ppc64el 0.2.2-4build1 [1348 kB] 463s Get:14 http://ftpmaster.internal/ubuntu noble/main ppc64el libjack-jackd2-0 ppc64el 1.9.21~dfsg-3ubuntu3 [340 kB] 463s Get:15 http://ftpmaster.internal/ubuntu noble/universe ppc64el liblua5.1-0 ppc64el 5.1.5-9build2 [157 kB] 463s Get:16 http://ftpmaster.internal/ubuntu noble/universe ppc64el libneon27t64 ppc64el 0.33.0-1.1build3 [120 kB] 463s Get:17 http://ftpmaster.internal/ubuntu noble/main ppc64el libltdl7 ppc64el 2.4.7-7build1 [48.2 kB] 463s Get:18 http://ftpmaster.internal/ubuntu noble/main ppc64el libodbc2 ppc64el 2.3.12-1build2 [188 kB] 463s Get:19 http://ftpmaster.internal/ubuntu noble/main ppc64el libogg0 ppc64el 1.3.5-3build1 [27.6 kB] 463s Get:20 http://ftpmaster.internal/ubuntu noble/universe ppc64el libopencore-amrnb0 ppc64el 0.1.6-1build1 [165 kB] 463s Get:21 http://ftpmaster.internal/ubuntu noble/universe ppc64el libopencore-amrwb0 ppc64el 0.1.6-1build1 [91.2 kB] 463s Get:22 http://ftpmaster.internal/ubuntu noble/universe ppc64el libopusenc0 ppc64el 0.2.1-2 [33.9 kB] 463s Get:23 http://ftpmaster.internal/ubuntu noble/universe ppc64el libopusfile0 ppc64el 0.12-4build3 [60.6 kB] 463s Get:24 http://ftpmaster.internal/ubuntu noble/main ppc64el libasound2-data all 1.2.11-1build2 [21.0 kB] 463s Get:25 http://ftpmaster.internal/ubuntu noble/main ppc64el libasound2t64 ppc64el 1.2.11-1build2 [502 kB] 463s Get:26 http://ftpmaster.internal/ubuntu noble/universe ppc64el libportaudio2 ppc64el 19.6.0-1.2build3 [87.5 kB] 463s Get:27 http://ftpmaster.internal/ubuntu noble/main ppc64el libpq5 ppc64el 16.2-1ubuntu4 [170 kB] 463s Get:28 http://ftpmaster.internal/ubuntu noble/universe ppc64el libradcli4 ppc64el 1.2.11-1build3 [45.5 kB] 463s Get:29 http://ftpmaster.internal/ubuntu noble/universe ppc64el libresample1 ppc64el 0.1.3-6 [11.1 kB] 463s Get:30 http://ftpmaster.internal/ubuntu noble/main ppc64el libsnmp-base all 5.9.4+dfsg-1.1ubuntu3 [206 kB] 463s Get:31 http://ftpmaster.internal/ubuntu noble/main ppc64el libsnmp40t64 ppc64el 5.9.4+dfsg-1.1ubuntu3 [1206 kB] 463s Get:32 http://ftpmaster.internal/ubuntu noble/universe ppc64el libspandsp2t64 ppc64el 0.0.6+dfsg-2.1build1 [399 kB] 463s Get:33 http://ftpmaster.internal/ubuntu noble/main ppc64el libspeex1 ppc64el 1.2.1-2ubuntu2 [111 kB] 463s Get:34 http://ftpmaster.internal/ubuntu noble/main ppc64el libspeexdsp1 ppc64el 1.2.1-1ubuntu3 [75.0 kB] 463s Get:35 http://ftpmaster.internal/ubuntu noble/universe ppc64el libsrtp2-1 ppc64el 2.5.0-3build1 [51.4 kB] 463s Get:36 http://ftpmaster.internal/ubuntu noble/main ppc64el freetds-common all 1.3.17+ds-2build3 [26.9 kB] 463s Get:37 http://ftpmaster.internal/ubuntu noble/main ppc64el libsybdb5 ppc64el 1.3.17+ds-2build3 [238 kB] 463s Get:38 http://ftpmaster.internal/ubuntu noble/main ppc64el libevent-2.1-7t64 ppc64el 2.1.12-stable-9ubuntu2 [174 kB] 463s Get:39 http://ftpmaster.internal/ubuntu noble/main ppc64el libunbound8 ppc64el 1.19.2-1ubuntu3 [537 kB] 463s Get:40 http://ftpmaster.internal/ubuntu noble/universe ppc64el libvo-amrwbenc0 ppc64el 0.1.3-2build1 [126 kB] 463s Get:41 http://ftpmaster.internal/ubuntu noble/main ppc64el libvorbis0a ppc64el 1.3.7-1build3 [142 kB] 463s Get:42 http://ftpmaster.internal/ubuntu noble/main ppc64el libvorbisenc2 ppc64el 1.3.7-1build3 [86.6 kB] 463s Get:43 http://ftpmaster.internal/ubuntu noble/main ppc64el libvorbisfile3 ppc64el 1.3.7-1build3 [22.9 kB] 463s Get:44 http://ftpmaster.internal/ubuntu noble/universe ppc64el asterisk-modules ppc64el 1:20.6.0~dfsg+~cs6.13.40431414-2build5 [3407 kB] 463s Get:45 http://ftpmaster.internal/ubuntu noble/universe ppc64el liburiparser1 ppc64el 0.9.7+dfsg-2build1 [53.6 kB] 463s Get:46 http://ftpmaster.internal/ubuntu noble/main ppc64el libxslt1.1 ppc64el 1.1.39-0exp1build1 [192 kB] 463s Get:47 http://ftpmaster.internal/ubuntu noble/universe ppc64el asterisk ppc64el 1:20.6.0~dfsg+~cs6.13.40431414-2build5 [2812 kB] 464s Get:48 http://ftpmaster.internal/ubuntu noble/universe ppc64el asterisk-tests ppc64el 1:20.6.0~dfsg+~cs6.13.40431414-2build5 [576 kB] 464s Get:49 http://ftpmaster.internal/ubuntu noble/main ppc64el libxml2-utils ppc64el 2.9.14+dfsg-1.3ubuntu3 [42.2 kB] 464s Fetched 27.3 MB in 5s (5689 kB/s) 464s Selecting previously unselected package asterisk-config. 464s (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 ... 72009 files and directories currently installed.) 464s Preparing to unpack .../00-asterisk-config_1%3a20.6.0~dfsg+~cs6.13.40431414-2build5_all.deb ... 464s Unpacking asterisk-config (1:20.6.0~dfsg+~cs6.13.40431414-2build5) ... 464s Selecting previously unselected package asterisk-core-sounds-en-gsm. 464s Preparing to unpack .../01-asterisk-core-sounds-en-gsm_1.6.1-1_all.deb ... 464s Unpacking asterisk-core-sounds-en-gsm (1.6.1-1) ... 464s Selecting previously unselected package asterisk-core-sounds-en. 464s Preparing to unpack .../02-asterisk-core-sounds-en_1.6.1-1_all.deb ... 464s Unpacking asterisk-core-sounds-en (1.6.1-1) ... 464s Selecting previously unselected package mlock. 464s Preparing to unpack .../03-mlock_8%3a2007f~dfsg-7build3_ppc64el.deb ... 464s Unpacking mlock (8:2007f~dfsg-7build3) ... 464s Selecting previously unselected package libc-client2007e. 464s Preparing to unpack .../04-libc-client2007e_8%3a2007f~dfsg-7build3_ppc64el.deb ... 464s Unpacking libc-client2007e (8:2007f~dfsg-7build3) ... 464s Selecting previously unselected package libcodec2-1.2:ppc64el. 464s Preparing to unpack .../05-libcodec2-1.2_1.2.0-2build1_ppc64el.deb ... 464s Unpacking libcodec2-1.2:ppc64el (1.2.0-2build1) ... 464s Selecting previously unselected package libgmime-3.0-0t64:ppc64el. 464s Preparing to unpack .../06-libgmime-3.0-0t64_3.2.13+dfsg-2.1build2_ppc64el.deb ... 464s Unpacking libgmime-3.0-0t64:ppc64el (3.2.13+dfsg-2.1build2) ... 464s Selecting previously unselected package libgsm1:ppc64el. 464s Preparing to unpack .../07-libgsm1_1.0.22-1build1_ppc64el.deb ... 464s Unpacking libgsm1:ppc64el (1.0.22-1build1) ... 464s Selecting previously unselected package libical3t64:ppc64el. 464s Preparing to unpack .../08-libical3t64_3.0.17-1.1build3_ppc64el.deb ... 464s Unpacking libical3t64:ppc64el (3.0.17-1.1build3) ... 465s Selecting previously unselected package libiksemel3:ppc64el. 465s Preparing to unpack .../09-libiksemel3_1.4-4build2_ppc64el.deb ... 465s Unpacking libiksemel3:ppc64el (1.4-4build2) ... 465s Selecting previously unselected package libopus0:ppc64el. 465s Preparing to unpack .../10-libopus0_1.4-1build1_ppc64el.deb ... 465s Unpacking libopus0:ppc64el (1.4-1build1) ... 465s Selecting previously unselected package libsamplerate0:ppc64el. 465s Preparing to unpack .../11-libsamplerate0_0.2.2-4build1_ppc64el.deb ... 465s Unpacking libsamplerate0:ppc64el (0.2.2-4build1) ... 465s Selecting previously unselected package libjack-jackd2-0:ppc64el. 465s Preparing to unpack .../12-libjack-jackd2-0_1.9.21~dfsg-3ubuntu3_ppc64el.deb ... 465s Unpacking libjack-jackd2-0:ppc64el (1.9.21~dfsg-3ubuntu3) ... 465s Selecting previously unselected package liblua5.1-0:ppc64el. 465s Preparing to unpack .../13-liblua5.1-0_5.1.5-9build2_ppc64el.deb ... 465s Unpacking liblua5.1-0:ppc64el (5.1.5-9build2) ... 465s Selecting previously unselected package libneon27t64:ppc64el. 465s Preparing to unpack .../14-libneon27t64_0.33.0-1.1build3_ppc64el.deb ... 465s Unpacking libneon27t64:ppc64el (0.33.0-1.1build3) ... 465s Selecting previously unselected package libltdl7:ppc64el. 465s Preparing to unpack .../15-libltdl7_2.4.7-7build1_ppc64el.deb ... 465s Unpacking libltdl7:ppc64el (2.4.7-7build1) ... 465s Selecting previously unselected package libodbc2:ppc64el. 465s Preparing to unpack .../16-libodbc2_2.3.12-1build2_ppc64el.deb ... 465s Unpacking libodbc2:ppc64el (2.3.12-1build2) ... 465s Selecting previously unselected package libogg0:ppc64el. 465s Preparing to unpack .../17-libogg0_1.3.5-3build1_ppc64el.deb ... 465s Unpacking libogg0:ppc64el (1.3.5-3build1) ... 465s Selecting previously unselected package libopencore-amrnb0:ppc64el. 465s Preparing to unpack .../18-libopencore-amrnb0_0.1.6-1build1_ppc64el.deb ... 465s Unpacking libopencore-amrnb0:ppc64el (0.1.6-1build1) ... 465s Selecting previously unselected package libopencore-amrwb0:ppc64el. 465s Preparing to unpack .../19-libopencore-amrwb0_0.1.6-1build1_ppc64el.deb ... 465s Unpacking libopencore-amrwb0:ppc64el (0.1.6-1build1) ... 465s Selecting previously unselected package libopusenc0:ppc64el. 465s Preparing to unpack .../20-libopusenc0_0.2.1-2_ppc64el.deb ... 465s Unpacking libopusenc0:ppc64el (0.2.1-2) ... 465s Selecting previously unselected package libopusfile0:ppc64el. 465s Preparing to unpack .../21-libopusfile0_0.12-4build3_ppc64el.deb ... 465s Unpacking libopusfile0:ppc64el (0.12-4build3) ... 465s Selecting previously unselected package libasound2-data. 465s Preparing to unpack .../22-libasound2-data_1.2.11-1build2_all.deb ... 465s Unpacking libasound2-data (1.2.11-1build2) ... 465s Selecting previously unselected package libasound2t64:ppc64el. 465s Preparing to unpack .../23-libasound2t64_1.2.11-1build2_ppc64el.deb ... 465s Unpacking libasound2t64:ppc64el (1.2.11-1build2) ... 465s Selecting previously unselected package libportaudio2:ppc64el. 465s Preparing to unpack .../24-libportaudio2_19.6.0-1.2build3_ppc64el.deb ... 465s Unpacking libportaudio2:ppc64el (19.6.0-1.2build3) ... 465s Selecting previously unselected package libpq5:ppc64el. 465s Preparing to unpack .../25-libpq5_16.2-1ubuntu4_ppc64el.deb ... 465s Unpacking libpq5:ppc64el (16.2-1ubuntu4) ... 465s Selecting previously unselected package libradcli4. 465s Preparing to unpack .../26-libradcli4_1.2.11-1build3_ppc64el.deb ... 465s Unpacking libradcli4 (1.2.11-1build3) ... 465s Selecting previously unselected package libresample1. 465s Preparing to unpack .../27-libresample1_0.1.3-6_ppc64el.deb ... 465s Unpacking libresample1 (0.1.3-6) ... 465s Selecting previously unselected package libsnmp-base. 465s Preparing to unpack .../28-libsnmp-base_5.9.4+dfsg-1.1ubuntu3_all.deb ... 465s Unpacking libsnmp-base (5.9.4+dfsg-1.1ubuntu3) ... 465s Selecting previously unselected package libsnmp40t64:ppc64el. 465s Preparing to unpack .../29-libsnmp40t64_5.9.4+dfsg-1.1ubuntu3_ppc64el.deb ... 465s Unpacking libsnmp40t64:ppc64el (5.9.4+dfsg-1.1ubuntu3) ... 465s Selecting previously unselected package libspandsp2t64:ppc64el. 465s Preparing to unpack .../30-libspandsp2t64_0.0.6+dfsg-2.1build1_ppc64el.deb ... 465s Unpacking libspandsp2t64:ppc64el (0.0.6+dfsg-2.1build1) ... 465s Selecting previously unselected package libspeex1:ppc64el. 465s Preparing to unpack .../31-libspeex1_1.2.1-2ubuntu2_ppc64el.deb ... 465s Unpacking libspeex1:ppc64el (1.2.1-2ubuntu2) ... 465s Selecting previously unselected package libspeexdsp1:ppc64el. 465s Preparing to unpack .../32-libspeexdsp1_1.2.1-1ubuntu3_ppc64el.deb ... 465s Unpacking libspeexdsp1:ppc64el (1.2.1-1ubuntu3) ... 465s Selecting previously unselected package libsrtp2-1:ppc64el. 465s Preparing to unpack .../33-libsrtp2-1_2.5.0-3build1_ppc64el.deb ... 465s Unpacking libsrtp2-1:ppc64el (2.5.0-3build1) ... 465s Selecting previously unselected package freetds-common. 465s Preparing to unpack .../34-freetds-common_1.3.17+ds-2build3_all.deb ... 465s Unpacking freetds-common (1.3.17+ds-2build3) ... 465s Selecting previously unselected package libsybdb5:ppc64el. 465s Preparing to unpack .../35-libsybdb5_1.3.17+ds-2build3_ppc64el.deb ... 465s Unpacking libsybdb5:ppc64el (1.3.17+ds-2build3) ... 465s Selecting previously unselected package libevent-2.1-7t64:ppc64el. 465s Preparing to unpack .../36-libevent-2.1-7t64_2.1.12-stable-9ubuntu2_ppc64el.deb ... 465s Unpacking libevent-2.1-7t64:ppc64el (2.1.12-stable-9ubuntu2) ... 465s Selecting previously unselected package libunbound8:ppc64el. 465s Preparing to unpack .../37-libunbound8_1.19.2-1ubuntu3_ppc64el.deb ... 465s Unpacking libunbound8:ppc64el (1.19.2-1ubuntu3) ... 465s Selecting previously unselected package libvo-amrwbenc0:ppc64el. 465s Preparing to unpack .../38-libvo-amrwbenc0_0.1.3-2build1_ppc64el.deb ... 465s Unpacking libvo-amrwbenc0:ppc64el (0.1.3-2build1) ... 465s Selecting previously unselected package libvorbis0a:ppc64el. 465s Preparing to unpack .../39-libvorbis0a_1.3.7-1build3_ppc64el.deb ... 465s Unpacking libvorbis0a:ppc64el (1.3.7-1build3) ... 465s Selecting previously unselected package libvorbisenc2:ppc64el. 465s Preparing to unpack .../40-libvorbisenc2_1.3.7-1build3_ppc64el.deb ... 465s Unpacking libvorbisenc2:ppc64el (1.3.7-1build3) ... 465s Selecting previously unselected package libvorbisfile3:ppc64el. 465s Preparing to unpack .../41-libvorbisfile3_1.3.7-1build3_ppc64el.deb ... 465s Unpacking libvorbisfile3:ppc64el (1.3.7-1build3) ... 465s Selecting previously unselected package asterisk-modules. 465s Preparing to unpack .../42-asterisk-modules_1%3a20.6.0~dfsg+~cs6.13.40431414-2build5_ppc64el.deb ... 465s Unpacking asterisk-modules (1:20.6.0~dfsg+~cs6.13.40431414-2build5) ... 465s Selecting previously unselected package liburiparser1:ppc64el. 465s Preparing to unpack .../43-liburiparser1_0.9.7+dfsg-2build1_ppc64el.deb ... 465s Unpacking liburiparser1:ppc64el (0.9.7+dfsg-2build1) ... 465s Selecting previously unselected package libxslt1.1:ppc64el. 465s Preparing to unpack .../44-libxslt1.1_1.1.39-0exp1build1_ppc64el.deb ... 465s Unpacking libxslt1.1:ppc64el (1.1.39-0exp1build1) ... 465s Selecting previously unselected package asterisk. 465s Preparing to unpack .../45-asterisk_1%3a20.6.0~dfsg+~cs6.13.40431414-2build5_ppc64el.deb ... 465s Unpacking asterisk (1:20.6.0~dfsg+~cs6.13.40431414-2build5) ... 466s Selecting previously unselected package asterisk-tests. 466s Preparing to unpack .../46-asterisk-tests_1%3a20.6.0~dfsg+~cs6.13.40431414-2build5_ppc64el.deb ... 466s Unpacking asterisk-tests (1:20.6.0~dfsg+~cs6.13.40431414-2build5) ... 466s Selecting previously unselected package libxml2-utils. 466s Preparing to unpack .../47-libxml2-utils_2.9.14+dfsg-1.3ubuntu3_ppc64el.deb ... 466s Unpacking libxml2-utils (2.9.14+dfsg-1.3ubuntu3) ... 466s Selecting previously unselected package autopkgtest-satdep. 466s Preparing to unpack .../48-1-autopkgtest-satdep.deb ... 466s Unpacking autopkgtest-satdep (0) ... 466s Setting up libvo-amrwbenc0:ppc64el (0.1.3-2build1) ... 466s Setting up libneon27t64:ppc64el (0.33.0-1.1build3) ... 466s Setting up libogg0:ppc64el (1.3.5-3build1) ... 466s Setting up libspeex1:ppc64el (1.2.1-2ubuntu2) ... 466s Setting up libgsm1:ppc64el (1.0.22-1build1) ... 466s Setting up asterisk-core-sounds-en-gsm (1.6.1-1) ... 466s Setting up libsnmp-base (5.9.4+dfsg-1.1ubuntu3) ... 466s Setting up libcodec2-1.2:ppc64el (1.2.0-2build1) ... 466s Setting up mlock (8:2007f~dfsg-7build3) ... 466s Setting up libsrtp2-1:ppc64el (2.5.0-3build1) ... 466s Setting up libpq5:ppc64el (16.2-1ubuntu4) ... 466s Setting up libevent-2.1-7t64:ppc64el (2.1.12-stable-9ubuntu2) ... 466s Setting up libasound2-data (1.2.11-1build2) ... 466s Setting up libopencore-amrwb0:ppc64el (0.1.6-1build1) ... 466s Setting up libunbound8:ppc64el (1.19.2-1ubuntu3) ... 466s Setting up libasound2t64:ppc64el (1.2.11-1build2) ... 466s Setting up libradcli4 (1.2.11-1build3) ... 466s Setting up libopus0:ppc64el (1.4-1build1) ... 466s Setting up asterisk-config (1:20.6.0~dfsg+~cs6.13.40431414-2build5) ... 466s Setting up libvorbis0a:ppc64el (1.3.7-1build3) ... 466s Setting up libical3t64:ppc64el (3.0.17-1.1build3) ... 466s Setting up libltdl7:ppc64el (2.4.7-7build1) ... 466s Setting up asterisk-core-sounds-en (1.6.1-1) ... 466s update-alternatives: using /usr/share/asterisk/sounds/en_US_f_Allison to provide /usr/share/asterisk/sounds/en (asterisk-prompt-en) in auto mode 466s 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 466s Setting up libiksemel3:ppc64el (1.4-4build2) ... 466s Setting up libodbc2:ppc64el (2.3.12-1build2) ... 466s Setting up liburiparser1:ppc64el (0.9.7+dfsg-2build1) ... 466s Setting up libspandsp2t64:ppc64el (0.0.6+dfsg-2.1build1) ... 466s Setting up libspeexdsp1:ppc64el (1.2.1-1ubuntu3) ... 466s Setting up liblua5.1-0:ppc64el (5.1.5-9build2) ... 466s Setting up libxslt1.1:ppc64el (1.1.39-0exp1build1) ... 466s Setting up libopencore-amrnb0:ppc64el (0.1.6-1build1) ... 466s Setting up libc-client2007e (8:2007f~dfsg-7build3) ... 466s Setting up libresample1 (0.1.3-6) ... 466s Setting up freetds-common (1.3.17+ds-2build3) ... 466s Setting up libxml2-utils (2.9.14+dfsg-1.3ubuntu3) ... 466s Setting up libgmime-3.0-0t64:ppc64el (3.2.13+dfsg-2.1build2) ... 466s Setting up libsamplerate0:ppc64el (0.2.2-4build1) ... 466s Setting up libopusfile0:ppc64el (0.12-4build3) ... 466s Setting up libvorbisenc2:ppc64el (1.3.7-1build3) ... 466s Setting up libopusenc0:ppc64el (0.2.1-2) ... 466s Setting up libsnmp40t64:ppc64el (5.9.4+dfsg-1.1ubuntu3) ... 466s Setting up libsybdb5:ppc64el (1.3.17+ds-2build3) ... 466s Setting up libvorbisfile3:ppc64el (1.3.7-1build3) ... 466s Setting up libjack-jackd2-0:ppc64el (1.9.21~dfsg-3ubuntu3) ... 466s Setting up libportaudio2:ppc64el (19.6.0-1.2build3) ... 466s Setting up asterisk-modules (1:20.6.0~dfsg+~cs6.13.40431414-2build5) ... 466s Setting up asterisk (1:20.6.0~dfsg+~cs6.13.40431414-2build5) ... 466s Adding system user for Asterisk 466s info: Adding user `asterisk' to group `dialout' ... 466s info: Adding user `asterisk' to group `audio' ... 467s Created symlink /etc/systemd/system/multi-user.target.wants/asterisk.service → /usr/lib/systemd/system/asterisk.service. 468s Setting up asterisk-tests (1:20.6.0~dfsg+~cs6.13.40431414-2build5) ... 468s Setting up autopkgtest-satdep (0) ... 468s Processing triggers for man-db (2.12.0-4build2) ... 469s Processing triggers for libc-bin (2.39-0ubuntu8) ... 472s (Reading database ... 74038 files and directories currently installed.) 472s Removing autopkgtest-satdep (0) ... 473s autopkgtest [18:04:55]: test asttestmods: [----------------------- 473s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 475s 'U' option is not compatible with remote console mode and has no effect. 475s 475s Asterisk has fully booted. 475s 'U' option is not compatible with remote console mode and has no effect. 475s 475s Running all available tests... 475s 475s START /apps/app_gosub/ - gosub application 475s END /apps/app_gosub/ - gosub application Time: <1ms Result: PASS 475s START /apps/app_voicemail/ - test_voicemail_vm_info 475s END /apps/app_voicemail/ - test_voicemail_vm_info Time: <1ms Result: PASS 475s START /apps/app_voicemail/ - test_voicemail_load_config 475s END /apps/app_voicemail/ - test_voicemail_load_config Time: <1ms Result: PASS 475s START /apps/app_voicemail/ - test_voicemail_notify_endl 475s END /apps/app_voicemail/ - test_voicemail_notify_endl Time: 5ms Result: PASS 475s START /apps/app_voicemail/ - vmuser 475s END /apps/app_voicemail/ - vmuser Time: <1ms Result: PASS 475s START /apps/app_voicemail/ - test_voicemail_msgcount 475s END /apps/app_voicemail/ - test_voicemail_msgcount Time: 33ms Result: PASS 475s START /apps/app_voicemail/ - vmsayname_exec 475s [app_voicemail.c:test_voicemail_vmsayname:15218]: Test playing of extension when greeting is not available... 479s [app_voicemail.c:test_voicemail_vmsayname:15239]: Test playing created mailbox greeting... 484s END /apps/app_voicemail/ - vmsayname_exec Time: 8886ms Result: PASS 484s START /ari/validators/ - validate_list 484s END /ari/validators/ - validate_list Time: <1ms Result: PASS 484s START /ari/validators/ - validate_date 484s END /ari/validators/ - validate_date Time: <1ms Result: PASS 484s START /ari/validators/ - validate_string 484s END /ari/validators/ - validate_string Time: <1ms Result: PASS 484s START /ari/validators/ - validate_long 484s END /ari/validators/ - validate_long Time: <1ms Result: PASS 484s START /ari/validators/ - validate_int 484s END /ari/validators/ - validate_int Time: <1ms Result: PASS 484s START /ari/validators/ - validate_boolean 484s END /ari/validators/ - validate_boolean Time: <1ms Result: PASS 484s START /ari/validators/ - validate_byte 484s END /ari/validators/ - validate_byte Time: <1ms Result: PASS 484s START /bridges/bridge_softmix/ - sfu_remove_destination_streams 484s END /bridges/bridge_softmix/ - sfu_remove_destination_streams Time: <1ms Result: PASS 484s START /bridges/bridge_softmix/ - sfu_append_source_streams 484s END /bridges/bridge_softmix/ - sfu_append_source_streams Time: <1ms Result: PASS 484s START /channels/features/ - test_features_channel_interval 487s END /channels/features/ - test_features_channel_interval Time: 3001ms Result: PASS 487s START /channels/features/ - test_features_channel_dtmf 489s END /channels/features/ - test_features_channel_dtmf Time: 2009ms Result: PASS 489s START /config/ - config_options_test 489s END /config/ - config_options_test Time: <1ms Result: PASS 489s START /config/ - ast_parse_arg 489s END /config/ - ast_parse_arg Time: <1ms Result: PASS 489s START /core/endpoints/ - setters 489s END /core/endpoints/ - setters Time: <1ms Result: PASS 489s START /core/endpoints/ - defaults 489s END /core/endpoints/ - defaults Time: <1ms Result: PASS 489s START /core/endpoints/ - create 489s END /core/endpoints/ - create Time: <1ms Result: PASS 489s START /funcs/func_curl/ - vulnerable_url 489s END /funcs/func_curl/ - vulnerable_url Time: <1ms Result: PASS 489s START /funcs/func_env/ - func_file 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=a'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,1)=a'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-8)=a'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-8)=a'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5,1)=b'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4,1)=b'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5,-3)=b'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4,-3)=b'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2)=c'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,2)=c'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-7)=c'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-7)=c'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,4,2)=d'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-5,2)=d'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,4,-3)=d'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-5,-3)=d'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5)=e'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5)='... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4)=e'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4)='... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=fg'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-8)=fg'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,1)=fg'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-8)=fg'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,)=h'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,,)=h'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,l)=h'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,ld)=h'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abc'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=abc'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=abc'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=abc'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=abc'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=abc'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=abc'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=abc'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=ab'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=ab'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=ab'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=ab'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=ab'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=ab'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=ab'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=ab'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcdefg'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcdefg'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcdefg'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcdefg'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcdefg'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcdefg'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcdefg'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcdefg'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcdefghijklmnop'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcdefghijklmnop'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcdefghijklmnop'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcdefghijklmnop'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcdefghijklmnop'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcdefghijklmnop'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcdefghijklmnop'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcdefghijklmnop'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,0,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,0,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,0,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,0,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,2,0,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-1,0,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,3,0,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,la)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)='... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)='... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)='... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)='... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)='... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)='... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)='... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)='... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,ld)='... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,ld)='... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,ld)='... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,ld)='... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,ld)='... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,ld)='... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,ld)='... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,ld)='... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=a'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,10)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 489s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=a'... OK! 489s END /funcs/func_env/ - func_file Time: 28ms Result: PASS 489s START /funcs/func_json/ - func_JSON_DECODE 489s END /funcs/func_json/ - func_JSON_DECODE Time: <1ms Result: PASS 489s START /funcs/func_presence/ - test_presence_state_base64_encode 489s END /funcs/func_presence/ - test_presence_state_base64_encode Time: 2ms Result: PASS 489s START /funcs/func_presence/ - test_presence_state_change 489s END /funcs/func_presence/ - test_presence_state_change Time: <1ms Result: PASS 489s START /funcs/func_presence/ - parse_invalid_presence_data 489s END /funcs/func_presence/ - parse_invalid_presence_data Time: <1ms Result: PASS 489s START /funcs/func_presence/ - parse_valid_presence_data 489s END /funcs/func_presence/ - parse_valid_presence_data Time: <1ms Result: PASS 489s START /funcs/func_sayfiles/ - test_SAYFILES_function 489s [func_sayfiles.c:test_SAYFILES_function:180]: Testing SAYFILES() substitution ... 489s END /funcs/func_sayfiles/ - test_SAYFILES_function Time: 6ms Result: PASS 489s START /funcs/func_strings/ - func_TRIM 489s END /funcs/func_strings/ - func_TRIM Time: <1ms Result: PASS 489s START /funcs/func_strings/ - func_STRBETWEEN 489s END /funcs/func_strings/ - func_STRBETWEEN Time: <1ms Result: PASS 489s START /funcs/func_strings/ - func_STRREPLACE_test 489s END /funcs/func_strings/ - func_STRREPLACE_test Time: <1ms Result: PASS 489s START /funcs/func_strings/ - func_FILTER_test 489s END /funcs/func_strings/ - func_FILTER_test Time: <1ms Result: PASS 489s START /funcs/func_strings/ - func_REPLACE_test 489s END /funcs/func_strings/ - func_REPLACE_test Time: <1ms Result: PASS 489s START /funcs/func_strings/ - func_FIELDNUM_test 489s END /funcs/func_strings/ - func_FIELDNUM_test Time: <1ms Result: PASS 489s START /geoloc/ - create_from_pidf 489s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1274]: ID: 'point-2d' pidf_element: 'tuple' format: 'GML' method: 'Manual' 489s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1286]: location_vars expected: shape=Point,crs=2d,pos=-34.410649 150.87651 489s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1287]: location_vars received: shape=Point,crs=2d,pos=-34.410649 150.87651 489s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1293]: usage_rules expected: retransmission-allowed='no',retention-expiry='2010-11-14T20:00:00Z' 489s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1294]: usage_rules received: retransmission-allowed='no',retention-expiry='2010-11-14T20:00:00Z' 489s END /geoloc/ - create_from_pidf Time: <1ms Result: PASS 489s START /geoloc/ - create_from_uri 489s END /geoloc/ - create_from_uri Time: <1ms Result: PASS 489s START /main/abstract_jb/ - AST_JB_FIXED_put_out_of_order 489s [test_abstract_jb.c:AST_JB_FIXED_put_out_of_order:531]: Executing AST_JB_FIXED_put_out_of_order... 489s END /main/abstract_jb/ - AST_JB_FIXED_put_out_of_order Time: <1ms Result: PASS 489s START /main/abstract_jb/ - AST_JB_FIXED_put_overflow 489s [test_abstract_jb.c:AST_JB_FIXED_put_overflow:529]: Executing AST_JB_FIXED_put_overflow... 489s END /main/abstract_jb/ - AST_JB_FIXED_put_overflow Time: <1ms Result: PASS 489s START /main/abstract_jb/ - AST_JB_FIXED_put 489s [test_abstract_jb.c:AST_JB_FIXED_put:527]: Executing AST_JB_FIXED_put... 489s END /main/abstract_jb/ - AST_JB_FIXED_put Time: <1ms Result: PASS 489s START /main/abstract_jb/ - AST_JB_FIXED_put_first 489s [test_abstract_jb.c:AST_JB_FIXED_put_first:525]: Executing AST_JB_FIXED_create... 489s END /main/abstract_jb/ - AST_JB_FIXED_put_first Time: <1ms Result: PASS 489s START /main/abstract_jb/ - AST_JB_FIXED_create 489s [test_abstract_jb.c:AST_JB_FIXED_create:523]: Executing AST_JB_FIXED_create... 489s END /main/abstract_jb/ - AST_JB_FIXED_create Time: <1ms Result: PASS 489s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_out_of_order 489s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_out_of_order:521]: Executing AST_JB_ADAPTIVE_put_out_of_order... 489s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_out_of_order Time: <1ms Result: PASS 489s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_overflow 489s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_overflow:519]: Executing AST_JB_ADAPTIVE_put_overflow... 489s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_overflow Time: <1ms Result: PASS 489s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put 489s [test_abstract_jb.c:AST_JB_ADAPTIVE_put:517]: Executing AST_JB_ADAPTIVE_put... 489s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put Time: <1ms Result: PASS 489s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_first 489s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_first:515]: Executing AST_JB_ADAPTIVE_create... 489s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_first Time: <1ms Result: PASS 489s START /main/abstract_jb/ - AST_JB_ADAPTIVE_create 489s [test_abstract_jb.c:AST_JB_ADAPTIVE_create:513]: Executing AST_JB_ADAPTIVE_create... 489s END /main/abstract_jb/ - AST_JB_ADAPTIVE_create Time: <1ms Result: PASS 489s START /main/acl/ - acl 489s END /main/acl/ - acl Time: <1ms Result: PASS 489s START /main/acl/ - invalid_acl 489s END /main/acl/ - invalid_acl Time: <1ms Result: PASS 489s START /main/amihooks/ - amihook_cli_send 489s END /main/amihooks/ - amihook_cli_send Time: <1ms Result: PASS 489s START /main/aoc/ - aoc_event_test 489s END /main/aoc/ - aoc_event_test Time: <1ms Result: PASS 489s START /main/aoc/ - aoc_encode_decode_test 489s END /main/aoc/ - aoc_encode_decode_test Time: <1ms Result: PASS 489s START /main/app/ - options_parsing 489s END /main/app/ - options_parsing Time: <1ms Result: PASS 489s START /main/app/ - app_group 489s [test_app.c:app_group:172]: Creating test channels with the following groups: 489s 'a groupgroupgroup', 'a groupGroupgroup', 'a group@a_category', 'a group@another!Category' 489s [test_app.c:app_group:211]: (Subtest 1) Found 4 matches as expected when examining group:'gr' category:'' 489s [test_app.c:app_group:211]: (Subtest 2) Found 1 matches as expected when examining group:'(group){2}$' category:'' 489s [test_app.c:app_group:211]: (Subtest 3) Found 4 matches as expected when examining group:'[:ascii:]' category:'' 489s [test_app.c:app_group:211]: (Subtest 4) Found 0 matches as expected when examining group:'^(NOMATCH)' category:'' 489s [test_app.c:app_group:211]: (Subtest 5) Found 2 matches as expected when examining group:'a group' category:'(gory)$' 489s [test_app.c:app_group:211]: (Subtest 6) Found 1 matches as expected when examining group:'a group' category:'[A-Z]+' 489s [test_app.c:app_group:211]: (Subtest 7) Found 0 matches as expected when examining group:'a group' category:'[[' 489s END /main/app/ - app_group Time: <1ms Result: PASS 489s START /main/ast_expr/ - expr_test 489s END /main/ast_expr/ - expr_test Time: <1ms Result: PASS 489s START /main/astdb/ - put_get_long 489s END /main/astdb/ - put_get_long Time: 82ms Result: PASS 489s START /main/astdb/ - perftest 489s END /main/astdb/ - perftest Time: 422ms Result: PASS 489s START /main/astdb/ - gettree_deltree 489s END /main/astdb/ - gettree_deltree Time: <1ms Result: PASS 489s START /main/astdb/ - put_get_del 489s END /main/astdb/ - put_get_del Time: <1ms Result: PASS 489s START /main/astobj2/ - thrash 489s [test_astobj2_thrash.c:hash_test:266]: Executing hash concurrency test... 489s END /main/astobj2/ - thrash Time: 13ms Result: PASS 489s START /main/astobj2/ - astobj2_test4 489s [test_astobj2.c:test_traversal_nonsorted:1389]: Test 1, List containers. 489s [test_astobj2.c:test_traversal_nonsorted:1389]: Test 2, Hash containers. 489s [test_astobj2.c:test_traversal_sorted:1615]: Test 3, List containers. 489s [test_astobj2.c:test_traversal_sorted:1615]: Test 4, Hash containers. 489s [test_astobj2.c:test_traversal_sorted:1615]: Test 5, RBTree containers. 489s END /main/astobj2/ - astobj2_test4 Time: <1ms Result: PASS 489s START /main/astobj2/ - astobj2_test3 489s END /main/astobj2/ - astobj2_test3 Time: <1ms Result: PASS 489s START /main/astobj2/ - astobj2_test2 489s END /main/astobj2/ - astobj2_test2 Time: <1ms Result: PASS 489s START /main/astobj2/ - astobj2_test1 489s [test_astobj2.c:astobj2_test_1_helper:434]: Test 1, List containers (non-sorted). 489s [test_astobj2.c:astobj2_test_1_helper:488]: List container created: buckets: 1, items: 50 489s [test_astobj2.c:astobj2_test_1_helper:434]: Test 2, List containers (sorted). 489s [test_astobj2.c:astobj2_test_1_helper:488]: List container created: buckets: 1, items: 50 489s [test_astobj2.c:astobj2_test_1_helper:434]: Test 3, Hash containers (non-sorted). 489s [test_astobj2.c:astobj2_test_1_helper:488]: Hash container created: buckets: 11, items: 1000 489s [test_astobj2.c:astobj2_test_1_helper:434]: Test 4, Hash containers (sorted). 489s [test_astobj2.c:astobj2_test_1_helper:488]: Hash container created: buckets: 172, items: 1000 489s [test_astobj2.c:astobj2_test_1_helper:434]: Test 4, RBTree containers (sorted). 489s [test_astobj2.c:astobj2_test_1_helper:488]: RBTree container created: buckets: 1, items: 1000 489s END /main/astobj2/ - astobj2_test1 Time: 17ms Result: PASS 489s START /main/astobj2/ - astobj2_weak_container 489s END /main/astobj2/ - astobj2_weak_container Time: <1ms Result: PASS 489s START /main/astobj2/ - astobj2_weak1 489s END /main/astobj2/ - astobj2_weak1 Time: <1ms Result: PASS 489s START /main/astobj2/perf/ - astobj2_test_perf 490s [test_astobj2.c:testloop:2001]: 20.00K traversals, List 492s [test_astobj2.c:testloop:2001]: 40.00K traversals, List 493s [test_astobj2.c:testloop:2001]: 60.00K traversals, List 495s [test_astobj2.c:testloop:2001]: 80.00K traversals, List 496s [test_astobj2.c:testloop:2006]: 100.00K traversals, List : 6839 ms 497s [test_astobj2.c:testloop:2001]: 20.00K traversals, Hash 498s [test_astobj2.c:testloop:2001]: 40.00K traversals, Hash 499s [test_astobj2.c:testloop:2001]: 60.00K traversals, Hash 500s [test_astobj2.c:testloop:2001]: 80.00K traversals, Hash 501s [test_astobj2.c:testloop:2006]: 100.00K traversals, Hash : 4823 ms 502s [test_astobj2.c:testloop:2001]: 20.00K traversals, RBTree 503s [test_astobj2.c:testloop:2001]: 40.00K traversals, RBTree 504s [test_astobj2.c:testloop:2001]: 60.00K traversals, RBTree 505s [test_astobj2.c:testloop:2001]: 80.00K traversals, RBTree 506s [test_astobj2.c:testloop:2006]: 100.00K traversals, RBTree : 5343 ms 506s END /main/astobj2/perf/ - astobj2_test_perf Time: 17006ms Result: PASS 506s START /main/bridging/ - test_bridging_deferred_queue 507s END /main/bridging/ - test_bridging_deferred_queue Time: 1007ms Result: PASS 507s START /main/bucket/ - bucket_file_json 507s [test_bucket.c:bucket_file_json:956]: Failed to allocate bucket 507s END /main/bucket/ - bucket_file_json Time: <1ms Result: FAIL 507s START /main/bucket/ - bucket_file_metadata_get 507s [test_bucket.c:bucket_file_metadata_get:914]: Failed to allocate file 507s END /main/bucket/ - bucket_file_metadata_get Time: <1ms Result: FAIL 507s START /main/bucket/ - bucket_file_metadata_unset 507s [test_bucket.c:bucket_file_metadata_unset:874]: Failed to allocate file 507s END /main/bucket/ - bucket_file_metadata_unset Time: <1ms Result: FAIL 507s START /main/bucket/ - bucket_file_metadata_set 507s [test_bucket.c:bucket_file_metadata_set:808]: Failed to allocate file 507s END /main/bucket/ - bucket_file_metadata_set Time: <1ms Result: FAIL 507s START /main/bucket/ - bucket_file_is_stale 507s [test_bucket.c:bucket_file_is_stale:775]: Failed to allocate file 507s END /main/bucket/ - bucket_file_is_stale Time: <1ms Result: FAIL 507s START /main/bucket/ - bucket_file_delete 507s [test_bucket.c:bucket_file_delete:732]: Failed to allocate file 507s END /main/bucket/ - bucket_file_delete Time: <1ms Result: FAIL 507s START /main/bucket/ - bucket_file_update 507s [test_bucket.c:bucket_file_update:689]: Failed to allocate file 507s END /main/bucket/ - bucket_file_update Time: <1ms Result: FAIL 507s START /main/bucket/ - bucket_file_retrieve 507s [test_bucket.c:bucket_file_retrieve:665]: Failed to retrieve known valid file 507s END /main/bucket/ - bucket_file_retrieve Time: <1ms Result: FAIL 507s START /main/bucket/ - bucket_file_copy 507s [test_bucket.c:bucket_file_copy:594]: Failed to allocate file 507s END /main/bucket/ - bucket_file_copy Time: <1ms Result: FAIL 507s START /main/bucket/ - bucket_file_clone 507s [test_bucket.c:bucket_file_clone:545]: Failed to allocate file 507s END /main/bucket/ - bucket_file_clone Time: <1ms Result: FAIL 507s START /main/bucket/ - bucket_file_create 507s [test_bucket.c:bucket_file_create:501]: Failed to allocate file 507s END /main/bucket/ - bucket_file_create Time: <1ms Result: FAIL 507s START /main/bucket/ - bucket_file_alloc 507s [test_bucket.c:bucket_file_alloc:460]: Failed to allocate file 507s END /main/bucket/ - bucket_file_alloc Time: <1ms Result: FAIL 507s START /main/bucket/ - bucket_json 507s END /main/bucket/ - bucket_json Time: <1ms Result: PASS 507s START /main/bucket/ - bucket_is_stale 507s END /main/bucket/ - bucket_is_stale Time: <1ms Result: PASS 507s START /main/bucket/ - bucket_retrieve 507s END /main/bucket/ - bucket_retrieve Time: <1ms Result: PASS 507s START /main/bucket/ - bucket_delete 507s END /main/bucket/ - bucket_delete Time: <1ms Result: PASS 507s START /main/bucket/ - bucket_clone 507s END /main/bucket/ - bucket_clone Time: <1ms Result: PASS 507s START /main/bucket/ - bucket_create 507s END /main/bucket/ - bucket_create Time: <1ms Result: PASS 507s START /main/bucket/ - bucket_alloc 507s END /main/bucket/ - bucket_alloc Time: <1ms Result: PASS 507s START /main/bucket/ - bucket_scheme_register_unregister 507s END /main/bucket/ - bucket_scheme_register_unregister Time: <1ms Result: PASS 507s START /main/callerid/ - parse_off_nominal 507s END /main/callerid/ - parse_off_nominal Time: <1ms Result: PASS 507s START /main/callerid/ - parse_nominal 507s END /main/callerid/ - parse_nominal Time: <1ms Result: PASS 507s START /main/cdr/ - test_cdr_fork_cdr 509s Verifying expected record CDRTestChannel/Alice, 509s Finished expected record CDRTestChannel/Alice, 509s Verifying expected record CDRTestChannel/Alice, 509s Finished expected record CDRTestChannel/Alice, 509s Verifying expected record CDRTestChannel/Alice, 509s Finished expected record CDRTestChannel/Alice, 509s END /main/cdr/ - test_cdr_fork_cdr Time: 2000ms Result: PASS 509s START /main/cdr/ - test_cdr_no_reset_cdr 510s Verifying expected record CDRTestChannel/Alice, 510s Finished expected record CDRTestChannel/Alice, 510s END /main/cdr/ - test_cdr_no_reset_cdr Time: 1000ms Result: PASS 510s START /main/cdr/ - test_cdr_fields 512s Verifying expected record CDRTestChannel/Alice, 512s Finished expected record CDRTestChannel/Alice, 512s Verifying expected record CDRTestChannel/Alice, 512s Finished expected record CDRTestChannel/Alice, 512s Verifying expected record CDRTestChannel/Alice, 512s Finished expected record CDRTestChannel/Alice, 512s END /main/cdr/ - test_cdr_fields Time: 2001ms Result: PASS 512s START /main/cdr/ - test_cdr_park 515s Verifying expected record CDRTestChannel/Alice, 515s Finished expected record CDRTestChannel/Alice, 515s Verifying expected record CDRTestChannel/Bob, 515s Finished expected record CDRTestChannel/Bob, 515s END /main/cdr/ - test_cdr_park Time: 3001ms Result: PASS 515s START /main/cdr/ - test_cdr_dial_answer_multiparty 520s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 520s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 520s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 520s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 520s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/David 520s Finished expected record CDRTestChannel/Alice, CDRTestChannel/David 520s Verifying expected record CDRTestChannel/Bob, CDRTestChannel/David 520s Finished expected record CDRTestChannel/Bob, CDRTestChannel/David 520s Verifying expected record CDRTestChannel/Charlie, CDRTestChannel/David 520s Finished expected record CDRTestChannel/Charlie, CDRTestChannel/David 520s Verifying expected record CDRTestChannel/Charlie, CDRTestChannel/Bob 520s Finished expected record CDRTestChannel/Charlie, CDRTestChannel/Bob 520s END /main/cdr/ - test_cdr_dial_answer_multiparty Time: 5002ms Result: PASS 520s START /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_b 523s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 523s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 523s END /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_b Time: 3001ms Result: PASS 523s START /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_a 525s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 525s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 525s END /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_a Time: 2001ms Result: PASS 525s START /main/cdr/ - test_cdr_dial_answer_no_bridge 525s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 525s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 525s Verifying expected record CDRTestChannel/Alice, 525s Finished expected record CDRTestChannel/Alice, 525s Verifying expected record CDRTestChannel/Bob, 525s Finished expected record CDRTestChannel/Bob, 525s END /main/cdr/ - test_cdr_dial_answer_no_bridge Time: <1ms Result: PASS 525s START /main/cdr/ - test_cdr_dial_parallel_failed 525s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 525s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 525s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 525s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 525s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/David 525s Finished expected record CDRTestChannel/Alice, CDRTestChannel/David 525s END /main/cdr/ - test_cdr_dial_parallel_failed Time: 1ms Result: PASS 525s START /main/cdr/ - test_cdr_dial_caller_cancel 525s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 525s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 525s END /main/cdr/ - test_cdr_dial_caller_cancel Time: <1ms Result: PASS 525s START /main/cdr/ - test_cdr_dial_unavailable 525s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 525s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 525s END /main/cdr/ - test_cdr_dial_unavailable Time: <1ms Result: PASS 525s START /main/cdr/ - test_cdr_dial_busy 525s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 525s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 525s END /main/cdr/ - test_cdr_dial_busy Time: <1ms Result: PASS 525s START /main/cdr/ - test_cdr_dial_congestion 525s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 525s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 525s END /main/cdr/ - test_cdr_dial_congestion Time: <1ms Result: PASS 525s START /main/cdr/ - test_cdr_dial_unanswered 525s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 525s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 525s END /main/cdr/ - test_cdr_dial_unanswered Time: <1ms Result: PASS 525s START /main/cdr/ - test_cdr_outbound_bridged_call 528s Verifying expected record CDRTestChannel/Bob, 528s Finished expected record CDRTestChannel/Bob, 528s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 528s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 528s END /main/cdr/ - test_cdr_outbound_bridged_call Time: 3001ms Result: PASS 528s START /main/cdr/ - test_cdr_single_multiparty_bridge 532s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 532s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 532s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 532s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 532s Verifying expected record CDRTestChannel/Bob, CDRTestChannel/Charlie 532s Finished expected record CDRTestChannel/Bob, CDRTestChannel/Charlie 532s Verifying expected record CDRTestChannel/Charlie, 532s Finished expected record CDRTestChannel/Charlie, 532s END /main/cdr/ - test_cdr_single_multiparty_bridge Time: 4002ms Result: PASS 532s START /main/cdr/ - test_cdr_single_twoparty_bridge_b 535s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 535s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 535s Verifying expected record CDRTestChannel/Bob, 535s Finished expected record CDRTestChannel/Bob, 535s END /main/cdr/ - test_cdr_single_twoparty_bridge_b Time: 3001ms Result: PASS 535s START /main/cdr/ - test_cdr_single_twoparty_bridge_a 537s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 537s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 537s Verifying expected record CDRTestChannel/Bob, 537s Finished expected record CDRTestChannel/Bob, 537s END /main/cdr/ - test_cdr_single_twoparty_bridge_a Time: 2001ms Result: PASS 537s START /main/cdr/ - test_cdr_single_bridge_continue 539s Verifying expected record CDRTestChannel/Alice, 539s Finished expected record CDRTestChannel/Alice, 539s Verifying expected record CDRTestChannel/Alice, 539s Finished expected record CDRTestChannel/Alice, 539s END /main/cdr/ - test_cdr_single_bridge_continue Time: 2000ms Result: PASS 539s START /main/cdr/ - test_cdr_single_bridge 541s Verifying expected record CDRTestChannel/Alice, 541s Finished expected record CDRTestChannel/Alice, 541s END /main/cdr/ - test_cdr_single_bridge Time: 2000ms Result: PASS 541s START /main/cdr/ - test_cdr_single_party 541s Verifying expected record CDRTestChannel/Alice, 541s Finished expected record CDRTestChannel/Alice, 541s END /main/cdr/ - test_cdr_single_party Time: <1ms Result: PASS 541s START /main/cdr/ - test_cdr_unanswered_outbound_call 541s Verifying expected record CDRTestChannel/Alice, 541s Finished expected record CDRTestChannel/Alice, 541s END /main/cdr/ - test_cdr_unanswered_outbound_call Time: <1ms Result: PASS 541s START /main/cdr/ - test_cdr_unanswered_inbound_call 541s Verifying expected record CDRTestChannel/Alice, 541s Finished expected record CDRTestChannel/Alice, 541s END /main/cdr/ - test_cdr_unanswered_inbound_call Time: <1ms Result: PASS 541s START /main/cdr/ - test_cdr_channel_creation 541s Verifying expected record CDRTestChannel/Alice, 541s Finished expected record CDRTestChannel/Alice, 541s END /main/cdr/ - test_cdr_channel_creation Time: <1ms Result: PASS 541s START /main/channel/ - add_fd 541s END /main/channel/ - add_fd Time: <1ms Result: PASS 541s START /main/channel/ - set_fd_grow 541s END /main/channel/ - set_fd_grow Time: <1ms Result: PASS 541s START /main/config/ - variable_list_from_quoted_string 541s END /main/config/ - variable_list_from_quoted_string Time: <1ms Result: PASS 541s START /main/config/ - variable_list_join_replace 541s END /main/config/ - variable_list_join_replace Time: <1ms Result: PASS 541s START /main/config/ - variable_lists_match 541s END /main/config/ - variable_lists_match Time: <1ms Result: PASS 541s START /main/config/ - config_dialplan_function 541s END /main/config/ - config_dialplan_function Time: <1ms Result: PASS 541s START /main/config/ - config_hook 541s END /main/config/ - config_hook Time: <1ms Result: PASS 541s START /main/config/ - copy_config 541s END /main/config/ - copy_config Time: <1ms Result: PASS 541s START /main/config/ - config_template_ops 541s END /main/config/ - config_template_ops Time: <1ms Result: PASS 541s START /main/config/ - config_filtered_ops 541s END /main/config/ - config_filtered_ops Time: <1ms Result: PASS 541s START /main/config/ - config_basic_ops 541s END /main/config/ - config_basic_ops Time: <1ms Result: PASS 541s START /main/config/ - config_save 541s END /main/config/ - config_save Time: <1ms Result: PASS 541s START /main/conversions/ - str_to_umax 541s END /main/conversions/ - str_to_umax Time: <1ms Result: PASS 541s START /main/conversions/ - str_to_imax 541s END /main/conversions/ - str_to_imax Time: <1ms Result: PASS 541s START /main/conversions/ - str_to_ulong 541s END /main/conversions/ - str_to_ulong Time: <1ms Result: PASS 541s START /main/conversions/ - str_to_long 541s END /main/conversions/ - str_to_long Time: <1ms Result: PASS 541s START /main/conversions/ - str_to_uint 541s END /main/conversions/ - str_to_uint Time: <1ms Result: PASS 541s START /main/conversions/ - str_to_int 541s END /main/conversions/ - str_to_int Time: <1ms Result: PASS 541s START /main/core_codec/ - codec_get_unknown 541s END /main/core_codec/ - codec_get_unknown Time: <1ms Result: PASS 541s START /main/core_codec/ - codec_get_unknown 541s END /main/core_codec/ - codec_get_unknown Time: <1ms Result: PASS 541s START /main/core_codec/ - codec_get_unregistered 541s END /main/core_codec/ - codec_get_unregistered Time: <1ms Result: PASS 541s START /main/core_codec/ - codec_get 541s END /main/core_codec/ - codec_get Time: <1ms Result: PASS 541s START /main/core_codec/ - codec_register_audio_no_sample_rate 541s END /main/core_codec/ - codec_register_audio_no_sample_rate Time: <1ms Result: PASS 541s START /main/core_codec/ - codec_register_unknown 541s END /main/core_codec/ - codec_register_unknown Time: <1ms Result: PASS 541s START /main/core_codec/ - codec_register_twice 541s END /main/core_codec/ - codec_register_twice Time: <1ms Result: PASS 541s START /main/core_codec/ - codec_register 541s END /main/core_codec/ - codec_register Time: <1ms Result: PASS 541s START /main/core_format/ - format_parse_and_generate_sdp_fmtp 541s END /main/core_format/ - format_parse_and_generate_sdp_fmtp Time: <1ms Result: PASS 541s START /main/core_format/ - format_parse_sdp_fmtp_without_interface 541s END /main/core_format/ - format_parse_sdp_fmtp_without_interface Time: <1ms Result: PASS 541s START /main/core_format/ - format_attribute_get_without_interface 541s END /main/core_format/ - format_attribute_get_without_interface Time: <1ms Result: PASS 541s START /main/core_format/ - format_attribute_set_without_interface 541s END /main/core_format/ - format_attribute_set_without_interface Time: <1ms Result: PASS 541s START /main/core_format/ - format_copy 541s END /main/core_format/ - format_copy Time: <1ms Result: PASS 541s START /main/core_format/ - format_joint_different_codec 541s END /main/core_format/ - format_joint_different_codec Time: <1ms Result: PASS 541s START /main/core_format/ - format_attr_joint_same_codec 541s END /main/core_format/ - format_attr_joint_same_codec Time: <1ms Result: PASS 541s START /main/core_format/ - format_joint_same_codec 541s END /main/core_format/ - format_joint_same_codec Time: <1ms Result: PASS 541s START /main/core_format/ - format_cmp_different_codec 541s END /main/core_format/ - format_cmp_different_codec Time: <1ms Result: PASS 541s START /main/core_format/ - format_attr_cmp_same_codec 541s END /main/core_format/ - format_attr_cmp_same_codec Time: <1ms Result: PASS 541s START /main/core_format/ - format_cmp_same_codec 541s END /main/core_format/ - format_cmp_same_codec Time: <1ms Result: PASS 541s START /main/core_format/ - format_clone 541s END /main/core_format/ - format_clone Time: <1ms Result: PASS 541s START /main/core_format/ - format_retrieve_attr 541s END /main/core_format/ - format_retrieve_attr Time: <1ms Result: PASS 541s START /main/core_format/ - format_create_attr 541s END /main/core_format/ - format_create_attr Time: <1ms Result: PASS 541s START /main/core_format/ - format_create 541s END /main/core_format/ - format_create Time: <1ms Result: PASS 541s START /main/data_buffer/ - buffer_nominal 541s END /main/data_buffer/ - buffer_nominal Time: <1ms Result: PASS 541s START /main/data_buffer/ - buffer_resize 541s END /main/data_buffer/ - buffer_resize Time: <1ms Result: PASS 541s START /main/data_buffer/ - buffer_put 541s END /main/data_buffer/ - buffer_put Time: <1ms Result: PASS 541s START /main/data_buffer/ - buffer_create 541s END /main/data_buffer/ - buffer_create Time: <1ms Result: PASS 541s START /main/devicestate/ - devstate_channels 541s END /main/devicestate/ - devstate_channels Time: <1ms Result: PASS 541s START /main/devicestate/ - devstate_conversions 541s END /main/devicestate/ - devstate_conversions Time: <1ms Result: PASS 541s START /main/devicestate/ - devstate_changed 541s [test_devicestate.c:wait_for_device_state_updates:308]: Received 8 of 8 updates 541s [test_devicestate.c:devstate_changed:716]: Testing update 0: actual is 1; expected is 1 541s [test_devicestate.c:devstate_changed:716]: Testing update 1: actual is 2; expected is 2 541s [test_devicestate.c:devstate_changed:716]: Testing update 2: actual is 3; expected is 3 541s [test_devicestate.c:devstate_changed:716]: Testing update 3: actual is 4; expected is 4 541s [test_devicestate.c:devstate_changed:716]: Testing update 4: actual is 5; expected is 5 541s [test_devicestate.c:devstate_changed:716]: Testing update 5: actual is 6; expected is 6 541s [test_devicestate.c:devstate_changed:716]: Testing update 6: actual is 7; expected is 7 541s [test_devicestate.c:devstate_changed:716]: Testing update 7: actual is 8; expected is 8 541s [test_devicestate.c:wait_for_device_state_updates:308]: Received 1 of 1 updates 541s [test_devicestate.c:wait_for_device_state_updates:308]: Received 8 of 8 updates 541s [test_devicestate.c:devstate_changed:754]: Testing update 0: actual is 1; expected is 1 541s [test_devicestate.c:devstate_changed:754]: Testing update 1: actual is 2; expected is 2 541s [test_devicestate.c:devstate_changed:754]: Testing update 2: actual is 3; expected is 3 541s [test_devicestate.c:devstate_changed:754]: Testing update 3: actual is 4; expected is 4 541s [test_devicestate.c:devstate_changed:754]: Testing update 4: actual is 5; expected is 5 541s [test_devicestate.c:devstate_changed:754]: Testing update 5: actual is 6; expected is 6 541s [test_devicestate.c:devstate_changed:754]: Testing update 6: actual is 7; expected is 7 541s [test_devicestate.c:devstate_changed:754]: Testing update 7: actual is 8; expected is 8 541s END /main/devicestate/ - devstate_changed Time: 2ms Result: PASS 541s START /main/devicestate/ - devstate_prov_del 541s END /main/devicestate/ - devstate_prov_del Time: <1ms Result: PASS 541s START /main/devicestate/ - devstate_prov_add 541s END /main/devicestate/ - devstate_prov_add Time: <1ms Result: PASS 541s START /main/devicestate/ - device2extenstate_test 541s END /main/devicestate/ - device2extenstate_test Time: <1ms Result: PASS 541s START /main/devicestate/ - device_state_aggregation_test 541s END /main/devicestate/ - device_state_aggregation_test Time: <1ms Result: PASS 541s START /main/dns/ - resolver_resolve_async_cancel 541s END /main/dns/ - resolver_resolve_async_cancel Time: <1ms Result: PASS 541s START /main/dns/ - resolver_resolve_async_off_nominal 541s END /main/dns/ - resolver_resolve_async_off_nominal Time: <1ms Result: PASS 541s START /main/dns/ - resolver_resolve_async 546s END /main/dns/ - resolver_resolve_async Time: 5000ms Result: PASS 546s START /main/dns/ - resolver_resolve_sync_off_nominal 546s END /main/dns/ - resolver_resolve_sync_off_nominal Time: <1ms Result: PASS 546s START /main/dns/ - resolver_resolve_sync 551s END /main/dns/ - resolver_resolve_sync Time: 5000ms Result: PASS 551s START /main/dns/ - resolver_add_record_off_nominal 551s END /main/dns/ - resolver_add_record_off_nominal Time: <1ms Result: PASS 551s START /main/dns/ - resolver_add_record 551s END /main/dns/ - resolver_add_record Time: <1ms Result: PASS 551s START /main/dns/ - resolver_set_result_off_nominal 551s END /main/dns/ - resolver_set_result_off_nominal Time: <1ms Result: PASS 551s START /main/dns/ - resolver_set_result 551s END /main/dns/ - resolver_set_result Time: <1ms Result: PASS 551s START /main/dns/ - resolver_data 551s END /main/dns/ - resolver_data Time: <1ms Result: PASS 551s START /main/dns/ - resolver_unregister_off_nominal 551s END /main/dns/ - resolver_unregister_off_nominal Time: <1ms Result: PASS 551s START /main/dns/ - resolver_register_off_nominal 551s END /main/dns/ - resolver_register_off_nominal Time: <1ms Result: PASS 551s START /main/dns/ - resolver_register_unregister 551s END /main/dns/ - resolver_register_unregister Time: <1ms Result: PASS 551s START /main/dns/naptr/ - naptr_resolve_off_nominal_interactions 551s END /main/dns/naptr/ - naptr_resolve_off_nominal_interactions Time: <1ms Result: PASS 551s START /main/dns/naptr/ - naptr_resolve_off_nominal_regexp 551s END /main/dns/naptr/ - naptr_resolve_off_nominal_regexp Time: <1ms Result: PASS 551s START /main/dns/naptr/ - naptr_resolve_off_nominal_services 551s END /main/dns/naptr/ - naptr_resolve_off_nominal_services Time: <1ms Result: PASS 551s START /main/dns/naptr/ - naptr_resolve_off_nominal_flags 551s END /main/dns/naptr/ - naptr_resolve_off_nominal_flags Time: <1ms Result: PASS 551s START /main/dns/naptr/ - naptr_resolve_off_nominal_length 551s END /main/dns/naptr/ - naptr_resolve_off_nominal_length Time: <1ms Result: PASS 551s START /main/dns/naptr/ - naptr_resolve 551s END /main/dns/naptr/ - naptr_resolve Time: <1ms Result: PASS 551s START /main/dns/query_set/ - query_set_off_nominal_cancel 551s END /main/dns/query_set/ - query_set_off_nominal_cancel Time: <1ms Result: PASS 551s START /main/dns/query_set/ - query_set_nominal_cancel 551s END /main/dns/query_set/ - query_set_nominal_cancel Time: <1ms Result: PASS 551s START /main/dns/query_set/ - query_set_empty 551s END /main/dns/query_set/ - query_set_empty Time: <1ms Result: PASS 551s START /main/dns/query_set/ - query_set 551s END /main/dns/query_set/ - query_set Time: <1ms Result: PASS 551s START /main/dns/recurring/ - recurring_query_cancel_during 551s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 558s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 568s END /main/dns/recurring/ - recurring_query_cancel_during Time: 16999ms Result: PASS 568s START /main/dns/recurring/ - recurring_query_cancel_between 568s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 578s END /main/dns/recurring/ - recurring_query_cancel_between Time: 10000ms Result: PASS 578s START /main/dns/recurring/ - recurring_query_off_nominal 578s END /main/dns/recurring/ - recurring_query_off_nominal Time: <1ms Result: PASS 578s START /main/dns/recurring/ - recurring_query 578s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 585s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 597s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 597s END /main/dns/recurring/ - recurring_query Time: 18998ms Result: PASS 597s START /main/dns/srv/ - srv_resolve_record_missing_host 597s END /main/dns/srv/ - srv_resolve_record_missing_host Time: <1ms Result: PASS 597s START /main/dns/srv/ - srv_resolve_record_missing_port_host 597s END /main/dns/srv/ - srv_resolve_record_missing_port_host Time: <1ms Result: PASS 597s START /main/dns/srv/ - srv_resolve_record_missing_weight_port_host 597s END /main/dns/srv/ - srv_resolve_record_missing_weight_port_host Time: <1ms Result: PASS 597s START /main/dns/srv/ - srv_resolve_different_priorities_different_weights 597s END /main/dns/srv/ - srv_resolve_different_priorities_different_weights Time: 4ms Result: PASS 597s START /main/dns/srv/ - srv_resolve_same_priority_different_weights 597s END /main/dns/srv/ - srv_resolve_same_priority_different_weights Time: 4ms Result: PASS 597s START /main/dns/srv/ - srv_resolve_same_priority_zero_weight 597s END /main/dns/srv/ - srv_resolve_same_priority_zero_weight Time: <1ms Result: PASS 597s START /main/dns/srv/ - srv_resolve_sort_priority 597s END /main/dns/srv/ - srv_resolve_sort_priority Time: <1ms Result: PASS 597s START /main/dns/srv/ - srv_resolve_single_record 597s END /main/dns/srv/ - srv_resolve_single_record Time: <1ms Result: PASS 597s START /main/dsp/ - dtmf 597s END /main/dsp/ - dtmf Time: 5ms Result: PASS 597s START /main/dsp/ - fax 598s END /main/dsp/ - fax Time: 780ms Result: PASS 598s START /main/event/ - ast_event_new_test 598s [test_event.c:event_new_test:125]: First, test dynamic event creation... 598s [test_event.c:check_event:88]: Event looks good. 598s [test_event.c:check_event:88]: Event looks good. 598s END /main/event/ - ast_event_new_test Time: <1ms Result: PASS 598s START /main/file/ - ast_format_str_reduce_test_1 598s END /main/file/ - ast_format_str_reduce_test_1 Time: <1ms Result: PASS 598s START /main/file/ - read_dir_test 598s END /main/file/ - read_dir_test Time: <1ms Result: PASS 598s START /main/format_cache/ - format_cache_get_nonxistent 598s END /main/format_cache/ - format_cache_get_nonxistent Time: <1ms Result: PASS 598s START /main/format_cache/ - format_cache_get 598s END /main/format_cache/ - format_cache_get Time: <1ms Result: PASS 598s START /main/format_cache/ - format_cache_set_null 598s END /main/format_cache/ - format_cache_set_null Time: <1ms Result: PASS 598s START /main/format_cache/ - format_cache_set_duplicate 598s END /main/format_cache/ - format_cache_set_duplicate Time: <1ms Result: PASS 598s START /main/format_cache/ - format_cache_set 598s END /main/format_cache/ - format_cache_set Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_replace_from_cap 598s END /main/format_cap/ - format_cap_replace_from_cap Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_best_by_type 598s END /main/format_cap/ - format_cap_best_by_type Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_iscompatible 598s END /main/format_cap/ - format_cap_iscompatible Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_get_compatible 598s END /main/format_cap/ - format_cap_get_compatible Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_iscompatible_format 598s END /main/format_cap/ - format_cap_iscompatible_format Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_get_compatible_format 598s END /main/format_cap/ - format_cap_get_compatible_format Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_get_names 598s END /main/format_cap/ - format_cap_get_names Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_remove_all 598s END /main/format_cap/ - format_cap_remove_all Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_remove_bytype 598s END /main/format_cap/ - format_cap_remove_bytype Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_remove_multiple 598s END /main/format_cap/ - format_cap_remove_multiple Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_remove_single 598s END /main/format_cap/ - format_cap_remove_single Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_set_framing 598s END /main/format_cap/ - format_cap_set_framing Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_append_from_cap_duplicate 598s END /main/format_cap/ - format_cap_append_from_cap_duplicate Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_append_from_cap 598s END /main/format_cap/ - format_cap_append_from_cap Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_append_duplicate 598s END /main/format_cap/ - format_cap_append_duplicate Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_append_all_audio 598s END /main/format_cap/ - format_cap_append_all_audio Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_append_all_unknown 598s END /main/format_cap/ - format_cap_append_all_unknown Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_append_multiple 598s END /main/format_cap/ - format_cap_append_multiple Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_append_single 598s END /main/format_cap/ - format_cap_append_single Time: <1ms Result: PASS 598s START /main/format_cap/ - format_cap_alloc 598s END /main/format_cap/ - format_cap_alloc Time: <1ms Result: PASS 598s START /main/hashtab/ - thrash 598s [test_hashtab_thrash.c:hash_test:246]: Executing hash concurrency test... 598s END /main/hashtab/ - thrash Time: 25ms Result: PASS 598s START /main/heap/ - heap_test_3 598s END /main/heap/ - heap_test_3 Time: 141ms Result: PASS 598s START /main/heap/ - heap_test_2 598s END /main/heap/ - heap_test_2 Time: 119ms Result: PASS 598s START /main/heap/ - heap_test_1 598s END /main/heap/ - heap_test_1 Time: <1ms Result: PASS 598s START /main/jitterbuf/ - jitterbuffer_resynch_control 598s END /main/jitterbuf/ - jitterbuffer_resynch_control Time: <1ms Result: PASS 598s START /main/jitterbuf/ - jitterbuffer_resynch_voice 598s END /main/jitterbuf/ - jitterbuffer_resynch_voice Time: <1ms Result: PASS 598s START /main/jitterbuf/ - jitterbuffer_overflow_control 598s END /main/jitterbuf/ - jitterbuffer_overflow_control Time: <1ms Result: PASS 598s START /main/jitterbuf/ - jitterbuffer_overflow_voice 598s END /main/jitterbuf/ - jitterbuffer_overflow_voice Time: <1ms Result: PASS 598s START /main/jitterbuf/ - jitterbuffer_late_control 598s END /main/jitterbuf/ - jitterbuffer_late_control Time: <1ms Result: PASS 598s START /main/jitterbuf/ - jitterbuffer_late_voice 598s END /main/jitterbuf/ - jitterbuffer_late_voice Time: <1ms Result: PASS 598s START /main/jitterbuf/ - jitterbuffer_lost_control 598s END /main/jitterbuf/ - jitterbuffer_lost_control Time: <1ms Result: PASS 598s START /main/jitterbuf/ - jitterbuffer_lost_voice 598s END /main/jitterbuf/ - jitterbuffer_lost_voice Time: <1ms Result: PASS 598s START /main/jitterbuf/ - jitterbuffer_out_of_order_voice 598s END /main/jitterbuf/ - jitterbuffer_out_of_order_voice Time: <1ms Result: PASS 598s START /main/jitterbuf/ - jitterbuffer_out_of_order_voice 598s END /main/jitterbuf/ - jitterbuffer_out_of_order_voice Time: <1ms Result: PASS 598s START /main/jitterbuf/ - jitterbuffer_nominal_control_frames 598s END /main/jitterbuf/ - jitterbuffer_nominal_control_frames Time: <1ms Result: PASS 598s START /main/jitterbuf/ - jitterbuffer_nominal_voice_frames 598s END /main/jitterbuf/ - jitterbuffer_nominal_voice_frames Time: <1ms Result: PASS 598s START /main/json/ - cep 598s END /main/json/ - cep Time: <1ms Result: PASS 598s START /main/json/ - type_timeval 598s END /main/json/ - type_timeval Time: <1ms Result: PASS 598s START /main/json/ - name_number 598s END /main/json/ - name_number Time: <1ms Result: PASS 598s START /main/json/ - clever_circle 598s END /main/json/ - clever_circle Time: <1ms Result: PASS 598s START /main/json/ - circular_array 598s END /main/json/ - circular_array Time: <1ms Result: PASS 598s START /main/json/ - circular_object 598s END /main/json/ - circular_object Time: <1ms Result: PASS 598s START /main/json/ - copy_null 598s END /main/json/ - copy_null Time: <1ms Result: PASS 598s START /main/json/ - deep_copy 598s END /main/json/ - deep_copy Time: <1ms Result: PASS 598s START /main/json/ - copy 598s END /main/json/ - copy Time: <1ms Result: PASS 598s START /main/json/ - object_alloc 598s END /main/json/ - object_alloc Time: <1ms Result: PASS 598s START /main/json/ - pack_ownership 598s END /main/json/ - pack_ownership Time: <1ms Result: PASS 598s START /main/json/ - pack 598s END /main/json/ - pack Time: <1ms Result: PASS 598s START /main/json/ - parse_errors 598s END /main/json/ - parse_errors Time: <1ms Result: PASS 598s START /main/json/ - dump_load_null 598s END /main/json/ - dump_load_null Time: <1ms Result: PASS 598s START /main/json/ - dump_load_new_file 598s END /main/json/ - dump_load_new_file Time: <1ms Result: PASS 598s START /main/json/ - dump_load_file 598s END /main/json/ - dump_load_file Time: <1ms Result: PASS 598s START /main/json/ - load_buffer 598s END /main/json/ - load_buffer Time: <1ms Result: PASS 598s START /main/json/ - dump_str_fail 598s END /main/json/ - dump_str_fail Time: <1ms Result: PASS 598s START /main/json/ - dump_load_str 598s END /main/json/ - dump_load_str Time: <1ms Result: PASS 598s START /main/json/ - dump_load_string 598s END /main/json/ - dump_load_string Time: <1ms Result: PASS 598s START /main/json/ - object_create_vars 598s END /main/json/ - object_create_vars Time: <1ms Result: PASS 598s START /main/json/ - object_iter_null 598s END /main/json/ - object_iter_null Time: <1ms Result: PASS 598s START /main/json/ - object_iter 598s END /main/json/ - object_iter Time: <1ms Result: PASS 598s START /main/json/ - object_null 598s END /main/json/ - object_null Time: <1ms Result: PASS 598s START /main/json/ - object_merge_missing 598s END /main/json/ - object_merge_missing Time: <1ms Result: PASS 598s START /main/json/ - object_alloc 598s END /main/json/ - object_alloc Time: <1ms Result: PASS 598s START /main/json/ - object_alloc 598s END /main/json/ - object_alloc Time: <1ms Result: PASS 598s START /main/json/ - object_clear 598s END /main/json/ - object_clear Time: <1ms Result: PASS 598s START /main/json/ - object_del 598s END /main/json/ - object_del Time: <1ms Result: PASS 598s START /main/json/ - object_get 598s END /main/json/ - object_get Time: <1ms Result: PASS 598s START /main/json/ - object_set_overwriting 598s END /main/json/ - object_set_overwriting Time: <1ms Result: PASS 598s START /main/json/ - object_set 598s END /main/json/ - object_set Time: <1ms Result: PASS 598s START /main/json/ - object_alloc 598s END /main/json/ - object_alloc Time: <1ms Result: PASS 598s START /main/json/ - array_null 598s END /main/json/ - array_null Time: <1ms Result: PASS 598s START /main/json/ - array_extend 598s END /main/json/ - array_extend Time: <1ms Result: PASS 598s START /main/json/ - array_clear 598s END /main/json/ - array_clear Time: <1ms Result: PASS 598s START /main/json/ - array_remove 598s END /main/json/ - array_remove Time: <1ms Result: PASS 598s START /main/json/ - array_set 598s END /main/json/ - array_set Time: <1ms Result: PASS 598s START /main/json/ - array_insert 598s END /main/json/ - array_insert Time: <1ms Result: PASS 598s START /main/json/ - array_append 598s END /main/json/ - array_append Time: <1ms Result: PASS 598s START /main/json/ - array_create 598s END /main/json/ - array_create Time: <1ms Result: PASS 598s START /main/json/ - non_int 598s END /main/json/ - non_int Time: <1ms Result: PASS 598s START /main/json/ - type_int 598s END /main/json/ - type_int Time: <1ms Result: PASS 598s START /main/json/ - stringf 598s END /main/json/ - stringf Time: <1ms Result: PASS 598s START /main/json/ - string_null 598s END /main/json/ - string_null Time: <1ms Result: PASS 598s START /main/json/ - type_string 598s END /main/json/ - type_string Time: <1ms Result: PASS 598s START /main/json/ - null_val 598s END /main/json/ - null_val Time: <1ms Result: PASS 598s START /main/json/ - type_null 598s END /main/json/ - type_null Time: <1ms Result: PASS 598s START /main/json/ - type_bool1 598s END /main/json/ - type_bool1 Time: <1ms Result: PASS 598s START /main/json/ - type_bool0 598s END /main/json/ - type_bool0 Time: <1ms Result: PASS 598s START /main/json/ - type_true 598s END /main/json/ - type_true Time: <1ms Result: PASS 598s START /main/json/ - type_false 598s END /main/json/ - type_false Time: <1ms Result: PASS 598s START /main/linkedlists/ - double_ll_tests 598s END /main/linkedlists/ - double_ll_tests Time: <1ms Result: PASS 598s START /main/linkedlists/ - ll_tests 598s END /main/linkedlists/ - ll_tests Time: <1ms Result: PASS 598s START /main/lock/ - cleanup_order_test 598s [test_scoped_lock.c:test_ref:149]: Ref is occurring 598s [test_scoped_lock.c:test_lock:117]: Lock is occurring 598s [test_scoped_lock.c:test_unlock:133]: Unlock is occurring 598s [test_scoped_lock.c:test_unref:166]: Unref is occurring 598s [test_scoped_lock.c:test_ref:149]: Ref is occurring 598s [test_scoped_lock.c:test_lock:117]: Lock is occurring 598s [test_scoped_lock.c:test_unlock:133]: Unlock is occurring 598s [test_scoped_lock.c:test_unref:166]: Unref is occurring 598s END /main/lock/ - cleanup_order_test Time: <1ms Result: PASS 598s START /main/lock/ - lock_test 598s END /main/lock/ - lock_test Time: <1ms Result: PASS 598s START /main/lock/ - named_lock_test 598s [test_named_lock.c:named_lock_test:80]: This test should take about 3 seconds 601s END /main/lock/ - named_lock_test Time: 3000ms Result: PASS 601s START /main/logging/ - scope_test 601s END /main/logging/ - scope_test Time: <1ms Result: PASS 601s START /main/media_cache/ - create_update_off_nominal 601s END /main/media_cache/ - create_update_off_nominal Time: <1ms Result: PASS 601s START /main/media_cache/ - create_update_metadata 601s [test_media_cache.c:create_update_metadata:364]: Got /tmp/test-media-cache-OjJRo3 for second file path 601s END /main/media_cache/ - create_update_metadata Time: 2ms Result: PASS 601s START /main/media_cache/ - create_update_nominal 601s [test_media_cache.c:create_update_nominal:235]: Creating resource with /tmp/test-media-cache-S1yYJG 601s [test_media_cache.c:create_update_nominal:240]: Got /tmp/test-media-cache-S1yYJG for first file path 601s [test_media_cache.c:create_update_nominal:244]: Creating resource with /tmp/test-media-cache-xpx0Xg 601s [test_media_cache.c:create_update_nominal:249]: Got /tmp/test-media-cache-xpx0Xg for second file path 601s END /main/media_cache/ - create_update_nominal Time: <1ms Result: PASS 601s START /main/media_cache/ - exists_off_nominal 601s END /main/media_cache/ - exists_off_nominal Time: <1ms Result: PASS 601s START /main/media_cache/ - exists_nominal 601s END /main/media_cache/ - exists_nominal Time: <1ms Result: PASS 601s START /main/netsock2/ - split_hostport 601s END /main/netsock2/ - split_hostport Time: <1ms Result: PASS 601s START /main/netsock2/ - parsing 601s END /main/netsock2/ - parsing Time: <1ms Result: PASS 601s START /main/optional_api/ - test_provide_last 601s END /main/optional_api/ - test_provide_last Time: <1ms Result: PASS 601s START /main/optional_api/ - test_provide_first 601s END /main/optional_api/ - test_provide_first Time: <1ms Result: PASS 601s START /main/pbx/ - test_substitution 601s [test_substitution.c:test_substitution:244]: Testing variable substitution ... 601s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGANI2}' . . . . . passed 601s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGTON}' . . . . . passed 601s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGTNS}' . . . . . passed 601s [test_substitution.c:test_chan_integer_accessor:89]: Tested '${HANGUPCAUSE}' . . . . . passed 601s [test_substitution.c:test_chan_integer_accessor:89]: Tested '${PRIORITY}' . . . . . passed 601s [test_substitution.c:test_chan_string:115]: Tested '${CONTEXT}' . . . . . passed 601s [test_substitution.c:test_chan_string:115]: Tested '${EXTEN}' . . . . . passed 601s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(language)}' . . . . . passed 601s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(musicclass)}' . . . . . passed 601s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(parkinglot)}' . . . . . passed 601s [test_substitution.c:test_chan_variable:144]: Tested '${CALLERID(name)}' . . . . . passed 601s [test_substitution.c:test_chan_variable:144]: Tested '${CURLOPT(proxyuserpwd)}' . . . . . passed 601s [test_substitution.c:test_chan_variable:144]: Tested '${CDR(foo)}' . . . . . passed 601s [test_substitution.c:test_chan_variable:144]: Tested '${ENV(foo)}' . . . . . passed 601s [test_substitution.c:test_chan_variable:144]: Tested '${GLOBAL(foo)}' . . . . . passed 601s [test_substitution.c:test_chan_variable:144]: Tested '${GROUP()}' . . . . . passed 601s [test_substitution.c:test_2way_function:193]: Tested '${AES_ENCRYPT(abcdefghijklmnop,)}' and '${AES_DECRYPT(abcdefghijklmnop,)}' . . . . . passed 601s [test_substitution.c:test_2way_function:193]: Tested '${BASE64_ENCODE()}' and '${BASE64_DECODE()}' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested '123123' ('${foo}${foo}') == '123123' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested 'A123A123A' ('A${foo}A${foo}A') == 'A123A123A' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested 'A123A' ('A${${bar}}A') == 'A123A' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested 'A123A' ('A${${baz}o}A') == 'A123A' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested 'A23A' ('A${${baz}o:1}A') == 'A23A' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:1:1}A') == 'A2A' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:1:-1}A') == 'A2A' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested 'A3A' ('A${${baz}o:-1:1}A') == 'A3A' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:-2:1}A') == 'A2A' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:-2:-1}A') == 'A2A' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested 'cd&ef' ('${LISTFILTER(list1,&,ab)}') == 'cd&ef' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested 'ab&ef' ('${LISTFILTER(list1,&,cd)}') == 'ab&ef' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd' ('${LISTFILTER(list1,&,ef)}') == 'ab&cd' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,gh)}') == 'ab&cd&ef' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,c)}') == 'ab&cd&ef' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,d)}') == 'ab&cd&ef' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested '' ('${LISTFILTER(list2,&,ab)}') == '' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested '' ('${LISTFILTER(list_empty,&,ab)}') == '' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested '123,456' ('${SHELL(printf '%d' 123)},${SHELL(printf '%d' 456)}') == '123,456' . . . . . passed 601s [test_substitution.c:test_expected_result:215]: Tested '123,,456' ('${foo},${CDR(answer)},${SHELL(printf '%d' 456)}') == '123,,456' . . . . . passed 601s [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 601s [test_substitution.c:test_expected_result:215]: Tested '123,,' ('${foo},${this_does_not_exist},${THIS_DOES_NOT_EXIST(either)}') == '123,,' . . . . . passed 601s [test_substitution.c:test_chan_function:168]: Tested '${BLACKLIST(foo)}' . . . . . passed 601s [test_substitution.c:test_chan_function:168]: Tested '${EVAL(foo)}' . . . . . passed 601s [test_substitution.c:test_chan_function:168]: Tested '${FIELDNUM(foo)}' . . . . . passed 601s [test_substitution.c:test_chan_function:168]: Tested '${FIELDQTY(foo)}' . . . . . passed 601s [test_substitution.c:test_chan_function:168]: Tested '${HASHKEYS(foo)}' . . . . . passed 601s [test_substitution.c:test_chan_function:168]: Tested '${IMPORT(foo)}' . . . . . passed 601s [test_substitution.c:test_chan_function:168]: Tested '${PP_EACH_USER(foo)}' . . . . . passed 601s [test_substitution.c:test_chan_function:168]: Tested '${TOLOWER(foo)}' . . . . . passed 601s [test_substitution.c:test_chan_function:168]: Tested '${TOUPPER(foo)}' . . . . . passed 601s END /main/pbx/ - test_substitution Time: 8ms Result: PASS 601s START /main/pbx/ - test_MATH_function 601s [func_math.c:test_MATH_function:682]: Testing MATH() substitution ... 601s END /main/pbx/ - test_MATH_function Time: <1ms Result: PASS 601s START /main/pbx/ - pattern_match_test 601s [test_pbx.c:test_exten:183]: Successfully matched 200 to exten _2. in context test_pattern with the old pattern match engine 601s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the old pattern match engine 601s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the old pattern match engine 601s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern_include with the old pattern match engine 601s [test_pbx.c:test_exten:183]: Successfully matched 200 to exten _2. in context test_pattern with the new pattern match engine 601s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the new pattern match engine 601s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the new pattern match engine 601s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern_include with the new pattern match engine 601s END /main/pbx/ - pattern_match_test Time: <1ms Result: PASS 601s START /main/pbx/ - variable_substrings 601s END /main/pbx/ - variable_substrings Time: <1ms Result: PASS 601s START /main/poll/ - poll_test 601s [test_poll.c:poll_test:95]: Creating handle that should NEVER block on write 601s [test_poll.c:poll_test:101]: Creating handle that should NEVER block on read 601s [test_poll.c:poll_test:108]: Creating handle that should block on read 601s [test_poll.c:poll_test:168]: Starting thread to ensure we don't block forever 601s [test_poll.c:poll_test:194]: Cancelling failsafe thread. 601s END /main/poll/ - poll_test Time: <1ms Result: PASS 601s START /main/presence/ - channel_presence 601s END /main/presence/ - channel_presence Time: <1ms Result: PASS 601s START /main/sample/ - sample_test 601s [test_skel.c:sample_test:57]: Executing sample test... 601s END /main/sample/ - sample_test Time: <1ms Result: PASS 601s START /main/sched/ - sched_test_freebird 601s [test_sched.c:sched_test_freebird:440]: Received signal, calling Scedule and UNREF 601s [test_sched.c:sched_test_freebird:441]: ID: 1 604s [test_sched.c:sched_test_freebird:448]: Correct number of references '2' 604s END /main/sched/ - sched_test_freebird Time: 3000ms Result: PASS 604s START /main/sched/ - sched_test_order 605s END /main/sched/ - sched_test_order Time: 400ms Result: PASS 605s START /main/sorcery/ - wizard_read_only 605s END /main/sorcery/ - wizard_read_only Time: <1ms Result: PASS 605s START /main/sorcery/ - wizard_observation 605s END /main/sorcery/ - wizard_observation Time: <1ms Result: PASS 605s START /main/sorcery/ - instance_observation 605s END /main/sorcery/ - instance_observation Time: <1ms Result: PASS 605s START /main/sorcery/ - global_observation 605s END /main/sorcery/ - global_observation Time: <1ms Result: PASS 605s START /main/sorcery/ - object_field_registered 605s END /main/sorcery/ - object_field_registered Time: <1ms Result: PASS 605s START /main/sorcery/ - dialplan_function 605s END /main/sorcery/ - dialplan_function Time: <1ms Result: PASS 605s START /main/sorcery/ - configuration_file_wizard_retrieve_multiple_all 605s END /main/sorcery/ - configuration_file_wizard_retrieve_multiple_all Time: <1ms Result: PASS 605s START /main/sorcery/ - configuration_file_wizard_retrieve_multiple 605s END /main/sorcery/ - configuration_file_wizard_retrieve_multiple Time: <1ms Result: PASS 605s START /main/sorcery/ - configuration_file_wizard_retrieve_field 605s END /main/sorcery/ - configuration_file_wizard_retrieve_field Time: <1ms Result: PASS 605s START /main/sorcery/ - configuration_file_wizard_with_criteria 605s END /main/sorcery/ - configuration_file_wizard_with_criteria Time: <1ms Result: PASS 605s START /main/sorcery/ - configuration_file_wizard_with_file_integrity 605s END /main/sorcery/ - configuration_file_wizard_with_file_integrity Time: <1ms Result: PASS 605s START /main/sorcery/ - configuration_file_wizard 605s END /main/sorcery/ - configuration_file_wizard Time: <1ms Result: PASS 605s START /main/sorcery/ - object_type_observer 605s END /main/sorcery/ - object_type_observer Time: <1ms Result: PASS 605s START /main/sorcery/ - caching_wizard_behavior 605s END /main/sorcery/ - caching_wizard_behavior Time: <1ms Result: PASS 605s START /main/sorcery/ - object_is_stale 605s END /main/sorcery/ - object_is_stale Time: <1ms Result: PASS 605s START /main/sorcery/ - object_delete_uncreated 605s END /main/sorcery/ - object_delete_uncreated Time: <1ms Result: PASS 605s START /main/sorcery/ - object_delete 605s END /main/sorcery/ - object_delete Time: <1ms Result: PASS 605s START /main/sorcery/ - object_update_uncreated 605s END /main/sorcery/ - object_update_uncreated Time: <1ms Result: PASS 605s START /main/sorcery/ - object_update 605s END /main/sorcery/ - object_update Time: <1ms Result: PASS 605s START /main/sorcery/ - object_retrieve_regex 605s END /main/sorcery/ - object_retrieve_regex Time: <1ms Result: PASS 605s START /main/sorcery/ - object_retrieve_multiple_field 605s END /main/sorcery/ - object_retrieve_multiple_field Time: <1ms Result: PASS 605s START /main/sorcery/ - object_retrieve_multiple_all 605s END /main/sorcery/ - object_retrieve_multiple_all Time: <1ms Result: PASS 605s START /main/sorcery/ - object_retrieve_field 605s END /main/sorcery/ - object_retrieve_field Time: <1ms Result: PASS 605s START /main/sorcery/ - object_retrieve_id 605s END /main/sorcery/ - object_retrieve_id Time: <1ms Result: PASS 605s START /main/sorcery/ - object_create 605s END /main/sorcery/ - object_create Time: <1ms Result: PASS 605s START /main/sorcery/ - changeset_create_unchanged 605s END /main/sorcery/ - changeset_create_unchanged Time: <1ms Result: PASS 605s START /main/sorcery/ - changeset_create 605s END /main/sorcery/ - changeset_create Time: <1ms Result: PASS 605s START /main/sorcery/ - extended_fields 605s END /main/sorcery/ - extended_fields Time: <1ms Result: PASS 605s START /main/sorcery/ - objectset_apply_fields 605s END /main/sorcery/ - objectset_apply_fields Time: <1ms Result: PASS 605s START /main/sorcery/ - objectset_transform 605s END /main/sorcery/ - objectset_transform Time: <1ms Result: PASS 605s START /main/sorcery/ - objectset_apply_invalid 605s END /main/sorcery/ - objectset_apply_invalid Time: <1ms Result: PASS 605s START /main/sorcery/ - objectset_apply_handler 605s END /main/sorcery/ - objectset_apply_handler Time: <1ms Result: PASS 605s START /main/sorcery/ - objectset_apply 605s END /main/sorcery/ - objectset_apply Time: <1ms Result: PASS 605s START /main/sorcery/ - objectset_create_regex 605s END /main/sorcery/ - objectset_create_regex Time: <1ms Result: PASS 605s START /main/sorcery/ - objectset_json_create 605s END /main/sorcery/ - objectset_json_create Time: <1ms Result: PASS 605s START /main/sorcery/ - objectset_create 605s END /main/sorcery/ - objectset_create Time: <1ms Result: PASS 605s START /main/sorcery/ - object_diff_native 605s END /main/sorcery/ - object_diff_native Time: <1ms Result: PASS 605s START /main/sorcery/ - object_diff 605s END /main/sorcery/ - object_diff Time: <1ms Result: PASS 605s START /main/sorcery/ - object_copy_native 605s END /main/sorcery/ - object_copy_native Time: <1ms Result: PASS 605s START /main/sorcery/ - object_copy 605s END /main/sorcery/ - object_copy Time: <1ms Result: PASS 605s START /main/sorcery/ - object_alloc_without_id 605s END /main/sorcery/ - object_alloc_without_id Time: <1ms Result: PASS 605s START /main/sorcery/ - object_alloc_with_id 605s END /main/sorcery/ - object_alloc_with_id Time: <1ms Result: PASS 605s START /main/sorcery/ - object_fields_register 605s END /main/sorcery/ - object_fields_register Time: <1ms Result: PASS 605s START /main/sorcery/ - object_field_register 605s END /main/sorcery/ - object_field_register Time: <1ms Result: PASS 605s START /main/sorcery/ - object_register_without_mapping 605s END /main/sorcery/ - object_register_without_mapping Time: <1ms Result: PASS 605s START /main/sorcery/ - object_register 605s END /main/sorcery/ - object_register Time: <1ms Result: PASS 605s START /main/sorcery/ - apply_config 605s END /main/sorcery/ - apply_config Time: <1ms Result: PASS 605s START /main/sorcery/ - apply_default 605s END /main/sorcery/ - apply_default Time: <1ms Result: PASS 605s START /main/sorcery/ - open 605s END /main/sorcery/ - open Time: <1ms Result: PASS 605s START /main/sorcery/ - wizard_registration 605s END /main/sorcery/ - wizard_registration Time: <1ms Result: PASS 605s START /main/sorcery/ - wizard_apply_and_insert 605s END /main/sorcery/ - wizard_apply_and_insert Time: <1ms Result: PASS 605s START /main/stdtime/ - time_create_by_unit_str 605s END /main/stdtime/ - time_create_by_unit_str Time: <1ms Result: PASS 605s START /main/stdtime/ - time_create_by_unit 605s END /main/stdtime/ - time_create_by_unit Time: <1ms Result: PASS 605s START /main/stdtime/ - time_str_to_unit 605s END /main/stdtime/ - time_str_to_unit Time: <1ms Result: PASS 605s START /main/stdtime/ - time_tv_to_usec 605s END /main/stdtime/ - time_tv_to_usec Time: <1ms Result: PASS 605s START /main/stdtime/ - timezone_watch 605s [test_time.c:test_timezone_watch:82]: Executing deletion test... 605s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.w0ULR7/test 606s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.w0ULR7/test 606s [test_time.c:test_timezone_watch:82]: Executing symlink test... 606s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.w0ULR7/test 607s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.w0ULR7/test 607s END /main/stdtime/ - timezone_watch Time: 2237ms Result: PASS 607s START /main/stream/ - stream_topology_map_create 607s END /main/stream/ - stream_topology_map_create Time: <1ms Result: PASS 607s START /main/stream/ - format_cap_from_stream_topology 607s END /main/stream/ - format_cap_from_stream_topology Time: <1ms Result: PASS 607s START /main/stream/ - stream_topology_change_request_from_channel 607s END /main/stream/ - stream_topology_change_request_from_channel Time: <1ms Result: PASS 607s START /main/stream/ - stream_topology_change_request_from_application 607s END /main/stream/ - stream_topology_change_request_from_application Time: <1ms Result: PASS 607s START /main/stream/ - stream_topology_change_request_from_channel_non_multistream 607s END /main/stream/ - stream_topology_change_request_from_channel_non_multistream Time: <1ms Result: PASS 607s START /main/stream/ - stream_topology_change_request_from_application_non_multistream 607s END /main/stream/ - stream_topology_change_request_from_application_non_multistream Time: <1ms Result: PASS 607s START /main/stream/ - stream_read_multistream 607s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 607s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 607s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 607s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 607s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 4 Frames: 16 Frames per read: 1 Expected Nulls: 8 607s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 8 607s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 4 Frames: 16 Frames per read: 1 Expected Nulls: 0 607s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 607s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 607s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 607s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 607s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 607s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 4 Frames: 16 Frames per read: 3 Expected Nulls: 8 607s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 8 607s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 4 Frames: 16 Frames per read: 3 Expected Nulls: 0 607s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 607s END /main/stream/ - stream_read_multistream Time: 1ms Result: PASS 607s START /main/stream/ - stream_read_non_multistream 607s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 607s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 607s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 607s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 607s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 607s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 607s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 607s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 607s END /main/stream/ - stream_read_non_multistream Time: <1ms Result: PASS 607s START /main/stream/ - stream_write_multistream 607s END /main/stream/ - stream_write_multistream Time: <1ms Result: PASS 607s START /main/stream/ - stream_write_non_multistream 607s END /main/stream/ - stream_write_non_multistream Time: <1ms Result: PASS 607s START /main/stream/ - stream_topology_channel_set 607s END /main/stream/ - stream_topology_channel_set Time: <1ms Result: PASS 607s START /main/stream/ - stream_topology_create_from_channel_nativeformats 607s END /main/stream/ - stream_topology_create_from_channel_nativeformats Time: <1ms Result: PASS 607s START /main/stream/ - stream_topology_get_first_stream_by_type 607s END /main/stream/ - stream_topology_get_first_stream_by_type Time: <1ms Result: PASS 607s START /main/stream/ - stream_topology_create_from_format_cap 607s END /main/stream/ - stream_topology_create_from_format_cap Time: <1ms Result: PASS 607s START /main/stream/ - stream_topology_del_stream 607s END /main/stream/ - stream_topology_del_stream Time: <1ms Result: PASS 607s START /main/stream/ - stream_topology_set_stream 607s END /main/stream/ - stream_topology_set_stream Time: <1ms Result: PASS 607s START /main/stream/ - stream_topology_append_stream 607s END /main/stream/ - stream_topology_append_stream Time: <1ms Result: PASS 607s START /main/stream/ - stream_topology_clone 607s END /main/stream/ - stream_topology_clone Time: <1ms Result: PASS 607s START /main/stream/ - stream_topology_create 607s END /main/stream/ - stream_topology_create Time: <1ms Result: PASS 607s START /main/stream/ - stream_metadata 607s END /main/stream/ - stream_metadata Time: <1ms Result: PASS 607s START /main/stream/ - stream_set_state 607s END /main/stream/ - stream_set_state Time: <1ms Result: PASS 607s START /main/stream/ - stream_set_formats 607s END /main/stream/ - stream_set_formats Time: <1ms Result: PASS 607s START /main/stream/ - stream_set_type 607s END /main/stream/ - stream_set_type Time: <1ms Result: PASS 607s START /main/stream/ - stream_create_no_name 607s END /main/stream/ - stream_create_no_name Time: <1ms Result: PASS 607s START /main/stream/ - stream_create 607s END /main/stream/ - stream_create Time: <1ms Result: PASS 607s START /main/strings/ - in_delimited_string 607s END /main/strings/ - in_delimited_string Time: <1ms Result: PASS 607s START /main/strings/ - temp_strings 607s END /main/strings/ - temp_strings Time: <1ms Result: PASS 607s START /main/strings/ - strings_match 607s END /main/strings/ - strings_match Time: <1ms Result: PASS 607s START /main/strings/ - escape 607s END /main/strings/ - escape Time: <1ms Result: PASS 607s START /main/strings/ - escape_semicolons 607s END /main/strings/ - escape_semicolons Time: <1ms Result: PASS 607s START /main/strings/ - strsep_quoted 607s END /main/strings/ - strsep_quoted Time: <1ms Result: PASS 607s START /main/strings/ - strsep 607s END /main/strings/ - strsep Time: <1ms Result: PASS 607s START /main/strings/ - ends_with 607s END /main/strings/ - ends_with Time: <1ms Result: PASS 607s START /main/strings/ - begins_with 607s END /main/strings/ - begins_with Time: <1ms Result: PASS 607s START /main/strings/ - str_test 607s END /main/strings/ - str_test Time: <1ms Result: PASS 607s START /main/taskprocessor/ - serializer_pool 611s END /main/taskprocessor/ - serializer_pool Time: 4000ms Result: PASS 611s START /main/taskprocessor/ - taskprocessor_push_local 611s END /main/taskprocessor/ - taskprocessor_push_local Time: <1ms Result: PASS 611s START /main/taskprocessor/ - taskprocessor_shutdown 611s END /main/taskprocessor/ - taskprocessor_shutdown Time: <1ms Result: PASS 611s START /main/taskprocessor/ - taskprocessor_listener 611s END /main/taskprocessor/ - taskprocessor_listener Time: <1ms Result: PASS 611s START /main/taskprocessor/ - subsystem_alert 611s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 1 611s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 2 611s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 3 611s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 4 611s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 5 611s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 6 611s [test_taskprocessor.c:subsystem_alert:244]: Subsystem alert triggered unexpectedly at 5 611s [test_taskprocessor.c:subsystem_alert:248]: Global alert triggered unexpectedly at 5 611s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 7 611s [test_taskprocessor.c:subsystem_alert:237]: Subsystem alert triggered correctly at 6 611s [test_taskprocessor.c:subsystem_alert:240]: Global alert triggered correctly at 6 611s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 8 611s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 9 611s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 10 611s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 1 611s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 2 612s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 3 612s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 4 613s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 5 613s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 6 614s [test_taskprocessor.c:subsystem_alert:279]: Subsystem alert cleared correctly at 3 614s [test_taskprocessor.c:subsystem_alert:282]: Global alert cleared correctly at 3 614s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 7 614s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 8 615s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 9 615s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 10 616s END /main/taskprocessor/ - subsystem_alert Time: 5001ms Result: FAIL 616s START /main/taskprocessor/ - default_taskprocessor_load 616s END /main/taskprocessor/ - default_taskprocessor_load Time: 61ms Result: PASS 616s START /main/taskprocessor/ - default_taskprocessor 616s END /main/taskprocessor/ - default_taskprocessor Time: <1ms Result: PASS 616s START /main/test/ - registrations 616s END /main/test/ - registrations Time: <1ms Result: PASS 616s START /main/test_capture/ - test_capture_false 616s [test_capture.c:test_capture_false:120]: Executing false exit test... 616s END /main/test_capture/ - test_capture_false Time: 6ms Result: PASS 616s START /main/test_capture/ - test_capture_true 616s [test_capture.c:test_capture_true:61]: Executing true exit test... 616s END /main/test_capture/ - test_capture_true Time: 5ms Result: PASS 616s START /main/test_capture/ - test_capture_stdout_stderr 616s [test_capture.c:test_capture_stdout_stderr:318]: Executing stdout/stderr test... 616s END /main/test_capture/ - test_capture_stdout_stderr Time: 5ms Result: PASS 616s START /main/test_capture/ - test_capture_with_dynamic 616s [test_capture.c:test_capture_with_dynamic:249]: Executing dynamic argument test... 616s END /main/test_capture/ - test_capture_with_dynamic Time: 5ms Result: PASS 616s START /main/test_capture/ - test_capture_with_stdin 616s [test_capture.c:test_capture_with_stdin:183]: Executing stdin test... 616s END /main/test_capture/ - test_capture_with_stdin Time: 5ms Result: PASS 616s START /main/threadpool/ - threadpool_serializer_dupe 616s END /main/threadpool/ - threadpool_serializer_dupe Time: <1ms Result: PASS 616s START /main/threadpool/ - threadpool_serializer 617s END /main/threadpool/ - threadpool_serializer Time: 1000ms Result: PASS 617s START /main/threadpool/ - more_destruction 617s END /main/threadpool/ - more_destruction Time: <1ms Result: PASS 617s START /main/threadpool/ - task_distribution 617s END /main/threadpool/ - task_distribution Time: <1ms Result: PASS 617s START /main/threadpool/ - reactivation 617s END /main/threadpool/ - reactivation Time: <1ms Result: PASS 617s START /main/threadpool/ - max_size 617s END /main/threadpool/ - max_size Time: <1ms Result: PASS 617s START /main/threadpool/ - auto_increment 617s END /main/threadpool/ - auto_increment Time: <1ms Result: PASS 617s START /main/threadpool/ - one_thread_multiple_tasks 617s END /main/threadpool/ - one_thread_multiple_tasks Time: <1ms Result: PASS 617s START /main/threadpool/ - one_thread_one_task 617s END /main/threadpool/ - one_thread_one_task Time: <1ms Result: PASS 617s START /main/threadpool/ - one_task_one_thread 617s END /main/threadpool/ - one_task_one_thread Time: <1ms Result: PASS 617s START /main/threadpool/ - thread_timeout_thrash 648s END /main/threadpool/ - thread_timeout_thrash Time: 31007ms Result: PASS 648s START /main/threadpool/ - thread_timeout 650s END /main/threadpool/ - thread_timeout Time: 2000ms Result: PASS 650s START /main/threadpool/ - thread_destruction 650s END /main/threadpool/ - thread_destruction Time: <1ms Result: PASS 650s START /main/threadpool/ - thread_creation 650s END /main/threadpool/ - thread_creation Time: <1ms Result: PASS 650s START /main/threadpool/ - initial_threads 650s END /main/threadpool/ - initial_threads Time: <1ms Result: PASS 650s START /main/threadpool/ - push 650s END /main/threadpool/ - push Time: <1ms Result: PASS 650s START /main/uri/ - uri_default_http_secure 650s END /main/uri/ - uri_default_http_secure Time: <1ms Result: PASS 650s START /main/uri/ - uri_default_http 650s END /main/uri/ - uri_default_http Time: <1ms Result: PASS 650s START /main/uri/ - uri_parse 650s END /main/uri/ - uri_parse Time: <1ms Result: PASS 650s START /main/utf8/ - replace_invalid 650s END /main/utf8/ - replace_invalid Time: <1ms Result: PASS 650s START /main/utf8/ - utf8_validator 650s END /main/utf8/ - utf8_validator Time: <1ms Result: PASS 650s START /main/utf8/ - copy_string 650s END /main/utf8/ - copy_string Time: <1ms Result: PASS 650s START /main/utf8/ - is_valid 650s END /main/utf8/ - is_valid Time: <1ms Result: PASS 650s START /main/utils/ - string_field_aggregate_test 650s [test_stringfields.c:string_field_aggregate_test:392]: Structures 3 embedded pool initialized successfully. 650s [test_stringfields.c:string_field_aggregate_test:410]: Structures 3 additional pool initialized successfully. 650s [test_stringfields.c:string_field_aggregate_test:422]: Structures 1/2 are equal as expected. 650s [test_stringfields.c:string_field_aggregate_test:430]: Structures 1/3 are different as expected. 650s [test_stringfields.c:string_field_aggregate_test:438]: Structures 2/3 are different as expected. 650s [test_stringfields.c:string_field_aggregate_test:446]: Structures 3/4 are different as expected. 650s [test_stringfields.c:string_field_aggregate_test:454]: Copying from structure 3 to structure 1 succeeded! 650s [test_stringfields.c:string_field_aggregate_test:463]: Structures 1/3 are equal as expected. 650s [test_stringfields.c:string_field_aggregate_test:470]: Structures 1/2 are different as expected. 650s [test_stringfields.c:string_field_aggregate_test:473]: Reset but don't free. 650s [test_stringfields.c:string_field_aggregate_test:484]: Structures 1/2 are the same (empty) as expected. 650s [test_stringfields.c:string_field_aggregate_test:492]: Structure 4 embedded pool is the current pool as expected. 650s [test_stringfields.c:string_field_aggregate_test:500]: Structure 4 embedded pool does not have a previous as expected. 650s END /main/utils/ - string_field_aggregate_test Time: <1ms Result: PASS 650s START /main/utils/ - string_field_test 650s [test_stringfields.c:string_field_test:79]: First things first. Let's see if we can actually allocate string fields 650s [test_stringfields.c:string_field_test:85]: All right! Successfully allocated! Now let's get down to business 650s [test_stringfields.c:string_field_test:89]: We're going to set some string fields and perform some checks 650s [test_stringfields.c:string_field_test:94]: First we're going to make sure that the strings are actually set to what we expect 650s [test_stringfields.c:string_field_test:100]: test_struct.string1 appears to be all clear. It has 'elephant' and that's what we expect 650s [test_stringfields.c:string_field_test:107]: test_struct.string2 appears to be all clear. It has 'hippopotamus' and that's what we expect 650s [test_stringfields.c:string_field_test:110]: Now let's make sure that our recorded capacities for these strings is what we expect 650s [test_stringfields.c:string_field_test:117]: string1 has the allocation area we expect: 9 650s [test_stringfields.c:string_field_test:125]: string2 has the allocation area we expect: 13 650s [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 650s [test_stringfields.c:string_field_test:137]: string1 successfully was changed to 'rhino' 650s [test_stringfields.c:string_field_test:144]: Shrinking string1 allowed it to stay in the same place in memory 650s [test_stringfields.c:string_field_test:151]: Shrinking string1 did not change its allocation area (This is a good thing) 650s [test_stringfields.c:string_field_test:154]: Next, let's increase it a little but not all the way to its original size 650s [test_stringfields.c:string_field_test:163]: string1 successfully was changed to 'mammoth' 650s [test_stringfields.c:string_field_test:170]: Expanding string1 allowed it to stay in the same place in memory 650s [test_stringfields.c:string_field_test:177]: Expanding string1 did not change its allocation area (This is a good thing) 650s [test_stringfields.c:string_field_test:180]: Cool, now let's bring it back to its original size and see what happens 650s [test_stringfields.c:string_field_test:188]: string1 successfully changed to 'elephant' 650s [test_stringfields.c:string_field_test:195]: Restoring string1 did not cause it to move (This is a good thing) 650s [test_stringfields.c:string_field_test:202]: The allocation amount for string1 is still holding steady 650s [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 650s [test_stringfields.c:string_field_test:214]: string2 successfully changed to 'hippopotamus face' 650s [test_stringfields.c:string_field_test:222]: The allocation amount successfully increased for string2 when it grew 650s [test_stringfields.c:string_field_test:229]: string2 stayed in place when it grew. Good job! 650s [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 650s [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' 650s [test_stringfields.c:string_field_test:248]: Good. Setting string1 to a long value caused it to change addresses 650s [test_stringfields.c:string_field_test:256]: The stored allocation size of string1 is what we expect 650s [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 650s [test_stringfields.c:string_field_test:281]: Three different pools are linked as expected. 650s [test_stringfields.c:string_field_test:289]: After removing a pool the remaining two are linked as expected. 650s END /main/utils/ - string_field_test Time: <1ms Result: PASS 650s START /main/utils/ - quote_unescaping 650s END /main/utils/ - quote_unescaping Time: <1ms Result: PASS 650s START /main/utils/ - quote_mutation 650s END /main/utils/ - quote_mutation Time: <1ms Result: PASS 650s START /main/utils/ - crypt_test 650s END /main/utils/ - crypt_test Time: 14ms Result: PASS 650s START /main/utils/ - safe_mkdir_test 650s END /main/utils/ - safe_mkdir_test Time: <1ms Result: PASS 650s START /main/utils/ - base64_test 650s END /main/utils/ - base64_test Time: <1ms Result: PASS 650s START /main/utils/ - sha1_test 650s [test_utils.c:sha1_test:250]: Testing SHA1 ... 650s END /main/utils/ - sha1_test Time: <1ms Result: PASS 650s START /main/utils/ - md5_test 650s [test_utils.c:md5_test:205]: Testing MD5 ... 650s END /main/utils/ - md5_test Time: <1ms Result: PASS 650s START /main/utils/ - quoted_escape_test 650s END /main/utils/ - quoted_escape_test Time: <1ms Result: PASS 650s START /main/utils/ - uri_encode_decode_test 650s END /main/utils/ - uri_encode_decode_test Time: <1ms Result: PASS 650s START /main/uuid/ - uuid 650s [test_uuid.c:uuid:59]: Generate UUID direct to string, got 7dde63eb-87ba-49bb-aae1-25363860ae9e 650s [test_uuid.c:uuid:90]: Second generated UUID converted to string, got ab947f36-52f6-4a0a-b8c4-fd76817fa15c 650s END /main/uuid/ - uuid Time: <1ms Result: PASS 650s START /main/vector/ - basic 650s END /main/vector/ - basic Time: <1ms Result: PASS 650s START /main/vector/ - basic_integer 650s END /main/vector/ - basic_integer Time: <1ms Result: PASS 650s START /main/vector/ - callbacks 650s END /main/vector/ - callbacks Time: <1ms Result: PASS 650s START /main/vector/ - locks 650s END /main/vector/ - locks Time: <1ms Result: PASS 650s START /main/voicemail_api/ - off_nominal_msg_playback 650s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1495]: Created message in test_vm_api_1234/Old with ID 1713550072-909401725 650s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1495]: Created message in test_vm_api_1234/INBOX with ID 1713550072-960311778 650s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1495]: Created message in test_vm_api_2345/INBOX with ID 1713550072-1500739833 650s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1495]: Created message in test_vm_api_2345/INBOX with ID 1713550072-719848782 650s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1504]: Playing back message from invalid mailbox 650s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1507]: Playing back message from NULL mailbox 650s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1510]: Playing back message from invalid context 650s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1513]: Playing back message from invalid folder 650s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1516]: Playing back message from NULL folder 650s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1519]: Playing back message with invalid message specifier 650s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1522]: Playing back message with NULL message specifier 650s END /main/voicemail_api/ - off_nominal_msg_playback Time: 9ms Result: PASS 650s START /main/voicemail_api/ - nominal_msg_playback 650s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1433]: Created message in test_vm_api_1234/Old with ID 1713550072-909401725 650s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1433]: Created message in test_vm_api_1234/INBOX with ID 1713550072-960311778 650s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1433]: Created message in test_vm_api_2345/INBOX with ID 1713550072-1500739833 650s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1433]: Created message in test_vm_api_2345/INBOX with ID 1713550072-719848782 650s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1445]: Playing back message from test_vm_api_1234 to mock channel 651s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1448]: Playing back message from test_vm_api_2345 to callback function 651s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1453]: Playing back message from test_vm_api_2345 to callback function with default context 651s END /main/voicemail_api/ - nominal_msg_playback Time: 453ms Result: PASS 651s START /main/voicemail_api/ - off_nominal_forward 651s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1355]: Created message in test_vm_api_1234/Old with ID 1713550072-909401725 651s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1355]: Created message in test_vm_api_1234/INBOX with ID 1713550072-960311778 651s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1355]: Created message in test_vm_api_2345/INBOX with ID 1713550072-1500739833 651s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1355]: Created message in test_vm_api_2345/INBOX with ID 1713550072-719848782 651s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1364]: Test forwarding from an invalid mailbox 651s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1367]: Test forwarding from a NULL mailbox 651s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1370]: Test forwarding from an invalid context 651s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1373]: Test forwarding from an invalid folder 651s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1376]: Test forwarding from a NULL folder 651s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1379]: Test forwarding to an invalid mailbox 651s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1382]: Test forwarding to a NULL mailbox 651s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1385]: Test forwarding to an invalid context 651s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1388]: Test forwarding to an invalid folder 651s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1392]: Test forwarding to a NULL folder 651s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1395]: Test forwarding when no messages are select 651s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1398]: Test forwarding a message that doesn't exist 651s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1402]: Test forwarding multiple messages, where some messages don't exist 651s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1405]: Test forwarding a message with an invalid size specifier 651s END /main/voicemail_api/ - off_nominal_forward Time: 9ms Result: PASS 651s START /main/voicemail_api/ - nominal_forward 651s [test_voicemail_api.c:voicemail_api_nominal_forward:1239]: Created message in test_vm_api_1234/Old with ID 1713550073-909401725 651s [test_voicemail_api.c:voicemail_api_nominal_forward:1239]: Created message in test_vm_api_1234/INBOX with ID 1713550073-960311778 651s [test_voicemail_api.c:voicemail_api_nominal_forward:1239]: Created message in test_vm_api_2345/INBOX with ID 1713550073-1500739833 651s [test_voicemail_api.c:voicemail_api_nominal_forward:1239]: Created message in test_vm_api_2345/INBOX with ID 1713550073-719848782 651s [test_voicemail_api.c:voicemail_api_nominal_forward:1246]: Test forwarding message 0 from test_vm_api_1234 INBOX to test_vm_api_2345 INBOX 651s [test_voicemail_api.c:voicemail_api_nominal_forward:1259]: Test forwarding message 0 from test_vm_api_1234 INBOX with default context to test_vm_api_2345 INBOX 651s [test_voicemail_api.c:voicemail_api_nominal_forward:1272]: Test forwarding message 0 from test_vm_api_1234 INBOX to test_vm_api_2345 INBOX with default context 651s [test_voicemail_api.c:voicemail_api_nominal_forward:1285]: Test forwarding message 0 from test_vm_api_1234 INBOX to test_vm_api_2345 INBOX, deleting original 651s [test_voicemail_api.c:voicemail_api_nominal_forward:1298]: Test forwarding 2 messages from test_vm_api_2345 INBOX to test_vm_api_1234 INBOX[test_voicemail_api.c:voicemail_api_nominal_forward:1311]: Test forwarding 2 messages from test_vm_api_2345 INBOX to test_vm_api_1234 Family, deleting original 651s END /main/voicemail_api/ - nominal_forward Time: 24ms Result: PASS 651s START /main/voicemail_api/ - off_nominal_remove 651s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1180]: Created message in test_vm_api_1234/Old with ID 1713550073-909401725 651s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1180]: Created message in test_vm_api_1234/INBOX with ID 1713550073-960311778 651s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1180]: Created message in test_vm_api_2345/INBOX with ID 1713550073-1500739833 651s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1180]: Created message in test_vm_api_2345/INBOX with ID 1713550073-719848782 651s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1186]: Test removing a single message with an invalid mailbox 651s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1189]: Test removing a single message with a NULL mailbox 651s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1192]: Test removing a single message with an invalid context 651s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1195]: Test removing a single message with an invalid folder 651s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1198]: Test removing a single message with a NULL folder 651s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1201]: Test removing a single message with an invalid message number 651s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1205]: Test removing multiple messages with a single invalid message number 651s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1209]: Test removing no messages with no message numbers 651s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1212]: Test removing multiple messages with an invalid size specifier 651s END /main/voicemail_api/ - off_nominal_remove Time: 9ms Result: PASS 651s START /main/voicemail_api/ - nominal_remove 651s [test_voicemail_api.c:voicemail_api_nominal_remove:1133]: Created message in test_vm_api_1234/Old with ID 1713550073-909401725 651s [test_voicemail_api.c:voicemail_api_nominal_remove:1133]: Created message in test_vm_api_1234/INBOX with ID 1713550073-960311778 651s [test_voicemail_api.c:voicemail_api_nominal_remove:1133]: Created message in test_vm_api_2345/INBOX with ID 1713550073-1500739833 651s [test_voicemail_api.c:voicemail_api_nominal_remove:1133]: Created message in test_vm_api_2345/INBOX with ID 1713550073-719848782 651s [test_voicemail_api.c:voicemail_api_nominal_remove:1141]: Test removing a single message from INBOX 651s [test_voicemail_api.c:voicemail_api_nominal_remove:1144]: Test removing a single message from Old 651s [test_voicemail_api.c:voicemail_api_nominal_remove:1147]: Test removing multiple messages from INBOX 651s END /main/voicemail_api/ - nominal_remove Time: 9ms Result: PASS 651s START /main/voicemail_api/ - off_nominal_move 651s [test_voicemail_api.c:voicemail_api_off_nominal_move:1061]: Created message in test_vm_api_1234/Old with ID 1713550073-909401725 651s [test_voicemail_api.c:voicemail_api_off_nominal_move:1061]: Created message in test_vm_api_1234/INBOX with ID 1713550073-960311778 651s [test_voicemail_api.c:voicemail_api_off_nominal_move:1061]: Created message in test_vm_api_2345/INBOX with ID 1713550073-1500739833 651s [test_voicemail_api.c:voicemail_api_off_nominal_move:1061]: Created message in test_vm_api_2345/INBOX with ID 1713550073-719848782 651s [test_voicemail_api.c:voicemail_api_off_nominal_move:1070]: Test move attempt for invalid mailbox test_vm_3456 651s [test_voicemail_api.c:voicemail_api_off_nominal_move:1075]: Test move attempt for invalid context test_vm_api_defunct 651s [test_voicemail_api.c:voicemail_api_off_nominal_move:1078]: Test move attempt to invalid folder 651s [test_voicemail_api.c:voicemail_api_off_nominal_move:1081]: Test move attempt from invalid folder 651s [test_voicemail_api.c:voicemail_api_off_nominal_move:1084]: Test move attempt to NULL folder 651s [test_voicemail_api.c:voicemail_api_off_nominal_move:1087]: Test move attempt from NULL folder 651s [test_voicemail_api.c:voicemail_api_off_nominal_move:1090]: Test move attempt with non-existent message number 651s [test_voicemail_api.c:voicemail_api_off_nominal_move:1094]: Test move attempt with invalid message number 651s [test_voicemail_api.c:voicemail_api_off_nominal_move:1098]: Test move attempt with 0 number of messages 651s [test_voicemail_api.c:voicemail_api_off_nominal_move:1102]: Test move attempt with invalid number of messages 651s [test_voicemail_api.c:voicemail_api_off_nominal_move:1105]: Test move attempt with non-existent multiple messages, where some messages exist 651s END /main/voicemail_api/ - off_nominal_move Time: 9ms Result: PASS 651s START /main/voicemail_api/ - nominal_move 651s [test_voicemail_api.c:voicemail_api_nominal_move:987]: Created message in test_vm_api_1234/Old with ID 1713550073-909401725 651s [test_voicemail_api.c:voicemail_api_nominal_move:987]: Created message in test_vm_api_1234/INBOX with ID 1713550073-960311778 651s [test_voicemail_api.c:voicemail_api_nominal_move:987]: Created message in test_vm_api_2345/INBOX with ID 1713550073-1500739833 651s [test_voicemail_api.c:voicemail_api_nominal_move:987]: Created message in test_vm_api_2345/INBOX with ID 1713550073-719848782 651s [test_voicemail_api.c:voicemail_api_nominal_move:994]: Test move of test_vm_api_1234 message from INBOX to Family 651s [test_voicemail_api.c:voicemail_api_nominal_move:997]: Test move of test_vm_api_1234 message from Old to Family 651s [test_voicemail_api.c:voicemail_api_nominal_move:1011]: Test move of test_vm_api_2345 messages from Inbox to Family 651s [test_voicemail_api.c:voicemail_api_nominal_move:1022]: Test move of test_vm_api_2345 message from Family to INBOX 651s END /main/voicemail_api/ - nominal_move Time: 12ms Result: PASS 651s START /main/voicemail_api/ - off_nominal_snapshot 651s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:947]: Created message in test_vm_api_1234/Old with ID 1713550073-909401725 651s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:947]: Created message in test_vm_api_1234/INBOX with ID 1713550073-960311778 651s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:947]: Created message in test_vm_api_2345/INBOX with ID 1713550073-1500739833 651s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:947]: Created message in test_vm_api_2345/INBOX with ID 1713550073-719848782 651s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:949]: Test access to non-existent mailbox test_vm_api_3456 651s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:952]: Test access to null mailbox 651s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:955]: Test access non-existent context test_vm_api_defunct 651s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:958]: Test non-existent folder test_vm_api_platypus 651s END /main/voicemail_api/ - off_nominal_snapshot Time: 7ms Result: PASS 651s START /main/voicemail_api/ - nominal_snapshot 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:856]: Created message in test_vm_api_1234/Old with ID 1713550073-909401725 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:856]: Created message in test_vm_api_1234/INBOX with ID 1713550073-960311778 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:856]: Created message in test_vm_api_2345/INBOX with ID 1713550073-1500739833 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:856]: Created message in test_vm_api_2345/INBOX with ID 1713550073-719848782 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:858]: Test retrieving message 1 from INBOX of test_vm_1234 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:861]: Found message 1713550073-960311778 in snapshot 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:864]: Test retrieving message 0 from Old of test_vm_1234 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:867]: Found message 1713550073-909401725 in snapshot 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:870]: Test retrieving message 0, 1 from Old and INBOX of test_vm_1234 ordered by time 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:873]: Found message 1713550073-909401725 in snapshot 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:874]: Found message 1713550073-960311778 in snapshot 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:877]: Test retrieving message 1, 0 from Old and INBOX of test_vm_1234 ordered by time desc 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:880]: Found message 1713550073-960311778 in snapshot 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:881]: Found message 1713550073-909401725 in snapshot 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:884]: Test retrieving message 0, 1 from Old and INBOX of test_vm_1234 ordered by id 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:887]: Found message 1713550073-960311778 in snapshot 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:888]: Found message 1713550073-909401725 in snapshot 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:891]: Test retrieving message 1, 0 from Old and INBOX of test_vm_1234 ordered by id desc 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:894]: Found message 1713550073-909401725 in snapshot 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:895]: Found message 1713550073-960311778 in snapshot 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:898]: Test retrieving message 0, 1 from all folders of test_vm_1234 ordered by id 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:901]: Found message 1713550073-909401725 in snapshot 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:902]: Found message 1713550073-960311778 in snapshot 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:905]: Test retrieving message 0, 1 from all folders of test_vm_1234 ordered by time 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:908]: Found message 1713550073-909401725 in snapshot 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:909]: Found message 1713550073-960311778 in snapshot 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:912]: Test retrieving message 0, 1 from all folders of test_vm_1234, default context ordered by time 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:915]: Found message 1713550073-909401725 in snapshot 651s [test_voicemail_api.c:voicemail_api_nominal_snapshot:916]: Found message 1713550073-960311778 in snapshot 651s END /main/voicemail_api/ - nominal_snapshot Time: 18ms Result: PASS 651s START /main/xml_escape/ - xml_escape_test 651s END /main/xml_escape/ - xml_escape_test Time: <1ms Result: PASS 651s START /mwi/ - explicit_publish 651s END /mwi/ - explicit_publish Time: 60ms Result: PASS 651s START /mwi/ - implicit_publish 651s END /mwi/ - implicit_publish Time: 56ms Result: PASS 651s START /res/adsi/ - adsi_loaded_test 651s END /res/adsi/ - adsi_loaded_test Time: <1ms Result: PASS 651s START /res/aeap/ - send_msg_handle_request 651s END /res/aeap/ - send_msg_handle_request Time: <1ms Result: PASS 651s START /res/aeap/ - send_msg_handle_response 651s END /res/aeap/ - send_msg_handle_response Time: <1ms Result: PASS 651s START /res/aeap/ - send_msg_handle_string 653s END /res/aeap/ - send_msg_handle_string Time: 1999ms Result: PASS 653s START /res/aeap/ - create_and_connect 653s END /res/aeap/ - create_and_connect Time: <1ms Result: PASS 653s START /res/aeap/speech/ - res_speech_aeap_test 653s END /res/aeap/speech/ - res_speech_aeap_test Time: 1ms Result: PASS 653s START /res/aeap/transaction/ - transaction_exec_timeout 653s END /res/aeap/transaction/ - transaction_exec_timeout Time: 99ms Result: PASS 653s START /res/aeap/transaction/ - transaction_exec 654s END /res/aeap/transaction/ - transaction_exec Time: 1000ms Result: PASS 654s START /res/aeap/transport/ - transport_create_invalid 654s END /res/aeap/transport/ - transport_create_invalid Time: <1ms Result: PASS 654s START /res/aeap/transport/ - transport_create 654s END /res/aeap/transport/ - transport_create Time: <1ms Result: PASS 654s START /res/aeap/transport/ - transport_connect 654s END /res/aeap/transport/ - transport_connect Time: <1ms Result: PASS 654s START /res/aeap/transport/ - transport_connect_fail 654s END /res/aeap/transport/ - transport_connect_fail Time: <1ms Result: PASS 654s START /res/aeap/transport/ - transport_binary 654s END /res/aeap/transport/ - transport_binary Time: <1ms Result: PASS 654s START /res/aeap/transport/ - transport_string 654s END /res/aeap/transport/ - transport_string Time: <1ms Result: PASS 654s START /res/agi/ - agi_loaded_test 654s END /res/agi/ - agi_loaded_test Time: <1ms Result: PASS 654s START /res/agi/ - null_agi_docs 654s END /res/agi/ - null_agi_docs Time: <1ms Result: PASS 654s START /res/ari/ - invoke_not_found 654s END /res/ari/ - invoke_not_found Time: <1ms Result: PASS 654s START /res/ari/ - invoke_bad_post 654s END /res/ari/ - invoke_bad_post Time: <1ms Result: PASS 654s START /res/ari/ - invoke_post 654s END /res/ari/ - invoke_post Time: <1ms Result: PASS 654s START /res/ari/ - invoke_delete 654s END /res/ari/ - invoke_delete Time: <1ms Result: PASS 654s START /res/ari/ - invoke_wildcard 654s END /res/ari/ - invoke_wildcard Time: <1ms Result: PASS 654s START /res/ari/ - invoke_get 654s END /res/ari/ - invoke_get Time: <1ms Result: PASS 654s START /res/ari/ - get_docs_hackerz 654s END /res/ari/ - get_docs_hackerz Time: <1ms Result: PASS 654s START /res/ari/ - get_docs_notfound 654s END /res/ari/ - get_docs_notfound Time: <1ms Result: PASS 654s START /res/ari/ - get_docs_nohost 654s END /res/ari/ - get_docs_nohost Time: <1ms Result: PASS 654s START /res/ari/ - get_docs 654s END /res/ari/ - get_docs Time: <1ms Result: PASS 654s START /res/crypto/ - crypto_loaded_test 654s END /res/crypto/ - crypto_loaded_test Time: <1ms Result: PASS 654s START /res/http_media_cache/ - retrieve_content_type 654s [test_http_media_cache.c:retrieve_content_type:255]: Condition failed: bucket_file != NULL 654s END /res/http_media_cache/ - retrieve_content_type Time: <1ms Result: FAIL 654s START /res/http_media_cache/ - retrieve_parsed_uri 654s [test_http_media_cache.c:retrieve_parsed_uri:289]: Condition failed: bucket_file != NULL 654s END /res/http_media_cache/ - retrieve_parsed_uri Time: <1ms Result: FAIL 654s START /res/http_media_cache/ - retrieve_cache_control_directives 654s [test_http_media_cache.c:retrieve_cache_control_directives:322]: Testing no-cache... 654s [test_http_media_cache.c:retrieve_cache_control_directives:325]: Condition failed: bucket_file != NULL 654s END /res/http_media_cache/ - retrieve_cache_control_directives Time: <1ms Result: FAIL 654s START /res/http_media_cache/ - retrieve_cache_control_age 654s [test_http_media_cache.c:retrieve_cache_control_age:406]: Testing max-age... 654s [test_http_media_cache.c:retrieve_cache_control_age:409]: Condition failed: bucket_file != NULL 654s END /res/http_media_cache/ - retrieve_cache_control_age Time: <1ms Result: FAIL 654s START /res/http_media_cache/ - retrieve_etag_expired 654s [test_http_media_cache.c:retrieve_etag_expired:510]: Condition failed: bucket_file != NULL 654s END /res/http_media_cache/ - retrieve_etag_expired Time: <1ms Result: FAIL 654s START /res/http_media_cache/ - retrieve_expires 654s [test_http_media_cache.c:retrieve_expires:551]: Condition failed: bucket_file != NULL 654s END /res/http_media_cache/ - retrieve_expires Time: <1ms Result: FAIL 654s START /res/http_media_cache/ - retrieve_etag 654s [test_http_media_cache.c:retrieve_etag:600]: Condition failed: bucket_file != NULL 654s END /res/http_media_cache/ - retrieve_etag Time: <1ms Result: FAIL 654s START /res/http_media_cache/ - retrieve_nominal 654s [test_http_media_cache.c:retrieve_nominal:639]: Condition failed: bucket_file != NULL 654s END /res/http_media_cache/ - retrieve_nominal Time: <1ms Result: FAIL 654s START /res/http_media_cache/ - create_nominal 654s [test_http_media_cache.c:create_nominal:673]: Condition failed: ast_bucket_file_temporary_create(bucket_file) == 0 654s END /res/http_media_cache/ - create_nominal Time: <1ms Result: FAIL 654s START /res/parking/ - dynamic_parking_variables 654s [parking/parking_tests.c:dynamic_parking_variables:756]: Creating expected configuration for dynamic parking lot 654s [parking/parking_tests.c:dynamic_parking_variables:775]: Creating template lot 654s [parking/parking_tests.c:dynamic_parking_variables:784]: Creating Alice channel to test dynamic parking lot creation. 654s [parking/parking_tests.c:dynamic_parking_variables:794]: Setting Dynamic Parking channel variables on Alice. 654s [parking/parking_tests.c:dynamic_parking_variables:802]: Generating dynamic parking lot based on Alice's channel variables. 654s [parking/parking_tests.c:dynamic_parking_variables:819]: Dynamic parking lot created successfully and matches expectations. Test passed. 654s END /res/parking/ - dynamic_parking_variables Time: <1ms Result: PASS 654s START /res/parking/ - extension_conflicts 654s [parking/parking_tests.c:extension_conflicts:597]: Creating the base lot. This should pass. 654s [parking/parking_tests.c:extension_conflicts:607]: Creating a test lot which will overlap. 654s [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. 654s [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. 654s [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. 654s [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. 654s END /res/parking/ - extension_conflicts Time: <1ms Result: PASS 654s START /res/parking/ - park_extensions 654s [parking/parking_tests.c:park_extensions:551]: Extensions for the test parking lot were verified. Cleaning up and verifying their removal. 654s [parking/parking_tests.c:park_extensions:565]: Extensions for the test parking lot verified as removed. Test completed successfully. 654s END /res/parking/ - park_extensions Time: <1ms Result: PASS 654s START /res/parking/ - park_retrieve 654s [parking/parking_tests.c:retrieve_call:405]: Creating test parking lot 'unit_tests_res_parking_test_lot' 655s [parking/parking_tests.c:retrieve_call:446]: Successfully retrieved parked user from the parking lot. Validating user data. 655s END /res/parking/ - park_retrieve Time: 1001ms Result: PASS 655s START /res/parking/ - park_channel 655s [parking/parking_tests.c:park_call:254]: Creating test parking lot 'unit_tests_res_parking_test_lot' 656s END /res/parking/ - park_channel Time: 1001ms Result: PASS 656s START /res/parking/ - create_lot 656s [parking/parking_tests.c:create_lot:206]: Creating test parking lot 'unit_tests_res_parking_test_lot' 656s [parking/parking_tests.c:create_lot:214]: Successfully created parking lot. Retrieving test parking lot from container. 656s [parking/parking_tests.c:create_lot:223]: Successfully retrieved parking lot. Removing test parking lot from container. 656s [parking/parking_tests.c:create_lot:229]: Parking lot was successfully removed from the container. Test complete. 656s END /res/parking/ - create_lot Time: <1ms Result: PASS 656s START /res/prometheus/ - bridge_to_string 656s [test_res_prometheus.c:bridge_to_string:744]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 656s # TYPE asterisk_channels_count gauge 656s asterisk_channels_count{eid="fa:16:3e:77:ba:2b"} 0 656s # HELP asterisk_calls_sum Total call count. 656s # TYPE asterisk_calls_sum counter 656s asterisk_calls_sum{eid="fa:16:3e:77:ba:2b"} 0 656s # HELP asterisk_calls_count Current call count. 656s # TYPE asterisk_calls_count gauge 656s asterisk_calls_count{eid="fa:16:3e:77:ba:2b"} 0 656s # HELP asterisk_endpoints_count Current endpoint count. 656s # TYPE asterisk_endpoints_count gauge 656s asterisk_endpoints_count{eid="fa:16:3e:77:ba:2b"} 0 656s # HELP asterisk_bridges_count Current bridge count. 656s # TYPE asterisk_bridges_count gauge 656s asterisk_bridges_count{eid="fa:16:3e:77:ba:2b"} 2 656s # HELP asterisk_bridges_channels_count Number of channels in the bridge. 656s # TYPE asterisk_bridges_channels_count gauge 656s asterisk_bridges_channels_count{eid="fa:16:3e:77:ba:2b",id="c597c2f5-81fc-4376-8537-3c65cffb0769",tech="simple_bridge",subclass="basic",creator="",name=""} 0 656s asterisk_bridges_channels_count{eid="fa:16:3e:77:ba:2b",id="c597c2f5-81fc-4376-8537-3c65cffb0769",tech="simple_bridge",subclass="basic",creator="",name=""} 0 656s 656s END /res/prometheus/ - bridge_to_string Time: <1ms Result: PASS 656s START /res/prometheus/ - config_general_core_metrics 656s [test_res_prometheus.c:config_general_core_metrics:680]: -> CURLing request... 656s [test_res_prometheus.c:config_general_core_metrics:688]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 656s # TYPE asterisk_channels_count gauge 656s asterisk_channels_count{eid="fa:16:3e:77:ba:2b"} 0 656s # HELP asterisk_calls_sum Total call count. 656s # TYPE asterisk_calls_sum counter 656s asterisk_calls_sum{eid="fa:16:3e:77:ba:2b"} 0 656s # HELP asterisk_calls_count Current call count. 656s # TYPE asterisk_calls_count gauge 656s asterisk_calls_count{eid="fa:16:3e:77:ba:2b"} 0 656s # HELP asterisk_endpoints_count Current endpoint count. 656s # TYPE asterisk_endpoints_count gauge 656s asterisk_endpoints_count{eid="fa:16:3e:77:ba:2b"} 0 656s # HELP asterisk_bridges_count Current bridge count. 656s # TYPE asterisk_bridges_count gauge 656s asterisk_bridges_count{eid="fa:16:3e:77:ba:2b"} 0 656s # HELP asterisk_core_properties Asterisk instance properties. The value of this will always be 1. 656s # TYPE asterisk_core_properties counter 656s asterisk_core_properties{eid="fa:16:3e:77:ba:2b",version="20.6.0~dfsg+~cs6.13.40431414-2build5",build_options="OPTIONAL_API, TEST_FRAMEWORK",build_date="2024-04-15 00:13:12 UTC",build_os="Linux",build_kernel="unknown",build_host="buildd.debian.org"} 1 656s # HELP asterisk_core_uptime_seconds Asterisk instance uptime in seconds. 656s # TYPE asterisk_core_uptime_seconds counter 656s asterisk_core_uptime_seconds{eid="fa:16:3e:77:ba:2b"} 182 656s # HELP asterisk_core_last_reload_seconds Time since last Asterisk reload in seconds. 656s # TYPE asterisk_core_last_reload_seconds counter 656s asterisk_core_last_reload_seconds{eid="fa:16:3e:77:ba:2b"} 182 656s # HELP asterisk_core_scrape_time_ms Total time taken to collect metrics, in milliseconds 656s # TYPE asterisk_core_scrape_time_ms counter 656s asterisk_core_scrape_time_ms{eid="fa:16:3e:77:ba:2b"} 0 656s 656s [test_res_prometheus.c:config_general_core_metrics:690]: -> Checking for core properties 656s [test_res_prometheus.c:config_general_core_metrics:693]: -> Checking for uptime 656s [test_res_prometheus.c:config_general_core_metrics:696]: -> Checking for last reload 656s [test_res_prometheus.c:config_general_core_metrics:699]: -> Checking for scrape time 656s END /res/prometheus/ - config_general_core_metrics Time: 2ms Result: PASS 656s START /res/prometheus/ - config_general_basic_auth 656s [test_res_prometheus.c:config_general_basic_auth:555]: Testing without auth credentials 656s [test_res_prometheus.c:config_general_basic_auth:556]: -> CURLing request... 656s [test_res_prometheus.c:config_general_basic_auth:563]: -> CURL returned 401 656s [test_res_prometheus.c:config_general_basic_auth:566]: Testing with invalid auth credentials 656s [test_res_prometheus.c:config_general_basic_auth:567]: -> CURLing request... 656s [test_res_prometheus.c:config_general_basic_auth:576]: -> CURL returned 401 656s [test_res_prometheus.c:config_general_basic_auth:579]: Testing with valid auth credentials 656s [test_res_prometheus.c:config_general_basic_auth:580]: -> CURLing request... 656s [test_res_prometheus.c:config_general_basic_auth:588]: -> CURL returned 200 656s END /res/prometheus/ - config_general_basic_auth Time: <1ms Result: PASS 656s START /res/prometheus/ - config_general_enabled 656s [test_res_prometheus.c:config_general_enabled:628]: -> CURLing request... 656s [test_res_prometheus.c:config_general_enabled:635]: -> CURL returned 503 656s END /res/prometheus/ - config_general_enabled Time: <1ms Result: PASS 656s START /res/prometheus/ - gauge_create 656s END /res/prometheus/ - gauge_create Time: <1ms Result: PASS 656s START /res/prometheus/ - gauge_to_string 656s END /res/prometheus/ - gauge_to_string Time: <1ms Result: PASS 656s START /res/prometheus/ - counter_create 656s END /res/prometheus/ - counter_create Time: <1ms Result: PASS 656s START /res/prometheus/ - counter_to_string 656s END /res/prometheus/ - counter_to_string Time: <1ms Result: PASS 656s START /res/prometheus/ - metric_register 656s [test_res_prometheus.c:metric_register:291]: Testing nominal registration 656s [test_res_prometheus.c:metric_register:292]: -> Static metric 656s [test_res_prometheus.c:metric_register:294]: -> Malloc'd metric 656s [test_res_prometheus.c:metric_register:300]: Testing nominal registration of child metrics 656s [test_res_prometheus.c:metric_register:315]: Testing name collisions 656s [test_res_prometheus.c:metric_register:322]: Testing label collisions 656s [test_res_prometheus.c:metric_register:331]: Testing removal of metrics 656s END /res/prometheus/ - metric_register Time: <1ms Result: PASS 656s START /res/prometheus/ - metric_callback_register 656s [test_res_prometheus.c:metric_callback_register:241]: -> CURLing request... 656s [test_res_prometheus.c:metric_callback_register:250]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 656s # TYPE asterisk_channels_count gauge 656s asterisk_channels_count{eid="fa:16:3e:77:ba:2b"} 0 656s # HELP asterisk_calls_sum Total call count. 656s # TYPE asterisk_calls_sum counter 656s asterisk_calls_sum{eid="fa:16:3e:77:ba:2b"} 0 656s # HELP asterisk_calls_count Current call count. 656s # TYPE asterisk_calls_count gauge 656s asterisk_calls_count{eid="fa:16:3e:77:ba:2b"} 0 656s # HELP asterisk_endpoints_count Current endpoint count. 656s # TYPE asterisk_endpoints_count gauge 656s asterisk_endpoints_count{eid="fa:16:3e:77:ba:2b"} 0 656s # HELP asterisk_bridges_count Current bridge count. 656s # TYPE asterisk_bridges_count gauge 656s asterisk_bridges_count{eid="fa:16:3e:77:ba:2b"} 0 656s # HELP test_counter A test counter 656s # TYPE test_counter counter 656s test_counter 0 656s 656s END /res/prometheus/ - metric_callback_register Time: <1ms Result: PASS 656s START /res/prometheus/ - metric_values 656s [test_res_prometheus.c:metric_values:166]: -> CURLing request... 656s [test_res_prometheus.c:metric_values:176]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 656s # TYPE asterisk_channels_count gauge 656s asterisk_channels_count{eid="fa:16:3e:77:ba:2b"} 0 656s # HELP asterisk_calls_sum Total call count. 656s # TYPE asterisk_calls_sum counter 656s asterisk_calls_sum{eid="fa:16:3e:77:ba:2b"} 0 656s # HELP asterisk_calls_count Current call count. 656s # TYPE asterisk_calls_count gauge 656s asterisk_calls_count{eid="fa:16:3e:77:ba:2b"} 0 656s # HELP asterisk_endpoints_count Current endpoint count. 656s # TYPE asterisk_endpoints_count gauge 656s asterisk_endpoints_count{eid="fa:16:3e:77:ba:2b"} 0 656s # HELP asterisk_bridges_count Current bridge count. 656s # TYPE asterisk_bridges_count gauge 656s asterisk_bridges_count{eid="fa:16:3e:77:ba:2b"} 0 656s # HELP test_counter_one A test counter 656s # TYPE test_counter_one counter 656s test_counter_one 1 656s # HELP test_counter_two A test counter 656s # TYPE test_counter_two counter 656s test_counter_two 2 656s 656s END /res/prometheus/ - metric_values Time: <1ms Result: PASS 656s START /res/res_crypto/ - crypto_aes_decrypt 656s [test_crypto.c:crypto_aes_decrypt:607]: Executing AES-ECB decryption test 656s END /res/res_crypto/ - crypto_aes_decrypt Time: 13ms Result: PASS 656s START /res/res_crypto/ - crypto_aes_encrypt 656s [test_crypto.c:crypto_aes_encrypt:531]: Executing AES-ECB encryption test 656s END /res/res_crypto/ - crypto_aes_encrypt Time: 12ms Result: PASS 656s START /res/res_crypto/ - crypto_verify 656s [test_crypto.c:crypto_verify:425]: Executing RSA signature verification test 656s [test_crypto.c:crypto_verify:456]: Couldn't read key: rsa_key1 656s END /res/res_crypto/ - crypto_verify Time: <1ms Result: FAIL 656s START /res/res_crypto/ - crypto_sign 656s [test_crypto.c:crypto_sign:306]: Executing RSA signing test 656s [test_crypto.c:crypto_sign:341]: Couldn't read key: rsa_key1 656s END /res/res_crypto/ - crypto_sign Time: <1ms Result: FAIL 656s START /res/res_crypto/ - crypto_decrypt_pub_key 656s [test_crypto.c:crypto_rsa_decrypt:203]: Executing RSA decryption test 656s [test_crypto.c:crypto_rsa_decrypt:231]: Couldn't read key: rsa_key1 656s END /res/res_crypto/ - crypto_decrypt_pub_key Time: <1ms Result: FAIL 656s START /res/res_crypto/ - crypto_rsa_encrypt 656s [test_crypto.c:crypto_rsa_encrypt:107]: Executing RSA encryption test 656s [test_crypto.c:crypto_rsa_encrypt:138]: Couldn't read key: rsa_key1 656s END /res/res_crypto/ - crypto_rsa_encrypt Time: <1ms Result: FAIL 656s START /res/res_pjproject/ - ast_sockaddr_from_pj_sockaddr_test 656s END /res/res_pjproject/ - ast_sockaddr_from_pj_sockaddr_test Time: <1ms Result: PASS 656s START /res/res_pjproject/ - ast_sockaddr_to_pj_sockaddr_test 656s END /res/res_pjproject/ - ast_sockaddr_to_pj_sockaddr_test Time: <1ms Result: PASS 656s START /res/res_pjsip/ - xml_sanitization_exceeds_buffer 656s END /res/res_pjsip/ - xml_sanitization_exceeds_buffer Time: <1ms Result: PASS 656s START /res/res_pjsip/ - xml_sanitization_end_null 656s END /res/res_pjsip/ - xml_sanitization_end_null Time: <1ms Result: PASS 656s START /res/res_pjsip/scheduler/ - scheduler_policy 656s [test_res_pjsip_scheduler.c:scheduler_policy:355]: This test will take about 4.5 seconds 660s END /res/res_pjsip/scheduler/ - scheduler_policy Time: 4499ms Result: PASS 660s START /res/res_pjsip/scheduler/ - scheduler_cancel 660s [test_res_pjsip_scheduler.c:scheduler_cancel:301]: This test will take about 1.5 seconds 662s END /res/res_pjsip/scheduler/ - scheduler_cancel Time: 1500ms Result: PASS 662s START /res/res_pjsip/scheduler/ - scheduler_cleanup 662s [test_res_pjsip_scheduler.c:scheduler_cleanup:250]: This test will take about 1.6 seconds 664s END /res/res_pjsip/scheduler/ - scheduler_cleanup Time: 1600ms Result: PASS 664s START /res/res_pjsip/scheduler/ - unserialized_scheduler 664s [test_res_pjsip_scheduler.c:scheduler:136]: This test will take about 3.0 seconds 667s [test_res_pjsip_scheduler.c:scheduler:167]: Condition failed: test_data1->tid != test_data2->tid 667s END /res/res_pjsip/scheduler/ - unserialized_scheduler Time: 3999ms Result: FAIL 667s START /res/res_pjsip/scheduler/ - serialized_scheduler 667s [test_res_pjsip_scheduler.c:scheduler:131]: This test will take about 4.0 seconds 671s END /res/res_pjsip/scheduler/ - serialized_scheduler Time: 3999ms Result: PASS 671s START /res/res_pjsip_pubsub/ - bad_event 671s END /res/res_pjsip_pubsub/ - bad_event Time: <1ms Result: PASS 671s START /res/res_pjsip_pubsub/ - loop 671s END /res/res_pjsip_pubsub/ - loop Time: <1ms Result: PASS 671s START /res/res_pjsip_pubsub/ - duplicate_resource 671s END /res/res_pjsip_pubsub/ - duplicate_resource Time: <1ms Result: PASS 671s START /res/res_pjsip_pubsub/ - bad_branch 671s END /res/res_pjsip_pubsub/ - bad_branch Time: <1ms Result: PASS 671s START /res/res_pjsip_pubsub/ - bad_resource 671s END /res/res_pjsip_pubsub/ - bad_resource Time: <1ms Result: PASS 671s START /res/res_pjsip_pubsub/ - complex_resource_tree 671s END /res/res_pjsip_pubsub/ - complex_resource_tree Time: <1ms Result: PASS 671s START /res/res_pjsip_pubsub/ - resource_tree 671s END /res/res_pjsip_pubsub/ - resource_tree Time: <1ms Result: PASS 671s START /res/res_pjsip_session/ - merge_refresh_topologies 671s [res_pjsip_session.c:test_resolve_refresh_media_states:5894]: Test 1 passed 671s [res_pjsip_session.c:test_resolve_refresh_media_states:5914]: Test 2 passed 671s [res_pjsip_session.c:test_resolve_refresh_media_states:5938]: Test 3 passed 671s [res_pjsip_session.c:test_resolve_refresh_media_states:5957]: Test 4 passed 671s [res_pjsip_session.c:test_resolve_refresh_media_states:5975]: Test 5 passed 671s [res_pjsip_session.c:test_resolve_refresh_media_states:5996]: Test 6 passed 671s [res_pjsip_session.c:test_resolve_refresh_media_states:6022]: Test 7 passed 671s [res_pjsip_session.c:test_resolve_refresh_media_states:6043]: Test 8 passed 671s [res_pjsip_session.c:test_resolve_refresh_media_states:6063]: Test 9 passed 671s [res_pjsip_session.c:test_resolve_refresh_media_states:6083]: Test 10 passed 671s [res_pjsip_session.c:test_resolve_refresh_media_states:6106]: Test 11 passed 671s [res_pjsip_session.c:test_resolve_refresh_media_states:6131]: Test 12 passed 671s [res_pjsip_session.c:test_resolve_refresh_media_states:6165]: Test 13 passed 671s [res_pjsip_session.c:test_resolve_refresh_media_states:6189]: Test 14 passed 671s [res_pjsip_session.c:test_resolve_refresh_media_states:6213]: Test 15 passed 671s END /res/res_pjsip_session/ - merge_refresh_topologies Time: <1ms Result: PASS 671s START /res/res_pjsip_session/caps/ - low_level 671s [test_res_pjsip_session_caps.c:low_level:134]: Testing incoming expected pass 671s [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) 671s [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) 671s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (slin), remote: (all), pref: (local ), outgoing: (no ), expected: (slin) expected result: (PASS) 671s [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) 671s [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) 671s [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) 671s [test_res_pjsip_session_caps.c:low_level:142]: Testing incoming expected fail 671s [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) 671s [test_res_pjsip_session_caps.c:test_create_joint:102]: Expected Failure: Expected: () Actual: (nothing) 671s [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) 671s [test_res_pjsip_session_caps.c:test_create_joint:81]: Expected Failure: Invalid preference string incoming/outgoing combination. 671s [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) 671s [test_res_pjsip_session_caps.c:test_create_joint:81]: Expected Failure: Invalid preference string incoming/outgoing combination. 671s [test_res_pjsip_session_caps.c:low_level:147]: Testing outgoing expected pass 671s [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) 671s [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) 671s [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) 671s [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) 671s [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) 671s [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) 671s [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) 671s END /res/res_pjsip_session/caps/ - low_level Time: 1ms Result: PASS 671s START /res/res_resolver_unbound/ - resolve_srv 671s END /res/res_resolver_unbound/ - resolve_srv Time: 2ms Result: PASS 671s START /res/res_resolver_unbound/ - resolve_naptr 672s END /res/res_resolver_unbound/ - resolve_naptr Time: <1ms Result: PASS 672s START /res/res_resolver_unbound/ - resolve_cancel_off_nominal 672s END /res/res_resolver_unbound/ - resolve_cancel_off_nominal Time: 1ms Result: PASS 672s START /res/res_resolver_unbound/ - resolve_async_off_nominal 672s [res_resolver_unbound.c:off_nominal_async_run:995]: Performing DNS query 'duck.feathers', type 1 672s [res_resolver_unbound.c:off_nominal_async_run:995]: Performing DNS query 'goose.feathers', type 28 672s [res_resolver_unbound.c:off_nominal_async_run:995]: Performing DNS query 'goose.feathers', type 1 672s END /res/res_resolver_unbound/ - resolve_async_off_nominal Time: <1ms Result: PASS 672s START /res/res_resolver_unbound/ - resolve_sync_off_nominal 672s END /res/res_resolver_unbound/ - resolve_sync_off_nominal Time: <1ms Result: PASS 672s START /res/res_resolver_unbound/ - resolve_async 672s [res_resolver_unbound.c:nominal_async_run:713]: Performing DNS query 'goose.feathers', type 1 672s [res_resolver_unbound.c:nominal_async_run:713]: Performing DNS query 'goose.feathers', type 28 672s [res_resolver_unbound.c:nominal_async_run:713]: Performing DNS query 'duck.feathers', type 1 672s END /res/res_resolver_unbound/ - resolve_async Time: <1ms Result: PASS 672s START /res/res_resolver_unbound/ - resolve_sync 672s [res_resolver_unbound.c:nominal_sync_run:563]: Performing DNS query 'goose.feathers', type 1 672s [res_resolver_unbound.c:nominal_sync_run:563]: Performing DNS query 'goose.feathers', type 28 672s [res_resolver_unbound.c:nominal_sync_run:563]: Performing DNS query 'duck.feathers', type 1 672s END /res/res_resolver_unbound/ - resolve_sync Time: <1ms Result: PASS 672s START /res/res_rtp/ - fir_nominal 672s END /res/res_rtp/ - fir_nominal Time: <1ms Result: PASS 672s START /res/res_rtp/ - sr_rr_nominal 672s END /res/res_rtp/ - sr_rr_nominal Time: <1ms Result: PASS 672s START /res/res_rtp/ - remb_nominal 672s END /res/res_rtp/ - remb_nominal Time: <1ms Result: PASS 672s START /res/res_rtp/ - lost_packet_stats_nominal 672s END /res/res_rtp/ - lost_packet_stats_nominal Time: <1ms Result: PASS 672s START /res/res_rtp/ - nack_overflow 672s END /res/res_rtp/ - nack_overflow Time: <1ms Result: PASS 672s START /res/res_rtp/ - nack_nominal 672s END /res/res_rtp/ - nack_nominal Time: <1ms Result: PASS 672s START /res/res_rtp/ - nack_no_packet_loss 672s END /res/res_rtp/ - nack_no_packet_loss Time: <1ms Result: PASS 672s START /res/res_sorcery_memory_cache/ - full_backend_cache_stale 687s END /res/res_sorcery_memory_cache/ - full_backend_cache_stale Time: 15000ms Result: PASS 687s START /res/res_sorcery_memory_cache/ - full_backend_cache_expiration 691s END /res/res_sorcery_memory_cache/ - full_backend_cache_expiration Time: 5000ms Result: PASS 691s START /res/res_sorcery_memory_cache/ - expiration 696s END /res/res_sorcery_memory_cache/ - expiration Time: 4999ms Result: PASS 696s START /res/res_sorcery_memory_cache/ - maximum_objects 697s END /res/res_sorcery_memory_cache/ - maximum_objects Time: 4ms Result: PASS 697s START /res/res_sorcery_memory_cache/ - delete 697s END /res/res_sorcery_memory_cache/ - delete Time: <1ms Result: PASS 697s START /res/res_sorcery_memory_cache/ - create 697s END /res/res_sorcery_memory_cache/ - create Time: <1ms Result: PASS 697s START /res/res_sorcery_memory_cache/ - create 697s END /res/res_sorcery_memory_cache/ - create Time: <1ms Result: PASS 697s START /res/res_sorcery_memory_cache/ - open_with_invalid_options 697s END /res/res_sorcery_memory_cache/ - open_with_invalid_options Time: <1ms Result: PASS 697s START /res/res_sorcery_memory_cache/ - open_with_valid_options 697s END /res/res_sorcery_memory_cache/ - open_with_valid_options Time: <1ms Result: PASS 697s START /res/res_sorcery_memory_cache/ - stale 697s [res_sorcery_memory_cache.c:stale:3189]: Begininning iteration 0 702s [res_sorcery_memory_cache.c:stale:3189]: Begininning iteration 1 707s [res_sorcery_memory_cache.c:stale:3189]: Begininning iteration 2 712s END /res/res_sorcery_memory_cache/ - stale Time: 15003ms Result: PASS 712s START /res/res_sorcery_memory_cache/thrash/ - high_object_count_without_expiration 715s END /res/res_sorcery_memory_cache/thrash/ - high_object_count_without_expiration Time: 3051ms Result: PASS 715s START /res/res_sorcery_memory_cache/thrash/ - conflicting_expire_and_stale 721s END /res/res_sorcery_memory_cache/thrash/ - conflicting_expire_and_stale Time: 6028ms Result: PASS 721s START /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum_with_expire_and_stale 727s END /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum_with_expire_and_stale Time: 6011ms Result: PASS 727s START /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum 730s END /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum Time: 3007ms Result: PASS 730s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_high_concurrent_updates 733s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_high_concurrent_updates Time: 3013ms Result: PASS 733s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_expire 736s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_expire Time: 3000ms Result: PASS 736s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_stale 739s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_stale Time: 3041ms Result: PASS 739s START /res/res_stir_shaken/ - stir_shaken_verify 739s END /res/res_stir_shaken/ - stir_shaken_verify Time: 2ms Result: PASS 739s START /res/res_stir_shaken/ - stir_shaken_sign 739s END /res/res_stir_shaken/ - stir_shaken_sign Time: 1ms Result: PASS 739s START /res/sorcery_astdb/ - object_delete_uncreated 739s END /res/sorcery_astdb/ - object_delete_uncreated Time: 1ms Result: PASS 739s START /res/sorcery_astdb/ - object_delete 739s END /res/sorcery_astdb/ - object_delete Time: <1ms Result: PASS 739s START /res/sorcery_astdb/ - object_update_uncreated 739s END /res/sorcery_astdb/ - object_update_uncreated Time: <1ms Result: PASS 739s START /res/sorcery_astdb/ - object_update 739s END /res/sorcery_astdb/ - object_update Time: <1ms Result: PASS 739s START /res/sorcery_astdb/ - object_retrieve_regex 739s END /res/sorcery_astdb/ - object_retrieve_regex Time: <1ms Result: PASS 739s START /res/sorcery_astdb/ - object_retrieve_multiple_field 739s END /res/sorcery_astdb/ - object_retrieve_multiple_field Time: <1ms Result: PASS 739s START /res/sorcery_astdb/ - object_retrieve_multiple_all 739s END /res/sorcery_astdb/ - object_retrieve_multiple_all Time: <1ms Result: PASS 739s START /res/sorcery_astdb/ - object_retrieve_field 739s END /res/sorcery_astdb/ - object_retrieve_field Time: <1ms Result: PASS 739s START /res/sorcery_astdb/ - object_retrieve_id 739s END /res/sorcery_astdb/ - object_retrieve_id Time: <1ms Result: PASS 739s START /res/sorcery_astdb/ - object_create 739s END /res/sorcery_astdb/ - object_create Time: <1ms Result: PASS 739s START /res/sorcery_realtime/ - object_filter 739s END /res/sorcery_realtime/ - object_filter Time: <1ms Result: PASS 739s START /res/sorcery_realtime/ - object_allocate_on_retrieval 739s END /res/sorcery_realtime/ - object_allocate_on_retrieval Time: <1ms Result: PASS 739s START /res/sorcery_realtime/ - object_delete_uncreated 739s END /res/sorcery_realtime/ - object_delete_uncreated Time: <1ms Result: PASS 739s START /res/sorcery_realtime/ - object_delete 739s END /res/sorcery_realtime/ - object_delete Time: <1ms Result: PASS 739s START /res/sorcery_realtime/ - object_update 739s END /res/sorcery_realtime/ - object_update Time: <1ms Result: PASS 739s START /res/sorcery_realtime/ - object_retrieve_regex_nofetch 739s END /res/sorcery_realtime/ - object_retrieve_regex_nofetch Time: <1ms Result: PASS 739s START /res/sorcery_realtime/ - object_retrieve_regex 739s END /res/sorcery_realtime/ - object_retrieve_regex Time: <1ms Result: PASS 739s START /res/sorcery_realtime/ - object_retrieve_multiple_field 739s END /res/sorcery_realtime/ - object_retrieve_multiple_field Time: <1ms Result: PASS 739s START /res/sorcery_realtime/ - object_retrieve_multiple_all_nofetch 739s END /res/sorcery_realtime/ - object_retrieve_multiple_all_nofetch Time: <1ms Result: PASS 739s START /res/sorcery_realtime/ - object_retrieve_multiple_all 739s END /res/sorcery_realtime/ - object_retrieve_multiple_all Time: <1ms Result: PASS 739s START /res/sorcery_realtime/ - object_retrieve_field 739s END /res/sorcery_realtime/ - object_retrieve_field Time: <1ms Result: PASS 739s START /res/sorcery_realtime/ - object_retrieve_id 739s END /res/sorcery_realtime/ - object_retrieve_id Time: <1ms Result: PASS 739s START /res/sorcery_realtime/ - object_create 739s END /res/sorcery_realtime/ - object_create Time: <1ms Result: PASS 739s START /res/websocket/ - websocket_client_multiple_protocols 739s END /res/websocket/ - websocket_client_multiple_protocols Time: <1ms Result: PASS 739s START /res/websocket/ - websocket_client_unsupported_protocol 739s END /res/websocket/ - websocket_client_unsupported_protocol Time: <1ms Result: PASS 739s START /res/websocket/ - websocket_client_bad_url 739s END /res/websocket/ - websocket_client_bad_url Time: 1ms Result: PASS 739s START /stasis/channels/ - channel_redirect_snapshot_json 739s END /stasis/channels/ - channel_redirect_snapshot_json Time: <1ms Result: PASS 739s START /stasis/channels/ - channel_snapshot_json 739s END /stasis/channels/ - channel_snapshot_json Time: <1ms Result: PASS 739s START /stasis/channels/ - multi_channel_blob_snapshots 739s END /stasis/channels/ - multi_channel_blob_snapshots Time: <1ms Result: PASS 739s START /stasis/channels/ - multi_channel_blob_create 739s END /stasis/channels/ - multi_channel_blob_create Time: <1ms Result: PASS 739s START /stasis/channels/ - null_blob 739s END /stasis/channels/ - null_blob Time: <1ms Result: PASS 739s START /stasis/channels/ - channel_blob_create 739s END /stasis/channels/ - channel_blob_create Time: <1ms Result: PASS 739s START /stasis/core/ - caching_dtor_order 739s END /stasis/core/ - caching_dtor_order Time: <1ms Result: PASS 739s START /stasis/core/ - dtor_order 739s END /stasis/core/ - dtor_order Time: <1ms Result: PASS 739s START /stasis/core/ - to_ami 739s END /stasis/core/ - to_ami Time: <1ms Result: PASS 739s START /stasis/core/ - no_to_ami 739s END /stasis/core/ - no_to_ami Time: <1ms Result: PASS 739s START /stasis/core/ - to_json 739s END /stasis/core/ - to_json Time: <1ms Result: PASS 739s START /stasis/core/ - no_to_json 739s END /stasis/core/ - no_to_json Time: <1ms Result: PASS 739s START /stasis/core/ - subscription_interleaving 739s END /stasis/core/ - subscription_interleaving Time: <1ms Result: PASS 739s START /stasis/core/ - interleaving 739s END /stasis/core/ - interleaving Time: <1ms Result: PASS 739s START /stasis/core/ - router_cache_updates 739s END /stasis/core/ - router_cache_updates Time: 100ms Result: PASS 739s START /stasis/core/ - router_pool 739s END /stasis/core/ - router_pool Time: <1ms Result: PASS 739s START /stasis/core/ - router 739s END /stasis/core/ - router Time: <1ms Result: PASS 739s START /stasis/core/ - cache_eid_aggregate 739s END /stasis/core/ - cache_eid_aggregate Time: <1ms Result: PASS 739s START /stasis/core/ - cache_dump 739s END /stasis/core/ - cache_dump Time: <1ms Result: PASS 739s START /stasis/core/ - cache 739s END /stasis/core/ - cache Time: <1ms Result: PASS 739s START /stasis/core/ - cache_filter 739s END /stasis/core/ - cache_filter Time: 100ms Result: PASS 739s START /stasis/core/ - forward 739s END /stasis/core/ - forward Time: <1ms Result: PASS 739s START /stasis/core/ - unsubscribe_stops_messages 739s END /stasis/core/ - unsubscribe_stops_messages Time: 100ms Result: PASS 739s START /stasis/core/ - publish_pool 739s END /stasis/core/ - publish_pool Time: <1ms Result: PASS 739s START /stasis/core/ - publish_sync 739s END /stasis/core/ - publish_sync Time: <1ms Result: PASS 739s START /stasis/core/ - publish 739s END /stasis/core/ - publish Time: <1ms Result: PASS 739s START /stasis/core/ - subscription_pool_messages 739s END /stasis/core/ - subscription_pool_messages Time: <1ms Result: PASS 739s START /stasis/core/ - subscription_messages 739s END /stasis/core/ - subscription_messages Time: <1ms Result: PASS 739s START /stasis/core/ - message 739s END /stasis/core/ - message Time: <1ms Result: PASS 739s START /stasis/core/ - message_type 739s END /stasis/core/ - message_type Time: <1ms Result: PASS 739s START /stasis/core/filtering/ - combo_filters 739s [test_stasis.c:dump_consumer:2198]: Messages received: 7 Final? yes 739s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 739s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType1 Pass 739s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass 739s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMI Pass 739s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass 739s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageJSON Pass 739s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 739s END /stasis/core/filtering/ - combo_filters Time: <1ms Result: PASS 739s START /stasis/core/filtering/ - formatter_filters 739s [test_stasis.c:dump_consumer:2198]: Messages received: 7 Final? yes 739s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 739s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMI Pass 739s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageJSON Pass 739s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass 739s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass2 739s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageEVENT Pass 739s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 739s END /stasis/core/filtering/ - formatter_filters Time: <1ms Result: PASS 739s START /stasis/core/filtering/ - type_filters 739s [test_stasis.c:dump_consumer:2198]: Messages received: 5 Final? yes 739s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 739s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType1 Pass 739s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass 739s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass2 739s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 739s END /stasis/core/filtering/ - type_filters Time: <1ms Result: PASS 739s START /stasis/core/state/ - explicit_publish 739s END /stasis/core/state/ - explicit_publish Time: 34ms Result: PASS 739s START /stasis/core/state/ - implicit_publish 739s END /stasis/core/state/ - implicit_publish Time: 26ms Result: PASS 739s START /stasis/endpoints/ - channel_messages 739s END /stasis/endpoints/ - channel_messages Time: <1ms Result: PASS 739s START /stasis/endpoints/ - cache_clear 739s END /stasis/endpoints/ - cache_clear Time: <1ms Result: PASS 739s START /stasis/endpoints/ - state_changes 739s END /stasis/endpoints/ - state_changes Time: <1ms Result: PASS 739s START /stasis/res/ - app_invoke_dne 739s END /stasis/res/ - app_invoke_dne Time: <1ms Result: PASS 739s START /stasis/res/ - app_invoke_one 739s END /stasis/res/ - app_invoke_one Time: <1ms Result: PASS 739s START /stasis/res/ - app_replaced 739s END /stasis/res/ - app_replaced Time: <1ms Result: PASS 739s 739s 658 Test(s) Executed 631 Passed 27 Failed 739s 'U' option is not compatible with remote console mode and has no effect. 739s 739s Results Generated Successfully: /tmp/autopkgtest.Fb03Z3/build.sq2/src/debian/tests/testmods/output/results.txt 739s 'U' option is not compatible with remote console mode and has no effect. 739s 739s Some test modules were not loaded: 739s 20a21 739s > test_cel.so 739s 53a55 739s > test_message.so 739s Manually disabled: 739s test_message 739s test_cel 739s 739s 'U' option is not compatible with remote console mode and has no effect. 739s 741s autopkgtest [18:09:23]: test asttestmods: -----------------------] 741s autopkgtest [18:09:23]: test asttestmods: - - - - - - - - - - results - - - - - - - - - - 741s asttestmods PASS 742s autopkgtest [18:09:24]: test amr: preparing testbed 879s autopkgtest [18:11:41]: testbed dpkg architecture: ppc64el 879s autopkgtest [18:11:41]: testbed apt version: 2.7.14build2 879s autopkgtest [18:11:41]: @@@@@@@@@@@@@@@@@@@@ test bed setup 880s Get:1 http://ftpmaster.internal/ubuntu noble-proposed InRelease [117 kB] 880s Get:2 http://ftpmaster.internal/ubuntu noble-proposed/restricted Sources [12.3 kB] 880s Get:3 http://ftpmaster.internal/ubuntu noble-proposed/main Sources [48.6 kB] 880s Get:4 http://ftpmaster.internal/ubuntu noble-proposed/multiverse Sources [2340 B] 880s Get:5 http://ftpmaster.internal/ubuntu noble-proposed/universe Sources [264 kB] 880s Get:6 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el Packages [81.4 kB] 880s Get:7 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el c-n-f Metadata [3116 B] 880s Get:8 http://ftpmaster.internal/ubuntu noble-proposed/restricted ppc64el Packages [976 B] 880s Get:9 http://ftpmaster.internal/ubuntu noble-proposed/restricted ppc64el c-n-f Metadata [116 B] 880s Get:10 http://ftpmaster.internal/ubuntu noble-proposed/universe ppc64el Packages [236 kB] 880s Get:11 http://ftpmaster.internal/ubuntu noble-proposed/universe ppc64el c-n-f Metadata [8652 B] 880s Get:12 http://ftpmaster.internal/ubuntu noble-proposed/multiverse ppc64el Packages [1376 B] 880s Get:13 http://ftpmaster.internal/ubuntu noble-proposed/multiverse ppc64el c-n-f Metadata [116 B] 882s Fetched 776 kB in 1s (839 kB/s) 882s Reading package lists... 884s sh: 4: dhclient: not found 884s Reading package lists... 885s Building dependency tree... 885s Reading state information... 885s Calculating upgrade... 885s The following packages will be upgraded: 885s libnss-systemd libpam-systemd libsystemd-shared libsystemd0 libudev1 systemd 885s systemd-dev systemd-resolved systemd-sysv systemd-timesyncd udev 885s 11 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 885s Need to get 9899 kB of archives. 885s After this operation, 6144 B of additional disk space will be used. 885s Get:1 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el systemd-dev all 255.4-1ubuntu8 [104 kB] 885s Get:2 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el systemd-timesyncd ppc64el 255.4-1ubuntu8 [37.9 kB] 885s Get:3 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el systemd-resolved ppc64el 255.4-1ubuntu8 [347 kB] 885s Get:4 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el libsystemd-shared ppc64el 255.4-1ubuntu8 [2351 kB] 886s Get:5 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el libsystemd0 ppc64el 255.4-1ubuntu8 [526 kB] 886s Get:6 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el systemd-sysv ppc64el 255.4-1ubuntu8 [11.9 kB] 886s Get:7 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el libnss-systemd ppc64el 255.4-1ubuntu8 [208 kB] 886s Get:8 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el libpam-systemd ppc64el 255.4-1ubuntu8 [304 kB] 886s Get:9 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el systemd ppc64el 255.4-1ubuntu8 [3771 kB] 886s Get:10 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el udev ppc64el 255.4-1ubuntu8 [2038 kB] 887s Get:11 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el libudev1 ppc64el 255.4-1ubuntu8 [201 kB] 887s Fetched 9899 kB in 2s (5735 kB/s) 887s (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 ... 72009 files and directories currently installed.) 887s Preparing to unpack .../systemd-dev_255.4-1ubuntu8_all.deb ... 887s Unpacking systemd-dev (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 887s Preparing to unpack .../systemd-timesyncd_255.4-1ubuntu8_ppc64el.deb ... 887s Unpacking systemd-timesyncd (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 887s Preparing to unpack .../systemd-resolved_255.4-1ubuntu8_ppc64el.deb ... 887s Unpacking systemd-resolved (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 887s Preparing to unpack .../libsystemd-shared_255.4-1ubuntu8_ppc64el.deb ... 887s Unpacking libsystemd-shared:ppc64el (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 887s Preparing to unpack .../libsystemd0_255.4-1ubuntu8_ppc64el.deb ... 887s Unpacking libsystemd0:ppc64el (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 887s Setting up libsystemd0:ppc64el (255.4-1ubuntu8) ... 887s (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 ... 72009 files and directories currently installed.) 887s Preparing to unpack .../0-systemd-sysv_255.4-1ubuntu8_ppc64el.deb ... 887s Unpacking systemd-sysv (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 887s Preparing to unpack .../1-libnss-systemd_255.4-1ubuntu8_ppc64el.deb ... 887s Unpacking libnss-systemd:ppc64el (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 887s Preparing to unpack .../2-libpam-systemd_255.4-1ubuntu8_ppc64el.deb ... 887s Unpacking libpam-systemd:ppc64el (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 887s Preparing to unpack .../3-systemd_255.4-1ubuntu8_ppc64el.deb ... 887s Unpacking systemd (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 888s Preparing to unpack .../4-udev_255.4-1ubuntu8_ppc64el.deb ... 888s Unpacking udev (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 888s Preparing to unpack .../5-libudev1_255.4-1ubuntu8_ppc64el.deb ... 888s Unpacking libudev1:ppc64el (255.4-1ubuntu8) over (255.4-1ubuntu7) ... 888s Setting up libudev1:ppc64el (255.4-1ubuntu8) ... 888s Setting up systemd-dev (255.4-1ubuntu8) ... 888s Setting up libsystemd-shared:ppc64el (255.4-1ubuntu8) ... 888s Setting up systemd (255.4-1ubuntu8) ... 888s Setting up systemd-timesyncd (255.4-1ubuntu8) ... 889s Setting up udev (255.4-1ubuntu8) ... 890s Setting up systemd-resolved (255.4-1ubuntu8) ... 890s Setting up systemd-sysv (255.4-1ubuntu8) ... 890s Setting up libnss-systemd:ppc64el (255.4-1ubuntu8) ... 890s Setting up libpam-systemd:ppc64el (255.4-1ubuntu8) ... 890s Processing triggers for libc-bin (2.39-0ubuntu8) ... 890s Processing triggers for man-db (2.12.0-4build2) ... 892s Processing triggers for dbus (1.14.10-4ubuntu4) ... 892s Processing triggers for initramfs-tools (0.142ubuntu25) ... 892s update-initramfs: Generating /boot/initrd.img-6.8.0-22-generic 892s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 898s Reading package lists... 898s Building dependency tree... 898s Reading state information... 898s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 898s Hit:1 http://ftpmaster.internal/ubuntu noble-proposed InRelease 899s Hit:2 http://ftpmaster.internal/ubuntu noble InRelease 899s Hit:3 http://ftpmaster.internal/ubuntu noble-updates InRelease 899s Hit:4 http://ftpmaster.internal/ubuntu noble-security InRelease 900s Reading package lists... 900s Reading package lists... 900s Building dependency tree... 900s Reading state information... 900s Calculating upgrade... 900s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 900s Reading package lists... 900s Building dependency tree... 900s Reading state information... 900s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 901s autopkgtest [18:12:03]: rebooting testbed after setup commands that affected boot 945s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 956s Reading package lists... 956s Building dependency tree... 956s Reading state information... 956s Starting pkgProblemResolver with broken count: 0 956s Starting 2 pkgProblemResolver with broken count: 0 956s Done 957s The following additional packages will be installed: 957s asterisk asterisk-config asterisk-core-sounds-en asterisk-core-sounds-en-gsm 957s asterisk-modules freetds-common libasound2-data libasound2t64 957s libc-client2007e libcodec2-1.2 libevent-2.1-7t64 libgmime-3.0-0t64 libgsm1 957s libical3t64 libiksemel3 libjack-jackd2-0 libltdl7 liblua5.1-0 libneon27t64 957s libodbc2 libogg0 libopencore-amrnb0 libopencore-amrwb0 libopus0 libopusenc0 957s libopusfile0 libportaudio2 libpq5 libradcli4 libresample1 libsamplerate0 957s libsnmp-base libsnmp40t64 libspandsp2t64 libspeex1 libspeexdsp1 libsrtp2-1 957s libsybdb5 libunbound8 liburiparser1 libvo-amrwbenc0 libvorbis0a 957s libvorbisenc2 libvorbisfile3 libxslt1.1 mlock 957s Suggested packages: 957s asterisk-dahdi asterisk-dev asterisk-doc asterisk-ooh323 asterisk-opus 957s alsa-utils libasound2-plugins uw-mailutils jackd2 odbc-postgresql tdsodbc 957s opus-tools snmp-mibs-downloader speex 957s Recommended packages: 957s asterisk-moh-opsound-gsm sox alsa-ucm-conf alsa-topology-conf 957s The following NEW packages will be installed: 957s asterisk asterisk-config asterisk-core-sounds-en asterisk-core-sounds-en-gsm 957s asterisk-modules autopkgtest-satdep freetds-common libasound2-data 957s libasound2t64 libc-client2007e libcodec2-1.2 libevent-2.1-7t64 957s libgmime-3.0-0t64 libgsm1 libical3t64 libiksemel3 libjack-jackd2-0 libltdl7 957s liblua5.1-0 libneon27t64 libodbc2 libogg0 libopencore-amrnb0 957s libopencore-amrwb0 libopus0 libopusenc0 libopusfile0 libportaudio2 libpq5 957s libradcli4 libresample1 libsamplerate0 libsnmp-base libsnmp40t64 957s libspandsp2t64 libspeex1 libspeexdsp1 libsrtp2-1 libsybdb5 libunbound8 957s liburiparser1 libvo-amrwbenc0 libvorbis0a libvorbisenc2 libvorbisfile3 957s libxslt1.1 mlock 957s 0 upgraded, 47 newly installed, 0 to remove and 0 not upgraded. 957s Need to get 26.6 MB/26.7 MB of archives. 957s After this operation, 90.2 MB of additional disk space will be used. 957s Get:1 /tmp/autopkgtest.Fb03Z3/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 957s Get:2 http://ftpmaster.internal/ubuntu noble/universe ppc64el asterisk-config all 1:20.6.0~dfsg+~cs6.13.40431414-2build5 [242 kB] 957s Get:3 http://ftpmaster.internal/ubuntu noble/universe ppc64el asterisk-core-sounds-en-gsm all 1.6.1-1 [2417 kB] 958s Get:4 http://ftpmaster.internal/ubuntu noble/universe ppc64el asterisk-core-sounds-en all 1.6.1-1 [20.6 kB] 958s Get:5 http://ftpmaster.internal/ubuntu noble/universe ppc64el mlock ppc64el 8:2007f~dfsg-7build3 [8082 B] 958s Get:6 http://ftpmaster.internal/ubuntu noble/universe ppc64el libc-client2007e ppc64el 8:2007f~dfsg-7build3 [676 kB] 958s Get:7 http://ftpmaster.internal/ubuntu noble/universe ppc64el libcodec2-1.2 ppc64el 1.2.0-2build1 [9048 kB] 959s Get:8 http://ftpmaster.internal/ubuntu noble/universe ppc64el libgmime-3.0-0t64 ppc64el 3.2.13+dfsg-2.1build2 [207 kB] 959s Get:9 http://ftpmaster.internal/ubuntu noble/universe ppc64el libgsm1 ppc64el 1.0.22-1build1 [41.9 kB] 959s Get:10 http://ftpmaster.internal/ubuntu noble/main ppc64el libical3t64 ppc64el 3.0.17-1.1build3 [349 kB] 959s Get:11 http://ftpmaster.internal/ubuntu noble/universe ppc64el libiksemel3 ppc64el 1.4-4build2 [34.8 kB] 959s Get:12 http://ftpmaster.internal/ubuntu noble/main ppc64el libopus0 ppc64el 1.4-1build1 [322 kB] 959s Get:13 http://ftpmaster.internal/ubuntu noble/main ppc64el libsamplerate0 ppc64el 0.2.2-4build1 [1348 kB] 959s Get:14 http://ftpmaster.internal/ubuntu noble/main ppc64el libjack-jackd2-0 ppc64el 1.9.21~dfsg-3ubuntu3 [340 kB] 959s Get:15 http://ftpmaster.internal/ubuntu noble/universe ppc64el liblua5.1-0 ppc64el 5.1.5-9build2 [157 kB] 959s Get:16 http://ftpmaster.internal/ubuntu noble/universe ppc64el libneon27t64 ppc64el 0.33.0-1.1build3 [120 kB] 959s Get:17 http://ftpmaster.internal/ubuntu noble/main ppc64el libltdl7 ppc64el 2.4.7-7build1 [48.2 kB] 959s Get:18 http://ftpmaster.internal/ubuntu noble/main ppc64el libodbc2 ppc64el 2.3.12-1build2 [188 kB] 959s Get:19 http://ftpmaster.internal/ubuntu noble/main ppc64el libogg0 ppc64el 1.3.5-3build1 [27.6 kB] 959s Get:20 http://ftpmaster.internal/ubuntu noble/universe ppc64el libopencore-amrnb0 ppc64el 0.1.6-1build1 [165 kB] 959s Get:21 http://ftpmaster.internal/ubuntu noble/universe ppc64el libopencore-amrwb0 ppc64el 0.1.6-1build1 [91.2 kB] 959s Get:22 http://ftpmaster.internal/ubuntu noble/universe ppc64el libopusenc0 ppc64el 0.2.1-2 [33.9 kB] 959s Get:23 http://ftpmaster.internal/ubuntu noble/universe ppc64el libopusfile0 ppc64el 0.12-4build3 [60.6 kB] 959s Get:24 http://ftpmaster.internal/ubuntu noble/main ppc64el libasound2-data all 1.2.11-1build2 [21.0 kB] 959s Get:25 http://ftpmaster.internal/ubuntu noble/main ppc64el libasound2t64 ppc64el 1.2.11-1build2 [502 kB] 959s Get:26 http://ftpmaster.internal/ubuntu noble/universe ppc64el libportaudio2 ppc64el 19.6.0-1.2build3 [87.5 kB] 959s Get:27 http://ftpmaster.internal/ubuntu noble/main ppc64el libpq5 ppc64el 16.2-1ubuntu4 [170 kB] 959s Get:28 http://ftpmaster.internal/ubuntu noble/universe ppc64el libradcli4 ppc64el 1.2.11-1build3 [45.5 kB] 959s Get:29 http://ftpmaster.internal/ubuntu noble/universe ppc64el libresample1 ppc64el 0.1.3-6 [11.1 kB] 959s Get:30 http://ftpmaster.internal/ubuntu noble/main ppc64el libsnmp-base all 5.9.4+dfsg-1.1ubuntu3 [206 kB] 959s Get:31 http://ftpmaster.internal/ubuntu noble/main ppc64el libsnmp40t64 ppc64el 5.9.4+dfsg-1.1ubuntu3 [1206 kB] 959s Get:32 http://ftpmaster.internal/ubuntu noble/universe ppc64el libspandsp2t64 ppc64el 0.0.6+dfsg-2.1build1 [399 kB] 959s Get:33 http://ftpmaster.internal/ubuntu noble/main ppc64el libspeex1 ppc64el 1.2.1-2ubuntu2 [111 kB] 959s Get:34 http://ftpmaster.internal/ubuntu noble/main ppc64el libspeexdsp1 ppc64el 1.2.1-1ubuntu3 [75.0 kB] 959s Get:35 http://ftpmaster.internal/ubuntu noble/universe ppc64el libsrtp2-1 ppc64el 2.5.0-3build1 [51.4 kB] 959s Get:36 http://ftpmaster.internal/ubuntu noble/main ppc64el freetds-common all 1.3.17+ds-2build3 [26.9 kB] 959s Get:37 http://ftpmaster.internal/ubuntu noble/main ppc64el libsybdb5 ppc64el 1.3.17+ds-2build3 [238 kB] 959s Get:38 http://ftpmaster.internal/ubuntu noble/main ppc64el libevent-2.1-7t64 ppc64el 2.1.12-stable-9ubuntu2 [174 kB] 959s Get:39 http://ftpmaster.internal/ubuntu noble/main ppc64el libunbound8 ppc64el 1.19.2-1ubuntu3 [537 kB] 959s Get:40 http://ftpmaster.internal/ubuntu noble/universe ppc64el libvo-amrwbenc0 ppc64el 0.1.3-2build1 [126 kB] 959s Get:41 http://ftpmaster.internal/ubuntu noble/main ppc64el libvorbis0a ppc64el 1.3.7-1build3 [142 kB] 959s Get:42 http://ftpmaster.internal/ubuntu noble/main ppc64el libvorbisenc2 ppc64el 1.3.7-1build3 [86.6 kB] 959s Get:43 http://ftpmaster.internal/ubuntu noble/main ppc64el libvorbisfile3 ppc64el 1.3.7-1build3 [22.9 kB] 959s Get:44 http://ftpmaster.internal/ubuntu noble/universe ppc64el asterisk-modules ppc64el 1:20.6.0~dfsg+~cs6.13.40431414-2build5 [3407 kB] 960s Get:45 http://ftpmaster.internal/ubuntu noble/universe ppc64el liburiparser1 ppc64el 0.9.7+dfsg-2build1 [53.6 kB] 960s Get:46 http://ftpmaster.internal/ubuntu noble/main ppc64el libxslt1.1 ppc64el 1.1.39-0exp1build1 [192 kB] 960s Get:47 http://ftpmaster.internal/ubuntu noble/universe ppc64el asterisk ppc64el 1:20.6.0~dfsg+~cs6.13.40431414-2build5 [2812 kB] 960s Fetched 26.6 MB in 3s (8796 kB/s) 960s Selecting previously unselected package asterisk-config. 960s (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 ... 72009 files and directories currently installed.) 960s Preparing to unpack .../00-asterisk-config_1%3a20.6.0~dfsg+~cs6.13.40431414-2build5_all.deb ... 960s Unpacking asterisk-config (1:20.6.0~dfsg+~cs6.13.40431414-2build5) ... 960s Selecting previously unselected package asterisk-core-sounds-en-gsm. 960s Preparing to unpack .../01-asterisk-core-sounds-en-gsm_1.6.1-1_all.deb ... 960s Unpacking asterisk-core-sounds-en-gsm (1.6.1-1) ... 960s Selecting previously unselected package asterisk-core-sounds-en. 960s Preparing to unpack .../02-asterisk-core-sounds-en_1.6.1-1_all.deb ... 960s Unpacking asterisk-core-sounds-en (1.6.1-1) ... 960s Selecting previously unselected package mlock. 961s Preparing to unpack .../03-mlock_8%3a2007f~dfsg-7build3_ppc64el.deb ... 961s Unpacking mlock (8:2007f~dfsg-7build3) ... 961s Selecting previously unselected package libc-client2007e. 961s Preparing to unpack .../04-libc-client2007e_8%3a2007f~dfsg-7build3_ppc64el.deb ... 961s Unpacking libc-client2007e (8:2007f~dfsg-7build3) ... 961s Selecting previously unselected package libcodec2-1.2:ppc64el. 961s Preparing to unpack .../05-libcodec2-1.2_1.2.0-2build1_ppc64el.deb ... 961s Unpacking libcodec2-1.2:ppc64el (1.2.0-2build1) ... 961s Selecting previously unselected package libgmime-3.0-0t64:ppc64el. 961s Preparing to unpack .../06-libgmime-3.0-0t64_3.2.13+dfsg-2.1build2_ppc64el.deb ... 961s Unpacking libgmime-3.0-0t64:ppc64el (3.2.13+dfsg-2.1build2) ... 961s Selecting previously unselected package libgsm1:ppc64el. 961s Preparing to unpack .../07-libgsm1_1.0.22-1build1_ppc64el.deb ... 961s Unpacking libgsm1:ppc64el (1.0.22-1build1) ... 961s Selecting previously unselected package libical3t64:ppc64el. 961s Preparing to unpack .../08-libical3t64_3.0.17-1.1build3_ppc64el.deb ... 961s Unpacking libical3t64:ppc64el (3.0.17-1.1build3) ... 961s Selecting previously unselected package libiksemel3:ppc64el. 961s Preparing to unpack .../09-libiksemel3_1.4-4build2_ppc64el.deb ... 961s Unpacking libiksemel3:ppc64el (1.4-4build2) ... 961s Selecting previously unselected package libopus0:ppc64el. 961s Preparing to unpack .../10-libopus0_1.4-1build1_ppc64el.deb ... 961s Unpacking libopus0:ppc64el (1.4-1build1) ... 961s Selecting previously unselected package libsamplerate0:ppc64el. 961s Preparing to unpack .../11-libsamplerate0_0.2.2-4build1_ppc64el.deb ... 961s Unpacking libsamplerate0:ppc64el (0.2.2-4build1) ... 961s Selecting previously unselected package libjack-jackd2-0:ppc64el. 961s Preparing to unpack .../12-libjack-jackd2-0_1.9.21~dfsg-3ubuntu3_ppc64el.deb ... 961s Unpacking libjack-jackd2-0:ppc64el (1.9.21~dfsg-3ubuntu3) ... 961s Selecting previously unselected package liblua5.1-0:ppc64el. 961s Preparing to unpack .../13-liblua5.1-0_5.1.5-9build2_ppc64el.deb ... 961s Unpacking liblua5.1-0:ppc64el (5.1.5-9build2) ... 961s Selecting previously unselected package libneon27t64:ppc64el. 961s Preparing to unpack .../14-libneon27t64_0.33.0-1.1build3_ppc64el.deb ... 961s Unpacking libneon27t64:ppc64el (0.33.0-1.1build3) ... 961s Selecting previously unselected package libltdl7:ppc64el. 961s Preparing to unpack .../15-libltdl7_2.4.7-7build1_ppc64el.deb ... 961s Unpacking libltdl7:ppc64el (2.4.7-7build1) ... 961s Selecting previously unselected package libodbc2:ppc64el. 961s Preparing to unpack .../16-libodbc2_2.3.12-1build2_ppc64el.deb ... 961s Unpacking libodbc2:ppc64el (2.3.12-1build2) ... 961s Selecting previously unselected package libogg0:ppc64el. 961s Preparing to unpack .../17-libogg0_1.3.5-3build1_ppc64el.deb ... 961s Unpacking libogg0:ppc64el (1.3.5-3build1) ... 961s Selecting previously unselected package libopencore-amrnb0:ppc64el. 961s Preparing to unpack .../18-libopencore-amrnb0_0.1.6-1build1_ppc64el.deb ... 961s Unpacking libopencore-amrnb0:ppc64el (0.1.6-1build1) ... 961s Selecting previously unselected package libopencore-amrwb0:ppc64el. 961s Preparing to unpack .../19-libopencore-amrwb0_0.1.6-1build1_ppc64el.deb ... 961s Unpacking libopencore-amrwb0:ppc64el (0.1.6-1build1) ... 961s Selecting previously unselected package libopusenc0:ppc64el. 961s Preparing to unpack .../20-libopusenc0_0.2.1-2_ppc64el.deb ... 961s Unpacking libopusenc0:ppc64el (0.2.1-2) ... 961s Selecting previously unselected package libopusfile0:ppc64el. 961s Preparing to unpack .../21-libopusfile0_0.12-4build3_ppc64el.deb ... 961s Unpacking libopusfile0:ppc64el (0.12-4build3) ... 961s Selecting previously unselected package libasound2-data. 961s Preparing to unpack .../22-libasound2-data_1.2.11-1build2_all.deb ... 961s Unpacking libasound2-data (1.2.11-1build2) ... 961s Selecting previously unselected package libasound2t64:ppc64el. 961s Preparing to unpack .../23-libasound2t64_1.2.11-1build2_ppc64el.deb ... 961s Unpacking libasound2t64:ppc64el (1.2.11-1build2) ... 961s Selecting previously unselected package libportaudio2:ppc64el. 961s Preparing to unpack .../24-libportaudio2_19.6.0-1.2build3_ppc64el.deb ... 961s Unpacking libportaudio2:ppc64el (19.6.0-1.2build3) ... 961s Selecting previously unselected package libpq5:ppc64el. 961s Preparing to unpack .../25-libpq5_16.2-1ubuntu4_ppc64el.deb ... 961s Unpacking libpq5:ppc64el (16.2-1ubuntu4) ... 961s Selecting previously unselected package libradcli4. 961s Preparing to unpack .../26-libradcli4_1.2.11-1build3_ppc64el.deb ... 961s Unpacking libradcli4 (1.2.11-1build3) ... 961s Selecting previously unselected package libresample1. 961s Preparing to unpack .../27-libresample1_0.1.3-6_ppc64el.deb ... 961s Unpacking libresample1 (0.1.3-6) ... 961s Selecting previously unselected package libsnmp-base. 961s Preparing to unpack .../28-libsnmp-base_5.9.4+dfsg-1.1ubuntu3_all.deb ... 961s Unpacking libsnmp-base (5.9.4+dfsg-1.1ubuntu3) ... 961s Selecting previously unselected package libsnmp40t64:ppc64el. 961s Preparing to unpack .../29-libsnmp40t64_5.9.4+dfsg-1.1ubuntu3_ppc64el.deb ... 961s Unpacking libsnmp40t64:ppc64el (5.9.4+dfsg-1.1ubuntu3) ... 961s Selecting previously unselected package libspandsp2t64:ppc64el. 961s Preparing to unpack .../30-libspandsp2t64_0.0.6+dfsg-2.1build1_ppc64el.deb ... 961s Unpacking libspandsp2t64:ppc64el (0.0.6+dfsg-2.1build1) ... 961s Selecting previously unselected package libspeex1:ppc64el. 961s Preparing to unpack .../31-libspeex1_1.2.1-2ubuntu2_ppc64el.deb ... 961s Unpacking libspeex1:ppc64el (1.2.1-2ubuntu2) ... 961s Selecting previously unselected package libspeexdsp1:ppc64el. 961s Preparing to unpack .../32-libspeexdsp1_1.2.1-1ubuntu3_ppc64el.deb ... 961s Unpacking libspeexdsp1:ppc64el (1.2.1-1ubuntu3) ... 961s Selecting previously unselected package libsrtp2-1:ppc64el. 961s Preparing to unpack .../33-libsrtp2-1_2.5.0-3build1_ppc64el.deb ... 961s Unpacking libsrtp2-1:ppc64el (2.5.0-3build1) ... 961s Selecting previously unselected package freetds-common. 961s Preparing to unpack .../34-freetds-common_1.3.17+ds-2build3_all.deb ... 961s Unpacking freetds-common (1.3.17+ds-2build3) ... 961s Selecting previously unselected package libsybdb5:ppc64el. 961s Preparing to unpack .../35-libsybdb5_1.3.17+ds-2build3_ppc64el.deb ... 961s Unpacking libsybdb5:ppc64el (1.3.17+ds-2build3) ... 961s Selecting previously unselected package libevent-2.1-7t64:ppc64el. 961s Preparing to unpack .../36-libevent-2.1-7t64_2.1.12-stable-9ubuntu2_ppc64el.deb ... 961s Unpacking libevent-2.1-7t64:ppc64el (2.1.12-stable-9ubuntu2) ... 961s Selecting previously unselected package libunbound8:ppc64el. 961s Preparing to unpack .../37-libunbound8_1.19.2-1ubuntu3_ppc64el.deb ... 961s Unpacking libunbound8:ppc64el (1.19.2-1ubuntu3) ... 961s Selecting previously unselected package libvo-amrwbenc0:ppc64el. 961s Preparing to unpack .../38-libvo-amrwbenc0_0.1.3-2build1_ppc64el.deb ... 961s Unpacking libvo-amrwbenc0:ppc64el (0.1.3-2build1) ... 961s Selecting previously unselected package libvorbis0a:ppc64el. 961s Preparing to unpack .../39-libvorbis0a_1.3.7-1build3_ppc64el.deb ... 961s Unpacking libvorbis0a:ppc64el (1.3.7-1build3) ... 961s Selecting previously unselected package libvorbisenc2:ppc64el. 961s Preparing to unpack .../40-libvorbisenc2_1.3.7-1build3_ppc64el.deb ... 961s Unpacking libvorbisenc2:ppc64el (1.3.7-1build3) ... 961s Selecting previously unselected package libvorbisfile3:ppc64el. 961s Preparing to unpack .../41-libvorbisfile3_1.3.7-1build3_ppc64el.deb ... 961s Unpacking libvorbisfile3:ppc64el (1.3.7-1build3) ... 961s Selecting previously unselected package asterisk-modules. 961s Preparing to unpack .../42-asterisk-modules_1%3a20.6.0~dfsg+~cs6.13.40431414-2build5_ppc64el.deb ... 961s Unpacking asterisk-modules (1:20.6.0~dfsg+~cs6.13.40431414-2build5) ... 962s Selecting previously unselected package liburiparser1:ppc64el. 962s Preparing to unpack .../43-liburiparser1_0.9.7+dfsg-2build1_ppc64el.deb ... 962s Unpacking liburiparser1:ppc64el (0.9.7+dfsg-2build1) ... 962s Selecting previously unselected package libxslt1.1:ppc64el. 962s Preparing to unpack .../44-libxslt1.1_1.1.39-0exp1build1_ppc64el.deb ... 962s Unpacking libxslt1.1:ppc64el (1.1.39-0exp1build1) ... 962s Selecting previously unselected package asterisk. 962s Preparing to unpack .../45-asterisk_1%3a20.6.0~dfsg+~cs6.13.40431414-2build5_ppc64el.deb ... 962s Unpacking asterisk (1:20.6.0~dfsg+~cs6.13.40431414-2build5) ... 962s Selecting previously unselected package autopkgtest-satdep. 962s Preparing to unpack .../46-2-autopkgtest-satdep.deb ... 962s Unpacking autopkgtest-satdep (0) ... 962s Setting up libvo-amrwbenc0:ppc64el (0.1.3-2build1) ... 962s Setting up libneon27t64:ppc64el (0.33.0-1.1build3) ... 962s Setting up libogg0:ppc64el (1.3.5-3build1) ... 962s Setting up libspeex1:ppc64el (1.2.1-2ubuntu2) ... 962s Setting up libgsm1:ppc64el (1.0.22-1build1) ... 962s Setting up asterisk-core-sounds-en-gsm (1.6.1-1) ... 962s Setting up libsnmp-base (5.9.4+dfsg-1.1ubuntu3) ... 962s Setting up libcodec2-1.2:ppc64el (1.2.0-2build1) ... 962s Setting up mlock (8:2007f~dfsg-7build3) ... 962s Setting up libsrtp2-1:ppc64el (2.5.0-3build1) ... 962s Setting up libpq5:ppc64el (16.2-1ubuntu4) ... 962s Setting up libevent-2.1-7t64:ppc64el (2.1.12-stable-9ubuntu2) ... 962s Setting up libasound2-data (1.2.11-1build2) ... 962s Setting up libopencore-amrwb0:ppc64el (0.1.6-1build1) ... 962s Setting up libunbound8:ppc64el (1.19.2-1ubuntu3) ... 962s Setting up libasound2t64:ppc64el (1.2.11-1build2) ... 962s Setting up libradcli4 (1.2.11-1build3) ... 962s Setting up libopus0:ppc64el (1.4-1build1) ... 962s Setting up asterisk-config (1:20.6.0~dfsg+~cs6.13.40431414-2build5) ... 962s Setting up libvorbis0a:ppc64el (1.3.7-1build3) ... 962s Setting up libical3t64:ppc64el (3.0.17-1.1build3) ... 962s Setting up libltdl7:ppc64el (2.4.7-7build1) ... 962s Setting up asterisk-core-sounds-en (1.6.1-1) ... 962s update-alternatives: using /usr/share/asterisk/sounds/en_US_f_Allison to provide /usr/share/asterisk/sounds/en (asterisk-prompt-en) in auto mode 962s 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 962s Setting up libiksemel3:ppc64el (1.4-4build2) ... 962s Setting up libodbc2:ppc64el (2.3.12-1build2) ... 962s Setting up liburiparser1:ppc64el (0.9.7+dfsg-2build1) ... 962s Setting up libspandsp2t64:ppc64el (0.0.6+dfsg-2.1build1) ... 962s Setting up libspeexdsp1:ppc64el (1.2.1-1ubuntu3) ... 962s Setting up liblua5.1-0:ppc64el (5.1.5-9build2) ... 962s Setting up libxslt1.1:ppc64el (1.1.39-0exp1build1) ... 962s Setting up libopencore-amrnb0:ppc64el (0.1.6-1build1) ... 962s Setting up libc-client2007e (8:2007f~dfsg-7build3) ... 962s Setting up libresample1 (0.1.3-6) ... 962s Setting up freetds-common (1.3.17+ds-2build3) ... 962s Setting up libgmime-3.0-0t64:ppc64el (3.2.13+dfsg-2.1build2) ... 962s Setting up libsamplerate0:ppc64el (0.2.2-4build1) ... 962s Setting up libopusfile0:ppc64el (0.12-4build3) ... 962s Setting up libvorbisenc2:ppc64el (1.3.7-1build3) ... 962s Setting up libopusenc0:ppc64el (0.2.1-2) ... 962s Setting up libsnmp40t64:ppc64el (5.9.4+dfsg-1.1ubuntu3) ... 962s Setting up libsybdb5:ppc64el (1.3.17+ds-2build3) ... 962s Setting up libvorbisfile3:ppc64el (1.3.7-1build3) ... 962s Setting up libjack-jackd2-0:ppc64el (1.9.21~dfsg-3ubuntu3) ... 962s Setting up libportaudio2:ppc64el (19.6.0-1.2build3) ... 962s Setting up asterisk-modules (1:20.6.0~dfsg+~cs6.13.40431414-2build5) ... 962s Setting up asterisk (1:20.6.0~dfsg+~cs6.13.40431414-2build5) ... 962s Adding system user for Asterisk 962s info: Adding user `asterisk' to group `dialout' ... 962s info: Adding user `asterisk' to group `audio' ... 963s Created symlink /etc/systemd/system/multi-user.target.wants/asterisk.service → /usr/lib/systemd/system/asterisk.service. 964s Setting up autopkgtest-satdep (0) ... 964s Processing triggers for man-db (2.12.0-4build2) ... 965s Processing triggers for libc-bin (2.39-0ubuntu8) ... 968s (Reading database ... 73928 files and directories currently installed.) 968s Removing autopkgtest-satdep (0) ... 981s autopkgtest [18:13:23]: test amr: [----------------------- 982s 1 audio amr amr (AMR) 982s 2 audio amrwb amrwb (AMR-WB) 982s amr amrwb codec2 ulaw alaw gsm g726 g726aal2 adpcm slin8 slin12 slin16 slin24 slin32 slin44 slin48 slin96 slin192 lpc10 speex8 speex16 speex32 g722 opus 982s amr - 23000 15000 15000 15000 15000 15000 15000 15000 9000 17000 17000 17000 17000 17000 17000 17000 17000 15000 15000 23000 23000 17250 15000 982s amr amrwb codec2 ulaw alaw gsm g726 g726aal2 adpcm slin8 slin12 slin16 slin24 slin32 slin44 slin48 slin96 slin192 lpc10 speex8 speex16 speex32 g722 opus 982s amrwb 23500 - 23500 23500 23500 23500 23500 23500 23500 17500 17500 9000 17000 17000 17000 17000 17000 17000 23500 23500 15000 23000 15000 14999 982s autopkgtest [18:13:24]: test amr: -----------------------] 982s autopkgtest [18:13:24]: test amr: - - - - - - - - - - results - - - - - - - - - - 982s amr PASS 983s autopkgtest [18:13:25]: @@@@@@@@@@@@@@@@@@@@ summary 983s asttestmods PASS 983s amr PASS 994s Creating nova instance adt-noble-ppc64el-asterisk-20240419-175702-juju-7f2275-prod-proposed-migration-environment-3-909d6297-3272-4708-86ed-9201ea8ff7f9 from image adt/ubuntu-noble-ppc64el-server-20240419.img (UUID b7a0af62-4a88-423a-a98e-eb9a30e958ea)... 994s Creating nova instance adt-noble-ppc64el-asterisk-20240419-175702-juju-7f2275-prod-proposed-migration-environment-3-909d6297-3272-4708-86ed-9201ea8ff7f9 from image adt/ubuntu-noble-ppc64el-server-20240419.img (UUID b7a0af62-4a88-423a-a98e-eb9a30e958ea)...