play_and_collect_input_failure ....................................2024-01-11 15:29:07.485614 100.00% [DEBUG] switch_ivr_originate.c:2301 Parsing global variables
2024-01-11 15:29:07.485614 100.00% [NOTICE] switch_channel.c:1142 New Channel null/+15553334444 [3249600b-fa32-4768-a4f4-20a18e3460f0]
2024-01-11 15:29:07.485614 100.00% [DEBUG] mod_loopback.c:1371 null/+15553334444 setup codec L16/8000/20
2024-01-11 15:29:07.485614 100.00% [NOTICE] switch_channel.c:1140 Rename Channel null/+15553334444->null/+15553334444 [3249600b-fa32-4768-a4f4-20a18e3460f0]
2024-01-11 15:29:07.485614 100.00% [DEBUG] mod_loopback.c:1836 (null/+15553334444) State Change CS_NEW -> CS_INIT
2024-01-11 15:29:07.505614 100.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_INIT (Cur 1 Tot 1)
2024-01-11 15:29:07.525619 100.00% [DEBUG] switch_core_state_machine.c:624 (null/+15553334444) State INIT
2024-01-11 15:29:07.525619 100.00% [DEBUG] mod_loopback.c:1466 (null/+15553334444) State Change CS_INIT -> CS_ROUTING
2024-01-11 15:29:07.525619 100.00% [DEBUG] switch_core_state_machine.c:624 (null/+15553334444) State INIT going to sleep
2024-01-11 15:29:07.525619 100.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_ROUTING (Cur 1 Tot 1)
2024-01-11 15:29:07.525619 100.00% [DEBUG] switch_core_state_machine.c:640 (null/+15553334444) State ROUTING
2024-01-11 15:29:07.525619 100.00% [DEBUG] switch_ivr_originate.c:67 (null/+15553334444) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2024-01-11 15:29:07.525619 100.00% [DEBUG] switch_core_state_machine.c:640 (null/+15553334444) State ROUTING going to sleep
2024-01-11 15:29:07.525619 100.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_CONSUME_MEDIA (Cur 1 Tot 1)
2024-01-11 15:29:07.525619 100.00% [DEBUG] switch_core_state_machine.c:659 (null/+15553334444) State CONSUME_MEDIA
2024-01-11 15:29:07.525619 100.00% [DEBUG] mod_loopback.c:1545 CHANNEL CONSUME_MEDIA
2024-01-11 15:29:07.525619 100.00% [DEBUG] mod_loopback.c:1554 CHANNEL CONSUME_MEDIA - answering in 0 ms
2024-01-11 15:29:07.525619 100.00% [NOTICE] mod_loopback.c:1562 Channel [null/+15553334444] has been answered
2024-01-11 15:29:07.545613 100.00% [DEBUG] switch_ivr_originate.c:3913 Originate Resulted in Success: [null/+15553334444] Peer UUID: 3249600b-fa32-4768-a4f4-20a18e3460f0
2024-01-11 15:29:07.545613 100.00% [DEBUG] switch_ivr_play_say.c:121 (null/+15553334444) State Change CS_CONSUME_MEDIA -> CS_SOFT_EXECUTE
2024-01-11 15:29:07.588594 96.67% [DEBUG] switch_channel.c:3912 (null/+15553334444) Callstate Change DOWN -> ACTIVE
2024-01-11 15:29:07.628604 96.67% [DEBUG] switch_core_state_machine.c:659 (null/+15553334444) State CONSUME_MEDIA going to sleep
2024-01-11 15:29:07.628604 96.67% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_SOFT_EXECUTE (Cur 1 Tot 1)
2024-01-11 15:29:07.725617 96.67% [DEBUG] switch_core_state_machine.c:653 (null/+15553334444) State SOFT_EXECUTE
2024-01-11 15:29:07.725617 96.67% [DEBUG] switch_core_state_machine.c:397 null/+15553334444 Standard SOFT_EXECUTE
2024-01-11 15:29:07.725617 96.67% [DEBUG] switch_core_state_machine.c:653 (null/+15553334444) State SOFT_EXECUTE going to sleep
2024-01-11 15:29:07.747657 96.67% [DEBUG] switch_ivr_async.c:1504 Record session sample rate: 8000 -> 8000
2024-01-11 15:29:07.747657 96.67% [DEBUG] switch_core_media_bug.c:976 Attaching BUG to null/+15553334444
2024-01-11 15:29:07.768610 96.67% [DEBUG] switch_scheduler.c:263 Added task 3 sched_api_function (none) to run at 1704986948
2024-01-11 15:29:07.768610 96.67% [INFO] switch_ivr_play_say.c:143 Injecting DTMF 1 at +1
2024-01-11 15:29:07.768610 96.67% [DEBUG] switch_scheduler.c:263 Added task 4 sched_api_function (none) to run at 1704986949
2024-01-11 15:29:07.792588 96.67% [INFO] switch_ivr_play_say.c:144 Injecting DTMF 2 at +2
2024-01-11 15:29:07.848596 96.67% [DEBUG] switch_scheduler.c:263 Added task 5 sched_api_function (none) to run at 1704986950
2024-01-11 15:29:07.865613 96.67% [INFO] switch_ivr_play_say.c:145 Injecting DTMF 3 at +3
2024-01-11 15:29:07.865613 96.67% [INFO] mod_test.c:104 codec = L16, rate = 8000, dest = (null)
2024-01-11 15:29:07.885610 96.67% [DEBUG] switch_core_media_bug.c:976 Attaching BUG to null/+15553334444
2024-01-11 15:29:07.905751 96.67% [DEBUG] mod_test.c:349 start-input-timers = 0
2024-01-11 15:29:07.905751 96.67% [DEBUG] mod_test.c:338 no-input-timeout = 15000
2024-01-11 15:29:07.905751 96.67% [DEBUG] mod_test.c:341 speech-timeout = 15000
2024-01-11 15:29:07.905751 96.67% [INFO] mod_test.c:141 load grammar default
2024-01-11 15:29:07.905751 96.67% [DEBUG] switch_ivr_play_say.c:1561 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:07.965621 96.67% [DEBUG] switch_core_io.c:448 Setting BUG Codec L16:100
2024-01-11 15:29:07.965621 96.67% [DEBUG] switch_ivr_async.c:1778 No silence detection configured; assuming start of speech
2024-01-11 15:29:08.365610 96.67% [INFO] switch_channel.c:528 RECV DTMF 1:2000
2024-01-11 15:29:08.365610 96.67% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=1 ms=250 samples=2000
2024-01-11 15:29:08.365610 96.67% [DEBUG] mod_commands.c:5270 Command uuid_recv_dtmf(3249600b-fa32-4768-a4f4-20a18e3460f0 1):
+OK 3249600b-fa32-4768-a4f4-20a18e3460f0 received DTMF 1.

2024-01-11 15:29:08.365610 96.67% [DEBUG] switch_scheduler.c:147 Deleting task 3 sched_api_function (none)
2024-01-11 15:29:08.365610 96.67% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986948365610
2024-01-11 15:29:08.365610 96.67% [DEBUG] switch_ivr_play_say.c:3381 (null/+15553334444) ACCEPT DIGIT 1
2024-01-11 15:29:08.365610 96.67% [DEBUG] switch_ivr_play_say.c:2010 done playing file silence_stream://2000
2024-01-11 15:29:08.385617 96.67% [DEBUG] mod_test.c:316 start_input_timers
2024-01-11 15:29:08.385617 96.67% [INFO] switch_ivr_play_say.c:3515 (null/+15553334444) WAITING FOR RESULT
2024-01-11 15:29:08.385617 96.67% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:09.365613 93.33% [INFO] switch_channel.c:528 RECV DTMF 2:2000
2024-01-11 15:29:09.365613 93.33% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=2 ms=250 samples=2000
2024-01-11 15:29:09.365613 93.33% [DEBUG] mod_commands.c:5270 Command uuid_recv_dtmf(3249600b-fa32-4768-a4f4-20a18e3460f0 2):
+OK 3249600b-fa32-4768-a4f4-20a18e3460f0 received DTMF 2.

2024-01-11 15:29:09.365613 93.33% [DEBUG] switch_scheduler.c:147 Deleting task 4 sched_api_function (none)
2024-01-11 15:29:09.365613 93.33% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986949365613
2024-01-11 15:29:09.365613 93.33% [DEBUG] switch_ivr_play_say.c:3381 (null/+15553334444) ACCEPT DIGIT 2
2024-01-11 15:29:09.385607 93.33% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:10.365612 90.00% [INFO] switch_channel.c:528 RECV DTMF 3:2000
2024-01-11 15:29:10.365612 90.00% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=3 ms=250 samples=2000
2024-01-11 15:29:10.365612 90.00% [DEBUG] mod_commands.c:5270 Command uuid_recv_dtmf(3249600b-fa32-4768-a4f4-20a18e3460f0 3):
+OK 3249600b-fa32-4768-a4f4-20a18e3460f0 received DTMF 3.

2024-01-11 15:29:10.365612 90.00% [DEBUG] switch_scheduler.c:147 Deleting task 5 sched_api_function (none)
2024-01-11 15:29:10.385610 90.00% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986950385610
2024-01-11 15:29:10.385610 90.00% [DEBUG] switch_ivr_play_say.c:3381 (null/+15553334444) ACCEPT DIGIT 3
2024-01-11 15:29:10.385610 90.00% [DEBUG] switch_ivr_play_say.c:3387 (null/+15553334444) MAX DIGITS COLLECTED
2024-01-11 15:29:10.385610 90.00% [DEBUG] mod_test.c:211 Pausing
2024-01-11 15:29:10.385610 90.00% [NOTICE] switch_ivr_play_say.c:154 Hangup null/+15553334444 [CS_SOFT_EXECUTE] [NORMAL_CLEARING]
2024-01-11 15:29:10.406275 90.00% [DEBUG] mod_loopback.c:1524 CHANNEL SWITCH_SIG_KILL - hanging up
 PASS
play_and_collect_input_success ....................................2024-01-11 15:29:11.408435 86.67% [DEBUG] switch_ivr_originate.c:2301 Parsing global variables
2024-01-11 15:29:11.408435 86.67% [NOTICE] switch_channel.c:1142 New Channel null/+15553334444 [01cac016-9639-4b06-aaa2-a865207b01cb]
2024-01-11 15:29:11.408435 86.67% [DEBUG] mod_loopback.c:1371 null/+15553334444 setup codec L16/8000/20
2024-01-11 15:29:11.428574 86.67% [NOTICE] switch_channel.c:1140 Rename Channel null/+15553334444->null/+15553334444 [01cac016-9639-4b06-aaa2-a865207b01cb]
2024-01-11 15:29:11.428574 86.67% [DEBUG] mod_loopback.c:1836 (null/+15553334444) State Change CS_NEW -> CS_INIT
2024-01-11 15:29:11.428574 86.67% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_INIT (Cur 1 Tot 2)
2024-01-11 15:29:11.428574 86.67% [DEBUG] switch_core_state_machine.c:624 (null/+15553334444) State INIT
2024-01-11 15:29:11.428574 86.67% [DEBUG] mod_loopback.c:1466 (null/+15553334444) State Change CS_INIT -> CS_ROUTING
2024-01-11 15:29:11.428574 86.67% [DEBUG] switch_core_state_machine.c:624 (null/+15553334444) State INIT going to sleep
2024-01-11 15:29:11.445779 86.67% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_ROUTING (Cur 1 Tot 2)
2024-01-11 15:29:11.445779 86.67% [DEBUG] switch_core_state_machine.c:640 (null/+15553334444) State ROUTING
2024-01-11 15:29:11.445779 86.67% [DEBUG] switch_ivr_originate.c:67 (null/+15553334444) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2024-01-11 15:29:11.445779 86.67% [DEBUG] switch_core_state_machine.c:640 (null/+15553334444) State ROUTING going to sleep
2024-01-11 15:29:11.445779 86.67% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_CONSUME_MEDIA (Cur 1 Tot 2)
2024-01-11 15:29:11.445779 86.67% [DEBUG] switch_core_state_machine.c:659 (null/+15553334444) State CONSUME_MEDIA
2024-01-11 15:29:11.465611 86.67% [DEBUG] mod_loopback.c:1545 CHANNEL CONSUME_MEDIA
2024-01-11 15:29:11.465611 86.67% [DEBUG] mod_loopback.c:1554 CHANNEL CONSUME_MEDIA - answering in 0 ms
2024-01-11 15:29:11.465611 86.67% [NOTICE] mod_loopback.c:1562 Channel [null/+15553334444] has been answered
2024-01-11 15:29:11.485619 86.67% [DEBUG] switch_ivr_originate.c:3913 Originate Resulted in Success: [null/+15553334444] Peer UUID: 01cac016-9639-4b06-aaa2-a865207b01cb
2024-01-11 15:29:11.485619 86.67% [DEBUG] switch_ivr_play_say.c:156 (null/+15553334444) State Change CS_CONSUME_MEDIA -> CS_SOFT_EXECUTE
2024-01-11 15:29:11.528580 86.67% [DEBUG] switch_channel.c:3912 (null/+15553334444) Callstate Change DOWN -> ACTIVE
2024-01-11 15:29:11.528580 86.67% [DEBUG] switch_core_state_machine.c:659 (null/+15553334444) State CONSUME_MEDIA going to sleep
2024-01-11 15:29:11.528580 86.67% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_SOFT_EXECUTE (Cur 1 Tot 2)
2024-01-11 15:29:11.592584 83.33% [DEBUG] switch_ivr_async.c:1504 Record session sample rate: 8000 -> 8000
2024-01-11 15:29:11.592584 83.33% [DEBUG] switch_core_media_bug.c:976 Attaching BUG to null/+15553334444
2024-01-11 15:29:11.592584 83.33% [DEBUG] switch_scheduler.c:263 Added task 6 sched_api_function (none) to run at 1704986953
2024-01-11 15:29:11.592584 83.33% [INFO] switch_ivr_play_say.c:178 Injecting DTMF 1# at +2
2024-01-11 15:29:11.645611 83.33% [INFO] mod_test.c:104 codec = L16, rate = 8000, dest = (null)
2024-01-11 15:29:11.625616 83.33% [DEBUG] switch_core_state_machine.c:653 (null/+15553334444) State SOFT_EXECUTE
2024-01-11 15:29:11.645611 83.33% [DEBUG] switch_core_state_machine.c:397 null/+15553334444 Standard SOFT_EXECUTE
2024-01-11 15:29:11.645611 83.33% [DEBUG] switch_core_state_machine.c:653 (null/+15553334444) State SOFT_EXECUTE going to sleep
2024-01-11 15:29:11.672577 83.33% [DEBUG] switch_core_media_bug.c:976 Attaching BUG to null/+15553334444
2024-01-11 15:29:11.672577 83.33% [DEBUG] mod_test.c:349 start-input-timers = 0
2024-01-11 15:29:11.692578 83.33% [DEBUG] mod_test.c:338 no-input-timeout = 5000
2024-01-11 15:29:11.692578 83.33% [DEBUG] mod_test.c:341 speech-timeout = 60000
2024-01-11 15:29:11.692578 83.33% [INFO] mod_test.c:141 load grammar default
2024-01-11 15:29:11.705613 83.33% [DEBUG] switch_ivr_play_say.c:1561 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:11.725617 83.33% [DEBUG] switch_core_io.c:448 Setting BUG Codec L16:100
2024-01-11 15:29:11.725617 83.33% [DEBUG] switch_ivr_async.c:1778 No silence detection configured; assuming start of speech
2024-01-11 15:29:12.685667 80.00% [DEBUG] switch_ivr_play_say.c:2010 done playing file silence_stream://1000
2024-01-11 15:29:12.685667 80.00% [DEBUG] mod_test.c:316 start_input_timers
2024-01-11 15:29:12.685667 80.00% [INFO] switch_ivr_play_say.c:3515 (null/+15553334444) WAITING FOR RESULT
2024-01-11 15:29:12.685667 80.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:13.092580 80.00% [INFO] switch_channel.c:528 RECV DTMF 1:2000
2024-01-11 15:29:13.092580 80.00% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=1 ms=250 samples=2000
2024-01-11 15:29:13.092580 80.00% [INFO] switch_channel.c:528 RECV DTMF #:2000
2024-01-11 15:29:13.092580 80.00% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=# ms=250 samples=2000
2024-01-11 15:29:13.092580 80.00% [DEBUG] mod_commands.c:5270 Command uuid_recv_dtmf(01cac016-9639-4b06-aaa2-a865207b01cb 1#):
+OK 01cac016-9639-4b06-aaa2-a865207b01cb received DTMF 1#.

2024-01-11 15:29:13.092580 80.00% [DEBUG] switch_scheduler.c:147 Deleting task 6 sched_api_function (none)
2024-01-11 15:29:13.106451 80.00% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986953106451
2024-01-11 15:29:13.106451 80.00% [DEBUG] switch_ivr_play_say.c:3381 (null/+15553334444) ACCEPT DIGIT 1
2024-01-11 15:29:13.106451 80.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms

TEST FAIL: switch_ivr_play_say.c(186): fst_check_duration: 1456 != 2500 +/- 1000
2024-01-11 15:29:13.106451 80.00% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986953106451
2024-01-11 15:29:13.106451 80.00% [DEBUG] switch_ivr_play_say.c:3360 (null/+15553334444) ACCEPT TERMINATOR #
2024-01-11 15:29:13.106451 80.00% [DEBUG] mod_test.c:211 Pausing
2024-01-11 15:29:13.106451 80.00% [DEBUG] switch_scheduler.c:263 Added task 7 sched_api_function (none) to run at 1704986955
2024-01-11 15:29:13.106451 80.00% [INFO] switch_ivr_play_say.c:193 Injecting DTMF 1# at +2
2024-01-11 15:29:13.106451 80.00% [DEBUG] mod_test.c:349 start-input-timers = 0
2024-01-11 15:29:13.106451 80.00% [DEBUG] mod_test.c:338 no-input-timeout = 5000
2024-01-11 15:29:13.106451 80.00% [DEBUG] mod_test.c:341 speech-timeout = 60000
2024-01-11 15:29:13.125680 80.00% [INFO] mod_test.c:141 load grammar default
2024-01-11 15:29:13.125680 80.00% [DEBUG] mod_test.c:226 Resuming
2024-01-11 15:29:13.125680 80.00% [DEBUG] switch_ivr_play_say.c:1561 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:14.125606 76.67% [DEBUG] switch_ivr_play_say.c:2010 done playing file silence_stream://1000
2024-01-11 15:29:14.125606 76.67% [DEBUG] mod_test.c:316 start_input_timers
2024-01-11 15:29:14.125606 76.67% [INFO] switch_ivr_play_say.c:3515 (null/+15553334444) WAITING FOR RESULT
2024-01-11 15:29:14.125606 76.67% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:15.108611 73.33% [INFO] switch_channel.c:528 RECV DTMF 1:2000
2024-01-11 15:29:15.108611 73.33% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=1 ms=250 samples=2000
2024-01-11 15:29:15.108611 73.33% [INFO] switch_channel.c:528 RECV DTMF #:2000
2024-01-11 15:29:15.108611 73.33% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=# ms=250 samples=2000
2024-01-11 15:29:15.108611 73.33% [DEBUG] mod_commands.c:5270 Command uuid_recv_dtmf(01cac016-9639-4b06-aaa2-a865207b01cb 1#):
+OK 01cac016-9639-4b06-aaa2-a865207b01cb received DTMF 1#.

2024-01-11 15:29:15.108611 73.33% [DEBUG] switch_scheduler.c:147 Deleting task 7 sched_api_function (none)
2024-01-11 15:29:15.132277 73.33% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986955132277
2024-01-11 15:29:15.132277 73.33% [DEBUG] switch_ivr_play_say.c:3381 (null/+15553334444) ACCEPT DIGIT 1
2024-01-11 15:29:15.132277 73.33% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:15.132277 73.33% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986955132277
2024-01-11 15:29:15.132277 73.33% [DEBUG] switch_ivr_play_say.c:3360 (null/+15553334444) ACCEPT TERMINATOR #
2024-01-11 15:29:15.132277 73.33% [DEBUG] mod_test.c:211 Pausing
2024-01-11 15:29:15.132277 73.33% [DEBUG] switch_scheduler.c:263 Added task 8 sched_api_function (none) to run at 1704986957
2024-01-11 15:29:15.148592 73.33% [INFO] switch_ivr_play_say.c:209 Injecting DTMF 1 at +2
2024-01-11 15:29:15.148592 73.33% [DEBUG] mod_test.c:349 start-input-timers = 0
2024-01-11 15:29:15.148592 73.33% [DEBUG] mod_test.c:338 no-input-timeout = 5000
2024-01-11 15:29:15.148592 73.33% [DEBUG] mod_test.c:341 speech-timeout = 60000
2024-01-11 15:29:15.148592 73.33% [INFO] mod_test.c:141 load grammar default
2024-01-11 15:29:15.148592 73.33% [DEBUG] mod_test.c:226 Resuming
2024-01-11 15:29:15.148592 73.33% [DEBUG] switch_ivr_play_say.c:1561 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:16.128581 70.00% [DEBUG] switch_ivr_play_say.c:2010 done playing file silence_stream://1000
2024-01-11 15:29:16.128581 70.00% [DEBUG] mod_test.c:316 start_input_timers
2024-01-11 15:29:16.128581 70.00% [INFO] switch_ivr_play_say.c:3515 (null/+15553334444) WAITING FOR RESULT
2024-01-11 15:29:16.128581 70.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:17.148592 66.67% [INFO] switch_channel.c:528 RECV DTMF 1:2000
2024-01-11 15:29:17.148592 66.67% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=1 ms=250 samples=2000
2024-01-11 15:29:17.148592 66.67% [DEBUG] mod_commands.c:5270 Command uuid_recv_dtmf(01cac016-9639-4b06-aaa2-a865207b01cb 1):
+OK 01cac016-9639-4b06-aaa2-a865207b01cb received DTMF 1.

2024-01-11 15:29:17.148592 66.67% [DEBUG] switch_scheduler.c:147 Deleting task 8 sched_api_function (none)
2024-01-11 15:29:17.148592 66.67% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986957148592
2024-01-11 15:29:17.148592 66.67% [DEBUG] switch_ivr_play_say.c:3381 (null/+15553334444) ACCEPT DIGIT 1
2024-01-11 15:29:17.148592 66.67% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:21.145618 53.33% [DEBUG] mod_test.c:248 NO INPUT TIMEOUT 5017ms
2024-01-11 15:29:21.145618 53.33% [DEBUG] mod_test.c:285 Result: NO INPUT
2024-01-11 15:29:21.165637 53.33% [INFO] switch_ivr_play_say.c:3319 (null/+15553334444) DETECTED SPEECH detected-speech
2024-01-11 15:29:21.165637 53.33% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:22.165608 50.00% [DEBUG] switch_ivr_play_say.c:3546  (null/+15553334444) INTER-DIGIT TIMEOUT is_speech = false; sleep_time >= digit_timeout; sleep_time=5017; last_digit_time=1704986957148592; digit_timeout=5000 
2024-01-11 15:29:22.165608 50.00% [DEBUG] mod_test.c:211 Pausing
2024-01-11 15:29:22.165608 50.00% [DEBUG] switch_scheduler.c:263 Added task 9 sched_api_function (none) to run at 1704986964
2024-01-11 15:29:22.165608 50.00% [INFO] switch_ivr_play_say.c:225 Injecting DTMF 12# at +2
2024-01-11 15:29:22.165608 50.00% [DEBUG] mod_test.c:349 start-input-timers = 0
2024-01-11 15:29:22.165608 50.00% [DEBUG] mod_test.c:338 no-input-timeout = 5000
2024-01-11 15:29:22.165608 50.00% [DEBUG] mod_test.c:341 speech-timeout = 60000
2024-01-11 15:29:22.165608 50.00% [INFO] mod_test.c:141 load grammar default
2024-01-11 15:29:22.165608 50.00% [DEBUG] mod_test.c:226 Resuming
2024-01-11 15:29:22.165608 50.00% [DEBUG] switch_ivr_play_say.c:1561 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:23.165631 46.67% [DEBUG] switch_ivr_play_say.c:2010 done playing file silence_stream://1000
2024-01-11 15:29:23.165631 46.67% [DEBUG] mod_test.c:316 start_input_timers
2024-01-11 15:29:23.165631 46.67% [INFO] switch_ivr_play_say.c:3515 (null/+15553334444) WAITING FOR RESULT
2024-01-11 15:29:23.165631 46.67% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:24.168578 43.33% [INFO] switch_channel.c:528 RECV DTMF 1:2000
2024-01-11 15:29:24.168578 43.33% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=1 ms=250 samples=2000
2024-01-11 15:29:24.168578 43.33% [INFO] switch_channel.c:528 RECV DTMF 2:2000
2024-01-11 15:29:24.168578 43.33% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=2 ms=250 samples=2000
2024-01-11 15:29:24.168578 43.33% [INFO] switch_channel.c:528 RECV DTMF #:2000
2024-01-11 15:29:24.168578 43.33% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=# ms=250 samples=2000
2024-01-11 15:29:24.168578 43.33% [DEBUG] mod_commands.c:5270 Command uuid_recv_dtmf(01cac016-9639-4b06-aaa2-a865207b01cb 12#):
+OK 01cac016-9639-4b06-aaa2-a865207b01cb received DTMF 12#.

2024-01-11 15:29:24.168578 43.33% [DEBUG] switch_scheduler.c:147 Deleting task 9 sched_api_function (none)
2024-01-11 15:29:24.188577 43.33% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986964188577
2024-01-11 15:29:24.188577 43.33% [DEBUG] switch_ivr_play_say.c:3381 (null/+15553334444) ACCEPT DIGIT 1
2024-01-11 15:29:24.188577 43.33% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:24.205772 43.33% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986964205772
2024-01-11 15:29:24.205772 43.33% [DEBUG] switch_ivr_play_say.c:3381 (null/+15553334444) ACCEPT DIGIT 2
2024-01-11 15:29:24.205772 43.33% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:24.205772 43.33% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986964205772
2024-01-11 15:29:24.205772 43.33% [DEBUG] switch_ivr_play_say.c:3360 (null/+15553334444) ACCEPT TERMINATOR #
2024-01-11 15:29:24.205772 43.33% [DEBUG] mod_test.c:211 Pausing
2024-01-11 15:29:24.205772 43.33% [DEBUG] switch_scheduler.c:263 Added task 10 sched_api_function (none) to run at 1704986966
2024-01-11 15:29:24.205772 43.33% [INFO] switch_ivr_play_say.c:241 Injecting DTMF 1 at +2
2024-01-11 15:29:24.205772 43.33% [DEBUG] switch_scheduler.c:263 Added task 11 sched_api_function (none) to run at 1704986968
2024-01-11 15:29:24.205772 43.33% [INFO] switch_ivr_play_say.c:242 Injecting DTMF 2 at +4
2024-01-11 15:29:24.205772 43.33% [DEBUG] switch_scheduler.c:263 Added task 12 sched_api_function (none) to run at 1704986970
2024-01-11 15:29:24.205772 43.33% [INFO] switch_ivr_play_say.c:243 Injecting DTMF 3 at +6
2024-01-11 15:29:24.205772 43.33% [DEBUG] switch_scheduler.c:263 Added task 13 sched_api_function (none) to run at 1704986972
2024-01-11 15:29:24.205772 43.33% [INFO] switch_ivr_play_say.c:244 Injecting DTMF 4 at +8
2024-01-11 15:29:24.205772 43.33% [DEBUG] switch_scheduler.c:263 Added task 14 sched_api_function (none) to run at 1704986974
2024-01-11 15:29:24.205772 43.33% [INFO] switch_ivr_play_say.c:245 Injecting DTMF # at +10
2024-01-11 15:29:24.228578 43.33% [DEBUG] mod_test.c:349 start-input-timers = 0
2024-01-11 15:29:24.228578 43.33% [DEBUG] mod_test.c:338 no-input-timeout = 5000
2024-01-11 15:29:24.228578 43.33% [DEBUG] mod_test.c:341 speech-timeout = 60000
2024-01-11 15:29:24.228578 43.33% [INFO] mod_test.c:141 load grammar default
2024-01-11 15:29:24.228578 43.33% [DEBUG] mod_test.c:226 Resuming
2024-01-11 15:29:24.228578 43.33% [DEBUG] switch_ivr_play_say.c:1561 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:25.209066 40.00% [DEBUG] switch_ivr_play_say.c:2010 done playing file silence_stream://1000
2024-01-11 15:29:25.209066 40.00% [DEBUG] mod_test.c:316 start_input_timers
2024-01-11 15:29:25.209066 40.00% [INFO] switch_ivr_play_say.c:3515 (null/+15553334444) WAITING FOR RESULT
2024-01-11 15:29:25.209066 40.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:26.228580 36.67% [INFO] switch_channel.c:528 RECV DTMF 1:2000
2024-01-11 15:29:26.228580 36.67% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=1 ms=250 samples=2000
2024-01-11 15:29:26.228580 36.67% [DEBUG] mod_commands.c:5270 Command uuid_recv_dtmf(01cac016-9639-4b06-aaa2-a865207b01cb 1):
+OK 01cac016-9639-4b06-aaa2-a865207b01cb received DTMF 1.

2024-01-11 15:29:26.228580 36.67% [DEBUG] switch_scheduler.c:147 Deleting task 10 sched_api_function (none)
2024-01-11 15:29:26.228580 36.67% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986966228580
2024-01-11 15:29:26.228580 36.67% [DEBUG] switch_ivr_play_say.c:3381 (null/+15553334444) ACCEPT DIGIT 1
2024-01-11 15:29:26.228580 36.67% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:28.225614 30.00% [INFO] switch_channel.c:528 RECV DTMF 2:2000
2024-01-11 15:29:28.225614 30.00% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=2 ms=250 samples=2000
2024-01-11 15:29:28.225614 30.00% [DEBUG] mod_commands.c:5270 Command uuid_recv_dtmf(01cac016-9639-4b06-aaa2-a865207b01cb 2):
+OK 01cac016-9639-4b06-aaa2-a865207b01cb received DTMF 2.

2024-01-11 15:29:28.225614 30.00% [DEBUG] switch_scheduler.c:147 Deleting task 11 sched_api_function (none)
2024-01-11 15:29:28.225614 30.00% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986968225614
2024-01-11 15:29:28.225614 30.00% [DEBUG] switch_ivr_play_say.c:3381 (null/+15553334444) ACCEPT DIGIT 2
2024-01-11 15:29:28.225614 30.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:30.226881 23.33% [DEBUG] mod_test.c:248 NO INPUT TIMEOUT 5017ms
2024-01-11 15:29:30.226881 23.33% [DEBUG] mod_test.c:285 Result: NO INPUT
2024-01-11 15:29:30.226881 23.33% [INFO] switch_channel.c:528 RECV DTMF 3:2000
2024-01-11 15:29:30.226881 23.33% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=3 ms=250 samples=2000
2024-01-11 15:29:30.245608 23.33% [DEBUG] mod_commands.c:5270 Command uuid_recv_dtmf(01cac016-9639-4b06-aaa2-a865207b01cb 3):
+OK 01cac016-9639-4b06-aaa2-a865207b01cb received DTMF 3.

2024-01-11 15:29:30.245608 23.33% [DEBUG] switch_scheduler.c:147 Deleting task 12 sched_api_function (none)
2024-01-11 15:29:30.245608 23.33% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986970245608
2024-01-11 15:29:30.245608 23.33% [DEBUG] switch_ivr_play_say.c:3381 (null/+15553334444) ACCEPT DIGIT 3
2024-01-11 15:29:30.245608 23.33% [INFO] switch_ivr_play_say.c:3319 (null/+15553334444) DETECTED SPEECH detected-speech
2024-01-11 15:29:30.245608 23.33% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:32.245614 16.67% [INFO] switch_channel.c:528 RECV DTMF 4:2000
2024-01-11 15:29:32.245614 16.67% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=4 ms=250 samples=2000
2024-01-11 15:29:32.245614 16.67% [DEBUG] mod_commands.c:5270 Command uuid_recv_dtmf(01cac016-9639-4b06-aaa2-a865207b01cb 4):
+OK 01cac016-9639-4b06-aaa2-a865207b01cb received DTMF 4.

2024-01-11 15:29:32.245614 16.67% [DEBUG] switch_scheduler.c:147 Deleting task 13 sched_api_function (none)
2024-01-11 15:29:32.245614 16.67% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986972245614
2024-01-11 15:29:32.245614 16.67% [DEBUG] switch_ivr_play_say.c:3381 (null/+15553334444) ACCEPT DIGIT 4
2024-01-11 15:29:32.245614 16.67% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:34.245621 10.00% [INFO] switch_channel.c:528 RECV DTMF #:2000
2024-01-11 15:29:34.245621 10.00% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=# ms=250 samples=2000
2024-01-11 15:29:34.245621 10.00% [DEBUG] mod_commands.c:5270 Command uuid_recv_dtmf(01cac016-9639-4b06-aaa2-a865207b01cb #):
+OK 01cac016-9639-4b06-aaa2-a865207b01cb received DTMF #.

2024-01-11 15:29:34.245621 10.00% [DEBUG] switch_scheduler.c:147 Deleting task 14 sched_api_function (none)
2024-01-11 15:29:34.245621 10.00% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986974245621
2024-01-11 15:29:34.245621 10.00% [DEBUG] switch_ivr_play_say.c:3360 (null/+15553334444) ACCEPT TERMINATOR #
2024-01-11 15:29:34.245621 10.00% [DEBUG] mod_test.c:211 Pausing
2024-01-11 15:29:34.245621 10.00% [DEBUG] switch_core_media_bug.c:976 Attaching BUG to null/+15553334444
2024-01-11 15:29:34.265619 10.00% [DEBUG] mod_test.c:349 start-input-timers = 0
2024-01-11 15:29:34.265619 10.00% [DEBUG] mod_test.c:338 no-input-timeout = 5000
2024-01-11 15:29:34.265619 10.00% [DEBUG] mod_test.c:341 speech-timeout = 60000
2024-01-11 15:29:34.265619 10.00% [INFO] mod_test.c:141 load grammar default
2024-01-11 15:29:34.265619 10.00% [DEBUG] mod_test.c:226 Resuming
2024-01-11 15:29:34.265619 10.00% [DEBUG] switch_ivr_play_say.c:1561 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:34.505622 10.00% [DEBUG] switch_core_io.c:780 Engaging Read Buffer at 320 bytes vs 160
2024-01-11 15:29:35.085618 6.67% [DEBUG] mod_test.c:292 Result: START OF SPEECH
2024-01-11 15:29:35.085618 6.67% [INFO] switch_ivr_play_say.c:3340 (null/+15553334444) START OF SPEECH
2024-01-11 15:29:35.085618 6.67% [DEBUG] switch_ivr_play_say.c:2010 done playing file silence_stream://1000
2024-01-11 15:29:35.108662 6.67% [DEBUG] mod_test.c:316 start_input_timers
2024-01-11 15:29:35.108662 6.67% [INFO] switch_ivr_play_say.c:3515 (null/+15553334444) WAITING FOR RESULT
2024-01-11 15:29:35.108662 6.67% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:37.025620 0.00% [DEBUG] switch_core_media_bug.c:1326 Removing BUG from null/+15553334444
2024-01-11 15:29:37.025620 0.00% [DEBUG] switch_core_io.c:780 Engaging Read Buffer at 320 bytes vs 0
2024-01-11 15:29:37.565618 0.00% [INFO] mod_test.c:190 Talking stopped, have result.
2024-01-11 15:29:37.565618 0.00% [NOTICE] mod_test.c:277 Final Result: {"grammar": "default", "text": "agent", "confidence": 87.300000}
2024-01-11 15:29:37.565618 0.00% [INFO] switch_ivr_play_say.c:3319 (null/+15553334444) DETECTED SPEECH detected-speech
2024-01-11 15:29:37.565618 0.00% [DEBUG] switch_ivr_play_say.c:3558 
is_speech = true; sleep_time < digit_timeout; sleep_time=5000; last_digit_time=1704986975108662; digit_timeout=5000 
2024-01-11 15:29:37.565618 0.00% [DEBUG] mod_test.c:211 Pausing
2024-01-11 15:29:37.565618 0.00% [DEBUG] switch_scheduler.c:263 Added task 15 sched_api_function (none) to run at 1704986979
2024-01-11 15:29:37.565618 0.00% [INFO] switch_ivr_play_say.c:281 Injecting DTMF 2 at +2
2024-01-11 15:29:37.565618 0.00% [DEBUG] mod_test.c:349 start-input-timers = 0
2024-01-11 15:29:37.565618 0.00% [DEBUG] mod_test.c:338 no-input-timeout = 5000
2024-01-11 15:29:37.565618 0.00% [DEBUG] mod_test.c:341 speech-timeout = 60000
2024-01-11 15:29:37.565618 0.00% [INFO] mod_test.c:141 load grammar default
2024-01-11 15:29:37.565618 0.00% [DEBUG] mod_test.c:226 Resuming
2024-01-11 15:29:37.565618 0.00% [DEBUG] switch_ivr_play_say.c:1561 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:38.565620 0.00% [DEBUG] switch_ivr_play_say.c:2010 done playing file silence_stream://1000
2024-01-11 15:29:38.565620 0.00% [DEBUG] mod_test.c:316 start_input_timers
2024-01-11 15:29:38.565620 0.00% [INFO] switch_ivr_play_say.c:3515 (null/+15553334444) WAITING FOR RESULT
2024-01-11 15:29:38.565620 0.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:39.065620 0.00% [INFO] switch_channel.c:528 RECV DTMF 2:2000
2024-01-11 15:29:39.065620 0.00% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=2 ms=250 samples=2000
2024-01-11 15:29:39.065620 0.00% [DEBUG] mod_commands.c:5270 Command uuid_recv_dtmf(01cac016-9639-4b06-aaa2-a865207b01cb 2):
+OK 01cac016-9639-4b06-aaa2-a865207b01cb received DTMF 2.

2024-01-11 15:29:39.065620 0.00% [DEBUG] switch_scheduler.c:147 Deleting task 15 sched_api_function (none)
2024-01-11 15:29:39.085620 0.00% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986979085620
2024-01-11 15:29:39.085620 0.00% [DEBUG] switch_ivr_play_say.c:3381 (null/+15553334444) ACCEPT DIGIT 2
2024-01-11 15:29:39.085620 0.00% [DEBUG] switch_ivr_play_say.c:3387 (null/+15553334444) MAX DIGITS COLLECTED
2024-01-11 15:29:39.085620 0.00% [DEBUG] mod_test.c:211 Pausing
2024-01-11 15:29:39.085620 0.00% [DEBUG] switch_scheduler.c:263 Added task 16 sched_api_function (none) to run at 1704986981
2024-01-11 15:29:39.105616 0.00% [INFO] switch_ivr_play_say.c:298 Injecting DTMF 259 at +2
2024-01-11 15:29:39.105616 0.00% [DEBUG] mod_test.c:349 start-input-timers = 0
2024-01-11 15:29:39.105616 0.00% [DEBUG] mod_test.c:338 no-input-timeout = 5000
2024-01-11 15:29:39.105616 0.00% [DEBUG] mod_test.c:341 speech-timeout = 60000
2024-01-11 15:29:39.105616 0.00% [INFO] mod_test.c:141 load grammar default
2024-01-11 15:29:39.105616 0.00% [DEBUG] mod_test.c:226 Resuming
2024-01-11 15:29:39.105616 0.00% [DEBUG] switch_ivr_play_say.c:1561 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:40.085641 0.00% [DEBUG] switch_ivr_play_say.c:2010 done playing file silence_stream://1000
2024-01-11 15:29:40.085641 0.00% [DEBUG] mod_test.c:316 start_input_timers
2024-01-11 15:29:40.085641 0.00% [INFO] switch_ivr_play_say.c:3515 (null/+15553334444) WAITING FOR RESULT
2024-01-11 15:29:40.085641 0.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:41.105623 0.00% [INFO] switch_channel.c:528 RECV DTMF 2:2000
2024-01-11 15:29:41.105623 0.00% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=2 ms=250 samples=2000
2024-01-11 15:29:41.105623 0.00% [INFO] switch_channel.c:528 RECV DTMF 5:2000
2024-01-11 15:29:41.105623 0.00% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=5 ms=250 samples=2000
2024-01-11 15:29:41.105623 0.00% [INFO] switch_channel.c:528 RECV DTMF 9:2000
2024-01-11 15:29:41.105623 0.00% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=9 ms=250 samples=2000
2024-01-11 15:29:41.105623 0.00% [DEBUG] mod_commands.c:5270 Command uuid_recv_dtmf(01cac016-9639-4b06-aaa2-a865207b01cb 259):
+OK 01cac016-9639-4b06-aaa2-a865207b01cb received DTMF 259.

2024-01-11 15:29:41.105623 0.00% [DEBUG] switch_scheduler.c:147 Deleting task 16 sched_api_function (none)
2024-01-11 15:29:41.125622 0.00% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986981125622
2024-01-11 15:29:41.125622 0.00% [DEBUG] switch_ivr_play_say.c:3381 (null/+15553334444) ACCEPT DIGIT 2
2024-01-11 15:29:41.125622 0.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:41.125622 0.00% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986981125622
2024-01-11 15:29:41.125622 0.00% [DEBUG] switch_ivr_play_say.c:3381 (null/+15553334444) ACCEPT DIGIT 5
2024-01-11 15:29:41.125622 0.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:41.125622 0.00% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986981125622
2024-01-11 15:29:41.125622 0.00% [DEBUG] switch_ivr_play_say.c:3381 (null/+15553334444) ACCEPT DIGIT 9
2024-01-11 15:29:41.125622 0.00% [DEBUG] switch_ivr_play_say.c:3387 (null/+15553334444) MAX DIGITS COLLECTED
2024-01-11 15:29:41.125622 0.00% [DEBUG] mod_test.c:211 Pausing
2024-01-11 15:29:41.125622 0.00% [DEBUG] switch_scheduler.c:263 Added task 17 sched_api_function (none) to run at 1704986983
2024-01-11 15:29:41.125622 0.00% [INFO] switch_ivr_play_say.c:316 Injecting DTMF 25 at +2
2024-01-11 15:29:41.145620 0.00% [DEBUG] mod_test.c:349 start-input-timers = 0
2024-01-11 15:29:41.145620 0.00% [DEBUG] mod_test.c:338 no-input-timeout = 5000
2024-01-11 15:29:41.145620 0.00% [DEBUG] mod_test.c:341 speech-timeout = 60000
2024-01-11 15:29:41.145620 0.00% [INFO] mod_test.c:141 load grammar default
2024-01-11 15:29:41.145620 0.00% [DEBUG] mod_test.c:226 Resuming
2024-01-11 15:29:41.145620 0.00% [DEBUG] switch_ivr_play_say.c:1561 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:42.125620 0.00% [DEBUG] switch_ivr_play_say.c:2010 done playing file silence_stream://1000
2024-01-11 15:29:42.145618 0.00% [DEBUG] mod_test.c:316 start_input_timers
2024-01-11 15:29:42.145618 0.00% [INFO] switch_ivr_play_say.c:3515 (null/+15553334444) WAITING FOR RESULT
2024-01-11 15:29:42.145618 0.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:43.125614 0.00% [INFO] switch_channel.c:528 RECV DTMF 2:2000
2024-01-11 15:29:43.125614 0.00% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=2 ms=250 samples=2000
2024-01-11 15:29:43.125614 0.00% [INFO] switch_channel.c:528 RECV DTMF 5:2000
2024-01-11 15:29:43.125614 0.00% [DEBUG] switch_channel.c:624 null/+15553334444 Queue dtmf
digit=5 ms=250 samples=2000
2024-01-11 15:29:43.125614 0.00% [DEBUG] mod_commands.c:5270 Command uuid_recv_dtmf(01cac016-9639-4b06-aaa2-a865207b01cb 25):
+OK 01cac016-9639-4b06-aaa2-a865207b01cb received DTMF 25.

2024-01-11 15:29:43.125614 0.00% [DEBUG] switch_scheduler.c:147 Deleting task 17 sched_api_function (none)
2024-01-11 15:29:43.145620 0.00% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986983145620
2024-01-11 15:29:43.145620 0.00% [DEBUG] switch_ivr_play_say.c:3381 (null/+15553334444) ACCEPT DIGIT 2
2024-01-11 15:29:43.145620 0.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:43.145620 0.00% [DEBUG] switch_ivr_play_say.c:3357 
is_speech = false; SWITCH_INPUT_TYPE_DTMF; last_digit_time=1704986983145620
2024-01-11 15:29:43.145620 0.00% [DEBUG] switch_ivr_play_say.c:3381 (null/+15553334444) ACCEPT DIGIT 5
2024-01-11 15:29:43.145620 0.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:47.145620 0.00% [DEBUG] mod_test.c:248 NO INPUT TIMEOUT 5000ms
2024-01-11 15:29:47.145620 0.00% [DEBUG] mod_test.c:285 Result: NO INPUT
2024-01-11 15:29:47.165623 0.00% [INFO] switch_ivr_play_say.c:3319 (null/+15553334444) DETECTED SPEECH detected-speech
2024-01-11 15:29:47.165623 0.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:48.165621 0.00% [DEBUG] switch_ivr_play_say.c:3546  (null/+15553334444) INTER-DIGIT TIMEOUT is_speech = false; sleep_time >= digit_timeout; sleep_time=5020; last_digit_time=1704986983145620; digit_timeout=5000 
2024-01-11 15:29:48.165621 0.00% [DEBUG] mod_test.c:211 Pausing
2024-01-11 15:29:48.165621 0.00% [NOTICE] switch_ivr_play_say.c:335 Hangup null/+15553334444 [CS_SOFT_EXECUTE] [NORMAL_CLEARING]
2024-01-11 15:29:48.165621 0.00% [DEBUG] mod_loopback.c:1524 CHANNEL SWITCH_SIG_KILL - hanging up
 FAIL ***
play_and_collect_input_partial ....................................2024-01-11 15:29:49.165620 0.00% [DEBUG] switch_ivr_originate.c:2301 Parsing global variables
2024-01-11 15:29:49.165620 0.00% [NOTICE] switch_channel.c:1142 New Channel null/+15553334444 [3c573a04-3e2c-45ec-a0b1-f172db03ba21]
2024-01-11 15:29:49.165620 0.00% [DEBUG] mod_loopback.c:1371 null/+15553334444 setup codec L16/8000/20
2024-01-11 15:29:49.188583 0.00% [NOTICE] switch_channel.c:1140 Rename Channel null/+15553334444->null/+15553334444 [3c573a04-3e2c-45ec-a0b1-f172db03ba21]
2024-01-11 15:29:49.188583 0.00% [DEBUG] mod_loopback.c:1836 (null/+15553334444) State Change CS_NEW -> CS_INIT
2024-01-11 15:29:49.188583 0.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_INIT (Cur 1 Tot 3)
2024-01-11 15:29:49.188583 0.00% [DEBUG] switch_core_state_machine.c:624 (null/+15553334444) State INIT
2024-01-11 15:29:49.188583 0.00% [DEBUG] mod_loopback.c:1466 (null/+15553334444) State Change CS_INIT -> CS_ROUTING
2024-01-11 15:29:49.188583 0.00% [DEBUG] switch_core_state_machine.c:624 (null/+15553334444) State INIT going to sleep
2024-01-11 15:29:49.188583 0.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_ROUTING (Cur 1 Tot 3)
2024-01-11 15:29:49.188583 0.00% [DEBUG] switch_core_state_machine.c:640 (null/+15553334444) State ROUTING
2024-01-11 15:29:49.188583 0.00% [DEBUG] switch_ivr_originate.c:67 (null/+15553334444) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2024-01-11 15:29:49.188583 0.00% [DEBUG] switch_core_state_machine.c:640 (null/+15553334444) State ROUTING going to sleep
2024-01-11 15:29:49.188583 0.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_CONSUME_MEDIA (Cur 1 Tot 3)
2024-01-11 15:29:49.208578 0.00% [DEBUG] switch_core_state_machine.c:659 (null/+15553334444) State CONSUME_MEDIA
2024-01-11 15:29:49.208578 0.00% [DEBUG] mod_loopback.c:1545 CHANNEL CONSUME_MEDIA
2024-01-11 15:29:49.208578 0.00% [DEBUG] mod_loopback.c:1554 CHANNEL CONSUME_MEDIA - answering in 0 ms
2024-01-11 15:29:49.208578 0.00% [NOTICE] mod_loopback.c:1562 Channel [null/+15553334444] has been answered
2024-01-11 15:29:49.208578 0.00% [DEBUG] switch_ivr_originate.c:3913 Originate Resulted in Success: [null/+15553334444] Peer UUID: 3c573a04-3e2c-45ec-a0b1-f172db03ba21
2024-01-11 15:29:49.208578 0.00% [DEBUG] switch_ivr_play_say.c:337 (null/+15553334444) State Change CS_CONSUME_MEDIA -> CS_SOFT_EXECUTE
2024-01-11 15:29:49.288577 0.00% [DEBUG] switch_channel.c:3912 (null/+15553334444) Callstate Change DOWN -> ACTIVE
2024-01-11 15:29:49.305610 0.00% [DEBUG] switch_core_state_machine.c:659 (null/+15553334444) State CONSUME_MEDIA going to sleep
2024-01-11 15:29:49.305610 0.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_SOFT_EXECUTE (Cur 1 Tot 3)
2024-01-11 15:29:49.385700 0.00% [DEBUG] switch_ivr_async.c:1504 Record session sample rate: 8000 -> 8000
2024-01-11 15:29:49.385700 0.00% [DEBUG] switch_core_media_bug.c:976 Attaching BUG to null/+15553334444
2024-01-11 15:29:49.425696 0.00% [DEBUG] switch_core_media_bug.c:976 Attaching BUG to null/+15553334444
2024-01-11 15:29:49.425696 0.00% [DEBUG] switch_core_state_machine.c:653 (null/+15553334444) State SOFT_EXECUTE
2024-01-11 15:29:49.425696 0.00% [DEBUG] switch_core_state_machine.c:397 null/+15553334444 Standard SOFT_EXECUTE
2024-01-11 15:29:49.425696 0.00% [DEBUG] switch_core_state_machine.c:653 (null/+15553334444) State SOFT_EXECUTE going to sleep
2024-01-11 15:29:49.425696 0.00% [INFO] mod_test.c:104 codec = L16, rate = 8000, dest = (null)
2024-01-11 15:29:49.446806 0.00% [DEBUG] switch_core_media_bug.c:976 Attaching BUG to null/+15553334444
2024-01-11 15:29:49.485793 0.00% [DEBUG] mod_test.c:349 start-input-timers = 0
2024-01-11 15:29:49.485793 0.00% [DEBUG] mod_test.c:338 no-input-timeout = 500
2024-01-11 15:29:49.485793 0.00% [DEBUG] mod_test.c:341 speech-timeout = 60000
2024-01-11 15:29:49.485793 0.00% [DEBUG] mod_test.c:373 partial = 3
2024-01-11 15:29:49.485793 0.00% [INFO] mod_test.c:141 load grammar default
2024-01-11 15:29:49.485793 0.00% [DEBUG] switch_ivr_play_say.c:1561 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:49.510871 0.00% [DEBUG] switch_core_io.c:448 Setting BUG Codec L16:100
2024-01-11 15:29:49.510871 0.00% [DEBUG] switch_ivr_async.c:1778 No silence detection configured; assuming start of speech
2024-01-11 15:29:49.745612 0.00% [DEBUG] switch_core_io.c:780 Engaging Read Buffer at 320 bytes vs 160
2024-01-11 15:29:50.325638 0.00% [DEBUG] mod_test.c:292 Result: START OF SPEECH
2024-01-11 15:29:50.348581 0.00% [INFO] switch_ivr_play_say.c:3340 (null/+15553334444) START OF SPEECH
2024-01-11 15:29:50.348581 0.00% [DEBUG] switch_ivr_play_say.c:2010 done playing file silence_stream://1000
2024-01-11 15:29:50.348581 0.00% [DEBUG] mod_test.c:316 start_input_timers
2024-01-11 15:29:50.348581 0.00% [INFO] switch_ivr_play_say.c:3515 (null/+15553334444) WAITING FOR RESULT
2024-01-11 15:29:50.348581 0.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:50.865622 0.00% [DEBUG] switch_ivr_play_say.c:3558 
is_speech = true; sleep_time < digit_timeout; sleep_time=500; last_digit_time=1704986990348581; digit_timeout=500 
2024-01-11 15:29:50.865622 0.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:51.365622 0.00% [DEBUG] switch_ivr_play_say.c:3558 
is_speech = true; sleep_time < digit_timeout; sleep_time=500; last_digit_time=1704986990348581; digit_timeout=500 
2024-01-11 15:29:51.365622 0.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:51.885622 0.00% [DEBUG] switch_ivr_play_say.c:3558 
is_speech = true; sleep_time < digit_timeout; sleep_time=500; last_digit_time=1704986990348581; digit_timeout=500 
2024-01-11 15:29:51.885622 0.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:52.265622 0.00% [DEBUG] switch_core_media_bug.c:1326 Removing BUG from null/+15553334444
2024-01-11 15:29:52.265622 0.00% [DEBUG] switch_core_io.c:780 Engaging Read Buffer at 320 bytes vs 0
2024-01-11 15:29:52.385624 0.00% [DEBUG] switch_ivr_play_say.c:3558 
is_speech = true; sleep_time < digit_timeout; sleep_time=500; last_digit_time=1704986990348581; digit_timeout=500 
2024-01-11 15:29:52.385624 0.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:52.805621 0.00% [INFO] mod_test.c:190 Talking stopped, have result.
2024-01-11 15:29:52.805621 0.00% [NOTICE] mod_test.c:277 Partial Result: {"grammar": "default", "text": "agent", "confidence": 87.300000}
2024-01-11 15:29:52.825621 0.00% [NOTICE] mod_test.c:277 Partial Result: {"grammar": "default", "text": "agent", "confidence": 87.300000}
2024-01-11 15:29:52.845620 0.00% [NOTICE] mod_test.c:277 Partial Result: {"grammar": "default", "text": "agent", "confidence": 87.300000}
2024-01-11 15:29:52.865622 0.00% [NOTICE] mod_test.c:277 Final Result: {"grammar": "default", "text": "agent", "confidence": 87.300000}
2024-01-11 15:29:52.865622 0.00% [INFO] switch_ivr_play_say.c:3319 (null/+15553334444) DETECTED SPEECH detected-speech
2024-01-11 15:29:52.865622 0.00% [DEBUG] switch_ivr_play_say.c:3558 
is_speech = true; sleep_time < digit_timeout; sleep_time=500; last_digit_time=1704986990348581; digit_timeout=500 
2024-01-11 15:29:52.865622 0.00% [DEBUG] mod_test.c:211 Pausing
2024-01-11 15:29:52.865622 0.00% [DEBUG] switch_core_media_bug.c:976 Attaching BUG to null/+15553334444
2024-01-11 15:29:52.865622 0.00% [DEBUG] mod_test.c:349 start-input-timers = 0
2024-01-11 15:29:52.865622 0.00% [DEBUG] mod_test.c:338 no-input-timeout = 500
2024-01-11 15:29:52.865622 0.00% [DEBUG] mod_test.c:341 speech-timeout = 60000
2024-01-11 15:29:52.865622 0.00% [DEBUG] mod_test.c:373 partial = 3
2024-01-11 15:29:52.865622 0.00% [INFO] mod_test.c:141 load grammar default
2024-01-11 15:29:52.865622 0.00% [DEBUG] mod_test.c:226 Resuming
2024-01-11 15:29:52.865622 0.00% [DEBUG] switch_ivr_play_say.c:1561 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:53.705622 0.00% [DEBUG] mod_test.c:292 Result: START OF SPEECH
2024-01-11 15:29:53.725621 0.00% [INFO] switch_ivr_play_say.c:3340 (null/+15553334444) START OF SPEECH
2024-01-11 15:29:53.725621 0.00% [DEBUG] switch_ivr_play_say.c:2010 done playing file silence_stream://1000
2024-01-11 15:29:53.725621 0.00% [DEBUG] mod_test.c:316 start_input_timers
2024-01-11 15:29:53.725621 0.00% [INFO] switch_ivr_play_say.c:3515 (null/+15553334444) WAITING FOR RESULT
2024-01-11 15:29:53.725621 0.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:54.228599 0.00% [DEBUG] switch_ivr_play_say.c:3558 
is_speech = true; sleep_time < digit_timeout; sleep_time=500; last_digit_time=1704986993725621; digit_timeout=500 
2024-01-11 15:29:54.228599 0.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:54.728647 0.00% [DEBUG] switch_ivr_play_say.c:3558 
is_speech = true; sleep_time < digit_timeout; sleep_time=500; last_digit_time=1704986993725621; digit_timeout=500 
2024-01-11 15:29:54.728647 0.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:55.248583 0.00% [DEBUG] switch_ivr_play_say.c:3558 
is_speech = true; sleep_time < digit_timeout; sleep_time=500; last_digit_time=1704986993725621; digit_timeout=500 
2024-01-11 15:29:55.248583 0.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:55.648857 0.00% [DEBUG] switch_core_media_bug.c:1326 Removing BUG from null/+15553334444
2024-01-11 15:29:55.648857 0.00% [DEBUG] switch_core_io.c:780 Engaging Read Buffer at 320 bytes vs 0
2024-01-11 15:29:55.768589 0.00% [DEBUG] switch_ivr_play_say.c:3558 
is_speech = true; sleep_time < digit_timeout; sleep_time=500; last_digit_time=1704986993725621; digit_timeout=500 
2024-01-11 15:29:55.768589 0.00% [DEBUG] switch_ivr.c:195 Codec Activated L16@8000hz 1 channels 20ms
2024-01-11 15:29:56.145623 0.00% [INFO] mod_test.c:190 Talking stopped, have result.
2024-01-11 15:29:56.145623 0.00% [NOTICE] mod_test.c:277 Partial Result: {"grammar": "default", "text": "agent", "confidence": 87.300000}
2024-01-11 15:29:56.165625 0.00% [INFO] switch_ivr_play_say.c:93 partial events count: 1
2024-01-11 15:29:56.165625 0.00% [NOTICE] mod_test.c:277 Partial Result: {"grammar": "default", "text": "agent", "confidence": 87.300000}
2024-01-11 15:29:56.165625 0.00% [NOTICE] switch_ivr_play_say.c:94 body=[{"grammar": "default", "text": "agent", "confidence": 87.300000}]
2024-01-11 15:29:56.188581 0.00% [INFO] switch_ivr_play_say.c:93 partial events count: 2
2024-01-11 15:29:56.188581 0.00% [NOTICE] switch_ivr_play_say.c:94 body=[{"grammar": "default", "text": "agent", "confidence": 87.300000}]
2024-01-11 15:29:56.188581 0.00% [NOTICE] mod_test.c:277 Partial Result: {"grammar": "default", "text": "agent", "confidence": 87.300000}
2024-01-11 15:29:56.208579 0.00% [INFO] switch_ivr_play_say.c:93 partial events count: 3
2024-01-11 15:29:56.208579 0.00% [NOTICE] switch_ivr_play_say.c:94 body=[{"grammar": "default", "text": "agent", "confidence": 87.300000}]
2024-01-11 15:29:56.208579 0.00% [NOTICE] mod_test.c:277 Final Result: {"grammar": "default", "text": "agent", "confidence": 87.300000}
2024-01-11 15:29:56.228579 0.00% [INFO] switch_ivr_play_say.c:3319 (null/+15553334444) DETECTED SPEECH detected-speech
2024-01-11 15:29:56.228579 0.00% [DEBUG] switch_ivr_play_say.c:3558 
is_speech = true; sleep_time < digit_timeout; sleep_time=500; last_digit_time=1704986993725621; digit_timeout=500 
2024-01-11 15:29:56.228579 0.00% [DEBUG] mod_test.c:211 Pausing
2024-01-11 15:29:56.228579 0.00% [INFO] switch_ivr_play_say.c:396 xxx count = 3
2024-01-11 15:29:56.228579 0.00% [NOTICE] switch_ivr_play_say.c:400 Hangup null/+15553334444 [CS_SOFT_EXECUTE] [NORMAL_CLEARING]
2024-01-11 15:29:56.228579 0.00% [DEBUG] mod_loopback.c:1524 CHANNEL SWITCH_SIG_KILL - hanging up
 PASS
record_file_event_vars ............................................2024-01-11 15:29:57.228583 0.00% [DEBUG] switch_ivr_originate.c:2301 Parsing global variables
2024-01-11 15:29:57.228583 0.00% [NOTICE] switch_channel.c:1142 New Channel null/+15553334444 [c6378ed7-feba-49f4-b082-98131617c431]
2024-01-11 15:29:57.228583 0.00% [DEBUG] mod_loopback.c:1371 null/+15553334444 setup codec L16/8000/20
2024-01-11 15:29:57.250854 0.00% [NOTICE] switch_channel.c:1140 Rename Channel null/+15553334444->null/+15553334444 [c6378ed7-feba-49f4-b082-98131617c431]
2024-01-11 15:29:57.250854 0.00% [DEBUG] mod_loopback.c:1836 (null/+15553334444) State Change CS_NEW -> CS_INIT
2024-01-11 15:29:57.250854 0.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_INIT (Cur 1 Tot 4)
2024-01-11 15:29:57.250854 0.00% [DEBUG] switch_core_state_machine.c:624 (null/+15553334444) State INIT
2024-01-11 15:29:57.250854 0.00% [DEBUG] mod_loopback.c:1466 (null/+15553334444) State Change CS_INIT -> CS_ROUTING
2024-01-11 15:29:57.250854 0.00% [DEBUG] switch_core_state_machine.c:624 (null/+15553334444) State INIT going to sleep
2024-01-11 15:29:57.250854 0.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_ROUTING (Cur 1 Tot 4)
2024-01-11 15:29:57.265619 0.00% [DEBUG] switch_core_state_machine.c:640 (null/+15553334444) State ROUTING
2024-01-11 15:29:57.265619 0.00% [DEBUG] switch_ivr_originate.c:67 (null/+15553334444) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2024-01-11 15:29:57.265619 0.00% [DEBUG] switch_core_state_machine.c:640 (null/+15553334444) State ROUTING going to sleep
2024-01-11 15:29:57.265619 0.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_CONSUME_MEDIA (Cur 1 Tot 4)
2024-01-11 15:29:57.265619 0.00% [DEBUG] switch_core_state_machine.c:659 (null/+15553334444) State CONSUME_MEDIA
2024-01-11 15:29:57.265619 0.00% [DEBUG] mod_loopback.c:1545 CHANNEL CONSUME_MEDIA
2024-01-11 15:29:57.265619 0.00% [DEBUG] mod_loopback.c:1554 CHANNEL CONSUME_MEDIA - answering in 0 ms
2024-01-11 15:29:57.265619 0.00% [NOTICE] mod_loopback.c:1562 Channel [null/+15553334444] has been answered
2024-01-11 15:29:57.265619 0.00% [DEBUG] switch_channel.c:3912 (null/+15553334444) Callstate Change DOWN -> ACTIVE
2024-01-11 15:29:57.265619 0.00% [DEBUG] switch_ivr_originate.c:3913 Originate Resulted in Success: [null/+15553334444] Peer UUID: c6378ed7-feba-49f4-b082-98131617c431
2024-01-11 15:29:57.265619 0.00% [DEBUG] switch_ivr_play_say.c:402 (null/+15553334444) State Change CS_CONSUME_MEDIA -> CS_SOFT_EXECUTE
2024-01-11 15:29:57.288581 0.00% [DEBUG] switch_core_state_machine.c:659 (null/+15553334444) State CONSUME_MEDIA going to sleep
2024-01-11 15:29:57.288581 0.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_SOFT_EXECUTE (Cur 1 Tot 4)
2024-01-11 15:29:57.288581 0.00% [DEBUG] switch_core_state_machine.c:653 (null/+15553334444) State SOFT_EXECUTE
2024-01-11 15:29:57.288581 0.00% [DEBUG] switch_core_state_machine.c:397 null/+15553334444 Standard SOFT_EXECUTE
2024-01-11 15:29:57.288581 0.00% [DEBUG] switch_core_state_machine.c:653 (null/+15553334444) State SOFT_EXECUTE going to sleep
2024-01-11 15:29:57.305614 0.00% [DEBUG] switch_ivr_async.c:1504 Record session sample rate: 8000 -> 8000
2024-01-11 15:29:57.305614 0.00% [DEBUG] switch_core_media_bug.c:976 Attaching BUG to null/+15553334444
2024-01-11 15:29:57.305614 0.00% [DEBUG] switch_core_media_bug.c:976 Attaching BUG to null/+15553334444
2024-01-11 15:29:57.305614 0.00% [DEBUG] switch_ivr_play_say.c:614 Raw Codec Activated, ready to waste resources!
2024-01-11 15:29:57.305614 0.00% [DEBUG] switch_ivr_play_say.c:726 Raw Codec Activated
2024-01-11 15:29:57.305614 0.00% [DEBUG] switch_core_codec.c:229 null/+15553334444 Push codec L16:100
2024-01-11 15:29:57.305614 0.00% [ERR] switch_ivr_play_say.c:41 Event-Name: [RECORD_START]
Core-UUID: [60e31209-5790-4de4-ae46-040e040c1c54]
FreeSWITCH-Hostname: [3e178341fa45]
FreeSWITCH-Switchname: [3e178341fa45]
FreeSWITCH-IPv4: [172.23.0.2]
FreeSWITCH-IPv6: [::1]
Event-Date-Local: [2024-01-11 15:29:57]
Event-Date-GMT: [Thu, 11 Jan 2024 15:29:57 GMT]
Event-Date-Timestamp: [1704986997305614]
Event-Calling-File: [switch_ivr_play_say.c]
Event-Calling-Function: [switch_ivr_record_file_event]
Event-Calling-Line-Number: [767]
Event-Sequence: [613]
Channel-State: [CS_SOFT_EXECUTE]
Channel-Call-State: [ACTIVE]
Channel-State-Number: [3]
Channel-Name: [null/+15553334444]
Unique-ID: [c6378ed7-feba-49f4-b082-98131617c431]
Call-Direction: [outbound]
Presence-Call-Direction: [outbound]
Channel-HIT-Dialplan: [false]
Channel-Call-UUID: [c6378ed7-feba-49f4-b082-98131617c431]
Answer-State: [answered]
Channel-Read-Codec-Name: [L16]
Channel-Read-Codec-Rate: [8000]
Channel-Read-Codec-Bit-Rate: [128000]
Channel-Write-Codec-Name: [L16]
Channel-Write-Codec-Rate: [8000]
Channel-Write-Codec-Bit-Rate: [128000]
Caller-Direction: [outbound]
Caller-Logical-Direction: [outbound]
Caller-Caller-ID-Number: [+15551112222]
Caller-Orig-Caller-ID-Number: [+15551112222]
Caller-Callee-ID-Name: [Outbound Call]
Caller-Callee-ID-Number: [+15553334444]
Caller-ANI: [+15551112222]
Caller-Destination-Number: [+15553334444]
Caller-Unique-ID: [c6378ed7-feba-49f4-b082-98131617c431]
Caller-Source: [mod_loopback]
Caller-Context: [default]
Caller-Channel-Name: [null/+15553334444]
Caller-Profile-Index: [1]
Caller-Profile-Created-Time: [1704986997250854]
Caller-Channel-Created-Time: [1704986997250854]
Caller-Channel-Answered-Time: [1704986997265619]
Caller-Channel-Progress-Time: [0]
Caller-Channel-Progress-Media-Time: [0]
Caller-Channel-Hangup-Time: [0]
Caller-Channel-Transfer-Time: [0]
Caller-Channel-Resurrect-Time: [0]
Caller-Channel-Bridged-Time: [0]
Caller-Channel-Last-Hold: [0]
Caller-Channel-Hold-Accum: [0]
Caller-Screen-Bit: [true]
Caller-Privacy-Hide-Name: [false]
Caller-Privacy-Hide-Number: [false]
variable_direction: [outbound]
variable_is_outbound: [true]
variable_uuid: [c6378ed7-feba-49f4-b082-98131617c431]
variable_call_uuid: [c6378ed7-feba-49f4-b082-98131617c431]
variable_session_id: [4]
variable_write_codec: [L16]
variable_write_rate: [8000]
variable_channel_name: [null/+15553334444]
variable_origination_caller_id_number: [+15551112222]
variable_rate: [8000]
variable_originate_early_media: [true]
variable_originate_endpoint: [null]
variable_endpoint_disposition: [ANSWER]
variable_send_silence_when_idle: [-1]
variable_silence_hits_exhausted: [false]
variable_read_codec: [L16]
variable_read_rate: [8000]
Record-File-Path: [/tmp/record_file_event_vars-tmp-c6378ed7-feba-49f4-b082-98131617c431.wav]
Recording-Variable-execute_on_record_start: [set record_start_test_pass=true]
Recording-Variable-execute_on_record_stop: [set record_stop_test_pass=true]
Recording-Variable-ID: [foo]

EXECUTE [depth=0] null/+15553334444 set(record_start_test_pass=true)
2024-01-11 15:29:57.328582 0.00% [DEBUG] mod_dptools.c:1671 SET null/+15553334444 [record_start_test_pass]=[true]
2024-01-11 15:29:57.328582 0.00% [DEBUG] switch_core_io.c:448 Setting BUG Codec L16:100
2024-01-11 15:29:57.328582 0.00% [DEBUG] switch_ivr_async.c:1778 No silence detection configured; assuming start of speech
2024-01-11 15:29:57.565620 0.00% [DEBUG] switch_core_io.c:780 Engaging Read Buffer at 320 bytes vs 160
2024-01-11 15:30:00.085619 0.00% [DEBUG] switch_core_media_bug.c:1326 Removing BUG from null/+15553334444
EXECUTE [depth=0] null/+15553334444 set(record_stop_test_pass=true)
2024-01-11 15:30:02.005623 0.00% [ERR] switch_ivr_play_say.c:61 Event-Name: [RECORD_STOP]
Core-UUID: [60e31209-5790-4de4-ae46-040e040c1c54]
FreeSWITCH-Hostname: [3e178341fa45]
FreeSWITCH-Switchname: [3e178341fa45]
FreeSWITCH-IPv4: [172.23.0.2]
FreeSWITCH-IPv6: [::1]
Event-Date-Local: [2024-01-11 15:30:02]
Event-Date-GMT: [Thu, 11 Jan 2024 15:30:02 GMT]
Event-Date-Timestamp: [1704987002005623]
Event-Calling-File: [switch_ivr_play_say.c]
Event-Calling-Function: [switch_ivr_record_file_event]
Event-Calling-Line-Number: [1030]
Event-Sequence: [620]
Channel-State: [CS_SOFT_EXECUTE]
Channel-Call-State: [ACTIVE]
Channel-State-Number: [3]
Channel-Name: [null/+15553334444]
Unique-ID: [c6378ed7-feba-49f4-b082-98131617c431]
Call-Direction: [outbound]
Presence-Call-Direction: [outbound]
Channel-HIT-Dialplan: [false]
Channel-Call-UUID: [c6378ed7-feba-49f4-b082-98131617c431]
Answer-State: [answered]
Channel-Read-Codec-Name: [L16]
Channel-Read-Codec-Rate: [8000]
Channel-Read-Codec-Bit-Rate: [128000]
Channel-Write-Codec-Name: [L16]
Channel-Write-Codec-Rate: [8000]
Channel-Write-Codec-Bit-Rate: [128000]
Caller-Direction: [outbound]
Caller-Logical-Direction: [outbound]
Caller-Caller-ID-Number: [+15551112222]
Caller-Orig-Caller-ID-Number: [+15551112222]
Caller-Callee-ID-Name: [Outbound Call]
Caller-Callee-ID-Number: [+15553334444]
Caller-ANI: [+15551112222]
Caller-Destination-Number: [+15553334444]
Caller-Unique-ID: [c6378ed7-feba-49f4-b082-98131617c431]
Caller-Source: [mod_loopback]
Caller-Context: [default]
Caller-Channel-Name: [null/+15553334444]
Caller-Profile-Index: [1]
Caller-Profile-Created-Time: [1704986997250854]
Caller-Channel-Created-Time: [1704986997250854]
Caller-Channel-Answered-Time: [1704986997265619]
Caller-Channel-Progress-Time: [0]
Caller-Channel-Progress-Media-Time: [0]
Caller-Channel-Hangup-Time: [0]
Caller-Channel-Transfer-Time: [0]
Caller-Channel-Resurrect-Time: [0]
Caller-Channel-Bridged-Time: [0]
Caller-Channel-Last-Hold: [0]
Caller-Channel-Hold-Accum: [0]
Caller-Screen-Bit: [true]
Caller-Privacy-Hide-Name: [false]
Caller-Privacy-Hide-Number: [false]
variable_direction: [outbound]
variable_is_outbound: [true]
variable_uuid: [c6378ed7-feba-49f4-b082-98131617c431]
variable_call_uuid: [c6378ed7-feba-49f4-b082-98131617c431]
variable_session_id: [4]
variable_write_codec: [L16]
variable_write_rate: [8000]
variable_channel_name: [null/+15553334444]
variable_origination_caller_id_number: [+15551112222]
variable_rate: [8000]
variable_originate_early_media: [true]
variable_originate_endpoint: [null]
variable_endpoint_disposition: [ANSWER]
variable_send_silence_when_idle: [-1]
variable_silence_hits_exhausted: [false]
variable_read_codec: [L16]
variable_read_rate: [8000]
variable_record_start_event_test_pass: [true]
variable_current_application_data: [record_start_test_pass=true]
variable_current_application: [set]
variable_record_start_test_pass: [true]
variable_record_record_file_size: [74604]
variable_record_file_size: [74604]
variable_record_seconds: [4]
variable_record_ms: [4660]
variable_record_samples: [37280]
Record-File-Path: [/tmp/record_file_event_vars-tmp-c6378ed7-feba-49f4-b082-98131617c431.wav]
Recording-Variable-execute_on_record_start: [set record_start_test_pass=true]
Recording-Variable-execute_on_record_stop: [set record_stop_test_pass=true]
Recording-Variable-ID: [foo]

2024-01-11 15:30:02.005623 0.00% [DEBUG] mod_dptools.c:1671 SET null/+15553334444 [record_stop_test_pass]=[true]
2024-01-11 15:30:02.005623 0.00% [DEBUG] switch_core_codec.c:254 null/+15553334444 Restore previous codec L16:100.
2024-01-11 15:30:03.025622 0.00% [DEBUG] switch_event.c:2156 Event Binding deleted for record_file_event:RECORD_START
2024-01-11 15:30:03.025622 0.00% [DEBUG] switch_event.c:2156 Event Binding deleted for record_file_event:RECORD_STOP
2024-01-11 15:30:03.025622 0.00% [NOTICE] switch_ivr_play_say.c:428 Hangup null/+15553334444 [CS_SOFT_EXECUTE] [NORMAL_CLEARING]
2024-01-11 15:30:03.025622 0.00% [DEBUG] mod_loopback.c:1524 CHANNEL SWITCH_SIG_KILL - hanging up
 PASS
record_file_event_chan_vars .......................................2024-01-11 15:30:04.025623 0.00% [DEBUG] switch_ivr_originate.c:2301 Parsing global variables
2024-01-11 15:30:04.025623 0.00% [NOTICE] switch_channel.c:1142 New Channel null/+15553334444 [bfe4b83c-faff-42ee-95ed-3cdcfca21bf6]
2024-01-11 15:30:04.025623 0.00% [DEBUG] mod_loopback.c:1371 null/+15553334444 setup codec L16/8000/20
2024-01-11 15:30:04.025623 0.00% [NOTICE] switch_channel.c:1140 Rename Channel null/+15553334444->null/+15553334444 [bfe4b83c-faff-42ee-95ed-3cdcfca21bf6]
2024-01-11 15:30:04.025623 0.00% [DEBUG] mod_loopback.c:1836 (null/+15553334444) State Change CS_NEW -> CS_INIT
2024-01-11 15:30:04.025623 0.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_INIT (Cur 1 Tot 5)
2024-01-11 15:30:04.025623 0.00% [DEBUG] switch_core_state_machine.c:624 (null/+15553334444) State INIT
2024-01-11 15:30:04.025623 0.00% [DEBUG] mod_loopback.c:1466 (null/+15553334444) State Change CS_INIT -> CS_ROUTING
2024-01-11 15:30:04.025623 0.00% [DEBUG] switch_core_state_machine.c:624 (null/+15553334444) State INIT going to sleep
2024-01-11 15:30:04.025623 0.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_ROUTING (Cur 1 Tot 5)
2024-01-11 15:30:04.025623 0.00% [DEBUG] switch_core_state_machine.c:640 (null/+15553334444) State ROUTING
2024-01-11 15:30:04.025623 0.00% [DEBUG] switch_ivr_originate.c:67 (null/+15553334444) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2024-01-11 15:30:04.025623 0.00% [DEBUG] switch_core_state_machine.c:640 (null/+15553334444) State ROUTING going to sleep
2024-01-11 15:30:04.025623 0.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_CONSUME_MEDIA (Cur 1 Tot 5)
2024-01-11 15:30:04.025623 0.00% [DEBUG] switch_core_state_machine.c:659 (null/+15553334444) State CONSUME_MEDIA
2024-01-11 15:30:04.045621 0.00% [DEBUG] mod_loopback.c:1545 CHANNEL CONSUME_MEDIA
2024-01-11 15:30:04.045621 0.00% [DEBUG] mod_loopback.c:1554 CHANNEL CONSUME_MEDIA - answering in 0 ms
2024-01-11 15:30:04.045621 0.00% [NOTICE] mod_loopback.c:1562 Channel [null/+15553334444] has been answered
2024-01-11 15:30:04.045621 0.00% [DEBUG] switch_ivr_originate.c:3913 Originate Resulted in Success: [null/+15553334444] Peer UUID: bfe4b83c-faff-42ee-95ed-3cdcfca21bf6
2024-01-11 15:30:04.045621 0.00% [DEBUG] switch_ivr_play_say.c:430 (null/+15553334444) State Change CS_CONSUME_MEDIA -> CS_SOFT_EXECUTE
2024-01-11 15:30:04.045621 0.00% [DEBUG] switch_channel.c:3912 (null/+15553334444) Callstate Change DOWN -> ACTIVE
2024-01-11 15:30:04.065622 0.00% [DEBUG] switch_core_state_machine.c:659 (null/+15553334444) State CONSUME_MEDIA going to sleep
2024-01-11 15:30:04.065622 0.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_SOFT_EXECUTE (Cur 1 Tot 5)
2024-01-11 15:30:04.065622 0.00% [DEBUG] switch_core_state_machine.c:653 (null/+15553334444) State SOFT_EXECUTE
2024-01-11 15:30:04.065622 0.00% [DEBUG] switch_core_state_machine.c:397 null/+15553334444 Standard SOFT_EXECUTE
2024-01-11 15:30:04.065622 0.00% [DEBUG] switch_core_state_machine.c:653 (null/+15553334444) State SOFT_EXECUTE going to sleep
2024-01-11 15:30:04.085617 0.00% [DEBUG] switch_ivr_async.c:1504 Record session sample rate: 8000 -> 8000
2024-01-11 15:30:04.085617 0.00% [DEBUG] switch_core_media_bug.c:976 Attaching BUG to null/+15553334444
2024-01-11 15:30:04.085617 0.00% [DEBUG] switch_core_media_bug.c:976 Attaching BUG to null/+15553334444
2024-01-11 15:30:04.085617 0.00% [DEBUG] switch_ivr_play_say.c:614 Raw Codec Activated, ready to waste resources!
2024-01-11 15:30:04.085617 0.00% [DEBUG] switch_ivr_play_say.c:726 Raw Codec Activated
2024-01-11 15:30:04.085617 0.00% [DEBUG] switch_core_codec.c:229 null/+15553334444 Push codec L16:100
EXECUTE [depth=0] null/+15553334444 set(record_start_test_pass=true)
2024-01-11 15:30:04.105620 0.00% [ERR] switch_ivr_play_say.c:41 Event-Name: [RECORD_START]
Core-UUID: [60e31209-5790-4de4-ae46-040e040c1c54]
FreeSWITCH-Hostname: [3e178341fa45]
FreeSWITCH-Switchname: [3e178341fa45]
FreeSWITCH-IPv4: [172.23.0.2]
FreeSWITCH-IPv6: [::1]
Event-Date-Local: [2024-01-11 15:30:04]
Event-Date-GMT: [Thu, 11 Jan 2024 15:30:04 GMT]
Event-Date-Timestamp: [1704987004105620]
Event-Calling-File: [switch_ivr_play_say.c]
Event-Calling-Function: [switch_ivr_record_file_event]
Event-Calling-Line-Number: [767]
Event-Sequence: [652]
Channel-State: [CS_SOFT_EXECUTE]
Channel-Call-State: [ACTIVE]
Channel-State-Number: [3]
Channel-Name: [null/+15553334444]
Unique-ID: [bfe4b83c-faff-42ee-95ed-3cdcfca21bf6]
Call-Direction: [outbound]
Presence-Call-Direction: [outbound]
Channel-HIT-Dialplan: [false]
Channel-Call-UUID: [bfe4b83c-faff-42ee-95ed-3cdcfca21bf6]
Answer-State: [answered]
Channel-Read-Codec-Name: [L16]
Channel-Read-Codec-Rate: [8000]
Channel-Read-Codec-Bit-Rate: [128000]
Channel-Write-Codec-Name: [L16]
Channel-Write-Codec-Rate: [8000]
Channel-Write-Codec-Bit-Rate: [128000]
Caller-Direction: [outbound]
Caller-Logical-Direction: [outbound]
Caller-Caller-ID-Number: [+15551112222]
Caller-Orig-Caller-ID-Number: [+15551112222]
Caller-Callee-ID-Name: [Outbound Call]
Caller-Callee-ID-Number: [+15553334444]
Caller-ANI: [+15551112222]
Caller-Destination-Number: [+15553334444]
Caller-Unique-ID: [bfe4b83c-faff-42ee-95ed-3cdcfca21bf6]
Caller-Source: [mod_loopback]
Caller-Context: [default]
Caller-Channel-Name: [null/+15553334444]
Caller-Profile-Index: [1]
Caller-Profile-Created-Time: [1704987004025623]
Caller-Channel-Created-Time: [1704987004025623]
Caller-Channel-Answered-Time: [1704987004045621]
Caller-Channel-Progress-Time: [0]
Caller-Channel-Progress-Media-Time: [0]
Caller-Channel-Hangup-Time: [0]
Caller-Channel-Transfer-Time: [0]
Caller-Channel-Resurrect-Time: [0]
Caller-Channel-Bridged-Time: [0]
Caller-Channel-Last-Hold: [0]
Caller-Channel-Hold-Accum: [0]
Caller-Screen-Bit: [true]
Caller-Privacy-Hide-Name: [false]
Caller-Privacy-Hide-Number: [false]
variable_direction: [outbound]
variable_is_outbound: [true]
variable_uuid: [bfe4b83c-faff-42ee-95ed-3cdcfca21bf6]
variable_call_uuid: [bfe4b83c-faff-42ee-95ed-3cdcfca21bf6]
variable_session_id: [5]
variable_write_codec: [L16]
variable_write_rate: [8000]
variable_channel_name: [null/+15553334444]
variable_origination_caller_id_number: [+15551112222]
variable_rate: [8000]
variable_originate_early_media: [true]
variable_originate_endpoint: [null]
variable_endpoint_disposition: [ANSWER]
variable_send_silence_when_idle: [-1]
variable_execute_on_record_start_1: [set record_start_test_pass=true]
variable_execute_on_record_stop_1: [set record_stop_test_pass=true]
variable_silence_hits_exhausted: [false]
variable_read_codec: [L16]
variable_read_rate: [8000]
Record-File-Path: [/tmp/record_file_event_chan_vars-tmp-bfe4b83c-faff-42ee-95ed-3cdcfca21bf6.wav]
Recording-Variable-ID: [foo]

2024-01-11 15:30:04.105620 0.00% [DEBUG] mod_dptools.c:1671 SET null/+15553334444 [record_start_test_pass]=[true]
2024-01-11 15:30:04.125621 0.00% [DEBUG] switch_core_io.c:448 Setting BUG Codec L16:100
2024-01-11 15:30:04.125621 0.00% [DEBUG] switch_ivr_async.c:1778 No silence detection configured; assuming start of speech
2024-01-11 15:30:04.345622 0.00% [DEBUG] switch_core_io.c:780 Engaging Read Buffer at 320 bytes vs 160
2024-01-11 15:30:06.865622 0.00% [DEBUG] switch_core_media_bug.c:1326 Removing BUG from null/+15553334444
EXECUTE [depth=0] null/+15553334444 set(record_stop_test_pass=true)
2024-01-11 15:30:09.005623 0.00% [ERR] switch_ivr_play_say.c:61 Event-Name: [RECORD_STOP]
Core-UUID: [60e31209-5790-4de4-ae46-040e040c1c54]
FreeSWITCH-Hostname: [3e178341fa45]
FreeSWITCH-Switchname: [3e178341fa45]
FreeSWITCH-IPv4: [172.23.0.2]
FreeSWITCH-IPv6: [::1]
Event-Date-Local: [2024-01-11 15:30:09]
Event-Date-GMT: [Thu, 11 Jan 2024 15:30:09 GMT]
Event-Date-Timestamp: [1704987009005623]
Event-Calling-File: [switch_ivr_play_say.c]
Event-Calling-Function: [switch_ivr_record_file_event]
Event-Calling-Line-Number: [1030]
Event-Sequence: [659]
Channel-State: [CS_SOFT_EXECUTE]
Channel-Call-State: [ACTIVE]
Channel-State-Number: [3]
Channel-Name: [null/+15553334444]
Unique-ID: [bfe4b83c-faff-42ee-95ed-3cdcfca21bf6]
Call-Direction: [outbound]
Presence-Call-Direction: [outbound]
Channel-HIT-Dialplan: [false]
Channel-Call-UUID: [bfe4b83c-faff-42ee-95ed-3cdcfca21bf6]
Answer-State: [answered]
Channel-Read-Codec-Name: [L16]
Channel-Read-Codec-Rate: [8000]
Channel-Read-Codec-Bit-Rate: [128000]
Channel-Write-Codec-Name: [L16]
Channel-Write-Codec-Rate: [8000]
Channel-Write-Codec-Bit-Rate: [128000]
Caller-Direction: [outbound]
Caller-Logical-Direction: [outbound]
Caller-Caller-ID-Number: [+15551112222]
Caller-Orig-Caller-ID-Number: [+15551112222]
Caller-Callee-ID-Name: [Outbound Call]
Caller-Callee-ID-Number: [+15553334444]
Caller-ANI: [+15551112222]
Caller-Destination-Number: [+15553334444]
Caller-Unique-ID: [bfe4b83c-faff-42ee-95ed-3cdcfca21bf6]
Caller-Source: [mod_loopback]
Caller-Context: [default]
Caller-Channel-Name: [null/+15553334444]
Caller-Profile-Index: [1]
Caller-Profile-Created-Time: [1704987004025623]
Caller-Channel-Created-Time: [1704987004025623]
Caller-Channel-Answered-Time: [1704987004045621]
Caller-Channel-Progress-Time: [0]
Caller-Channel-Progress-Media-Time: [0]
Caller-Channel-Hangup-Time: [0]
Caller-Channel-Transfer-Time: [0]
Caller-Channel-Resurrect-Time: [0]
Caller-Channel-Bridged-Time: [0]
Caller-Channel-Last-Hold: [0]
Caller-Channel-Hold-Accum: [0]
Caller-Screen-Bit: [true]
Caller-Privacy-Hide-Name: [false]
Caller-Privacy-Hide-Number: [false]
variable_direction: [outbound]
variable_is_outbound: [true]
variable_uuid: [bfe4b83c-faff-42ee-95ed-3cdcfca21bf6]
variable_call_uuid: [bfe4b83c-faff-42ee-95ed-3cdcfca21bf6]
variable_session_id: [5]
variable_write_codec: [L16]
variable_write_rate: [8000]
variable_channel_name: [null/+15553334444]
variable_origination_caller_id_number: [+15551112222]
variable_rate: [8000]
variable_originate_early_media: [true]
variable_originate_endpoint: [null]
variable_endpoint_disposition: [ANSWER]
variable_send_silence_when_idle: [-1]
variable_execute_on_record_start_1: [set record_start_test_pass=true]
variable_execute_on_record_stop_1: [set record_stop_test_pass=true]
variable_silence_hits_exhausted: [false]
variable_read_codec: [L16]
variable_read_rate: [8000]
variable_current_application_data: [record_start_test_pass=true]
variable_record_start_event_test_pass: [true]
variable_current_application: [set]
variable_record_start_test_pass: [true]
variable_record_record_file_size: [78124]
variable_record_file_size: [78124]
variable_record_seconds: [4]
variable_record_ms: [4880]
variable_record_samples: [39040]
Record-File-Path: [/tmp/record_file_event_chan_vars-tmp-bfe4b83c-faff-42ee-95ed-3cdcfca21bf6.wav]
Recording-Variable-ID: [foo]

2024-01-11 15:30:09.005623 0.00% [DEBUG] mod_dptools.c:1671 SET null/+15553334444 [record_stop_test_pass]=[true]
2024-01-11 15:30:09.025620 0.00% [DEBUG] switch_core_codec.c:254 null/+15553334444 Restore previous codec L16:100.
2024-01-11 15:30:10.025625 0.00% [DEBUG] switch_event.c:2156 Event Binding deleted for record_file_event:RECORD_START
2024-01-11 15:30:10.025625 0.00% [DEBUG] switch_event.c:2156 Event Binding deleted for record_file_event:RECORD_STOP
2024-01-11 15:30:10.025625 0.00% [NOTICE] switch_ivr_play_say.c:456 Hangup null/+15553334444 [CS_SOFT_EXECUTE] [NORMAL_CLEARING]
2024-01-11 15:30:10.025625 0.00% [DEBUG] mod_loopback.c:1524 CHANNEL SWITCH_SIG_KILL - hanging up
2024-01-11 15:30:10.025625 0.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_HANGUP (Cur 1 Tot 5)
2024-01-11 15:30:10.025625 0.00% [DEBUG] switch_ivr_async.c:1597 Stop recording file /tmp/record_file_event_chan_vars.wav
 PASS
record_file_event_chan_vars_only ..................................2024-01-11 15:30:11.025621 0.00% [DEBUG] switch_ivr_originate.c:2301 Parsing global variables
2024-01-11 15:30:11.025621 0.00% [NOTICE] switch_channel.c:1142 New Channel null/+15553334444 [baa62e58-bfac-40d8-94ae-64615e649f1b]
2024-01-11 15:30:11.025621 0.00% [DEBUG] mod_loopback.c:1371 null/+15553334444 setup codec L16/8000/20
2024-01-11 15:30:11.025621 0.00% [NOTICE] switch_channel.c:1140 Rename Channel null/+15553334444->null/+15553334444 [baa62e58-bfac-40d8-94ae-64615e649f1b]
2024-01-11 15:30:11.025621 0.00% [DEBUG] mod_loopback.c:1836 (null/+15553334444) State Change CS_NEW -> CS_INIT
2024-01-11 15:30:11.025621 0.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_INIT (Cur 1 Tot 6)
2024-01-11 15:30:11.045615 0.00% [DEBUG] switch_core_state_machine.c:624 (null/+15553334444) State INIT
2024-01-11 15:30:11.045615 0.00% [DEBUG] mod_loopback.c:1466 (null/+15553334444) State Change CS_INIT -> CS_ROUTING
2024-01-11 15:30:11.045615 0.00% [DEBUG] switch_core_state_machine.c:624 (null/+15553334444) State INIT going to sleep
2024-01-11 15:30:11.045615 0.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_ROUTING (Cur 1 Tot 6)
2024-01-11 15:30:11.045615 0.00% [DEBUG] switch_core_state_machine.c:640 (null/+15553334444) State ROUTING
2024-01-11 15:30:11.045615 0.00% [DEBUG] switch_ivr_originate.c:67 (null/+15553334444) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2024-01-11 15:30:11.045615 0.00% [DEBUG] switch_core_state_machine.c:640 (null/+15553334444) State ROUTING going to sleep
2024-01-11 15:30:11.045615 0.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_CONSUME_MEDIA (Cur 1 Tot 6)
2024-01-11 15:30:11.045615 0.00% [DEBUG] switch_core_state_machine.c:659 (null/+15553334444) State CONSUME_MEDIA
2024-01-11 15:30:11.045615 0.00% [DEBUG] mod_loopback.c:1545 CHANNEL CONSUME_MEDIA
2024-01-11 15:30:11.045615 0.00% [DEBUG] mod_loopback.c:1554 CHANNEL CONSUME_MEDIA - answering in 0 ms
2024-01-11 15:30:11.065620 0.00% [DEBUG] switch_ivr_originate.c:3913 Originate Resulted in Success: [null/+15553334444] Peer UUID: baa62e58-bfac-40d8-94ae-64615e649f1b
2024-01-11 15:30:11.065620 0.00% [DEBUG] switch_ivr_play_say.c:458 (null/+15553334444) State Change CS_CONSUME_MEDIA -> CS_SOFT_EXECUTE
2024-01-11 15:30:11.065620 0.00% [NOTICE] mod_loopback.c:1562 Channel [null/+15553334444] has been answered
2024-01-11 15:30:11.065620 0.00% [DEBUG] switch_channel.c:3912 (null/+15553334444) Callstate Change DOWN -> ACTIVE
2024-01-11 15:30:11.065620 0.00% [DEBUG] switch_core_state_machine.c:659 (null/+15553334444) State CONSUME_MEDIA going to sleep
2024-01-11 15:30:11.065620 0.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_SOFT_EXECUTE (Cur 1 Tot 6)
2024-01-11 15:30:11.065620 0.00% [DEBUG] switch_core_state_machine.c:653 (null/+15553334444) State SOFT_EXECUTE
2024-01-11 15:30:11.085620 0.00% [DEBUG] switch_core_state_machine.c:397 null/+15553334444 Standard SOFT_EXECUTE
2024-01-11 15:30:11.085620 0.00% [DEBUG] switch_core_state_machine.c:653 (null/+15553334444) State SOFT_EXECUTE going to sleep
2024-01-11 15:30:11.085620 0.00% [DEBUG] switch_ivr_async.c:1504 Record session sample rate: 8000 -> 8000
2024-01-11 15:30:11.085620 0.00% [DEBUG] switch_core_media_bug.c:976 Attaching BUG to null/+15553334444
2024-01-11 15:30:11.085620 0.00% [DEBUG] switch_core_media_bug.c:976 Attaching BUG to null/+15553334444
2024-01-11 15:30:11.105619 0.00% [DEBUG] switch_ivr_play_say.c:614 Raw Codec Activated, ready to waste resources!
2024-01-11 15:30:11.105619 0.00% [DEBUG] switch_ivr_play_say.c:726 Raw Codec Activated
2024-01-11 15:30:11.105619 0.00% [DEBUG] switch_core_codec.c:229 null/+15553334444 Push codec L16:100
EXECUTE [depth=0] null/+15553334444 set(record_start_test_pass=true)
2024-01-11 15:30:11.125617 0.00% [DEBUG] mod_dptools.c:1671 SET null/+15553334444 [record_start_test_pass]=[true]
2024-01-11 15:30:11.125617 0.00% [DEBUG] switch_core_io.c:448 Setting BUG Codec L16:100
2024-01-11 15:30:11.125617 0.00% [DEBUG] switch_ivr_async.c:1778 No silence detection configured; assuming start of speech
2024-01-11 15:30:11.365624 0.00% [DEBUG] switch_core_io.c:780 Engaging Read Buffer at 320 bytes vs 160
2024-01-11 15:30:13.885625 0.00% [DEBUG] switch_core_media_bug.c:1326 Removing BUG from null/+15553334444
EXECUTE [depth=0] null/+15553334444 set(record_stop_test_pass=true)
2024-01-11 15:30:16.025619 0.00% [DEBUG] mod_dptools.c:1671 SET null/+15553334444 [record_stop_test_pass]=[true]
2024-01-11 15:30:16.025619 0.00% [DEBUG] switch_core_codec.c:254 null/+15553334444 Restore previous codec L16:100.
2024-01-11 15:30:17.025619 0.00% [NOTICE] switch_ivr_play_say.c:473 Hangup null/+15553334444 [CS_SOFT_EXECUTE] [NORMAL_CLEARING]
2024-01-11 15:30:17.025619 0.00% [DEBUG] mod_loopback.c:1524 CHANNEL SWITCH_SIG_KILL - hanging up
2024-01-11 15:30:17.025619 0.00% [DEBUG] switch_core_state_machine.c:581 (null/+15553334444) Running State Change CS_HANGUP (Cur 1 Tot 6)
 PASS

----------------------------------------------------------------------------

FAILED TESTS


play_and_collect_input_success
  switch_ivr_play_say.c(186):
    fst_check_duration: 1456 != 2500 +/- 1000



----------------------------------------------------------------------------

FAILED (5/6 tests in 1.694490s)