0s autopkgtest [08:53:59]: starting date and time: 2025-01-20 08:53:59+0000 0s autopkgtest [08:53:59]: git checkout: 325255d2 Merge branch 'pin-any-arch' into 'ubuntu/production' 0s autopkgtest [08:53:59]: host juju-7f2275-prod-proposed-migration-environment-20; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.zoyuf1fc/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:libedit,src:libxcrypt --apt-upgrade asterisk --timeout-short=300 --timeout-copy=20000 --timeout-build=20000 '--env=ADT_TEST_TRIGGERS=libedit/3.1-20250104-1 libxcrypt/1:4.4.38-1' -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor builder-cpu2-ram4-disk20 --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-20@bos03-6.secgroup --name adt-plucky-amd64-asterisk-20250120-072951-juju-7f2275-prod-proposed-migration-environment-20-ea450aa8-3b4f-4fb9-8316-db17536d758e --image adt/ubuntu-plucky-amd64-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-20 --net-id=net_prod-proposed-migration-amd64 -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com,radosgw.ps5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 279s autopkgtest [08:58:38]: testbed dpkg architecture: amd64 279s autopkgtest [08:58:38]: testbed apt version: 2.9.18 279s autopkgtest [08:58:38]: @@@@@@@@@@@@@@@@@@@@ test bed setup 279s autopkgtest [08:58:38]: testbed release detected to be: None 280s autopkgtest [08:58:39]: updating testbed package index (apt update) 281s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed InRelease [73.9 kB] 281s Hit:2 http://ftpmaster.internal/ubuntu plucky InRelease 281s Hit:3 http://ftpmaster.internal/ubuntu plucky-updates InRelease 281s Hit:4 http://ftpmaster.internal/ubuntu plucky-security InRelease 281s Get:5 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse Sources [15.3 kB] 281s Get:6 http://ftpmaster.internal/ubuntu plucky-proposed/restricted Sources [9708 B] 281s Get:7 http://ftpmaster.internal/ubuntu plucky-proposed/main Sources [145 kB] 281s Get:8 http://ftpmaster.internal/ubuntu plucky-proposed/universe Sources [820 kB] 281s Get:9 http://ftpmaster.internal/ubuntu plucky-proposed/main amd64 Packages [274 kB] 281s Get:10 http://ftpmaster.internal/ubuntu plucky-proposed/main i386 Packages [185 kB] 281s Get:11 http://ftpmaster.internal/ubuntu plucky-proposed/restricted amd64 Packages [40.1 kB] 281s Get:12 http://ftpmaster.internal/ubuntu plucky-proposed/restricted i386 Packages [2408 B] 281s Get:13 http://ftpmaster.internal/ubuntu plucky-proposed/universe amd64 Packages [925 kB] 281s Get:14 http://ftpmaster.internal/ubuntu plucky-proposed/universe i386 Packages [384 kB] 281s Get:15 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse amd64 Packages [25.5 kB] 281s Get:16 http://ftpmaster.internal/ubuntu plucky-proposed/multiverse i386 Packages [4420 B] 282s Fetched 2905 kB in 1s (2376 kB/s) 282s Reading package lists... 283s Reading package lists... 283s Building dependency tree... 283s Reading state information... 284s Calculating upgrade... 284s The following packages will be upgraded: 284s netcat-openbsd python3-more-itertools 284s 2 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 284s Need to get 103 kB of archives. 284s After this operation, 13.3 kB of additional disk space will be used. 284s Get:1 http://ftpmaster.internal/ubuntu plucky/main amd64 netcat-openbsd amd64 1.228-1 [44.9 kB] 284s Get:2 http://ftpmaster.internal/ubuntu plucky/main amd64 python3-more-itertools all 10.6.0-1 [57.7 kB] 284s Fetched 103 kB in 0s (297 kB/s) 285s (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 ... 89449 files and directories currently installed.) 285s Preparing to unpack .../netcat-openbsd_1.228-1_amd64.deb ... 285s Unpacking netcat-openbsd (1.228-1) over (1.226-1.1) ... 285s Preparing to unpack .../python3-more-itertools_10.6.0-1_all.deb ... 285s Unpacking python3-more-itertools (10.6.0-1) over (10.5.0-1) ... 285s Setting up python3-more-itertools (10.6.0-1) ... 285s Setting up netcat-openbsd (1.228-1) ... 285s Processing triggers for man-db (2.13.0-1) ... 286s 286s Running kernel seems to be up-to-date. 286s 286s No services need to be restarted. 286s 286s No containers need to be restarted. 286s 286s No user sessions are running outdated binaries. 286s 286s No VM guests are running outdated hypervisor (qemu) binaries on this host. 287s Reading package lists... 288s Building dependency tree... 288s Reading state information... 288s 0 upgraded, 0 newly installed, 0 to remove and 3 not upgraded. 288s autopkgtest [08:58:47]: upgrading testbed (apt dist-upgrade and autopurge) 288s Reading package lists... 289s Building dependency tree... 289s Reading state information... 289s Calculating upgrade...Starting pkgProblemResolver with broken count: 0 289s Starting 2 pkgProblemResolver with broken count: 0 289s Done 289s Entering ResolveByKeep 290s 290s The following packages will be upgraded: 290s libcrypt-dev libcrypt1 libedit2 290s 3 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 290s Need to get 320 kB of archives. 290s After this operation, 4096 B disk space will be freed. 290s Get:1 http://ftpmaster.internal/ubuntu plucky-proposed/main amd64 libcrypt-dev amd64 1:4.4.38-1 [120 kB] 290s Get:2 http://ftpmaster.internal/ubuntu plucky-proposed/main amd64 libcrypt1 amd64 1:4.4.38-1 [90.2 kB] 290s Get:3 http://ftpmaster.internal/ubuntu plucky-proposed/main amd64 libedit2 amd64 3.1-20250104-1 [110 kB] 290s Fetched 320 kB in 0s (642 kB/s) 290s (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 ... 89449 files and directories currently installed.) 290s Preparing to unpack .../libcrypt-dev_1%3a4.4.38-1_amd64.deb ... 291s Unpacking libcrypt-dev:amd64 (1:4.4.38-1) over (1:4.4.36-5) ... 291s Preparing to unpack .../libcrypt1_1%3a4.4.38-1_amd64.deb ... 291s Unpacking libcrypt1:amd64 (1:4.4.38-1) over (1:4.4.36-5) ... 291s Setting up libcrypt1:amd64 (1:4.4.38-1) ... 291s (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 ... 89449 files and directories currently installed.) 291s Preparing to unpack .../libedit2_3.1-20250104-1_amd64.deb ... 291s Unpacking libedit2:amd64 (3.1-20250104-1) over (3.1-20240808-1) ... 291s Setting up libedit2:amd64 (3.1-20250104-1) ... 291s Setting up libcrypt-dev:amd64 (1:4.4.38-1) ... 291s Processing triggers for man-db (2.13.0-1) ... 292s Processing triggers for libc-bin (2.40-4ubuntu1) ... 292s 292s Running kernel seems to be up-to-date. 292s 292s Restarting services... 292s /etc/needrestart/restart.d/systemd-manager 292s systemctl restart ssh.service systemd-journald.service systemd-networkd.service systemd-resolved.service systemd-timesyncd.service 293s 293s Service restarts being deferred: 293s systemctl restart systemd-logind.service 293s 293s No containers need to be restarted. 293s 293s User sessions running outdated binaries: 293s ubuntu @ session #4: sshd-session[1203] 293s ubuntu @ user manager service: systemd[956] 293s 293s No VM guests are running outdated hypervisor (qemu) binaries on this host. 294s Reading package lists... 294s Building dependency tree... 294s Reading state information... 294s Starting pkgProblemResolver with broken count: 0 294s Starting 2 pkgProblemResolver with broken count: 0 294s Done 295s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 297s autopkgtest [08:58:56]: testbed running kernel: Linux 6.11.0-8-generic #8-Ubuntu SMP PREEMPT_DYNAMIC Mon Sep 16 13:41:20 UTC 2024 297s autopkgtest [08:58:56]: @@@@@@@@@@@@@@@@@@@@ apt-source asterisk 304s Get:1 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:22.1.1~dfsg+~cs6.14.60671435-1 (dsc) [5416 B] 304s Get:2 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:22.1.1~dfsg+~cs6.14.60671435-1 (tar) [11.3 kB] 304s Get:3 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:22.1.1~dfsg+~cs6.14.60671435-1 (tar) [22.0 kB] 304s Get:4 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:22.1.1~dfsg+~cs6.14.60671435-1 (tar) [22.5 kB] 304s Get:5 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:22.1.1~dfsg+~cs6.14.60671435-1 (tar) [6344 kB] 304s Get:6 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:22.1.1~dfsg+~cs6.14.60671435-1 (tar) [5938 kB] 304s Get:7 http://ftpmaster.internal/ubuntu plucky/universe asterisk 1:22.1.1~dfsg+~cs6.14.60671435-1 (diff) [122 kB] 305s gpgv: Signature made Sun Jan 12 23:14:35 2025 UTC 305s gpgv: using RSA key 9FE3E9C36691A69FF53CC6842C7C3146C1A00121 305s gpgv: Can't check signature: No public key 305s dpkg-source: warning: cannot verify inline signature for ./asterisk_22.1.1~dfsg+~cs6.14.60671435-1.dsc: no acceptable signature found 305s autopkgtest [08:59:04]: testing package asterisk version 1:22.1.1~dfsg+~cs6.14.60671435-1 306s autopkgtest [08:59:05]: build not needed 311s autopkgtest [08:59:10]: test asttestmods: preparing testbed 312s Reading package lists... 312s Building dependency tree... 312s Reading state information... 312s Starting pkgProblemResolver with broken count: 0 312s Starting 2 pkgProblemResolver with broken count: 0 312s Done 312s The following NEW packages will be installed: 312s asterisk asterisk-config asterisk-core-sounds-en asterisk-core-sounds-en-gsm 312s asterisk-modules asterisk-tests freetds-common libasound2-data libasound2t64 312s libb64-0d libc-client2007e libcodec2-1.2 libdeflate0 libevent-2.1-7t64 312s libgmime-3.0-0t64 libgsm1 libical3t64 libiksemel3 libjack-jackd2-0 libjbig0 312s libjpeg-turbo8 libjpeg8 libjwt2 liblerc4 libltdl7 liblua5.1-0 libneon27t64 312s libodbc2 libogg0 libopencore-amrnb0 libopencore-amrwb0 libopus0 libopusenc0 312s libopusfile0 libportaudio2 libpq5 libradcli4 libresample1 libsamplerate0 312s libsharpyuv0 libsnmp-base libsnmp40t64 libspandsp2t64 libspeex1 libspeexdsp1 312s libsrtp2-1 libsybdb5 libtiff6 libunbound8 liburiparser1 libvo-amrwbenc0 312s libvorbis0a libvorbisenc2 libvorbisfile3 libwebp7 libxml2-utils mlock 313s 0 upgraded, 57 newly installed, 0 to remove and 0 not upgraded. 313s Need to get 29.0 MB of archives. 313s After this operation, 73.9 MB of additional disk space will be used. 313s Get:1 http://ftpmaster.internal/ubuntu plucky/universe amd64 asterisk-config all 1:22.1.1~dfsg+~cs6.14.60671435-1 [223 kB] 313s Get:2 http://ftpmaster.internal/ubuntu plucky/universe amd64 asterisk-core-sounds-en-gsm all 1.6.1-1 [2417 kB] 313s Get:3 http://ftpmaster.internal/ubuntu plucky/universe amd64 asterisk-core-sounds-en all 1.6.1-1 [20.6 kB] 313s Get:4 http://ftpmaster.internal/ubuntu plucky/universe amd64 mlock amd64 8:2007f~dfsg-7.1 [8612 B] 313s Get:5 http://ftpmaster.internal/ubuntu plucky/universe amd64 libc-client2007e amd64 8:2007f~dfsg-7.1 [629 kB] 313s Get:6 http://ftpmaster.internal/ubuntu plucky/universe amd64 libcodec2-1.2 amd64 1.2.0-2build1 [8998 kB] 314s Get:7 http://ftpmaster.internal/ubuntu plucky/universe amd64 libgmime-3.0-0t64 amd64 3.2.15+dfsg-1 [176 kB] 314s Get:8 http://ftpmaster.internal/ubuntu plucky/universe amd64 libgsm1 amd64 1.0.22-1build1 [27.8 kB] 314s Get:9 http://ftpmaster.internal/ubuntu plucky/main amd64 libical3t64 amd64 3.0.19-3 [319 kB] 314s Get:10 http://ftpmaster.internal/ubuntu plucky/universe amd64 libiksemel3 amd64 1.4-4build2 [28.0 kB] 314s Get:11 http://ftpmaster.internal/ubuntu plucky/main amd64 libopus0 amd64 1.5.2-2 [2913 kB] 314s Get:12 http://ftpmaster.internal/ubuntu plucky/main amd64 libsamplerate0 amd64 0.2.2-4build1 [1344 kB] 314s Get:13 http://ftpmaster.internal/ubuntu plucky/main amd64 libjack-jackd2-0 amd64 1.9.22~dfsg-4 [312 kB] 314s Get:14 http://ftpmaster.internal/ubuntu plucky/universe amd64 libb64-0d amd64 1.2-5build1 [9692 B] 314s Get:15 http://ftpmaster.internal/ubuntu plucky/universe amd64 libjwt2 amd64 1.17.2-1 [18.5 kB] 314s Get:16 http://ftpmaster.internal/ubuntu plucky/universe amd64 liblua5.1-0 amd64 5.1.5-10 [144 kB] 314s Get:17 http://ftpmaster.internal/ubuntu plucky/universe amd64 libneon27t64 amd64 0.34.0-1 [108 kB] 314s Get:18 http://ftpmaster.internal/ubuntu plucky/main amd64 libltdl7 amd64 2.4.7-8 [43.9 kB] 314s Get:19 http://ftpmaster.internal/ubuntu plucky/main amd64 libodbc2 amd64 2.3.12-1ubuntu1 [158 kB] 314s Get:20 http://ftpmaster.internal/ubuntu plucky/main amd64 libogg0 amd64 1.3.5-3build1 [22.7 kB] 314s Get:21 http://ftpmaster.internal/ubuntu plucky/universe amd64 libopencore-amrnb0 amd64 0.1.6-1build1 [98.2 kB] 314s Get:22 http://ftpmaster.internal/ubuntu plucky/universe amd64 libopencore-amrwb0 amd64 0.1.6-1build1 [53.2 kB] 314s Get:23 http://ftpmaster.internal/ubuntu plucky/universe amd64 libopusenc0 amd64 0.2.1-2build1 [25.7 kB] 314s Get:24 http://ftpmaster.internal/ubuntu plucky/universe amd64 libopusfile0 amd64 0.12-4build3 [44.7 kB] 314s Get:25 http://ftpmaster.internal/ubuntu plucky/main amd64 libasound2-data all 1.2.12-1 [21.0 kB] 314s Get:26 http://ftpmaster.internal/ubuntu plucky/main amd64 libasound2t64 amd64 1.2.12-1 [394 kB] 314s Get:27 http://ftpmaster.internal/ubuntu plucky/universe amd64 libportaudio2 amd64 19.6.0-1.2build3 [67.9 kB] 314s Get:28 http://ftpmaster.internal/ubuntu plucky/main amd64 libpq5 amd64 17.2-1 [153 kB] 314s Get:29 http://ftpmaster.internal/ubuntu plucky/universe amd64 libradcli4 amd64 1.2.11-1build3 [40.5 kB] 314s Get:30 http://ftpmaster.internal/ubuntu plucky/universe amd64 libresample1 amd64 0.1.3-8 [8758 B] 314s Get:31 http://ftpmaster.internal/ubuntu plucky/main amd64 libsnmp-base all 5.9.4+dfsg-1.1ubuntu5 [206 kB] 314s Get:32 http://ftpmaster.internal/ubuntu plucky/main amd64 libsnmp40t64 amd64 5.9.4+dfsg-1.1ubuntu5 [1065 kB] 314s Get:33 http://ftpmaster.internal/ubuntu plucky/main amd64 libdeflate0 amd64 1.23-1 [64.1 kB] 314s Get:34 http://ftpmaster.internal/ubuntu plucky/main amd64 libjbig0 amd64 2.1-6.1ubuntu2 [29.7 kB] 314s Get:35 http://ftpmaster.internal/ubuntu plucky/main amd64 libjpeg-turbo8 amd64 2.1.5-3ubuntu2 [179 kB] 314s Get:36 http://ftpmaster.internal/ubuntu plucky/main amd64 libjpeg8 amd64 8c-2ubuntu11 [2148 B] 314s Get:37 http://ftpmaster.internal/ubuntu plucky/main amd64 liblerc4 amd64 4.0.0+ds-5ubuntu1 [271 kB] 314s Get:38 http://ftpmaster.internal/ubuntu plucky/main amd64 libsharpyuv0 amd64 1.5.0-0.1 [25.9 kB] 314s Get:39 http://ftpmaster.internal/ubuntu plucky/main amd64 libwebp7 amd64 1.5.0-0.1 [378 kB] 314s Get:40 http://ftpmaster.internal/ubuntu plucky/main amd64 libtiff6 amd64 4.5.1+git230720-4ubuntu4 [200 kB] 314s Get:41 http://ftpmaster.internal/ubuntu plucky/universe amd64 libspandsp2t64 amd64 0.0.6+dfsg-2.1build1 [311 kB] 314s Get:42 http://ftpmaster.internal/ubuntu plucky/main amd64 libspeex1 amd64 1.2.1-3 [86.7 kB] 314s Get:43 http://ftpmaster.internal/ubuntu plucky/main amd64 libspeexdsp1 amd64 1.2.1-1ubuntu3 [43.1 kB] 314s Get:44 http://ftpmaster.internal/ubuntu plucky/universe amd64 libsrtp2-1 amd64 2.5.0-3build1 [41.9 kB] 314s Get:45 http://ftpmaster.internal/ubuntu plucky/main amd64 freetds-common all 1.3.17+ds-2build3 [26.9 kB] 314s Get:46 http://ftpmaster.internal/ubuntu plucky/main amd64 libsybdb5 amd64 1.3.17+ds-2build3 [192 kB] 314s Get:47 http://ftpmaster.internal/ubuntu plucky/main amd64 libevent-2.1-7t64 amd64 2.1.12-stable-10 [144 kB] 314s Get:48 http://ftpmaster.internal/ubuntu plucky/main amd64 libunbound8 amd64 1.20.0-1ubuntu2.1 [447 kB] 314s Get:49 http://ftpmaster.internal/ubuntu plucky/universe amd64 libvo-amrwbenc0 amd64 0.1.3-2build1 [76.7 kB] 314s Get:50 http://ftpmaster.internal/ubuntu plucky/main amd64 libvorbis0a amd64 1.3.7-2 [98.4 kB] 314s Get:51 http://ftpmaster.internal/ubuntu plucky/main amd64 libvorbisenc2 amd64 1.3.7-2 [80.8 kB] 314s Get:52 http://ftpmaster.internal/ubuntu plucky/main amd64 libvorbisfile3 amd64 1.3.7-2 [17.1 kB] 314s Get:53 http://ftpmaster.internal/ubuntu plucky/universe amd64 asterisk-modules amd64 1:22.1.1~dfsg+~cs6.14.60671435-1 [2948 kB] 314s Get:54 http://ftpmaster.internal/ubuntu plucky/universe amd64 liburiparser1 amd64 0.9.8+dfsg-2 [46.8 kB] 314s Get:55 http://ftpmaster.internal/ubuntu plucky/universe amd64 asterisk amd64 1:22.1.1~dfsg+~cs6.14.60671435-1 [2620 kB] 314s Get:56 http://ftpmaster.internal/ubuntu plucky/universe amd64 asterisk-tests amd64 1:22.1.1~dfsg+~cs6.14.60671435-1 [557 kB] 314s Get:57 http://ftpmaster.internal/ubuntu plucky/main amd64 libxml2-utils amd64 2.12.7+dfsg+really2.9.14-0.2ubuntu2 [39.6 kB] 315s Fetched 29.0 MB in 2s (14.6 MB/s) 315s Selecting previously unselected package asterisk-config. 315s (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 ... 89449 files and directories currently installed.) 315s Preparing to unpack .../00-asterisk-config_1%3a22.1.1~dfsg+~cs6.14.60671435-1_all.deb ... 315s Unpacking asterisk-config (1:22.1.1~dfsg+~cs6.14.60671435-1) ... 315s Selecting previously unselected package asterisk-core-sounds-en-gsm. 315s Preparing to unpack .../01-asterisk-core-sounds-en-gsm_1.6.1-1_all.deb ... 315s Unpacking asterisk-core-sounds-en-gsm (1.6.1-1) ... 315s Selecting previously unselected package asterisk-core-sounds-en. 315s Preparing to unpack .../02-asterisk-core-sounds-en_1.6.1-1_all.deb ... 315s Unpacking asterisk-core-sounds-en (1.6.1-1) ... 315s Selecting previously unselected package mlock. 315s Preparing to unpack .../03-mlock_8%3a2007f~dfsg-7.1_amd64.deb ... 315s Unpacking mlock (8:2007f~dfsg-7.1) ... 315s Selecting previously unselected package libc-client2007e. 315s Preparing to unpack .../04-libc-client2007e_8%3a2007f~dfsg-7.1_amd64.deb ... 315s Unpacking libc-client2007e (8:2007f~dfsg-7.1) ... 315s Selecting previously unselected package libcodec2-1.2:amd64. 315s Preparing to unpack .../05-libcodec2-1.2_1.2.0-2build1_amd64.deb ... 315s Unpacking libcodec2-1.2:amd64 (1.2.0-2build1) ... 315s Selecting previously unselected package libgmime-3.0-0t64:amd64. 315s Preparing to unpack .../06-libgmime-3.0-0t64_3.2.15+dfsg-1_amd64.deb ... 315s Unpacking libgmime-3.0-0t64:amd64 (3.2.15+dfsg-1) ... 315s Selecting previously unselected package libgsm1:amd64. 315s Preparing to unpack .../07-libgsm1_1.0.22-1build1_amd64.deb ... 315s Unpacking libgsm1:amd64 (1.0.22-1build1) ... 315s Selecting previously unselected package libical3t64:amd64. 315s Preparing to unpack .../08-libical3t64_3.0.19-3_amd64.deb ... 315s Unpacking libical3t64:amd64 (3.0.19-3) ... 315s Selecting previously unselected package libiksemel3:amd64. 315s Preparing to unpack .../09-libiksemel3_1.4-4build2_amd64.deb ... 315s Unpacking libiksemel3:amd64 (1.4-4build2) ... 315s Selecting previously unselected package libopus0:amd64. 315s Preparing to unpack .../10-libopus0_1.5.2-2_amd64.deb ... 315s Unpacking libopus0:amd64 (1.5.2-2) ... 315s Selecting previously unselected package libsamplerate0:amd64. 315s Preparing to unpack .../11-libsamplerate0_0.2.2-4build1_amd64.deb ... 315s Unpacking libsamplerate0:amd64 (0.2.2-4build1) ... 315s Selecting previously unselected package libjack-jackd2-0:amd64. 315s Preparing to unpack .../12-libjack-jackd2-0_1.9.22~dfsg-4_amd64.deb ... 315s Unpacking libjack-jackd2-0:amd64 (1.9.22~dfsg-4) ... 315s Selecting previously unselected package libb64-0d:amd64. 316s Preparing to unpack .../13-libb64-0d_1.2-5build1_amd64.deb ... 316s Unpacking libb64-0d:amd64 (1.2-5build1) ... 316s Selecting previously unselected package libjwt2:amd64. 316s Preparing to unpack .../14-libjwt2_1.17.2-1_amd64.deb ... 316s Unpacking libjwt2:amd64 (1.17.2-1) ... 316s Selecting previously unselected package liblua5.1-0:amd64. 316s Preparing to unpack .../15-liblua5.1-0_5.1.5-10_amd64.deb ... 316s Unpacking liblua5.1-0:amd64 (5.1.5-10) ... 316s Selecting previously unselected package libneon27t64:amd64. 316s Preparing to unpack .../16-libneon27t64_0.34.0-1_amd64.deb ... 316s Unpacking libneon27t64:amd64 (0.34.0-1) ... 316s Selecting previously unselected package libltdl7:amd64. 316s Preparing to unpack .../17-libltdl7_2.4.7-8_amd64.deb ... 316s Unpacking libltdl7:amd64 (2.4.7-8) ... 316s Selecting previously unselected package libodbc2:amd64. 316s Preparing to unpack .../18-libodbc2_2.3.12-1ubuntu1_amd64.deb ... 316s Unpacking libodbc2:amd64 (2.3.12-1ubuntu1) ... 316s Selecting previously unselected package libogg0:amd64. 316s Preparing to unpack .../19-libogg0_1.3.5-3build1_amd64.deb ... 316s Unpacking libogg0:amd64 (1.3.5-3build1) ... 316s Selecting previously unselected package libopencore-amrnb0:amd64. 316s Preparing to unpack .../20-libopencore-amrnb0_0.1.6-1build1_amd64.deb ... 316s Unpacking libopencore-amrnb0:amd64 (0.1.6-1build1) ... 316s Selecting previously unselected package libopencore-amrwb0:amd64. 316s Preparing to unpack .../21-libopencore-amrwb0_0.1.6-1build1_amd64.deb ... 316s Unpacking libopencore-amrwb0:amd64 (0.1.6-1build1) ... 316s Selecting previously unselected package libopusenc0:amd64. 316s Preparing to unpack .../22-libopusenc0_0.2.1-2build1_amd64.deb ... 316s Unpacking libopusenc0:amd64 (0.2.1-2build1) ... 316s Selecting previously unselected package libopusfile0:amd64. 316s Preparing to unpack .../23-libopusfile0_0.12-4build3_amd64.deb ... 316s Unpacking libopusfile0:amd64 (0.12-4build3) ... 316s Selecting previously unselected package libasound2-data. 316s Preparing to unpack .../24-libasound2-data_1.2.12-1_all.deb ... 316s Unpacking libasound2-data (1.2.12-1) ... 316s Selecting previously unselected package libasound2t64:amd64. 316s Preparing to unpack .../25-libasound2t64_1.2.12-1_amd64.deb ... 316s Unpacking libasound2t64:amd64 (1.2.12-1) ... 316s Selecting previously unselected package libportaudio2:amd64. 316s Preparing to unpack .../26-libportaudio2_19.6.0-1.2build3_amd64.deb ... 316s Unpacking libportaudio2:amd64 (19.6.0-1.2build3) ... 316s Selecting previously unselected package libpq5:amd64. 316s Preparing to unpack .../27-libpq5_17.2-1_amd64.deb ... 316s Unpacking libpq5:amd64 (17.2-1) ... 316s Selecting previously unselected package libradcli4. 316s Preparing to unpack .../28-libradcli4_1.2.11-1build3_amd64.deb ... 316s Unpacking libradcli4 (1.2.11-1build3) ... 316s Selecting previously unselected package libresample1. 316s Preparing to unpack .../29-libresample1_0.1.3-8_amd64.deb ... 316s Unpacking libresample1 (0.1.3-8) ... 316s Selecting previously unselected package libsnmp-base. 316s Preparing to unpack .../30-libsnmp-base_5.9.4+dfsg-1.1ubuntu5_all.deb ... 316s Unpacking libsnmp-base (5.9.4+dfsg-1.1ubuntu5) ... 316s Selecting previously unselected package libsnmp40t64:amd64. 316s Preparing to unpack .../31-libsnmp40t64_5.9.4+dfsg-1.1ubuntu5_amd64.deb ... 316s Unpacking libsnmp40t64:amd64 (5.9.4+dfsg-1.1ubuntu5) ... 316s Selecting previously unselected package libdeflate0:amd64. 316s Preparing to unpack .../32-libdeflate0_1.23-1_amd64.deb ... 316s Unpacking libdeflate0:amd64 (1.23-1) ... 316s Selecting previously unselected package libjbig0:amd64. 316s Preparing to unpack .../33-libjbig0_2.1-6.1ubuntu2_amd64.deb ... 316s Unpacking libjbig0:amd64 (2.1-6.1ubuntu2) ... 316s Selecting previously unselected package libjpeg-turbo8:amd64. 316s Preparing to unpack .../34-libjpeg-turbo8_2.1.5-3ubuntu2_amd64.deb ... 316s Unpacking libjpeg-turbo8:amd64 (2.1.5-3ubuntu2) ... 316s Selecting previously unselected package libjpeg8:amd64. 316s Preparing to unpack .../35-libjpeg8_8c-2ubuntu11_amd64.deb ... 316s Unpacking libjpeg8:amd64 (8c-2ubuntu11) ... 316s Selecting previously unselected package liblerc4:amd64. 316s Preparing to unpack .../36-liblerc4_4.0.0+ds-5ubuntu1_amd64.deb ... 316s Unpacking liblerc4:amd64 (4.0.0+ds-5ubuntu1) ... 316s Selecting previously unselected package libsharpyuv0:amd64. 316s Preparing to unpack .../37-libsharpyuv0_1.5.0-0.1_amd64.deb ... 316s Unpacking libsharpyuv0:amd64 (1.5.0-0.1) ... 316s Selecting previously unselected package libwebp7:amd64. 316s Preparing to unpack .../38-libwebp7_1.5.0-0.1_amd64.deb ... 316s Unpacking libwebp7:amd64 (1.5.0-0.1) ... 316s Selecting previously unselected package libtiff6:amd64. 316s Preparing to unpack .../39-libtiff6_4.5.1+git230720-4ubuntu4_amd64.deb ... 316s Unpacking libtiff6:amd64 (4.5.1+git230720-4ubuntu4) ... 316s Selecting previously unselected package libspandsp2t64:amd64. 316s Preparing to unpack .../40-libspandsp2t64_0.0.6+dfsg-2.1build1_amd64.deb ... 316s Unpacking libspandsp2t64:amd64 (0.0.6+dfsg-2.1build1) ... 316s Selecting previously unselected package libspeex1:amd64. 316s Preparing to unpack .../41-libspeex1_1.2.1-3_amd64.deb ... 316s Unpacking libspeex1:amd64 (1.2.1-3) ... 316s Selecting previously unselected package libspeexdsp1:amd64. 316s Preparing to unpack .../42-libspeexdsp1_1.2.1-1ubuntu3_amd64.deb ... 316s Unpacking libspeexdsp1:amd64 (1.2.1-1ubuntu3) ... 316s Selecting previously unselected package libsrtp2-1:amd64. 316s Preparing to unpack .../43-libsrtp2-1_2.5.0-3build1_amd64.deb ... 316s Unpacking libsrtp2-1:amd64 (2.5.0-3build1) ... 316s Selecting previously unselected package freetds-common. 316s Preparing to unpack .../44-freetds-common_1.3.17+ds-2build3_all.deb ... 316s Unpacking freetds-common (1.3.17+ds-2build3) ... 316s Selecting previously unselected package libsybdb5:amd64. 317s Preparing to unpack .../45-libsybdb5_1.3.17+ds-2build3_amd64.deb ... 317s Unpacking libsybdb5:amd64 (1.3.17+ds-2build3) ... 317s Selecting previously unselected package libevent-2.1-7t64:amd64. 317s Preparing to unpack .../46-libevent-2.1-7t64_2.1.12-stable-10_amd64.deb ... 317s Unpacking libevent-2.1-7t64:amd64 (2.1.12-stable-10) ... 317s Selecting previously unselected package libunbound8:amd64. 317s Preparing to unpack .../47-libunbound8_1.20.0-1ubuntu2.1_amd64.deb ... 317s Unpacking libunbound8:amd64 (1.20.0-1ubuntu2.1) ... 317s Selecting previously unselected package libvo-amrwbenc0:amd64. 317s Preparing to unpack .../48-libvo-amrwbenc0_0.1.3-2build1_amd64.deb ... 317s Unpacking libvo-amrwbenc0:amd64 (0.1.3-2build1) ... 317s Selecting previously unselected package libvorbis0a:amd64. 317s Preparing to unpack .../49-libvorbis0a_1.3.7-2_amd64.deb ... 317s Unpacking libvorbis0a:amd64 (1.3.7-2) ... 317s Selecting previously unselected package libvorbisenc2:amd64. 317s Preparing to unpack .../50-libvorbisenc2_1.3.7-2_amd64.deb ... 317s Unpacking libvorbisenc2:amd64 (1.3.7-2) ... 317s Selecting previously unselected package libvorbisfile3:amd64. 317s Preparing to unpack .../51-libvorbisfile3_1.3.7-2_amd64.deb ... 317s Unpacking libvorbisfile3:amd64 (1.3.7-2) ... 317s Selecting previously unselected package asterisk-modules. 317s Preparing to unpack .../52-asterisk-modules_1%3a22.1.1~dfsg+~cs6.14.60671435-1_amd64.deb ... 317s Unpacking asterisk-modules (1:22.1.1~dfsg+~cs6.14.60671435-1) ... 317s Selecting previously unselected package liburiparser1:amd64. 317s Preparing to unpack .../53-liburiparser1_0.9.8+dfsg-2_amd64.deb ... 317s Unpacking liburiparser1:amd64 (0.9.8+dfsg-2) ... 317s Selecting previously unselected package asterisk. 317s Preparing to unpack .../54-asterisk_1%3a22.1.1~dfsg+~cs6.14.60671435-1_amd64.deb ... 317s Unpacking asterisk (1:22.1.1~dfsg+~cs6.14.60671435-1) ... 317s Selecting previously unselected package asterisk-tests. 317s Preparing to unpack .../55-asterisk-tests_1%3a22.1.1~dfsg+~cs6.14.60671435-1_amd64.deb ... 317s Unpacking asterisk-tests (1:22.1.1~dfsg+~cs6.14.60671435-1) ... 317s Selecting previously unselected package libxml2-utils. 317s Preparing to unpack .../56-libxml2-utils_2.12.7+dfsg+really2.9.14-0.2ubuntu2_amd64.deb ... 317s Unpacking libxml2-utils (2.12.7+dfsg+really2.9.14-0.2ubuntu2) ... 317s Setting up libsharpyuv0:amd64 (1.5.0-0.1) ... 317s Setting up libvo-amrwbenc0:amd64 (0.1.3-2build1) ... 317s Setting up libneon27t64:amd64 (0.34.0-1) ... 317s Setting up libogg0:amd64 (1.3.5-3build1) ... 317s Setting up liblerc4:amd64 (4.0.0+ds-5ubuntu1) ... 317s Setting up libspeex1:amd64 (1.2.1-3) ... 317s Setting up libgsm1:amd64 (1.0.22-1build1) ... 317s Setting up asterisk-core-sounds-en-gsm (1.6.1-1) ... 317s Setting up libsnmp-base (5.9.4+dfsg-1.1ubuntu5) ... 317s Setting up libcodec2-1.2:amd64 (1.2.0-2build1) ... 317s Setting up mlock (8:2007f~dfsg-7.1) ... 317s Setting up libsrtp2-1:amd64 (2.5.0-3build1) ... 317s Setting up libpq5:amd64 (17.2-1) ... 317s Setting up libdeflate0:amd64 (1.23-1) ... 317s Setting up libevent-2.1-7t64:amd64 (2.1.12-stable-10) ... 317s Setting up libb64-0d:amd64 (1.2-5build1) ... 317s Setting up libjwt2:amd64 (1.17.2-1) ... 317s Setting up libjbig0:amd64 (2.1-6.1ubuntu2) ... 317s Setting up libasound2-data (1.2.12-1) ... 317s Setting up libopencore-amrwb0:amd64 (0.1.6-1build1) ... 317s Setting up libunbound8:amd64 (1.20.0-1ubuntu2.1) ... 317s Setting up libasound2t64:amd64 (1.2.12-1) ... 317s Setting up libradcli4 (1.2.11-1build3) ... 317s Setting up libopus0:amd64 (1.5.2-2) ... 317s Setting up asterisk-config (1:22.1.1~dfsg+~cs6.14.60671435-1) ... 317s Setting up libvorbis0a:amd64 (1.3.7-2) ... 317s Setting up libical3t64:amd64 (3.0.19-3) ... 317s Setting up libjpeg-turbo8:amd64 (2.1.5-3ubuntu2) ... 317s Setting up libltdl7:amd64 (2.4.7-8) ... 317s Setting up asterisk-core-sounds-en (1.6.1-1) ... 317s update-alternatives: using /usr/share/asterisk/sounds/en_US_f_Allison to provide /usr/share/asterisk/sounds/en (asterisk-prompt-en) in auto mode 317s 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 317s Setting up libwebp7:amd64 (1.5.0-0.1) ... 317s Setting up libiksemel3:amd64 (1.4-4build2) ... 317s Setting up libodbc2:amd64 (2.3.12-1ubuntu1) ... 317s Setting up liburiparser1:amd64 (0.9.8+dfsg-2) ... 317s Setting up libspeexdsp1:amd64 (1.2.1-1ubuntu3) ... 317s Setting up liblua5.1-0:amd64 (5.1.5-10) ... 317s Setting up libopencore-amrnb0:amd64 (0.1.6-1build1) ... 317s Setting up libc-client2007e (8:2007f~dfsg-7.1) ... 317s Setting up libresample1 (0.1.3-8) ... 317s Setting up freetds-common (1.3.17+ds-2build3) ... 317s Setting up libxml2-utils (2.12.7+dfsg+really2.9.14-0.2ubuntu2) ... 317s Setting up libgmime-3.0-0t64:amd64 (3.2.15+dfsg-1) ... 317s Setting up libsamplerate0:amd64 (0.2.2-4build1) ... 317s Setting up libopusfile0:amd64 (0.12-4build3) ... 317s Setting up libvorbisenc2:amd64 (1.3.7-2) ... 317s Setting up libjpeg8:amd64 (8c-2ubuntu11) ... 317s Setting up libopusenc0:amd64 (0.2.1-2build1) ... 317s Setting up libsnmp40t64:amd64 (5.9.4+dfsg-1.1ubuntu5) ... 317s Setting up libsybdb5:amd64 (1.3.17+ds-2build3) ... 317s Setting up libvorbisfile3:amd64 (1.3.7-2) ... 317s Setting up libjack-jackd2-0:amd64 (1.9.22~dfsg-4) ... 317s Setting up libtiff6:amd64 (4.5.1+git230720-4ubuntu4) ... 317s Setting up libportaudio2:amd64 (19.6.0-1.2build3) ... 317s Setting up libspandsp2t64:amd64 (0.0.6+dfsg-2.1build1) ... 317s Setting up asterisk-modules (1:22.1.1~dfsg+~cs6.14.60671435-1) ... 317s Setting up asterisk (1:22.1.1~dfsg+~cs6.14.60671435-1) ... 317s Adding system user for Asterisk 317s info: Adding user `asterisk' to group `dialout' ... 317s info: Adding user `asterisk' to group `audio' ... 318s invoke-rc.d: policy-rc.d denied execution of start. 318s Created symlink '/etc/systemd/system/multi-user.target.wants/asterisk.service' → '/usr/lib/systemd/system/asterisk.service'. 318s /usr/sbin/policy-rc.d returned 101, not running 'start asterisk.service' 318s Setting up asterisk-tests (1:22.1.1~dfsg+~cs6.14.60671435-1) ... 318s Processing triggers for libc-bin (2.40-4ubuntu1) ... 318s Processing triggers for man-db (2.13.0-1) ... 320s 320s Running kernel seems to be up-to-date. 320s 320s Restarting services... 320s 320s Service restarts being deferred: 320s systemctl restart systemd-logind.service 320s 320s No containers need to be restarted. 320s 320s User sessions running outdated binaries: 320s ubuntu @ session #4: sshd-session[1203] 320s ubuntu @ user manager service: systemd[956] 320s 320s No VM guests are running outdated hypervisor (qemu) binaries on this host. 322s autopkgtest [08:59:21]: test asttestmods: [----------------------- 322s dpkg-architecture: warning: cannot determine CC system type, falling back to default (native compilation) 324s Asterisk has fully booted. 324s 'U' option is not compatible with remote console mode and has no effect. 324s 324s 'U' option is not compatible with remote console mode and has no effect. 324s 324s Running all available tests... 324s 324s START /apps/app_gosub/ - gosub application 324s END /apps/app_gosub/ - gosub application Time: <1ms Result: PASS 324s START /apps/app_voicemail/ - test_voicemail_vm_info 324s END /apps/app_voicemail/ - test_voicemail_vm_info Time: <1ms Result: PASS 324s START /apps/app_voicemail/ - test_voicemail_load_config 324s END /apps/app_voicemail/ - test_voicemail_load_config Time: <1ms Result: PASS 324s START /apps/app_voicemail/ - test_voicemail_notify_endl 324s END /apps/app_voicemail/ - test_voicemail_notify_endl Time: 2ms Result: PASS 324s START /apps/app_voicemail/ - vmuser 324s END /apps/app_voicemail/ - vmuser Time: <1ms Result: PASS 324s START /apps/app_voicemail/ - test_voicemail_msgcount 324s END /apps/app_voicemail/ - test_voicemail_msgcount Time: 78ms Result: PASS 324s START /apps/app_voicemail/ - vmsayname_exec 324s [app_voicemail.c:test_voicemail_vmsayname:15701]: Test playing of extension when greeting is not available... 328s [app_voicemail.c:test_voicemail_vmsayname:15722]: Test playing created mailbox greeting... 333s END /apps/app_voicemail/ - vmsayname_exec Time: 8889ms Result: PASS 333s START /ari/validators/ - validate_list 333s END /ari/validators/ - validate_list Time: <1ms Result: PASS 333s START /ari/validators/ - validate_date 333s END /ari/validators/ - validate_date Time: <1ms Result: PASS 333s START /ari/validators/ - validate_string 333s END /ari/validators/ - validate_string Time: <1ms Result: PASS 333s START /ari/validators/ - validate_long 333s END /ari/validators/ - validate_long Time: <1ms Result: PASS 333s START /ari/validators/ - validate_int 333s END /ari/validators/ - validate_int Time: <1ms Result: PASS 333s START /ari/validators/ - validate_boolean 333s END /ari/validators/ - validate_boolean Time: <1ms Result: PASS 333s START /ari/validators/ - validate_byte 333s END /ari/validators/ - validate_byte Time: <1ms Result: PASS 333s START /bridges/bridge_softmix/ - sfu_remove_destination_streams 333s END /bridges/bridge_softmix/ - sfu_remove_destination_streams Time: <1ms Result: PASS 333s START /bridges/bridge_softmix/ - sfu_append_source_streams 333s END /bridges/bridge_softmix/ - sfu_append_source_streams Time: <1ms Result: PASS 333s START /channels/features/ - test_features_channel_interval 336s END /channels/features/ - test_features_channel_interval Time: 3005ms Result: PASS 336s START /channels/features/ - test_features_channel_dtmf 338s END /channels/features/ - test_features_channel_dtmf Time: 2011ms Result: PASS 338s START /config/ - config_options_test 338s END /config/ - config_options_test Time: <1ms Result: PASS 338s START /config/ - ast_parse_arg 338s END /config/ - ast_parse_arg Time: <1ms Result: PASS 338s START /core/endpoints/ - setters 338s END /core/endpoints/ - setters Time: <1ms Result: PASS 338s START /core/endpoints/ - defaults 338s END /core/endpoints/ - defaults Time: <1ms Result: PASS 338s START /core/endpoints/ - create 338s END /core/endpoints/ - create Time: <1ms Result: PASS 338s START /funcs/func_curl/ - vulnerable_url 338s END /funcs/func_curl/ - vulnerable_url Time: <1ms Result: PASS 338s START /funcs/func_env/ - func_file 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=a'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,1)=a'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-8)=a'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-8)=a'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5,1)=b'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4,1)=b'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5,-3)=b'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4,-3)=b'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2)=c'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,2)=c'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-7)=c'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-7)=c'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,4,2)=d'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-5,2)=d'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,4,-3)=d'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-5,-3)=d'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5)=e'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,5)='... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4)=e'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-4)='... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=fg'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-8)=fg'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,1)=fg'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-9,-8)=fg'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,)=h'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,,)=h'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,l)=h'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,ld)=h'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abc'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=abc'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=abc'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=abc'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=abc'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=abc'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=abc'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=abc'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=ab'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=ab'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=ab'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=ab'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=ab'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=ab'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=ab'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=ab'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcdefg'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcdefg'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcdefg'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcdefg'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcdefg'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcdefg'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcdefg'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcdefg'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,2,l)=abcdefghijklmnop'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,2,l)=abcdefghijklmnop'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-1,l)=abcdefghijklmnop'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-1,l)=abcdefghijklmnop'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,2,l)=abcdefghijklmnop'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,,l)=abcdefghijklmnop'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,2,l)=abcdefghijklmnop'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,,l)=abcdefghijklmnop'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,0,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,0,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,0,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,0,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,2,0,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-1,0,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,3,0,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,,,la)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)='... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,l)='... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,l)='... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,l)='... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,l)='... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,l)='... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,l)='... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,l)='... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,ld)='... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,1,ld)='... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,-2,ld)='... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-3,-2,ld)='... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,1,ld)='... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,1,-1,ld)='... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,1,ld)='... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,-2,-1,ld)='... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=a'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,10)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=abcd'... OK! 338s [test_func_file.c:test_func_file:375]: Expression 'FILE(...,0,1,l)=a'... OK! 338s END /funcs/func_env/ - func_file Time: 9ms Result: PASS 338s START /funcs/func_json/ - func_JSON_DECODE 338s END /funcs/func_json/ - func_JSON_DECODE Time: <1ms Result: PASS 338s START /funcs/func_presence/ - test_presence_state_base64_encode 338s END /funcs/func_presence/ - test_presence_state_base64_encode Time: 7ms Result: PASS 338s START /funcs/func_presence/ - test_presence_state_change 338s END /funcs/func_presence/ - test_presence_state_change Time: <1ms Result: PASS 338s START /funcs/func_presence/ - parse_invalid_presence_data 338s END /funcs/func_presence/ - parse_invalid_presence_data Time: <1ms Result: PASS 338s START /funcs/func_presence/ - parse_valid_presence_data 338s END /funcs/func_presence/ - parse_valid_presence_data Time: <1ms Result: PASS 338s START /funcs/func_sayfiles/ - test_SAYFILES_function 338s [func_sayfiles.c:test_SAYFILES_function:180]: Testing SAYFILES() substitution ... 338s END /funcs/func_sayfiles/ - test_SAYFILES_function Time: 8ms Result: PASS 338s START /funcs/func_strings/ - func_TRIM 338s END /funcs/func_strings/ - func_TRIM Time: <1ms Result: PASS 338s START /funcs/func_strings/ - func_STRBETWEEN 338s END /funcs/func_strings/ - func_STRBETWEEN Time: <1ms Result: PASS 338s START /funcs/func_strings/ - func_STRREPLACE_test 338s END /funcs/func_strings/ - func_STRREPLACE_test Time: <1ms Result: PASS 338s START /funcs/func_strings/ - func_FILTER_test 338s END /funcs/func_strings/ - func_FILTER_test Time: <1ms Result: PASS 338s START /funcs/func_strings/ - func_REPLACE_test 338s END /funcs/func_strings/ - func_REPLACE_test Time: <1ms Result: PASS 338s START /funcs/func_strings/ - func_FIELDNUM_test 338s END /funcs/func_strings/ - func_FIELDNUM_test Time: <1ms Result: PASS 338s START /geoloc/ - create_from_pidf 338s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1274]: ID: 'point-2d' pidf_element: 'tuple' format: 'GML' method: 'Manual' 338s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1286]: location_vars expected: shape=Point,crs=2d,pos=-34.410649 150.87651 338s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1287]: location_vars received: shape=Point,crs=2d,pos=-34.410649 150.87651 338s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1293]: usage_rules expected: retransmission-allowed='no',retention-expiry='2010-11-14T20:00:00Z' 338s [res_geolocation/geoloc_eprofile.c:validate_eprofile:1294]: usage_rules received: retransmission-allowed='no',retention-expiry='2010-11-14T20:00:00Z' 338s END /geoloc/ - create_from_pidf Time: 1ms Result: PASS 338s START /geoloc/ - create_from_uri 338s END /geoloc/ - create_from_uri Time: <1ms Result: PASS 338s START /main/abstract_jb/ - AST_JB_FIXED_put_out_of_order 338s [test_abstract_jb.c:AST_JB_FIXED_put_out_of_order:531]: Executing AST_JB_FIXED_put_out_of_order... 338s END /main/abstract_jb/ - AST_JB_FIXED_put_out_of_order Time: <1ms Result: PASS 338s START /main/abstract_jb/ - AST_JB_FIXED_put_overflow 338s [test_abstract_jb.c:AST_JB_FIXED_put_overflow:529]: Executing AST_JB_FIXED_put_overflow... 338s END /main/abstract_jb/ - AST_JB_FIXED_put_overflow Time: <1ms Result: PASS 338s START /main/abstract_jb/ - AST_JB_FIXED_put 338s [test_abstract_jb.c:AST_JB_FIXED_put:527]: Executing AST_JB_FIXED_put... 338s END /main/abstract_jb/ - AST_JB_FIXED_put Time: <1ms Result: PASS 338s START /main/abstract_jb/ - AST_JB_FIXED_put_first 338s [test_abstract_jb.c:AST_JB_FIXED_put_first:525]: Executing AST_JB_FIXED_create... 338s END /main/abstract_jb/ - AST_JB_FIXED_put_first Time: <1ms Result: PASS 338s START /main/abstract_jb/ - AST_JB_FIXED_create 338s [test_abstract_jb.c:AST_JB_FIXED_create:523]: Executing AST_JB_FIXED_create... 338s END /main/abstract_jb/ - AST_JB_FIXED_create Time: <1ms Result: PASS 338s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_out_of_order 338s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_out_of_order:521]: Executing AST_JB_ADAPTIVE_put_out_of_order... 338s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_out_of_order Time: <1ms Result: PASS 338s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_overflow 338s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_overflow:519]: Executing AST_JB_ADAPTIVE_put_overflow... 338s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_overflow Time: <1ms Result: PASS 338s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put 338s [test_abstract_jb.c:AST_JB_ADAPTIVE_put:517]: Executing AST_JB_ADAPTIVE_put... 338s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put Time: <1ms Result: PASS 338s START /main/abstract_jb/ - AST_JB_ADAPTIVE_put_first 338s [test_abstract_jb.c:AST_JB_ADAPTIVE_put_first:515]: Executing AST_JB_ADAPTIVE_create... 338s END /main/abstract_jb/ - AST_JB_ADAPTIVE_put_first Time: <1ms Result: PASS 338s START /main/abstract_jb/ - AST_JB_ADAPTIVE_create 338s [test_abstract_jb.c:AST_JB_ADAPTIVE_create:513]: Executing AST_JB_ADAPTIVE_create... 338s END /main/abstract_jb/ - AST_JB_ADAPTIVE_create Time: <1ms Result: PASS 338s START /main/acl/ - acl 338s END /main/acl/ - acl Time: <1ms Result: PASS 338s START /main/acl/ - invalid_acl 338s END /main/acl/ - invalid_acl Time: <1ms Result: PASS 338s START /main/amihooks/ - amihook_cli_send 338s END /main/amihooks/ - amihook_cli_send Time: 1ms Result: PASS 338s START /main/aoc/ - aoc_event_test 338s END /main/aoc/ - aoc_event_test Time: <1ms Result: PASS 338s START /main/aoc/ - aoc_encode_decode_test 338s END /main/aoc/ - aoc_encode_decode_test Time: <1ms Result: PASS 338s START /main/app/ - options_parsing 338s END /main/app/ - options_parsing Time: <1ms Result: PASS 338s START /main/app/ - app_group 338s [test_app.c:app_group:172]: Creating test channels with the following groups: 338s 'a groupgroupgroup', 'a groupGroupgroup', 'a group@a_category', 'a group@another!Category' 338s [test_app.c:app_group:211]: (Subtest 1) Found 4 matches as expected when examining group:'gr' category:'' 338s [test_app.c:app_group:211]: (Subtest 2) Found 1 matches as expected when examining group:'(group){2}$' category:'' 338s [test_app.c:app_group:211]: (Subtest 3) Found 4 matches as expected when examining group:'[:ascii:]' category:'' 338s [test_app.c:app_group:211]: (Subtest 4) Found 0 matches as expected when examining group:'^(NOMATCH)' category:'' 338s [test_app.c:app_group:211]: (Subtest 5) Found 2 matches as expected when examining group:'a group' category:'(gory)$' 338s [test_app.c:app_group:211]: (Subtest 6) Found 1 matches as expected when examining group:'a group' category:'[A-Z]+' 338s [test_app.c:app_group:211]: (Subtest 7) Found 0 matches as expected when examining group:'a group' category:'[[' 338s END /main/app/ - app_group Time: <1ms Result: PASS 338s START /main/ast_expr/ - expr_test 338s END /main/ast_expr/ - expr_test Time: <1ms Result: PASS 338s START /main/astdb/ - put_get_long 338s END /main/astdb/ - put_get_long Time: 76ms Result: PASS 338s START /main/astdb/ - perftest 338s END /main/astdb/ - perftest Time: 199ms Result: PASS 338s START /main/astdb/ - gettree_deltree 338s END /main/astdb/ - gettree_deltree Time: <1ms Result: PASS 338s START /main/astdb/ - put_get_del 338s END /main/astdb/ - put_get_del Time: <1ms Result: PASS 338s START /main/astobj2/ - thrash 338s [test_astobj2_thrash.c:hash_test:266]: Executing hash concurrency test... 338s END /main/astobj2/ - thrash Time: 23ms Result: PASS 338s START /main/astobj2/ - astobj2_test4 338s [test_astobj2.c:test_traversal_nonsorted:1389]: Test 1, List containers. 338s [test_astobj2.c:test_traversal_nonsorted:1389]: Test 2, Hash containers. 338s [test_astobj2.c:test_traversal_sorted:1615]: Test 3, List containers. 338s [test_astobj2.c:test_traversal_sorted:1615]: Test 4, Hash containers. 338s [test_astobj2.c:test_traversal_sorted:1615]: Test 5, RBTree containers. 338s END /main/astobj2/ - astobj2_test4 Time: <1ms Result: PASS 338s START /main/astobj2/ - astobj2_test3 338s END /main/astobj2/ - astobj2_test3 Time: <1ms Result: PASS 338s START /main/astobj2/ - astobj2_test2 338s END /main/astobj2/ - astobj2_test2 Time: <1ms Result: PASS 338s START /main/astobj2/ - astobj2_test1 338s [test_astobj2.c:astobj2_test_1_helper:434]: Test 1, List containers (non-sorted). 338s [test_astobj2.c:astobj2_test_1_helper:488]: List container created: buckets: 1, items: 50 338s [test_astobj2.c:astobj2_test_1_helper:434]: Test 2, List containers (sorted). 338s [test_astobj2.c:astobj2_test_1_helper:488]: List container created: buckets: 1, items: 50 338s [test_astobj2.c:astobj2_test_1_helper:434]: Test 3, Hash containers (non-sorted). 338s [test_astobj2.c:astobj2_test_1_helper:488]: Hash container created: buckets: 37, items: 1000 338s [test_astobj2.c:astobj2_test_1_helper:434]: Test 4, Hash containers (sorted). 338s [test_astobj2.c:astobj2_test_1_helper:488]: Hash container created: buckets: 68, items: 1000 338s [test_astobj2.c:astobj2_test_1_helper:434]: Test 4, RBTree containers (sorted). 338s [test_astobj2.c:astobj2_test_1_helper:488]: RBTree container created: buckets: 1, items: 1000 338s END /main/astobj2/ - astobj2_test1 Time: 6ms Result: PASS 338s START /main/astobj2/ - astobj2_weak_container 338s END /main/astobj2/ - astobj2_weak_container Time: <1ms Result: PASS 338s START /main/astobj2/ - astobj2_weak1 338s END /main/astobj2/ - astobj2_weak1 Time: <1ms Result: PASS 338s START /main/astobj2/perf/ - astobj2_test_perf 339s [test_astobj2.c:testloop:2001]: 20.00K traversals, List 339s [test_astobj2.c:testloop:2001]: 40.00K traversals, List 340s [test_astobj2.c:testloop:2001]: 60.00K traversals, List 340s [test_astobj2.c:testloop:2001]: 80.00K traversals, List 341s [test_astobj2.c:testloop:2006]: 100.00K traversals, List : 2968 ms 341s [test_astobj2.c:testloop:2001]: 20.00K traversals, Hash 342s [test_astobj2.c:testloop:2001]: 40.00K traversals, Hash 342s [test_astobj2.c:testloop:2001]: 60.00K traversals, Hash 342s [test_astobj2.c:testloop:2001]: 80.00K traversals, Hash 342s [test_astobj2.c:testloop:2006]: 100.00K traversals, Hash : 1400 ms 343s [test_astobj2.c:testloop:2001]: 20.00K traversals, RBTree 343s [test_astobj2.c:testloop:2001]: 40.00K traversals, RBTree 343s [test_astobj2.c:testloop:2001]: 60.00K traversals, RBTree 344s [test_astobj2.c:testloop:2001]: 80.00K traversals, RBTree 344s [test_astobj2.c:testloop:2006]: 100.00K traversals, RBTree : 1722 ms 344s END /main/astobj2/perf/ - astobj2_test_perf Time: 6092ms Result: PASS 344s START /main/bridging/ - test_bridging_deferred_queue 345s END /main/bridging/ - test_bridging_deferred_queue Time: 1015ms Result: PASS 345s START /main/bucket/ - bucket_file_json 345s END /main/bucket/ - bucket_file_json Time: 1ms Result: PASS 345s START /main/bucket/ - bucket_file_metadata_get 345s END /main/bucket/ - bucket_file_metadata_get Time: <1ms Result: PASS 345s START /main/bucket/ - bucket_file_metadata_unset 345s END /main/bucket/ - bucket_file_metadata_unset Time: <1ms Result: PASS 345s START /main/bucket/ - bucket_file_metadata_set 345s END /main/bucket/ - bucket_file_metadata_set Time: <1ms Result: PASS 345s START /main/bucket/ - bucket_file_is_stale 345s END /main/bucket/ - bucket_file_is_stale Time: <1ms Result: PASS 345s START /main/bucket/ - bucket_file_delete 345s END /main/bucket/ - bucket_file_delete Time: <1ms Result: PASS 345s START /main/bucket/ - bucket_file_update 345s END /main/bucket/ - bucket_file_update Time: <1ms Result: PASS 345s START /main/bucket/ - bucket_file_retrieve 345s END /main/bucket/ - bucket_file_retrieve Time: <1ms Result: PASS 345s START /main/bucket/ - bucket_file_copy 345s END /main/bucket/ - bucket_file_copy Time: <1ms Result: PASS 345s START /main/bucket/ - bucket_file_clone 345s END /main/bucket/ - bucket_file_clone Time: <1ms Result: PASS 345s START /main/bucket/ - bucket_file_create 345s END /main/bucket/ - bucket_file_create Time: <1ms Result: PASS 345s START /main/bucket/ - bucket_file_alloc 345s END /main/bucket/ - bucket_file_alloc Time: <1ms Result: PASS 345s START /main/bucket/ - bucket_json 345s END /main/bucket/ - bucket_json Time: <1ms Result: PASS 345s START /main/bucket/ - bucket_is_stale 345s END /main/bucket/ - bucket_is_stale Time: <1ms Result: PASS 345s START /main/bucket/ - bucket_retrieve 345s END /main/bucket/ - bucket_retrieve Time: <1ms Result: PASS 345s START /main/bucket/ - bucket_delete 345s END /main/bucket/ - bucket_delete Time: <1ms Result: PASS 345s START /main/bucket/ - bucket_clone 345s END /main/bucket/ - bucket_clone Time: <1ms Result: PASS 345s START /main/bucket/ - bucket_create 345s END /main/bucket/ - bucket_create Time: <1ms Result: PASS 345s START /main/bucket/ - bucket_alloc 345s END /main/bucket/ - bucket_alloc Time: <1ms Result: PASS 345s START /main/bucket/ - bucket_scheme_register_unregister 345s END /main/bucket/ - bucket_scheme_register_unregister Time: <1ms Result: PASS 345s START /main/callerid/ - parse_off_nominal 345s END /main/callerid/ - parse_off_nominal Time: <1ms Result: PASS 345s START /main/callerid/ - parse_nominal 345s END /main/callerid/ - parse_nominal Time: <1ms Result: PASS 345s START /main/cdr/ - test_cdr_fork_cdr 347s Verifying expected record CDRTestChannel/Alice, 347s Finished expected record CDRTestChannel/Alice, 347s Verifying expected record CDRTestChannel/Alice, 347s Finished expected record CDRTestChannel/Alice, 347s Verifying expected record CDRTestChannel/Alice, 347s Finished expected record CDRTestChannel/Alice, 347s END /main/cdr/ - test_cdr_fork_cdr Time: 2000ms Result: PASS 347s START /main/cdr/ - test_cdr_no_reset_cdr 348s Verifying expected record CDRTestChannel/Alice, 348s Finished expected record CDRTestChannel/Alice, 348s END /main/cdr/ - test_cdr_no_reset_cdr Time: 1000ms Result: PASS 348s START /main/cdr/ - test_cdr_fields 350s Verifying expected record CDRTestChannel/Alice, 350s Finished expected record CDRTestChannel/Alice, 350s Verifying expected record CDRTestChannel/Alice, 350s Finished expected record CDRTestChannel/Alice, 350s Verifying expected record CDRTestChannel/Alice, 350s Finished expected record CDRTestChannel/Alice, 350s END /main/cdr/ - test_cdr_fields Time: 2000ms Result: PASS 350s START /main/cdr/ - test_cdr_park 353s Verifying expected record CDRTestChannel/Alice, 353s Finished expected record CDRTestChannel/Alice, 353s Verifying expected record CDRTestChannel/Bob, 353s Finished expected record CDRTestChannel/Bob, 353s END /main/cdr/ - test_cdr_park Time: 3001ms Result: PASS 353s START /main/cdr/ - test_cdr_dial_answer_multiparty 358s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 358s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 358s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 358s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 358s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/David 358s Finished expected record CDRTestChannel/Alice, CDRTestChannel/David 358s Verifying expected record CDRTestChannel/Bob, CDRTestChannel/David 358s Finished expected record CDRTestChannel/Bob, CDRTestChannel/David 358s Verifying expected record CDRTestChannel/Charlie, CDRTestChannel/David 358s Finished expected record CDRTestChannel/Charlie, CDRTestChannel/David 358s Verifying expected record CDRTestChannel/Charlie, CDRTestChannel/Bob 358s Finished expected record CDRTestChannel/Charlie, CDRTestChannel/Bob 358s END /main/cdr/ - test_cdr_dial_answer_multiparty Time: 5003ms Result: PASS 358s START /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_b 361s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 361s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 361s END /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_b Time: 3001ms Result: PASS 361s START /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_a 363s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 363s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 363s END /main/cdr/ - test_cdr_dial_answer_twoparty_bridge_a Time: 2002ms Result: PASS 363s START /main/cdr/ - test_cdr_dial_answer_no_bridge 363s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 363s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 363s Verifying expected record CDRTestChannel/Alice, 363s Finished expected record CDRTestChannel/Alice, 363s Verifying expected record CDRTestChannel/Bob, 363s Finished expected record CDRTestChannel/Bob, 363s END /main/cdr/ - test_cdr_dial_answer_no_bridge Time: <1ms Result: PASS 363s START /main/cdr/ - test_cdr_dial_parallel_failed 363s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 363s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 363s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 363s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 363s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/David 363s Finished expected record CDRTestChannel/Alice, CDRTestChannel/David 363s END /main/cdr/ - test_cdr_dial_parallel_failed Time: <1ms Result: PASS 363s START /main/cdr/ - test_cdr_dial_caller_cancel 363s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 363s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 363s END /main/cdr/ - test_cdr_dial_caller_cancel Time: <1ms Result: PASS 363s START /main/cdr/ - test_cdr_dial_unavailable 363s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 363s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 363s END /main/cdr/ - test_cdr_dial_unavailable Time: <1ms Result: PASS 363s START /main/cdr/ - test_cdr_dial_busy 363s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 363s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 363s END /main/cdr/ - test_cdr_dial_busy Time: <1ms Result: PASS 363s START /main/cdr/ - test_cdr_dial_congestion 363s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 363s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 363s END /main/cdr/ - test_cdr_dial_congestion Time: <1ms Result: PASS 363s START /main/cdr/ - test_cdr_dial_unanswered 363s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 363s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 363s END /main/cdr/ - test_cdr_dial_unanswered Time: <1ms Result: PASS 363s START /main/cdr/ - test_cdr_outbound_bridged_call 366s Verifying expected record CDRTestChannel/Bob, 366s Finished expected record CDRTestChannel/Bob, 366s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 366s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 366s END /main/cdr/ - test_cdr_outbound_bridged_call Time: 3001ms Result: PASS 366s START /main/cdr/ - test_cdr_single_multiparty_bridge 370s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 370s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 370s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 370s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Charlie 370s Verifying expected record CDRTestChannel/Bob, CDRTestChannel/Charlie 370s Finished expected record CDRTestChannel/Bob, CDRTestChannel/Charlie 370s Verifying expected record CDRTestChannel/Charlie, 370s Finished expected record CDRTestChannel/Charlie, 370s END /main/cdr/ - test_cdr_single_multiparty_bridge Time: 4002ms Result: PASS 370s START /main/cdr/ - test_cdr_single_twoparty_bridge_b 373s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 373s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 373s Verifying expected record CDRTestChannel/Bob, 373s Finished expected record CDRTestChannel/Bob, 373s END /main/cdr/ - test_cdr_single_twoparty_bridge_b Time: 3001ms Result: PASS 373s START /main/cdr/ - test_cdr_single_twoparty_bridge_a 375s Verifying expected record CDRTestChannel/Alice, CDRTestChannel/Bob 375s Finished expected record CDRTestChannel/Alice, CDRTestChannel/Bob 375s Verifying expected record CDRTestChannel/Bob, 375s Finished expected record CDRTestChannel/Bob, 375s END /main/cdr/ - test_cdr_single_twoparty_bridge_a Time: 2002ms Result: PASS 375s START /main/cdr/ - test_cdr_single_bridge_continue 377s Verifying expected record CDRTestChannel/Alice, 377s Finished expected record CDRTestChannel/Alice, 377s Verifying expected record CDRTestChannel/Alice, 377s Finished expected record CDRTestChannel/Alice, 377s END /main/cdr/ - test_cdr_single_bridge_continue Time: 2000ms Result: PASS 377s START /main/cdr/ - test_cdr_single_bridge 379s Verifying expected record CDRTestChannel/Alice, 379s Finished expected record CDRTestChannel/Alice, 379s END /main/cdr/ - test_cdr_single_bridge Time: 2001ms Result: PASS 379s START /main/cdr/ - test_cdr_single_party 379s Verifying expected record CDRTestChannel/Alice, 379s Finished expected record CDRTestChannel/Alice, 379s END /main/cdr/ - test_cdr_single_party Time: <1ms Result: PASS 379s START /main/cdr/ - test_cdr_unanswered_outbound_call 379s Verifying expected record CDRTestChannel/Alice, 379s Finished expected record CDRTestChannel/Alice, 379s END /main/cdr/ - test_cdr_unanswered_outbound_call Time: <1ms Result: PASS 379s START /main/cdr/ - test_cdr_unanswered_inbound_call 379s Verifying expected record CDRTestChannel/Alice, 379s Finished expected record CDRTestChannel/Alice, 379s END /main/cdr/ - test_cdr_unanswered_inbound_call Time: <1ms Result: PASS 379s START /main/cdr/ - test_cdr_channel_creation 379s Verifying expected record CDRTestChannel/Alice, 379s Finished expected record CDRTestChannel/Alice, 379s END /main/cdr/ - test_cdr_channel_creation Time: <1ms Result: PASS 379s START /main/channel/ - add_fd 379s END /main/channel/ - add_fd Time: <1ms Result: PASS 379s START /main/channel/ - set_fd_grow 379s END /main/channel/ - set_fd_grow Time: <1ms Result: PASS 379s START /main/config/ - variable_list_from_quoted_string 379s END /main/config/ - variable_list_from_quoted_string Time: <1ms Result: PASS 379s START /main/config/ - variable_list_join_replace 379s END /main/config/ - variable_list_join_replace Time: <1ms Result: PASS 379s START /main/config/ - variable_lists_match 379s END /main/config/ - variable_lists_match Time: <1ms Result: PASS 379s START /main/config/ - config_dialplan_function 379s END /main/config/ - config_dialplan_function Time: <1ms Result: PASS 379s START /main/config/ - config_hook 379s END /main/config/ - config_hook Time: <1ms Result: PASS 379s START /main/config/ - copy_config 379s END /main/config/ - copy_config Time: <1ms Result: PASS 379s START /main/config/ - config_template_ops 379s END /main/config/ - config_template_ops Time: <1ms Result: PASS 379s START /main/config/ - config_filtered_ops 379s END /main/config/ - config_filtered_ops Time: <1ms Result: PASS 379s START /main/config/ - config_basic_ops 379s END /main/config/ - config_basic_ops Time: <1ms Result: PASS 379s START /main/config/ - config_save 379s END /main/config/ - config_save Time: <1ms Result: PASS 379s START /main/conversions/ - str_to_umax 379s END /main/conversions/ - str_to_umax Time: <1ms Result: PASS 379s START /main/conversions/ - str_to_imax 379s END /main/conversions/ - str_to_imax Time: <1ms Result: PASS 379s START /main/conversions/ - str_to_ulong 379s END /main/conversions/ - str_to_ulong Time: <1ms Result: PASS 379s START /main/conversions/ - str_to_long 379s END /main/conversions/ - str_to_long Time: <1ms Result: PASS 379s START /main/conversions/ - str_to_uint 379s END /main/conversions/ - str_to_uint Time: <1ms Result: PASS 379s START /main/conversions/ - str_to_int 379s END /main/conversions/ - str_to_int Time: <1ms Result: PASS 379s START /main/core_codec/ - codec_get_unknown 379s END /main/core_codec/ - codec_get_unknown Time: <1ms Result: PASS 379s START /main/core_codec/ - codec_get_unknown 379s END /main/core_codec/ - codec_get_unknown Time: <1ms Result: PASS 379s START /main/core_codec/ - codec_get_unregistered 379s END /main/core_codec/ - codec_get_unregistered Time: <1ms Result: PASS 379s START /main/core_codec/ - codec_get 379s END /main/core_codec/ - codec_get Time: <1ms Result: PASS 379s START /main/core_codec/ - codec_register_audio_no_sample_rate 379s END /main/core_codec/ - codec_register_audio_no_sample_rate Time: <1ms Result: PASS 379s START /main/core_codec/ - codec_register_unknown 379s END /main/core_codec/ - codec_register_unknown Time: <1ms Result: PASS 379s START /main/core_codec/ - codec_register_twice 379s END /main/core_codec/ - codec_register_twice Time: <1ms Result: PASS 379s START /main/core_codec/ - codec_register 379s END /main/core_codec/ - codec_register Time: <1ms Result: PASS 379s START /main/core_format/ - format_parse_and_generate_sdp_fmtp 379s END /main/core_format/ - format_parse_and_generate_sdp_fmtp Time: <1ms Result: PASS 379s START /main/core_format/ - format_parse_sdp_fmtp_without_interface 379s END /main/core_format/ - format_parse_sdp_fmtp_without_interface Time: <1ms Result: PASS 379s START /main/core_format/ - format_attribute_get_without_interface 379s END /main/core_format/ - format_attribute_get_without_interface Time: <1ms Result: PASS 379s START /main/core_format/ - format_attribute_set_without_interface 379s END /main/core_format/ - format_attribute_set_without_interface Time: <1ms Result: PASS 379s START /main/core_format/ - format_copy 379s END /main/core_format/ - format_copy Time: <1ms Result: PASS 379s START /main/core_format/ - format_joint_different_codec 379s END /main/core_format/ - format_joint_different_codec Time: <1ms Result: PASS 379s START /main/core_format/ - format_attr_joint_same_codec 379s END /main/core_format/ - format_attr_joint_same_codec Time: <1ms Result: PASS 379s START /main/core_format/ - format_joint_same_codec 379s END /main/core_format/ - format_joint_same_codec Time: <1ms Result: PASS 379s START /main/core_format/ - format_cmp_different_codec 379s END /main/core_format/ - format_cmp_different_codec Time: <1ms Result: PASS 379s START /main/core_format/ - format_attr_cmp_same_codec 379s END /main/core_format/ - format_attr_cmp_same_codec Time: <1ms Result: PASS 379s START /main/core_format/ - format_cmp_same_codec 379s END /main/core_format/ - format_cmp_same_codec Time: <1ms Result: PASS 379s START /main/core_format/ - format_clone 379s END /main/core_format/ - format_clone Time: <1ms Result: PASS 379s START /main/core_format/ - format_retrieve_attr 379s END /main/core_format/ - format_retrieve_attr Time: <1ms Result: PASS 379s START /main/core_format/ - format_create_attr 379s END /main/core_format/ - format_create_attr Time: <1ms Result: PASS 379s START /main/core_format/ - format_create 379s END /main/core_format/ - format_create Time: <1ms Result: PASS 379s START /main/data_buffer/ - buffer_nominal 379s END /main/data_buffer/ - buffer_nominal Time: <1ms Result: PASS 379s START /main/data_buffer/ - buffer_resize 379s END /main/data_buffer/ - buffer_resize Time: <1ms Result: PASS 379s START /main/data_buffer/ - buffer_put 379s END /main/data_buffer/ - buffer_put Time: <1ms Result: PASS 379s START /main/data_buffer/ - buffer_create 379s END /main/data_buffer/ - buffer_create Time: <1ms Result: PASS 379s START /main/devicestate/ - devstate_channels 379s END /main/devicestate/ - devstate_channels Time: <1ms Result: PASS 379s START /main/devicestate/ - devstate_conversions 379s END /main/devicestate/ - devstate_conversions Time: <1ms Result: PASS 379s START /main/devicestate/ - devstate_changed 379s [test_devicestate.c:wait_for_device_state_updates:308]: Received 8 of 8 updates 379s [test_devicestate.c:devstate_changed:716]: Testing update 0: actual is 1; expected is 1 379s [test_devicestate.c:devstate_changed:716]: Testing update 1: actual is 2; expected is 2 379s [test_devicestate.c:devstate_changed:716]: Testing update 2: actual is 3; expected is 3 379s [test_devicestate.c:devstate_changed:716]: Testing update 3: actual is 4; expected is 4 379s [test_devicestate.c:devstate_changed:716]: Testing update 4: actual is 5; expected is 5 379s [test_devicestate.c:devstate_changed:716]: Testing update 5: actual is 6; expected is 6 379s [test_devicestate.c:devstate_changed:716]: Testing update 6: actual is 7; expected is 7 379s [test_devicestate.c:devstate_changed:716]: Testing update 7: actual is 8; expected is 8 379s [test_devicestate.c:wait_for_device_state_updates:308]: Received 1 of 1 updates 379s [test_devicestate.c:wait_for_device_state_updates:308]: Received 8 of 8 updates 379s [test_devicestate.c:devstate_changed:754]: Testing update 0: actual is 1; expected is 1 379s [test_devicestate.c:devstate_changed:754]: Testing update 1: actual is 2; expected is 2 379s [test_devicestate.c:devstate_changed:754]: Testing update 2: actual is 3; expected is 3 379s [test_devicestate.c:devstate_changed:754]: Testing update 3: actual is 4; expected is 4 379s [test_devicestate.c:devstate_changed:754]: Testing update 4: actual is 5; expected is 5 379s [test_devicestate.c:devstate_changed:754]: Testing update 5: actual is 6; expected is 6 379s [test_devicestate.c:devstate_changed:754]: Testing update 6: actual is 7; expected is 7 379s [test_devicestate.c:devstate_changed:754]: Testing update 7: actual is 8; expected is 8 379s END /main/devicestate/ - devstate_changed Time: <1ms Result: PASS 379s START /main/devicestate/ - devstate_prov_del 379s END /main/devicestate/ - devstate_prov_del Time: <1ms Result: PASS 379s START /main/devicestate/ - devstate_prov_add 379s END /main/devicestate/ - devstate_prov_add Time: <1ms Result: PASS 379s START /main/devicestate/ - device2extenstate_test 379s END /main/devicestate/ - device2extenstate_test Time: <1ms Result: PASS 379s START /main/devicestate/ - device_state_aggregation_test 379s END /main/devicestate/ - device_state_aggregation_test Time: <1ms Result: PASS 379s START /main/dns/ - resolver_resolve_async_cancel 379s END /main/dns/ - resolver_resolve_async_cancel Time: <1ms Result: PASS 379s START /main/dns/ - resolver_resolve_async_off_nominal 379s END /main/dns/ - resolver_resolve_async_off_nominal Time: <1ms Result: PASS 379s START /main/dns/ - resolver_resolve_async 384s END /main/dns/ - resolver_resolve_async Time: 5000ms Result: PASS 384s START /main/dns/ - resolver_resolve_sync_off_nominal 384s END /main/dns/ - resolver_resolve_sync_off_nominal Time: <1ms Result: PASS 384s START /main/dns/ - resolver_resolve_sync 389s END /main/dns/ - resolver_resolve_sync Time: 5000ms Result: PASS 389s START /main/dns/ - resolver_add_record_off_nominal 389s END /main/dns/ - resolver_add_record_off_nominal Time: <1ms Result: PASS 389s START /main/dns/ - resolver_add_record 389s END /main/dns/ - resolver_add_record Time: <1ms Result: PASS 389s START /main/dns/ - resolver_set_result_off_nominal 389s END /main/dns/ - resolver_set_result_off_nominal Time: <1ms Result: PASS 389s START /main/dns/ - resolver_set_result 389s END /main/dns/ - resolver_set_result Time: <1ms Result: PASS 389s START /main/dns/ - resolver_data 389s END /main/dns/ - resolver_data Time: <1ms Result: PASS 389s START /main/dns/ - resolver_unregister_off_nominal 389s END /main/dns/ - resolver_unregister_off_nominal Time: <1ms Result: PASS 389s START /main/dns/ - resolver_register_off_nominal 389s END /main/dns/ - resolver_register_off_nominal Time: <1ms Result: PASS 389s START /main/dns/ - resolver_register_unregister 389s END /main/dns/ - resolver_register_unregister Time: <1ms Result: PASS 389s START /main/dns/naptr/ - naptr_resolve_off_nominal_interactions 389s END /main/dns/naptr/ - naptr_resolve_off_nominal_interactions Time: <1ms Result: PASS 389s START /main/dns/naptr/ - naptr_resolve_off_nominal_regexp 389s END /main/dns/naptr/ - naptr_resolve_off_nominal_regexp Time: <1ms Result: PASS 389s START /main/dns/naptr/ - naptr_resolve_off_nominal_services 389s END /main/dns/naptr/ - naptr_resolve_off_nominal_services Time: <1ms Result: PASS 389s START /main/dns/naptr/ - naptr_resolve_off_nominal_flags 389s END /main/dns/naptr/ - naptr_resolve_off_nominal_flags Time: <1ms Result: PASS 389s START /main/dns/naptr/ - naptr_resolve_off_nominal_length 389s END /main/dns/naptr/ - naptr_resolve_off_nominal_length Time: <1ms Result: PASS 389s START /main/dns/naptr/ - naptr_resolve 389s END /main/dns/naptr/ - naptr_resolve Time: <1ms Result: PASS 389s START /main/dns/query_set/ - query_set_off_nominal_cancel 389s END /main/dns/query_set/ - query_set_off_nominal_cancel Time: <1ms Result: PASS 389s START /main/dns/query_set/ - query_set_nominal_cancel 389s END /main/dns/query_set/ - query_set_nominal_cancel Time: <1ms Result: PASS 389s START /main/dns/query_set/ - query_set_empty 389s END /main/dns/query_set/ - query_set_empty Time: <1ms Result: PASS 389s START /main/dns/query_set/ - query_set 389s END /main/dns/query_set/ - query_set Time: <1ms Result: PASS 389s START /main/dns/recurring/ - recurring_query_cancel_during 389s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 396s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 406s END /main/dns/recurring/ - recurring_query_cancel_during Time: 16999ms Result: PASS 406s START /main/dns/recurring/ - recurring_query_cancel_between 406s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 416s END /main/dns/recurring/ - recurring_query_cancel_between Time: 10000ms Result: PASS 416s START /main/dns/recurring/ - recurring_query_off_nominal 416s END /main/dns/recurring/ - recurring_query_off_nominal Time: <1ms Result: PASS 416s START /main/dns/recurring/ - recurring_query 416s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 423s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 435s [test_dns_recurring.c:wait_for_resolution:252]: Query completed in expected time frame 435s END /main/dns/recurring/ - recurring_query Time: 19000ms Result: PASS 435s START /main/dns/srv/ - srv_resolve_record_missing_host 435s END /main/dns/srv/ - srv_resolve_record_missing_host Time: <1ms Result: PASS 435s START /main/dns/srv/ - srv_resolve_record_missing_port_host 435s END /main/dns/srv/ - srv_resolve_record_missing_port_host Time: <1ms Result: PASS 435s START /main/dns/srv/ - srv_resolve_record_missing_weight_port_host 435s END /main/dns/srv/ - srv_resolve_record_missing_weight_port_host Time: <1ms Result: PASS 435s START /main/dns/srv/ - srv_resolve_different_priorities_different_weights 435s END /main/dns/srv/ - srv_resolve_different_priorities_different_weights Time: 5ms Result: PASS 435s START /main/dns/srv/ - srv_resolve_same_priority_different_weights 435s END /main/dns/srv/ - srv_resolve_same_priority_different_weights Time: 5ms Result: PASS 435s START /main/dns/srv/ - srv_resolve_same_priority_zero_weight 435s END /main/dns/srv/ - srv_resolve_same_priority_zero_weight Time: <1ms Result: PASS 435s START /main/dns/srv/ - srv_resolve_sort_priority 435s END /main/dns/srv/ - srv_resolve_sort_priority Time: <1ms Result: PASS 435s START /main/dns/srv/ - srv_resolve_single_record 435s END /main/dns/srv/ - srv_resolve_single_record Time: <1ms Result: PASS 435s START /main/dsp/ - dtmf 435s END /main/dsp/ - dtmf Time: 3ms Result: PASS 435s START /main/dsp/ - fax 436s END /main/dsp/ - fax Time: 350ms Result: PASS 436s START /main/event/ - ast_event_new_test 436s [test_event.c:event_new_test:125]: First, test dynamic event creation... 436s [test_event.c:check_event:88]: Event looks good. 436s [test_event.c:check_event:88]: Event looks good. 436s END /main/event/ - ast_event_new_test Time: <1ms Result: PASS 436s START /main/file/ - read_dir_test 436s END /main/file/ - read_dir_test Time: <1ms Result: PASS 436s START /main/file/ - ast_format_str_reduce_test_1 436s END /main/file/ - ast_format_str_reduce_test_1 Time: <1ms Result: PASS 436s START /main/format_cache/ - format_cache_get_nonxistent 436s END /main/format_cache/ - format_cache_get_nonxistent Time: <1ms Result: PASS 436s START /main/format_cache/ - format_cache_get 436s END /main/format_cache/ - format_cache_get Time: <1ms Result: PASS 436s START /main/format_cache/ - format_cache_set_null 436s END /main/format_cache/ - format_cache_set_null Time: <1ms Result: PASS 436s START /main/format_cache/ - format_cache_set_duplicate 436s END /main/format_cache/ - format_cache_set_duplicate Time: <1ms Result: PASS 436s START /main/format_cache/ - format_cache_set 436s END /main/format_cache/ - format_cache_set Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_replace_from_cap 436s END /main/format_cap/ - format_cap_replace_from_cap Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_best_by_type 436s END /main/format_cap/ - format_cap_best_by_type Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_iscompatible 436s END /main/format_cap/ - format_cap_iscompatible Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_get_compatible 436s END /main/format_cap/ - format_cap_get_compatible Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_iscompatible_format 436s END /main/format_cap/ - format_cap_iscompatible_format Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_get_compatible_format 436s END /main/format_cap/ - format_cap_get_compatible_format Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_get_names 436s END /main/format_cap/ - format_cap_get_names Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_remove_all 436s END /main/format_cap/ - format_cap_remove_all Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_remove_bytype 436s END /main/format_cap/ - format_cap_remove_bytype Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_remove_multiple 436s END /main/format_cap/ - format_cap_remove_multiple Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_remove_single 436s END /main/format_cap/ - format_cap_remove_single Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_set_framing 436s END /main/format_cap/ - format_cap_set_framing Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_append_from_cap_duplicate 436s END /main/format_cap/ - format_cap_append_from_cap_duplicate Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_append_from_cap 436s END /main/format_cap/ - format_cap_append_from_cap Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_append_duplicate 436s END /main/format_cap/ - format_cap_append_duplicate Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_append_all_audio 436s END /main/format_cap/ - format_cap_append_all_audio Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_append_all_unknown 436s END /main/format_cap/ - format_cap_append_all_unknown Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_append_multiple 436s END /main/format_cap/ - format_cap_append_multiple Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_append_single 436s END /main/format_cap/ - format_cap_append_single Time: <1ms Result: PASS 436s START /main/format_cap/ - format_cap_alloc 436s END /main/format_cap/ - format_cap_alloc Time: <1ms Result: PASS 436s START /main/hashtab/ - thrash 436s [test_hashtab_thrash.c:hash_test:246]: Executing hash concurrency test... 436s END /main/hashtab/ - thrash Time: 15ms Result: PASS 436s START /main/heap/ - heap_test_3 436s END /main/heap/ - heap_test_3 Time: 99ms Result: PASS 436s START /main/heap/ - heap_test_2 436s END /main/heap/ - heap_test_2 Time: 90ms Result: PASS 436s START /main/heap/ - heap_test_1 436s END /main/heap/ - heap_test_1 Time: <1ms Result: PASS 436s START /main/jitterbuf/ - jitterbuffer_resynch_control 436s END /main/jitterbuf/ - jitterbuffer_resynch_control Time: <1ms Result: PASS 436s START /main/jitterbuf/ - jitterbuffer_resynch_voice 436s END /main/jitterbuf/ - jitterbuffer_resynch_voice Time: <1ms Result: PASS 436s START /main/jitterbuf/ - jitterbuffer_overflow_control 436s END /main/jitterbuf/ - jitterbuffer_overflow_control Time: <1ms Result: PASS 436s START /main/jitterbuf/ - jitterbuffer_overflow_voice 436s END /main/jitterbuf/ - jitterbuffer_overflow_voice Time: <1ms Result: PASS 436s START /main/jitterbuf/ - jitterbuffer_late_control 436s END /main/jitterbuf/ - jitterbuffer_late_control Time: <1ms Result: PASS 436s START /main/jitterbuf/ - jitterbuffer_late_voice 436s END /main/jitterbuf/ - jitterbuffer_late_voice Time: <1ms Result: PASS 436s START /main/jitterbuf/ - jitterbuffer_lost_control 436s END /main/jitterbuf/ - jitterbuffer_lost_control Time: <1ms Result: PASS 436s START /main/jitterbuf/ - jitterbuffer_lost_voice 436s END /main/jitterbuf/ - jitterbuffer_lost_voice Time: <1ms Result: PASS 436s START /main/jitterbuf/ - jitterbuffer_out_of_order_voice 436s END /main/jitterbuf/ - jitterbuffer_out_of_order_voice Time: <1ms Result: PASS 436s START /main/jitterbuf/ - jitterbuffer_out_of_order_voice 436s END /main/jitterbuf/ - jitterbuffer_out_of_order_voice Time: <1ms Result: PASS 436s START /main/jitterbuf/ - jitterbuffer_nominal_control_frames 436s END /main/jitterbuf/ - jitterbuffer_nominal_control_frames Time: <1ms Result: PASS 436s START /main/jitterbuf/ - jitterbuffer_nominal_voice_frames 436s END /main/jitterbuf/ - jitterbuffer_nominal_voice_frames Time: <1ms Result: PASS 436s START /main/json/ - cep 436s END /main/json/ - cep Time: <1ms Result: PASS 436s START /main/json/ - type_timeval 436s END /main/json/ - type_timeval Time: <1ms Result: PASS 436s START /main/json/ - name_number 436s END /main/json/ - name_number Time: <1ms Result: PASS 436s START /main/json/ - clever_circle 436s END /main/json/ - clever_circle Time: <1ms Result: PASS 436s START /main/json/ - circular_array 436s END /main/json/ - circular_array Time: <1ms Result: PASS 436s START /main/json/ - circular_object 436s END /main/json/ - circular_object Time: <1ms Result: PASS 436s START /main/json/ - copy_null 436s END /main/json/ - copy_null Time: <1ms Result: PASS 436s START /main/json/ - deep_copy 436s END /main/json/ - deep_copy Time: <1ms Result: PASS 436s START /main/json/ - copy 436s END /main/json/ - copy Time: <1ms Result: PASS 436s START /main/json/ - object_alloc 436s END /main/json/ - object_alloc Time: 1ms Result: PASS 436s START /main/json/ - pack_ownership 436s END /main/json/ - pack_ownership Time: <1ms Result: PASS 436s START /main/json/ - pack 436s END /main/json/ - pack Time: <1ms Result: PASS 436s START /main/json/ - parse_errors 436s END /main/json/ - parse_errors Time: <1ms Result: PASS 436s START /main/json/ - dump_load_null 436s END /main/json/ - dump_load_null Time: <1ms Result: PASS 436s START /main/json/ - dump_load_new_file 436s END /main/json/ - dump_load_new_file Time: <1ms Result: PASS 436s START /main/json/ - dump_load_file 436s END /main/json/ - dump_load_file Time: <1ms Result: PASS 436s START /main/json/ - load_buffer 436s END /main/json/ - load_buffer Time: <1ms Result: PASS 436s START /main/json/ - dump_str_fail 436s END /main/json/ - dump_str_fail Time: <1ms Result: PASS 436s START /main/json/ - dump_load_str 436s END /main/json/ - dump_load_str Time: <1ms Result: PASS 436s START /main/json/ - dump_load_string 436s END /main/json/ - dump_load_string Time: <1ms Result: PASS 436s START /main/json/ - object_create_vars 436s END /main/json/ - object_create_vars Time: <1ms Result: PASS 436s START /main/json/ - object_iter_null 436s END /main/json/ - object_iter_null Time: <1ms Result: PASS 436s START /main/json/ - object_iter 436s END /main/json/ - object_iter Time: <1ms Result: PASS 436s START /main/json/ - object_null 436s END /main/json/ - object_null Time: <1ms Result: PASS 436s START /main/json/ - object_merge_missing 436s END /main/json/ - object_merge_missing Time: <1ms Result: PASS 436s START /main/json/ - object_alloc 436s END /main/json/ - object_alloc Time: <1ms Result: PASS 436s START /main/json/ - object_alloc 436s END /main/json/ - object_alloc Time: <1ms Result: PASS 436s START /main/json/ - object_clear 436s END /main/json/ - object_clear Time: <1ms Result: PASS 436s START /main/json/ - object_del 436s END /main/json/ - object_del Time: <1ms Result: PASS 436s START /main/json/ - object_get 436s END /main/json/ - object_get Time: <1ms Result: PASS 436s START /main/json/ - object_set_overwriting 436s END /main/json/ - object_set_overwriting Time: <1ms Result: PASS 436s START /main/json/ - object_set 436s END /main/json/ - object_set Time: <1ms Result: PASS 436s START /main/json/ - object_alloc 436s END /main/json/ - object_alloc Time: <1ms Result: PASS 436s START /main/json/ - array_null 436s END /main/json/ - array_null Time: <1ms Result: PASS 436s START /main/json/ - array_extend 436s END /main/json/ - array_extend Time: <1ms Result: PASS 436s START /main/json/ - array_clear 436s END /main/json/ - array_clear Time: <1ms Result: PASS 436s START /main/json/ - array_remove 436s END /main/json/ - array_remove Time: <1ms Result: PASS 436s START /main/json/ - array_set 436s END /main/json/ - array_set Time: <1ms Result: PASS 436s START /main/json/ - array_insert 436s END /main/json/ - array_insert Time: <1ms Result: PASS 436s START /main/json/ - array_append 436s END /main/json/ - array_append Time: <1ms Result: PASS 436s START /main/json/ - array_create 436s END /main/json/ - array_create Time: <1ms Result: PASS 436s START /main/json/ - non_int 436s END /main/json/ - non_int Time: <1ms Result: PASS 436s START /main/json/ - type_int 436s END /main/json/ - type_int Time: <1ms Result: PASS 436s START /main/json/ - stringf 436s END /main/json/ - stringf Time: <1ms Result: PASS 436s START /main/json/ - string_null 436s END /main/json/ - string_null Time: <1ms Result: PASS 436s START /main/json/ - type_string 436s END /main/json/ - type_string Time: <1ms Result: PASS 436s START /main/json/ - null_val 436s END /main/json/ - null_val Time: <1ms Result: PASS 436s START /main/json/ - type_null 436s END /main/json/ - type_null Time: <1ms Result: PASS 436s START /main/json/ - type_bool1 436s END /main/json/ - type_bool1 Time: <1ms Result: PASS 436s START /main/json/ - type_bool0 436s END /main/json/ - type_bool0 Time: <1ms Result: PASS 436s START /main/json/ - type_true 436s END /main/json/ - type_true Time: <1ms Result: PASS 436s START /main/json/ - type_false 436s END /main/json/ - type_false Time: <1ms Result: PASS 436s START /main/linkedlists/ - double_ll_tests 436s END /main/linkedlists/ - double_ll_tests Time: <1ms Result: PASS 436s START /main/linkedlists/ - ll_tests 436s END /main/linkedlists/ - ll_tests Time: <1ms Result: PASS 436s START /main/lock/ - cleanup_order_test 436s [test_scoped_lock.c:test_ref:149]: Ref is occurring 436s [test_scoped_lock.c:test_lock:117]: Lock is occurring 436s [test_scoped_lock.c:test_unlock:133]: Unlock is occurring 436s [test_scoped_lock.c:test_unref:166]: Unref is occurring 436s [test_scoped_lock.c:test_ref:149]: Ref is occurring 436s [test_scoped_lock.c:test_lock:117]: Lock is occurring 436s [test_scoped_lock.c:test_unlock:133]: Unlock is occurring 436s [test_scoped_lock.c:test_unref:166]: Unref is occurring 436s END /main/lock/ - cleanup_order_test Time: <1ms Result: PASS 436s START /main/lock/ - lock_test 436s END /main/lock/ - lock_test Time: <1ms Result: PASS 436s START /main/lock/ - named_lock_test 436s [test_named_lock.c:named_lock_test:80]: This test should take about 3 seconds 439s END /main/lock/ - named_lock_test Time: 3000ms Result: PASS 439s START /main/logging/ - scope_test 439s END /main/logging/ - scope_test Time: <1ms Result: PASS 439s START /main/manager/ - originate_permissions_test 439s END /main/manager/ - originate_permissions_test Time: <1ms Result: PASS 439s START /main/manager/ - eventfilter_test_matching 439s Loaded 7 filters 439s Tested 9 events 439s END /main/manager/ - eventfilter_test_matching Time: <1ms Result: PASS 439s START /main/manager/ - eventfilter_test_creation 439s [manager.c:eventfilter_test_creation:6199]: Tested 29 filters 439s END /main/manager/ - eventfilter_test_creation Time: <1ms Result: PASS 439s START /main/media_cache/ - create_update_off_nominal 439s END /main/media_cache/ - create_update_off_nominal Time: <1ms Result: PASS 439s START /main/media_cache/ - create_update_metadata 439s [test_media_cache.c:create_update_metadata:367]: Got /tmp/test-media-cache-AZ1gnN for second file path 439s END /main/media_cache/ - create_update_metadata Time: <1ms Result: PASS 439s START /main/media_cache/ - create_update_nominal 439s [test_media_cache.c:create_update_nominal:236]: Creating resource with /tmp/test-media-cache-xWoptB 439s [test_media_cache.c:create_update_nominal:241]: Got /tmp/test-media-cache-xWoptB for first file path 439s [test_media_cache.c:create_update_nominal:245]: Creating resource with /tmp/test-media-cache-ZLtVUa 439s [test_media_cache.c:create_update_nominal:250]: Got /tmp/test-media-cache-ZLtVUa for second file path 439s END /main/media_cache/ - create_update_nominal Time: 1ms Result: PASS 439s START /main/media_cache/ - exists_off_nominal 439s END /main/media_cache/ - exists_off_nominal Time: <1ms Result: PASS 439s START /main/media_cache/ - exists_nominal 439s END /main/media_cache/ - exists_nominal Time: <1ms Result: PASS 439s START /main/netsock2/ - split_hostport 439s END /main/netsock2/ - split_hostport Time: <1ms Result: PASS 439s START /main/netsock2/ - parsing 439s END /main/netsock2/ - parsing Time: <1ms Result: PASS 439s START /main/optional_api/ - test_provide_last 439s END /main/optional_api/ - test_provide_last Time: <1ms Result: PASS 439s START /main/optional_api/ - test_provide_first 439s END /main/optional_api/ - test_provide_first Time: <1ms Result: PASS 439s START /main/pbx/ - test_MATH_function 439s [func_math.c:test_MATH_function:682]: Testing MATH() substitution ... 439s END /main/pbx/ - test_MATH_function Time: <1ms Result: PASS 439s START /main/pbx/ - test_substitution 439s [test_substitution.c:test_substitution:244]: Testing variable substitution ... 439s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGANI2}' . . . . . passed 439s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGTON}' . . . . . passed 439s [test_substitution.c:test_chan_integer:65]: Tested '${CALLINGTNS}' . . . . . passed 439s [test_substitution.c:test_chan_integer_accessor:89]: Tested '${HANGUPCAUSE}' . . . . . passed 439s [test_substitution.c:test_chan_integer_accessor:89]: Tested '${PRIORITY}' . . . . . passed 439s [test_substitution.c:test_chan_string:115]: Tested '${CONTEXT}' . . . . . passed 439s [test_substitution.c:test_chan_string:115]: Tested '${EXTEN}' . . . . . passed 439s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(language)}' . . . . . passed 439s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(musicclass)}' . . . . . passed 439s [test_substitution.c:test_chan_variable:144]: Tested '${CHANNEL(parkinglot)}' . . . . . passed 439s [test_substitution.c:test_chan_variable:144]: Tested '${CALLERID(name)}' . . . . . passed 439s [test_substitution.c:test_chan_variable:144]: Tested '${CURLOPT(proxyuserpwd)}' . . . . . passed 439s [test_substitution.c:test_chan_variable:144]: Tested '${CDR(foo)}' . . . . . passed 439s [test_substitution.c:test_chan_variable:144]: Tested '${ENV(foo)}' . . . . . passed 439s [test_substitution.c:test_chan_variable:144]: Tested '${GLOBAL(foo)}' . . . . . passed 439s [test_substitution.c:test_chan_variable:144]: Tested '${GROUP()}' . . . . . passed 439s [test_substitution.c:test_2way_function:193]: Tested '${AES_ENCRYPT(abcdefghijklmnop,)}' and '${AES_DECRYPT(abcdefghijklmnop,)}' . . . . . passed 439s [test_substitution.c:test_2way_function:193]: Tested '${BASE64_ENCODE()}' and '${BASE64_DECODE()}' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested '123123' ('${foo}${foo}') == '123123' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested 'A123A123A' ('A${foo}A${foo}A') == 'A123A123A' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested 'A123A' ('A${${bar}}A') == 'A123A' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested 'A123A' ('A${${baz}o}A') == 'A123A' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested 'A23A' ('A${${baz}o:1}A') == 'A23A' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:1:1}A') == 'A2A' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:1:-1}A') == 'A2A' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested 'A3A' ('A${${baz}o:-1:1}A') == 'A3A' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:-2:1}A') == 'A2A' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested 'A2A' ('A${${baz}o:-2:-1}A') == 'A2A' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested 'cd&ef' ('${LISTFILTER(list1,&,ab)}') == 'cd&ef' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested 'ab&ef' ('${LISTFILTER(list1,&,cd)}') == 'ab&ef' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd' ('${LISTFILTER(list1,&,ef)}') == 'ab&cd' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,gh)}') == 'ab&cd&ef' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,c)}') == 'ab&cd&ef' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested 'ab&cd&ef' ('${LISTFILTER(list1,&,d)}') == 'ab&cd&ef' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested '' ('${LISTFILTER(list2,&,ab)}') == '' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested '' ('${LISTFILTER(list_empty,&,ab)}') == '' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested '123,456' ('${SHELL(printf '%d' 123)},${SHELL(printf '%d' 456)}') == '123,456' . . . . . passed 439s [test_substitution.c:test_expected_result:215]: Tested '123,,456' ('${foo},${CDR(answer)},${SHELL(printf '%d' 456)}') == '123,,456' . . . . . passed 439s [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 439s [test_substitution.c:test_expected_result:215]: Tested '123,,' ('${foo},${this_does_not_exist},${THIS_DOES_NOT_EXIST(either)}') == '123,,' . . . . . passed 439s [test_substitution.c:test_chan_function:168]: Tested '${BLACKLIST(foo)}' . . . . . passed 439s [test_substitution.c:test_chan_function:168]: Tested '${EVAL(foo)}' . . . . . passed 439s [test_substitution.c:test_chan_function:168]: Tested '${FIELDNUM(foo)}' . . . . . passed 439s [test_substitution.c:test_chan_function:168]: Tested '${FIELDQTY(foo)}' . . . . . passed 439s [test_substitution.c:test_chan_function:168]: Tested '${HASHKEYS(foo)}' . . . . . passed 439s [test_substitution.c:test_chan_function:168]: Tested '${IMPORT(foo)}' . . . . . passed 439s [test_substitution.c:test_chan_function:168]: Tested '${PP_EACH_USER(foo)}' . . . . . passed 439s [test_substitution.c:test_chan_function:168]: Tested '${TOLOWER(foo)}' . . . . . passed 439s [test_substitution.c:test_chan_function:168]: Tested '${TOUPPER(foo)}' . . . . . passed 439s END /main/pbx/ - test_substitution Time: 12ms Result: PASS 439s START /main/pbx/ - pattern_match_test 439s [test_pbx.c:test_exten:183]: Successfully matched 200 to exten _2. in context test_pattern with the old pattern match engine 439s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the old pattern match engine 439s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the old pattern match engine 439s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern_include with the old pattern match engine 439s [test_pbx.c:test_exten:183]: Successfully matched 200 to exten _2. in context test_pattern with the new pattern match engine 439s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the new pattern match engine 439s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern with the new pattern match engine 439s [test_pbx.c:test_exten:183]: Successfully matched 2000 to exten 2000 in context test_pattern_include with the new pattern match engine 439s END /main/pbx/ - pattern_match_test Time: <1ms Result: PASS 439s START /main/pbx/ - variable_substrings 439s END /main/pbx/ - variable_substrings Time: <1ms Result: PASS 439s START /main/poll/ - poll_test 439s [test_poll.c:poll_test:95]: Creating handle that should NEVER block on write 439s [test_poll.c:poll_test:101]: Creating handle that should NEVER block on read 439s [test_poll.c:poll_test:108]: Creating handle that should block on read 439s [test_poll.c:poll_test:168]: Starting thread to ensure we don't block forever 439s [test_poll.c:poll_test:194]: Cancelling failsafe thread. 439s END /main/poll/ - poll_test Time: <1ms Result: PASS 439s START /main/presence/ - channel_presence 439s END /main/presence/ - channel_presence Time: <1ms Result: PASS 439s START /main/sample/ - sample_test 439s [test_skel.c:sample_test:57]: Executing sample test... 439s END /main/sample/ - sample_test Time: <1ms Result: PASS 439s START /main/sched/ - sched_test_freebird 439s [test_sched.c:sched_test_freebird:440]: Received signal, calling Scedule and UNREF 439s [test_sched.c:sched_test_freebird:441]: ID: 1 442s [test_sched.c:sched_test_freebird:448]: Correct number of references '2' 442s END /main/sched/ - sched_test_freebird Time: 3000ms Result: PASS 442s START /main/sched/ - sched_test_order 442s END /main/sched/ - sched_test_order Time: 400ms Result: PASS 442s START /main/sorcery/ - wizard_read_only 442s END /main/sorcery/ - wizard_read_only Time: <1ms Result: PASS 442s START /main/sorcery/ - wizard_observation 442s END /main/sorcery/ - wizard_observation Time: <1ms Result: PASS 442s START /main/sorcery/ - instance_observation 442s END /main/sorcery/ - instance_observation Time: <1ms Result: PASS 442s START /main/sorcery/ - global_observation 442s END /main/sorcery/ - global_observation Time: <1ms Result: PASS 442s START /main/sorcery/ - object_field_registered 442s END /main/sorcery/ - object_field_registered Time: <1ms Result: PASS 442s START /main/sorcery/ - dialplan_function 442s END /main/sorcery/ - dialplan_function Time: <1ms Result: PASS 442s START /main/sorcery/ - configuration_file_wizard_retrieve_multiple_all 442s END /main/sorcery/ - configuration_file_wizard_retrieve_multiple_all Time: <1ms Result: PASS 442s START /main/sorcery/ - configuration_file_wizard_retrieve_multiple 442s END /main/sorcery/ - configuration_file_wizard_retrieve_multiple Time: <1ms Result: PASS 442s START /main/sorcery/ - configuration_file_wizard_retrieve_field 442s END /main/sorcery/ - configuration_file_wizard_retrieve_field Time: <1ms Result: PASS 442s START /main/sorcery/ - configuration_file_wizard_with_criteria 442s END /main/sorcery/ - configuration_file_wizard_with_criteria Time: <1ms Result: PASS 442s START /main/sorcery/ - configuration_file_wizard_with_file_integrity 442s END /main/sorcery/ - configuration_file_wizard_with_file_integrity Time: <1ms Result: PASS 442s START /main/sorcery/ - configuration_file_wizard 442s END /main/sorcery/ - configuration_file_wizard Time: <1ms Result: PASS 442s START /main/sorcery/ - object_type_observer 442s END /main/sorcery/ - object_type_observer Time: <1ms Result: PASS 442s START /main/sorcery/ - caching_wizard_behavior 442s END /main/sorcery/ - caching_wizard_behavior Time: <1ms Result: PASS 442s START /main/sorcery/ - object_is_stale 442s END /main/sorcery/ - object_is_stale Time: <1ms Result: PASS 442s START /main/sorcery/ - object_delete_uncreated 442s END /main/sorcery/ - object_delete_uncreated Time: <1ms Result: PASS 442s START /main/sorcery/ - object_delete 442s END /main/sorcery/ - object_delete Time: <1ms Result: PASS 442s START /main/sorcery/ - object_update_uncreated 442s END /main/sorcery/ - object_update_uncreated Time: <1ms Result: PASS 442s START /main/sorcery/ - object_update 442s END /main/sorcery/ - object_update Time: <1ms Result: PASS 442s START /main/sorcery/ - object_retrieve_regex 442s END /main/sorcery/ - object_retrieve_regex Time: <1ms Result: PASS 442s START /main/sorcery/ - object_retrieve_multiple_field 442s END /main/sorcery/ - object_retrieve_multiple_field Time: <1ms Result: PASS 442s START /main/sorcery/ - object_retrieve_multiple_all 442s END /main/sorcery/ - object_retrieve_multiple_all Time: <1ms Result: PASS 442s START /main/sorcery/ - object_retrieve_field 442s END /main/sorcery/ - object_retrieve_field Time: <1ms Result: PASS 442s START /main/sorcery/ - object_retrieve_id 442s END /main/sorcery/ - object_retrieve_id Time: <1ms Result: PASS 442s START /main/sorcery/ - object_create 442s END /main/sorcery/ - object_create Time: <1ms Result: PASS 442s START /main/sorcery/ - changeset_create_unchanged 442s END /main/sorcery/ - changeset_create_unchanged Time: <1ms Result: PASS 442s START /main/sorcery/ - changeset_create 442s END /main/sorcery/ - changeset_create Time: <1ms Result: PASS 442s START /main/sorcery/ - extended_fields 442s END /main/sorcery/ - extended_fields Time: <1ms Result: PASS 442s START /main/sorcery/ - objectset_apply_fields 442s END /main/sorcery/ - objectset_apply_fields Time: <1ms Result: PASS 442s START /main/sorcery/ - objectset_transform 442s END /main/sorcery/ - objectset_transform Time: <1ms Result: PASS 442s START /main/sorcery/ - objectset_apply_invalid 442s END /main/sorcery/ - objectset_apply_invalid Time: <1ms Result: PASS 442s START /main/sorcery/ - objectset_apply_handler 442s END /main/sorcery/ - objectset_apply_handler Time: <1ms Result: PASS 442s START /main/sorcery/ - objectset_apply 442s END /main/sorcery/ - objectset_apply Time: <1ms Result: PASS 442s START /main/sorcery/ - objectset_create_regex 442s END /main/sorcery/ - objectset_create_regex Time: <1ms Result: PASS 442s START /main/sorcery/ - objectset_json_create 442s END /main/sorcery/ - objectset_json_create Time: <1ms Result: PASS 442s START /main/sorcery/ - objectset_create 442s END /main/sorcery/ - objectset_create Time: <1ms Result: PASS 442s START /main/sorcery/ - object_diff_native 442s END /main/sorcery/ - object_diff_native Time: <1ms Result: PASS 442s START /main/sorcery/ - object_diff 442s END /main/sorcery/ - object_diff Time: <1ms Result: PASS 442s START /main/sorcery/ - object_copy_native 442s END /main/sorcery/ - object_copy_native Time: <1ms Result: PASS 442s START /main/sorcery/ - object_copy 442s END /main/sorcery/ - object_copy Time: <1ms Result: PASS 442s START /main/sorcery/ - object_alloc_without_id 442s END /main/sorcery/ - object_alloc_without_id Time: <1ms Result: PASS 442s START /main/sorcery/ - object_alloc_with_id 442s END /main/sorcery/ - object_alloc_with_id Time: <1ms Result: PASS 442s START /main/sorcery/ - object_fields_register 442s END /main/sorcery/ - object_fields_register Time: <1ms Result: PASS 442s START /main/sorcery/ - object_field_register 442s END /main/sorcery/ - object_field_register Time: <1ms Result: PASS 442s START /main/sorcery/ - object_register_without_mapping 442s END /main/sorcery/ - object_register_without_mapping Time: <1ms Result: PASS 442s START /main/sorcery/ - object_register 442s END /main/sorcery/ - object_register Time: <1ms Result: PASS 442s START /main/sorcery/ - apply_config 442s END /main/sorcery/ - apply_config Time: <1ms Result: PASS 442s START /main/sorcery/ - apply_default 442s END /main/sorcery/ - apply_default Time: <1ms Result: PASS 442s START /main/sorcery/ - open 442s END /main/sorcery/ - open Time: <1ms Result: PASS 442s START /main/sorcery/ - wizard_registration 442s END /main/sorcery/ - wizard_registration Time: <1ms Result: PASS 442s START /main/sorcery/ - wizard_apply_and_insert 442s END /main/sorcery/ - wizard_apply_and_insert Time: <1ms Result: PASS 442s START /main/stdtime/ - time_create_by_unit_str 442s END /main/stdtime/ - time_create_by_unit_str Time: <1ms Result: PASS 442s START /main/stdtime/ - time_create_by_unit 442s END /main/stdtime/ - time_create_by_unit Time: <1ms Result: PASS 442s START /main/stdtime/ - time_str_to_unit 442s END /main/stdtime/ - time_str_to_unit Time: <1ms Result: PASS 442s START /main/stdtime/ - time_tv_to_usec 442s END /main/stdtime/ - time_tv_to_usec Time: <1ms Result: PASS 442s START /main/stdtime/ - timezone_watch 442s [test_time.c:test_timezone_watch:82]: Executing deletion test... 442s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.ouGHvX/test 443s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.ouGHvX/test 443s [test_time.c:test_timezone_watch:82]: Executing symlink test... 443s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.ouGHvX/test 445s [test_time.c:test_timezone_watch:90]: Querying timezone /tmp/timezone.ouGHvX/test 445s END /main/stdtime/ - timezone_watch Time: 2275ms Result: PASS 445s START /main/stream/ - stream_topology_map_create 445s END /main/stream/ - stream_topology_map_create Time: <1ms Result: PASS 445s START /main/stream/ - format_cap_from_stream_topology 445s END /main/stream/ - format_cap_from_stream_topology Time: <1ms Result: PASS 445s START /main/stream/ - stream_topology_change_request_from_channel 445s END /main/stream/ - stream_topology_change_request_from_channel Time: <1ms Result: PASS 445s START /main/stream/ - stream_topology_change_request_from_application 445s END /main/stream/ - stream_topology_change_request_from_application Time: <1ms Result: PASS 445s START /main/stream/ - stream_topology_change_request_from_channel_non_multistream 445s END /main/stream/ - stream_topology_change_request_from_channel_non_multistream Time: <1ms Result: PASS 445s START /main/stream/ - stream_topology_change_request_from_application_non_multistream 445s END /main/stream/ - stream_topology_change_request_from_application_non_multistream Time: <1ms Result: PASS 445s START /main/stream/ - stream_read_multistream 445s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 445s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 445s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 445s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 445s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 4 Frames: 16 Frames per read: 1 Expected Nulls: 8 445s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 8 445s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 4 Frames: 16 Frames per read: 1 Expected Nulls: 0 445s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 445s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 445s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 445s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 445s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 445s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: NON-STREAM Streams: 4 Frames: 16 Frames per read: 3 Expected Nulls: 8 445s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 8 445s [test_stream.c:read_test:1726]: ChanType: MULTI ReadType: STREAM Streams: 4 Frames: 16 Frames per read: 3 Expected Nulls: 0 445s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 445s END /main/stream/ - stream_read_multistream Time: <1ms Result: PASS 445s START /main/stream/ - stream_read_non_multistream 445s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 445s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 445s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 1 Expected Nulls: 0 445s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 445s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: NON-STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 445s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 445s [test_stream.c:read_test:1726]: ChanType: NON-MULTI ReadType: STREAM Streams: 2 Frames: 16 Frames per read: 3 Expected Nulls: 0 445s [test_stream.c:read_test:1759]: Frames read: 16 NULL frames: 0 445s END /main/stream/ - stream_read_non_multistream Time: <1ms Result: PASS 445s START /main/stream/ - stream_write_multistream 445s END /main/stream/ - stream_write_multistream Time: <1ms Result: PASS 445s START /main/stream/ - stream_write_non_multistream 445s END /main/stream/ - stream_write_non_multistream Time: <1ms Result: PASS 445s START /main/stream/ - stream_topology_channel_set 445s END /main/stream/ - stream_topology_channel_set Time: <1ms Result: PASS 445s START /main/stream/ - stream_topology_create_from_channel_nativeformats 445s END /main/stream/ - stream_topology_create_from_channel_nativeformats Time: <1ms Result: PASS 445s START /main/stream/ - stream_topology_get_first_stream_by_type 445s END /main/stream/ - stream_topology_get_first_stream_by_type Time: <1ms Result: PASS 445s START /main/stream/ - stream_topology_create_from_format_cap 445s END /main/stream/ - stream_topology_create_from_format_cap Time: <1ms Result: PASS 445s START /main/stream/ - stream_topology_del_stream 445s END /main/stream/ - stream_topology_del_stream Time: <1ms Result: PASS 445s START /main/stream/ - stream_topology_set_stream 445s END /main/stream/ - stream_topology_set_stream Time: <1ms Result: PASS 445s START /main/stream/ - stream_topology_append_stream 445s END /main/stream/ - stream_topology_append_stream Time: <1ms Result: PASS 445s START /main/stream/ - stream_topology_clone 445s END /main/stream/ - stream_topology_clone Time: <1ms Result: PASS 445s START /main/stream/ - stream_topology_create 445s END /main/stream/ - stream_topology_create Time: <1ms Result: PASS 445s START /main/stream/ - stream_metadata 445s END /main/stream/ - stream_metadata Time: <1ms Result: PASS 445s START /main/stream/ - stream_set_state 445s END /main/stream/ - stream_set_state Time: <1ms Result: PASS 445s START /main/stream/ - stream_set_formats 445s END /main/stream/ - stream_set_formats Time: <1ms Result: PASS 445s START /main/stream/ - stream_set_type 445s END /main/stream/ - stream_set_type Time: <1ms Result: PASS 445s START /main/stream/ - stream_create_no_name 445s END /main/stream/ - stream_create_no_name Time: <1ms Result: PASS 445s START /main/stream/ - stream_create 445s END /main/stream/ - stream_create Time: <1ms Result: PASS 445s START /main/strings/ - in_delimited_string 445s END /main/strings/ - in_delimited_string Time: <1ms Result: PASS 445s START /main/strings/ - temp_strings 445s END /main/strings/ - temp_strings Time: <1ms Result: PASS 445s START /main/strings/ - strings_match 445s END /main/strings/ - strings_match Time: <1ms Result: PASS 445s START /main/strings/ - escape 445s END /main/strings/ - escape Time: <1ms Result: PASS 445s START /main/strings/ - escape_semicolons 445s END /main/strings/ - escape_semicolons Time: <1ms Result: PASS 445s START /main/strings/ - strsep_quoted 445s END /main/strings/ - strsep_quoted Time: <1ms Result: PASS 445s START /main/strings/ - strsep 445s END /main/strings/ - strsep Time: <1ms Result: PASS 445s START /main/strings/ - ends_with 445s END /main/strings/ - ends_with Time: <1ms Result: PASS 445s START /main/strings/ - begins_with 445s END /main/strings/ - begins_with Time: <1ms Result: PASS 445s START /main/strings/ - str_test 445s END /main/strings/ - str_test Time: <1ms Result: PASS 445s START /main/taskprocessor/ - serializer_pool 449s END /main/taskprocessor/ - serializer_pool Time: 4000ms Result: PASS 449s START /main/taskprocessor/ - taskprocessor_push_local 449s END /main/taskprocessor/ - taskprocessor_push_local Time: <1ms Result: PASS 449s START /main/taskprocessor/ - taskprocessor_shutdown 449s END /main/taskprocessor/ - taskprocessor_shutdown Time: <1ms Result: PASS 449s START /main/taskprocessor/ - taskprocessor_listener 449s END /main/taskprocessor/ - taskprocessor_listener Time: <1ms Result: PASS 449s START /main/taskprocessor/ - subsystem_alert 449s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 1 449s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 2 449s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 3 449s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 4 449s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 5 449s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 6 449s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 7 449s [test_taskprocessor.c:subsystem_alert:237]: Subsystem alert triggered correctly at 6 449s [test_taskprocessor.c:subsystem_alert:240]: Global alert triggered correctly at 6 449s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 8 449s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 9 449s [test_taskprocessor.c:subsystem_alert:224]: Pushing task 10 449s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 1 449s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 2 450s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 3 450s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 4 451s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 5 451s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 6 452s [test_taskprocessor.c:subsystem_alert:279]: Subsystem alert cleared correctly at 3 452s [test_taskprocessor.c:subsystem_alert:282]: Global alert cleared correctly at 3 452s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 7 452s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 8 453s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 9 453s [test_taskprocessor.c:subsystem_alert:266]: Waiting on task 10 454s END /main/taskprocessor/ - subsystem_alert Time: 5001ms Result: PASS 454s START /main/taskprocessor/ - default_taskprocessor_load 454s END /main/taskprocessor/ - default_taskprocessor_load Time: 23ms Result: PASS 454s START /main/taskprocessor/ - default_taskprocessor 454s END /main/taskprocessor/ - default_taskprocessor Time: <1ms Result: PASS 454s START /main/test/ - registrations 454s END /main/test/ - registrations Time: <1ms Result: PASS 454s START /main/test_capture/ - test_capture_false 454s [test_capture.c:test_capture_false:120]: Executing false exit test... 454s END /main/test_capture/ - test_capture_false Time: 13ms Result: PASS 454s START /main/test_capture/ - test_capture_true 454s [test_capture.c:test_capture_true:61]: Executing true exit test... 454s END /main/test_capture/ - test_capture_true Time: 9ms Result: PASS 454s START /main/test_capture/ - test_capture_stdout_stderr 454s [test_capture.c:test_capture_stdout_stderr:318]: Executing stdout/stderr test... 454s END /main/test_capture/ - test_capture_stdout_stderr Time: 9ms Result: PASS 454s START /main/test_capture/ - test_capture_with_dynamic 454s [test_capture.c:test_capture_with_dynamic:249]: Executing dynamic argument test... 454s END /main/test_capture/ - test_capture_with_dynamic Time: 9ms Result: PASS 454s START /main/test_capture/ - test_capture_with_stdin 454s [test_capture.c:test_capture_with_stdin:183]: Executing stdin test... 454s END /main/test_capture/ - test_capture_with_stdin Time: 10ms Result: PASS 454s START /main/threadpool/ - threadpool_serializer_dupe 454s END /main/threadpool/ - threadpool_serializer_dupe Time: <1ms Result: PASS 454s START /main/threadpool/ - threadpool_serializer 455s END /main/threadpool/ - threadpool_serializer Time: 1000ms Result: PASS 455s START /main/threadpool/ - more_destruction 455s END /main/threadpool/ - more_destruction Time: <1ms Result: PASS 455s START /main/threadpool/ - task_distribution 455s END /main/threadpool/ - task_distribution Time: <1ms Result: PASS 455s START /main/threadpool/ - reactivation 455s END /main/threadpool/ - reactivation Time: <1ms Result: PASS 455s START /main/threadpool/ - max_size 455s END /main/threadpool/ - max_size Time: <1ms Result: PASS 455s START /main/threadpool/ - auto_increment 455s END /main/threadpool/ - auto_increment Time: <1ms Result: PASS 455s START /main/threadpool/ - one_thread_multiple_tasks 455s END /main/threadpool/ - one_thread_multiple_tasks Time: <1ms Result: PASS 455s START /main/threadpool/ - one_thread_one_task 455s END /main/threadpool/ - one_thread_one_task Time: <1ms Result: PASS 455s START /main/threadpool/ - one_task_one_thread 455s END /main/threadpool/ - one_task_one_thread Time: <1ms Result: PASS 455s START /main/threadpool/ - thread_timeout_thrash 486s END /main/threadpool/ - thread_timeout_thrash Time: 31009ms Result: PASS 486s START /main/threadpool/ - thread_timeout 488s END /main/threadpool/ - thread_timeout Time: 2000ms Result: PASS 488s START /main/threadpool/ - thread_destruction 488s END /main/threadpool/ - thread_destruction Time: <1ms Result: PASS 488s START /main/threadpool/ - thread_creation 488s END /main/threadpool/ - thread_creation Time: <1ms Result: PASS 488s START /main/threadpool/ - initial_threads 488s END /main/threadpool/ - initial_threads Time: <1ms Result: PASS 488s START /main/threadpool/ - push 488s END /main/threadpool/ - push Time: <1ms Result: PASS 488s START /main/uri/ - uri_default_http_secure 488s END /main/uri/ - uri_default_http_secure Time: <1ms Result: PASS 488s START /main/uri/ - uri_default_http 488s END /main/uri/ - uri_default_http Time: <1ms Result: PASS 488s START /main/uri/ - uri_parse 488s END /main/uri/ - uri_parse Time: <1ms Result: PASS 488s START /main/utf8/ - replace_invalid 488s END /main/utf8/ - replace_invalid Time: <1ms Result: PASS 488s START /main/utf8/ - utf8_validator 488s END /main/utf8/ - utf8_validator Time: <1ms Result: PASS 488s START /main/utf8/ - copy_string 488s END /main/utf8/ - copy_string Time: <1ms Result: PASS 488s START /main/utf8/ - is_valid 488s END /main/utf8/ - is_valid Time: <1ms Result: PASS 488s START /main/utils/ - quote_unescaping 488s END /main/utils/ - quote_unescaping Time: <1ms Result: PASS 488s START /main/utils/ - quote_mutation 488s END /main/utils/ - quote_mutation Time: <1ms Result: PASS 488s START /main/utils/ - crypt_test 488s END /main/utils/ - crypt_test Time: 9ms Result: PASS 488s START /main/utils/ - safe_mkdir_test 488s END /main/utils/ - safe_mkdir_test Time: <1ms Result: PASS 488s START /main/utils/ - base64_test 488s END /main/utils/ - base64_test Time: <1ms Result: PASS 488s START /main/utils/ - sha1_test 488s [test_utils.c:sha1_test:250]: Testing SHA1 ... 488s END /main/utils/ - sha1_test Time: <1ms Result: PASS 488s START /main/utils/ - md5_test 488s [test_utils.c:md5_test:205]: Testing MD5 ... 488s END /main/utils/ - md5_test Time: <1ms Result: PASS 488s START /main/utils/ - quoted_escape_test 488s END /main/utils/ - quoted_escape_test Time: <1ms Result: PASS 488s START /main/utils/ - uri_encode_decode_test 488s END /main/utils/ - uri_encode_decode_test Time: <1ms Result: PASS 488s START /main/utils/ - string_field_aggregate_test 488s [test_stringfields.c:string_field_aggregate_test:392]: Structures 3 embedded pool initialized successfully. 488s [test_stringfields.c:string_field_aggregate_test:410]: Structures 3 additional pool initialized successfully. 488s [test_stringfields.c:string_field_aggregate_test:422]: Structures 1/2 are equal as expected. 488s [test_stringfields.c:string_field_aggregate_test:430]: Structures 1/3 are different as expected. 488s [test_stringfields.c:string_field_aggregate_test:438]: Structures 2/3 are different as expected. 488s [test_stringfields.c:string_field_aggregate_test:446]: Structures 3/4 are different as expected. 488s [test_stringfields.c:string_field_aggregate_test:454]: Copying from structure 3 to structure 1 succeeded! 488s [test_stringfields.c:string_field_aggregate_test:463]: Structures 1/3 are equal as expected. 488s [test_stringfields.c:string_field_aggregate_test:470]: Structures 1/2 are different as expected. 488s [test_stringfields.c:string_field_aggregate_test:473]: Reset but don't free. 488s [test_stringfields.c:string_field_aggregate_test:484]: Structures 1/2 are the same (empty) as expected. 488s [test_stringfields.c:string_field_aggregate_test:492]: Structure 4 embedded pool is the current pool as expected. 488s [test_stringfields.c:string_field_aggregate_test:500]: Structure 4 embedded pool does not have a previous as expected. 488s END /main/utils/ - string_field_aggregate_test Time: <1ms Result: PASS 488s START /main/utils/ - string_field_test 488s [test_stringfields.c:string_field_test:79]: First things first. Let's see if we can actually allocate string fields 488s [test_stringfields.c:string_field_test:85]: All right! Successfully allocated! Now let's get down to business 488s [test_stringfields.c:string_field_test:89]: We're going to set some string fields and perform some checks 488s [test_stringfields.c:string_field_test:94]: First we're going to make sure that the strings are actually set to what we expect 488s [test_stringfields.c:string_field_test:100]: test_struct.string1 appears to be all clear. It has 'elephant' and that's what we expect 488s [test_stringfields.c:string_field_test:107]: test_struct.string2 appears to be all clear. It has 'hippopotamus' and that's what we expect 488s [test_stringfields.c:string_field_test:110]: Now let's make sure that our recorded capacities for these strings is what we expect 488s [test_stringfields.c:string_field_test:117]: string1 has the allocation area we expect: 9 488s [test_stringfields.c:string_field_test:125]: string2 has the allocation area we expect: 13 488s [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 488s [test_stringfields.c:string_field_test:137]: string1 successfully was changed to 'rhino' 488s [test_stringfields.c:string_field_test:144]: Shrinking string1 allowed it to stay in the same place in memory 488s [test_stringfields.c:string_field_test:151]: Shrinking string1 did not change its allocation area (This is a good thing) 488s [test_stringfields.c:string_field_test:154]: Next, let's increase it a little but not all the way to its original size 488s [test_stringfields.c:string_field_test:163]: string1 successfully was changed to 'mammoth' 488s [test_stringfields.c:string_field_test:170]: Expanding string1 allowed it to stay in the same place in memory 488s [test_stringfields.c:string_field_test:177]: Expanding string1 did not change its allocation area (This is a good thing) 488s [test_stringfields.c:string_field_test:180]: Cool, now let's bring it back to its original size and see what happens 488s [test_stringfields.c:string_field_test:188]: string1 successfully changed to 'elephant' 488s [test_stringfields.c:string_field_test:195]: Restoring string1 did not cause it to move (This is a good thing) 488s [test_stringfields.c:string_field_test:202]: The allocation amount for string1 is still holding steady 488s [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 488s [test_stringfields.c:string_field_test:214]: string2 successfully changed to 'hippopotamus face' 488s [test_stringfields.c:string_field_test:222]: The allocation amount successfully increased for string2 when it grew 488s [test_stringfields.c:string_field_test:229]: string2 stayed in place when it grew. Good job! 488s [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 488s [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' 488s [test_stringfields.c:string_field_test:248]: Good. Setting string1 to a long value caused it to change addresses 488s [test_stringfields.c:string_field_test:256]: The stored allocation size of string1 is what we expect 488s [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 488s [test_stringfields.c:string_field_test:281]: Three different pools are linked as expected. 488s [test_stringfields.c:string_field_test:289]: After removing a pool the remaining two are linked as expected. 488s END /main/utils/ - string_field_test Time: <1ms Result: PASS 488s START /main/uuid/ - uuid 488s [test_uuid.c:uuid:59]: Generate UUID direct to string, got 93df8188-854a-43da-a915-c00c23e1d96d 488s [test_uuid.c:uuid:90]: Second generated UUID converted to string, got d16bf59d-b4d4-4bf8-8faa-e74b26352895 488s END /main/uuid/ - uuid Time: <1ms Result: PASS 488s START /main/vector/ - basic 488s END /main/vector/ - basic Time: <1ms Result: PASS 488s START /main/vector/ - basic_integer 488s END /main/vector/ - basic_integer Time: <1ms Result: PASS 488s START /main/vector/ - callbacks 488s END /main/vector/ - callbacks Time: <1ms Result: PASS 488s START /main/vector/ - locks 488s END /main/vector/ - locks Time: <1ms Result: PASS 488s START /main/voicemail_api/ - off_nominal_msg_playback 488s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1493]: Created message in test_vm_api_1234/Old with ID 1737363727-909401725 488s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1493]: Created message in test_vm_api_1234/INBOX with ID 1737363727-960311778 488s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1493]: Created message in test_vm_api_2345/INBOX with ID 1737363727-1500739833 488s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1493]: Created message in test_vm_api_2345/INBOX with ID 1737363727-719848782 488s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1502]: Playing back message from invalid mailbox 488s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1505]: Playing back message from NULL mailbox 488s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1508]: Playing back message from invalid context 488s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1511]: Playing back message from invalid folder 488s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1514]: Playing back message from NULL folder 488s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1517]: Playing back message with invalid message specifier 488s [test_voicemail_api.c:voicemail_api_off_nominal_msg_playback:1520]: Playing back message with NULL message specifier 488s END /main/voicemail_api/ - off_nominal_msg_playback Time: 6ms Result: PASS 488s START /main/voicemail_api/ - nominal_msg_playback 488s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1431]: Created message in test_vm_api_1234/Old with ID 1737363727-909401725 488s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1431]: Created message in test_vm_api_1234/INBOX with ID 1737363727-960311778 488s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1431]: Created message in test_vm_api_2345/INBOX with ID 1737363727-1500739833 488s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1431]: Created message in test_vm_api_2345/INBOX with ID 1737363727-719848782 488s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1443]: Playing back message from test_vm_api_1234 to mock channel 488s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1446]: Playing back message from test_vm_api_2345 to callback function 488s [test_voicemail_api.c:voicemail_api_nominal_msg_playback:1451]: Playing back message from test_vm_api_2345 to callback function with default context 488s END /main/voicemail_api/ - nominal_msg_playback Time: 450ms Result: PASS 488s START /main/voicemail_api/ - off_nominal_forward 488s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1353]: Created message in test_vm_api_1234/Old with ID 1737363727-909401725 488s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1353]: Created message in test_vm_api_1234/INBOX with ID 1737363727-960311778 488s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1353]: Created message in test_vm_api_2345/INBOX with ID 1737363727-1500739833 488s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1353]: Created message in test_vm_api_2345/INBOX with ID 1737363727-719848782 488s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1362]: Test forwarding from an invalid mailbox 488s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1365]: Test forwarding from a NULL mailbox 488s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1368]: Test forwarding from an invalid context 488s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1371]: Test forwarding from an invalid folder 488s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1374]: Test forwarding from a NULL folder 488s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1377]: Test forwarding to an invalid mailbox 488s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1380]: Test forwarding to a NULL mailbox 488s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1383]: Test forwarding to an invalid context 488s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1386]: Test forwarding to an invalid folder 488s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1390]: Test forwarding to a NULL folder 488s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1393]: Test forwarding when no messages are select 488s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1396]: Test forwarding a message that doesn't exist 488s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1400]: Test forwarding multiple messages, where some messages don't exist 488s [test_voicemail_api.c:voicemail_api_off_nominal_forward:1403]: Test forwarding a message with an invalid size specifier 488s END /main/voicemail_api/ - off_nominal_forward Time: 6ms Result: PASS 488s START /main/voicemail_api/ - nominal_forward 488s [test_voicemail_api.c:voicemail_api_nominal_forward:1237]: Created message in test_vm_api_1234/Old with ID 1737363727-909401725 488s [test_voicemail_api.c:voicemail_api_nominal_forward:1237]: Created message in test_vm_api_1234/INBOX with ID 1737363727-960311778 488s [test_voicemail_api.c:voicemail_api_nominal_forward:1237]: Created message in test_vm_api_2345/INBOX with ID 1737363727-1500739833 488s [test_voicemail_api.c:voicemail_api_nominal_forward:1237]: Created message in test_vm_api_2345/INBOX with ID 1737363727-719848782 488s [test_voicemail_api.c:voicemail_api_nominal_forward:1244]: Test forwarding message 0 from test_vm_api_1234 INBOX to test_vm_api_2345 INBOX 488s [test_voicemail_api.c:voicemail_api_nominal_forward:1257]: Test forwarding message 0 from test_vm_api_1234 INBOX with default context to test_vm_api_2345 INBOX 488s [test_voicemail_api.c:voicemail_api_nominal_forward:1270]: Test forwarding message 0 from test_vm_api_1234 INBOX to test_vm_api_2345 INBOX with default context 488s [test_voicemail_api.c:voicemail_api_nominal_forward:1283]: Test forwarding message 0 from test_vm_api_1234 INBOX to test_vm_api_2345 INBOX, deleting original 488s [test_voicemail_api.c:voicemail_api_nominal_forward:1296]: Test forwarding 2 messages from test_vm_api_2345 INBOX to test_vm_api_1234 INBOX[test_voicemail_api.c:voicemail_api_nominal_forward:1309]: Test forwarding 2 messages from test_vm_api_2345 INBOX to test_vm_api_1234 Family, deleting original 488s END /main/voicemail_api/ - nominal_forward Time: 24ms Result: PASS 488s START /main/voicemail_api/ - off_nominal_remove 488s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1178]: Created message in test_vm_api_1234/Old with ID 1737363727-909401725 488s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1178]: Created message in test_vm_api_1234/INBOX with ID 1737363727-960311778 488s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1178]: Created message in test_vm_api_2345/INBOX with ID 1737363727-1500739833 488s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1178]: Created message in test_vm_api_2345/INBOX with ID 1737363727-719848782 488s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1184]: Test removing a single message with an invalid mailbox 488s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1187]: Test removing a single message with a NULL mailbox 488s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1190]: Test removing a single message with an invalid context 488s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1193]: Test removing a single message with an invalid folder 488s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1196]: Test removing a single message with a NULL folder 488s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1199]: Test removing a single message with an invalid message number 488s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1203]: Test removing multiple messages with a single invalid message number 488s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1207]: Test removing no messages with no message numbers 488s [test_voicemail_api.c:voicemail_api_off_nominal_remove:1210]: Test removing multiple messages with an invalid size specifier 488s END /main/voicemail_api/ - off_nominal_remove Time: 6ms Result: PASS 488s START /main/voicemail_api/ - nominal_remove 488s [test_voicemail_api.c:voicemail_api_nominal_remove:1131]: Created message in test_vm_api_1234/Old with ID 1737363727-909401725 488s [test_voicemail_api.c:voicemail_api_nominal_remove:1131]: Created message in test_vm_api_1234/INBOX with ID 1737363727-960311778 488s [test_voicemail_api.c:voicemail_api_nominal_remove:1131]: Created message in test_vm_api_2345/INBOX with ID 1737363727-1500739833 488s [test_voicemail_api.c:voicemail_api_nominal_remove:1131]: Created message in test_vm_api_2345/INBOX with ID 1737363727-719848782 488s [test_voicemail_api.c:voicemail_api_nominal_remove:1139]: Test removing a single message from INBOX 488s [test_voicemail_api.c:voicemail_api_nominal_remove:1142]: Test removing a single message from Old 488s [test_voicemail_api.c:voicemail_api_nominal_remove:1145]: Test removing multiple messages from INBOX 488s END /main/voicemail_api/ - nominal_remove Time: 7ms Result: PASS 488s START /main/voicemail_api/ - off_nominal_move 488s [test_voicemail_api.c:voicemail_api_off_nominal_move:1059]: Created message in test_vm_api_1234/Old with ID 1737363727-909401725 488s [test_voicemail_api.c:voicemail_api_off_nominal_move:1059]: Created message in test_vm_api_1234/INBOX with ID 1737363727-960311778 488s [test_voicemail_api.c:voicemail_api_off_nominal_move:1059]: Created message in test_vm_api_2345/INBOX with ID 1737363727-1500739833 488s [test_voicemail_api.c:voicemail_api_off_nominal_move:1059]: Created message in test_vm_api_2345/INBOX with ID 1737363727-719848782 488s [test_voicemail_api.c:voicemail_api_off_nominal_move:1068]: Test move attempt for invalid mailbox test_vm_3456 488s [test_voicemail_api.c:voicemail_api_off_nominal_move:1073]: Test move attempt for invalid context test_vm_api_defunct 488s [test_voicemail_api.c:voicemail_api_off_nominal_move:1076]: Test move attempt to invalid folder 488s [test_voicemail_api.c:voicemail_api_off_nominal_move:1079]: Test move attempt from invalid folder 488s [test_voicemail_api.c:voicemail_api_off_nominal_move:1082]: Test move attempt to NULL folder 488s [test_voicemail_api.c:voicemail_api_off_nominal_move:1085]: Test move attempt from NULL folder 488s [test_voicemail_api.c:voicemail_api_off_nominal_move:1088]: Test move attempt with non-existent message number 488s [test_voicemail_api.c:voicemail_api_off_nominal_move:1092]: Test move attempt with invalid message number 488s [test_voicemail_api.c:voicemail_api_off_nominal_move:1096]: Test move attempt with 0 number of messages 488s [test_voicemail_api.c:voicemail_api_off_nominal_move:1100]: Test move attempt with invalid number of messages 488s [test_voicemail_api.c:voicemail_api_off_nominal_move:1103]: Test move attempt with non-existent multiple messages, where some messages exist 488s END /main/voicemail_api/ - off_nominal_move Time: 6ms Result: PASS 488s START /main/voicemail_api/ - nominal_move 488s [test_voicemail_api.c:voicemail_api_nominal_move:985]: Created message in test_vm_api_1234/Old with ID 1737363727-909401725 488s [test_voicemail_api.c:voicemail_api_nominal_move:985]: Created message in test_vm_api_1234/INBOX with ID 1737363727-960311778 488s [test_voicemail_api.c:voicemail_api_nominal_move:985]: Created message in test_vm_api_2345/INBOX with ID 1737363727-1500739833 488s [test_voicemail_api.c:voicemail_api_nominal_move:985]: Created message in test_vm_api_2345/INBOX with ID 1737363727-719848782 488s [test_voicemail_api.c:voicemail_api_nominal_move:992]: Test move of test_vm_api_1234 message from INBOX to Family 488s [test_voicemail_api.c:voicemail_api_nominal_move:995]: Test move of test_vm_api_1234 message from Old to Family 488s [test_voicemail_api.c:voicemail_api_nominal_move:1009]: Test move of test_vm_api_2345 messages from Inbox to Family 488s [test_voicemail_api.c:voicemail_api_nominal_move:1020]: Test move of test_vm_api_2345 message from Family to INBOX 488s END /main/voicemail_api/ - nominal_move Time: 10ms Result: PASS 488s START /main/voicemail_api/ - off_nominal_snapshot 488s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:945]: Created message in test_vm_api_1234/Old with ID 1737363727-909401725 488s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:945]: Created message in test_vm_api_1234/INBOX with ID 1737363727-960311778 488s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:945]: Created message in test_vm_api_2345/INBOX with ID 1737363727-1500739833 488s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:945]: Created message in test_vm_api_2345/INBOX with ID 1737363727-719848782 488s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:947]: Test access to non-existent mailbox test_vm_api_3456 488s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:950]: Test access to null mailbox 488s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:953]: Test access non-existent context test_vm_api_defunct 488s [test_voicemail_api.c:voicemail_api_off_nominal_snapshot:956]: Test non-existent folder test_vm_api_platypus 488s END /main/voicemail_api/ - off_nominal_snapshot Time: 4ms Result: PASS 488s START /main/voicemail_api/ - nominal_snapshot 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:854]: Created message in test_vm_api_1234/Old with ID 1737363727-909401725 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:854]: Created message in test_vm_api_1234/INBOX with ID 1737363727-960311778 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:854]: Created message in test_vm_api_2345/INBOX with ID 1737363727-1500739833 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:854]: Created message in test_vm_api_2345/INBOX with ID 1737363727-719848782 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:856]: Test retrieving message 1 from INBOX of test_vm_1234 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:859]: Found message 1737363727-960311778 in snapshot 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:862]: Test retrieving message 0 from Old of test_vm_1234 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:865]: Found message 1737363727-909401725 in snapshot 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:868]: Test retrieving message 0, 1 from Old and INBOX of test_vm_1234 ordered by time 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:871]: Found message 1737363727-909401725 in snapshot 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:872]: Found message 1737363727-960311778 in snapshot 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:875]: Test retrieving message 1, 0 from Old and INBOX of test_vm_1234 ordered by time desc 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:878]: Found message 1737363727-960311778 in snapshot 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:879]: Found message 1737363727-909401725 in snapshot 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:882]: Test retrieving message 0, 1 from Old and INBOX of test_vm_1234 ordered by id 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:885]: Found message 1737363727-960311778 in snapshot 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:886]: Found message 1737363727-909401725 in snapshot 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:889]: Test retrieving message 1, 0 from Old and INBOX of test_vm_1234 ordered by id desc 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:892]: Found message 1737363727-909401725 in snapshot 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:893]: Found message 1737363727-960311778 in snapshot 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:896]: Test retrieving message 0, 1 from all folders of test_vm_1234 ordered by id 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:899]: Found message 1737363727-909401725 in snapshot 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:900]: Found message 1737363727-960311778 in snapshot 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:903]: Test retrieving message 0, 1 from all folders of test_vm_1234 ordered by time 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:906]: Found message 1737363727-909401725 in snapshot 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:907]: Found message 1737363727-960311778 in snapshot 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:910]: Test retrieving message 0, 1 from all folders of test_vm_1234, default context ordered by time 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:913]: Found message 1737363727-909401725 in snapshot 488s [test_voicemail_api.c:voicemail_api_nominal_snapshot:914]: Found message 1737363727-960311778 in snapshot 488s END /main/voicemail_api/ - nominal_snapshot Time: 12ms Result: PASS 488s START /main/xml_escape/ - xml_escape_test 488s END /main/xml_escape/ - xml_escape_test Time: <1ms Result: PASS 488s START /mwi/ - explicit_publish 488s END /mwi/ - explicit_publish Time: 40ms Result: PASS 488s START /mwi/ - implicit_publish 488s END /mwi/ - implicit_publish Time: 45ms Result: PASS 488s START /res/adsi/ - adsi_loaded_test 488s END /res/adsi/ - adsi_loaded_test Time: <1ms Result: PASS 488s START /res/aeap/ - send_msg_handle_request 488s END /res/aeap/ - send_msg_handle_request Time: 1ms Result: PASS 488s START /res/aeap/ - send_msg_handle_response 488s END /res/aeap/ - send_msg_handle_response Time: <1ms Result: PASS 488s START /res/aeap/ - send_msg_handle_string 490s END /res/aeap/ - send_msg_handle_string Time: 1999ms Result: PASS 490s START /res/aeap/ - create_and_connect 490s END /res/aeap/ - create_and_connect Time: <1ms Result: PASS 490s START /res/aeap/speech/ - res_speech_aeap_test 490s END /res/aeap/speech/ - res_speech_aeap_test Time: 2ms Result: PASS 490s START /res/aeap/transaction/ - transaction_exec_timeout 490s END /res/aeap/transaction/ - transaction_exec_timeout Time: 99ms Result: PASS 490s START /res/aeap/transaction/ - transaction_exec 491s END /res/aeap/transaction/ - transaction_exec Time: 1000ms Result: PASS 491s START /res/aeap/transport/ - transport_create_invalid 491s END /res/aeap/transport/ - transport_create_invalid Time: <1ms Result: PASS 491s START /res/aeap/transport/ - transport_create 491s END /res/aeap/transport/ - transport_create Time: <1ms Result: PASS 491s START /res/aeap/transport/ - transport_connect 491s END /res/aeap/transport/ - transport_connect Time: <1ms Result: PASS 491s START /res/aeap/transport/ - transport_connect_fail 491s END /res/aeap/transport/ - transport_connect_fail Time: <1ms Result: PASS 491s START /res/aeap/transport/ - transport_binary 491s END /res/aeap/transport/ - transport_binary Time: <1ms Result: PASS 491s START /res/aeap/transport/ - transport_string 491s END /res/aeap/transport/ - transport_string Time: <1ms Result: PASS 491s START /res/agi/ - agi_loaded_test 491s END /res/agi/ - agi_loaded_test Time: <1ms Result: PASS 491s START /res/agi/ - null_agi_docs 491s END /res/agi/ - null_agi_docs Time: <1ms Result: PASS 491s START /res/ari/ - invoke_not_found 491s END /res/ari/ - invoke_not_found Time: <1ms Result: PASS 491s START /res/ari/ - invoke_bad_post 491s END /res/ari/ - invoke_bad_post Time: <1ms Result: PASS 491s START /res/ari/ - invoke_post 491s END /res/ari/ - invoke_post Time: <1ms Result: PASS 491s START /res/ari/ - invoke_delete 491s END /res/ari/ - invoke_delete Time: <1ms Result: PASS 491s START /res/ari/ - invoke_wildcard 491s END /res/ari/ - invoke_wildcard Time: <1ms Result: PASS 491s START /res/ari/ - invoke_get 491s END /res/ari/ - invoke_get Time: <1ms Result: PASS 491s START /res/ari/ - get_docs_hackerz 491s END /res/ari/ - get_docs_hackerz Time: <1ms Result: PASS 491s START /res/ari/ - get_docs_notfound 491s END /res/ari/ - get_docs_notfound Time: <1ms Result: PASS 491s START /res/ari/ - get_docs_nohost 491s END /res/ari/ - get_docs_nohost Time: <1ms Result: PASS 491s START /res/ari/ - get_docs 491s END /res/ari/ - get_docs Time: <1ms Result: PASS 491s START /res/crypto/ - crypto_loaded_test 491s END /res/crypto/ - crypto_loaded_test Time: <1ms Result: PASS 491s START /res/http_media_cache/ - retrieve_content_type 491s END /res/http_media_cache/ - retrieve_content_type Time: 2ms Result: PASS 491s START /res/http_media_cache/ - retrieve_parsed_uri 491s END /res/http_media_cache/ - retrieve_parsed_uri Time: <1ms Result: PASS 491s START /res/http_media_cache/ - retrieve_cache_control_directives 491s [test_http_media_cache.c:retrieve_cache_control_directives:322]: Testing no-cache... 491s [test_http_media_cache.c:retrieve_cache_control_directives:329]: Testing no-cache with ETag... 491s [test_http_media_cache.c:retrieve_cache_control_directives:339]: Testing no-cache with max-age... 491s [test_http_media_cache.c:retrieve_cache_control_directives:344]: Checking 1737364033 >= 1737364030 and 1737364027 <= 1737364030 491s [test_http_media_cache.c:retrieve_cache_control_directives:351]: Testing must-revalidate... 491s [test_http_media_cache.c:retrieve_cache_control_directives:358]: Testing must-revalidate with ETag... 491s [test_http_media_cache.c:retrieve_cache_control_directives:368]: Testing must-revalidate with max-age... 491s [test_http_media_cache.c:retrieve_cache_control_directives:373]: Checking 1737364033 >= 1737364030 and 1737364027 <= 1737364030 491s END /res/http_media_cache/ - retrieve_cache_control_directives Time: 3ms Result: PASS 491s START /res/http_media_cache/ - retrieve_cache_control_age 491s [test_http_media_cache.c:retrieve_cache_control_age:406]: Testing max-age... 491s [test_http_media_cache.c:retrieve_cache_control_age:410]: Checking 1737364033 >= 1737364030 and 1737364027 <= 1737364030 491s [test_http_media_cache.c:retrieve_cache_control_age:414]: Testing s-maxage... 491s [test_http_media_cache.c:retrieve_cache_control_age:420]: Checking 1737364033 >= 1737364030 and 1737364027 <= 1737364030 491s [test_http_media_cache.c:retrieve_cache_control_age:424]: Testing max-age and s-maxage... 491s [test_http_media_cache.c:retrieve_cache_control_age:430]: Checking 1737364333 >= 1737364330 and 1737364327 <= 1737364330 491s [test_http_media_cache.c:retrieve_cache_control_age:434]: Testing max-age and Expires... 491s [test_http_media_cache.c:retrieve_cache_control_age:441]: Checking 1737364033 >= 1737364030 and 1737364027 <= 1737364030 491s [test_http_media_cache.c:retrieve_cache_control_age:445]: Testing s-maxage and Expires... 491s [test_http_media_cache.c:retrieve_cache_control_age:452]: Checking 1737364033 >= 1737364030 and 1737364027 <= 1737364030 491s [test_http_media_cache.c:retrieve_cache_control_age:456]: Testing s-maxage and Expires... 491s [test_http_media_cache.c:retrieve_cache_control_age:463]: Checking 1737364033 >= 1737364030 and 1737364027 <= 1737364030 491s [test_http_media_cache.c:retrieve_cache_control_age:467]: Testing max-age, s-maxage, and Expires... 491s [test_http_media_cache.c:retrieve_cache_control_age:474]: Checking 1737364333 >= 1737364330 and 1737364327 <= 1737364330 491s END /res/http_media_cache/ - retrieve_cache_control_age Time: 3ms Result: PASS 491s START /res/http_media_cache/ - retrieve_etag_expired 491s [test_http_media_cache.c:retrieve_etag_expired:514]: Checking 1737363732 >= 1737363729 and 1737363726 <= 1737363729 491s END /res/http_media_cache/ - retrieve_etag_expired Time: <1ms Result: PASS 491s START /res/http_media_cache/ - retrieve_expires 491s [test_http_media_cache.c:retrieve_expires:554]: Checking 1737366733 >= 1737366730 and 1737366727 <= 1737366730 491s [test_http_media_cache.c:retrieve_expires:564]: Checking 1737363732 >= 1737363729 and 1737363726 <= 1737363729 491s END /res/http_media_cache/ - retrieve_expires Time: <1ms Result: PASS 491s START /res/http_media_cache/ - retrieve_etag 491s [test_http_media_cache.c:retrieve_etag:604]: Checking 1737363733 >= 1737363730 and 1737363727 <= 1737363730 491s END /res/http_media_cache/ - retrieve_etag Time: <1ms Result: PASS 491s START /res/http_media_cache/ - retrieve_nominal 491s [test_http_media_cache.c:retrieve_nominal:642]: Checking 1737363733 >= 1737363730 and 1737363727 <= 1737363730 491s END /res/http_media_cache/ - retrieve_nominal Time: <1ms Result: PASS 491s START /res/http_media_cache/ - create_nominal 491s [test_http_media_cache.c:create_nominal:675]: Checking 1737363733 >= 1737363730 and 1737363727 <= 1737363730 491s END /res/http_media_cache/ - create_nominal Time: <1ms Result: PASS 491s START /res/parking/ - dynamic_parking_variables 491s [parking/parking_tests.c:dynamic_parking_variables:756]: Creating expected configuration for dynamic parking lot 491s [parking/parking_tests.c:dynamic_parking_variables:775]: Creating template lot 491s [parking/parking_tests.c:dynamic_parking_variables:784]: Creating Alice channel to test dynamic parking lot creation. 491s [parking/parking_tests.c:dynamic_parking_variables:794]: Setting Dynamic Parking channel variables on Alice. 491s [parking/parking_tests.c:dynamic_parking_variables:802]: Generating dynamic parking lot based on Alice's channel variables. 491s [parking/parking_tests.c:dynamic_parking_variables:819]: Dynamic parking lot created successfully and matches expectations. Test passed. 491s END /res/parking/ - dynamic_parking_variables Time: <1ms Result: PASS 491s START /res/parking/ - extension_conflicts 491s [parking/parking_tests.c:extension_conflicts:597]: Creating the base lot. This should pass. 491s [parking/parking_tests.c:extension_conflicts:607]: Creating a test lot which will overlap. 491s [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. 491s [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. 491s [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. 491s [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. 491s END /res/parking/ - extension_conflicts Time: <1ms Result: PASS 491s START /res/parking/ - park_extensions 491s [parking/parking_tests.c:park_extensions:551]: Extensions for the test parking lot were verified. Cleaning up and verifying their removal. 491s [parking/parking_tests.c:park_extensions:565]: Extensions for the test parking lot verified as removed. Test completed successfully. 491s END /res/parking/ - park_extensions Time: <1ms Result: PASS 491s START /res/parking/ - park_retrieve 491s [parking/parking_tests.c:retrieve_call:405]: Creating test parking lot 'unit_tests_res_parking_test_lot' 492s [parking/parking_tests.c:retrieve_call:446]: Successfully retrieved parked user from the parking lot. Validating user data. 492s END /res/parking/ - park_retrieve Time: 1001ms Result: PASS 492s START /res/parking/ - park_channel 492s [parking/parking_tests.c:park_call:254]: Creating test parking lot 'unit_tests_res_parking_test_lot' 493s END /res/parking/ - park_channel Time: 1000ms Result: PASS 493s START /res/parking/ - create_lot 493s [parking/parking_tests.c:create_lot:206]: Creating test parking lot 'unit_tests_res_parking_test_lot' 493s [parking/parking_tests.c:create_lot:214]: Successfully created parking lot. Retrieving test parking lot from container. 493s [parking/parking_tests.c:create_lot:223]: Successfully retrieved parking lot. Removing test parking lot from container. 493s [parking/parking_tests.c:create_lot:229]: Parking lot was successfully removed from the container. Test complete. 493s END /res/parking/ - create_lot Time: <1ms Result: PASS 493s START /res/prometheus/ - bridge_to_string 493s [test_res_prometheus.c:bridge_to_string:760]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 493s # TYPE asterisk_channels_count gauge 493s asterisk_channels_count{eid="fa:16:3e:bd:c6:2c"} 0 493s # HELP asterisk_calls_sum Total call count. 493s # TYPE asterisk_calls_sum counter 493s asterisk_calls_sum{eid="fa:16:3e:bd:c6:2c"} 0 493s # HELP asterisk_calls_count Current call count. 493s # TYPE asterisk_calls_count gauge 493s asterisk_calls_count{eid="fa:16:3e:bd:c6:2c"} 0 493s # HELP asterisk_endpoints_count Current endpoint count. 493s # TYPE asterisk_endpoints_count gauge 493s asterisk_endpoints_count{eid="fa:16:3e:bd:c6:2c"} 0 493s # HELP asterisk_bridges_count Current bridge count. 493s # TYPE asterisk_bridges_count gauge 493s asterisk_bridges_count{eid="fa:16:3e:bd:c6:2c"} 3 493s # HELP asterisk_bridges_channels_count Number of channels in the bridge. 493s # TYPE asterisk_bridges_channels_count gauge 493s asterisk_bridges_channels_count{eid="fa:16:3e:bd:c6:2c",id="1366ea0e-f365-43c0-9042-78b8491c8b2b",tech="simple_bridge",subclass="basic",creator="",name=""} 0 493s asterisk_bridges_channels_count{eid="fa:16:3e:bd:c6:2c",id="89eca058-77da-4502-9b87-6f13a7e0932f",tech="simple_bridge",subclass="basic",creator="",name=""} 0 493s 493s END /res/prometheus/ - bridge_to_string Time: <1ms Result: PASS 493s START /res/prometheus/ - config_general_core_metrics 493s [test_res_prometheus.c:config_general_core_metrics:680]: -> CURLing request... 493s [test_res_prometheus.c:config_general_core_metrics:688]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 493s # TYPE asterisk_channels_count gauge 493s asterisk_channels_count{eid="fa:16:3e:bd:c6:2c"} 0 493s # HELP asterisk_calls_sum Total call count. 493s # TYPE asterisk_calls_sum counter 493s asterisk_calls_sum{eid="fa:16:3e:bd:c6:2c"} 0 493s # HELP asterisk_calls_count Current call count. 493s # TYPE asterisk_calls_count gauge 493s asterisk_calls_count{eid="fa:16:3e:bd:c6:2c"} 0 493s # HELP asterisk_endpoints_count Current endpoint count. 493s # TYPE asterisk_endpoints_count gauge 493s asterisk_endpoints_count{eid="fa:16:3e:bd:c6:2c"} 0 493s # HELP asterisk_bridges_count Current bridge count. 493s # TYPE asterisk_bridges_count gauge 493s asterisk_bridges_count{eid="fa:16:3e:bd:c6:2c"} 0 493s # HELP asterisk_core_properties Asterisk instance properties. The value of this will always be 1. 493s # TYPE asterisk_core_properties counter 493s asterisk_core_properties{eid="fa:16:3e:bd:c6:2c",version="22.1.1~dfsg+~cs6.14.60671435-1",build_options="OPTIONAL_API, TEST_FRAMEWORK",build_date="2025-01-12 23:01:35 UTC",build_os="Linux",build_kernel="unknown",build_host="buildd.debian.org"} 1 493s # HELP asterisk_core_uptime_seconds Asterisk instance uptime in seconds. 493s # TYPE asterisk_core_uptime_seconds counter 493s asterisk_core_uptime_seconds{eid="fa:16:3e:bd:c6:2c"} 170 493s # HELP asterisk_core_last_reload_seconds Time since last Asterisk reload in seconds. 493s # TYPE asterisk_core_last_reload_seconds counter 493s asterisk_core_last_reload_seconds{eid="fa:16:3e:bd:c6:2c"} 170 493s # HELP asterisk_core_scrape_time_ms Total time taken to collect metrics, in milliseconds 493s # TYPE asterisk_core_scrape_time_ms counter 493s asterisk_core_scrape_time_ms{eid="fa:16:3e:bd:c6:2c"} 0 493s 493s [test_res_prometheus.c:config_general_core_metrics:690]: -> Checking for core properties 493s [test_res_prometheus.c:config_general_core_metrics:693]: -> Checking for uptime 493s [test_res_prometheus.c:config_general_core_metrics:696]: -> Checking for last reload 493s [test_res_prometheus.c:config_general_core_metrics:699]: -> Checking for scrape time 493s END /res/prometheus/ - config_general_core_metrics Time: <1ms Result: PASS 493s START /res/prometheus/ - config_general_basic_auth 493s [test_res_prometheus.c:config_general_basic_auth:555]: Testing without auth credentials 493s [test_res_prometheus.c:config_general_basic_auth:556]: -> CURLing request... 493s [test_res_prometheus.c:config_general_basic_auth:563]: -> CURL returned 401 493s [test_res_prometheus.c:config_general_basic_auth:566]: Testing with invalid auth credentials 493s [test_res_prometheus.c:config_general_basic_auth:567]: -> CURLing request... 493s [test_res_prometheus.c:config_general_basic_auth:576]: -> CURL returned 401 493s [test_res_prometheus.c:config_general_basic_auth:579]: Testing with valid auth credentials 493s [test_res_prometheus.c:config_general_basic_auth:580]: -> CURLing request... 493s [test_res_prometheus.c:config_general_basic_auth:588]: -> CURL returned 200 493s END /res/prometheus/ - config_general_basic_auth Time: <1ms Result: PASS 493s START /res/prometheus/ - config_general_enabled 493s [test_res_prometheus.c:config_general_enabled:628]: -> CURLing request... 493s [test_res_prometheus.c:config_general_enabled:635]: -> CURL returned 503 493s END /res/prometheus/ - config_general_enabled Time: <1ms Result: PASS 493s START /res/prometheus/ - gauge_create 493s END /res/prometheus/ - gauge_create Time: <1ms Result: PASS 493s START /res/prometheus/ - gauge_to_string 493s END /res/prometheus/ - gauge_to_string Time: <1ms Result: PASS 493s START /res/prometheus/ - counter_create 493s END /res/prometheus/ - counter_create Time: <1ms Result: PASS 493s START /res/prometheus/ - counter_to_string 493s END /res/prometheus/ - counter_to_string Time: <1ms Result: PASS 493s START /res/prometheus/ - metric_register 493s [test_res_prometheus.c:metric_register:291]: Testing nominal registration 493s [test_res_prometheus.c:metric_register:292]: -> Static metric 493s [test_res_prometheus.c:metric_register:294]: -> Malloc'd metric 493s [test_res_prometheus.c:metric_register:300]: Testing nominal registration of child metrics 493s [test_res_prometheus.c:metric_register:315]: Testing name collisions 493s [test_res_prometheus.c:metric_register:322]: Testing label collisions 493s [test_res_prometheus.c:metric_register:331]: Testing removal of metrics 493s END /res/prometheus/ - metric_register Time: <1ms Result: PASS 493s START /res/prometheus/ - metric_callback_register 493s [test_res_prometheus.c:metric_callback_register:241]: -> CURLing request... 493s [test_res_prometheus.c:metric_callback_register:250]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 493s # TYPE asterisk_channels_count gauge 493s asterisk_channels_count{eid="fa:16:3e:bd:c6:2c"} 0 493s # HELP asterisk_calls_sum Total call count. 493s # TYPE asterisk_calls_sum counter 493s asterisk_calls_sum{eid="fa:16:3e:bd:c6:2c"} 0 493s # HELP asterisk_calls_count Current call count. 493s # TYPE asterisk_calls_count gauge 493s asterisk_calls_count{eid="fa:16:3e:bd:c6:2c"} 0 493s # HELP asterisk_endpoints_count Current endpoint count. 493s # TYPE asterisk_endpoints_count gauge 493s asterisk_endpoints_count{eid="fa:16:3e:bd:c6:2c"} 0 493s # HELP asterisk_bridges_count Current bridge count. 493s # TYPE asterisk_bridges_count gauge 493s asterisk_bridges_count{eid="fa:16:3e:bd:c6:2c"} 0 493s # HELP test_counter A test counter 493s # TYPE test_counter counter 493s test_counter 0 493s 493s END /res/prometheus/ - metric_callback_register Time: <1ms Result: PASS 493s START /res/prometheus/ - metric_values 493s [test_res_prometheus.c:metric_values:166]: -> CURLing request... 493s [test_res_prometheus.c:metric_values:176]: -> Retrieved: # HELP asterisk_channels_count Current channel count. 493s # TYPE asterisk_channels_count gauge 493s asterisk_channels_count{eid="fa:16:3e:bd:c6:2c"} 0 493s # HELP asterisk_calls_sum Total call count. 493s # TYPE asterisk_calls_sum counter 493s asterisk_calls_sum{eid="fa:16:3e:bd:c6:2c"} 0 493s # HELP asterisk_calls_count Current call count. 493s # TYPE asterisk_calls_count gauge 493s asterisk_calls_count{eid="fa:16:3e:bd:c6:2c"} 0 493s # HELP asterisk_endpoints_count Current endpoint count. 493s # TYPE asterisk_endpoints_count gauge 493s asterisk_endpoints_count{eid="fa:16:3e:bd:c6:2c"} 0 493s # HELP asterisk_bridges_count Current bridge count. 493s # TYPE asterisk_bridges_count gauge 493s asterisk_bridges_count{eid="fa:16:3e:bd:c6:2c"} 0 493s # HELP test_counter_one A test counter 493s # TYPE test_counter_one counter 493s test_counter_one 1 493s # HELP test_counter_two A test counter 493s # TYPE test_counter_two counter 493s test_counter_two 2 493s 493s END /res/prometheus/ - metric_values Time: <1ms Result: PASS 493s START /res/res_crypto/ - crypto_aes_decrypt 493s [test_crypto.c:crypto_aes_decrypt:607]: Executing AES-ECB decryption test 493s END /res/res_crypto/ - crypto_aes_decrypt Time: 26ms Result: PASS 493s START /res/res_crypto/ - crypto_aes_encrypt 493s [test_crypto.c:crypto_aes_encrypt:531]: Executing AES-ECB encryption test 493s END /res/res_crypto/ - crypto_aes_encrypt Time: 20ms Result: PASS 493s START /res/res_crypto/ - crypto_verify 493s [test_crypto.c:crypto_verify:425]: Executing RSA signature verification test 493s [test_crypto.c:crypto_verify:456]: Couldn't read key: rsa_key1 493s END /res/res_crypto/ - crypto_verify Time: <1ms Result: FAIL 493s START /res/res_crypto/ - crypto_sign 493s [test_crypto.c:crypto_sign:306]: Executing RSA signing test 493s [test_crypto.c:crypto_sign:341]: Couldn't read key: rsa_key1 493s END /res/res_crypto/ - crypto_sign Time: <1ms Result: FAIL 493s START /res/res_crypto/ - crypto_decrypt_pub_key 493s [test_crypto.c:crypto_rsa_decrypt:203]: Executing RSA decryption test 493s [test_crypto.c:crypto_rsa_decrypt:231]: Couldn't read key: rsa_key1 493s END /res/res_crypto/ - crypto_decrypt_pub_key Time: <1ms Result: FAIL 493s START /res/res_crypto/ - crypto_rsa_encrypt 493s [test_crypto.c:crypto_rsa_encrypt:107]: Executing RSA encryption test 493s [test_crypto.c:crypto_rsa_encrypt:138]: Couldn't read key: rsa_key1 493s END /res/res_crypto/ - crypto_rsa_encrypt Time: <1ms Result: FAIL 493s START /res/res_pjproject/ - ast_sockaddr_from_pj_sockaddr_test 493s END /res/res_pjproject/ - ast_sockaddr_from_pj_sockaddr_test Time: <1ms Result: PASS 493s START /res/res_pjproject/ - ast_sockaddr_to_pj_sockaddr_test 493s END /res/res_pjproject/ - ast_sockaddr_to_pj_sockaddr_test Time: <1ms Result: PASS 493s START /res/res_pjsip/ - xml_sanitization_exceeds_buffer 493s END /res/res_pjsip/ - xml_sanitization_exceeds_buffer Time: <1ms Result: PASS 493s START /res/res_pjsip/ - xml_sanitization_end_null 493s END /res/res_pjsip/ - xml_sanitization_end_null Time: <1ms Result: PASS 493s START /res/res_pjsip/scheduler/ - scheduler_policy 493s [test_res_pjsip_scheduler.c:scheduler_policy:355]: This test will take about 4.5 seconds 498s END /res/res_pjsip/scheduler/ - scheduler_policy Time: 4499ms Result: PASS 498s START /res/res_pjsip/scheduler/ - scheduler_cancel 498s [test_res_pjsip_scheduler.c:scheduler_cancel:301]: This test will take about 1.5 seconds 499s END /res/res_pjsip/scheduler/ - scheduler_cancel Time: 1500ms Result: PASS 499s START /res/res_pjsip/scheduler/ - scheduler_cleanup 499s [test_res_pjsip_scheduler.c:scheduler_cleanup:250]: This test will take about 1.6 seconds 501s END /res/res_pjsip/scheduler/ - scheduler_cleanup Time: 1600ms Result: PASS 501s START /res/res_pjsip/scheduler/ - unserialized_scheduler 501s [test_res_pjsip_scheduler.c:scheduler:136]: This test will take about 3.0 seconds 504s END /res/res_pjsip/scheduler/ - unserialized_scheduler Time: 2999ms Result: PASS 504s START /res/res_pjsip/scheduler/ - serialized_scheduler 504s [test_res_pjsip_scheduler.c:scheduler:131]: This test will take about 4.0 seconds 508s END /res/res_pjsip/scheduler/ - serialized_scheduler Time: 3999ms Result: PASS 508s START /res/res_pjsip_pubsub/ - bad_event 508s END /res/res_pjsip_pubsub/ - bad_event Time: 5ms Result: PASS 508s START /res/res_pjsip_pubsub/ - loop 508s END /res/res_pjsip_pubsub/ - loop Time: <1ms Result: PASS 508s START /res/res_pjsip_pubsub/ - duplicate_resource 508s END /res/res_pjsip_pubsub/ - duplicate_resource Time: <1ms Result: PASS 508s START /res/res_pjsip_pubsub/ - bad_branch 508s END /res/res_pjsip_pubsub/ - bad_branch Time: <1ms Result: PASS 508s START /res/res_pjsip_pubsub/ - bad_resource 508s END /res/res_pjsip_pubsub/ - bad_resource Time: <1ms Result: PASS 508s START /res/res_pjsip_pubsub/ - complex_resource_tree 508s END /res/res_pjsip_pubsub/ - complex_resource_tree Time: <1ms Result: PASS 508s START /res/res_pjsip_pubsub/ - resource_tree 508s END /res/res_pjsip_pubsub/ - resource_tree Time: <1ms Result: PASS 508s START /res/res_pjsip_session/ - merge_refresh_topologies 508s [res_pjsip_session.c:test_resolve_refresh_media_states:5892]: Test 1 passed 508s [res_pjsip_session.c:test_resolve_refresh_media_states:5912]: Test 2 passed 508s [res_pjsip_session.c:test_resolve_refresh_media_states:5936]: Test 3 passed 508s [res_pjsip_session.c:test_resolve_refresh_media_states:5955]: Test 4 passed 508s [res_pjsip_session.c:test_resolve_refresh_media_states:5973]: Test 5 passed 508s [res_pjsip_session.c:test_resolve_refresh_media_states:5994]: Test 6 passed 508s [res_pjsip_session.c:test_resolve_refresh_media_states:6020]: Test 7 passed 508s [res_pjsip_session.c:test_resolve_refresh_media_states:6041]: Test 8 passed 508s [res_pjsip_session.c:test_resolve_refresh_media_states:6061]: Test 9 passed 508s [res_pjsip_session.c:test_resolve_refresh_media_states:6081]: Test 10 passed 508s [res_pjsip_session.c:test_resolve_refresh_media_states:6104]: Test 11 passed 508s [res_pjsip_session.c:test_resolve_refresh_media_states:6129]: Test 12 passed 508s [res_pjsip_session.c:test_resolve_refresh_media_states:6163]: Test 13 passed 508s [res_pjsip_session.c:test_resolve_refresh_media_states:6187]: Test 14 passed 508s [res_pjsip_session.c:test_resolve_refresh_media_states:6211]: Test 15 passed 508s END /res/res_pjsip_session/ - merge_refresh_topologies Time: 1ms Result: PASS 508s START /res/res_pjsip_session/caps/ - low_level 508s [test_res_pjsip_session_caps.c:low_level:134]: Testing incoming expected pass 508s [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) 508s [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) 508s [test_res_pjsip_session_caps.c:test_create_joint:60]: Testing local: (slin), remote: (all), pref: (local ), outgoing: (no ), expected: (slin) expected result: (PASS) 508s [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) 508s [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) 508s [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) 508s [test_res_pjsip_session_caps.c:low_level:142]: Testing incoming expected fail 508s [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) 508s [test_res_pjsip_session_caps.c:test_create_joint:102]: Expected Failure: Expected: () Actual: (nothing) 508s [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) 508s [test_res_pjsip_session_caps.c:test_create_joint:81]: Expected Failure: Invalid preference string incoming/outgoing combination. 508s [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) 508s [test_res_pjsip_session_caps.c:test_create_joint:81]: Expected Failure: Invalid preference string incoming/outgoing combination. 508s [test_res_pjsip_session_caps.c:low_level:147]: Testing outgoing expected pass 508s [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) 508s [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) 508s [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) 508s [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) 508s [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) 508s [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) 508s [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) 508s END /res/res_pjsip_session/caps/ - low_level Time: 1ms Result: PASS 508s START /res/res_resolver_unbound/ - resolve_srv 508s END /res/res_resolver_unbound/ - resolve_srv Time: 3ms Result: PASS 508s START /res/res_resolver_unbound/ - resolve_naptr 508s END /res/res_resolver_unbound/ - resolve_naptr Time: <1ms Result: PASS 508s START /res/res_resolver_unbound/ - resolve_cancel_off_nominal 508s END /res/res_resolver_unbound/ - resolve_cancel_off_nominal Time: 4ms Result: PASS 508s START /res/res_resolver_unbound/ - resolve_async_off_nominal 508s [res_resolver_unbound.c:off_nominal_async_run:1004]: Performing DNS query 'duck.feathers', type 1 508s [res_resolver_unbound.c:off_nominal_async_run:1004]: Performing DNS query 'goose.feathers', type 28 508s [res_resolver_unbound.c:off_nominal_async_run:1004]: Performing DNS query 'goose.feathers', type 1 508s [res_resolver_unbound.c:off_nominal_async_run:1004]: Performing DNS query '.1', type 1 508s [res_resolver_unbound.c:off_nominal_async_run:1004]: Performing DNS query '.www', type 1 508s [res_resolver_unbound.c:off_nominal_async_run:1004]: Performing DNS query '.1', type 12 508s [res_resolver_unbound.c:off_nominal_async_run:1004]: Performing DNS query '.www', type 12 508s END /res/res_resolver_unbound/ - resolve_async_off_nominal Time: <1ms Result: PASS 508s START /res/res_resolver_unbound/ - resolve_sync_off_nominal 508s END /res/res_resolver_unbound/ - resolve_sync_off_nominal Time: <1ms Result: PASS 508s START /res/res_resolver_unbound/ - resolve_async 508s [res_resolver_unbound.c:nominal_async_run:721]: Performing DNS query 'goose.feathers', type 1 508s [res_resolver_unbound.c:nominal_async_run:721]: Performing DNS query 'goose.feathers', type 28 508s [res_resolver_unbound.c:nominal_async_run:721]: Performing DNS query 'duck.feathers', type 1 508s END /res/res_resolver_unbound/ - resolve_async Time: <1ms Result: PASS 508s START /res/res_resolver_unbound/ - resolve_sync 508s [res_resolver_unbound.c:nominal_sync_run:571]: Performing DNS query 'goose.feathers', type 1 508s [res_resolver_unbound.c:nominal_sync_run:571]: Performing DNS query 'goose.feathers', type 28 508s [res_resolver_unbound.c:nominal_sync_run:571]: Performing DNS query 'duck.feathers', type 1 508s END /res/res_resolver_unbound/ - resolve_sync Time: <1ms Result: PASS 508s START /res/res_rtp/ - fir_nominal 508s END /res/res_rtp/ - fir_nominal Time: 1ms Result: PASS 508s START /res/res_rtp/ - sr_rr_nominal 508s END /res/res_rtp/ - sr_rr_nominal Time: <1ms Result: PASS 508s START /res/res_rtp/ - remb_nominal 508s END /res/res_rtp/ - remb_nominal Time: <1ms Result: PASS 508s START /res/res_rtp/ - lost_packet_stats_nominal 508s END /res/res_rtp/ - lost_packet_stats_nominal Time: <1ms Result: PASS 508s START /res/res_rtp/ - nack_overflow 508s END /res/res_rtp/ - nack_overflow Time: <1ms Result: PASS 508s START /res/res_rtp/ - nack_nominal 508s END /res/res_rtp/ - nack_nominal Time: <1ms Result: PASS 508s START /res/res_rtp/ - nack_no_packet_loss 508s END /res/res_rtp/ - nack_no_packet_loss Time: <1ms Result: PASS 508s START /res/res_sorcery_memory_cache/ - full_backend_cache_stale 523s END /res/res_sorcery_memory_cache/ - full_backend_cache_stale Time: 15000ms Result: PASS 523s START /res/res_sorcery_memory_cache/ - full_backend_cache_expiration 528s END /res/res_sorcery_memory_cache/ - full_backend_cache_expiration Time: 5000ms Result: PASS 528s START /res/res_sorcery_memory_cache/ - expiration 533s END /res/res_sorcery_memory_cache/ - expiration Time: 4999ms Result: PASS 533s START /res/res_sorcery_memory_cache/ - maximum_objects 533s END /res/res_sorcery_memory_cache/ - maximum_objects Time: 4ms Result: PASS 533s START /res/res_sorcery_memory_cache/ - delete 533s END /res/res_sorcery_memory_cache/ - delete Time: <1ms Result: PASS 533s START /res/res_sorcery_memory_cache/ - create 533s END /res/res_sorcery_memory_cache/ - create Time: <1ms Result: PASS 533s START /res/res_sorcery_memory_cache/ - create 533s END /res/res_sorcery_memory_cache/ - create Time: <1ms Result: PASS 533s START /res/res_sorcery_memory_cache/ - open_with_invalid_options 533s END /res/res_sorcery_memory_cache/ - open_with_invalid_options Time: <1ms Result: PASS 533s START /res/res_sorcery_memory_cache/ - open_with_valid_options 533s END /res/res_sorcery_memory_cache/ - open_with_valid_options Time: <1ms Result: PASS 533s START /res/res_sorcery_memory_cache/ - stale 533s [res_sorcery_memory_cache.c:stale:3189]: Begininning iteration 0 538s [res_sorcery_memory_cache.c:stale:3189]: Begininning iteration 1 543s [res_sorcery_memory_cache.c:stale:3189]: Begininning iteration 2 548s END /res/res_sorcery_memory_cache/ - stale Time: 15002ms Result: PASS 548s START /res/res_sorcery_memory_cache/thrash/ - high_object_count_without_expiration 551s END /res/res_sorcery_memory_cache/thrash/ - high_object_count_without_expiration Time: 3017ms Result: PASS 551s START /res/res_sorcery_memory_cache/thrash/ - conflicting_expire_and_stale 557s END /res/res_sorcery_memory_cache/thrash/ - conflicting_expire_and_stale Time: 6013ms Result: PASS 557s START /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum_with_expire_and_stale 563s END /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum_with_expire_and_stale Time: 6016ms Result: PASS 563s START /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum 566s END /res/res_sorcery_memory_cache/thrash/ - unique_objects_exceeding_maximum Time: 3016ms Result: PASS 566s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_high_concurrent_updates 569s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_high_concurrent_updates Time: 3027ms Result: PASS 569s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_expire 572s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_expire Time: 3032ms Result: PASS 572s START /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_stale 575s END /res/res_sorcery_memory_cache/thrash/ - low_unique_object_count_immediately_stale Time: 3022ms Result: PASS 575s START /res/sorcery_astdb/ - object_delete_uncreated 575s END /res/sorcery_astdb/ - object_delete_uncreated Time: 1ms Result: PASS 575s START /res/sorcery_astdb/ - object_delete 575s END /res/sorcery_astdb/ - object_delete Time: 2ms Result: PASS 575s START /res/sorcery_astdb/ - object_update_uncreated 575s END /res/sorcery_astdb/ - object_update_uncreated Time: <1ms Result: PASS 575s START /res/sorcery_astdb/ - object_update 575s END /res/sorcery_astdb/ - object_update Time: <1ms Result: PASS 575s START /res/sorcery_astdb/ - object_retrieve_regex 575s END /res/sorcery_astdb/ - object_retrieve_regex Time: <1ms Result: PASS 575s START /res/sorcery_astdb/ - object_retrieve_multiple_field 575s END /res/sorcery_astdb/ - object_retrieve_multiple_field Time: <1ms Result: PASS 575s START /res/sorcery_astdb/ - object_retrieve_multiple_all 575s END /res/sorcery_astdb/ - object_retrieve_multiple_all Time: <1ms Result: PASS 575s START /res/sorcery_astdb/ - object_retrieve_field 575s END /res/sorcery_astdb/ - object_retrieve_field Time: <1ms Result: PASS 575s START /res/sorcery_astdb/ - object_retrieve_id 575s END /res/sorcery_astdb/ - object_retrieve_id Time: <1ms Result: PASS 575s START /res/sorcery_astdb/ - object_create 575s END /res/sorcery_astdb/ - object_create Time: <1ms Result: PASS 575s START /res/sorcery_realtime/ - object_filter 575s END /res/sorcery_realtime/ - object_filter Time: <1ms Result: PASS 575s START /res/sorcery_realtime/ - object_allocate_on_retrieval 575s END /res/sorcery_realtime/ - object_allocate_on_retrieval Time: <1ms Result: PASS 575s START /res/sorcery_realtime/ - object_delete_uncreated 575s END /res/sorcery_realtime/ - object_delete_uncreated Time: <1ms Result: PASS 575s START /res/sorcery_realtime/ - object_delete 575s END /res/sorcery_realtime/ - object_delete Time: <1ms Result: PASS 575s START /res/sorcery_realtime/ - object_update 575s END /res/sorcery_realtime/ - object_update Time: <1ms Result: PASS 575s START /res/sorcery_realtime/ - object_retrieve_regex_nofetch 575s END /res/sorcery_realtime/ - object_retrieve_regex_nofetch Time: <1ms Result: PASS 575s START /res/sorcery_realtime/ - object_retrieve_regex 575s END /res/sorcery_realtime/ - object_retrieve_regex Time: <1ms Result: PASS 575s START /res/sorcery_realtime/ - object_retrieve_multiple_field 575s END /res/sorcery_realtime/ - object_retrieve_multiple_field Time: <1ms Result: PASS 575s START /res/sorcery_realtime/ - object_retrieve_multiple_all_nofetch 575s END /res/sorcery_realtime/ - object_retrieve_multiple_all_nofetch Time: <1ms Result: PASS 575s START /res/sorcery_realtime/ - object_retrieve_multiple_all 575s END /res/sorcery_realtime/ - object_retrieve_multiple_all Time: <1ms Result: PASS 575s START /res/sorcery_realtime/ - object_retrieve_field 575s END /res/sorcery_realtime/ - object_retrieve_field Time: <1ms Result: PASS 575s START /res/sorcery_realtime/ - object_retrieve_id 575s END /res/sorcery_realtime/ - object_retrieve_id Time: <1ms Result: PASS 575s START /res/sorcery_realtime/ - object_create 575s END /res/sorcery_realtime/ - object_create Time: <1ms Result: PASS 575s START /res/websocket/ - websocket_client_multiple_protocols 575s END /res/websocket/ - websocket_client_multiple_protocols Time: <1ms Result: PASS 575s START /res/websocket/ - websocket_client_unsupported_protocol 575s END /res/websocket/ - websocket_client_unsupported_protocol Time: <1ms Result: PASS 575s START /res/websocket/ - websocket_client_bad_url 575s END /res/websocket/ - websocket_client_bad_url Time: <1ms Result: PASS 575s START /stasis/channels/ - channel_redirect_snapshot_json 575s END /stasis/channels/ - channel_redirect_snapshot_json Time: 3ms Result: PASS 575s START /stasis/channels/ - channel_snapshot_json 575s END /stasis/channels/ - channel_snapshot_json Time: <1ms Result: PASS 575s START /stasis/channels/ - multi_channel_blob_snapshots 575s END /stasis/channels/ - multi_channel_blob_snapshots Time: <1ms Result: PASS 575s START /stasis/channels/ - multi_channel_blob_create 575s END /stasis/channels/ - multi_channel_blob_create Time: <1ms Result: PASS 575s START /stasis/channels/ - null_blob 575s END /stasis/channels/ - null_blob Time: <1ms Result: PASS 575s START /stasis/channels/ - channel_blob_create 575s END /stasis/channels/ - channel_blob_create Time: <1ms Result: PASS 575s START /stasis/core/ - caching_dtor_order 575s END /stasis/core/ - caching_dtor_order Time: 1ms Result: PASS 575s START /stasis/core/ - dtor_order 575s END /stasis/core/ - dtor_order Time: <1ms Result: PASS 575s START /stasis/core/ - to_ami 575s END /stasis/core/ - to_ami Time: <1ms Result: PASS 575s START /stasis/core/ - no_to_ami 575s END /stasis/core/ - no_to_ami Time: <1ms Result: PASS 575s START /stasis/core/ - to_json 575s END /stasis/core/ - to_json Time: <1ms Result: PASS 575s START /stasis/core/ - no_to_json 575s END /stasis/core/ - no_to_json Time: <1ms Result: PASS 575s START /stasis/core/ - subscription_interleaving 575s END /stasis/core/ - subscription_interleaving Time: <1ms Result: PASS 575s START /stasis/core/ - interleaving 575s END /stasis/core/ - interleaving Time: <1ms Result: PASS 575s START /stasis/core/ - router_cache_updates 575s END /stasis/core/ - router_cache_updates Time: 100ms Result: PASS 575s START /stasis/core/ - router_pool 575s END /stasis/core/ - router_pool Time: <1ms Result: PASS 575s START /stasis/core/ - router 575s END /stasis/core/ - router Time: <1ms Result: PASS 575s START /stasis/core/ - cache_eid_aggregate 575s END /stasis/core/ - cache_eid_aggregate Time: <1ms Result: PASS 575s START /stasis/core/ - cache_dump 575s END /stasis/core/ - cache_dump Time: <1ms Result: PASS 575s START /stasis/core/ - cache 575s END /stasis/core/ - cache Time: <1ms Result: PASS 575s START /stasis/core/ - cache_filter 575s END /stasis/core/ - cache_filter Time: 100ms Result: PASS 575s START /stasis/core/ - forward 575s END /stasis/core/ - forward Time: <1ms Result: PASS 575s START /stasis/core/ - unsubscribe_stops_messages 576s END /stasis/core/ - unsubscribe_stops_messages Time: 100ms Result: PASS 576s START /stasis/core/ - publish_pool 576s END /stasis/core/ - publish_pool Time: <1ms Result: PASS 576s START /stasis/core/ - publish_sync 576s END /stasis/core/ - publish_sync Time: <1ms Result: PASS 576s START /stasis/core/ - publish 576s END /stasis/core/ - publish Time: <1ms Result: PASS 576s START /stasis/core/ - subscription_pool_messages 576s END /stasis/core/ - subscription_pool_messages Time: <1ms Result: PASS 576s START /stasis/core/ - subscription_messages 576s END /stasis/core/ - subscription_messages Time: <1ms Result: PASS 576s START /stasis/core/ - message 576s END /stasis/core/ - message Time: <1ms Result: PASS 576s START /stasis/core/ - message_type 576s END /stasis/core/ - message_type Time: <1ms Result: PASS 576s START /stasis/core/filtering/ - combo_filters 576s [test_stasis.c:dump_consumer:2198]: Messages received: 7 Final? yes 576s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 576s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType1 Pass 576s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass 576s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMI Pass 576s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass 576s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageJSON Pass 576s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 576s END /stasis/core/filtering/ - combo_filters Time: <1ms Result: PASS 576s START /stasis/core/filtering/ - formatter_filters 576s [test_stasis.c:dump_consumer:2198]: Messages received: 7 Final? yes 576s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 576s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMI Pass 576s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageJSON Pass 576s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass 576s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageAMIEVENT Pass2 576s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageEVENT Pass 576s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 576s END /stasis/core/filtering/ - formatter_filters Time: <1ms Result: PASS 576s START /stasis/core/filtering/ - type_filters 576s [test_stasis.c:dump_consumer:2198]: Messages received: 5 Final? yes 576s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Subscribe 576s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType1 Pass 576s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass 576s [test_stasis.c:dump_consumer:2202]: Message type received: TestMessageType2 Pass2 576s [test_stasis.c:dump_consumer:2202]: Message type received: stasis_subscription_change_type Unsubscribe 576s END /stasis/core/filtering/ - type_filters Time: <1ms Result: PASS 576s START /stasis/core/state/ - explicit_publish 576s END /stasis/core/state/ - explicit_publish Time: 28ms Result: PASS 576s START /stasis/core/state/ - implicit_publish 576s END /stasis/core/state/ - implicit_publish Time: 37ms Result: PASS 576s START /stasis/endpoints/ - channel_messages 576s END /stasis/endpoints/ - channel_messages Time: 1ms Result: PASS 576s START /stasis/endpoints/ - cache_clear 576s END /stasis/endpoints/ - cache_clear Time: <1ms Result: PASS 576s START /stasis/endpoints/ - state_changes 576s END /stasis/endpoints/ - state_changes Time: <1ms Result: PASS 576s START /stasis/res/ - app_invoke_dne 576s END /stasis/res/ - app_invoke_dne Time: <1ms Result: PASS 576s START /stasis/res/ - app_invoke_one 576s END /stasis/res/ - app_invoke_one Time: <1ms Result: PASS 576s START /stasis/res/ - app_replaced 576s END /stasis/res/ - app_replaced Time: <1ms Result: PASS 576s 576s 659 Test(s) Executed 655 Passed 4 Failed 576s 'U' option is not compatible with remote console mode and has no effect. 576s 576s Results Generated Successfully: /tmp/autopkgtest.jObLj0/build.8V4/src/debian/tests/testmods/output/results.txt 576s 'U' option is not compatible with remote console mode and has no effect. 576s 576s Some test modules were not loaded: 576s 20a21 576s > test_cel.so 576s 53a55 576s > test_message.so 576s Manually disabled: 576s test_message 576s test_cel 576s 576s 'U' option is not compatible with remote console mode and has no effect. 576s 577s autopkgtest [09:03:36]: test asttestmods: -----------------------] 578s asttestmods PASS 578s autopkgtest [09:03:37]: test asttestmods: - - - - - - - - - - results - - - - - - - - - - 578s autopkgtest [09:03:37]: test amr: preparing testbed 5191s nova [W] Skipping flock for amd64 5191s Creating nova instance adt-plucky-amd64-asterisk-20250120-072951-juju-7f2275-prod-proposed-migration-environment-20-ea450aa8-3b4f-4fb9-8316-db17536d758e from image adt/ubuntu-plucky-amd64-server-20250120.img (UUID 6dcf8cbe-dbc3-4abc-a32e-fe359949151c)... 5191s retry: sh returned 1, backing off for 15 seconds and trying again... 5191s retry: sh returned 1, backing off for 15 seconds and trying again... 5191s retry: sh returned 1, backing off for 15 seconds and trying again... 5191s retry: sh returned 1, backing off for 15 seconds and trying again... 5191s nova [E] Failed to issue delete command for server 97e9933c-e454-4423-a68b-4d5ca49660f5 5191s nova [W] Timed out waiting for 97e9933c-e454-4423-a68b-4d5ca49660f5 to get deleted. 5191s Unexpected error: 5191s Traceback (most recent call last): 5191s File "/home/ubuntu/autopkgtest/lib/VirtSubproc.py", line 833, in mainloop 5191s command() 5191s File "/home/ubuntu/autopkgtest/lib/VirtSubproc.py", line 762, in command 5191s r = f(c, ce) 5191s File "/home/ubuntu/autopkgtest/lib/VirtSubproc.py", line 395, in cmd_revert 5191s caller.hook_revert() 5191s File "/home/ubuntu/autopkgtest/virt/autopkgtest-virt-ssh", line 433, in hook_revert 5191s host_setup('revert') 5191s File "/home/ubuntu/autopkgtest/virt/autopkgtest-virt-ssh", line 252, in host_setup 5191s execute_setup_script(command) 5191s File "/home/ubuntu/autopkgtest/virt/autopkgtest-virt-ssh", line 201, in execute_setup_script 5191s (status, out, err) = VirtSubproc.execute_timeout( 5191s File "/home/ubuntu/autopkgtest/lib/VirtSubproc.py", line 155, in execute_timeout 5191s (out, err) = sp.communicate(instr) 5191s File "/usr/lib/python3.8/subprocess.py", line 1028, in communicate 5191s stdout, stderr = self._communicate(input, endtime, timeout) 5191s File "/usr/lib/python3.8/subprocess.py", line 1868, in _communicate 5191s ready = selector.select(timeout) 5191s File "/usr/lib/python3.8/selectors.py", line 415, in select 5191s fd_event_list = self._selector.poll(timeout) 5191s File "/home/ubuntu/autopkgtest/lib/VirtSubproc.py", line 75, in alarm_handler 5191s raise Timeout(to) 5191s VirtSubproc.Timeout: 1800 5191s autopkgtest [10:20:30]: ERROR: testbed failure: unexpected eof from the testbed