2017-02-06 14:41:25.751235 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'internal' for [0105914600@cvt-fusion.convergedgroup.co.za] from ip 154.118.252.42 1034293f-e4bf-4fb4-861a-d6c45b755379 2017-02-06 14:41:25.791239 [INFO] mod_dialplan_xml.c:637 Processing test100 ->0105914600 in context cvt-fusion.convergedgroup.co.za 1034293f-e4bf-4fb4-861a-d6c45b755379 Dialplan: sofia/internal/cvtmx1@154.118.252.42 Regex (FAIL) [redial] destination_number(0105914600) =~ /^(redial|\*870)$/ break=on-true 1034293f-e4bf-4fb4-861a-d6c45b755379 Dialplan: sofia/internal/cvtmx1@154.118.252.42 Regex (FAIL) [speed_dial] destination_number(0105914600) =~ /^\*0(.*)$/ break=on-false 1034293f-e4bf-4fb4-861a-d6c45b755379 Dialplan: sofia/internal/cvtmx1@154.118.252.42 Regex (PASS) [fusiontest.10d] destination_number(0105914600) =~ /^(\d{10})$/ break=on-false 1034293f-e4bf-4fb4-861a-d6c45b755379 Dialplan: sofia/internal/cvtmx1@154.118.252.42 Regex (PASS) [fusiontest.10d] destination_number(0105914600) =~ /^(\d{10})$/ break=on-false 1034293f-e4bf-4fb4-861a-d6c45b755379 Dialplan: sofia/internal/cvtmx1@154.118.252.42 Action bridge(sofia/gateway/13015ebd-ddf3-4e35-8ad5-26d5a8f98484/0105914600) 1034293f-e4bf-4fb4-861a-d6c45b755379 EXECUTE sofia/internal/cvtmx1@154.118.252.42 export(origination_callee_id_name=0105914600) 1034293f-e4bf-4fb4-861a-d6c45b755379 2017-02-06 14:41:25.811233 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[0105914600] 1034293f-e4bf-4fb4-861a-d6c45b755379 EXECUTE sofia/internal/cvtmx1@154.118.252.42 hash(insert/cvt-fusion.convergedgroup.co.za-last_dial/cvtmx1/0105914600) 1034293f-e4bf-4fb4-861a-d6c45b755379 EXECUTE sofia/internal/cvtmx1@154.118.252.42 bridge(sofia/gateway/13015ebd-ddf3-4e35-8ad5-26d5a8f98484/0105914600) 1034293f-e4bf-4fb4-861a-d6c45b755379 2017-02-06 14:41:29.431238 [DEBUG] switch_channel.c:1250 sofia/internal/cvtmx1@154.118.252.42 EXPORTING[export_vars] [origination_callee_id_name]=[0105914600] to event 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.431238 [NOTICE] switch_channel.c:1104 New Channel sofia/external/0105914600 [9413c4ac-0659-4b69-bd76-df3a45e3fc10] 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.431238 [DEBUG] mod_sofia.c:4808 (sofia/external/0105914600) State Change CS_NEW -> CS_INIT 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.431238 [DEBUG] switch_core_state_machine.c:584 (sofia/external/0105914600) Running State Change CS_INIT (Cur 32 Tot 14821) 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.431238 [DEBUG] switch_core_state_machine.c:627 (sofia/external/0105914600) State INIT 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.431238 [DEBUG] mod_sofia.c:90 sofia/external/0105914600 SOFIA INIT 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.431238 [DEBUG] sofia_glue.c:1283 sofia/external/0105914600 sending invite version: 1.6.14 -23-e460bf8 64bit 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.431238 [DEBUG] switch_core_state_machine.c:40 sofia/external/0105914600 Standard INIT 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.431238 [DEBUG] switch_core_state_machine.c:48 (sofia/external/0105914600) State Change CS_INIT -> CS_ROUTING 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.431238 [DEBUG] switch_core_state_machine.c:627 (sofia/external/0105914600) State INIT going to sleep 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.431238 [DEBUG] switch_core_state_machine.c:584 (sofia/external/0105914600) Running State Change CS_ROUTING (Cur 32 Tot 14821) 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.431238 [DEBUG] sofia.c:7041 Channel sofia/external/0105914600 entering state [calling][0] 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.431238 [DEBUG] switch_core_state_machine.c:643 (sofia/external/0105914600) State ROUTING 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.431238 [DEBUG] mod_sofia.c:143 sofia/external/0105914600 SOFIA ROUTING 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.431238 [DEBUG] switch_ivr_originate.c:67 (sofia/external/0105914600) State Change CS_ROUTING -> CS_CONSUME_MEDIA 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.431238 [DEBUG] switch_core_state_machine.c:643 (sofia/external/0105914600) State ROUTING going to sleep 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.431238 [DEBUG] switch_core_state_machine.c:584 (sofia/external/0105914600) Running State Change CS_CONSUME_MEDIA (Cur 32 Tot 14821) 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.431238 [DEBUG] switch_core_state_machine.c:662 (sofia/external/0105914600) State CONSUME_MEDIA 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.431238 [DEBUG] switch_core_state_machine.c:662 (sofia/external/0105914600) State CONSUME_MEDIA going to sleep 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.431238 [DEBUG] sofia.c:7041 Channel sofia/external/0105914600 entering state [calling][0] 2017-02-06 14:41:29.631289 [INFO] sofia.c:1279 sofia/external/0105914600 Update Callee ID to "27105914600" <27105914600> 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.631289 [DEBUG] sofia.c:7041 Channel sofia/external/0105914600 entering state [proceeding][180] 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.631289 [NOTICE] sofia.c:7149 Ring-Ready sofia/external/0105914600! 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:29.631289 [DEBUG] switch_channel.c:3345 (sofia/external/0105914600) Callstate Change DOWN -> RINGING 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [DEBUG] sofia.c:7041 Channel sofia/external/0105914600 entering state [completing][200] 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [DEBUG] sofia.c:7041 Channel sofia/external/0105914600 entering state [ready][200] 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [DEBUG] switch_core_media.c:3043 Set Codec sofia/external/0105914600 G729/8000 20 ms 160 samples 8000 bits 1 channels 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [DEBUG] switch_core_codec.c:111 sofia/external/0105914600 Original read codec set to G729:18 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [DEBUG] switch_core_media.c:4696 sofia/external/0105914600 Set 2833 dtmf send payload to 101 recv payload to 101 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [DEBUG] switch_core_media.c:6703 AUDIO RTP [sofia/external/0105914600] 154.118.252.39 port 25274 -> 154.118.252.43 port 12258 codec: 18 ms: 20 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [DEBUG] switch_core_media.c:7009 sofia/external/0105914600 Set 2833 dtmf send payload to 101 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [DEBUG] switch_core_media.c:7016 sofia/external/0105914600 Set 2833 dtmf receive payload to 101 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [DEBUG] switch_core_media.c:7039 sofia/external/0105914600 Set rtp dtmf delay to 40 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [NOTICE] sofia.c:8157 Channel [sofia/external/0105914600] has been answered 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [DEBUG] switch_channel.c:3772 (sofia/external/0105914600) Callstate Change RINGING -> ACTIVE 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [DEBUG] sofia.c:7041 Channel sofia/external/0105914600 entering state [received][100] 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [DEBUG] switch_core_media.c:4696 sofia/external/0105914600 Set 2833 dtmf send payload to 101 recv payload to 101 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [DEBUG] switch_core_media.c:6692 Audio params changed for sofia/external/0105914600 from 154.118.252.43:12258 to 192.168.16.199:16706 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [DEBUG] switch_core_media.c:6703 AUDIO RTP [sofia/external/0105914600] 154.118.252.39 port 25274 -> 192.168.16.199 port 16706 codec: 18 ms: 20 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [DEBUG] sofia.c:7041 Channel sofia/external/0105914600 entering state [completed][200] 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [DEBUG] sofia.c:7041 Channel sofia/external/0105914600 entering state [ready][200] 1034293f-e4bf-4fb4-861a-d6c45b755379 2017-02-06 14:41:34.651235 [DEBUG] switch_ivr_originate.c:3686 Originate Resulted in Success: [sofia/external/0105914600] 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [DEBUG] switch_ivr_bridge.c:1566 (sofia/external/0105914600) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [DEBUG] switch_core_state_machine.c:584 (sofia/external/0105914600) Running State Change CS_EXCHANGE_MEDIA (Cur 36 Tot 14825) 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:34.651235 [DEBUG] switch_core_state_machine.c:653 (sofia/external/0105914600) State EXCHANGE_MEDIA 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] switch_ivr_bridge.c:752 BRIDGE THREAD DONE [sofia/external/0105914600] 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [NOTICE] switch_ivr_bridge.c:856 Hangup sofia/external/0105914600 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] switch_core_state_machine.c:653 (sofia/external/0105914600) State EXCHANGE_MEDIA going to sleep 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] switch_core_state_machine.c:584 (sofia/external/0105914600) Running State Change CS_HANGUP (Cur 36 Tot 14825) 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] switch_core_state_machine.c:850 (sofia/external/0105914600) Callstate Change ACTIVE -> HANGUP 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] switch_core_state_machine.c:852 (sofia/external/0105914600) State HANGUP 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] mod_sofia.c:432 sofia/external/0105914600 Overriding SIP cause 480 with 200 from the other leg 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] mod_sofia.c:438 Channel sofia/external/0105914600 hanging up, cause: NORMAL_CLEARING 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/external/0105914600 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] switch_ivr_bridge.c:1664 sofia/external/0105914600 skip receive message [UNBRIDGE] (channel is hungup already) 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] switch_core_state_machine.c:60 sofia/external/0105914600 Standard HANGUP, cause: NORMAL_CLEARING 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] switch_core_state_machine.c:852 (sofia/external/0105914600) State HANGUP going to sleep 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] switch_core_state_machine.c:619 (sofia/external/0105914600) State Change CS_HANGUP -> CS_REPORTING 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] switch_core_state_machine.c:584 (sofia/external/0105914600) Running State Change CS_REPORTING (Cur 36 Tot 14825) 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] switch_core_state_machine.c:938 (sofia/external/0105914600) State REPORTING 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] switch_core_state_machine.c:174 sofia/external/0105914600 Standard REPORTING, cause: NORMAL_CLEARING 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] switch_core_state_machine.c:938 (sofia/external/0105914600) State REPORTING going to sleep 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] switch_core_state_machine.c:610 (sofia/external/0105914600) State Change CS_REPORTING -> CS_DESTROY 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] switch_core_session.c:1647 Session 14821 (sofia/external/0105914600) Locked, Waiting on external entities 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [NOTICE] switch_core_session.c:1665 Session 14821 (sofia/external/0105914600) Ended 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [NOTICE] switch_core_session.c:1669 Close Channel sofia/external/0105914600 [CS_DESTROY] 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] switch_core_state_machine.c:741 (sofia/external/0105914600) Running State Change CS_DESTROY (Cur 35 Tot 14825) 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] switch_core_state_machine.c:751 (sofia/external/0105914600) State DESTROY 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] mod_sofia.c:343 sofia/external/0105914600 SOFIA DESTROY 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] switch_core_state_machine.c:181 sofia/external/0105914600 Standard DESTROY 9413c4ac-0659-4b69-bd76-df3a45e3fc10 2017-02-06 14:41:36.811236 [DEBUG] switch_core_state_machine.c:751 (sofia/external/0105914600) State DESTROY going to sleep