recv 1280 bytes from udp/[172.19.51.21]:5060 at 23:52:59.065331: ------------------------------------------------------------------------ INVITE sip:0108008080800@pbx.[anonym].net;user=phone SIP/2.0 Via: SIP/2.0/UDP 172.19.51.21:5060;branch=z9hG4bK-B89D2271;rport From: ;tag=4241842629 To: Call-ID: fa59464a61e75b01907f0090332616fc@5 CSeq: 1286550375 INVITE Contact: Allow: REGISTER,SUBSCRIBE,NOTIFY,INVITE,ACK,PRACK,OPTIONS,BYE,CANCEL,REFER,INFO,UPDATE,PUBLISH Content-Length: 514 Content-Type: application/sdp Max-Forwards: 63 Supported: 100rel,replaces,privacy,timer,from-change,histinfo,answermode User-Agent: (innovaphone IP240/12r1 sr26 [12.1257/121257/301]) P-Preferred-Identity: Recv-Info: dtmf P-Sig-Options: Sending-Complete,bc=038090a3 v=0 o=- 5 1 IN IP4 172.19.51.21 s=- t=0 0 m=audio 16386 RTP/AVP 8 18 4 0 101 13 c=IN IP4 172.19.51.21 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:4 G723/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=rtpmap:13 CN/8000 a=fmtp:18 annexb=yes a=fmtp:101 0-15 a=ptime:20 a=silenceSupp:on - - - - a=sendrecv a=ice-ufrag:w7Ce a=ice-pwd:VWGNhMKhGBOF4qSOrfWHP7 a=candidate:1 1 UDP 2130569471 172.19.51.21 16386 typ host a=candidate:1 2 UDP 2130569726 172.19.51.21 16387 typ host ------------------------------------------------------------------------ 2018-11-10 23:52:59.055672 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/11@pbx.[anonym].net [4ef5163f-777a-413d-8ba7-5a983d75f668] 2018-11-10 23:52:59.055672 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@pbx.[anonym].net) Running State Change CS_NEW (Cur 1 Tot 1) 2018-11-10 23:52:59.055672 [DEBUG] sofia.c:10080 sofia/internal/11@pbx.[anonym].net receiving invite from 172.19.51.21:5060 version: 1.8.2 -3-a98a958ac3 64bit 2018-11-10 23:52:59.055672 [DEBUG] sofia.c:10251 IP 172.19.51.21 Rejected by acl "domains". Falling back to Digest auth. 2018-11-10 23:52:59.055672 [WARNING] sofia_reg.c:1793 SIP auth challenge (INVITE) on sofia profile 'internal' for [0108008080800@pbx.[anonym].net] from ip 172.19.51.21 2018-11-10 23:52:59.055672 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/11@pbx.[anonym].net) State NEW send 805 bytes to udp/[172.19.51.21]:5060 at 23:52:59.071069: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 172.19.51.21:5060;branch=z9hG4bK-B89D2271;rport=5060 From: ;tag=4241842629 To: ;tag=BQK6yKFpygX2Q Call-ID: fa59464a61e75b01907f0090332616fc@5 CSeq: 1286550375 INVITE User-Agent: FreeSWITCH Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Proxy-Authenticate: Digest realm="pbx.[anonym].net", nonce="63e024d3-63ce-40e6-96e4-609a5ba18097", algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ 2018-11-10 23:52:59.055672 [DEBUG] sofia.c:2413 detaching session 4ef5163f-777a-413d-8ba7-5a983d75f668 recv 392 bytes from udp/[172.19.51.21]:5060 at 23:52:59.073914: ------------------------------------------------------------------------ ACK sip:0108008080800@pbx.[anonym].net;user=phone SIP/2.0 Via: SIP/2.0/UDP 172.19.51.21:5060;branch=z9hG4bK-B89D2271;rport From: ;tag=4241842629 To: ;tag=BQK6yKFpygX2Q Call-ID: fa59464a61e75b01907f0090332616fc@5 CSeq: 1286550375 ACK Contact: Content-Length: 0 Max-Forwards: 70 ------------------------------------------------------------------------ recv 1544 bytes from udp/[172.19.51.21]:5060 at 23:52:59.077003: ------------------------------------------------------------------------ INVITE sip:0108008080800@pbx.[anonym].net;user=phone SIP/2.0 Proxy-Authorization: Digest username="11",realm="pbx.[anonym].net",nonce="63e024d3-63ce-40e6-96e4-609a5ba18097",response="f933176b57b576d0b597e4b3c45fcc20",uri="sip:0108008080800@pbx.[anonym].net;user=phone",qop=auth,cnonce="00039f9680560c34",nc=00000001,algorithm=MD5 Via: SIP/2.0/UDP 172.19.51.21:5060;branch=z9hG4bK-B89D2272;rport From: ;tag=4241842629 To: Call-ID: fa59464a61e75b01907f0090332616fc@5 CSeq: 1286550376 INVITE Contact: Allow: REGISTER,SUBSCRIBE,NOTIFY,INVITE,ACK,PRACK,OPTIONS,BYE,CANCEL,REFER,INFO,UPDATE,PUBLISH Content-Length: 514 Content-Type: application/sdp Max-Forwards: 63 Supported: 100rel,replaces,privacy,timer,from-change,histinfo,answermode User-Agent: (innovaphone IP240/12r1 sr26 [12.1257/121257/301]) P-Preferred-Identity: Recv-Info: dtmf P-Sig-Options: Sending-Complete,bc=038090a3 v=0 o=- 5 1 IN IP4 172.19.51.21 s=- t=0 0 m=audio 16386 RTP/AVP 8 18 4 0 101 13 c=IN IP4 172.19.51.21 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:4 G723/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=rtpmap:13 CN/8000 a=fmtp:18 annexb=yes a=fmtp:101 0-15 a=ptime:20 a=silenceSupp:on - - - - a=sendrecv a=ice-ufrag:w7Ce a=ice-pwd:VWGNhMKhGBOF4qSOrfWHP7 a=candidate:1 1 UDP 2130569471 172.19.51.21 16386 typ host a=candidate:1 2 UDP 2130569726 172.19.51.21 16387 typ host ------------------------------------------------------------------------ 2018-11-10 23:52:59.075716 [DEBUG] sofia.c:2522 Re-attaching to session 4ef5163f-777a-413d-8ba7-5a983d75f668 2018-11-10 23:52:59.075716 [DEBUG] sofia.c:10080 sofia/internal/11@pbx.[anonym].net receiving invite from 172.19.51.21:5060 version: 1.8.2 -3-a98a958ac3 64bit 2018-11-10 23:52:59.075716 [DEBUG] sofia.c:10251 IP 172.19.51.21 Rejected by acl "domains". Falling back to Digest auth. 2018-11-10 23:52:59.135683 [DEBUG] sofia.c:7291 Channel sofia/internal/11@pbx.[anonym].net entering state [received][100] 2018-11-10 23:52:59.135683 [DEBUG] sofia.c:7301 Remote SDP: v=0 o=- 5 1 IN IP4 172.19.51.21 s=- t=0 0 m=audio 16386 RTP/AVP 8 18 4 0 101 13 c=IN IP4 172.19.51.21 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=yes a=rtpmap:4 G723/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=rtpmap:13 CN/8000 a=ptime:20 a=silenceSupp:on - - - - a=ice-ufrag:w7Ce a=ice-pwd:VWGNhMKhGBOF4qSOrfWHP7 a=candidate:1 1 UDP 2130569471 172.19.51.21 16386 typ host a=candidate:1 2 UDP 2130569726 172.19.51.21 16387 typ host 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1] 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1] 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G723:4:8000:20:6300:1]/[opus:116:48000:20:0:1] 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G723:4:8000:20:6300:1]/[G722:9:8000:20:64000:1] 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMA:8:8000:20:64000:1] 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:3781 Set Codec sofia/internal/11@pbx.[anonym].net PCMA/8000 20 ms 160 samples 64000 bits 1 channels 2018-11-10 23:52:59.135683 [DEBUG] switch_core_codec.c:111 sofia/internal/11@pbx.[anonym].net Original read codec set to PCMA:8 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:4211 Save audio Candidate cid: 1 proto: UDP type: host addr: 172.19.51.21:16386 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:4211 Save audio Candidate cid: 2 proto: UDP type: host addr: 172.19.51.21:16387 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:4256 Searching for rtp candidate. 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:4265 Choose rtp candidate, index 0, 172.19.51.21:16386 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:4031 sofia/internal/11@pbx.[anonym].net choosing family v4 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:4256 Searching for rtcp candidate. 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:4265 Choose rtcp candidate, index 0, 172.19.51.21:16387 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:4031 sofia/internal/11@pbx.[anonym].net choosing family v4 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:4328 setting remote audio ice addr to index 0 172.19.51.21:16386 based on candidate 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:4363 Setting remote rtcp audio addr to 172.19.51.21:16387 based on candidate 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:5737 Set telephone-event payload to 101@8000 2018-11-10 23:52:59.135683 [DEBUG] switch_core_media.c:5795 sofia/internal/11@pbx.[anonym].net Set 2833 dtmf send payload to 101 recv payload to 101 2018-11-10 23:52:59.135683 [DEBUG] sofia.c:7716 (sofia/internal/11@pbx.[anonym].net) State Change CS_NEW -> CS_INIT 2018-11-10 23:52:59.135683 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@pbx.[anonym].net) Running State Change CS_INIT (Cur 1 Tot 1) 2018-11-10 23:52:59.135683 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/11@pbx.[anonym].net) State INIT 2018-11-10 23:52:59.135683 [DEBUG] mod_sofia.c:93 sofia/internal/11@pbx.[anonym].net SOFIA INIT 2018-11-10 23:52:59.135683 [DEBUG] switch_core_state_machine.c:40 sofia/internal/11@pbx.[anonym].net Standard INIT 2018-11-10 23:52:59.135683 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/11@pbx.[anonym].net) State Change CS_INIT -> CS_ROUTING 2018-11-10 23:52:59.135683 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/11@pbx.[anonym].net) State INIT going to sleep 2018-11-10 23:52:59.135683 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@pbx.[anonym].net) Running State Change CS_ROUTING (Cur 1 Tot 1) 2018-11-10 23:52:59.135683 [DEBUG] switch_channel.c:2249 (sofia/internal/11@pbx.[anonym].net) Callstate Change DOWN -> RINGING 2018-11-10 23:52:59.135683 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/11@pbx.[anonym].net) State ROUTING 2018-11-10 23:52:59.135683 [DEBUG] mod_sofia.c:154 sofia/internal/11@pbx.[anonym].net SOFIA ROUTING 2018-11-10 23:52:59.135683 [DEBUG] switch_core_state_machine.c:236 sofia/internal/11@pbx.[anonym].net Standard ROUTING 2018-11-10 23:52:59.135683 [INFO] mod_dialplan_xml.c:637 Processing 11 <11>->0108008080800 in context pbx.[anonym].net send 301 bytes to udp/[172.19.51.21]:5060 at 23:52:59.140116: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 172.19.51.21:5060;branch=z9hG4bK-B89D2272;rport=5060 From: ;tag=4241842629 To: Call-ID: fa59464a61e75b01907f0090332616fc@5 CSeq: 1286550376 INVITE User-Agent: FreeSWITCH Content-Length: 0 ------------------------------------------------------------------------ Dialplan: sofia/internal/11@pbx.[anonym].net parsing [pbx.[anonym].net->user_exists] continue=true Dialplan: sofia/internal/11@pbx.[anonym].net Regex (PASS) [user_exists] () =~ // break=on-false Dialplan: sofia/internal/11@pbx.[anonym].net Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE EXECUTE sofia/internal/11@pbx.[anonym].net set(user_exists=false) 2018-11-10 23:52:59.215661 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [user_exists]=[false] Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false Dialplan: sofia/internal/11@pbx.[anonym].net parsing [pbx.[anonym].net->caller-details] continue=true Dialplan: sofia/internal/11@pbx.[anonym].net Regex (PASS) [caller-details] ${caller_destination}() =~ /^$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Action set(caller_destination=${destination_number}) INLINE EXECUTE sofia/internal/11@pbx.[anonym].net set(caller_destination=0108008080800) 2018-11-10 23:52:59.235663 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [caller_destination]=[0108008080800] Dialplan: sofia/internal/11@pbx.[anonym].net Action set(caller_id_name=${caller_id_name}) INLINE EXECUTE sofia/internal/11@pbx.[anonym].net set(caller_id_name=11) 2018-11-10 23:52:59.235663 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [caller_id_name]=[11] Dialplan: sofia/internal/11@pbx.[anonym].net Action set(caller_id_number=${caller_id_number}) INLINE EXECUTE sofia/internal/11@pbx.[anonym].net set(caller_id_number=11) 2018-11-10 23:52:59.235663 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [caller_id_number]=[11] Dialplan: sofia/internal/11@pbx.[anonym].net parsing [pbx.[anonym].net->variables] continue=true Dialplan: sofia/internal/11@pbx.[anonym].net Regex (PASS) [variables] () =~ // break=on-false Dialplan: sofia/internal/11@pbx.[anonym].net Action export(origination_callee_id_name=${destination_number}) Dialplan: sofia/internal/11@pbx.[anonym].net Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/11@pbx.[anonym].net parsing [pbx.[anonym].net->call-direction] continue=true Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net ANTI-Action export(call_direction=local) Dialplan: sofia/internal/11@pbx.[anonym].net parsing [pbx.[anonym].net->user_record] continue=true Dialplan: sofia/internal/11@pbx.[anonym].net Regex (PASS) [user_record] () =~ // break=on-false Dialplan: sofia/internal/11@pbx.[anonym].net Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE EXECUTE sofia/internal/11@pbx.[anonym].net set(user_record=) 2018-11-10 23:52:59.275663 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [user_record]=[UNDEF] Dialplan: sofia/internal/11@pbx.[anonym].net Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE EXECUTE sofia/internal/11@pbx.[anonym].net set(from_user_exists=true) 2018-11-10 23:52:59.295664 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [from_user_exists]=[true] Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [user_record] ${call_direction}() =~ /^inbound$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [user_record] ${call_direction}() =~ /^outbound$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [user_record] ${call_direction}() =~ /^local$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_record}) INLINE EXECUTE sofia/internal/11@pbx.[anonym].net set(from_user_record=all) 2018-11-10 23:52:59.315667 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [from_user_record]=[all] Dialplan: sofia/internal/11@pbx.[anonym].net Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (PASS) [user_record] ${from_user_record}(all) =~ /^all$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Action set(record_session=true) INLINE EXECUTE sofia/internal/11@pbx.[anonym].net set(record_session=true) 2018-11-10 23:52:59.335699 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [record_session]=[true] Dialplan: sofia/internal/11@pbx.[anonym].net Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [user_record] ${call_direction}() =~ /^inbound$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^inbound$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [user_record] ${call_direction}() =~ /^outbound$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^outbound$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [user_record] ${call_direction}() =~ /^local$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^local$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Regex (PASS) [user_record] ${record_session}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/11@pbx.[anonym].net Action set(record_path=${recordings_dir}/${domain_name}/archive/${strftime(%Y)}/${strftime(%b)}/${strftime(%d)}) INLINE EXECUTE sofia/internal/11@pbx.[anonym].net set(record_path=/var/lib/freeswitch/recordings/pbx.[anonym].net/archive/2018/Nov/10) 2018-11-10 23:52:59.335699 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [record_path]=[/var/lib/freeswitch/recordings/pbx.[anonym].net/archive/2018/Nov/10] Dialplan: sofia/internal/11@pbx.[anonym].net Action set(record_name=${uuid}.${record_ext}) INLINE EXECUTE sofia/internal/11@pbx.[anonym].net set(record_name=4ef5163f-777a-413d-8ba7-5a983d75f668.wav) 2018-11-10 23:52:59.335699 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [record_name]=[4ef5163f-777a-413d-8ba7-5a983d75f668.wav] Dialplan: sofia/internal/11@pbx.[anonym].net Action set(recording_follow_transfer=true) INLINE EXECUTE sofia/internal/11@pbx.[anonym].net set(recording_follow_transfer=true) 2018-11-10 23:52:59.335699 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [recording_follow_transfer]=[true] Dialplan: sofia/internal/11@pbx.[anonym].net Action set(record_append=true) INLINE EXECUTE sofia/internal/11@pbx.[anonym].net set(record_append=true) 2018-11-10 23:52:59.335699 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [record_append]=[true] Dialplan: sofia/internal/11@pbx.[anonym].net Action set(record_in_progress=true) INLINE EXECUTE sofia/internal/11@pbx.[anonym].net set(record_in_progress=true) 2018-11-10 23:52:59.335699 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [record_in_progress]=[true] Dialplan: sofia/internal/11@pbx.[anonym].net Action set(${uuid_record ${uuid} start ${record_path}/${record_name}}) Dialplan: sofia/internal/11@pbx.[anonym].net parsing [pbx.[anonym].net->redial] continue=true Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [redial] destination_number(0108008080800) =~ /^(redial|\*870)$/ break=on-true Dialplan: sofia/internal/11@pbx.[anonym].net Regex (PASS) [redial] () =~ // break=never Dialplan: sofia/internal/11@pbx.[anonym].net Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/internal/11@pbx.[anonym].net parsing [pbx.[anonym].net->speed_dial] continue=false Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [speed_dial] destination_number(0108008080800) =~ /^\*0(.*)$/ break=on-false Dialplan: sofia/internal/11@pbx.[anonym].net parsing [pbx.[anonym].net->default_caller_id] continue=true Dialplan: sofia/internal/11@pbx.[anonym].net Regex (PASS) [default_caller_id] ${emergency_caller_id_number}() =~ /^$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Action set(emergency_caller_id_name=${default_emergency_caller_id_name}) INLINE EXECUTE sofia/internal/11@pbx.[anonym].net set(emergency_caller_id_name=) 2018-11-10 23:52:59.335699 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [emergency_caller_id_name]=[UNDEF] Dialplan: sofia/internal/11@pbx.[anonym].net Action set(emergency_caller_id_number=${default_emergency_caller_id_number}) INLINE EXECUTE sofia/internal/11@pbx.[anonym].net set(emergency_caller_id_number=) 2018-11-10 23:52:59.335699 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [emergency_caller_id_number]=[UNDEF] Dialplan: sofia/internal/11@pbx.[anonym].net Regex (PASS) [default_caller_id] ${outbound_caller_id_number}() =~ /^$/ break=never Dialplan: sofia/internal/11@pbx.[anonym].net Action set(outbound_caller_id_name=${default_outbound_caller_id_name}) INLINE EXECUTE sofia/internal/11@pbx.[anonym].net set(outbound_caller_id_name=) 2018-11-10 23:52:59.335699 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [outbound_caller_id_name]=[UNDEF] Dialplan: sofia/internal/11@pbx.[anonym].net Action set(outbound_caller_id_number=${default_outbound_caller_id_number}) INLINE EXECUTE sofia/internal/11@pbx.[anonym].net set(outbound_caller_id_number=) 2018-11-10 23:52:59.335699 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [outbound_caller_id_number]=[UNDEF] Dialplan: sofia/internal/11@pbx.[anonym].net parsing [pbx.[anonym].net->49[anonym]156.d] continue=false Dialplan: sofia/internal/11@pbx.[anonym].net Regex (PASS) [49[anonym]156.d] ${user_exists}(false) =~ /false/ break=on-false Dialplan: sofia/internal/11@pbx.[anonym].net Regex (FAIL) [49[anonym]156.d] ${sip_from_user}(11) =~ /12/ break=on-false Dialplan: sofia/internal/11@pbx.[anonym].net parsing [pbx.[anonym].net->+49[anonym]206.01d] continue=false Dialplan: sofia/internal/11@pbx.[anonym].net Regex (PASS) [+49[anonym]206.01d] ${user_exists}(false) =~ /false/ break=on-false Dialplan: sofia/internal/11@pbx.[anonym].net Regex (PASS) [+49[anonym]206.01d] destination_number(0108008080800) =~ /^01(\d+)$/ break=on-false Dialplan: sofia/internal/11@pbx.[anonym].net Action set(sip_h_X-accountcode=${accountcode}) Dialplan: sofia/internal/11@pbx.[anonym].net Action export(call_direction=outbound) Dialplan: sofia/internal/11@pbx.[anonym].net Action unset(call_timeout) Dialplan: sofia/internal/11@pbx.[anonym].net Action set(hangup_after_bridge=true) Dialplan: sofia/internal/11@pbx.[anonym].net Action set(effective_caller_id_name=${outbound_caller_id_name}) Dialplan: sofia/internal/11@pbx.[anonym].net Action set(effective_caller_id_number=${outbound_caller_id_number}) Dialplan: sofia/internal/11@pbx.[anonym].net Action set(inherit_codec=true) Dialplan: sofia/internal/11@pbx.[anonym].net Action set(ignore_display_updates=true) Dialplan: sofia/internal/11@pbx.[anonym].net Action set(callee_id_number=08008080800) Dialplan: sofia/internal/11@pbx.[anonym].net Action set(continue_on_fail=true) Dialplan: sofia/internal/11@pbx.[anonym].net Action set(outbound_prefix=01) Dialplan: sofia/internal/11@pbx.[anonym].net Action bridge(sofia/gateway/737888c4-6119-4b50-9b6d-176732c5fb2d/08008080800) 2018-11-10 23:52:59.335699 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/11@pbx.[anonym].net) State Change CS_ROUTING -> CS_EXECUTE 2018-11-10 23:52:59.335699 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/11@pbx.[anonym].net) State ROUTING going to sleep 2018-11-10 23:52:59.335699 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@pbx.[anonym].net) Running State Change CS_EXECUTE (Cur 1 Tot 1) 2018-11-10 23:52:59.335699 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/11@pbx.[anonym].net) State EXECUTE 2018-11-10 23:52:59.335699 [DEBUG] mod_sofia.c:209 sofia/internal/11@pbx.[anonym].net SOFIA EXECUTE 2018-11-10 23:52:59.335699 [DEBUG] switch_core_state_machine.c:328 sofia/internal/11@pbx.[anonym].net Standard EXECUTE EXECUTE sofia/internal/11@pbx.[anonym].net export(origination_callee_id_name=0108008080800) 2018-11-10 23:52:59.335699 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[0108008080800] EXECUTE sofia/internal/11@pbx.[anonym].net set(RFC2822_DATE=Sat, 10 Nov 2018 23:52:59 +0100) 2018-11-10 23:52:59.335699 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [RFC2822_DATE]=[Sat, 10 Nov 2018 23:52:59 +0100] EXECUTE sofia/internal/11@pbx.[anonym].net export(call_direction=local) 2018-11-10 23:52:59.335699 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[local] 2018-11-10 23:52:59.355691 [INFO] switch_ivr_async.c:2557 Sending early media 2018-11-10 23:52:59.355691 [DEBUG] switch_core_media.c:8511 AUDIO RTP [sofia/internal/11@pbx.[anonym].net] 172.19.50.3 port 18920 -> 172.19.51.21 port 16386 codec: 8 ms: 20 2018-11-10 23:52:59.355691 [DEBUG] switch_rtp.c:4300 Starting timer [soft] 160 bytes per 20ms send 1303 bytes to udp/[172.19.51.21]:5060 at 23:52:59.358752: ------------------------------------------------------------------------ NOTIFY sip:11@172.19.51.21:5060;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 172.19.50.3;rport;branch=z9hG4bK9c79mgpBya7eB Max-Forwards: 70 From: ;tag=ldmvNmA2D3ym To: ;tag=1898982082 Call-ID: d5abfc275ee75b015bde0090332616fc@2 CSeq: 1356458951 NOTIFY Contact: User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Event: presence Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=20 Content-Type: application/pidf+xml Content-Length: 505 open Call 0108008080800 ------------------------------------------------------------------------ send 1304 bytes to udp/[172.19.51.21]:5060 at 23:52:59.359834: ------------------------------------------------------------------------ NOTIFY sip:11@172.19.51.21:5060;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 172.19.50.3;rport;branch=z9hG4bKap02pB7eUKX1p Max-Forwards: 70 From: ;tag=G3MK4pPAsqMh To: ;tag=4241842626 Call-ID: f22da23761e75b01897f0090332616fc@2 CSeq: 1356458952 NOTIFY Contact: User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Event: presence 2018-11-10 23:52:59.355691 [INFO] switch_core_media.c:8690 Activating Audio ICE Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=100 Content-Type: application/pidf+xml Content-Length: 505 2018-11-10 23:52:59.355691 [NOTICE] switch_rtp.c:4799 Activating RTP audio ICE: w7Ce:S6hEQ7A2aexCjyqk 172.19.51.21:16386 open 2018-11-10 23:52:59.355691 [DEBUG] switch_core_media.c:8815 sofia/internal/11@pbx.[anonym].net Set 2833 dtmf send payload to 101 2018-11-10 23:52:59.355691 [DEBUG] switch_core_media.c:8822 sofia/internal/11@pbx.[anonym].net Set 2833 dtmf receive payload to 101 Call 0108008080800 ------------------------------------------------------------------------ 2018-11-10 23:52:59.355691 [DEBUG] switch_core_media.c:8845 sofia/internal/11@pbx.[anonym].net Set rtp dtmf delay to 40 2018-11-10 23:52:59.355691 [DEBUG] switch_core_media.c:8851 Set comfort noise payload to 13 2018-11-10 23:52:59.355691 [DEBUG] mod_sofia.c:2514 Ring SDP: v=0 o=FreeSWITCH 1541871459 1541871460 IN IP4 172.19.50.3 s=FreeSWITCH c=IN IP4 172.19.50.3 t=0 0 a=msid-semantic: WMS v5PF46BjpB7TzUKGtGYbVTZ5ldOFCfaX m=audio 18920 RTP/AVP 8 101 13 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 a=sendrecv a=ice-ufrag:S6hEQ7A2aexCjyqk a=ice-pwd:fJfStkKFnmh9ypggmnK3kaVl a=candidate:3769281485 1 udp 659136 172.19.50.3 18920 typ host generation 0 a=candidate:3769281485 2 udp 659135 172.19.50.3 18921 typ host generation 0 a=end-of-candidates a=ssrc:1072399891 cname:aQt5MUf2mcLLWmig a=ssrc:1072399891 msid:v5PF46BjpB7TzUKGtGYbVTZ5ldOFCfaX a0 a=ssrc:1072399891 mslabel:v5PF46BjpB7TzUKGtGYbVTZ5ldOFCfaX a=ssrc:1072399891 label:v5PF46BjpB7TzUKGtGYbVTZ5ldOFCfaXa0 2018-11-10 23:52:59.355691 [NOTICE] mod_sofia.c:2517 Pre-Answer sofia/internal/11@pbx.[anonym].net! recv 353 bytes from udp/[172.19.51.21]:5060 at 23:52:59.362385: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.19.50.3;rport;branch=z9hG4bK9c79mgpBya7eB;received=172.19.50.3 From: ;tag=ldmvNmA2D3ym To: ;tag=1898982082 Call-ID: d5abfc275ee75b015bde0090332616fc@2 CSeq: 1356458951 NOTIFY Content-Length: 0 Server: (innovaphone IP240/12r1 sr26 [12.1257/121257/301]) ------------------------------------------------------------------------ 2018-11-10 23:52:59.355691 [DEBUG] switch_channel.c:3482 (sofia/internal/11@pbx.[anonym].net) Callstate Change RINGING -> EARLY send 1625 bytes to udp/[172.19.51.21]:5060 at 23:52:59.366524: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 172.19.51.21:5060;branch=z9hG4bK-B89D2272;rport=5060 From: ;tag=4241842629 To: ;tag=c0cZ0e0SUSKNK Call-ID: fa59464a61e75b01907f0090332616fc@5 CSeq: 1286550376 INVITE Contact: User-Agent: FreeSWITCH Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 760 P-Asserted-Identity: "0108008080800" v=0 o=FreeSWITCH 1541871459 1541871460 IN IP4 172.19.50.3 s=FreeSWITCH c=IN IP4 172.19.50.3 t=0 0 a=msid-semantic: WMS v5PF46BjpB7TzUKGtGYbVTZ5ldOFCfaX m=audio 18920 RTP/AVP 8 101 13 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 a=ice-ufrag:S6hEQ7A2aexCjyqk a=ice-pwd:fJfStkKFnmh9ypggmnK3kaVl a=candidate:3769281485 1 udp 659136 172.19.50.3 18920 typ host generation 0 a=candidate:3769281485 2 udp 659135 172.19.50.3 18921 typ host generation 0 a=end-of-candidates a=ssrc:1072399891 cname:aQt5MUf2mcLLWmig a=ssrc:1072399891 msid:v5PF46BjpB7TzUKGtGYbVTZ5ldOFCfaX a0 a=ssrc:1072399891 mslabel:v5PF46BjpB7TzUKGtGYbVTZ5ldOFCfaX a=ssrc:1072399891 label:v5PF46BjpB7TzUKGtGYbVTZ5ldOFCfaXa0 ------------------------------------------------------------------------ recv 353 bytes from udp/[172.19.51.21]:5060 at 23:52:59.367778: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.19.50.3;rport;branch=z9hG4bKap02pB7eUKX1p;received=172.19.50.3 From: ;tag=G3MK4pPAsqMh To: ;tag=4241842626 Call-ID: f22da23761e75b01897f0090332616fc@2 CSeq: 1356458952 NOTIFY Content-Length: 0 Server: (innovaphone IP240/12r1 sr26 [12.1257/121257/301]) ------------------------------------------------------------------------ 2018-11-10 23:52:59.375660 [DEBUG] switch_ivr_async.c:1319 Record session sample rate: 8000 -> 8000 2018-11-10 23:52:59.375660 [DEBUG] switch_core_media_bug.c:962 Attaching BUG to sofia/internal/11@pbx.[anonym].net 2018-11-10 23:52:59.375660 [DEBUG] sofia.c:7291 Channel sofia/internal/11@pbx.[anonym].net entering state [early][183] EXECUTE sofia/internal/11@pbx.[anonym].net set(+OK Success ) 2018-11-10 23:52:59.375660 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [+OK Success ]=[UNDEF] EXECUTE sofia/internal/11@pbx.[anonym].net hash(insert/pbx.[anonym].net-last_dial/11/0108008080800) EXECUTE sofia/internal/11@pbx.[anonym].net set(sip_h_X-accountcode=) 2018-11-10 23:52:59.375660 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [sip_h_X-accountcode]=[UNDEF] EXECUTE sofia/internal/11@pbx.[anonym].net export(call_direction=outbound) 2018-11-10 23:52:59.375660 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[outbound] EXECUTE sofia/internal/11@pbx.[anonym].net unset(call_timeout) 2018-11-10 23:52:59.375660 [DEBUG] mod_dptools.c:1743 UNSET [call_timeout] EXECUTE sofia/internal/11@pbx.[anonym].net set(hangup_after_bridge=true) 2018-11-10 23:52:59.375660 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [hangup_after_bridge]=[true] EXECUTE sofia/internal/11@pbx.[anonym].net set(effective_caller_id_name=) 2018-11-10 23:52:59.375660 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [effective_caller_id_name]=[UNDEF] EXECUTE sofia/internal/11@pbx.[anonym].net set(effective_caller_id_number=) 2018-11-10 23:52:59.375660 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [effective_caller_id_number]=[UNDEF] EXECUTE sofia/internal/11@pbx.[anonym].net set(inherit_codec=true) 2018-11-10 23:52:59.375660 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [inherit_codec]=[true] EXECUTE sofia/internal/11@pbx.[anonym].net set(ignore_display_updates=true) 2018-11-10 23:52:59.375660 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [ignore_display_updates]=[true] EXECUTE sofia/internal/11@pbx.[anonym].net set(callee_id_number=08008080800) 2018-11-10 23:52:59.375660 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [callee_id_number]=[08008080800] EXECUTE sofia/internal/11@pbx.[anonym].net set(continue_on_fail=true) 2018-11-10 23:52:59.375660 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [continue_on_fail]=[true] EXECUTE sofia/internal/11@pbx.[anonym].net set(outbound_prefix=01) 2018-11-10 23:52:59.375660 [DEBUG] mod_dptools.c:1598 SET sofia/internal/11@pbx.[anonym].net [outbound_prefix]=[01] EXECUTE sofia/internal/11@pbx.[anonym].net bridge(sofia/gateway/737888c4-6119-4b50-9b6d-176732c5fb2d/08008080800) 2018-11-10 23:52:59.395667 [DEBUG] switch_channel.c:1250 sofia/internal/11@pbx.[anonym].net EXPORTING[export_vars] [domain_name]=[pbx.[anonym].net] to event 2018-11-10 23:52:59.395667 [DEBUG] switch_channel.c:1250 sofia/internal/11@pbx.[anonym].net EXPORTING[export_vars] [origination_callee_id_name]=[0108008080800] to event 2018-11-10 23:52:59.395667 [DEBUG] switch_channel.c:1250 sofia/internal/11@pbx.[anonym].net EXPORTING[export_vars] [call_direction]=[outbound] to event 2018-11-10 23:52:59.395667 [DEBUG] switch_channel.c:1250 sofia/internal/11@pbx.[anonym].net EXPORTING[export_vars] [call_direction]=[outbound] to event 2018-11-10 23:52:59.395667 [DEBUG] switch_ivr_originate.c:2204 Parsing global variables 2018-11-10 23:52:59.395667 [NOTICE] switch_channel.c:1104 New Channel sofia/external/08008080800 [bf9b0974-f3f7-48d8-86da-9e79668319fb] 2018-11-10 23:52:59.395667 [DEBUG] mod_sofia.c:5028 (sofia/external/08008080800) State Change CS_NEW -> CS_INIT 2018-11-10 23:52:59.395667 [DEBUG] switch_core_state_machine.c:584 (sofia/external/08008080800) Running State Change CS_INIT (Cur 2 Tot 2) 2018-11-10 23:52:59.395667 [DEBUG] switch_core_state_machine.c:627 (sofia/external/08008080800) State INIT 2018-11-10 23:52:59.395667 [DEBUG] mod_sofia.c:93 sofia/external/08008080800 SOFIA INIT 2018-11-10 23:52:59.395667 [DEBUG] sofia_glue.c:1299 sofia/external/08008080800 sending invite version: 1.8.2 -3-a98a958ac3 64bit Local SDP: v=0 o=FreeSWITCH 1541866197 1541866198 IN IP4 172.19.50.3 s=FreeSWITCH c=IN IP4 172.19.50.3 t=0 0 m=audio 24182 RTP/AVP 8 101 13 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 a=sendrecv 2018-11-10 23:52:59.395667 [DEBUG] switch_core_state_machine.c:40 sofia/external/08008080800 Standard INIT 2018-11-10 23:52:59.395667 [DEBUG] switch_core_state_machine.c:48 (sofia/external/08008080800) State Change CS_INIT -> CS_ROUTING 2018-11-10 23:52:59.395667 [DEBUG] switch_core_state_machine.c:627 (sofia/external/08008080800) State INIT going to sleep 2018-11-10 23:52:59.395667 [DEBUG] switch_core_state_machine.c:584 (sofia/external/08008080800) Running State Change CS_ROUTING (Cur 2 Tot 2) 2018-11-10 23:52:59.395667 [DEBUG] sofia.c:7291 Channel sofia/external/08008080800 entering state [calling][0] 2018-11-10 23:52:59.395667 [DEBUG] switch_core_state_machine.c:643 (sofia/external/08008080800) State ROUTING 2018-11-10 23:52:59.395667 [DEBUG] mod_sofia.c:154 sofia/external/08008080800 SOFIA ROUTING 2018-11-10 23:52:59.395667 [DEBUG] switch_ivr_originate.c:67 (sofia/external/08008080800) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2018-11-10 23:52:59.395667 [DEBUG] switch_core_state_machine.c:643 (sofia/external/08008080800) State ROUTING going to sleep 2018-11-10 23:52:59.395667 [DEBUG] switch_core_state_machine.c:584 (sofia/external/08008080800) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 2) 2018-11-10 23:52:59.395667 [DEBUG] switch_core_state_machine.c:662 (sofia/external/08008080800) State CONSUME_MEDIA 2018-11-10 23:52:59.395667 [DEBUG] switch_core_state_machine.c:662 (sofia/external/08008080800) State CONSUME_MEDIA going to sleep 2018-11-10 23:52:59.395667 [WARNING] switch_rtp.c:974 sofia/internal/11@pbx.[anonym].net got audio stun binding response 487 2018-11-10 23:52:59.395667 [WARNING] switch_rtp.c:985 audio STUN Changing role to CONTROLLED send 1127 bytes to udp/[217.0.27.32]:5060 at 23:52:59.411318: ------------------------------------------------------------------------ INVITE sip:08008080800@tel.t-online.de SIP/2.0 Via: SIP/2.0/UDP 172.19.50.3:5080;rport;branch=z9hG4bKy3Np48ZBt0vmK Max-Forwards: 62 From: "11" ;tag=t2eppXypav9yK To: Call-ID: 3657973f-5fde-1237-1193-000db9478a88 CSeq: 130609125 INVITE Contact: User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 242 P-Sig-Options: Sending-Complete,bc=038090a3 X-FS-Support: update_display,send_info Remote-Party-ID: "11" ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1541866197 1541866198 IN IP4 172.19.50.3 s=FreeSWITCH c=IN IP4 172.19.50.3 t=0 0 m=audio 24182 RTP/AVP 8 101 13 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 ------------------------------------------------------------------------ 2018-11-10 23:52:59.415691 [DEBUG] switch_ivr_async.c:1608 No silence detection configured; assuming start of speech recv 520 bytes from udp/[217.0.27.32]:5060 at 23:52:59.526494: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required 02035034C Via: SIP/2.0/UDP 172.19.50.3:5080;received=172.19.50.3;rport=5080;branch=z9hG4bKy3Np48ZBt0vmK To: ;tag=h7g4Esbg_c903247e015827eb90d40c3d01b3c836 From: "11" ;tag=t2eppXypav9yK Call-ID: 3657973f-5fde-1237-1193-000db9478a88 CSeq: 130609125 INVITE Content-Length: 0 Proxy-Authenticate: Digest nonce="F048CDD55761E75B00000000CFF40400",realm="tel.t-online.de",algorithm=MD5,qop="auth",stale=true ------------------------------------------------------------------------ send 372 bytes to udp/[217.0.27.32]:5060 at 23:52:59.527072: ------------------------------------------------------------------------ ACK sip:08008080800@tel.t-online.de SIP/2.0 Via: SIP/2.0/UDP 172.19.50.3:5080;rport;branch=z9hG4bKy3Np48ZBt0vmK Max-Forwards: 62 From: "11" ;tag=t2eppXypav9yK To: ;tag=h7g4Esbg_c903247e015827eb90d40c3d01b3c836 Call-ID: 3657973f-5fde-1237-1193-000db9478a88 CSeq: 130609125 ACK Content-Length: 0 ------------------------------------------------------------------------ send 1402 bytes to udp/[217.0.27.32]:5060 at 23:52:59.528221: ------------------------------------------------------------------------ INVITE sip:08008080800@tel.t-online.de SIP/2.0 Via: SIP/2.0/UDP 172.19.50.3:5080;rport;branch=z9hG4bKZcFF63gFQ9j7e Max-Forwards: 62 From: "11" ;tag=t2eppXypav9yK To: Call-ID: 3657973f-5fde-1237-1193-000db9478a88 CSeq: 130609126 INVITE Contact: User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Proxy-Authorization: Digest username="551124935083", realm="tel.t-online.de", nonce="F048CDD55761E75B00000000CFF40400", cnonce="NmqTBV/eEjeTEQANuUeKiA", algorithm=MD5, uri="sip:08008080800@tel.t-online.de", response="e69e104546ed1892e1997b18dcc9bd29", qop=auth, nc=00000001 Content-Type: application/sdp Content-Disposition: session Content-Length: 242 P-Sig-Options: Sending-Complete,bc=038090a3 X-FS-Support: update_display,send_info Remote-Party-ID: "11" ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1541866197 1541866198 IN IP4 172.19.50.3 s=FreeSWITCH c=IN IP4 172.19.50.3 t=0 0 m=audio 24182 RTP/AVP 8 101 13 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 ------------------------------------------------------------------------ 2018-11-10 23:52:59.516166 [DEBUG] sofia.c:7291 Channel sofia/external/08008080800 entering state [calling][0] recv 312 bytes from udp/[217.0.27.32]:5060 at 23:52:59.740881: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 172.19.50.3:5080;received=172.19.50.3;rport=5080;branch=z9hG4bKZcFF63gFQ9j7e To: From: "11" ;tag=t2eppXypav9yK Call-ID: 3657973f-5fde-1237-1193-000db9478a88 CSeq: 130609126 INVITE Content-Length: 0 ------------------------------------------------------------------------ recv 851 bytes from udp/[217.0.27.32]:5060 at 23:52:59.814986: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 172.19.50.3:5080;received=172.19.50.3;rport=5080;branch=z9hG4bKZcFF63gFQ9j7e To: ;tag=h7g4Esbg_p65555t1541890379m568871c371372549s1_1415273537-177558755 From: "11" ;tag=t2eppXypav9yK Call-ID: 3657973f-5fde-1237-1193-000db9478a88 CSeq: 130609126 INVITE Contact: Record-Route: P-Early-Media: sendonly Supported: timer Content-Type: application/sdp Content-Length: 217 Allow: UPDATE, PRACK, OPTIONS, BYE, ACK, CANCEL, INVITE, REGISTER v=0 o=- 220059467 1415471457 IN IP4 217.0.27.32 s=SIP Call c=IN IP4 217.0.6.52 t=0 0 m=audio 29556 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv ------------------------------------------------------------------------ 2018-11-10 23:52:59.815679 [DEBUG] sofia.c:7291 Channel sofia/external/08008080800 entering state [proceeding][183] 2018-11-10 23:52:59.815679 [DEBUG] sofia.c:7301 Remote SDP: v=0 o=- 220059467 1415471457 IN IP4 217.0.27.32 s=SIP Call c=IN IP4 217.0.6.52 t=0 0 m=audio 29556 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 2018-11-10 23:52:59.815679 [NOTICE] sofia.c:7304 Pre-Answer sofia/external/08008080800! 2018-11-10 23:52:59.815679 [DEBUG] switch_channel.c:3482 (sofia/external/08008080800) Callstate Change DOWN -> EARLY 2018-11-10 23:52:59.815679 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-11-10 23:52:59.815679 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2018-11-10 23:52:59.815679 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000 2018-11-10 23:52:59.815679 [DEBUG] switch_core_media.c:3781 Set Codec sofia/external/08008080800 PCMA/8000 20 ms 160 samples 64000 bits 1 channels 2018-11-10 23:52:59.815679 [DEBUG] switch_core_codec.c:111 sofia/external/08008080800 Original read codec set to PCMA:8 2018-11-10 23:52:59.815679 [DEBUG] switch_core_media.c:5737 Set telephone-event payload to 101@8000 2018-11-10 23:52:59.815679 [DEBUG] switch_core_media.c:5795 sofia/external/08008080800 Set 2833 dtmf send payload to 101 recv payload to 101 2018-11-10 23:52:59.815679 [DEBUG] switch_core_media.c:8511 AUDIO RTP [sofia/external/08008080800] 172.19.50.3 port 24182 -> 217.0.6.52 port 29556 codec: 8 ms: 20 2018-11-10 23:52:59.815679 [DEBUG] switch_rtp.c:4300 Starting timer [soft] 160 bytes per 20ms 2018-11-10 23:52:59.815679 [DEBUG] switch_core_media.c:8815 sofia/external/08008080800 Set 2833 dtmf send payload to 101 2018-11-10 23:52:59.815679 [DEBUG] switch_core_media.c:8822 sofia/external/08008080800 Set 2833 dtmf receive payload to 101 2018-11-10 23:52:59.815679 [DEBUG] switch_core_media.c:8845 sofia/external/08008080800 Set rtp dtmf delay to 40 2018-11-10 23:52:59.835677 [DEBUG] switch_ivr_originate.c:3798 Originate Resulted in Success: [sofia/external/08008080800] 2018-11-10 23:52:59.835677 [DEBUG] switch_ivr_bridge.c:1782 (sofia/external/08008080800) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2018-11-10 23:52:59.835677 [DEBUG] switch_core_state_machine.c:584 (sofia/external/08008080800) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 2) 2018-11-10 23:52:59.835677 [DEBUG] switch_core_state_machine.c:653 (sofia/external/08008080800) State EXCHANGE_MEDIA 2018-11-10 23:52:59.835677 [DEBUG] mod_sofia.c:645 SOFIA EXCHANGE_MEDIA 2018-11-10 23:52:59.875661 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed. recv 1120 bytes from udp/[217.0.27.32]:5060 at 23:53:04.615229: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.19.50.3:5080;received=172.19.50.3;rport=5080;branch=z9hG4bKZcFF63gFQ9j7e To: ;tag=h7g4Esbg_p65555t1541890379m568871c371372549s1_1415273537-177558755 From: "11" ;tag=t2eppXypav9yK Call-ID: 3657973f-5fde-1237-1193-000db9478a88 CSeq: 130609126 INVITE Contact: ;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mmtel";transport=udp Record-Route: Session-Expires: 1800;refresher=uas Supported: timer Content-Type: application/sdp Content-Length: 217 Session-ID: 36fc5134af312d69d731ebd6afccb1fd Authentication-Info: qop=auth,rspauth="ed2405023cb4f949fe39f30b77a95e56",cnonce="NmqTBV/eEjeTEQANuUeKiA",nc=00000001 Allow: REGISTER, REFER, NOTIFY, SUBSCRIBE, INFO, PRACK, UPDATE, INVITE, ACK, OPTIONS, CANCEL, BYE v=0 o=- 220059467 1415471457 IN IP4 217.0.27.32 s=SIP Call c=IN IP4 217.0.6.52 t=0 0 m=audio 29556 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv ------------------------------------------------------------------------ 2018-11-10 23:53:04.615671 [DEBUG] sofia.c:7291 Channel sofia/external/08008080800 entering state [completing][200] 2018-11-10 23:53:04.615671 [DEBUG] sofia.c:7298 Duplicate SDP v=0 o=- 220059467 1415471457 IN IP4 217.0.27.32 s=SIP Call c=IN IP4 217.0.6.52 t=0 0 m=audio 29556 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 send 846 bytes to udp/[217.0.27.32]:5060 at 23:53:04.628167: ------------------------------------------------------------------------ ACK sip:sgc_c@217.0.27.32;transport=udp SIP/2.0 Via: SIP/2.0/UDP 172.19.50.3:5080;rport;branch=z9hG4bK0N877y1jmj9Sa Route: Max-Forwards: 70 From: "11" ;tag=t2eppXypav9yK To: ;tag=h7g4Esbg_p65555t1541890379m568871c371372549s1_1415273537-177558755 Call-ID: 3657973f-5fde-1237-1193-000db9478a88 CSeq: 130609126 ACK Contact: Proxy-Authorization: Digest username="551124935083", realm="tel.t-online.de", nonce="F048CDD55761E75B00000000CFF40400", cnonce="NmqTBV/eEjeTEQANuUeKiA", algorithm=MD5, uri="sip:08008080800@tel.t-online.de", response="e69e104546ed1892e1997b18dcc9bd29", qop=auth, nc=00000001 Content-Length: 0 ------------------------------------------------------------------------ 2018-11-10 23:53:04.635681 [DEBUG] sofia.c:7291 Channel sofia/external/08008080800 entering state [ready][200] 2018-11-10 23:53:04.635681 [NOTICE] sofia.c:8370 Channel [sofia/external/08008080800] has been answered 2018-11-10 23:53:04.635681 [DEBUG] switch_channel.c:3781 (sofia/external/08008080800) Callstate Change EARLY -> ACTIVE 2018-11-10 23:53:04.655679 [DEBUG] switch_core_media.c:8494 Audio params are unchanged for sofia/internal/11@pbx.[anonym].net. 2018-11-10 23:53:04.655679 [DEBUG] mod_sofia.c:881 Local SDP sofia/internal/11@pbx.[anonym].net: v=0 o=FreeSWITCH 1541871459 1541871461 IN IP4 172.19.50.3 s=FreeSWITCH c=IN IP4 172.19.50.3 t=0 0 a=msid-semantic: WMS v5PF46BjpB7TzUKGtGYbVTZ5ldOFCfaX m=audio 18920 RTP/AVP 8 101 13 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 a=sendrecv a=ice-ufrag:S6hEQ7A2aexCjyqk a=ice-pwd:fJfStkKFnmh9ypggmnK3kaVl a=candidate:7066243327 1 udp 659136 172.19.50.3 18920 typ host generation 0 a=candidate:7066243327 2 udp 659135 172.19.50.3 18921 typ host generation 0 a=end-of-candidates a=ssrc:1072399891 cname:aQt5MUf2mcLLWmig a=ssrc:1072399891 msid:v5PF46BjpB7TzUKGtGYbVTZ5ldOFCfaX a0 a=ssrc:1072399891 mslabel:v5PF46BjpB7TzUKGtGYbVTZ5ldOFCfaX a=ssrc:1072399891 label:v5PF46BjpB7TzUKGtGYbVTZ5ldOFCfaXa0 send 1584 bytes to udp/[172.19.51.21]:5060 at 23:53:04.661305: ------------------------------------------------------------------------ SIP/2.0 200 OK 2018-11-10 23:53:04.655679 [NOTICE] switch_ivr_bridge.c:736 Channel [sofia/internal/11@pbx.[anonym].net] has been answered Via: SIP/2.0/UDP 172.19.51.21:5060;branch=z9hG4bK-B89D2272;rport=5060 From: ;tag=4241842629 To: ;tag=c0cZ0e0SUSKNK Call-ID: fa59464a61e75b01907f0090332616fc@5 CSeq: 1286550376 INVITE Contact: User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 760 P-Asserted-Identity: "0108008080800" v=0 o=FreeSWITCH 1541871459 1541871460 IN IP4 172.19.50.3 s=FreeSWITCH c=IN IP4 172.19.50.3 t=0 0 a=msid-semantic: WMS v5PF46BjpB7TzUKGtGYbVTZ5ldOFCfaX m=audio 18920 RTP/AVP 8 101 13 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 a=ice-ufrag:S6hEQ7A2aexCjyqk a=ice-pwd:fJfStkKFnmh9ypggmnK3kaVl a=candidate:3769281485 1 udp 659136 172.19.50.3 18920 typ host generation 0 a=candidate:3769281485 2 udp 659135 172.19.50.3 18921 typ host generation 0 a=end-of-candidates a=ssrc:1072399891 cname:aQt5MUf2mcLLWmig a=ssrc:1072399891 msid:v5PF46BjpB7TzUKGtGYbVTZ5ldOFCfaX a0 a=ssrc:1072399891 mslabel:v5PF46BjpB7TzUKGtGYbVTZ5ldOFCfaX a=ssrc:1072399891 label:v5PF46BjpB7TzUKGtGYbVTZ5ldOFCfaXa0 ------------------------------------------------------------------------ 2018-11-10 23:53:04.655679 [DEBUG] switch_channel.c:3781 (sofia/internal/11@pbx.[anonym].net) Callstate Change EARLY -> ACTIVE 2018-11-10 23:53:04.655679 [DEBUG] sofia.c:7291 Channel sofia/internal/11@pbx.[anonym].net entering state [completed][200] send 1301 bytes to udp/[172.19.51.21]:5060 at 23:53:04.670768: ------------------------------------------------------------------------ NOTIFY sip:11@172.19.51.21:5060;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 172.19.50.3;rport;branch=z9hG4bKBZSUr6QjrvKmj Max-Forwards: 70 From: ;tag=ldmvNmA2D3ym To: ;tag=1898982082 Call-ID: d5abfc275ee75b015bde0090332616fc@2 CSeq: 1356459201 NOTIFY Contact: User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Event: presence Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=15 Content-Type: application/pidf+xml Content-Length: 503 open Talk 08008080800 ------------------------------------------------------------------------ recv 662 bytes from udp/[172.19.51.21]:5060 at 23:53:04.671330: ------------------------------------------------------------------------ ACK sip:0108008080800@172.19.50.3:5060;transport=udp SIP/2.0 Proxy-Authorization: Digest username="11",realm="pbx.[anonym].net",nonce="63e024d3-63ce-40e6-96e4-609a5ba18097",response="f933176b57b576d0b597e4b3c45fcc20",uri="sip:0108008080800@pbx.[anonym].net;user=phone",qop=auth,cnonce="00039f9680560c34",nc=00000001,algorithm=MD5 Via: SIP/2.0/UDP 172.19.51.21:5060;branch=z9hG4bK-B89D2273;rport From: ;tag=4241842629 To: ;tag=c0cZ0e0SUSKNK Call-ID: fa59464a61e75b01907f0090332616fc@5 CSeq: 1286550376 ACK Contact: Content-Length: 0 Max-Forwards: 70 ------------------------------------------------------------------------ send 1301 bytes to udp/[172.19.51.21]:5060 at 23:53:04.671878: ------------------------------------------------------------------------ NOTIFY sip:11@172.19.51.21:5060;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 172.19.50.3;rport;branch=z9hG4bKc8jmt18NN596D Max-Forwards: 70 From: ;tag=G3MK4pPAsqMh To: ;tag=4241842626 Call-ID: f22da23761e75b01897f0090332616fc@2 CSeq: 1356459202 NOTIFY Contact: User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Event: presence Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=95 Content-Type: application/pidf+xml Content-Length: 503 open Talk 08008080800 ------------------------------------------------------------------------ recv 353 bytes from udp/[172.19.51.21]:5060 at 23:53:04.674409: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.19.50.3;rport;branch=z9hG4bKBZSUr6QjrvKmj;received=172.19.50.3 From: ;tag=ldmvNmA2D3ym To: ;tag=1898982082 Call-ID: d5abfc275ee75b015bde0090332616fc@2 CSeq: 1356459201 NOTIFY Content-Length: 0 Server: (innovaphone IP240/12r1 sr26 [12.1257/121257/301]) ------------------------------------------------------------------------ recv 353 bytes from udp/[172.19.51.21]:5060 at 23:53:04.677605: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.19.50.3;rport;branch=z9hG4bKc8jmt18NN596D;received=172.19.50.3 From: ;tag=G3MK4pPAsqMh To: ;tag=4241842626 Call-ID: f22da23761e75b01897f0090332616fc@2 CSeq: 1356459202 NOTIFY Content-Length: 0 Server: (innovaphone IP240/12r1 sr26 [12.1257/121257/301]) ------------------------------------------------------------------------ 2018-11-10 23:53:04.675674 [DEBUG] sofia.c:7291 Channel sofia/internal/11@pbx.[anonym].net entering state [ready][200] 2018-11-10 23:53:04.695681 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed. recv 671 bytes from udp/[172.19.51.21]:5060 at 23:53:09.468580: ------------------------------------------------------------------------ BYE sip:0108008080800@172.19.50.3:5060;transport=udp SIP/2.0 Proxy-Authorization: Digest username="11",realm="pbx.[anonym].net",nonce="63e024d3-63ce-40e6-96e4-609a5ba18097",response="5b30bc0859ac48f46dcaee45584f6ac3",uri="sip:0108008080800@pbx.[anonym].net;user=phone",qop=auth,cnonce="00039f9680560c34",nc=00000002,algorithm=MD5 Via: SIP/2.0/UDP 172.19.51.21:5060;branch=z9hG4bK-B89D2274;rport From: ;tag=4241842629 To: ;tag=c0cZ0e0SUSKNK Call-ID: fa59464a61e75b01907f0090332616fc@5 CSeq: 1286550377 BYE Content-Length: 0 Max-Forwards: 70 Reason: Q.850;cause=34;text="No circuit/channel available" ------------------------------------------------------------------------ 2018-11-10 23:53:09.475673 [NOTICE] sofia.c:1079 Hangup sofia/internal/11@pbx.[anonym].net [CS_EXECUTE] [NORMAL_CIRCUIT_CONGESTION] send 456 bytes to udp/[172.19.51.21]:5060 at 23:53:09.484055: ------------------------------------------------------------------------ 2018-11-10 23:53:09.475673 [DEBUG] switch_ivr_bridge.c:825 sofia/internal/11@pbx.[anonym].net ending bridge by request from write function SIP/2.0 200 OK Via: SIP/2.0/UDP 172.19.51.21:5060;branch=z9hG4bK-B89D2274;rport=5060 From: ;tag=4241842629 To: ;tag=c0cZ0e0SUSKNK Call-ID: fa59464a61e75b01907f0090332616fc@5 CSeq: 1286550377 BYE User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2018-11-10 23:53:09.475673 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/external/08008080800] 2018-11-10 23:53:09.475673 [NOTICE] switch_ivr_bridge.c:1034 Hangup sofia/external/08008080800 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2018-11-10 23:53:09.475673 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/internal/11@pbx.[anonym].net] 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:653 (sofia/external/08008080800) State EXCHANGE_MEDIA going to sleep 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:584 (sofia/external/08008080800) Running State Change CS_HANGUP (Cur 2 Tot 2) 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:847 (sofia/external/08008080800) Callstate Change ACTIVE -> HANGUP 2018-11-10 23:53:09.475673 [DEBUG] switch_ivr_bridge.c:1881 sofia/external/08008080800 skip receive message [TRANSFER] (channel is hungup already) 2018-11-10 23:53:09.475673 [DEBUG] switch_ivr_bridge.c:1884 sofia/internal/11@pbx.[anonym].net skip receive message [TRANSFER] (channel is hungup already) 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:849 (sofia/external/08008080800) State HANGUP 2018-11-10 23:53:09.475673 [DEBUG] mod_sofia.c:443 sofia/external/08008080800 Overriding SIP cause 480 with 200 from the other leg 2018-11-10 23:53:09.475673 [DEBUG] mod_sofia.c:449 Channel sofia/external/08008080800 hanging up, cause: NORMAL_CLEARING 2018-11-10 23:53:09.475673 [DEBUG] mod_sofia.c:502 Sending BYE to sofia/external/08008080800 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:60 sofia/external/08008080800 Standard HANGUP, cause: NORMAL_CLEARING 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:849 (sofia/external/08008080800) State HANGUP going to sleep 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:619 (sofia/external/08008080800) State Change CS_HANGUP -> CS_REPORTING 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:584 (sofia/external/08008080800) Running State Change CS_REPORTING (Cur 2 Tot 2) 2018-11-10 23:53:09.475673 [DEBUG] switch_core_session.c:2886 sofia/internal/11@pbx.[anonym].net skip receive message [PHONE_EVENT] (channel is hungup already) 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/11@pbx.[anonym].net) State EXECUTE going to sleep 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@pbx.[anonym].net) Running State Change CS_HANGUP (Cur 2 Tot 2) send 931 bytes to udp/[217.0.27.32]:5060 at 23:53:09.488555: ------------------------------------------------------------------------ BYE sip:sgc_c@217.0.27.32;transport=udp SIP/2.0 Via: SIP/2.0/UDP 172.19.50.3:5080;rport;branch=z9hG4bK1y109SjpHUZcp Route: Max-Forwards: 70 From: "11" ;tag=t2eppXypav9yK To: ;tag=h7g4Esbg_p65555t1541890379m568871c371372549s1_1415273537-177558755 Call-ID: 3657973f-5fde-1237-1193-000db9478a88 CSeq: 130609127 BYE User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Proxy-Authorization: Digest username="551124935083", realm="tel.t-online.de", nonce="F048CDD55761E75B00000000CFF40400", cnonce="NmqTBV/eEjeTEQANuUeKiA", algorithm=MD5, uri="sip:sgc_c@217.0.27.32;transport=udp", response="24f29709ae4baee6fcbc05ed281915e7", qop=auth, nc=00000002 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:935 (sofia/external/08008080800) State REPORTING Reason: Q.850;cause=34;text="No circuit/channel available" Content-Length: 0 ------------------------------------------------------------------------ 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:174 sofia/external/08008080800 Standard REPORTING, cause: NORMAL_CLEARING 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:935 (sofia/external/08008080800) State REPORTING going to sleep 2018-11-10 23:53:09.475673 [DEBUG] switch_ivr_async.c:1413 Stop recording file /var/lib/freeswitch/recordings/pbx.[anonym].net/archive/2018/Nov/10/4ef5163f-777a-413d-8ba7-5a983d75f668.wav 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:610 (sofia/external/08008080800) State Change CS_REPORTING -> CS_DESTROY 2018-11-10 23:53:09.475673 [DEBUG] switch_core_session.c:1714 Session 2 (sofia/external/08008080800) Locked, Waiting on external entities 2018-11-10 23:53:09.475673 [NOTICE] switch_core_session.c:1732 Session 2 (sofia/external/08008080800) Ended 2018-11-10 23:53:09.475673 [NOTICE] switch_core_session.c:1736 Close Channel sofia/external/08008080800 [CS_DESTROY] 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:738 (sofia/external/08008080800) Running State Change CS_DESTROY (Cur 1 Tot 2) 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:748 (sofia/external/08008080800) State DESTROY 2018-11-10 23:53:09.475673 [DEBUG] mod_sofia.c:354 sofia/external/08008080800 SOFIA DESTROY 2018-11-10 23:53:09.475673 [DEBUG] switch_ivr_async.c:1488 Channel is hung up 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:181 sofia/external/08008080800 Standard DESTROY 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:748 (sofia/external/08008080800) State DESTROY going to sleep 2018-11-10 23:53:09.475673 [DEBUG] switch_core_media_bug.c:1276 Removing BUG from sofia/internal/11@pbx.[anonym].net 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:847 (sofia/internal/11@pbx.[anonym].net) Callstate Change ACTIVE -> HANGUP 2018-11-10 23:53:09.475673 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/11@pbx.[anonym].net) State HANGUP 2018-11-10 23:53:09.475673 [DEBUG] mod_sofia.c:449 Channel sofia/internal/11@pbx.[anonym].net hanging up, cause: NORMAL_CIRCUIT_CONGESTION 2018-11-10 23:53:09.495699 [DEBUG] switch_core_state_machine.c:60 sofia/internal/11@pbx.[anonym].net Standard HANGUP, cause: NORMAL_CIRCUIT_CONGESTION 2018-11-10 23:53:09.495699 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/11@pbx.[anonym].net) State HANGUP going to sleep 2018-11-10 23:53:09.495699 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/11@pbx.[anonym].net) State Change CS_HANGUP -> CS_REPORTING 2018-11-10 23:53:09.495699 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/11@pbx.[anonym].net) Running State Change CS_REPORTING (Cur 1 Tot 2) 2018-11-10 23:53:09.495699 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/11@pbx.[anonym].net) State REPORTING send 1228 bytes to udp/[172.19.51.21]:5060 at 23:53:09.506545: ------------------------------------------------------------------------ NOTIFY sip:11@172.19.51.21:5060;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 172.19.50.3;rport;branch=z9hG4bKDHcDvvSSje0SS Max-Forwards: 70 From: ;tag=ldmvNmA2D3ym To: ;tag=1898982082 Call-ID: d5abfc275ee75b015bde0090332616fc@2 CSeq: 1356459451 NOTIFY Contact: User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Event: presence Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=10 Content-Type: application/pidf+xml Content-Length: 430 open Available ------------------------------------------------------------------------ send 1228 bytes to udp/[172.19.51.21]:5060 at 23:53:09.507535: ------------------------------------------------------------------------ NOTIFY sip:11@172.19.51.21:5060;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 172.19.50.3;rport;branch=z9hG4bKet55XQaXFQpcN Max-Forwards: 70 From: ;tag=G3MK4pPAsqMh To: ;tag=4241842626 Call-ID: f22da23761e75b01897f0090332616fc@2 CSeq: 1356459452 NOTIFY Contact: User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Event: presence Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=90 Content-Type: application/pidf+xml Content-Length: 430 open Available ------------------------------------------------------------------------ recv 353 bytes from udp/[172.19.51.21]:5060 at 23:53:09.510465: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.19.50.3;rport;branch=z9hG4bKDHcDvvSSje0SS;received=172.19.50.3 From: ;tag=ldmvNmA2D3ym To: ;tag=1898982082 Call-ID: d5abfc275ee75b015bde0090332616fc@2 CSeq: 1356459451 NOTIFY Content-Length: 0 Server: (innovaphone IP240/12r1 sr26 [12.1257/121257/301]) ------------------------------------------------------------------------ recv 353 bytes from udp/[172.19.51.21]:5060 at 23:53:09.513631: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.19.50.3;rport;branch=z9hG4bKet55XQaXFQpcN;received=172.19.50.3 From: ;tag=G3MK4pPAsqMh To: ;tag=4241842626 Call-ID: f22da23761e75b01897f0090332616fc@2 CSeq: 1356459452 NOTIFY Content-Length: 0 Server: (innovaphone IP240/12r1 sr26 [12.1257/121257/301]) ------------------------------------------------------------------------ recv 475 bytes from udp/[217.0.27.32]:5060 at 23:53:09.555735: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.19.50.3:5080;received=172.19.50.3;rport=5080;branch=z9hG4bK1y109SjpHUZcp To: ;tag=h7g4Esbg_p65555t1541890379m568871c371372549s1_1415273537-177558755 From: "11" ;tag=t2eppXypav9yK Call-ID: 3657973f-5fde-1237-1193-000db9478a88 CSeq: 130609127 BYE Content-Length: 0 Allow: REGISTER, REFER, NOTIFY, SUBSCRIBE, INFO, PRACK, UPDATE, INVITE, ACK, OPTIONS, CANCEL, BYE ------------------------------------------------------------------------ 2018-11-10 23:53:09.715693 [DEBUG] switch_core_state_machine.c:174 sofia/internal/11@pbx.[anonym].net Standard REPORTING, cause: NORMAL_CIRCUIT_CONGESTION 2018-11-10 23:53:09.715693 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/11@pbx.[anonym].net) State REPORTING going to sleep 2018-11-10 23:53:09.715693 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/11@pbx.[anonym].net) State Change CS_REPORTING -> CS_DESTROY 2018-11-10 23:53:09.715693 [DEBUG] switch_core_session.c:1714 Session 1 (sofia/internal/11@pbx.[anonym].net) Locked, Waiting on external entities 2018-11-10 23:53:09.715693 [NOTICE] switch_core_session.c:1732 Session 1 (sofia/internal/11@pbx.[anonym].net) Ended 2018-11-10 23:53:09.715693 [NOTICE] switch_core_session.c:1736 Close Channel sofia/internal/11@pbx.[anonym].net [CS_DESTROY] 2018-11-10 23:53:09.715693 [DEBUG] switch_core_state_machine.c:738 (sofia/internal/11@pbx.[anonym].net) Running State Change CS_DESTROY (Cur 0 Tot 2) 2018-11-10 23:53:09.715693 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/11@pbx.[anonym].net) State DESTROY 2018-11-10 23:53:09.715693 [DEBUG] mod_sofia.c:354 sofia/internal/11@pbx.[anonym].net SOFIA DESTROY 2018-11-10 23:53:09.715693 [DEBUG] switch_core_state_machine.c:181 sofia/internal/11@pbx.[anonym].net Standard DESTROY 2018-11-10 23:53:09.715693 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/11@pbx.[anonym].net) State DESTROY going to sleep recv 763 bytes from udp/[172.19.50.4]:3861 at 23:53:28.746907: ------------------------------------------------------------------------ REGISTER sip:pbx.[anonym].net SIP/2.0 Authorization: Digest username="9590206",realm="pbx.[anonym].net",nonce="d9fb4777-4364-4a78-b513-5925e62367b5",response="09cc45b9fc7d30b531b18804e1c84e5a",uri="sip:pbx.[anonym].net",qop=auth,cnonce="719b57f454db5b017ede009033060682",nc=00000002,algorithm=MD5 Via: SIP/2.0/UDP 172.19.50.4:3861;branch=z9hG4bK-03B4322B;rport From: ;tag=2770963674 To: Call-ID: c7e2bd8b47e55b014639009033060682 CSeq: 2568 REGISTER Contact: ;expires=120 Accept: innovaphone/data Content-Length: 0 Expires: 120 Max-Forwards: 70 User-Agent: (innovaphone IP800/11r2 sr15 [11.3587/113587/106]) Allow-Events: reg,dialog,message-summary,presence ------------------------------------------------------------------------ send 544 bytes to udp/[172.19.50.4]:3861 at 23:53:28.788886: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.19.50.4:3861;branch=z9hG4bK-03B4322B;rport=3861 From: ;tag=2770963674 To: ;tag=D95Q29gXr297e Call-ID: c7e2bd8b47e55b014639009033060682 CSeq: 2568 REGISTER Contact: ;expires=120 Date: Sat, 10 Nov 2018 22:53:28 GMT User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------