------------------------------------------------------------------------ recv 861 bytes from udp/[10.3.0.22]:5060 at 17:34:05.594085: ------------------------------------------------------------------------ INVITE sip:30@10.3.0.4:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.3.0.22;branch=z9hG4bK8ad4759287A067FB From: "A" ;tag=B0C14C18-E7DC6BB1 To: CSeq: 1 INVITE Call-ID: c64e932c-3eca2965-da54ee6@10.3.0.22 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_670-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 241 v=0 o=- 1167627581 1167627581 IN IP4 10.3.0.22 s=Polycom IP Phone c=IN IP4 10.3.0.22 t=0 0 a=sendrecv m=audio 2262 RTP/AVP 9 0 8 127 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:127 telephone-event/8000 ------------------------------------------------------------------------ send 333 bytes to udp/[10.3.0.22]:5060 at 17:34:05.595235: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.3.0.22;branch=z9hG4bK8ad4759287A067FB From: "A" ;tag=B0C14C18-E7DC6BB1 To: Call-ID: c64e932c-3eca2965-da54ee6@10.3.0.22 CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:05.592923 [DEBUG] sofia.c:7559 IP 10.3.0.22 Rejected by acl "domains". Falling back to Digest auth. 2012-03-08 18:34:05.592923 [WARNING] sofia_reg.c:1422 SIP auth challenge (INVITE) on sofia profile 'internal' for [30@10.3.0.4] from ip 10.3.0.22 send 816 bytes to udp/[10.3.0.22]:5060 at 17:34:05.598758: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.3.0.22;branch=z9hG4bK8ad4759287A067FB From: "A" ;tag=B0C14C18-E7DC6BB1 To: ;tag=Bvv69Ze2ttHyB Call-ID: c64e932c-3eca2965-da54ee6@10.3.0.22 CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Proxy-Authenticate: Digest realm="10.3.0.4", nonce="e73b92aa-6944-11e1-a7c3-a55c2ebde3ff", algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ recv 535 bytes from udp/[10.3.0.22]:5060 at 17:34:05.608337: ------------------------------------------------------------------------ ACK sip:30@10.3.0.4:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.3.0.22;branch=z9hG4bK8ad4759287A067FB From: "A" ;tag=B0C14C18-E7DC6BB1 To: ;tag=Bvv69Ze2ttHyB CSeq: 1 ACK Call-ID: c64e932c-3eca2965-da54ee6@10.3.0.22 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_670-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Max-Forwards: 70 Content-Length: 0 ------------------------------------------------------------------------ recv 1115 bytes from udp/[10.3.0.22]:5060 at 17:34:05.611505: ------------------------------------------------------------------------ INVITE sip:30@10.3.0.4:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.3.0.22;branch=z9hG4bKacba9efF22172C0 From: "A" ;tag=B0C14C18-E7DC6BB1 To: CSeq: 2 INVITE Call-ID: c64e932c-3eca2965-da54ee6@10.3.0.22 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_670-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Supported: 100rel,replaces Allow-Events: talk,hold,conference Proxy-Authorization: Digest username="10", realm="10.3.0.4", nonce="e73b92aa-6944-11e1-a7c3-a55c2ebde3ff", qop=auth, cnonce="eRH+crsyq6cDpwa", nc=00000001, uri="sip:30@10.3.0.4:5060;user=phone", response="a3d381aceaa4551a5eabcb39b426928d", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 241 v=0 o=- 1167627581 1167627581 IN IP4 10.3.0.22 s=Polycom IP Phone c=IN IP4 10.3.0.22 t=0 0 a=sendrecv m=audio 2262 RTP/AVP 9 0 8 127 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:127 telephone-event/8000 ------------------------------------------------------------------------ send 332 bytes to udp/[10.3.0.22]:5060 at 17:34:05.612619: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.3.0.22;branch=z9hG4bKacba9efF22172C0 From: "A" ;tag=B0C14C18-E7DC6BB1 To: Call-ID: c64e932c-3eca2965-da54ee6@10.3.0.22 CSeq: 2 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:05.612916 [DEBUG] sofia.c:7559 IP 10.3.0.22 Rejected by acl "domains". Falling back to Digest auth. 2012-03-08 18:34:05.612916 [NOTICE] switch_channel.c:926 New Channel sofia/internal/10@10.3.0.4 [e73f07fa-6944-11e1-a7c4-a55c2ebde3ff] 2012-03-08 18:34:05.612916 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10@10.3.0.4) Running State Change CS_NEW 2012-03-08 18:34:05.612916 [DEBUG] switch_core_state_machine.c:380 (sofia/internal/10@10.3.0.4) State NEW 2012-03-08 18:34:05.612916 [DEBUG] sofia.c:5526 Channel sofia/internal/10@10.3.0.4 entering state [received][100] 2012-03-08 18:34:05.612916 [DEBUG] sofia.c:5537 Remote SDP: v=0 o=- 1167627581 1167627581 IN IP4 10.3.0.22 s=Polycom IP Phone c=IN IP4 10.3.0.22 t=0 0 a=sendrecv m=audio 2262 RTP/AVP 9 0 8 127 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:127 telephone-event/8000 2012-03-08 18:34:05.612916 [DEBUG] sofia_glue.c:4865 Audio Codec Compare [G722:9:8000:20:64000]/[G722:9:8000:20:64000] 2012-03-08 18:34:05.612916 [DEBUG] sofia_glue.c:2982 Set Codec sofia/internal/10@10.3.0.4 G722/8000 20 ms 160 samples 64000 bits 2012-03-08 18:34:05.612916 [DEBUG] switch_core_codec.c:111 sofia/internal/10@10.3.0.4 Original read codec set to G722:9 2012-03-08 18:34:05.612916 [DEBUG] sofia_glue.c:4986 Set 2833 dtmf send/recv payload to 127 2012-03-08 18:34:05.612916 [DEBUG] sofia.c:5749 (sofia/internal/10@10.3.0.4) State Change CS_NEW -> CS_INIT 2012-03-08 18:34:05.612916 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:05.612916 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10@10.3.0.4) Running State Change CS_INIT 2012-03-08 18:34:05.612916 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/10@10.3.0.4) State INIT 2012-03-08 18:34:05.612916 [DEBUG] mod_sofia.c:85 sofia/internal/10@10.3.0.4 SOFIA INIT 2012-03-08 18:34:05.612916 [DEBUG] mod_sofia.c:125 (sofia/internal/10@10.3.0.4) State Change CS_INIT -> CS_ROUTING 2012-03-08 18:34:05.612916 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:05.612916 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/10@10.3.0.4) State INIT going to sleep 2012-03-08 18:34:05.612916 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10@10.3.0.4) Running State Change CS_ROUTING 2012-03-08 18:34:05.612916 [DEBUG] switch_channel.c:1886 (sofia/internal/10@10.3.0.4) Callstate Change DOWN -> RINGING 2012-03-08 18:34:05.612916 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/10@10.3.0.4) State ROUTING 2012-03-08 18:34:05.612916 [DEBUG] mod_sofia.c:148 sofia/internal/10@10.3.0.4 SOFIA ROUTING 2012-03-08 18:34:05.612916 [DEBUG] switch_core_state_machine.c:104 sofia/internal/10@10.3.0.4 Standard ROUTING 2012-03-08 18:34:05.612916 [INFO] mod_dialplan_xml.c:485 Processing A <10>->30 in context default Dialplan: sofia/internal/10@10.3.0.4 parsing [default->nxo_enable_chefsec] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [nxo_enable_chefsec] destination_number(30) =~ /^\*95(\d{0,7})$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->group-intercept] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [group-intercept] destination_number(30) =~ /^\*82$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->intercept-ext] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [intercept-ext] destination_number(30) =~ /^\*81(\d+)$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->nxo_single_intercom_with_two_way_audio] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [nxo_single_intercom_with_two_way_audio] destination_number(30) =~ /^\*01(\d{2,7})$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->nxo_group_intercom] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [nxo_group_intercom] destination_number(30) =~ /^\*02(\d{0,7})$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->Outbound to PSTN 11 Digits] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [Outbound to PSTN 11 Digits] destination_number(30) =~ /^(1[2-9][0-9]{2}[2-9]{7})$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->del-group] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [del-group] destination_number(30) =~ /^\*\*50(\d{2})$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->add-group] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [add-group] destination_number(30) =~ /^\*\*51(\d{2})$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->call-group-simo] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [call-group-simo] destination_number(30) =~ /^\*52(\d{2,4})$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->call-group-order] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [call-group-order] destination_number(30) =~ /^\*53(\d{2,4})$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->nb_conferences] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [nb_conferences] destination_number(30) =~ /^\*(30\d{2})$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->wb_conferences] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [wb_conferences] destination_number(30) =~ /^\*(31\d{2})$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->uwb_conferences] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [uwb_conferences] destination_number(30) =~ /^\*(32\d{2})$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->cdquality_conferences] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [cdquality_conferences] destination_number(30) =~ /^\*(33\d{2})$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->global_directory] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [global_directory] destination_number(30) =~ /^\*77(\d{1,3})$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->redirect_now] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [redirect_now] destination_number(30) =~ /^\*21(\d{0,20})$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->redirect_timeout] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [redirect_timeout] destination_number(30) =~ /^\*22(\d{0,20})$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->redirect_busy] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [redirect_busy] destination_number(30) =~ /^\*23(\d{0,20})$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->call_privacy] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [call_privacy] destination_number(30) =~ /^\*67(\d+)$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->call_privacy] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [call_privacy] destination_number(30) =~ /^\*60$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->send_to_voicemail] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [send_to_voicemail] destination_number(30) =~ /^\*99(\d{2,7})$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->vmain] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [vmain] destination_number(30) =~ /^vmain$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->vmain1] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [vmain1] destination_number(30) =~ /^vmain1$|^\*97$|^97$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->vmain2] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [vmain2] destination_number(30) =~ /^vmain2$|^\*98$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->redirect_now] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (FAIL) [redirect_now] destination_number(30) =~ /^\*35$/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 parsing [default->Local_Extension_test] continue=false Dialplan: sofia/internal/10@10.3.0.4 Regex (PASS) [Local_Extension_test] destination_number(30) =~ /(^\d{2,7}$)/ break=on-false Dialplan: sofia/internal/10@10.3.0.4 Action set(dialed_extension=30) Dialplan: sofia/internal/10@10.3.0.4 Action export(dialed_extension=30) Dialplan: sofia/internal/10@10.3.0.4 Action python(nxo_test) 2012-03-08 18:34:05.612916 [DEBUG] switch_core_state_machine.c:154 (sofia/internal/10@10.3.0.4) State Change CS_ROUTING -> CS_EXECUTE 2012-03-08 18:34:05.612916 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:05.612916 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/10@10.3.0.4) State ROUTING going to sleep 2012-03-08 18:34:05.612916 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10@10.3.0.4) Running State Change CS_EXECUTE 2012-03-08 18:34:05.612916 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/10@10.3.0.4) State EXECUTE 2012-03-08 18:34:05.612916 [DEBUG] mod_sofia.c:241 sofia/internal/10@10.3.0.4 SOFIA EXECUTE 2012-03-08 18:34:05.612916 [DEBUG] switch_core_state_machine.c:192 sofia/internal/10@10.3.0.4 Standard EXECUTE EXECUTE sofia/internal/10@10.3.0.4 set(dialed_extension=30) 2012-03-08 18:34:05.633001 [DEBUG] mod_dptools.c:1281 sofia/internal/10@10.3.0.4 SET [dialed_extension]=[30] EXECUTE sofia/internal/10@10.3.0.4 export(dialed_extension=30) 2012-03-08 18:34:05.633001 [DEBUG] switch_channel.c:1093 EXPORT (export_vars) [dialed_extension]=[30] EXECUTE sofia/internal/10@10.3.0.4 python(nxo_test) 2012-03-08 18:34:05.633001 [NOTICE] mod_python.c:212 Invoking py module: nxo_test 2012-03-08 18:34:05.652944 [DEBUG] mod_python.c:281 Call python script 2012-03-08 18:34:05.652944 [INFO] switch_cpp.cpp:1227 TEST: Destination-extension 30 send 1326 bytes to udp/[10.3.0.25]:5060 at 17:34:05.792382: ------------------------------------------------------------------------ NOTIFY sip:20@10.3.0.25 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKptUaH731cyvgm Max-Forwards: 70 From: ;tag=JElIsHAUjri7 To: "C" ;tag=432C4A25-2C483674 Call-ID: a941c408-2c54f3a7-82c5a8d6@10.3.0.25 CSeq: 185332666 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=1156 Content-Type: application/dialog-info+xml Content-Length: 513 confirmed sip:10@10.3.0.4 sip:30@10.3.0.4 ------------------------------------------------------------------------ send 1334 bytes to udp/[10.3.0.26]:5060 at 17:34:05.793468: ------------------------------------------------------------------------ NOTIFY sip:30@10.3.0.26 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKQ3m3j2m596j3F Max-Forwards: 70 From: ;tag=hzYaAHIZscZq To: "B" ;tag=A52D4836-AD38FE89 Call-ID: 3f77033d-f3b24ec8-f0479fab@10.3.0.26 CSeq: 185332667 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=1156 Content-Type: application/dialog-info+xml Content-Length: 513 confirmed sip:10@10.3.0.4 sip:30@10.3.0.4 ------------------------------------------------------------------------ recv 406 bytes from udp/[10.3.0.25]:5060 at 17:34:05.799132: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKptUaH731cyvgm From: ;tag=JElIsHAUjri7 To: "C" ;tag=432C4A25-2C483674 CSeq: 185332666 NOTIFY Call-ID: a941c408-2c54f3a7-82c5a8d6@10.3.0.25 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ recv 414 bytes from udp/[10.3.0.26]:5060 at 17:34:05.799603: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKQ3m3j2m596j3F From: ;tag=hzYaAHIZscZq To: "B" ;tag=A52D4836-AD38FE89 CSeq: 185332667 NOTIFY Call-ID: 3f77033d-f3b24ec8-f0479fab@10.3.0.26 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ EXECUTE sofia/internal/10@10.3.0.4 set(continue_on_fail=true) 2012-03-08 18:34:06.232952 [DEBUG] mod_dptools.c:1281 sofia/internal/10@10.3.0.4 SET [continue_on_fail]=[true] EXECUTE sofia/internal/10@10.3.0.4 set(hangup_after_bridge=true) 2012-03-08 18:34:06.232952 [DEBUG] mod_dptools.c:1281 sofia/internal/10@10.3.0.4 SET [hangup_after_bridge]=[true] 2012-03-08 18:34:06.232952 [WARNING] switch_cpp.cpp:1227 TEST 1 for UUID e73f07fa-6944-11e1-a7c4-a55c2ebde3ff, src 10 dest 30 EXECUTE sofia/internal/10@10.3.0.4 sleep(1000) 2012-03-08 18:34:07.232931 [WARNING] switch_cpp.cpp:1227 TEST 2 for UUID e73f07fa-6944-11e1-a7c4-a55c2ebde3ff, src 10 dest 30 EXECUTE sofia/internal/10@10.3.0.4 sleep(1000) 2012-03-08 18:34:08.232934 [WARNING] switch_cpp.cpp:1227 TEST 3 for UUID e73f07fa-6944-11e1-a7c4-a55c2ebde3ff, src 10 dest 30 EXECUTE sofia/internal/10@10.3.0.4 sleep(1000) EXECUTE sofia/internal/10@10.3.0.4 info() 2012-03-08 18:34:09.252934 [INFO] mod_dptools.c:1439 CHANNEL_DATA: Channel-State: [CS_EXECUTE] Channel-Call-State: [RINGING] Channel-State-Number: [4] Channel-Name: [sofia/internal/10@10.3.0.4] Unique-ID: [e73f07fa-6944-11e1-a7c4-a55c2ebde3ff] Call-Direction: [inbound] Presence-Call-Direction: [inbound] Channel-HIT-Dialplan: [true] Channel-Presence-ID: [10@10.3.0.4] Channel-Call-UUID: [e73f07fa-6944-11e1-a7c4-a55c2ebde3ff] Answer-State: [ringing] Channel-Read-Codec-Name: [G722] Channel-Read-Codec-Rate: [16000] Channel-Read-Codec-Bit-Rate: [64000] Channel-Write-Codec-Name: [G722] Channel-Write-Codec-Rate: [16000] Channel-Write-Codec-Bit-Rate: [64000] Caller-Direction: [inbound] Caller-Username: [10] Caller-Dialplan: [XML] Caller-Caller-ID-Name: [A] Caller-Caller-ID-Number: [10] Caller-Network-Addr: [10.3.0.22] Caller-ANI: [10] Caller-Destination-Number: [30] Caller-Unique-ID: [e73f07fa-6944-11e1-a7c4-a55c2ebde3ff] Caller-Source: [mod_sofia] Caller-Context: [default] Caller-Channel-Name: [sofia/internal/10@10.3.0.4] Caller-Profile-Index: [1] Caller-Profile-Created-Time: [1331228045612916] Caller-Channel-Created-Time: [1331228045612916] Caller-Channel-Answered-Time: [0] Caller-Channel-Progress-Time: [0] Caller-Channel-Progress-Media-Time: [0] Caller-Channel-Hangup-Time: [0] Caller-Channel-Transfer-Time: [0] Caller-Screen-Bit: [true] Caller-Privacy-Hide-Name: [false] Caller-Privacy-Hide-Number: [false] variable_direction: [inbound] variable_uuid: [e73f07fa-6944-11e1-a7c4-a55c2ebde3ff] variable_session_id: [9] variable_sip_local_network_addr: [10.3.0.4] variable_sip_network_ip: [10.3.0.22] variable_sip_network_port: [5060] variable_sip_received_ip: [10.3.0.22] variable_sip_received_port: [5060] variable_sip_via_protocol: [udp] variable_sip_authorized: [true] variable_sip_number_alias: [10] variable_sip_auth_username: [10] variable_sip_auth_realm: [10.3.0.4] variable_number_alias: [10] variable_user_name: [10] variable_domain_name: [10.3.0.4] variable_record_stereo: [true] variable_default_gateway: [fonira] variable_default_areacode: [01] variable_transfer_fallback_extension: [operator] variable_toll_allow: [local,domestic,international,vas] variable_accountcode: [10] variable_user_context: [default] variable_effective_caller_id_name: [A ] variable_effective_caller_id_number: [10] variable_outbound_caller_id_name: [A ] variable_outbound_caller_id_number: [1997156010] variable_callgroup: [intercept] variable_sip_from_user: [10] variable_sip_from_uri: [10@10.3.0.4] variable_sip_from_host: [10.3.0.4] variable_sip_from_user_stripped: [10] variable_sip_from_tag: [B0C14C18-E7DC6BB1] variable_sofia_profile_name: [internal] variable_sip_full_via: [SIP/2.0/UDP 10.3.0.22;branch=z9hG4bKacba9efF22172C0] variable_sip_from_display: [A] variable_sip_full_from: ["A" ;tag=B0C14C18-E7DC6BB1] variable_sip_full_to: [] variable_sip_req_params: [user=phone] variable_sip_req_user: [30] variable_sip_req_port: [5060] variable_sip_req_uri: [30@10.3.0.4:5060] variable_sip_req_host: [10.3.0.4] variable_sip_to_params: [user=phone] variable_sip_to_user: [30] variable_sip_to_uri: [30@10.3.0.4] variable_sip_to_host: [10.3.0.4] variable_sip_contact_user: [10] variable_sip_contact_uri: [10@10.3.0.22] variable_sip_contact_host: [10.3.0.22] variable_channel_name: [sofia/internal/10@10.3.0.4] variable_sip_call_id: [c64e932c-3eca2965-da54ee6@10.3.0.22] variable_sip_user_agent: [PolycomSoundPointIP-SPIP_670-UA/3.3.1.0933] variable_sip_via_host: [10.3.0.22] variable_max_forwards: [70] variable_presence_id: [10@10.3.0.4] variable_switch_r_sdp: [v=0 o=- 1167627581 1167627581 IN IP4 10.3.0.22 s=Polycom IP Phone c=IN IP4 10.3.0.22 t=0 0 a=sendrecv m=audio 2262 RTP/AVP 9 0 8 127 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:127 telephone-event/8000 ] variable_remote_media_ip: [10.3.0.22] variable_remote_media_port: [2262] variable_sip_audio_recv_pt: [9] variable_sip_use_codec_name: [G722] variable_sip_use_codec_rate: [8000] variable_sip_use_codec_ptime: [20] variable_read_codec: [G722] variable_read_rate: [16000] variable_write_codec: [G722] variable_write_rate: [16000] variable_endpoint_disposition: [RECEIVED] variable_DP_MATCH: [ARRAY::30|:30] variable_call_uuid: [e73f07fa-6944-11e1-a7c4-a55c2ebde3ff] variable_dialed_extension: [30] variable_export_vars: [dialed_extension] variable_continue_on_fail: [true] variable_hangup_after_bridge: [true] variable_current_application: [info] EXECUTE sofia/internal/10@10.3.0.4 bridge([leg_timeout=15][origination_caller_id_number=10]user/30@10.3.0.4) 2012-03-08 18:34:09.252934 [DEBUG] switch_channel.c:1047 sofia/internal/10@10.3.0.4 EXPORTING[export_vars] [dialed_extension]=[30] to event 2012-03-08 18:34:09.252934 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables 2012-03-08 18:34:09.252934 [DEBUG] switch_ivr_originate.c:2299 Parsing session specific variables 2012-03-08 18:34:09.252934 [DEBUG] switch_event.c:1522 Parsing variable [leg_timeout]=[15] 2012-03-08 18:34:09.252934 [DEBUG] switch_event.c:1522 Parsing variable [origination_caller_id_number]=[10] 2012-03-08 18:34:09.252934 [DEBUG] switch_channel.c:1047 sofia/internal/10@10.3.0.4 EXPORTING[export_vars] [dialed_extension]=[30] to event 2012-03-08 18:34:09.252934 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables 2012-03-08 18:34:09.252934 [DEBUG] switch_event.c:1522 Parsing variable [presence_id]=[30@10.3.0.4] 2012-03-08 18:34:09.252934 [NOTICE] switch_channel.c:926 New Channel sofia/internal/sip:30@10.3.0.26 [e96bae48-6944-11e1-a7cc-a55c2ebde3ff] 2012-03-08 18:34:09.252934 [DEBUG] mod_sofia.c:4673 (sofia/internal/sip:30@10.3.0.26) State Change CS_NEW -> CS_INIT 2012-03-08 18:34:09.252934 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:09.252934 [DEBUG] switch_ivr_originate.c:2561 sofia/internal/sip:30@10.3.0.26 Setting leg timeout to 15 2012-03-08 18:34:09.252934 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:30@10.3.0.26) Running State Change CS_INIT 2012-03-08 18:34:09.252934 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:30@10.3.0.26) State INIT 2012-03-08 18:34:09.252934 [DEBUG] mod_sofia.c:85 sofia/internal/sip:30@10.3.0.26 SOFIA INIT 2012-03-08 18:34:09.252934 [DEBUG] mod_sofia.c:125 (sofia/internal/sip:30@10.3.0.26) State Change CS_INIT -> CS_ROUTING 2012-03-08 18:34:09.252934 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:09.252934 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:30@10.3.0.26) State INIT going to sleep 2012-03-08 18:34:09.252934 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:30@10.3.0.26) Running State Change CS_ROUTING 2012-03-08 18:34:09.252934 [DEBUG] switch_channel.c:1886 (sofia/internal/sip:30@10.3.0.26) Callstate Change DOWN -> RINGING send 1255 bytes to udp/[10.3.0.26]:5060 at 17:34:09.271864: ------------------------------------------------------------------------ INVITE sip:30@10.3.0.26 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKrcevmX586F9NB Max-Forwards: 69 From: "A " ;tag=DeFrDpg9mcy3j To: Call-ID: c0caa6b7-e3e7-122f-41a2-00900b1be504 CSeq: 25277960 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 369 X-FS-Support: update_display,send_info Remote-Party-ID: "A " ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1331211599 1331211600 IN IP4 10.3.0.4 s=FreeSWITCH c=IN IP4 10.3.0.4 t=0 0 m=audio 16450 RTP/AVP 9 0 8 3 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 16418 RTP/AVP 98 99 100 34 31 a=rtpmap:98 H264/90000 a=rtpmap:99 H263-2000/90000 a=rtpmap:100 H263-1998/90000 a=rtpmap:34 H263/90000 a=rtpmap:31 H261/90000 ------------------------------------------------------------------------ 2012-03-08 18:34:09.252934 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:30@10.3.0.26) State ROUTING 2012-03-08 18:34:09.252934 [DEBUG] mod_sofia.c:148 sofia/internal/sip:30@10.3.0.26 SOFIA ROUTING 2012-03-08 18:34:09.252934 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:30@10.3.0.26) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2012-03-08 18:34:09.252934 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:09.252934 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:30@10.3.0.26) State ROUTING going to sleep 2012-03-08 18:34:09.252934 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:30@10.3.0.26) Running State Change CS_CONSUME_MEDIA 2012-03-08 18:34:09.252934 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:30@10.3.0.26) State CONSUME_MEDIA 2012-03-08 18:34:09.252934 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:30@10.3.0.26) State CONSUME_MEDIA going to sleep 2012-03-08 18:34:09.252934 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:09.252934 [DEBUG] sofia.c:5526 Channel sofia/internal/sip:30@10.3.0.26 entering state [calling][0] recv 413 bytes from udp/[10.3.0.26]:5060 at 17:34:09.279527: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKrcevmX586F9NB From: "A" ;tag=DeFrDpg9mcy3j To: "B" ;tag=7463F28A-2FFBD77D CSeq: 25277960 INVITE Call-ID: c0caa6b7-e3e7-122f-41a2-00900b1be504 Contact: User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ send 1323 bytes to udp/[10.3.0.22]:5060 at 17:34:09.314994: ------------------------------------------------------------------------ NOTIFY sip:10@10.3.0.22 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKSN7mprpc4rZ8p Max-Forwards: 70 From: ;tag=BL1yX2TI1X2c To: "A" ;tag=7B5DFEAE-48CDC3F7 Call-ID: ef7cb8bd-dc381cfe-bf64ccc7@10.3.0.22 CSeq: 185332668 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=3315 Content-Type: application/dialog-info+xml Content-Length: 509 early sip:30@10.3.0.4 sip:10@10.3.0.4 ------------------------------------------------------------------------ send 1321 bytes to udp/[10.3.0.25]:5060 at 17:34:09.318770: ------------------------------------------------------------------------ NOTIFY sip:20@10.3.0.25 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKty0DrK7F11NUj Max-Forwards: 70 From: ;tag=zVD97bWqz9Ei To: "C" ;tag=E729C66F-499D331E Call-ID: 6e8428e-4012accd-98b6429c@10.3.0.25 CSeq: 185332669 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=3315 Content-Type: application/dialog-info+xml Content-Length: 509 early sip:30@10.3.0.4 sip:10@10.3.0.4 ------------------------------------------------------------------------ recv 407 bytes from udp/[10.3.0.22]:5060 at 17:34:09.320972: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKSN7mprpc4rZ8p From: ;tag=BL1yX2TI1X2c To: "A" ;tag=7B5DFEAE-48CDC3F7 CSeq: 185332668 NOTIFY Call-ID: ef7cb8bd-dc381cfe-bf64ccc7@10.3.0.22 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_670-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ send 1333 bytes to udp/[10.3.0.27]:5060 at 17:34:09.323875: ------------------------------------------------------------------------ NOTIFY sip:31@10.3.0.27 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKU7S6SerKyacee Max-Forwards: 70 From: ;tag=j2FaQyd4KlIW To: "Patrick SXXXXXXl" ;tag=26B3115D-24F8F110 Call-ID: 11c82624-cdfad25f-e9f5882@10.3.0.27 CSeq: 185332670 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=3315 Content-Type: application/dialog-info+xml Content-Length: 509 early sip:30@10.3.0.4 sip:10@10.3.0.4 ------------------------------------------------------------------------ recv 405 bytes from udp/[10.3.0.25]:5060 at 17:34:09.324463: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKty0DrK7F11NUj From: ;tag=zVD97bWqz9Ei To: "C" ;tag=E729C66F-499D331E CSeq: 185332669 NOTIFY Call-ID: 6e8428e-4012accd-98b6429c@10.3.0.25 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ recv 417 bytes from udp/[10.3.0.27]:5060 at 17:34:09.328816: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKU7S6SerKyacee From: ;tag=j2FaQyd4KlIW To: "Patrick SXXXXXXl" ;tag=26B3115D-24F8F110 CSeq: 185332670 NOTIFY Call-ID: 11c82624-cdfad25f-e9f5882@10.3.0.27 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ recv 450 bytes from udp/[10.3.0.26]:5060 at 17:34:09.330485: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKrcevmX586F9NB From: "A" ;tag=DeFrDpg9mcy3j To: "B" ;tag=7463F28A-2FFBD77D CSeq: 25277960 INVITE Call-ID: c0caa6b7-e3e7-122f-41a2-00900b1be504 Contact: User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Allow-Events: talk,hold,conference Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:09.312952 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:09.312952 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:09.352961 [DEBUG] sofia.c:5526 Channel sofia/internal/sip:30@10.3.0.26 entering state [proceeding][180] 2012-03-08 18:34:09.352961 [NOTICE] sofia.c:5618 Ring-Ready sofia/internal/sip:30@10.3.0.26! 2012-03-08 18:34:09.352961 [NOTICE] mod_sofia.c:2514 Ring-Ready sofia/internal/10@10.3.0.4! send 797 bytes to udp/[10.3.0.22]:5060 at 17:34:09.373141: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.3.0.22;branch=z9hG4bKacba9efF22172C0 From: "A" ;tag=B0C14C18-E7DC6BB1 To: ;tag=c5NZBUZ5Q37gQ Call-ID: c64e932c-3eca2965-da54ee6@10.3.0.22 CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0 Remote-Party-ID: "Outbound Call" <30>;party=calling;privacy=off;screen=no ------------------------------------------------------------------------ 2012-03-08 18:34:09.352961 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:09.374533 [DEBUG] sofia.c:5526 Channel sofia/internal/10@10.3.0.4 entering state [early][180] 2012-03-08 18:34:09.374533 [DEBUG] switch_core_session.c:729 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:09.374533 [NOTICE] switch_ivr_originate.c:483 Ring Ready sofia/internal/10@10.3.0.4! recv 915 bytes from udp/[10.3.0.26]:5060 at 17:34:10.190061: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKrcevmX586F9NB From: "A" ;tag=DeFrDpg9mcy3j To: "B" ;tag=7463F28A-2FFBD77D CSeq: 25277960 INVITE Call-ID: c0caa6b7-e3e7-122f-41a2-00900b1be504 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER Supported: 100rel,replaces User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Type: application/sdp Content-Length: 347 v=0 o=- 1167627586 1167627586 IN IP4 10.3.0.26 s=Polycom IP Phone c=IN IP4 10.3.0.26 t=0 0 m=audio 2234 RTP/AVP 9 127 a=rtpmap:9 G722/8000 a=rtpmap:127 telephone-event/8000 m=video 0 RTP/AVP 98 99 100 34 31 a=rtpmap:98 H264/90000 a=rtpmap:99 H263-2000/90000 a=rtpmap:100 H263-1998/90000 a=rtpmap:34 H263/90000 a=rtpmap:31 H261/90000 ------------------------------------------------------------------------ 2012-03-08 18:34:10.172931 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:10.172931 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:10.192945 [DEBUG] sofia.c:5526 Channel sofia/internal/sip:30@10.3.0.26 entering state [completing][200] 2012-03-08 18:34:10.192945 [DEBUG] sofia.c:5537 Remote SDP: v=0 o=- 1167627586 1167627586 IN IP4 10.3.0.26 s=Polycom IP Phone c=IN IP4 10.3.0.26 t=0 0 m=audio 2234 RTP/AVP 9 127 a=rtpmap:9 G722/8000 a=rtpmap:127 telephone-event/8000 m=video 0 RTP/AVP 98 99 100 34 31 a=rtpmap:98 H264/90000 a=rtpmap:99 H263-2000/90000 a=rtpmap:100 H263-1998/90000 a=rtpmap:34 H263/90000 a=rtpmap:31 H261/90000 send 336 bytes to udp/[10.3.0.26]:5060 at 17:34:10.201818: ------------------------------------------------------------------------ ACK sip:30@10.3.0.26 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKvgKZU98pUK20S Max-Forwards: 70 From: "A " ;tag=DeFrDpg9mcy3j To: ;tag=7463F28A-2FFBD77D Call-ID: c0caa6b7-e3e7-122f-41a2-00900b1be504 CSeq: 25277960 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:10.192945 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:10.192945 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:10.192945 [DEBUG] sofia.c:5526 Channel sofia/internal/sip:30@10.3.0.26 entering state [ready][200] 2012-03-08 18:34:10.192945 [DEBUG] sofia_glue.c:4865 Audio Codec Compare [G722:9:8000:20:64000]/[G722:9:8000:20:64000] 2012-03-08 18:34:10.192945 [DEBUG] sofia_glue.c:2982 Set Codec sofia/internal/sip:30@10.3.0.26 G722/8000 20 ms 160 samples 64000 bits 2012-03-08 18:34:10.192945 [DEBUG] switch_core_codec.c:111 sofia/internal/sip:30@10.3.0.26 Original read codec set to G722:9 2012-03-08 18:34:10.192945 [DEBUG] sofia_glue.c:4979 Set 2833 dtmf send payload to 127 2012-03-08 18:34:10.192945 [DEBUG] sofia_glue.c:3234 AUDIO RTP [sofia/internal/sip:30@10.3.0.26] 10.3.0.4 port 16450 -> 10.3.0.26 port 2234 codec: 9 ms: 20 2012-03-08 18:34:10.192945 [DEBUG] switch_rtp.c:1661 Starting timer [soft] 160 bytes per 20ms 2012-03-08 18:34:10.192945 [DEBUG] sofia_glue.c:3498 Set 2833 dtmf send payload to 127 2012-03-08 18:34:10.192945 [DEBUG] sofia_glue.c:3504 Set 2833 dtmf receive payload to 101 2012-03-08 18:34:10.192945 [DEBUG] switch_channel.c:3190 (sofia/internal/sip:30@10.3.0.26) Callstate Change RINGING -> ACTIVE 2012-03-08 18:34:10.192945 [DEBUG] switch_channel.c:3202 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:10.192945 [NOTICE] sofia.c:6238 Channel [sofia/internal/sip:30@10.3.0.26] has been answered 2012-03-08 18:34:10.212964 [DEBUG] sofia_glue.c:3234 AUDIO RTP [sofia/internal/10@10.3.0.4] 10.3.0.4 port 16420 -> 10.3.0.22 port 2262 codec: 9 ms: 20 2012-03-08 18:34:10.212964 [DEBUG] switch_rtp.c:1661 Starting timer [soft] 160 bytes per 20ms 2012-03-08 18:34:10.212964 [DEBUG] sofia_glue.c:3498 Set 2833 dtmf send payload to 127 2012-03-08 18:34:10.212964 [DEBUG] sofia_glue.c:3504 Set 2833 dtmf receive payload to 127 2012-03-08 18:34:10.212964 [DEBUG] mod_sofia.c:750 Local SDP sofia/internal/10@10.3.0.4: v=0 o=FreeSWITCH 1331211630 1331211631 IN IP4 10.3.0.4 s=FreeSWITCH c=IN IP4 10.3.0.4 t=0 0 m=audio 16420 RTP/AVP 9 127 a=rtpmap:9 G722/8000 a=rtpmap:127 telephone-event/8000 a=fmtp:127 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv 2012-03-08 18:34:10.212964 [DEBUG] switch_core_session.c:729 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:10.212964 [DEBUG] switch_channel.c:3190 (sofia/internal/10@10.3.0.4) Callstate Change RINGING -> ACTIVE send 1069 bytes to udp/[10.3.0.22]:5060 at 17:34:10.220245: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.22;branch=z9hG4bKacba9efF22172C0 From: "A" ;tag=B0C14C18-E7DC6BB1 To: ;tag=c5NZBUZ5Q37gQ Call-ID: c64e932c-3eca2965-da54ee6@10.3.0.22 CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 239 Remote-Party-ID: "Outbound Call" <30>;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1331211630 1331211631 IN IP4 10.3.0.4 s=FreeSWITCH c=IN IP4 10.3.0.4 t=0 0 m=audio 16420 RTP/AVP 9 127 a=rtpmap:9 G722/80002012-03-08 18:34:10.212964 [NOTICE] switch_ivr_originate.c:3209 Channel [sofia/internal/10@10.3.0.4] has been answered a=rtpmap:127 telephone-event/8000 a=fmtp:127 0-16 a=silenceSupp:off - - - - a=ptime:20 ------------------------------------------------------------------------ 2012-03-08 18:34:10.212964 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:10.212964 [DEBUG] sofia.c:5526 Channel sofia/internal/10@10.3.0.4 entering state [completed][200] 2012-03-08 18:34:10.212964 [DEBUG] switch_ivr_originate.c:3266 Originate Resulted in Success: [sofia/internal/sip:30@10.3.0.26] 2012-03-08 18:34:10.212964 [DEBUG] switch_ivr_originate.c:2561 sofia/internal/sip:30@10.3.0.26 Setting leg timeout to 15 2012-03-08 18:34:10.212964 [DEBUG] switch_ivr_originate.c:3266 Originate Resulted in Success: [sofia/internal/sip:30@10.3.0.26] recv 538 bytes from udp/[10.3.0.22]:5060 at 17:34:10.229645: ------------------------------------------------------------------------ ACK sip:30@10.3.0.4:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.3.0.22;branch=z9hG4bKe8d47063D608BAD4 From: "A" ;tag=B0C14C18-E7DC6BB1 To: ;tag=c5NZBUZ5Q37gQ CSeq: 2 ACK Call-ID: c64e932c-3eca2965-da54ee6@10.3.0.22 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_670-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Max-Forwards: 70 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:10.212964 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:10.212964 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:10.212964 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:10.212964 [DEBUG] sofia.c:5526 Channel sofia/internal/10@10.3.0.4 entering state [ready][200] 2012-03-08 18:34:10.232988 [DEBUG] switch_core_session.c:729 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:10.232988 [DEBUG] switch_core_session.c:729 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:10.232988 [DEBUG] switch_ivr_bridge.c:1328 (sofia/internal/sip:30@10.3.0.26) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2012-03-08 18:34:10.232988 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:10.232988 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:30@10.3.0.26) Running State Change CS_EXCHANGE_MEDIA 2012-03-08 18:34:10.232988 [DEBUG] switch_core_state_machine.c:420 (sofia/internal/sip:30@10.3.0.26) State EXCHANGE_MEDIA 2012-03-08 18:34:10.232988 [DEBUG] mod_sofia.c:578 SOFIA EXCHANGE_MEDIA 2012-03-08 18:34:10.232988 [DEBUG] switch_core_session.c:791 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:10.232988 [DEBUG] switch_core_session.c:791 Send signal sofia/internal/10@10.3.0.4 [BREAK] send 1325 bytes to udp/[10.3.0.25]:5060 at 17:34:10.284271: ------------------------------------------------------------------------ NOTIFY sip:20@10.3.0.25 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKXScrX4StrvrKN Max-Forwards: 70 From: ;tag=zVD97bWqz9Ei To: "C" ;tag=E729C66F-499D331E Call-ID: 6e8428e-4012accd-98b6429c@10.3.0.25 CSeq: 185332671 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=3314 Content-Type: application/dialog-info+xml Content-Length: 513 confirmed sip:30@10.3.0.4 sip:10@10.3.0.4 ------------------------------------------------------------------------ send 1337 bytes to udp/[10.3.0.27]:5060 at 17:34:10.287919: ------------------------------------------------------------------------ NOTIFY sip:31@10.3.0.27 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKy25gZZayN5e6g Max-Forwards: 70 From: ;tag=j2FaQyd4KlIW To: "Patrick SXXXXXXl" ;tag=26B3115D-24F8F110 Call-ID: 11c82624-cdfad25f-e9f5882@10.3.0.27 CSeq: 185332672 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=3314 Content-Type: application/dialog-info+xml Content-Length: 513 confirmed sip:30@10.3.0.4 sip:10@10.3.0.4 ------------------------------------------------------------------------ recv 405 bytes from udp/[10.3.0.25]:5060 at 17:34:10.289984: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKXScrX4StrvrKN From: ;tag=zVD97bWqz9Ei To: "C" ;tag=E729C66F-499D331E CSeq: 185332671 NOTIFY Call-ID: 6e8428e-4012accd-98b6429c@10.3.0.25 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ send 1327 bytes to udp/[10.3.0.22]:5060 at 17:34:10.292085: ------------------------------------------------------------------------ NOTIFY sip:10@10.3.0.22 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKZBZ90tU1je5rc Max-Forwards: 70 From: ;tag=BL1yX2TI1X2c To: "A" ;tag=7B5DFEAE-48CDC3F7 Call-ID: ef7cb8bd-dc381cfe-bf64ccc7@10.3.0.22 CSeq: 185332673 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=3314 Content-Type: application/dialog-info+xml Content-Length: 513 confirmed sip:30@10.3.0.4 sip:10@10.3.0.4 ------------------------------------------------------------------------ recv 417 bytes from udp/[10.3.0.27]:5060 at 17:34:10.294071: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKy25gZZayN5e6g From: ;tag=j2FaQyd4KlIW To: "Patrick SXXXXXXl" ;tag=26B3115D-24F8F110 CSeq: 185332672 NOTIFY Call-ID: 11c82624-cdfad25f-e9f5882@10.3.0.27 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:10.295560 [DEBUG] switch_rtp.c:3205 Correct ip/port confirmed. recv 407 bytes from udp/[10.3.0.22]:5060 at 17:34:10.306207: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKZBZ90tU1je5rc From: ;tag=BL1yX2TI1X2c To: "A" ;tag=7B5DFEAE-48CDC3F7 CSeq: 185332673 NOTIFY Call-ID: ef7cb8bd-dc381cfe-bf64ccc7@10.3.0.22 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_670-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ send 1326 bytes to udp/[10.3.0.25]:5060 at 17:34:10.321415: ------------------------------------------------------------------------ NOTIFY sip:20@10.3.0.25 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK0mr22Nc5FQUBr Max-Forwards: 70 From: ;tag=JElIsHAUjri7 To: "C" ;tag=432C4A25-2C483674 Call-ID: a941c408-2c54f3a7-82c5a8d6@10.3.0.25 CSeq: 185332674 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=1151 Content-Type: application/dialog-info+xml Content-Length: 513 confirmed sip:10@10.3.0.4 sip:30@10.3.0.4 ------------------------------------------------------------------------ send 1334 bytes to udp/[10.3.0.26]:5060 at 17:34:10.325110: ------------------------------------------------------------------------ NOTIFY sip:30@10.3.0.26 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK1XHU4gX8c0HyK Max-Forwards: 70 From: ;tag=hzYaAHIZscZq To: "B" ;tag=A52D4836-AD38FE89 Call-ID: 3f77033d-f3b24ec8-f0479fab@10.3.0.26 CSeq: 185332675 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=1151 Content-Type: application/dialog-info+xml Content-Length: 513 confirmed sip:10@10.3.0.4 sip:30@10.3.0.4 ------------------------------------------------------------------------ recv 406 bytes from udp/[10.3.0.25]:5060 at 17:34:10.327746: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK0mr22Nc5FQUBr From: ;tag=JElIsHAUjri7 To: "C" ;tag=432C4A25-2C483674 CSeq: 185332674 NOTIFY Call-ID: a941c408-2c54f3a7-82c5a8d6@10.3.0.25 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ recv 414 bytes from udp/[10.3.0.26]:5060 at 17:34:10.330727: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK1XHU4gX8c0HyK From: ;tag=hzYaAHIZscZq To: "B" ;tag=A52D4836-AD38FE89 CSeq: 185332675 NOTIFY Call-ID: 3f77033d-f3b24ec8-f0479fab@10.3.0.26 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:10.332940 [DEBUG] switch_rtp.c:3205 Correct ip/port confirmed. recv 986 bytes from udp/[10.3.0.26]:5060 at 17:34:12.188618: ------------------------------------------------------------------------ INVITE sip:mod_sofia@10.3.0.4:5060 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.26;branch=z9hG4bKb0c085088B8047EB From: "B" ;tag=7463F28A-2FFBD77D To: "A" ;tag=DeFrDpg9mcy3j CSeq: 1 INVITE Call-ID: c0caa6b7-e3e7-122f-41a2-00900b1be504 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 345 v=0 o=- 1167627586 1167627587 IN IP4 10.3.0.26 s=Polycom IP Phone c=IN IP4 0.0.0.0 t=0 0 m=audio 2234 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 m=video 0 RTP/AVP 98 99 100 34 31 a=rtpmap:98 H264/90000 a=rtpmap:99 H263-2000/90000 a=rtpmap:100 H263-1998/90000 a=rtpmap:34 H263/90000 a=rtpmap:31 H261/90000 ------------------------------------------------------------------------ send 358 bytes to udp/[10.3.0.26]:5060 at 17:34:12.189427: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.3.0.26;branch=z9hG4bKb0c085088B8047EB From: "B" ;tag=7463F28A-2FFBD77D To: "A" ;tag=DeFrDpg9mcy3j Call-ID: c0caa6b7-e3e7-122f-41a2-00900b1be504 CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:12.172933 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:12.172933 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:12.192941 [DEBUG] sofia.c:5526 Channel sofia/internal/sip:30@10.3.0.26 entering state [received][100] 2012-03-08 18:34:12.192941 [DEBUG] sofia.c:5537 Remote SDP: v=0 o=- 1167627586 1167627587 IN IP4 10.3.0.26 s=Polycom IP Phone c=IN IP4 0.0.0.0 t=0 0 m=audio 2234 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=sendonly m=video 0 RTP/AVP 98 99 100 34 31 a=rtpmap:98 H264/90000 a=rtpmap:99 H263-2000/90000 a=rtpmap:100 H263-1998/90000 a=rtpmap:34 H263/90000 a=rtpmap:31 H261/90000 2012-03-08 18:34:12.192941 [DEBUG] switch_channel.c:1560 (sofia/internal/sip:30@10.3.0.26) Callstate Change ACTIVE -> HELD 2012-03-08 18:34:12.192941 [DEBUG] switch_core_session.c:1012 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:12.212935 [DEBUG] switch_core_session.c:729 Send signal sofia/internal/10@10.3.0.4 [BREAK] send 1322 bytes to udp/[10.3.0.22]:5060 at 17:34:12.251628: ------------------------------------------------------------------------ NOTIFY sip:10@10.3.0.22 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK26am6Beca97gF Max-Forwards: 70 From: ;tag=BL1yX2TI1X2c To: "A" ;tag=7B5DFEAE-48CDC3F7 Call-ID: ef7cb8bd-dc381cfe-bf64ccc7@10.3.0.22 CSeq: 185332676 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=3312 Content-Type: application/dialog-info+xml Content-Length: 508 early sip:30@10.3.0.4 sip:10@10.3.0.4 ------------------------------------------------------------------------ send 1320 bytes to udp/[10.3.0.25]:5060 at 17:34:12.252624: ------------------------------------------------------------------------ NOTIFY sip:20@10.3.0.25 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK3F4c86yF7Hy3a Max-Forwards: 70 From: ;tag=zVD97bWqz9Ei To: "C" ;tag=E729C66F-499D331E Call-ID: 6e8428e-4012accd-98b6429c@10.3.0.25 CSeq: 185332677 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=3312 Content-Type: application/dialog-info+xml Content-Length: 508 early sip:30@10.3.0.4 sip:10@10.3.0.4 ------------------------------------------------------------------------ send 1332 bytes to udp/[10.3.0.27]:5060 at 17:34:12.257830: ------------------------------------------------------------------------ NOTIFY sip:31@10.3.0.27 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK4rX591FK4tmpp Max-Forwards: 70 From: ;tag=j2FaQyd4KlIW To: "Patrick SXXXXXXl" ;tag=26B3115D-24F8F110 Call-ID: 11c82624-cdfad25f-e9f5882@10.3.0.27 CSeq: 185332678 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=3312 Content-Type: application/dialog-info+xml Content-Length: 508 early sip:30@10.3.0.4 sip:10@10.3.0.4 ------------------------------------------------------------------------ recv 405 bytes from udp/[10.3.0.25]:5060 at 17:34:12.259955: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK3F4c86yF7Hy3a From: ;tag=zVD97bWqz9Ei To: "C" ;tag=E729C66F-499D331E CSeq: 185332677 NOTIFY Call-ID: 6e8428e-4012accd-98b6429c@10.3.0.25 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ recv 407 bytes from udp/[10.3.0.22]:5060 at 17:34:12.260542: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK26am6Beca97gF From: ;tag=BL1yX2TI1X2c To: "A" ;tag=7B5DFEAE-48CDC3F7 CSeq: 185332676 NOTIFY Call-ID: ef7cb8bd-dc381cfe-bf64ccc7@10.3.0.22 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_670-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ recv 417 bytes from udp/[10.3.0.27]:5060 at 17:34:12.264011: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK4rX591FK4tmpp From: ;tag=j2FaQyd4KlIW To: "Patrick SXXXXXXl" ;tag=26B3115D-24F8F110 CSeq: 185332678 NOTIFY Call-ID: 11c82624-cdfad25f-e9f5882@10.3.0.27 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:12.392939 [DEBUG] switch_ivr.c:591 sofia/internal/10@10.3.0.4 Command Execute playback(local_stream://moh) EXECUTE sofia/internal/10@10.3.0.4 playback(local_stream://moh) 2012-03-08 18:34:12.392939 [DEBUG] mod_local_stream.c:421 Opening Stream [moh/16000] 16000hz 2012-03-08 18:34:12.392939 [DEBUG] switch_ivr_play_say.c:1306 Codec Activated L16@16000hz 1 channels 20ms 2012-03-08 18:34:12.432933 [DEBUG] sofia_glue.c:4865 Audio Codec Compare [G722:9:8000:20:64000]/[G722:9:8000:20:64000] 2012-03-08 18:34:12.432933 [DEBUG] sofia_glue.c:2916 Already using G722 2012-03-08 18:34:12.432933 [DEBUG] sofia_glue.c:4979 Set 2833 dtmf send payload to 101 2012-03-08 18:34:12.432933 [DEBUG] sofia_glue.c:3223 Audio params changed for sofia/internal/sip:30@10.3.0.26 from 10.3.0.26:2234 to 0.0.0.0:2234 2012-03-08 18:34:12.432933 [DEBUG] sofia_glue.c:3234 AUDIO RTP [sofia/internal/sip:30@10.3.0.26] 10.3.0.4 port 16450 -> 0.0.0.0 port 2234 codec: 9 ms: 20 2012-03-08 18:34:12.432933 [DEBUG] sofia_glue.c:3275 AUDIO RTP CHANGING DEST TO: [0.0.0.0:2234] 2012-03-08 18:34:12.432933 [DEBUG] sofia.c:6034 Processing updated SDP send 937 bytes to udp/[10.3.0.26]:5060 at 17:34:12.446972: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.26;branch=z9hG4bKb0c085088B8047EB From: "B" ;tag=7463F28A-2FFBD77D To: "A" ;tag=DeFrDpg9mcy3j Call-ID: c0caa6b7-e3e7-122f-41a2-00900b1be504 CSeq: 1 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Content-Type: application/sdp Content-Disposition: session Content-Length: 297 v=0 o=FreeSWITCH 1331211599 1331211601 IN IP4 10.3.0.4 s=FreeSWITCH c=IN IP4 10.3.0.4 t=0 0 m=audio 16450 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=recvonly a=silenceSupp:off - - - - a=ptime:20 m=video 0 RTP/AVP 98 a=rtpmap:98 H264/90000 ------------------------------------------------------------------------ 2012-03-08 18:34:12.432933 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:12.452935 [DEBUG] sofia.c:5526 Channel sofia/internal/sip:30@10.3.0.26 entering state [completed][200] recv 537 bytes from udp/[10.3.0.26]:5060 at 17:34:12.455260: ------------------------------------------------------------------------ ACK sip:mod_sofia@10.3.0.4:5060 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.26;branch=z9hG4bKe85649e7EEFB8C2 From: "B" ;tag=7463F28A-2FFBD77D To: "A" ;tag=DeFrDpg9mcy3j CSeq: 1 ACK Call-ID: c0caa6b7-e3e7-122f-41a2-00900b1be504 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Max-Forwards: 70 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:12.452935 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:12.452935 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:12.452935 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:12.472932 [DEBUG] sofia.c:5526 Channel sofia/internal/sip:30@10.3.0.26 entering state [ready][200] recv 869 bytes from udp/[10.3.0.26]:5060 at 17:34:14.406913: ------------------------------------------------------------------------ INVITE sip:20@10.3.0.4:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.3.0.26;branch=z9hG4bK460db7754D408CC0 From: "B" ;tag=4AB6AEB9-5DA56A24 To: CSeq: 1 INVITE Call-ID: da10f563-8c35d41e-ad0761b1@10.3.0.26 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 241 v=0 o=- 1167627590 1167627590 IN IP4 10.3.0.26 s=Polycom IP Phone c=IN IP4 10.3.0.26 t=0 0 a=sendrecv m=audio 2236 RTP/AVP 9 0 8 127 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:127 telephone-event/8000 ------------------------------------------------------------------------ send 341 bytes to udp/[10.3.0.26]:5060 at 17:34:14.407711: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.3.0.26;branch=z9hG4bK460db7754D408CC0 From: "B" ;tag=4AB6AEB9-5DA56A24 To: Call-ID: da10f563-8c35d41e-ad0761b1@10.3.0.26 CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:14.392941 [DEBUG] sofia.c:7559 IP 10.3.0.26 Rejected by acl "domains". Falling back to Digest auth. 2012-03-08 18:34:14.392941 [WARNING] sofia_reg.c:1422 SIP auth challenge (INVITE) on sofia profile 'internal' for [20@10.3.0.4] from ip 10.3.0.26 send 824 bytes to udp/[10.3.0.26]:5060 at 17:34:14.412500: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.3.0.26;branch=z9hG4bK460db7754D408CC0 From: "B" ;tag=4AB6AEB9-5DA56A24 To: ;tag=eQ8gFH1cjNmpe Call-ID: da10f563-8c35d41e-ad0761b1@10.3.0.26 CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Proxy-Authenticate: Digest realm="10.3.0.4", nonce="ec7c3b52-6944-11e1-a7d4-a55c2ebde3ff", algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ recv 543 bytes from udp/[10.3.0.26]:5060 at 17:34:14.420731: ------------------------------------------------------------------------ ACK sip:20@10.3.0.4:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.3.0.26;branch=z9hG4bK460db7754D408CC0 From: "B" ;tag=4AB6AEB9-5DA56A24 To: ;tag=eQ8gFH1cjNmpe CSeq: 1 ACK Call-ID: da10f563-8c35d41e-ad0761b1@10.3.0.26 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Max-Forwards: 70 Content-Length: 0 ------------------------------------------------------------------------ recv 1124 bytes from udp/[10.3.0.26]:5060 at 17:34:14.423632: ------------------------------------------------------------------------ INVITE sip:20@10.3.0.4:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.3.0.26;branch=z9hG4bK909bdcdc8659BA5F From: "B" ;tag=4AB6AEB9-5DA56A24 To: CSeq: 2 INVITE Call-ID: da10f563-8c35d41e-ad0761b1@10.3.0.26 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Supported: 100rel,replaces Allow-Events: talk,hold,conference Proxy-Authorization: Digest username="30", realm="10.3.0.4", nonce="ec7c3b52-6944-11e1-a7d4-a55c2ebde3ff", qop=auth, cnonce="XJz4HrL/160QNgt", nc=00000001, uri="sip:20@10.3.0.4:5060;user=phone", response="5aa06aa91b7e6941539ee02b96a22789", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 241 v=0 o=- 1167627590 1167627590 IN IP4 10.3.0.26 s=Polycom IP Phone c=IN IP4 10.3.0.26 t=0 0 a=sendrecv m=audio 2236 RTP/AVP 9 0 8 127 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:127 telephone-event/8000 ------------------------------------------------------------------------ send 341 bytes to udp/[10.3.0.26]:5060 at 17:34:14.424685: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.3.0.26;branch=z9hG4bK909bdcdc8659BA5F From: "B" ;tag=4AB6AEB9-5DA56A24 To: Call-ID: da10f563-8c35d41e-ad0761b1@10.3.0.26 CSeq: 2 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:14.412921 [DEBUG] sofia.c:7559 IP 10.3.0.26 Rejected by acl "domains". Falling back to Digest auth. 2012-03-08 18:34:14.432937 [NOTICE] switch_channel.c:926 New Channel sofia/internal/30@10.3.0.4 [ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff] 2012-03-08 18:34:14.432937 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/30@10.3.0.4) Running State Change CS_NEW 2012-03-08 18:34:14.432937 [DEBUG] switch_core_state_machine.c:380 (sofia/internal/30@10.3.0.4) State NEW 2012-03-08 18:34:14.432937 [DEBUG] sofia.c:5526 Channel sofia/internal/30@10.3.0.4 entering state [received][100] 2012-03-08 18:34:14.432937 [DEBUG] sofia.c:5537 Remote SDP: v=0 o=- 1167627590 1167627590 IN IP4 10.3.0.26 s=Polycom IP Phone c=IN IP4 10.3.0.26 t=0 0 a=sendrecv m=audio 2236 RTP/AVP 9 0 8 127 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:127 telephone-event/8000 2012-03-08 18:34:14.432937 [DEBUG] sofia_glue.c:4865 Audio Codec Compare [G722:9:8000:20:64000]/[G722:9:8000:20:64000] 2012-03-08 18:34:14.432937 [DEBUG] sofia_glue.c:2982 Set Codec sofia/internal/30@10.3.0.4 G722/8000 20 ms 160 samples 64000 bits 2012-03-08 18:34:14.432937 [DEBUG] switch_core_codec.c:111 sofia/internal/30@10.3.0.4 Original read codec set to G722:9 2012-03-08 18:34:14.432937 [DEBUG] sofia_glue.c:4986 Set 2833 dtmf send/recv payload to 127 2012-03-08 18:34:14.432937 [DEBUG] sofia.c:5749 (sofia/internal/30@10.3.0.4) State Change CS_NEW -> CS_INIT 2012-03-08 18:34:14.432937 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/30@10.3.0.4 [BREAK] 2012-03-08 18:34:14.432937 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/30@10.3.0.4) Running State Change CS_INIT 2012-03-08 18:34:14.432937 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/30@10.3.0.4) State INIT 2012-03-08 18:34:14.432937 [DEBUG] mod_sofia.c:85 sofia/internal/30@10.3.0.4 SOFIA INIT 2012-03-08 18:34:14.432937 [DEBUG] mod_sofia.c:125 (sofia/internal/30@10.3.0.4) State Change CS_INIT -> CS_ROUTING 2012-03-08 18:34:14.432937 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/30@10.3.0.4 [BREAK] 2012-03-08 18:34:14.432937 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/30@10.3.0.4) State INIT going to sleep 2012-03-08 18:34:14.432937 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/30@10.3.0.4) Running State Change CS_ROUTING 2012-03-08 18:34:14.432937 [DEBUG] switch_channel.c:1886 (sofia/internal/30@10.3.0.4) Callstate Change DOWN -> RINGING 2012-03-08 18:34:14.432937 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/30@10.3.0.4) State ROUTING 2012-03-08 18:34:14.432937 [DEBUG] mod_sofia.c:148 sofia/internal/30@10.3.0.4 SOFIA ROUTING 2012-03-08 18:34:14.432937 [DEBUG] switch_core_state_machine.c:104 sofia/internal/30@10.3.0.4 Standard ROUTING 2012-03-08 18:34:14.432937 [INFO] mod_dialplan_xml.c:485 Processing B <30>->20 in context default Dialplan: sofia/internal/30@10.3.0.4 parsing [default->nxo_enable_chefsec] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [nxo_enable_chefsec] destination_number(20) =~ /^\*95(\d{0,7})$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->group-intercept] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [group-intercept] destination_number(20) =~ /^\*82$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->intercept-ext] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [intercept-ext] destination_number(20) =~ /^\*81(\d+)$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->nxo_single_intercom_with_two_way_audio] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [nxo_single_intercom_with_two_way_audio] destination_number(20) =~ /^\*01(\d{2,7})$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->nxo_group_intercom] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [nxo_group_intercom] destination_number(20) =~ /^\*02(\d{0,7})$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->Outbound to PSTN 11 Digits] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [Outbound to PSTN 11 Digits] destination_number(20) =~ /^(1[2-9][0-9]{2}[2-9]{7})$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->del-group] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [del-group] destination_number(20) =~ /^\*\*50(\d{2})$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->add-group] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [add-group] destination_number(20) =~ /^\*\*51(\d{2})$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->call-group-simo] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [call-group-simo] destination_number(20) =~ /^\*52(\d{2,4})$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->call-group-order] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [call-group-order] destination_number(20) =~ /^\*53(\d{2,4})$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->nb_conferences] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [nb_conferences] destination_number(20) =~ /^\*(30\d{2})$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->wb_conferences] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [wb_conferences] destination_number(20) =~ /^\*(31\d{2})$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->uwb_conferences] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [uwb_conferences] destination_number(20) =~ /^\*(32\d{2})$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->cdquality_conferences] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [cdquality_conferences] destination_number(20) =~ /^\*(33\d{2})$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->global_directory] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [global_directory] destination_number(20) =~ /^\*77(\d{1,3})$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->redirect_now] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [redirect_now] destination_number(20) =~ /^\*21(\d{0,20})$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->redirect_timeout] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [redirect_timeout] destination_number(20) =~ /^\*22(\d{0,20})$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->redirect_busy] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [redirect_busy] destination_number(20) =~ /^\*23(\d{0,20})$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->call_privacy] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [call_privacy] destination_number(20) =~ /^\*67(\d+)$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->call_privacy] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [call_privacy] destination_number(20) =~ /^\*60$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->send_to_voicemail] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [send_to_voicemail] destination_number(20) =~ /^\*99(\d{2,7})$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->vmain] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [vmain] destination_number(20) =~ /^vmain$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->vmain1] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [vmain1] destination_number(20) =~ /^vmain1$|^\*97$|^97$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->vmain2] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [vmain2] destination_number(20) =~ /^vmain2$|^\*98$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->redirect_now] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (FAIL) [redirect_now] destination_number(20) =~ /^\*35$/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 parsing [default->Local_Extension_test] continue=false Dialplan: sofia/internal/30@10.3.0.4 Regex (PASS) [Local_Extension_test] destination_number(20) =~ /(^\d{2,7}$)/ break=on-false Dialplan: sofia/internal/30@10.3.0.4 Action set(dialed_extension=20) Dialplan: sofia/internal/30@10.3.0.4 Action export(dialed_extension=20) Dialplan: sofia/internal/30@10.3.0.4 Action python(nxo_test) 2012-03-08 18:34:14.432937 [DEBUG] switch_core_state_machine.c:154 (sofia/internal/30@10.3.0.4) State Change CS_ROUTING -> CS_EXECUTE 2012-03-08 18:34:14.432937 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/30@10.3.0.4 [BREAK] 2012-03-08 18:34:14.432937 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/30@10.3.0.4) State ROUTING going to sleep 2012-03-08 18:34:14.432937 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/30@10.3.0.4) Running State Change CS_EXECUTE 2012-03-08 18:34:14.432937 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/30@10.3.0.4) State EXECUTE 2012-03-08 18:34:14.432937 [DEBUG] mod_sofia.c:241 sofia/internal/30@10.3.0.4 SOFIA EXECUTE 2012-03-08 18:34:14.432937 [DEBUG] switch_core_state_machine.c:192 sofia/internal/30@10.3.0.4 Standard EXECUTE EXECUTE sofia/internal/30@10.3.0.4 set(dialed_extension=20) 2012-03-08 18:34:14.432937 [DEBUG] mod_dptools.c:1281 sofia/internal/30@10.3.0.4 SET [dialed_extension]=[20] EXECUTE sofia/internal/30@10.3.0.4 export(dialed_extension=20) 2012-03-08 18:34:14.432937 [DEBUG] switch_channel.c:1093 EXPORT (export_vars) [dialed_extension]=[20] EXECUTE sofia/internal/30@10.3.0.4 python(nxo_test) 2012-03-08 18:34:14.452987 [NOTICE] mod_python.c:212 Invoking py module: nxo_test 2012-03-08 18:34:14.452987 [DEBUG] mod_python.c:281 Call python script 2012-03-08 18:34:14.452987 [INFO] switch_cpp.cpp:1227 TEST: Destination-extension 20 send 1327 bytes to udp/[10.3.0.22]:5060 at 17:34:14.522894: ------------------------------------------------------------------------ NOTIFY sip:10@10.3.0.22 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK51pyBX0p13a9H Max-Forwards: 70 From: ;tag=BL1yX2TI1X2c To: "A" ;tag=7B5DFEAE-48CDC3F7 Call-ID: ef7cb8bd-dc381cfe-bf64ccc7@10.3.0.22 CSeq: 185332679 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=3310 Content-Type: application/dialog-info+xml Content-Length: 513 confirmed sip:30@10.3.0.4 sip:20@10.3.0.4 ------------------------------------------------------------------------ send 1325 bytes to udp/[10.3.0.25]:5060 at 17:34:14.523907: ------------------------------------------------------------------------ NOTIFY sip:20@10.3.0.25 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK6agQDrHtyc1UD Max-Forwards: 70 From: ;tag=zVD97bWqz9Ei To: "C" ;tag=E729C66F-499D331E Call-ID: 6e8428e-4012accd-98b6429c@10.3.0.25 CSeq: 185332680 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=3310 Content-Type: application/dialog-info+xml Content-Length: 513 confirmed sip:30@10.3.0.4 sip:20@10.3.0.4 ------------------------------------------------------------------------ send 1337 bytes to udp/[10.3.0.27]:5060 at 17:34:14.524901: ------------------------------------------------------------------------ NOTIFY sip:31@10.3.0.27 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK7K9FFK2XUNQeS Max-Forwards: 70 From: ;tag=j2FaQyd4KlIW To: "Patrick SXXXXXXl" ;tag=26B3115D-24F8F110 Call-ID: 11c82624-cdfad25f-e9f5882@10.3.0.27 CSeq: 185332681 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=3310 Content-Type: application/dialog-info+xml Content-Length: 513 confirmed sip:30@10.3.0.4 sip:20@10.3.0.4 ------------------------------------------------------------------------ recv 407 bytes from udp/[10.3.0.22]:5060 at 17:34:14.530514: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK51pyBX0p13a9H From: ;tag=BL1yX2TI1X2c To: "A" ;tag=7B5DFEAE-48CDC3F7 CSeq: 185332679 NOTIFY Call-ID: ef7cb8bd-dc381cfe-bf64ccc7@10.3.0.22 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_670-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ recv 417 bytes from udp/[10.3.0.27]:5060 at 17:34:14.530992: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK7K9FFK2XUNQeS From: ;tag=j2FaQyd4KlIW To: "Patrick SXXXXXXl" ;tag=26B3115D-24F8F110 CSeq: 185332681 NOTIFY Call-ID: 11c82624-cdfad25f-e9f5882@10.3.0.27 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ recv 405 bytes from udp/[10.3.0.25]:5060 at 17:34:14.531364: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK6agQDrHtyc1UD From: ;tag=zVD97bWqz9Ei To: "C" ;tag=E729C66F-499D331E CSeq: 185332680 NOTIFY Call-ID: 6e8428e-4012accd-98b6429c@10.3.0.25 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ EXECUTE sofia/internal/30@10.3.0.4 set(continue_on_fail=true) 2012-03-08 18:34:14.952961 [DEBUG] mod_dptools.c:1281 sofia/internal/30@10.3.0.4 SET [continue_on_fail]=[true] EXECUTE sofia/internal/30@10.3.0.4 set(hangup_after_bridge=true) 2012-03-08 18:34:14.952961 [DEBUG] mod_dptools.c:1281 sofia/internal/30@10.3.0.4 SET [hangup_after_bridge]=[true] 2012-03-08 18:34:14.952961 [WARNING] switch_cpp.cpp:1227 TEST 1 for UUID ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff, src 30 dest 20 EXECUTE sofia/internal/30@10.3.0.4 sleep(1000) 2012-03-08 18:34:15.952932 [WARNING] switch_cpp.cpp:1227 TEST 2 for UUID ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff, src 30 dest 20 EXECUTE sofia/internal/30@10.3.0.4 sleep(1000) 2012-03-08 18:34:16.952933 [WARNING] switch_cpp.cpp:1227 TEST 3 for UUID ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff, src 30 dest 20 EXECUTE sofia/internal/30@10.3.0.4 sleep(1000) EXECUTE sofia/internal/30@10.3.0.4 info() 2012-03-08 18:34:17.952932 [INFO] mod_dptools.c:1439 CHANNEL_DATA: Channel-State: [CS_EXECUTE] Channel-Call-State: [RINGING] Channel-State-Number: [4] Channel-Name: [sofia/internal/30@10.3.0.4] Unique-ID: [ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff] Call-Direction: [inbound] Presence-Call-Direction: [inbound] Channel-HIT-Dialplan: [true] Channel-Presence-ID: [30@10.3.0.4] Channel-Call-UUID: [ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff] Answer-State: [ringing] Channel-Read-Codec-Name: [G722] Channel-Read-Codec-Rate: [16000] Channel-Read-Codec-Bit-Rate: [64000] Channel-Write-Codec-Name: [G722] Channel-Write-Codec-Rate: [16000] Channel-Write-Codec-Bit-Rate: [64000] Caller-Direction: [inbound] Caller-Username: [30] Caller-Dialplan: [XML] Caller-Caller-ID-Name: [B] Caller-Caller-ID-Number: [30] Caller-Network-Addr: [10.3.0.26] Caller-ANI: [30] Caller-Destination-Number: [20] Caller-Unique-ID: [ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff] Caller-Source: [mod_sofia] Caller-Context: [default] Caller-Channel-Name: [sofia/internal/30@10.3.0.4] Caller-Profile-Index: [1] Caller-Profile-Created-Time: [1331228054432937] Caller-Channel-Created-Time: [1331228054432937] Caller-Channel-Answered-Time: [0] Caller-Channel-Progress-Time: [0] Caller-Channel-Progress-Media-Time: [0] Caller-Channel-Hangup-Time: [0] Caller-Channel-Transfer-Time: [0] Caller-Screen-Bit: [true] Caller-Privacy-Hide-Name: [false] Caller-Privacy-Hide-Number: [false] variable_direction: [inbound] variable_uuid: [ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff] variable_session_id: [11] variable_sip_local_network_addr: [10.3.0.4] variable_sip_network_ip: [10.3.0.26] variable_sip_network_port: [5060] variable_sip_received_ip: [10.3.0.26] variable_sip_received_port: [5060] variable_sip_via_protocol: [udp] variable_sip_authorized: [true] variable_sip_number_alias: [30] variable_sip_auth_username: [30] variable_sip_auth_realm: [10.3.0.4] variable_number_alias: [30] variable_user_name: [30] variable_domain_name: [10.3.0.4] variable_record_stereo: [true] variable_default_gateway: [fonira] variable_default_areacode: [01] variable_transfer_fallback_extension: [operator] variable_toll_allow: [local,domestic,international,vas] variable_accountcode: [30] variable_user_context: [default] variable_effective_caller_id_name: [B] variable_effective_caller_id_number: [30] variable_outbound_caller_id_name: [B] variable_outbound_caller_id_number: [1997156030] variable_callgroup: [intercept] variable_sip_from_user: [30] variable_sip_from_uri: [30@10.3.0.4] variable_sip_from_host: [10.3.0.4] variable_sip_from_user_stripped: [30] variable_sip_from_tag: [4AB6AEB9-5DA56A24] variable_sofia_profile_name: [internal] variable_sip_full_via: [SIP/2.0/UDP 10.3.0.26;branch=z9hG4bK909bdcdc8659BA5F] variable_sip_from_display: [B] variable_sip_full_from: ["B" ;tag=4AB6AEB9-5DA56A24] variable_sip_full_to: [] variable_sip_req_params: [user=phone] variable_sip_req_user: [20] variable_sip_req_port: [5060] variable_sip_req_uri: [20@10.3.0.4:5060] variable_sip_req_host: [10.3.0.4] variable_sip_to_params: [user=phone] variable_sip_to_user: [20] variable_sip_to_uri: [20@10.3.0.4] variable_sip_to_host: [10.3.0.4] variable_sip_contact_user: [30] variable_sip_contact_uri: [30@10.3.0.26] variable_sip_contact_host: [10.3.0.26] variable_channel_name: [sofia/internal/30@10.3.0.4] variable_sip_call_id: [da10f563-8c35d41e-ad0761b1@10.3.0.26] variable_sip_user_agent: [PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933] variable_sip_via_host: [10.3.0.26] variable_max_forwards: [70] variable_presence_id: [30@10.3.0.4] variable_switch_r_sdp: [v=0 o=- 1167627590 1167627590 IN IP4 10.3.0.26 s=Polycom IP Phone c=IN IP4 10.3.0.26 t=0 0 a=sendrecv m=audio 2236 RTP/AVP 9 0 8 127 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:127 telephone-event/8000 ] variable_remote_media_ip: [10.3.0.26] variable_remote_media_port: [2236] variable_sip_audio_recv_pt: [9] variable_sip_use_codec_name: [G722] variable_sip_use_codec_rate: [8000] variable_sip_use_codec_ptime: [20] variable_read_codec: [G722] variable_read_rate: [16000] variable_write_codec: [G722] variable_write_rate: [16000] variable_endpoint_disposition: [RECEIVED] variable_DP_MATCH: [ARRAY::20|:20] variable_call_uuid: [ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff] variable_dialed_extension: [20] variable_export_vars: [dialed_extension] variable_continue_on_fail: [true] variable_hangup_after_bridge: [true] variable_current_application: [info] EXECUTE sofia/internal/30@10.3.0.4 bridge([leg_timeout=15][origination_caller_id_number=30]user/20@10.3.0.4) 2012-03-08 18:34:17.972915 [DEBUG] switch_channel.c:1047 sofia/internal/30@10.3.0.4 EXPORTING[export_vars] [dialed_extension]=[20] to event 2012-03-08 18:34:17.972915 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables 2012-03-08 18:34:17.972915 [DEBUG] switch_ivr_originate.c:2299 Parsing session specific variables 2012-03-08 18:34:17.972915 [DEBUG] switch_event.c:1522 Parsing variable [leg_timeout]=[15] 2012-03-08 18:34:17.972915 [DEBUG] switch_event.c:1522 Parsing variable [origination_caller_id_number]=[30] 2012-03-08 18:34:17.972915 [DEBUG] switch_channel.c:1047 sofia/internal/30@10.3.0.4 EXPORTING[export_vars] [dialed_extension]=[20] to event 2012-03-08 18:34:17.972915 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables 2012-03-08 18:34:17.972915 [DEBUG] switch_event.c:1522 Parsing variable [presence_id]=[20@10.3.0.4] 2012-03-08 18:34:17.972915 [NOTICE] switch_channel.c:926 New Channel sofia/internal/sip:20@10.3.0.25 [ee9ed232-6944-11e1-a7dd-a55c2ebde3ff] 2012-03-08 18:34:17.972915 [DEBUG] mod_sofia.c:4673 (sofia/internal/sip:20@10.3.0.25) State Change CS_NEW -> CS_INIT 2012-03-08 18:34:17.972915 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:20@10.3.0.25 [BREAK] 2012-03-08 18:34:17.992947 [DEBUG] switch_ivr_originate.c:2561 sofia/internal/sip:20@10.3.0.25 Setting leg timeout to 15 2012-03-08 18:34:17.992947 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:20@10.3.0.25) Running State Change CS_INIT 2012-03-08 18:34:17.992947 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:20@10.3.0.25) State INIT 2012-03-08 18:34:17.992947 [DEBUG] mod_sofia.c:85 sofia/internal/sip:20@10.3.0.25 SOFIA INIT 2012-03-08 18:34:17.992947 [DEBUG] mod_sofia.c:125 (sofia/internal/sip:20@10.3.0.25) State Change CS_INIT -> CS_ROUTING 2012-03-08 18:34:17.992947 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:20@10.3.0.25 [BREAK] 2012-03-08 18:34:17.992947 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:20@10.3.0.25) State INIT going to sleep 2012-03-08 18:34:17.992947 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:20@10.3.0.25) Running State Change CS_ROUTING 2012-03-08 18:34:17.992947 [DEBUG] switch_channel.c:1886 (sofia/internal/sip:20@10.3.0.25) Callstate Change DOWN -> RINGING send 1267 bytes to udp/[10.3.0.25]:5060 at 17:34:17.995749: ------------------------------------------------------------------------ INVITE sip:20@10.3.0.25 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK8v28geK1ryD1m Max-Forwards: 69 From: "B" ;tag=g9t2j72Kc70UN To: Call-ID: c5fdcf90-e3e7-122f-41a2-00900b1be504 CSeq: 25277964 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 369 X-FS-Support: update_display,send_info Remote-Party-ID: "B" ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1331211673 1331211674 IN IP4 10.3.0.4 s=FreeSWITCH c=IN IP4 10.3.0.4 t=0 0 m=audio 16384 RTP/AVP 9 0 8 3 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 16422 RTP/AVP 98 99 100 34 31 a=rtpmap:98 H264/90000 a=rtpmap:99 H263-2000/90000 a=rtpmap:100 H263-1998/90000 a=rtpmap:34 H263/90000 a=rtpmap:31 H261/90000 ------------------------------------------------------------------------ 2012-03-08 18:34:17.992947 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:20@10.3.0.25) State ROUTING 2012-03-08 18:34:17.992947 [DEBUG] mod_sofia.c:148 sofia/internal/sip:20@10.3.0.25 SOFIA ROUTING 2012-03-08 18:34:17.992947 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:20@10.3.0.25) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2012-03-08 18:34:17.992947 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:20@10.3.0.25 [BREAK] 2012-03-08 18:34:17.992947 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:20@10.3.0.25) State ROUTING going to sleep 2012-03-08 18:34:17.992947 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:20@10.3.0.25) Running State Change CS_CONSUME_MEDIA 2012-03-08 18:34:17.992947 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:20@10.3.0.25) State CONSUME_MEDIA 2012-03-08 18:34:17.992947 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:20@10.3.0.25) State CONSUME_MEDIA going to sleep 2012-03-08 18:34:17.992947 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:20@10.3.0.25 [BREAK] 2012-03-08 18:34:17.992947 [DEBUG] sofia.c:5526 Channel sofia/internal/sip:20@10.3.0.25 entering state [calling][0] recv 412 bytes from udp/[10.3.0.25]:5060 at 17:34:18.004636: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK8v28geK1ryD1m From: "B" ;tag=g9t2j72Kc70UN To: "C" ;tag=D3DA58FE-5FE1943D CSeq: 25277964 INVITE Call-ID: c5fdcf90-e3e7-122f-41a2-00900b1be504 Contact: User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ send 1323 bytes to udp/[10.3.0.22]:5060 at 17:34:18.044978: ------------------------------------------------------------------------ NOTIFY sip:10@10.3.0.22 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK95U1j934N73Kg Max-Forwards: 70 From: ;tag=nYGREnwV9Yw1 To: "A" ;tag=3AFAE503-964EC474 Call-ID: 5e0bdbb0-b7399c09-c8206caa@10.3.0.22 CSeq: 185332682 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=3307 Content-Type: application/dialog-info+xml Content-Length: 509 early sip:20@10.3.0.4 sip:30@10.3.0.4 ------------------------------------------------------------------------ send 1330 bytes to udp/[10.3.0.26]:5060 at 17:34:18.048242: ------------------------------------------------------------------------ NOTIFY sip:30@10.3.0.26 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKaFNtm4m8jgt6B Max-Forwards: 70 From: ;tag=eMGDLbL5kcdj To: "B" ;tag=5D666AB7-2B76D012 Call-ID: 467e0be4-bb0339a7-ce4d6682@10.3.0.26 CSeq: 185332683 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=3306 Content-Type: application/dialog-info+xml Content-Length: 509 early sip:20@10.3.0.4 sip:30@10.3.0.4 ------------------------------------------------------------------------ recv 407 bytes from udp/[10.3.0.22]:5060 at 17:34:18.052291: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK95U1j934N73Kg From: ;tag=nYGREnwV9Yw1 To: "A" ;tag=3AFAE503-964EC474 CSeq: 185332682 NOTIFY Call-ID: 5e0bdbb0-b7399c09-c8206caa@10.3.0.22 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_670-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ recv 414 bytes from udp/[10.3.0.26]:5060 at 17:34:18.053999: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKaFNtm4m8jgt6B From: ;tag=eMGDLbL5kcdj To: "B" ;tag=5D666AB7-2B76D012 CSeq: 185332683 NOTIFY Call-ID: 467e0be4-bb0339a7-ce4d6682@10.3.0.26 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ recv 449 bytes from udp/[10.3.0.25]:5060 at 17:34:18.060861: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK8v28geK1ryD1m From: "B" ;tag=g9t2j72Kc70UN To: "C" ;tag=D3DA58FE-5FE1943D CSeq: 25277964 INVITE Call-ID: c5fdcf90-e3e7-122f-41a2-00900b1be504 Contact: User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Allow-Events: talk,hold,conference Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:18.052945 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:20@10.3.0.25 [BREAK] 2012-03-08 18:34:18.052945 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:20@10.3.0.25 [BREAK] 2012-03-08 18:34:18.052945 [DEBUG] sofia.c:5526 Channel sofia/internal/sip:20@10.3.0.25 entering state [proceeding][180] 2012-03-08 18:34:18.052945 [NOTICE] sofia.c:5618 Ring-Ready sofia/internal/sip:20@10.3.0.25! 2012-03-08 18:34:18.052945 [NOTICE] mod_sofia.c:2514 Ring-Ready sofia/internal/30@10.3.0.4! send 806 bytes to udp/[10.3.0.26]:5060 at 17:34:18.071638: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.3.0.26;branch=z9hG4bK909bdcdc8659BA5F From: "B" ;tag=4AB6AEB9-5DA56A24 To: ;tag=F019gcjgFya9S Call-ID: da10f563-8c35d41e-ad0761b1@10.3.0.26 CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0 Remote-Party-ID: "Outbound Call" <20>;party=calling;privacy=off;screen=no ------------------------------------------------------------------------ 2012-03-08 18:34:18.052945 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/30@10.3.0.4 [BREAK] 2012-03-08 18:34:18.072922 [DEBUG] sofia.c:5526 Channel sofia/internal/30@10.3.0.4 entering state [early][180] 2012-03-08 18:34:18.072922 [DEBUG] switch_core_session.c:729 Send signal sofia/internal/30@10.3.0.4 [BREAK] 2012-03-08 18:34:18.072922 [NOTICE] switch_ivr_originate.c:483 Ring Ready sofia/internal/30@10.3.0.4! recv 625 bytes from udp/[10.3.0.26]:5060 at 17:34:20.691350: ------------------------------------------------------------------------ REFER sip:mod_sofia@10.3.0.4:5060 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.26;branch=z9hG4bKb6a74a78C1F008DB From: "B" ;tag=7463F28A-2FFBD77D To: "A" ;tag=DeFrDpg9mcy3j CSeq: 2 REFER Call-ID: c0caa6b7-e3e7-122f-41a2-00900b1be504 Contact: User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Refer-To: Referred-By: Max-Forwards: 70 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:20.672931 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:20.692943 [DEBUG] sofia.c:6514 Process REFER to [20@10.3.0.4] 2012-03-08 18:34:20.692943 [DEBUG] sofia.c:6532 Replaces: [da10f563-8c35d41e-ad0761b1@10.3.0.26] send 711 bytes to udp/[10.3.0.26]:5060 at 17:34:20.693751: ------------------------------------------------------------------------ SIP/2.0 202 Accepted Via: SIP/2.0/UDP 10.3.0.26;branch=z9hG4bKb6a74a78C1F008DB From: "B" ;tag=7463F28A-2FFBD77D To: "A" ;tag=DeFrDpg9mcy3j Call-ID: c0caa6b7-e3e7-122f-41a2-00900b1be504 CSeq: 2 REFER Contact: Expires: 60 User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:20.692943 [NOTICE] sofia.c:6615 Attended Transfer on originating session ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff 2012-03-08 18:34:20.692943 [DEBUG] switch_ivr.c:1711 (sofia/internal/10@10.3.0.4) State Change CS_EXECUTE -> CS_ROUTING 2012-03-08 18:34:20.692943 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:20.692943 [DEBUG] switch_core_session.c:729 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:20.692943 [NOTICE] switch_ivr.c:1717 Transfer sofia/internal/10@10.3.0.4 to inline[endless_playback:local_stream://moh,park@default] send 851 bytes to udp/[10.3.0.26]:5060 at 17:34:20.695326: ------------------------------------------------------------------------ NOTIFY sip:30@10.3.0.26 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKBreKpZ5BgSgSQ Max-Forwards: 70 From: "A " ;tag=DeFrDpg9mcy3j To: ;tag=7463F28A-2FFBD77D Call-ID: c0caa6b7-e3e7-122f-41a2-00900b1be504 CSeq: 25277961 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: refer;id=2 Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Content-Length: 16 SIP/2.0 200 OK ------------------------------------------------------------------------ send 645 bytes to udp/[10.3.0.26]:5060 at 17:34:20.696067: ------------------------------------------------------------------------ BYE sip:30@10.3.0.26 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKc17BrtpFD26BK Max-Forwards: 70 From: ;tag=F019gcjgFya9S To: "B" ;tag=4AB6AEB9-5DA56A24 Call-ID: da10f563-8c35d41e-ad0761b1@10.3.0.26 CSeq: 25277966 BYE Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Reason: Q.850;cause=16;text="normal_clearing" Content-Length: 0 ------------------------------------------------------------------------ send 661 bytes to udp/[10.3.0.26]:5060 at 17:34:20.696525: ------------------------------------------------------------------------ SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 10.3.0.26;branch=z9hG4bK909bdcdc8659BA5F From: "B" ;tag=4AB6AEB9-5DA56A24 To: ;tag=F019gcjgFya9S Call-ID: da10f563-8c35d41e-ad0761b1@10.3.0.26 CSeq: 2 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0 ------------------------------------------------------------------------ recv 428 bytes from udp/[10.3.0.26]:5060 at 17:34:20.703100: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKBreKpZ5BgSgSQ From: "A" ;tag=DeFrDpg9mcy3j To: "B" ;tag=7463F28A-2FFBD77D CSeq: 25277961 NOTIFY Call-ID: c0caa6b7-e3e7-122f-41a2-00900b1be504 Contact: Event: refer;id=2 User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:20.692943 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] recv 440 bytes from udp/[10.3.0.26]:5060 at 17:34:20.705492: ------------------------------------------------------------------------ BYE sip:mod_sofia@10.3.0.4:5060 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.26;branch=z9hG4bK415b2b56FCCA5AA9 From: "B" ;tag=7463F28A-2FFBD77D To: "A" ;tag=DeFrDpg9mcy3j CSeq: 3 BYE Call-ID: c0caa6b7-e3e7-122f-41a2-00900b1be504 Contact: User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Max-Forwards: 70 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:20.692943 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] recv 744 bytes from udp/[10.3.0.26]:5060 at 17:34:20.709331: ------------------------------------------------------------------------ CANCEL sip:20@10.3.0.4:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.3.0.26;branch=z9hG4bK909bdcdc8659BA5F From: "B" ;tag=4AB6AEB9-5DA56A24 To: CSeq: 2 CANCEL Call-ID: da10f563-8c35d41e-ad0761b1@10.3.0.26 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Proxy-Authorization: Digest username="30", realm="10.3.0.4", nonce="ec7c3b52-6944-11e1-a7d4-a55c2ebde3ff", qop=auth, cnonce="XJz4HrL/160QNgt", nc=00000002, uri="sip:20@10.3.0.4:5060;user=phone", response="05c11ccdcec345f1fca83aa780770b28", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 ------------------------------------------------------------------------ send 274 bytes to udp/[10.3.0.26]:5060 at 17:34:20.709881: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.26;branch=z9hG4bK909bdcdc8659BA5F From: "B" ;tag=4AB6AEB9-5DA56A24 To: ;tag=F019gcjgFya9S Call-ID: da10f563-8c35d41e-ad0761b1@10.3.0.26 CSeq: 2 CANCEL Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:20.712938 [DEBUG] switch_ivr_play_say.c:1678 done playing file local_stream://moh 2012-03-08 18:34:20.712938 [DEBUG] switch_ivr_bridge.c:586 BRIDGE THREAD DONE [sofia/internal/sip:30@10.3.0.26] 2012-03-08 18:34:20.712938 [DEBUG] switch_ivr_bridge.c:611 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:20.712938 [DEBUG] switch_channel.c:2848 (sofia/internal/sip:30@10.3.0.26) Callstate Change HELD -> HANGUP 2012-03-08 18:34:20.712938 [NOTICE] switch_ivr_bridge.c:669 Hangup sofia/internal/sip:30@10.3.0.26 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2012-03-08 18:34:20.712938 [DEBUG] switch_channel.c:2871 Send signal sofia/internal/sip:30@10.3.0.26 [KILL] 2012-03-08 18:34:20.712938 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:20.712938 [DEBUG] switch_core_state_machine.c:420 (sofia/internal/sip:30@10.3.0.26) State EXCHANGE_MEDIA going to sleep 2012-03-08 18:34:20.712938 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:30@10.3.0.26) Running State Change CS_HANGUP 2012-03-08 18:34:20.712938 [DEBUG] switch_core_session.c:729 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:20.712938 [DEBUG] switch_ivr_bridge.c:329 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:20.712938 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/sip:30@10.3.0.26) State HANGUP 2012-03-08 18:34:20.712938 [DEBUG] mod_sofia.c:469 Channel sofia/internal/sip:30@10.3.0.26 hanging up, cause: NORMAL_CLEARING 2012-03-08 18:34:20.712938 [DEBUG] mod_sofia.c:513 Sending BYE to sofia/internal/sip:30@10.3.0.26 send 622 bytes to udp/[10.3.0.26]:5060 at 17:34:20.724016: ------------------------------------------------------------------------ BYE sip:30@10.3.0.26 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKDa14SN7jaBXye Max-Forwards: 70 From: "A " ;tag=DeFrDpg9mcy3j To: ;tag=7463F28A-2FFBD77D Call-ID: c0caa6b7-e3e7-122f-41a2-00900b1be504 CSeq: 25277962 BYE Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:20.712938 [DEBUG] switch_core_state_machine.c:47 sofia/internal/sip:30@10.3.0.26 Standard HANGUP, cause: NORMAL_CLEARING 2012-03-08 18:34:20.712938 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/sip:30@10.3.0.26) State HANGUP going to sleep 2012-03-08 18:34:20.712938 [DEBUG] switch_core_state_machine.c:393 (sofia/internal/sip:30@10.3.0.26) State Change CS_HANGUP -> CS_REPORTING 2012-03-08 18:34:20.712938 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:20.712938 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:30@10.3.0.26) Running State Change CS_REPORTING 2012-03-08 18:34:20.712938 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/sip:30@10.3.0.26) State REPORTING 2012-03-08 18:34:20.712938 [DEBUG] switch_core_state_machine.c:79 sofia/internal/sip:30@10.3.0.26 Standard REPORTING, cause: NORMAL_CLEARING 2012-03-08 18:34:20.712938 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/sip:30@10.3.0.26) State REPORTING going to sleep 2012-03-08 18:34:20.712938 [DEBUG] switch_core_state_machine.c:387 (sofia/internal/sip:30@10.3.0.26) State Change CS_REPORTING -> CS_DESTROY 2012-03-08 18:34:20.712938 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:20.712938 [DEBUG] switch_core_session.c:1380 Session 10 (sofia/internal/sip:30@10.3.0.26) Locked, Waiting on external entities recv 411 bytes from udp/[10.3.0.26]:5060 at 17:34:20.729848: ------------------------------------------------------------------------ SIP/2.0 481 Call Leg/Transaction Does Not Exist Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKc17BrtpFD26BK From: ;tag=F019gcjgFya9S To: "B" ;tag=4AB6AEB9-5DA56A24 CSeq: 25277966 BYE Call-ID: da10f563-8c35d41e-ad0761b1@10.3.0.26 User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:20.712938 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/30@10.3.0.4 [BREAK] 2012-03-08 18:34:20.712938 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/30@10.3.0.4 [BREAK] 2012-03-08 18:34:20.712938 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/30@10.3.0.4 [BREAK] 2012-03-08 18:34:20.712938 [DEBUG] sofia.c:5526 Channel sofia/internal/30@10.3.0.4 entering state [terminated][481] 2012-03-08 18:34:20.712938 [DEBUG] switch_channel.c:2848 (sofia/internal/30@10.3.0.4) Callstate Change RINGING -> HANGUP 2012-03-08 18:34:20.712938 [NOTICE] sofia.c:6293 Hangup sofia/internal/30@10.3.0.4 [CS_EXECUTE] [NORMAL_TEMPORARY_FAILURE] 2012-03-08 18:34:20.712938 [DEBUG] switch_channel.c:2871 Send signal sofia/internal/30@10.3.0.4 [KILL] 2012-03-08 18:34:20.712938 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/30@10.3.0.4 [BREAK] 2012-03-08 18:34:20.732954 [DEBUG] switch_ivr_bridge.c:586 BRIDGE THREAD DONE [sofia/internal/10@10.3.0.4] 2012-03-08 18:34:20.732954 [DEBUG] switch_ivr_bridge.c:611 Send signal sofia/internal/sip:30@10.3.0.26 [BREAK] 2012-03-08 18:34:20.732954 [DEBUG] switch_core_session.c:729 Send signal sofia/internal/10@10.3.0.4 [BREAK] recv 543 bytes from udp/[10.3.0.26]:5060 at 17:34:20.734163: ------------------------------------------------------------------------ ACK sip:20@10.3.0.4:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.3.0.26;branch=z9hG4bK909bdcdc8659BA5F From: "B" ;tag=4AB6AEB9-5DA56A24 To: ;tag=F019gcjgFya9S CSeq: 2 ACK Call-ID: da10f563-8c35d41e-ad0761b1@10.3.0.26 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Max-Forwards: 70 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:20.732954 [INFO] switch_cpp.cpp:1227 hangup hook for transfer!! EXECUTE sofia/internal/10@10.3.0.4 info() 2012-03-08 18:34:20.732954 [NOTICE] switch_core_session.c:1398 Session 10 (sofia/internal/sip:30@10.3.0.26) Ended 2012-03-08 18:34:20.732954 [NOTICE] switch_core_session.c:1400 Close Channel sofia/internal/sip:30@10.3.0.26 [CS_DESTROY] 2012-03-08 18:34:20.732954 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/sip:30@10.3.0.26) Callstate Change HANGUP -> DOWN 2012-03-08 18:34:20.732954 [DEBUG] switch_core_state_machine.c:494 (sofia/internal/sip:30@10.3.0.26) Running State Change CS_DESTROY 2012-03-08 18:34:20.732954 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/sip:30@10.3.0.26) State DESTROY 2012-03-08 18:34:20.732954 [DEBUG] mod_sofia.c:374 sofia/internal/sip:30@10.3.0.26 SOFIA DESTROY 2012-03-08 18:34:20.732954 [DEBUG] switch_core_state_machine.c:86 sofia/internal/sip:30@10.3.0.26 Standard DESTROY 2012-03-08 18:34:20.732954 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/sip:30@10.3.0.26) State DESTROY going to sleep 2012-03-08 18:34:20.732954 [INFO] mod_dptools.c:1439 CHANNEL_DATA: Channel-State: [CS_ROUTING] Channel-Call-State: [ACTIVE] Channel-State-Number: [2] Channel-Name: [sofia/internal/10@10.3.0.4] Unique-ID: [e73f07fa-6944-11e1-a7c4-a55c2ebde3ff] Call-Direction: [inbound] Presence-Call-Direction: [inbound] Channel-HIT-Dialplan: [true] Channel-Presence-ID: [10@10.3.0.4] Channel-Call-UUID: [e73f07fa-6944-11e1-a7c4-a55c2ebde3ff] Answer-State: [answered] Channel-Read-Codec-Name: [G722] Channel-Read-Codec-Rate: [16000] Channel-Read-Codec-Bit-Rate: [64000] Channel-Write-Codec-Name: [G722] Channel-Write-Codec-Rate: [16000] Channel-Write-Codec-Bit-Rate: [64000] Caller-Direction: [inbound] Caller-Username: [10] Caller-Dialplan: [inline] Caller-Caller-ID-Name: [A] Caller-Caller-ID-Number: [10] Caller-Callee-ID-Name: [Outbound Call] Caller-Callee-ID-Number: [30] Caller-Network-Addr: [10.3.0.22] Caller-ANI: [10] Caller-Destination-Number: [endless_playback:local_stream://moh,park] Caller-Unique-ID: [e73f07fa-6944-11e1-a7c4-a55c2ebde3ff] Caller-Source: [mod_sofia] Caller-Transfer-Source: [1331228060:f03b71c2-6944-11e1-a7e1-a55c2ebde3ff:bl_xfer:endless_playback:local_stream://moh,park/default/inline] Caller-Context: [default] Caller-RDNIS: [30] Caller-Channel-Name: [sofia/internal/10@10.3.0.4] Caller-Profile-Index: [2] Caller-Profile-Created-Time: [1331228060692943] Caller-Channel-Created-Time: [1331228045612916] Caller-Channel-Answered-Time: [1331228050212964] Caller-Channel-Progress-Time: [1331228049352961] Caller-Channel-Progress-Media-Time: [0] Caller-Channel-Hangup-Time: [0] Caller-Channel-Transfer-Time: [0] Caller-Screen-Bit: [true] Caller-Privacy-Hide-Name: [false] Caller-Privacy-Hide-Number: [false] variable_direction: [inbound] variable_uuid: [e73f07fa-6944-11e1-a7c4-a55c2ebde3ff] variable_session_id: [9] variable_sip_local_network_addr: [10.3.0.4] variable_sip_network_ip: [10.3.0.22] variable_sip_network_port: [5060] variable_sip_received_ip: [10.3.0.22] variable_sip_received_port: [5060] variable_sip_via_protocol: [udp] variable_sip_authorized: [true] variable_sip_number_alias: [10] variable_sip_auth_username: [10] variable_sip_auth_realm: [10.3.0.4] variable_number_alias: [10] variable_user_name: [10] variable_domain_name: [10.3.0.4] variable_record_stereo: [true] variable_default_gateway: [fonira] variable_default_areacode: [01] variable_transfer_fallback_extension: [operator] variable_toll_allow: [local,domestic,international,vas] variable_accountcode: [10] variable_user_context: [default] variable_effective_caller_id_name: [A ] variable_effective_caller_id_number: [10] variable_outbound_caller_id_name: [A ] variable_outbound_caller_id_number: [1997156010] variable_callgroup: [intercept] variable_sip_from_user: [10] variable_sip_from_uri: [10@10.3.0.4] variable_sip_from_host: [10.3.0.4] variable_sip_from_user_stripped: [10] variable_sofia_profile_name: [internal] variable_sip_req_params: [user=phone] variable_sip_req_user: [30] variable_sip_req_port: [5060] variable_sip_req_uri: [30@10.3.0.4:5060] variable_sip_req_host: [10.3.0.4] variable_sip_to_params: [user=phone] variable_sip_to_user: [30] variable_sip_to_uri: [30@10.3.0.4] variable_sip_to_host: [10.3.0.4] variable_sip_contact_user: [10] variable_sip_contact_uri: [10@10.3.0.22] variable_sip_contact_host: [10.3.0.22] variable_channel_name: [sofia/internal/10@10.3.0.4] variable_sip_user_agent: [PolycomSoundPointIP-SPIP_670-UA/3.3.1.0933] variable_sip_via_host: [10.3.0.22] variable_presence_id: [10@10.3.0.4] variable_switch_r_sdp: [v=0 o=- 1167627581 1167627581 IN IP4 10.3.0.22 s=Polycom IP Phone c=IN IP4 10.3.0.22 t=0 0 a=sendrecv m=audio 2262 RTP/AVP 9 0 8 127 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:127 telephone-event/8000 ] variable_sip_audio_recv_pt: [9] variable_sip_use_codec_name: [G722] variable_sip_use_codec_rate: [8000] variable_sip_use_codec_ptime: [20] variable_read_codec: [G722] variable_read_rate: [16000] variable_write_codec: [G722] variable_write_rate: [16000] variable_DP_MATCH: [ARRAY::30|:30] variable_call_uuid: [e73f07fa-6944-11e1-a7c4-a55c2ebde3ff] variable_dialed_extension: [30] variable_export_vars: [dialed_extension] variable_continue_on_fail: [true] variable_hangup_after_bridge: [true] variable_dialed_user: [30] variable_dialed_domain: [10.3.0.4] variable_sip_local_sdp_str: [v=0 o=FreeSWITCH 1331211630 1331211631 IN IP4 10.3.0.4 s=FreeSWITCH c=IN IP4 10.3.0.4 t=0 0 m=audio 16420 RTP/AVP 9 127 a=rtpmap:9 G722/8000 a=rtpmap:127 telephone-event/8000 a=fmtp:127 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv ] variable_local_media_ip: [10.3.0.4] variable_local_media_port: [16420] variable_advertised_media_ip: [10.3.0.4] variable_sip_use_pt: [9] variable_rtp_use_ssrc: [2056504069] variable_sip_2833_send_payload: [127] variable_sip_2833_recv_payload: [127] variable_remote_media_ip: [10.3.0.22] variable_remote_media_port: [2262] variable_endpoint_disposition: [ANSWER] variable_originate_disposition: [SUCCESS] variable_DIALSTATUS: [SUCCESS] variable_last_bridge_to: [e96bae48-6944-11e1-a7cc-a55c2ebde3ff] variable_sip_to_tag: [c5NZBUZ5Q37gQ] variable_sip_from_tag: [B0C14C18-E7DC6BB1] variable_sip_cseq: [2] variable_sip_call_id: [c64e932c-3eca2965-da54ee6@10.3.0.22] variable_sip_full_via: [SIP/2.0/UDP 10.3.0.22;branch=z9hG4bKe8d47063D608BAD4] variable_sip_from_display: [A] variable_sip_full_from: ["A" ;tag=B0C14C18-E7DC6BB1] variable_sip_full_to: [;tag=c5NZBUZ5Q37gQ] variable_bridge_channel: [sofia/internal/sip:30@10.3.0.26] variable_bridge_uuid: [e96bae48-6944-11e1-a7cc-a55c2ebde3ff] variable_switch_m_sdp: [v=0 o=- 1167627586 1167627587 IN IP4 10.3.0.26 s=Polycom IP Phone c=IN IP4 0.0.0.0 t=0 0 m=audio 2234 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=sendonly m=video 0 RTP/AVP 98 99 100 34 31 a=rtpmap:98 H264/90000 a=rtpmap:99 H263-2000/90000 a=rtpmap:100 H263-1998/90000 a=rtpmap:34 H263/90000 a=rtpmap:31 H261/90000 ] variable_att_xfer_kill_uuid: [ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff] variable_max_forwards: [69] variable_transfer_history: [ARRAY::1331228060:f03b71c2-6944-11e1-a7e1-a55c2ebde3ff:bl_xfer:endless_playback:local_stream://moh,park/default/inline] variable_transfer_source: [1331228060:f03b71c2-6944-11e1-a7e1-a55c2ebde3ff:bl_xfer:endless_playback:local_stream://moh,park/default/inline] variable_playback_seconds: [16] variable_playback_ms: [16720] variable_playback_samples: [133760] variable_bridge_hangup_cause: [NORMAL_CLEARING] variable_current_application: [info] 2012-03-08 18:34:20.732954 [WARNING] switch_cpp.cpp:1227 TEST X for UUID e73f07fa-6944-11e1-a7c4-a55c2ebde3ff, src 10 dest 30 2012-03-08 18:34:20.732954 [WARNING] switch_cpp.cpp:1227 TEST: Originate Disposition after bridge is SUCCESS 2012-03-08 18:34:20.732954 [WARNING] switch_cpp.cpp:1227 TEST 4 for UUID e73f07fa-6944-11e1-a7c4-a55c2ebde3ff, src 10 dest 30 EXECUTE sofia/internal/10@10.3.0.4 sleep(1000) recv 394 bytes from udp/[10.3.0.26]:5060 at 17:34:20.741808: ------------------------------------------------------------------------ SIP/2.0 481 Call Leg/Transaction Does Not Exist Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKDa14SN7jaBXye From: "A" ;tag=DeFrDpg9mcy3j To: ;tag=7463F28A-2FFBD77D CSeq: 25277962 BYE Call-ID: c0caa6b7-e3e7-122f-41a2-00900b1be504 User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ send 270 bytes to udp/[10.3.0.26]:5060 at 17:34:20.745132: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.26;branch=z9hG4bK415b2b56FCCA5AA9 From: "B" ;tag=7463F28A-2FFBD77D To: "A" ;tag=DeFrDpg9mcy3j Call-ID: c0caa6b7-e3e7-122f-41a2-00900b1be504 CSeq: 3 BYE Content-Length: 0 ------------------------------------------------------------------------ send 1070 bytes to udp/[10.3.0.25]:5060 at 17:34:20.776577: ------------------------------------------------------------------------ NOTIFY sip:20@10.3.0.25 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKeKtXUgrp7KKHa Max-Forwards: 70 From: ;tag=zVD97bWqz9Ei To: "C" ;tag=E729C66F-499D331E Call-ID: 6e8428e-4012accd-98b6429c@10.3.0.25 CSeq: 185332684 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=3304 Content-Type: application/dialog-info+xml Content-Length: 258 terminated ------------------------------------------------------------------------ send 1082 bytes to udp/[10.3.0.27]:5060 at 17:34:20.780085: ------------------------------------------------------------------------ NOTIFY sip:31@10.3.0.27 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKFvKpXB9S4v93N Max-Forwards: 70 From: ;tag=j2FaQyd4KlIW To: "Patrick SXXXXXXl" ;tag=26B3115D-24F8F110 Call-ID: 11c82624-cdfad25f-e9f5882@10.3.0.27 CSeq: 185332685 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=3304 Content-Type: application/dialog-info+xml Content-Length: 258 terminated ------------------------------------------------------------------------ recv 405 bytes from udp/[10.3.0.25]:5060 at 17:34:20.783041: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKeKtXUgrp7KKHa From: ;tag=zVD97bWqz9Ei To: "C" ;tag=E729C66F-499D331E CSeq: 185332684 NOTIFY Call-ID: 6e8428e-4012accd-98b6429c@10.3.0.25 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ send 1072 bytes to udp/[10.3.0.22]:5060 at 17:34:20.783873: ------------------------------------------------------------------------ NOTIFY sip:10@10.3.0.22 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKg5cFZ6SX15ZpH Max-Forwards: 70 From: ;tag=BL1yX2TI1X2c To: "A" ;tag=7B5DFEAE-48CDC3F7 Call-ID: ef7cb8bd-dc381cfe-bf64ccc7@10.3.0.22 CSeq: 185332686 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=3304 Content-Type: application/dialog-info+xml Content-Length: 258 terminated ------------------------------------------------------------------------ recv 417 bytes from udp/[10.3.0.27]:5060 at 17:34:20.787412: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKFvKpXB9S4v93N From: ;tag=j2FaQyd4KlIW To: "Patrick SXXXXXXl" ;tag=26B3115D-24F8F110 CSeq: 185332685 NOTIFY Call-ID: 11c82624-cdfad25f-e9f5882@10.3.0.27 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ recv 407 bytes from udp/[10.3.0.22]:5060 at 17:34:20.790635: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKg5cFZ6SX15ZpH From: ;tag=BL1yX2TI1X2c To: "A" ;tag=7B5DFEAE-48CDC3F7 CSeq: 185332686 NOTIFY Call-ID: ef7cb8bd-dc381cfe-bf64ccc7@10.3.0.22 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_670-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:21.732935 [WARNING] switch_cpp.cpp:1227 TEST 5 for UUID e73f07fa-6944-11e1-a7c4-a55c2ebde3ff, src 10 dest 30 EXECUTE sofia/internal/10@10.3.0.4 sleep(1000) 2012-03-08 18:34:22.732931 [WARNING] switch_cpp.cpp:1227 TEST 6 for UUID e73f07fa-6944-11e1-a7c4-a55c2ebde3ff, src 10 dest 30 EXECUTE sofia/internal/10@10.3.0.4 sleep(1000) 2012-03-08 18:34:23.732934 [DEBUG] mod_python.c:284 Finished calling python script 2012-03-08 18:34:23.732934 [DEBUG] switch_cpp.cpp:1007 sofia/internal/10@10.3.0.4 destroy/unlink session from object 2012-03-08 18:34:23.732934 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/10@10.3.0.4) State EXECUTE going to sleep 2012-03-08 18:34:23.732934 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10@10.3.0.4) Running State Change CS_ROUTING 2012-03-08 18:34:23.732934 [DEBUG] switch_channel.c:1886 (sofia/internal/10@10.3.0.4) Callstate Change ACTIVE -> RINGING 2012-03-08 18:34:23.753118 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/10@10.3.0.4) State ROUTING 2012-03-08 18:34:23.753118 [DEBUG] mod_sofia.c:148 sofia/internal/10@10.3.0.4 SOFIA ROUTING 2012-03-08 18:34:23.753118 [DEBUG] switch_core_state_machine.c:104 sofia/internal/10@10.3.0.4 Standard ROUTING 2012-03-08 18:34:23.753118 [DEBUG] switch_core_state_machine.c:154 (sofia/internal/10@10.3.0.4) State Change CS_ROUTING -> CS_EXECUTE 2012-03-08 18:34:23.753118 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:23.753118 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/10@10.3.0.4) State ROUTING going to sleep 2012-03-08 18:34:23.753118 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10@10.3.0.4) Running State Change CS_EXECUTE 2012-03-08 18:34:23.753118 [DEBUG] switch_channel.c:1888 (sofia/internal/10@10.3.0.4) Callstate Change RINGING -> ACTIVE 2012-03-08 18:34:23.753118 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/10@10.3.0.4) State EXECUTE 2012-03-08 18:34:23.753118 [DEBUG] mod_sofia.c:241 sofia/internal/10@10.3.0.4 SOFIA EXECUTE 2012-03-08 18:34:23.753118 [DEBUG] switch_core_state_machine.c:192 sofia/internal/10@10.3.0.4 Standard EXECUTE EXECUTE sofia/internal/10@10.3.0.4 endless_playback(local_stream://moh) 2012-03-08 18:34:23.753118 [DEBUG] mod_local_stream.c:421 Opening Stream [moh/16000] 16000hz 2012-03-08 18:34:23.753118 [DEBUG] switch_ivr_play_say.c:1306 Codec Activated L16@16000hz 1 channels 20ms send 1402 bytes to udp/[10.3.0.25]:5060 at 17:34:23.860078: ------------------------------------------------------------------------ NOTIFY sip:20@10.3.0.25 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKHe6701a1yep9c Max-Forwards: 70 From: ;tag=JElIsHAUjri7 To: "C" ;tag=432C4A25-2C483674 Call-ID: a941c408-2c54f3a7-82c5a8d6@10.3.0.25 CSeq: 185332687 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=1138 Content-Type: application/dialog-info+xml Content-Length: 589 confirmed sip:10@10.3.0.4 sip:endless_playback:local_stream://moh,park@10.3.0.4 ------------------------------------------------------------------------ send 1410 bytes to udp/[10.3.0.26]:5060 at 17:34:23.862933: ------------------------------------------------------------------------ NOTIFY sip:30@10.3.0.26 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKjQZ02vU4UQcvr Max-Forwards: 70 From: ;tag=hzYaAHIZscZq To: "B" ;tag=A52D4836-AD38FE89 Call-ID: 3f77033d-f3b24ec8-f0479fab@10.3.0.26 CSeq: 185332688 NOTIFY Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Event: dialog Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=1138 Content-Type: application/dialog-info+xml Content-Length: 589 confirmed sip:10@10.3.0.4 sip:endless_playback:local_stream://moh,park@10.3.0.4 ------------------------------------------------------------------------ recv 406 bytes from udp/[10.3.0.25]:5060 at 17:34:23.867468: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKHe6701a1yep9c From: ;tag=JElIsHAUjri7 To: "C" ;tag=432C4A25-2C483674 CSeq: 185332687 NOTIFY Call-ID: a941c408-2c54f3a7-82c5a8d6@10.3.0.25 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ recv 414 bytes from udp/[10.3.0.26]:5060 at 17:34:23.870281: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKjQZ02vU4UQcvr From: ;tag=hzYaAHIZscZq To: "B" ;tag=A52D4836-AD38FE89 CSeq: 185332688 NOTIFY Call-ID: 3f77033d-f3b24ec8-f0479fab@10.3.0.26 Contact: Event: dialog User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:32.012932 [DEBUG] switch_channel.c:2598 (sofia/internal/10@10.3.0.4) State Change CS_EXECUTE -> CS_RESET 2012-03-08 18:34:32.012932 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:32.032936 [DEBUG] switch_ivr_play_say.c:1678 done playing file local_stream://moh 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/10@10.3.0.4) State EXECUTE going to sleep 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10@10.3.0.4) Running State Change CS_RESET 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:413 (sofia/internal/10@10.3.0.4) State RESET 2012-03-08 18:34:32.032936 [DEBUG] switch_channel.c:2600 (sofia/internal/10@10.3.0.4) State Change CS_RESET -> CS_EXECUTE 2012-03-08 18:34:32.032936 [DEBUG] mod_sofia.c:166 sofia/internal/10@10.3.0.4 SOFIA RESET 2012-03-08 18:34:32.032936 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:32.032936 [DEBUG] switch_channel.c:2848 (sofia/internal/sip:20@10.3.0.25) Callstate Change RINGING -> HANGUP 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:413 (sofia/internal/10@10.3.0.4) State RESET going to sleep 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10@10.3.0.4) Running State Change CS_EXECUTE 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/10@10.3.0.4) State EXECUTE 2012-03-08 18:34:32.032936 [DEBUG] mod_sofia.c:241 sofia/internal/10@10.3.0.4 SOFIA EXECUTE 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:192 sofia/internal/10@10.3.0.4 Standard EXECUTE 2012-03-08 18:34:32.032936 [NOTICE] switch_ivr_originate.c:3075 Hangup sofia/internal/sip:20@10.3.0.25 [CS_CONSUME_MEDIA] [ATTENDED_TRANSFER] 2012-03-08 18:34:32.032936 [NOTICE] switch_core_state_machine.c:226 sofia/internal/10@10.3.0.4 has executed the last dialplan instruction, hanging up. 2012-03-08 18:34:32.032936 [DEBUG] switch_channel.c:2848 (sofia/internal/10@10.3.0.4) Callstate Change ACTIVE -> HANGUP 2012-03-08 18:34:32.032936 [NOTICE] switch_core_state_machine.c:228 Hangup sofia/internal/10@10.3.0.4 [CS_EXECUTE] [NORMAL_CLEARING] 2012-03-08 18:34:32.032936 [DEBUG] switch_channel.c:2871 Send signal sofia/internal/sip:20@10.3.0.25 [KILL] 2012-03-08 18:34:32.032936 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:20@10.3.0.25 [BREAK] 2012-03-08 18:34:32.032936 [NOTICE] switch_ivr_originate.c:2459 Cannot create outgoing channel of type [user] cause: [ATTENDED_TRANSFER] 2012-03-08 18:34:32.032936 [DEBUG] switch_ivr_originate.c:3364 Originate Resulted in Error Cause: 601 [ATTENDED_TRANSFER] 2012-03-08 18:34:32.032936 [INFO] mod_dptools.c:2922 Originate Failed. Cause: ATTENDED_TRANSFER 2012-03-08 18:34:32.032936 [DEBUG] switch_channel.c:2871 Send signal sofia/internal/10@10.3.0.4 [KILL] 2012-03-08 18:34:32.032936 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/10@10.3.0.4) State EXECUTE going to sleep 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10@10.3.0.4) Running State Change CS_HANGUP 2012-03-08 18:34:32.032936 [DEBUG] switch_core_session.c:2285 sofia/internal/30@10.3.0.4 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2012-03-08 18:34:32.032936 [INFO] switch_cpp.cpp:1227 hangup hook for hangup!! 2012-03-08 18:34:32.032936 [DEBUG] switch_core_session.c:2095 sofia/internal/30@10.3.0.4 ZOMBIE EXEC info() EXECUTE sofia/internal/30@10.3.0.4 info() 2012-03-08 18:34:32.032936 [DEBUG] switch_core_session.c:2271 sofia/internal/30@10.3.0.4 skip receive message [APPLICATION_EXEC] (channel is hungup already) 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/10@10.3.0.4) State HANGUP 2012-03-08 18:34:32.032936 [DEBUG] mod_sofia.c:469 Channel sofia/internal/10@10.3.0.4 hanging up, cause: NORMAL_CLEARING 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:20@10.3.0.25) Running State Change CS_HANGUP 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/sip:20@10.3.0.25) State HANGUP 2012-03-08 18:34:32.032936 [DEBUG] mod_sofia.c:469 Channel sofia/internal/sip:20@10.3.0.25 hanging up, cause: ATTENDED_TRANSFER 2012-03-08 18:34:32.032936 [INFO] mod_dptools.c:1439 CHANNEL_DATA: Channel-State: [CS_HANGUP] Channel-Call-State: [HANGUP] Channel-State-Number: [10] Channel-Name: [sofia/internal/30@10.3.0.4] Unique-ID: [ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff] Call-Direction: [inbound] Presence-Call-Direction: [inbound] Channel-HIT-Dialplan: [true] Channel-Presence-ID: [30@10.3.0.4] Channel-Call-UUID: [ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff] Answer-State: [hangup] Channel-Read-Codec-Name: [G722] Channel-Read-Codec-Rate: [16000] Channel-Read-Codec-Bit-Rate: [64000] Channel-Write-Codec-Name: [G722] Channel-Write-Codec-Rate: [16000] Channel-Write-Codec-Bit-Rate: [64000] Caller-Direction: [inbound] Caller-Username: [30] Caller-Dialplan: [XML] Caller-Caller-ID-Name: [B] Caller-Caller-ID-Number: [30] Caller-Callee-ID-Name: [Outbound Call] Caller-Callee-ID-Number: [20] Caller-Network-Addr: [10.3.0.26] Caller-ANI: [30] Caller-Destination-Number: [20] Caller-Unique-ID: [ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff] Caller-Source: [mod_sofia] Caller-Context: [default] Caller-Channel-Name: [sofia/internal/30@10.3.0.4] Caller-Profile-Index: [1] Caller-Profile-Created-Time: [1331228054432937] Caller-Channel-Created-Time: [1331228054432937] Caller-Channel-Answered-Time: [0] Caller-Channel-Progress-Time: [1331228058052945] Caller-Channel-Progress-Media-Time: [0] Caller-Channel-Hangup-Time: [0] Caller-Channel-Transfer-Time: [0] Caller-Screen-Bit: [true] Caller-Privacy-Hide-Name: [false] Caller-Privacy-Hide-Number: [false] variable_direction: [inbound] variable_uuid: [ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff] variable_session_id: [11] variable_sip_local_network_addr: [10.3.0.4] variable_sip_network_ip: [10.3.0.26] variable_sip_network_port: [5060] variable_sip_received_ip: [10.3.0.26] variable_sip_received_port: [5060] variable_sip_via_protocol: [udp] variable_sip_authorized: [true] variable_sip_number_alias: [30] variable_sip_auth_username: [30] variable_sip_auth_realm: [10.3.0.4] variable_number_alias: [30] variable_user_name: [30] variable_domain_name: [10.3.0.4] variable_record_stereo: [true] variable_default_gateway: [fonira] variable_default_areacode: [01] variable_transfer_fallback_extension: [operator] variable_toll_allow: [local,domestic,international,vas] variable_accountcode: [30] variable_user_context: [default] variable_effective_caller_id_name: [B] variable_effective_caller_id_number: [30] variable_outbound_caller_id_name: [B] variable_outbound_caller_id_number: [1997156030] variable_callgroup: [intercept] variable_sip_from_user: [30] variable_sip_from_uri: [30@10.3.0.4] variable_sip_from_host: [10.3.0.4] variable_sip_from_user_stripped: [30] variable_sip_from_tag: [4AB6AEB9-5DA56A24] variable_sofia_profile_name: [internal] variable_sip_full_via: [SIP/2.0/UDP 10.3.0.26;branch=z9hG4bK909bdcdc8659BA5F] variable_sip_from_display: [B] variable_sip_full_from: ["B" ;tag=4AB6AEB9-5DA56A24] variable_sip_full_to: [] variable_sip_req_params: [user=phone] variable_sip_req_user: [20] variable_sip_req_port: [5060] variable_sip_req_uri: [20@10.3.0.4:5060] variable_sip_req_host: [10.3.0.4] variable_sip_to_params: [user=phone] variable_sip_to_user: [20] variable_sip_to_uri: [20@10.3.0.4] variable_sip_to_host: [10.3.0.4] variable_sip_contact_user: [30] variable_sip_contact_uri: [30@10.3.0.26] variable_sip_contact_host: [10.3.0.26] variable_channel_name: [sofia/internal/30@10.3.0.4] variable_sip_call_id: [da10f563-8c35d41e-ad0761b1@10.3.0.26] variable_sip_user_agent: [PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933] variable_sip_via_host: [10.3.0.26] variable_max_forwards: [70] variable_presence_id: [30@10.3.0.4] variable_switch_r_sdp: [v=0 o=- 1167627590 1167627590 IN IP4 10.3.0.26 s=Polycom IP Phone c=IN IP4 10.3.0.26 t=0 0 a=sendrecv m=audio 2236 RTP/AVP 9 0 8 127 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:127 telephone-event/8000 ] variable_remote_media_ip: [10.3.0.26] variable_remote_media_port: [2236] variable_sip_audio_recv_pt: [9] variable_sip_use_codec_name: [G722] variable_sip_use_codec_rate: [8000] variable_sip_use_codec_ptime: [20] variable_read_codec: [G722] variable_read_rate: [16000] variable_write_codec: [G722] variable_write_rate: [16000] variable_DP_MATCH: [ARRAY::20|:20] variable_call_uuid: [ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff] variable_dialed_extension: [20] variable_export_vars: [dialed_extension] variable_continue_on_fail: [true] variable_hangup_after_bridge: [true] variable_dialed_user: [20] variable_dialed_domain: [10.3.0.4] variable_endpoint_disposition: [ATTENDED_TRANSFER] variable_sip_term_status: [481] variable_proto_specific_hangup_cause: [sip:481] variable_sip_term_cause: [41] variable_originate_disposition: [ATTENDED_TRANSFER] variable_DIALSTATUS: [ATTENDED_TRANSFER] variable_current_application: [info] 2012-03-08 18:34:32.032936 [DEBUG] switch_core_session.c:2285 sofia/internal/30@10.3.0.4 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2012-03-08 18:34:32.032936 [WARNING] switch_cpp.cpp:1227 TEST X for UUID ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff, src 30 dest 20 2012-03-08 18:34:32.032936 [WARNING] switch_cpp.cpp:1227 TEST: Originate Disposition after bridge is ATTENDED_TRANSFER 2012-03-08 18:34:32.032936 [WARNING] switch_cpp.cpp:1227 TEST 4 for UUID ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff, src 30 dest 20 2012-03-08 18:34:32.032936 [DEBUG] switch_core_session.c:2100 sofia/internal/30@10.3.0.4 Channel is hungup and application 'sleep' does not have the zombie_exec flag. 2012-03-08 18:34:32.032936 [WARNING] switch_cpp.cpp:1227 TEST 5 for UUID ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff, src 30 dest 20 2012-03-08 18:34:32.032936 [DEBUG] switch_core_session.c:2100 sofia/internal/30@10.3.0.4 Channel is hungup and application 'sleep' does not have the zombie_exec flag. 2012-03-08 18:34:32.032936 [WARNING] switch_cpp.cpp:1227 TEST 6 for UUID ec80d1f8-6944-11e1-a7d5-a55c2ebde3ff, src 30 dest 20 2012-03-08 18:34:32.032936 [DEBUG] switch_core_session.c:2100 sofia/internal/30@10.3.0.4 Channel is hungup and application 'sleep' does not have the zombie_exec flag. 2012-03-08 18:34:32.032936 [DEBUG] mod_python.c:284 Finished calling python script 2012-03-08 18:34:32.032936 [DEBUG] switch_cpp.cpp:1007 sofia/internal/30@10.3.0.4 destroy/unlink session from object 2012-03-08 18:34:32.032936 [DEBUG] switch_core_session.c:2285 sofia/internal/30@10.3.0.4 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/30@10.3.0.4) State EXECUTE going to sleep 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/30@10.3.0.4) Running State Change CS_HANGUP 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/30@10.3.0.4) State HANGUP 2012-03-08 18:34:32.032936 [DEBUG] mod_sofia.c:469 Channel sofia/internal/30@10.3.0.4 hanging up, cause: NORMAL_TEMPORARY_FAILURE 2012-03-08 18:34:32.032936 [DEBUG] mod_sofia.c:513 Sending BYE to sofia/internal/10@10.3.0.4 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:47 sofia/internal/10@10.3.0.4 Standard HANGUP, cause: NORMAL_CLEARING 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/10@10.3.0.4) State HANGUP going to sleep 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:393 (sofia/internal/10@10.3.0.4) State Change CS_HANGUP -> CS_REPORTING send 637 bytes to udp/[10.3.0.22]:5060 at 17:34:32.048986: ------------------------------------------------------------------------ BYE sip:10@10.3.0.22 SIP/2.02012-03-08 18:34:32.032936 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10@10.3.0.4 [BREAK] Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKK0rS4Qc8r02em Max-Forwards: 70 From: ;tag=c5NZBUZ5Q37gQ To: "A" ;tag=B0C14C18-E7DC6BB12012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10@10.3.0.4) Running State Change CS_REPORTING Call-ID: c64e932c-3eca2965-da54ee6@10.3.0.22 CSeq: 25277972 BYE Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-fbe4e64 2012-02-22 23-08-19 -0600 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/10@10.3.0.4) State REPORTING 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:79 sofia/internal/10@10.3.0.4 Standard REPORTING, cause: NORMAL_CLEARING 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/10@10.3.0.4) State REPORTING going to sleep 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:387 (sofia/internal/10@10.3.0.4) State Change CS_REPORTING -> CS_DESTROY 2012-03-08 18:34:32.032936 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10@10.3.0.4 [BREAK] 2012-03-08 18:34:32.032936 [DEBUG] switch_core_session.c:1380 Session 9 (sofia/internal/10@10.3.0.4) Locked, Waiting on external entities 2012-03-08 18:34:32.032936 [NOTICE] switch_core_session.c:1398 Session 9 (sofia/internal/10@10.3.0.4) Ended 2012-03-08 18:34:32.032936 [NOTICE] switch_core_session.c:1400 Close Channel sofia/internal/10@10.3.0.4 [CS_DESTROY] 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/10@10.3.0.4) Callstate Change HANGUP -> DOWN 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:494 (sofia/internal/10@10.3.0.4) Running State Change CS_DESTROY 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/10@10.3.0.4) State DESTROY 2012-03-08 18:34:32.032936 [DEBUG] mod_sofia.c:374 sofia/internal/10@10.3.0.4 SOFIA DESTROY 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:86 sofia/internal/10@10.3.0.4 Standard DESTROY 2012-03-08 18:34:32.032936 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/10@10.3.0.4) State DESTROY going to sleep recv 399 bytes from udp/[10.3.0.22]:5060 at 17:34:32.055973: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKK0rS4Qc8r02em From: ;tag=c5NZBUZ5Q37gQ To: "A" ;tag=B0C14C18-E7DC6BB1 CSeq: 25277972 BYE Call-ID: c64e932c-3eca2965-da54ee6@10.3.0.22 Contact: 2012-03-08 18:34:32.052952 [DEBUG] mod_sofia.c:523 Sending CANCEL to sofia/internal/sip:20@10.3.0.25 User-Agent: PolycomSoundPointIP-SPIP_670-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:47 sofia/internal/sip:20@10.3.0.25 Standard HANGUP, cause: ATTENDED_TRANSFER 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/sip:20@10.3.0.25) State HANGUP going to sleep 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:393 (sofia/internal/sip:20@10.3.0.25) State Change CS_HANGUP -> CS_REPORTING 2012-03-08 18:34:32.052952 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:20@10.3.0.25 [BREAK] 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:20@10.3.0.25) Running State Change CS_REPORTING 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/sip:20@10.3.0.25) State REPORTING 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:79 sofia/internal/sip:20@10.3.0.25 Standard REPORTING, cause: ATTENDED_TRANSFER 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/sip:20@10.3.0.25) State REPORTING going to sleep send 341 bytes to udp/[10.3.0.25]:5060 at 17:34:32.056855: ------------------------------------------------------------------------ CANCEL sip:20@10.3.0.25 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK8v28geK1ryD1m Max-Forwards: 69 From: "B" ;tag=g9t2j72Kc70UN To: Call-ID: c5fdcf90-e3e7-122f-41a2-00900b1be504 CSeq: 25277964 CANCEL Reason: FreeSWITCH;cause=601;text="ATTENDED_TRANSFER" Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:387 (sofia/internal/sip:20@10.3.0.25) State Change CS_REPORTING -> CS_DESTROY 2012-03-08 18:34:32.052952 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:20@10.3.0.25 [BREAK] 2012-03-08 18:34:32.052952 [DEBUG] switch_core_session.c:1380 Session 12 (sofia/internal/sip:20@10.3.0.25) Locked, Waiting on external entities 2012-03-08 18:34:32.052952 [NOTICE] switch_core_session.c:1398 Session 12 (sofia/internal/sip:20@10.3.0.25) Ended 2012-03-08 18:34:32.052952 [NOTICE] switch_core_session.c:1400 Close Channel sofia/internal/sip:20@10.3.0.25 [CS_DESTROY] 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/sip:20@10.3.0.25) Callstate Change HANGUP -> DOWN 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:494 (sofia/internal/sip:20@10.3.0.25) Running State Change CS_DESTROY 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/sip:20@10.3.0.25) State DESTROY 2012-03-08 18:34:32.052952 [DEBUG] mod_sofia.c:374 sofia/internal/sip:20@10.3.0.25 SOFIA DESTROY 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:86 sofia/internal/sip:20@10.3.0.25 Standard DESTROY 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/sip:20@10.3.0.25) State DESTROY going to sleep recv 386 bytes from udp/[10.3.0.25]:5060 at 17:34:32.061492: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK8v28geK1ryD1m From: "B" ;tag=g9t2j72Kc70UN To: "C" CSeq: 25277964 CANCEL Call-ID: c5fdcf90-e3e7-122f-41a2-00900b1be504 Contact: User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933 Accept-Language: de-de,de;q=0.9,en;q=0.8 Content-Length: 0 ------------------------------------------------------------------------ 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:47 sofia/internal/30@10.3.0.4 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/30@10.3.0.4) State HANGUP going to sleep 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:393 (sofia/internal/30@10.3.0.4) State Change CS_HANGUP -> CS_REPORTING 2012-03-08 18:34:32.052952 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/30@10.3.0.4 [BREAK] 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/30@10.3.0.4) Running State Change CS_REPORTING 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/30@10.3.0.4) State REPORTING 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:79 sofia/internal/30@10.3.0.4 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/30@10.3.0.4) State REPORTING going to sleep 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:387 (sofia/internal/30@10.3.0.4) State Change CS_REPORTING -> CS_DESTROY 2012-03-08 18:34:32.052952 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/30@10.3.0.4 [BREAK] 2012-03-08 18:34:32.052952 [DEBUG] switch_core_session.c:1380 Session 11 (sofia/internal/30@10.3.0.4) Locked, Waiting on external entities 2012-03-08 18:34:32.052952 [NOTICE] switch_core_session.c:1398 Session 11 (sofia/internal/30@10.3.0.4) Ended 2012-03-08 18:34:32.052952 [NOTICE] switch_core_session.c:1400 Close Channel sofia/internal/30@10.3.0.4 [CS_DESTROY] 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/30@10.3.0.4) Callstate Change HANGUP -> DOWN 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:494 (sofia/internal/30@10.3.0.4) Running State Change CS_DESTROY 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/30@10.3.0.4) State DESTROY 2012-03-08 18:34:32.052952 [DEBUG] mod_sofia.c:374 sofia/internal/30@10.3.0.4 SOFIA DESTROY 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:86 sofia/internal/30@10.3.0.4 Standard DESTROY 2012-03-08 18:34:32.052952 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/30@10.3.0.4) State DESTROY going to sleep