freeswitch@ubu> 2014-09-02 19:59:31.164700 [NOTICE] switch_channel.c:1054 New Channel sofia/profile5090/pap2@192.168.1.71:5090 [53898cb2-3316-11e4-9c83-bd56c23fe68b] 2014-09-02 19:59:31.164700 [DEBUG] switch_core_session.c:1052 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:31.164700 [DEBUG] switch_core_session.c:1052 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:467 (sofia/profile5090/pap2@192.168.1.71:5090) Running State Change CS_NEW 2014-09-02 19:59:31.164700 [DEBUG] sofia.c:8342 sofia/profile5090/pap2@192.168.1.71:5090 receiving invite from 192.168.1.106:5061 version: 1.5.13b git 795d974 2014-05-27 16:20:29Z 64bit 2014-09-02 19:59:31.164700 [DEBUG] sofia.c:6204 Channel sofia/profile5090/pap2@192.168.1.71:5090 entering state [received][100] 2014-09-02 19:59:31.164700 [DEBUG] sofia.c:6214 Remote SDP: v=0 o=- 130086 130086 IN IP4 192.168.1.106 s=- c=IN IP4 192.168.1.106 t=0 0 m=audio 16412 RTP/AVP 4 100 101 a=rtpmap:4 G723/8000 a=rtpmap:100 NSE/8000 a=fmtp:100 192-193 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 2014-09-02 19:59:31.164700 [DEBUG] sofia.c:6469 (sofia/profile5090/pap2@192.168.1.71:5090) State Change CS_NEW -> CS_INIT 2014-09-02 19:59:31.164700 [DEBUG] switch_core_session.c:1387 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:486 (sofia/profile5090/pap2@192.168.1.71:5090) State NEW 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:467 (sofia/profile5090/pap2@192.168.1.71:5090) Running State Change CS_INIT 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:507 (sofia/profile5090/pap2@192.168.1.71:5090) State INIT 2014-09-02 19:59:31.164700 [DEBUG] mod_sofia.c:87 sofia/profile5090/pap2@192.168.1.71:5090 SOFIA INIT 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:40 sofia/profile5090/pap2@192.168.1.71:5090 Standard INIT 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:48 (sofia/profile5090/pap2@192.168.1.71:5090) State Change CS_INIT -> CS_ROUTING 2014-09-02 19:59:31.164700 [DEBUG] switch_core_session.c:1387 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:507 (sofia/profile5090/pap2@192.168.1.71:5090) State INIT going to sleep 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:467 (sofia/profile5090/pap2@192.168.1.71:5090) Running State Change CS_ROUTING 2014-09-02 19:59:31.164700 [DEBUG] switch_channel.c:2178 (sofia/profile5090/pap2@192.168.1.71:5090) Callstate Change DOWN -> RINGING 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:523 (sofia/profile5090/pap2@192.168.1.71:5090) State ROUTING 2014-09-02 19:59:31.164700 [DEBUG] mod_sofia.c:123 sofia/profile5090/pap2@192.168.1.71:5090 SOFIA ROUTING 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:164 sofia/profile5090/pap2@192.168.1.71:5090 Standard ROUTING 2014-09-02 19:59:31.164700 [INFO] mod_dialplan_xml.c:558 Processing PAP2 ->1213xxxxxxx in context fromUAs Dialplan: sofia/profile5090/pap2@192.168.1.71:5090 parsing [fromUAs->test_codec_issue] continue=false Dialplan: sofia/profile5090/pap2@192.168.1.71:5090 Regex (PASS) [test_codec_issue] destination_number(1213xxxxxxx) =~ /^1.*/ break=on-false Dialplan: sofia/profile5090/pap2@192.168.1.71:5090 Action set(continue_on_fail=true) Dialplan: sofia/profile5090/pap2@192.168.1.71:5090 Action set(proxy_media=false) Dialplan: sofia/profile5090/pap2@192.168.1.71:5090 Action bridge([leg_timeout=60,process_cdr=false,execute_on_answer=sched_hangup +6 alloted_timeout,sip_auth_username=XXXXXXXX,sip_auth_password=XXXXXXX,origination_caller_id_number=1223334444]sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:214 (sofia/profile5090/pap2@192.168.1.71:5090) State Change CS_ROUTING -> CS_EXECUTE 2014-09-02 19:59:31.164700 [DEBUG] switch_core_session.c:1387 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:523 (sofia/profile5090/pap2@192.168.1.71:5090) State ROUTING going to sleep 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:467 (sofia/profile5090/pap2@192.168.1.71:5090) Running State Change CS_EXECUTE 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:530 (sofia/profile5090/pap2@192.168.1.71:5090) State EXECUTE 2014-09-02 19:59:31.164700 [DEBUG] mod_sofia.c:178 sofia/profile5090/pap2@192.168.1.71:5090 SOFIA EXECUTE 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:256 sofia/profile5090/pap2@192.168.1.71:5090 Standard EXECUTE EXECUTE sofia/profile5090/pap2@192.168.1.71:5090 set(continue_on_fail=true) 2014-09-02 19:59:31.164700 [DEBUG] mod_dptools.c:1435 sofia/profile5090/pap2@192.168.1.71:5090 SET [continue_on_fail]=[true] EXECUTE sofia/profile5090/pap2@192.168.1.71:5090 set(proxy_media=false) 2014-09-02 19:59:31.164700 [DEBUG] mod_dptools.c:1435 sofia/profile5090/pap2@192.168.1.71:5090 SET [proxy_media]=[false] EXECUTE sofia/profile5090/pap2@192.168.1.71:5090 bridge([leg_timeout=60,process_cdr=false,execute_on_answer=sched_hangup +6 alloted_timeout,sip_auth_username=XXXXXXX,sip_auth_password=XXXXXXX,origination_caller_id_number=1223334444]sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) 2014-09-02 19:59:31.164700 [DEBUG] switch_ivr_originate.c:2078 Parsing global variables 2014-09-02 19:59:31.164700 [DEBUG] switch_ivr_originate.c:2525 Parsing session specific variables 2014-09-02 19:59:31.164700 [DEBUG] switch_event.c:1687 Parsing variable [leg_timeout]=[60] 2014-09-02 19:59:31.164700 [DEBUG] switch_event.c:1687 Parsing variable [process_cdr]=[false] 2014-09-02 19:59:31.164700 [DEBUG] switch_event.c:1687 Parsing variable [execute_on_answer]=[sched_hangup +6 alloted_timeout] 2014-09-02 19:59:31.164700 [DEBUG] switch_event.c:1687 Parsing variable [sip_auth_username]=[XXXXXXX] 2014-09-02 19:59:31.164700 [DEBUG] switch_event.c:1687 Parsing variable [sip_auth_password]=[XXXXXXX] 2014-09-02 19:59:31.164700 [DEBUG] switch_event.c:1687 Parsing variable [origination_caller_id_number]=[1223334444] 2014-09-02 19:59:31.164700 [NOTICE] switch_channel.c:1054 New Channel sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [538a555c-3316-11e4-9c8a-bd56c23fe68b] 2014-09-02 19:59:31.164700 [DEBUG] mod_sofia.c:4565 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State Change CS_NEW -> CS_INIT 2014-09-02 19:59:31.164700 [DEBUG] switch_core_session.c:1387 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [BREAK] 2014-09-02 19:59:31.164700 [DEBUG] mod_sofia.c:4635 [zrtp_passthru] Setting a-leg inherit_codec=true 2014-09-02 19:59:31.164700 [DEBUG] mod_sofia.c:4638 [zrtp_passthru] Setting b-leg absolute_codec_string='G723@8000h@30i@6300b' 2014-09-02 19:59:31.164700 [DEBUG] switch_ivr_originate.c:2819 sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 Setting leg timeout to 60 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:467 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) Running State Change CS_INIT 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:507 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State INIT 2014-09-02 19:59:31.164700 [DEBUG] mod_sofia.c:87 sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 SOFIA INIT 2014-09-02 19:59:31.164700 [DEBUG] sofia_glue.c:1226 sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 sending invite version: 1.5.13b git 795d974 2014-05-27 16:20:29Z 64bit Local SDP: v=0 o=FreeSWITCH 1409682965 1409682966 IN IP4 192.168.1.71 s=FreeSWITCH c=IN IP4 192.168.1.71 t=0 0 m=audio 30206 RTP/AVP 4 101 13 a=rtpmap:4 G723/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:30 a=sendrecv 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:40 sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 Standard INIT 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:48 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State Change CS_INIT -> CS_ROUTING 2014-09-02 19:59:31.164700 [DEBUG] switch_core_session.c:1387 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [BREAK] 2014-09-02 19:59:31.164700 [DEBUG] switch_core_state_machine.c:507 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State INIT going to sleep 2014-09-02 19:59:31.184635 [DEBUG] switch_core_session.c:1052 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [BREAK] 2014-09-02 19:59:31.184635 [DEBUG] switch_core_state_machine.c:467 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) Running State Change CS_ROUTING 2014-09-02 19:59:31.184635 [DEBUG] sofia.c:6204 Channel sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 entering state [calling][0] 2014-09-02 19:59:31.184635 [DEBUG] switch_core_state_machine.c:523 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State ROUTING 2014-09-02 19:59:31.184635 [DEBUG] mod_sofia.c:123 sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 SOFIA ROUTING 2014-09-02 19:59:31.184635 [DEBUG] switch_ivr_originate.c:67 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2014-09-02 19:59:31.184635 [DEBUG] switch_core_session.c:1387 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [BREAK] 2014-09-02 19:59:31.184635 [DEBUG] switch_core_state_machine.c:523 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State ROUTING going to sleep 2014-09-02 19:59:31.184635 [DEBUG] switch_core_state_machine.c:467 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) Running State Change CS_CONSUME_MEDIA 2014-09-02 19:59:31.184635 [DEBUG] switch_core_state_machine.c:542 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State CONSUME_MEDIA 2014-09-02 19:59:31.184635 [DEBUG] switch_core_state_machine.c:542 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State CONSUME_MEDIA going to sleep 2014-09-02 19:59:31.204637 [DEBUG] switch_core_session.c:1052 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [BREAK] 2014-09-02 19:59:31.204637 [DEBUG] switch_core_session.c:1052 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [BREAK] 2014-09-02 19:59:31.204637 [DEBUG] sofia.c:6204 Channel sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 entering state [calling][0] 2014-09-02 19:59:34.504698 [DEBUG] switch_core_session.c:1052 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [BREAK] 2014-09-02 19:59:34.504698 [DEBUG] switch_core_session.c:1052 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [BREAK] 2014-09-02 19:59:34.524678 [DEBUG] sofia.c:6204 Channel sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 entering state [proceeding][183] 2014-09-02 19:59:34.524678 [DEBUG] sofia.c:6214 Remote SDP: v=0 o=Sippy 148147724 1 IN IP4 SIP.PROVIDER.TLD s=- t=0 0 m=audio 59130 RTP/AVP 4 101 c=IN IP4 SIP.PROVIDER.TLD a=rtpmap:4 G723/8000 a=fmtp:4 annexa=yes a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 2014-09-02 19:59:34.524678 [DEBUG] switch_core_media.c:3383 Audio Codec Compare [G723:4:8000:30:6300]/[G723:4:8000:30:6300] 2014-09-02 19:59:34.524678 [DEBUG] switch_core_media.c:3437 Audio Codec Compare [G723:4:8000:30:6300] ++++ is saved as a match 2014-09-02 19:59:34.524678 [DEBUG] switch_core_media.c:3309 Set telephone-event payload to 101 2014-09-02 19:59:34.524678 [DEBUG] switch_core_media.c:2343 Set Codec sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 G723/8000 30 ms 240 samples 6300 bits 2014-09-02 19:59:34.524678 [DEBUG] switch_core_codec.c:111 sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 Original read codec set to G723:4 2014-09-02 19:59:34.524678 [DEBUG] switch_core_media.c:3617 Set 2833 dtmf send payload to 101 2014-09-02 19:59:34.524678 [DEBUG] switch_core_media.c:4841 AUDIO RTP [sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060] 192.168.1.71 port 30206 -> SIP.PROVIDER.TLD port 59130 codec: 4 ms: 30 2014-09-02 19:59:34.524678 [DEBUG] switch_rtp.c:3349 Starting timer [soft] 240 bytes per 30ms 2014-09-02 19:59:34.524678 [DEBUG] switch_core_media.c:5188 Set 2833 dtmf send payload to 101 2014-09-02 19:59:34.524678 [DEBUG] switch_core_media.c:5194 Set 2833 dtmf receive payload to 101 2014-09-02 19:59:34.524678 [NOTICE] sofia_media.c:92 Pre-Answer sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060! 2014-09-02 19:59:34.524678 [DEBUG] switch_channel.c:3389 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:34.524678 [DEBUG] switch_channel.c:3393 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) Callstate Change DOWN -> EARLY 2014-09-02 19:59:34.524678 [DEBUG] switch_ivr_originate.c:412 Setting codec string on sofia/profile5090/pap2@192.168.1.71:5090 to G723@8000h@30i 2014-09-02 19:59:34.524678 [INFO] switch_ivr_originate.c:3500 Sending early media 2014-09-02 19:59:34.524678 [DEBUG] switch_core_media.c:3383 Audio Codec Compare [G723:4:8000:30:6300]/[G723:4:8000:30:6300] 2014-09-02 19:59:34.524678 [DEBUG] switch_core_media.c:3437 Audio Codec Compare [G723:4:8000:30:6300] ++++ is saved as a match 2014-09-02 19:59:34.524678 [DEBUG] switch_core_media.c:3383 Audio Codec Compare [NSE:100:8000:30:0]/[G723:4:8000:30:6300] 2014-09-02 19:59:34.524678 [DEBUG] switch_core_media.c:3309 Set telephone-event payload to 101 2014-09-02 19:59:34.524678 [DEBUG] switch_core_media.c:2343 Set Codec sofia/profile5090/pap2@192.168.1.71:5090 G723/8000 30 ms 240 samples 6300 bits 2014-09-02 19:59:34.524678 [DEBUG] switch_core_codec.c:111 sofia/profile5090/pap2@192.168.1.71:5090 Original read codec set to G723:4 2014-09-02 19:59:34.524678 [DEBUG] switch_core_media.c:3626 Set 2833 dtmf send/recv payload to 101 2014-09-02 19:59:34.524678 [DEBUG] switch_core_media.c:4841 AUDIO RTP [sofia/profile5090/pap2@192.168.1.71:5090] 192.168.1.71 port 20568 -> 192.168.1.106 port 16412 codec: 4 ms: 30 2014-09-02 19:59:34.524678 [DEBUG] switch_rtp.c:3349 Starting timer [soft] 240 bytes per 30ms 2014-09-02 19:59:34.544646 [DEBUG] switch_core_media.c:5188 Set 2833 dtmf send payload to 101 2014-09-02 19:59:34.544646 [DEBUG] switch_core_media.c:5194 Set 2833 dtmf receive payload to 101 2014-09-02 19:59:34.544646 [NOTICE] sofia_media.c:92 Pre-Answer sofia/profile5090/pap2@192.168.1.71:5090! 2014-09-02 19:59:34.544646 [DEBUG] switch_channel.c:3393 (sofia/profile5090/pap2@192.168.1.71:5090) Callstate Change RINGING -> EARLY 2014-09-02 19:59:34.544646 [DEBUG] mod_sofia.c:2222 Ring SDP: v=0 o=FreeSWITCH 1409692606 1409692607 IN IP4 192.168.1.71 s=FreeSWITCH c=IN IP4 192.168.1.71 t=0 0 m=audio 20568 RTP/AVP 4 101 a=rtpmap:4 G723/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:30 a=sendrecv 2014-09-02 19:59:34.544646 [DEBUG] switch_core_session.c:907 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:34.544646 [DEBUG] switch_ivr_originate.c:3551 Originate Resulted in Success: [sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060] 2014-09-02 19:59:34.544646 [DEBUG] switch_core_session.c:1052 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:34.544646 [DEBUG] sofia.c:6204 Channel sofia/profile5090/pap2@192.168.1.71:5090 entering state [early][183] 2014-09-02 19:59:34.544646 [DEBUG] switch_core_session.c:907 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [BREAK] 2014-09-02 19:59:34.544646 [DEBUG] switch_core_session.c:907 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:34.544646 [DEBUG] switch_ivr_bridge.c:1460 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2014-09-02 19:59:34.544646 [DEBUG] switch_core_session.c:1387 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [BREAK] 2014-09-02 19:59:34.544646 [DEBUG] switch_core_state_machine.c:467 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) Running State Change CS_EXCHANGE_MEDIA 2014-09-02 19:59:34.544646 [DEBUG] switch_core_state_machine.c:533 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State EXCHANGE_MEDIA 2014-09-02 19:59:34.544646 [DEBUG] mod_sofia.c:592 SOFIA EXCHANGE_MEDIA 2014-09-02 19:59:34.564665 [DEBUG] switch_rtp.c:5570 Correct ip/port confirmed. 2014-09-02 19:59:34.604668 [DEBUG] switch_rtp.c:5570 Correct ip/port confirmed. 2014-09-02 19:59:49.904636 [DEBUG] switch_core_session.c:1052 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [BREAK] 2014-09-02 19:59:49.904636 [DEBUG] switch_core_session.c:1052 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [BREAK] 2014-09-02 19:59:49.944725 [DEBUG] sofia.c:6204 Channel sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 entering state [completing][200] 2014-09-02 19:59:49.944725 [DEBUG] sofia.c:6214 Remote SDP: v=0 o=Sippy 148147724 2 IN IP4 SIP.PROVIDER.TLD s=- t=0 0 m=audio 59130 RTP/AVP 4 101 c=IN IP4 SIP.PROVIDER.TLD a=rtpmap:4 G723/8000 a=fmtp:4 annexa=yes a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 2014-09-02 19:59:49.944725 [DEBUG] switch_core_session.c:1052 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [BREAK] 2014-09-02 19:59:49.944725 [DEBUG] switch_core_session.c:1052 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [BREAK] 2014-09-02 19:59:49.964640 [DEBUG] sofia.c:6204 Channel sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 entering state [ready][200] 2014-09-02 19:59:49.964640 [DEBUG] sofia.c:6214 Remote SDP: v=0 o=Sippy 148147724 2 IN IP4 SIP.PROVIDER.TLD s=- t=0 0 m=audio 59130 RTP/AVP 4 101 c=IN IP4 SIP.PROVIDER.TLD a=rtpmap:4 G723/8000 a=fmtp:4 annexa=yes a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv 2014-09-02 19:59:49.964640 [DEBUG] switch_core_media.c:3383 Audio Codec Compare [G723:4:8000:30:6300]/[G723:4:8000:30:6300] 2014-09-02 19:59:49.964640 [DEBUG] switch_core_media.c:3437 Audio Codec Compare [G723:4:8000:30:6300] ++++ is saved as a match 2014-09-02 19:59:49.964640 [DEBUG] switch_core_media.c:3309 Set telephone-event payload to 101 2014-09-02 19:59:49.964640 [DEBUG] switch_core_media.c:3617 Set 2833 dtmf send payload to 101 2014-09-02 19:59:49.964640 [DEBUG] sofia.c:6871 Processing updated SDP 2014-09-02 19:59:49.964640 [DEBUG] switch_core_media.c:4825 Audio params are unchanged for sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060. 2014-09-02 19:59:49.964640 [DEBUG] switch_channel.c:3629 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:49.964640 [NOTICE] sofia.c:6971 Channel [sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060] has been answered EXECUTE sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 sched_hangup(+6 alloted_timeout) 2014-09-02 19:59:49.964640 [DEBUG] switch_scheduler.c:249 Added task 6 switch_ivr_schedule_hangup (538a555c-3316-11e4-9c8a-bd56c23fe68b) to run at 1409713195 2014-09-02 19:59:49.964640 [DEBUG] switch_channel.c:3683 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) Callstate Change EARLY -> ACTIVE 2014-09-02 19:59:49.984639 [DEBUG] mod_sofia.c:778 Local SDP sofia/profile5090/pap2@192.168.1.71:5090: v=0 o=FreeSWITCH 1409692606 1409692608 IN IP4 192.168.1.71 s=FreeSWITCH c=IN IP4 192.168.1.71 t=0 0 m=audio 20568 RTP/AVP 4 101 a=rtpmap:4 G723/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:30 a=sendrecv 2014-09-02 19:59:49.984639 [DEBUG] switch_core_session.c:907 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:49.984639 [NOTICE] switch_ivr_bridge.c:496 Channel [sofia/profile5090/pap2@192.168.1.71:5090] has been answered 2014-09-02 19:59:49.984639 [DEBUG] switch_core_session.c:1052 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:49.984639 [DEBUG] switch_channel.c:3683 (sofia/profile5090/pap2@192.168.1.71:5090) Callstate Change EARLY -> ACTIVE 2014-09-02 19:59:49.984639 [DEBUG] sofia.c:6204 Channel sofia/profile5090/pap2@192.168.1.71:5090 entering state [completed][200] 2014-09-02 19:59:50.004700 [DEBUG] switch_core_media.c:2271 Already using G723 2014-09-02 19:59:50.004700 [DEBUG] switch_core_session.c:1052 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:50.004700 [DEBUG] switch_core_session.c:1052 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:50.004700 [DEBUG] switch_core_session.c:1052 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:50.004700 [DEBUG] sofia.c:6204 Channel sofia/profile5090/pap2@192.168.1.71:5090 entering state [ready][200] 2014-09-02 19:59:50.024656 [DEBUG] switch_core_session.c:969 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [BREAK] 2014-09-02 19:59:50.024656 [DEBUG] switch_core_session.c:969 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:55.464701 [NOTICE] switch_ivr_async.c:4261 Hangup sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [CS_EXCHANGE_MEDIA] [NONE] 2014-09-02 19:59:55.464701 [DEBUG] switch_channel.c:3216 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [KILL] 2014-09-02 19:59:55.464701 [DEBUG] switch_core_session.c:1387 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [BREAK] 2014-09-02 19:59:55.464701 [DEBUG] switch_scheduler.c:144 Deleting task 6 switch_ivr_schedule_hangup (538a555c-3316-11e4-9c8a-bd56c23fe68b) 2014-09-02 19:59:55.464701 [DEBUG] switch_ivr_bridge.c:578 sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 ending bridge by request from write function 2014-09-02 19:59:55.484654 [DEBUG] switch_ivr_bridge.c:659 BRIDGE THREAD DONE [sofia/profile5090/pap2@192.168.1.71:5090] 2014-09-02 19:59:55.484654 [DEBUG] switch_ivr_bridge.c:689 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [BREAK] 2014-09-02 19:59:55.484654 [DEBUG] switch_ivr_bridge.c:1558 sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 skip receive message [UNBRIDGE] (channel is hungup already) 2014-09-02 19:59:55.484654 [DEBUG] switch_core_session.c:907 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:55.484654 [NOTICE] switch_core_state_machine.c:313 sofia/profile5090/pap2@192.168.1.71:5090 has executed the last dialplan instruction, hanging up. 2014-09-02 19:59:55.484654 [NOTICE] switch_core_state_machine.c:315 Hangup sofia/profile5090/pap2@192.168.1.71:5090 [CS_EXECUTE] [NORMAL_CLEARING] 2014-09-02 19:59:55.484654 [DEBUG] switch_channel.c:3216 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [KILL] 2014-09-02 19:59:55.484654 [DEBUG] switch_core_session.c:1387 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:530 (sofia/profile5090/pap2@192.168.1.71:5090) State EXECUTE going to sleep 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:467 (sofia/profile5090/pap2@192.168.1.71:5090) Running State Change CS_HANGUP 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:730 (sofia/profile5090/pap2@192.168.1.71:5090) Callstate Change ACTIVE -> HANGUP 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:732 (sofia/profile5090/pap2@192.168.1.71:5090) State HANGUP 2014-09-02 19:59:55.484654 [DEBUG] mod_sofia.c:413 Channel sofia/profile5090/pap2@192.168.1.71:5090 hanging up, cause: NORMAL_CLEARING 2014-09-02 19:59:55.484654 [DEBUG] mod_sofia.c:465 Sending BYE to sofia/profile5090/pap2@192.168.1.71:5090 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:58 sofia/profile5090/pap2@192.168.1.71:5090 Standard HANGUP, cause: NORMAL_CLEARING 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:732 (sofia/profile5090/pap2@192.168.1.71:5090) State HANGUP going to sleep 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:499 (sofia/profile5090/pap2@192.168.1.71:5090) State Change CS_HANGUP -> CS_REPORTING 2014-09-02 19:59:55.484654 [DEBUG] switch_core_session.c:1387 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:467 (sofia/profile5090/pap2@192.168.1.71:5090) Running State Change CS_REPORTING 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:818 (sofia/profile5090/pap2@192.168.1.71:5090) State REPORTING 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:102 sofia/profile5090/pap2@192.168.1.71:5090 Standard REPORTING, cause: NORMAL_CLEARING 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:818 (sofia/profile5090/pap2@192.168.1.71:5090) State REPORTING going to sleep 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:493 (sofia/profile5090/pap2@192.168.1.71:5090) State Change CS_REPORTING -> CS_DESTROY 2014-09-02 19:59:55.484654 [DEBUG] switch_core_session.c:1387 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:55.484654 [DEBUG] switch_core_session.c:1614 Session 7 (sofia/profile5090/pap2@192.168.1.71:5090) Locked, Waiting on external entities 2014-09-02 19:59:55.484654 [DEBUG] switch_ivr_bridge.c:584 sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 ending bridge by request from read function 2014-09-02 19:59:55.484654 [DEBUG] switch_ivr_bridge.c:659 BRIDGE THREAD DONE [sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060] 2014-09-02 19:59:55.484654 [DEBUG] switch_ivr_bridge.c:689 Send signal sofia/profile5090/pap2@192.168.1.71:5090 [BREAK] 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:533 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State EXCHANGE_MEDIA going to sleep 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:467 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) Running State Change CS_HANGUP 2014-09-02 19:59:55.484654 [NOTICE] switch_core_session.c:1632 Session 7 (sofia/profile5090/pap2@192.168.1.71:5090) Ended 2014-09-02 19:59:55.484654 [NOTICE] switch_core_session.c:1636 Close Channel sofia/profile5090/pap2@192.168.1.71:5090 [CS_DESTROY] 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:730 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) Callstate Change ACTIVE -> HANGUP 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:618 (sofia/profile5090/pap2@192.168.1.71:5090) Callstate Change HANGUP -> DOWN 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:732 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State HANGUP 2014-09-02 19:59:55.484654 [DEBUG] mod_sofia.c:413 Channel sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 hanging up, cause: NONE 2014-09-02 19:59:55.484654 [DEBUG] mod_sofia.c:465 Sending BYE to sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:621 (sofia/profile5090/pap2@192.168.1.71:5090) Running State Change CS_DESTROY 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:58 sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 Standard HANGUP, cause: NONE 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:732 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State HANGUP going to sleep 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:499 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State Change CS_HANGUP -> CS_REPORTING 2014-09-02 19:59:55.484654 [DEBUG] switch_core_session.c:1387 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [BREAK] 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:467 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) Running State Change CS_REPORTING 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:631 (sofia/profile5090/pap2@192.168.1.71:5090) State DESTROY 2014-09-02 19:59:55.484654 [DEBUG] mod_sofia.c:323 sofia/profile5090/pap2@192.168.1.71:5090 SOFIA DESTROY 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:109 sofia/profile5090/pap2@192.168.1.71:5090 Standard DESTROY 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:631 (sofia/profile5090/pap2@192.168.1.71:5090) State DESTROY going to sleep 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:818 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State REPORTING 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:102 sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 Standard REPORTING, cause: NONE 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:818 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State REPORTING going to sleep 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:493 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State Change CS_REPORTING -> CS_DESTROY 2014-09-02 19:59:55.484654 [DEBUG] switch_core_session.c:1387 Send signal sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [BREAK] 2014-09-02 19:59:55.484654 [DEBUG] switch_core_session.c:1614 Session 8 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) Locked, Waiting on external entities 2014-09-02 19:59:55.484654 [NOTICE] switch_core_session.c:1632 Session 8 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) Ended 2014-09-02 19:59:55.484654 [NOTICE] switch_core_session.c:1636 Close Channel sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 [CS_DESTROY] 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:618 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) Callstate Change HANGUP -> DOWN 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:621 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) Running State Change CS_DESTROY 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:631 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State DESTROY 2014-09-02 19:59:55.484654 [DEBUG] mod_sofia.c:323 sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 SOFIA DESTROY 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:109 sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060 Standard DESTROY 2014-09-02 19:59:55.484654 [DEBUG] switch_core_state_machine.c:631 (sofia/profile5090/0111213xxxxxxx@SIP.PROVIDER.TLD:5060) State DESTROY going to sleep freeswitch@ubu>