freeswitch@internal> sofia global siptrace on +OK Global siptrace on freeswitch@internal> recv 1050 bytes from udp/[10.1.1.3]:21194 at 20:37:10.418033: ------------------------------------------------------------------------ INVITE sip:1001@10.1.1.1 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.3:21194;branch=z9hG4bK-d8754z-0e061d6b0960fa75-1---d8754z-;rport Max-Forwards: 70 Contact: To: From: ;tag=fc96497b Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 1 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp Supported: replaces User-Agent: X-Lite 4.7.0 73589-abcb99a9-W6.1 Content-Length: 508 v=0 o=- 13065203331951171 1 IN IP4 10.1.1.3 s=X-Lite release 4.7.0 stamp 73589 c=IN IP4 10.1.1.3 t=0 0 m=audio 56818 RTP/AVP 125 100 0 9 8 101 a=rtpmap:125 opus/48000/2 a=fmtp:125 useinbandfec=1 a=rtpmap:100 speex/16000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv m=video 51488 RTP/AVP 115 34 a=rtpmap:115 H263-1998/90000 a=fmtp:115 QCIF=2;CIF=2;VGA=2;CIF4=2;I=1;J=1;T=1 a=rtpmap:34 H263/90000 a=fmtp:34 QCIF=2;CIF=2;VGA=2;CIF4=2 a=rtcp-fb:* nack pli a=sendrecv ------------------------------------------------------------------------ send 367 bytes to udp/[10.1.1.3]:21194 at 20:37:10.418426: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.1.3:21194;branch=z9hG4bK-d8754z-0e061d6b0960fa75-1---d8754z-;rport=21194 From: ;tag=fc96497b To: Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20150108T034022Z~1ed290e930~64bit Content-Length: 0 ------------------------------------------------------------------------ 2015-01-08 20:37:10.398899 [NOTICE] switch_channel.c:1055 New Channel sofia/internal/1004@10.1.1.1 [04ef4178-9748-11e4-981f-3136adddb849] 2015-01-08 20:37:10.398899 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/1004@10.1.1.1 [BREAK] 2015-01-08 20:37:10.398899 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/1004@10.1.1.1 [BREAK] 2015-01-08 20:37:10.398899 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1004@10.1.1.1) Running State Change CS_NEW 2015-01-08 20:37:10.398899 [DEBUG] sofia.c:8834 sofia/internal/1004@10.1.1.1 receiving invite from 10.1.1.3:21194 version: 1.5.15b git 1ed290e 2015-01-08 03:40:22Z 64bit 2015-01-08 20:37:10.418893 [DEBUG] sofia.c:9001 IP 10.1.1.3 Rejected by acl "domains". Falling back to Digest auth. 2015-01-08 20:37:10.418893 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/1004@10.1.1.1) State NEW send 871 bytes to udp/[10.1.1.3]:21194 at 20:37:10.419509: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.1.1.3:21194;branch=z9hG4bK-d8754z-0e061d6b0960fa75-1---d8754z-;rport=21194 From: ;tag=fc96497b To: ;tag=tSSB99r2Fypaa Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20150108T034022Z~1ed290e930~64bit 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="10.1.1.1", nonce="04ef5302-9748-11e4-9820-3136adddb849", algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ 2015-01-08 20:37:10.418893 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/1004@10.1.1.1 [BREAK] 2015-01-08 20:37:10.418893 [DEBUG] sofia.c:2067 detaching session 04ef4178-9748-11e4-981f-3136adddb849 recv 330 bytes from udp/[10.1.1.3]:21194 at 20:37:10.423840: ------------------------------------------------------------------------ ACK sip:1001@10.1.1.1 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.3:21194;branch=z9hG4bK-d8754z-0e061d6b0960fa75-1---d8754z-;rport Max-Forwards: 70 To: ;tag=tSSB99r2Fypaa From: ;tag=fc96497b Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 1 ACK Content-Length: 0 ------------------------------------------------------------------------ recv 1312 bytes from udp/[10.1.1.3]:21194 at 20:37:10.429397: ------------------------------------------------------------------------ INVITE sip:1001@10.1.1.1 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.3:21194;branch=z9hG4bK-d8754z-7013cd70d2e6694e-1---d8754z-;rport Max-Forwards: 70 Contact: To: From: ;tag=fc96497b Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 2 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp Proxy-Authorization: Digest username="1004",realm="10.1.1.1",nonce="04ef5302-9748-11e4-9820-3136adddb849",uri="sip:1001@10.1.1.1",response="481a9aca4f69b1b4fb3ea4426111efa4",cnonce="5dbdd76fed771a60c49b5a60917f09a4",nc=00000001,qop=auth,algorithm=MD5 Supported: replaces User-Agent: X-Lite 4.7.0 73589-abcb99a9-W6.1 Content-Length: 508 v=0 o=- 13065203331951171 1 IN IP4 10.1.1.3 s=X-Lite release 4.7.0 stamp 73589 c=IN IP4 10.1.1.3 t=0 0 m=audio 56818 RTP/AVP 125 100 0 9 8 101 a=rtpmap:125 opus/48000/2 a=fmtp:125 useinbandfec=1 a=rtpmap:100 speex/16000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv m=video 51488 RTP/AVP 115 34 a=rtpmap:115 H263-1998/90000 a=fmtp:115 QCIF=2;CIF=2;VGA=2;CIF4=2;I=1;J=1;T=1 a=rtpmap:34 H263/90000 a=fmtp:34 QCIF=2;CIF=2;VGA=2;CIF4=2 a=rtcp-fb:* nack pli a=sendrecv ------------------------------------------------------------------------ send 367 bytes to udp/[10.1.1.3]:21194 at 20:37:10.429689: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.1.3:21194;branch=z9hG4bK-d8754z-7013cd70d2e6694e-1---d8754z-;rport=21194 From: ;tag=fc96497b To: Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 2 INVITE User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20150108T034022Z~1ed290e930~64bit Content-Length: 0 ------------------------------------------------------------------------ 2015-01-08 20:37:10.418893 [DEBUG] sofia.c:2175 Re-attaching to session 04ef4178-9748-11e4-981f-3136adddb849 2015-01-08 20:37:10.418893 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/1004@10.1.1.1 [BREAK] 2015-01-08 20:37:10.418893 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/1004@10.1.1.1 [BREAK] 2015-01-08 20:37:10.438894 [DEBUG] sofia.c:8834 sofia/internal/1004@10.1.1.1 receiving invite from 10.1.1.3:21194 version: 1.5.15b git 1ed290e 2015-01-08 03:40:22Z 64bit 2015-01-08 20:37:10.438894 [DEBUG] sofia.c:9001 IP 10.1.1.3 Rejected by acl "domains". Falling back to Digest auth. 2015-01-08 20:37:10.438894 [DEBUG] sofia.c:6614 Channel sofia/internal/1004@10.1.1.1 entering state [received][100] 2015-01-08 20:37:10.438894 [DEBUG] sofia.c:6624 Remote SDP: v=0 o=- 13065203331951171 1 IN IP4 10.1.1.3 s=X-Lite release 4.7.0 stamp 73589 c=IN IP4 10.1.1.3 t=0 0 m=audio 56818 RTP/AVP 125 100 0 9 8 101 a=rtpmap:125 opus/48000/2 a=fmtp:125 useinbandfec=1 a=rtpmap:100 speex/16000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 m=video 51488 RTP/AVP 115 34 a=rtpmap:115 H263-1998/90000 a=fmtp:115 QCIF=2;CIF=2;VGA=2;CIF4=2;I=1;J=1;T=1 a=rtpmap:34 H263/90000 a=fmtp:34 QCIF=2;CIF=2;VGA=2;CIF4=2 a=rtcp-fb:* nack pli 2015-01-08 20:37:10.438894 [DEBUG] sofia.c:6890 (sofia/internal/1004@10.1.1.1) State Change CS_NEW -> CS_INIT 2015-01-08 20:37:10.438894 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/1004@10.1.1.1 [BREAK] 2015-01-08 20:37:10.438894 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1004@10.1.1.1) Running State Change CS_INIT 2015-01-08 20:37:10.438894 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/1004@10.1.1.1) State INIT 2015-01-08 20:37:10.438894 [DEBUG] mod_sofia.c:87 sofia/internal/1004@10.1.1.1 SOFIA INIT 2015-01-08 20:37:10.438894 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1004@10.1.1.1 Standard INIT 2015-01-08 20:37:10.438894 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1004@10.1.1.1) State Change CS_INIT -> CS_ROUTING 2015-01-08 20:37:10.438894 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/1004@10.1.1.1 [BREAK] 2015-01-08 20:37:10.438894 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/1004@10.1.1.1) State INIT going to sleep 2015-01-08 20:37:10.438894 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1004@10.1.1.1) Running State Change CS_ROUTING 2015-01-08 20:37:10.438894 [DEBUG] switch_channel.c:2184 (sofia/internal/1004@10.1.1.1) Callstate Change DOWN -> RINGING 2015-01-08 20:37:10.438894 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/1004@10.1.1.1) State ROUTING 2015-01-08 20:37:10.438894 [DEBUG] mod_sofia.c:123 sofia/internal/1004@10.1.1.1 SOFIA ROUTING 2015-01-08 20:37:10.438894 [DEBUG] switch_core_state_machine.c:166 sofia/internal/1004@10.1.1.1 Standard ROUTING 2015-01-08 20:37:10.438894 [INFO] mod_dialplan_xml.c:635 Processing 1004 <1004>->1001 in context default Dialplan: sofia/internal/1004@10.1.1.1 parsing [default->unloop] continue=false Dialplan: sofia/internal/1004@10.1.1.1 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/1004@10.1.1.1 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/1004@10.1.1.1 parsing [default->tod_example] continue=true Dialplan: sofia/internal/1004@10.1.1.1 Date/TimeMatch (FAIL) [tod_example] break=on-false Dialplan: sofia/internal/1004@10.1.1.1 parsing [default->holiday_example] continue=true Dialplan: sofia/internal/1004@10.1.1.1 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: sofia/internal/1004@10.1.1.1 parsing [default->global-intercept] continue=false Dialplan: sofia/internal/1004@10.1.1.1 Regex (FAIL) [global-intercept] destination_number(1001) =~ /^886$/ break=on-false Dialplan: sofia/internal/1004@10.1.1.1 parsing [default->group-intercept] continue=false Dialplan: sofia/internal/1004@10.1.1.1 Regex (FAIL) [group-intercept] destination_number(1001) =~ /^\*8$/ break=on-false Dialplan: sofia/internal/1004@10.1.1.1 parsing [default->intercept-ext] continue=false Dialplan: sofia/internal/1004@10.1.1.1 Regex (FAIL) [intercept-ext] destination_number(1001) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/internal/1004@10.1.1.1 parsing [default->redial] continue=false Dialplan: sofia/internal/1004@10.1.1.1 Regex (FAIL) [redial] destination_number(1001) =~ /^(redial|870)$/ break=on-false Dialplan: sofia/internal/1004@10.1.1.1 parsing [default->global] continue=true Dialplan: sofia/internal/1004@10.1.1.1 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/1004@10.1.1.1 Regex (PASS) [global] ${default_password}(1234) =~ /^1234$/ break=never Dialplan: sofia/internal/1004@10.1.1.1 Action log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING ) Dialplan: sofia/internal/1004@10.1.1.1 Action log(CRIT Open /usr/local/freeswitch/conf/vars.xml and change the default_password.) Dialplan: sofia/internal/1004@10.1.1.1 Action log(CRIT Once changed type 'reloadxml' at the console.) Dialplan: sofia/internal/1004@10.1.1.1 Action log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING ) Dialplan: sofia/internal/1004@10.1.1.1 Action sleep(10000) Dialplan: sofia/internal/1004@10.1.1.1 Regex (FAIL) [global] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=never Dialplan: sofia/internal/1004@10.1.1.1 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false Dialplan: sofia/internal/1004@10.1.1.1 Regex (FAIL) [global] ${switch_r_sdp}(v=0 o=- 13065203331951171 1 IN IP4 10.1.1.3 s=X-Lite release 4.7.0 stamp 73589 c=IN IP4 10.1.1.3 t=0 0 m=audio 56818 RTP/AVP 125 100 0 9 8 101 a=rtpmap:125 opus/48000/2 a=fmtp:125 useinbandfec=1 a=rtpmap:100 speex/16000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 m=video 51488 RTP/AVP 115 34 a=rtpmap:115 H263-1998/90000 a=fmtp:115 QCIF=2;CIF=2;VGA=2;CIF4=2;I=1;J=1;T=1 a=rtpmap:34 H263/90000 a=fmtp:34 QCIF=2;CIF=2;VGA=2;CIF4=2 a=rtcp-fb:* nack pli ) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never Dialplan: sofia/internal/1004@10.1.1.1 Absolute Condition [global] Dialplan: sofia/internal/1004@10.1.1.1 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) Dialplan: sofia/internal/1004@10.1.1.1 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/internal/1004@10.1.1.1 Action hash(insert/${domain_name}-last_dial/global/${uuid}) Dialplan: sofia/internal/1004@10.1.1.1 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/1004@10.1.1.1 parsing [default->snom-demo-2] continue=false Dialplan: sofia/internal/1004@10.1.1.1 Regex (FAIL) [snom-demo-2] destination_number(1001) =~ /^9001$/ break=on-false Dialplan: sofia/internal/1004@10.1.1.1 parsing [default->snom-demo-1] continue=false Dialplan: sofia/internal/1004@10.1.1.1 Regex (FAIL) [snom-demo-1] destination_number(1001) =~ /^9000$/ break=on-false Dialplan: sofia/internal/1004@10.1.1.1 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1004@10.1.1.1 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false Dialplan: sofia/internal/1004@10.1.1.1 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1004@10.1.1.1 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^779$/ break=on-false Dialplan: sofia/internal/1004@10.1.1.1 parsing [default->call_return] continue=false Dialplan: sofia/internal/1004@10.1.1.1 Regex (FAIL) [call_return] destination_number(1001) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/internal/1004@10.1.1.1 parsing [default->del-group] continue=false Dialplan: sofia/internal/1004@10.1.1.1 Regex (FAIL) [del-group] destination_number(1001) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/internal/1004@10.1.1.1 parsing [default->add-group] continue=false Dialplan: sofia/internal/1004@10.1.1.1 Regex (FAIL) [add-group] destination_number(1001) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/internal/1004@10.1.1.1 parsing [default->call-group-simo] continue=false Dialplan: sofia/internal/1004@10.1.1.1 Regex (FAIL) [call-group-simo] destination_number(1001) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/internal/1004@10.1.1.1 parsing [default->call-group-order] continue=false Dialplan: sofia/internal/1004@10.1.1.1 Regex (FAIL) [call-group-order] destination_number(1001) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/internal/1004@10.1.1.1 parsing [default->extension-intercom] continue=false Dialplan: sofia/internal/1004@10.1.1.1 Regex (FAIL) [extension-intercom] destination_number(1001) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1004@10.1.1.1 parsing [default->Local_Extension] continue=false Dialplan: sofia/internal/1004@10.1.1.1 Regex (PASS) [Local_Extension] destination_number(1001) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1004@10.1.1.1 Action export(dialed_extension=1001) Dialplan: sofia/internal/1004@10.1.1.1 Action bind_meta_app(1 b s execute_extension::dx XML features) Dialplan: sofia/internal/1004@10.1.1.1 Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav) Dialplan: sofia/internal/1004@10.1.1.1 Action bind_meta_app(3 b s execute_extension::cf XML features) Dialplan: sofia/internal/1004@10.1.1.1 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) Dialplan: sofia/internal/1004@10.1.1.1 Action set(ringback=${us-ring}) Dialplan: sofia/internal/1004@10.1.1.1 Action set(transfer_ringback=local_stream://moh) Dialplan: sofia/internal/1004@10.1.1.1 Action set(call_timeout=30) Dialplan: sofia/internal/1004@10.1.1.1 Action set(hangup_after_bridge=true) Dialplan: sofia/internal/1004@10.1.1.1 Action set(continue_on_fail=true) Dialplan: sofia/internal/1004@10.1.1.1 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) Dialplan: sofia/internal/1004@10.1.1.1 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/internal/1004@10.1.1.1 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) Dialplan: sofia/internal/1004@10.1.1.1 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1004@10.1.1.1 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) Dialplan: sofia/internal/1004@10.1.1.1 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1004@10.1.1.1 Action bridge(user/${dialed_extension}@${domain_name}) Dialplan: sofia/internal/1004@10.1.1.1 Action answer() Dialplan: sofia/internal/1004@10.1.1.1 Action sleep(1000) Dialplan: sofia/internal/1004@10.1.1.1 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 2015-01-08 20:37:10.438894 [DEBUG] switch_core_state_machine.c:216 (sofia/internal/1004@10.1.1.1) State Change CS_ROUTING -> CS_EXECUTE 2015-01-08 20:37:10.438894 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/1004@10.1.1.1 [BREAK] 2015-01-08 20:37:10.438894 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/1004@10.1.1.1) State ROUTING going to sleep 2015-01-08 20:37:10.438894 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1004@10.1.1.1) Running State Change CS_EXECUTE 2015-01-08 20:37:10.438894 [DEBUG] switch_core_state_machine.c:535 (sofia/internal/1004@10.1.1.1) State EXECUTE 2015-01-08 20:37:10.438894 [DEBUG] mod_sofia.c:178 sofia/internal/1004@10.1.1.1 SOFIA EXECUTE 2015-01-08 20:37:10.438894 [DEBUG] switch_core_state_machine.c:258 sofia/internal/1004@10.1.1.1 Standard EXECUTE EXECUTE sofia/internal/1004@10.1.1.1 log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING ) 2015-01-08 20:37:10.438894 [CRIT] mod_dptools.c:1628 WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING EXECUTE sofia/internal/1004@10.1.1.1 log(CRIT Open /usr/local/freeswitch/conf/vars.xml and change the default_password.) 2015-01-08 20:37:10.438894 [CRIT] mod_dptools.c:1628 Open /usr/local/freeswitch/conf/vars.xml and change the default_password. EXECUTE sofia/internal/1004@10.1.1.1 log(CRIT Once changed type 'reloadxml' at the console.) 2015-01-08 20:37:10.438894 [CRIT] mod_dptools.c:1628 Once changed type 'reloadxml' at the console. EXECUTE sofia/internal/1004@10.1.1.1 log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING ) 2015-01-08 20:37:10.438894 [CRIT] mod_dptools.c:1628 WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING EXECUTE sofia/internal/1004@10.1.1.1 sleep(10000) EXECUTE sofia/internal/1004@10.1.1.1 hash(insert/10.1.1.1-spymap/1004/04ef4178-9748-11e4-981f-3136adddb849) EXECUTE sofia/internal/1004@10.1.1.1 hash(insert/10.1.1.1-last_dial/1004/1001) EXECUTE sofia/internal/1004@10.1.1.1 hash(insert/10.1.1.1-last_dial/global/04ef4178-9748-11e4-981f-3136adddb849) EXECUTE sofia/internal/1004@10.1.1.1 export(RFC2822_DATE=Thu, 08 Jan 2015 20:37:20 +0530) 2015-01-08 20:37:20.458892 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [RFC2822_DATE]=[Thu, 08 Jan 2015 20:37:20 +0530] EXECUTE sofia/internal/1004@10.1.1.1 export(dialed_extension=1001) 2015-01-08 20:37:20.458892 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [dialed_extension]=[1001] EXECUTE sofia/internal/1004@10.1.1.1 bind_meta_app(1 b s execute_extension::dx XML features) 2015-01-08 20:37:20.458892 [INFO] switch_ivr_async.c:3822 Bound B-Leg: *1 execute_extension::dx XML features EXECUTE sofia/internal/1004@10.1.1.1 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/1004.2015-01-08-20-37-20.wav) 2015-01-08 20:37:20.458892 [INFO] switch_ivr_async.c:3822 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/1004.2015-01-08-20-37-20.wav EXECUTE sofia/internal/1004@10.1.1.1 bind_meta_app(3 b s execute_extension::cf XML features) 2015-01-08 20:37:20.458892 [INFO] switch_ivr_async.c:3822 Bound B-Leg: *3 execute_extension::cf XML features EXECUTE sofia/internal/1004@10.1.1.1 bind_meta_app(4 b s execute_extension::att_xfer XML features) 2015-01-08 20:37:20.458892 [INFO] switch_ivr_async.c:3822 Bound B-Leg: *4 execute_extension::att_xfer XML features EXECUTE sofia/internal/1004@10.1.1.1 set(ringback=%(2000,4000,440,480)) 2015-01-08 20:37:20.458892 [DEBUG] mod_dptools.c:1435 sofia/internal/1004@10.1.1.1 SET [ringback]=[%(2000,4000,440,480)] EXECUTE sofia/internal/1004@10.1.1.1 set(transfer_ringback=local_stream://moh) 2015-01-08 20:37:20.458892 [DEBUG] mod_dptools.c:1435 sofia/internal/1004@10.1.1.1 SET [transfer_ringback]=[local_stream://moh] EXECUTE sofia/internal/1004@10.1.1.1 set(call_timeout=30) 2015-01-08 20:37:20.458892 [DEBUG] mod_dptools.c:1435 sofia/internal/1004@10.1.1.1 SET [call_timeout]=[30] EXECUTE sofia/internal/1004@10.1.1.1 set(hangup_after_bridge=true) 2015-01-08 20:37:20.458892 [DEBUG] mod_dptools.c:1435 sofia/internal/1004@10.1.1.1 SET [hangup_after_bridge]=[true] EXECUTE sofia/internal/1004@10.1.1.1 set(continue_on_fail=true) 2015-01-08 20:37:20.458892 [DEBUG] mod_dptools.c:1435 sofia/internal/1004@10.1.1.1 SET [continue_on_fail]=[true] EXECUTE sofia/internal/1004@10.1.1.1 hash(insert/10.1.1.1-call_return/1001/1004) EXECUTE sofia/internal/1004@10.1.1.1 hash(insert/10.1.1.1-last_dial_ext/1001/04ef4178-9748-11e4-981f-3136adddb849) EXECUTE sofia/internal/1004@10.1.1.1 set(called_party_callgroup=techsupport) 2015-01-08 20:37:20.458892 [DEBUG] mod_dptools.c:1435 sofia/internal/1004@10.1.1.1 SET [called_party_callgroup]=[techsupport] EXECUTE sofia/internal/1004@10.1.1.1 hash(insert/10.1.1.1-last_dial_ext/techsupport/04ef4178-9748-11e4-981f-3136adddb849) EXECUTE sofia/internal/1004@10.1.1.1 hash(insert/10.1.1.1-last_dial_ext/global/04ef4178-9748-11e4-981f-3136adddb849) EXECUTE sofia/internal/1004@10.1.1.1 hash(insert/10.1.1.1-last_dial/techsupport/04ef4178-9748-11e4-981f-3136adddb849) EXECUTE sofia/internal/1004@10.1.1.1 bridge(user/1001@10.1.1.1) 2015-01-08 20:37:20.458892 [DEBUG] switch_channel.c:1201 sofia/internal/1004@10.1.1.1 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 08 Jan 2015 20:37:20 +0530] to event 2015-01-08 20:37:20.458892 [DEBUG] switch_channel.c:1201 sofia/internal/1004@10.1.1.1 EXPORTING[export_vars] [dialed_extension]=[1001] to event 2015-01-08 20:37:20.458892 [DEBUG] switch_ivr_originate.c:2103 Parsing global variables 2015-01-08 20:37:20.458892 [DEBUG] switch_channel.c:1201 sofia/internal/1004@10.1.1.1 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 08 Jan 2015 20:37:20 +0530] to event 2015-01-08 20:37:20.458892 [DEBUG] switch_channel.c:1201 sofia/internal/1004@10.1.1.1 EXPORTING[export_vars] [dialed_extension]=[1001] to event 2015-01-08 20:37:20.458892 [DEBUG] switch_ivr_originate.c:2103 Parsing global variables 2015-01-08 20:37:20.458892 [DEBUG] switch_event.c:1688 Parsing variable [sip_invite_domain]=[10.1.1.1] 2015-01-08 20:37:20.458892 [DEBUG] switch_event.c:1688 Parsing variable [presence_id]=[1001@10.1.1.1] 2015-01-08 20:37:20.458892 [NOTICE] switch_channel.c:1055 New Channel sofia/internal/sip:1001@10.1.1.4:36762 [0aece904-9748-11e4-9842-3136adddb849] 2015-01-08 20:37:20.458892 [DEBUG] mod_sofia.c:4636 (sofia/internal/sip:1001@10.1.1.4:36762) State Change CS_NEW -> CS_INIT 2015-01-08 20:37:20.458892 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/sip:1001@10.1.1.4:36762 [BREAK] 2015-01-08 20:37:20.458892 [DEBUG] mod_sofia.c:4706 [zrtp_passthru] Setting a-leg inherit_codec=true 2015-01-08 20:37:20.458892 [DEBUG] mod_sofia.c:4709 [zrtp_passthru] Setting b-leg absolute_codec_string='opus@48000h@20i@2c,PCMU@8000h@20i@64000b,G722@8000h@20i@64000b,PCMA@8000h@20i@64000b,H263@90000h@1c,H263-1998@90000h@1c' 2015-01-08 20:37:20.458892 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/sip:1001@10.1.1.4:36762) Running State Change CS_INIT 2015-01-08 20:37:20.458892 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/sip:1001@10.1.1.4:36762) State INIT 2015-01-08 20:37:20.458892 [DEBUG] mod_sofia.c:87 sofia/internal/sip:1001@10.1.1.4:36762 SOFIA INIT 2015-01-08 20:37:20.458892 [DEBUG] sofia_glue.c:1232 sofia/internal/sip:1001@10.1.1.4:36762 sending invite version: 1.5.15b git 1ed290e 2015-01-08 03:40:22Z 64bit Local SDP: v=0 o=FreeSWITCH 1420703660 1420703661 IN IP4 10.1.1.1 s=FreeSWITCH c=IN IP4 10.1.1.1 t=0 0 m=audio 25980 RTP/AVP 125 0 9 8 101 13 a=rtpmap:125 opus/48000/2 a=fmtp:125 useinbandfec=1 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv m=video 30320 RTP/AVP 34 115 a=rtpmap:34 H263/90000 a=rtpmap:115 H263-1998/90000 a=fmtp:115 QCIF=2;CIF=2;VGA=2;CIF4=2;I=1;J=1;T=1 2015-01-08 20:37:20.458892 [DEBUG] switch_core_state_machine.c:40 sofia/internal/sip:1001@10.1.1.4:36762 Standard INIT 2015-01-08 20:37:20.458892 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/sip:1001@10.1.1.4:36762) State Change CS_INIT -> CS_ROUTING 2015-01-08 20:37:20.458892 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/sip:1001@10.1.1.4:36762 [BREAK] 2015-01-08 20:37:20.458892 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/sip:1001@10.1.1.4:36762) State INIT going to sleep 2015-01-08 20:37:20.458892 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/sip:1001@10.1.1.4:36762) Running State Change CS_ROUTING send 1482 bytes to udp/[10.1.1.4]:36762 at 20:37:20.471070: ------------------------------------------------------------------------ INVITE sip:1001@10.1.1.4:36762;rinstance=18b07042dd52441e SIP/2.0 Via: SIP/2.0/UDP 10.1.1.1;rport;branch=z9hG4bKXKKNgevFvQaUQ Max-Forwards: 69 From: "Extension 1004" ;tag=vBcXc0t99F3FH To: Call-ID: e24b5e56-11ea-1233-39bf-005056aa6ca1 CSeq: 70028756 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20150108T034022Z~1ed290e930~64bit 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: 465 X-FS-Support: update_display,send_info Remote-Party-ID: "Extension 1004" ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1420703660 1420703661 IN IP4 10.1.1.1 s=FreeSWITCH c=IN IP4 10.1.1.1 t=0 0 m=audio 25980 RTP/AVP 125 0 9 8 101 13 a=rtpmap:125 opus/48000/2 2015-01-08 20:37:20.458892 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/sip:1001@10.1.1.4:36762) State ROUTING a=fmtp:125 useinbandfec=1 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 2015-01-08 20:37:20.458892 [DEBUG] mod_sofia.c:123 sofia/internal/sip:1001@10.1.1.4:36762 SOFIA ROUTING a=fmtp:101 0-16 a=ptime:20 m=video 30320 RTP/AVP 34 115 a=rtpmap:34 H263/90000 a=rtpmap:115 H263-1998/90000 2015-01-08 20:37:20.458892 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/sip:1001@10.1.1.4:36762) State Change CS_ROUTING -> CS_CONSUME_MEDIA a=fmtp:115 QCIF=2;CIF=2;VGA=2;CIF4=2;I=1;J=1;T=1 ------------------------------------------------------------------------ 2015-01-08 20:37:20.458892 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/sip:1001@10.1.1.4:36762 [BREAK] 2015-01-08 20:37:20.458892 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/sip:1001@10.1.1.4:36762) State ROUTING going to sleep 2015-01-08 20:37:20.458892 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/sip:1001@10.1.1.4:36762 [BREAK] 2015-01-08 20:37:20.458892 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/sip:1001@10.1.1.4:36762) Running State Change CS_CONSUME_MEDIA 2015-01-08 20:37:20.458892 [DEBUG] sofia.c:6614 Channel sofia/internal/sip:1001@10.1.1.4:36762 entering state [calling][0] 2015-01-08 20:37:20.458892 [DEBUG] switch_core_state_machine.c:547 (sofia/internal/sip:1001@10.1.1.4:36762) State CONSUME_MEDIA 2015-01-08 20:37:20.458892 [DEBUG] switch_core_state_machine.c:547 (sofia/internal/sip:1001@10.1.1.4:36762) State CONSUME_MEDIA going to sleep recv 412 bytes from udp/[10.1.1.4]:36762 at 20:37:20.550219: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.1.1.1;rport=5060;branch=z9hG4bKXKKNgevFvQaUQ Contact: To: ;tag=7d1efd53 From: "Extension 1004";tag=vBcXc0t99F3FH Call-ID: e24b5e56-11ea-1233-39bf-005056aa6ca1 CSeq: 70028756 INVITE User-Agent: X-Lite release 4.7.1 stamp 74247 Content-Length: 0 ------------------------------------------------------------------------ 2015-01-08 20:37:20.538891 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/sip:1001@10.1.1.4:36762 [BREAK] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/sip:1001@10.1.1.4:36762 [BREAK] 2015-01-08 20:37:20.538891 [DEBUG] sofia.c:6614 Channel sofia/internal/sip:1001@10.1.1.4:36762 entering state [proceeding][180] 2015-01-08 20:37:20.538891 [NOTICE] sofia.c:6716 Ring-Ready sofia/internal/sip:1001@10.1.1.4:36762! 2015-01-08 20:37:20.538891 [DEBUG] switch_channel.c:3277 (sofia/internal/sip:1001@10.1.1.4:36762) Callstate Change DOWN -> RINGING 2015-01-08 20:37:20.538891 [INFO] switch_ivr_originate.c:1192 Sending early media 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [opus:125:48000:20:0:1]/[opus:116:48000:20:0:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3682 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [opus:125:48000:20:0:1]/[G722:9:8000:20:64000:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [opus:125:48000:20:0:1]/[PCMU:0:8000:20:64000:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [opus:125:48000:20:0:1]/[PCMA:8:8000:20:64000:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [opus:125:48000:20:0:1]/[GSM:3:8000:20:13200:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [speex:100:16000:20:0:1]/[opus:116:48000:20:0:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [speex:100:16000:20:0:1]/[G722:9:8000:20:64000:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [speex:100:16000:20:0:1]/[PCMU:0:8000:20:64000:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [speex:100:16000:20:0:1]/[PCMA:8:8000:20:64000:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [speex:100:16000:20:0:1]/[GSM:3:8000:20:13200:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3682 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3682 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [G722:9:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3682 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3543 Set telephone-event payload to 101 2015-01-08 20:37:20.538891 [DEBUG] mod_opus.c:287 Opus encoder set bitrate to local settings [-1000bps] 2015-01-08 20:37:20.538891 [DEBUG] mod_opus.c:287 Opus encoder set bitrate to local settings [-1000bps] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:2473 Set Codec sofia/internal/1004@10.1.1.1 opus/48000 20 ms 960 samples 0 bits 1 channels 2015-01-08 20:37:20.538891 [DEBUG] switch_core_codec.c:111 sofia/internal/1004@10.1.1.1 Original read codec set to opus:116 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:3890 Set 2833 dtmf send/recv payload to 101 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:4007 Video Codec Compare [H263-1998:115]/[H261:31] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:4007 Video Codec Compare [H263-1998:115]/[H263:34] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:4007 Video Codec Compare [H263-1998:115]/[H263-1998:115] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:4020 Video Codec Compare [H263-1998:115] +++ is saved as a match 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:4007 Video Codec Compare [H263-1998:115]/[H263-2000:121] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:4007 Video Codec Compare [H263-1998:115]/[H264:97] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:4007 Video Codec Compare [H263-1998:115]/[VP8:99] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:4007 Video Codec Compare [H263:34]/[H261:31] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:4007 Video Codec Compare [H263:34]/[H263:34] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:4020 Video Codec Compare [H263:34] +++ is saved as a match 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:4007 Video Codec Compare [H263:34]/[H263-1998:115] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:4007 Video Codec Compare [H263:34]/[H263-2000:121] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:4007 Video Codec Compare [H263:34]/[H264:97] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:4007 Video Codec Compare [H263:34]/[VP8:99] 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:2293 Set VIDEO Codec sofia/internal/1004@10.1.1.1 H263-1998/90000 0 ms 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:5141 AUDIO RTP [sofia/internal/1004@10.1.1.1] 10.1.1.1 port 19038 -> 10.1.1.3 port 56818 codec: 125 ms: 20 2015-01-08 20:37:20.538891 [DEBUG] switch_rtp.c:3548 Starting timer [soft] 960 bytes per 20ms 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:5439 Set 2833 dtmf send payload to 101 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:5445 Set 2833 dtmf receive payload to 101 2015-01-08 20:37:20.538891 [DEBUG] switch_rtp.c:3557 Not using a timer 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:5643 VIDEO RTP [sofia/internal/1004@10.1.1.1] 10.1.1.3:29642->10.1.1.3:51488 codec: 115 ms: 0 [SUCCESS] 2015-01-08 20:37:20.538891 [NOTICE] switch_core_media.c:4405 sofia/internal/1004@10.1.1.1 Starting Video thread 2015-01-08 20:37:20.538891 [DEBUG] switch_core_media.c:4329 sofia/internal/1004@10.1.1.1 Video thread started. Echo is on 2015-01-08 20:37:20.538891 [INFO] switch_core_media.c:5723 Activating VIDEO RTCP PORT 0 mux -1 2015-01-08 20:37:20.538891 [DEBUG] switch_rtp.c:3898 RTCP send rate is: 10000 and packet rate is: 90000 Remote Port: 51489 2015-01-08 20:37:20.538891 [DEBUG] switch_rtp.c:2354 Setting RTCP remote addr to 10.1.1.3:51489 2015-01-08 20:37:20.538891 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1004@10.1.1.1! 2015-01-08 20:37:20.538891 [DEBUG] switch_channel.c:3399 (sofia/internal/1004@10.1.1.1) Callstate Change RINGING -> EARLY 2015-01-08 20:37:20.538891 [DEBUG] mod_sofia.c:2268 Ring SDP: v=0 o=FreeSWITCH 1420710602 1420710603 IN IP4 10.1.1.1 s=FreeSWITCH c=IN IP4 10.1.1.1 t=0 0 m=audio 19038 RTP/AVP 125 101 a=rtpmap:125 opus/48000/2 a=fmtp:125 useinbandfec=1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv m=video 29642 RTP/AVP 115 a=rtpmap:115 H263-1998/90000 a=fmtp:115 QCIF=2;CIF=2;VGA=2;CIF4=2;I=1;J=1;T=1 a=rtcp:29643 IN IP4 10.1.1.1 2015-01-08 20:37:20.538891 [DEBUG] switch_core_session.c:908 Send signal sofia/internal/1004@10.1.1.1 [BREAK] 2015-01-08 20:37:20.538891 [DEBUG] switch_ivr_originate.c:1249 Raw Codec Activation Success L16@48000hz 1 channel 20ms 2015-01-08 20:37:20.538891 [DEBUG] switch_core_codec.c:221 sofia/internal/1004@10.1.1.1 Push codec L16:70 2015-01-08 20:37:20.538891 [DEBUG] switch_ivr_originate.c:1317 Play Ringback Tone [%(2000,4000,440,480)] send 1336 bytes to udp/[10.1.1.3]:21194 at 20:37:20.558402: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 10.1.1.3:21194;branch=z9hG4bK-d8754z-7013cd70d2e6694e-1---d8754z-;rport=21194 From: ;tag=fc96497b To: ;tag=U2j4a595c7cXN Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20150108T034022Z~1ed290e930~64bit 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: 398 Remote-Party-ID: "1001" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1420710602 1420710603 IN IP4 10.1.1.1 s=FreeSWITCH c=IN IP4 10.1.1.1 t=0 0 m=audio 19038 RTP/AVP 125 101 a=rtpmap:125 opus/48000/2 a=fmtp:125 useinbandfec=1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 29642 RTP/AVP 115 a=rtpmap:115 H263-1998/90000 a=fmtp:115 QCIF=2;CIF=2;VGA=2;CIF4=2;I=1;J=1;T=1 a=rtcp:29643 IN IP4 10.1.1.1 ------------------------------------------------------------------------ 2015-01-08 20:37:20.538891 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/1004@10.1.1.1 [BREAK] send 816 bytes to udp/[10.1.1.3]:21194 at 20:37:20.558650: ------------------------------------------------------------------------ INFO sip:1004@10.1.1.3:21194 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.1;rport;branch=z9hG4bKyvcej9cKS00DK Max-Forwards: 70 From: ;tag=U2j4a595c7cXN To: ;tag=fc96497b Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 70028756 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20150108T034022Z~1ed290e930~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Type: application/media_control+xml Content-Length: 175 ------------------------------------------------------------------------ 2015-01-08 20:37:20.578891 [DEBUG] sofia.c:6614 Channel sofia/internal/1004@10.1.1.1 entering state [early][183] 2015-01-08 20:37:20.618894 [DEBUG] switch_rtp.c:5853 Correct ip/port confirmed. send 816 bytes to udp/[10.1.1.3]:21194 at 20:37:21.559269: ------------------------------------------------------------------------ INFO sip:1004@10.1.1.3:21194 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.1;rport;branch=z9hG4bKyvcej9cKS00DK Max-Forwards: 70 From: ;tag=U2j4a595c7cXN To: ;tag=fc96497b Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 70028756 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20150108T034022Z~1ed290e930~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Type: application/media_control+xml Content-Length: 175 ------------------------------------------------------------------------ recv 1033 bytes from udp/[10.1.1.4]:36762 at 20:37:22.558754: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.1.1;rport=5060;branch=z9hG4bKXKKNgevFvQaUQ Contact: To: ;tag=7d1efd53 From: "Extension 1004";tag=vBcXc0t99F3FH Call-ID: e24b5e56-11ea-1233-39bf-005056aa6ca1 CSeq: 70028756 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp Supported: replaces, eventlist User-Agent: X-Lite release 4.7.1 stamp 74247 Content-Length: 478 v=0 o=- 13065203368350614 3 IN IP4 10.1.1.4 s=X-Lite release 4.7.1 stamp 74247 c=IN IP4 10.1.1.4 t=0 0 m=audio 62698 RTP/AVP 125 0 9 8 101 a=rtpmap:125 opus/48000/2 a=fmtp:125 useinbandfec=1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv m=video 49936 RTP/AVP 34 115 a=rtpmap:34 H263/90000 a=fmtp:34 QCIF=2;CIF=2;VGA=2;CIF4=2 a=rtpmap:115 H263-1998/90000 a=fmtp:115 QCIF=2;CIF=2;VGA=2;CIF4=2;I=1;J=1;T=1 a=sendrecv a=rtcp-fb:* nack pli ------------------------------------------------------------------------ 2015-01-08 20:37:22.558880 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/sip:1001@10.1.1.4:36762 [BREAK] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/sip:1001@10.1.1.4:36762 [BREAK] 2015-01-08 20:37:22.558880 [DEBUG] sofia.c:6614 Channel sofia/internal/sip:1001@10.1.1.4:36762 entering state [completing][200] 2015-01-08 20:37:22.558880 [DEBUG] sofia.c:6624 Remote SDP: v=0 o=- 13065203368350614 3 IN IP4 10.1.1.4 s=X-Lite release 4.7.1 stamp 74247 c=IN IP4 10.1.1.4 t=0 0 m=audio 62698 RTP/AVP 125 0 9 8 101 a=rtpmap:125 opus/48000/2 a=fmtp:125 useinbandfec=1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 m=video 49936 RTP/AVP 34 115 a=rtpmap:34 H263/90000 a=fmtp:34 QCIF=2;CIF=2;VGA=2;CIF4=2 a=rtpmap:115 H263-1998/90000 a=fmtp:115 QCIF=2;CIF=2;VGA=2;CIF4=2;I=1;J=1;T=1 a=rtcp-fb:* nack pli send 402 bytes to udp/[10.1.1.4]:36762 at 20:37:22.560661: ------------------------------------------------------------------------ ACK sip:1001@10.1.1.4:36762 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.1;rport;branch=z9hG4bKZ556K4Xpp9p0e Max-Forwards: 70 From: "Extension 1004" ;tag=vBcXc0t99F3FH To: ;tag=7d1efd53 Call-ID: e24b5e56-11ea-1233-39bf-005056aa6ca1 CSeq: 70028756 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ 2015-01-08 20:37:22.558880 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/sip:1001@10.1.1.4:36762 [BREAK] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/sip:1001@10.1.1.4:36762 [BREAK] 2015-01-08 20:37:22.558880 [DEBUG] sofia.c:6614 Channel sofia/internal/sip:1001@10.1.1.4:36762 entering state [ready][200] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [opus:125:48000:20:0:1]/[opus:116:48000:20:0:2] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3682 Audio Codec Compare [opus:116:48000:20:0:2] ++++ is saved as a match 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [opus:125:48000:20:0:1]/[PCMU:0:8000:20:64000:1] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [opus:125:48000:20:0:1]/[G722:9:8000:20:64000:1] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [opus:125:48000:20:0:1]/[PCMA:8:8000:20:64000:1] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:2] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3682 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:2] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3682 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:2] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3682 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3543 Set telephone-event payload to 101 2015-01-08 20:37:22.558880 [DEBUG] mod_opus.c:287 Opus encoder set bitrate to local settings [-1000bps] 2015-01-08 20:37:22.558880 [DEBUG] mod_opus.c:287 Opus encoder set bitrate to local settings [-1000bps] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:2473 Set Codec sofia/internal/sip:1001@10.1.1.4:36762 opus/48000 20 ms 960 samples 0 bits 1 channels 2015-01-08 20:37:22.558880 [DEBUG] switch_core_codec.c:111 sofia/internal/sip:1001@10.1.1.4:36762 Original read codec set to opus:116 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:3881 Set 2833 dtmf send payload to 101 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:4007 Video Codec Compare [H263:34]/[H263:34] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:4020 Video Codec Compare [H263:34] +++ is saved as a match 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:4007 Video Codec Compare [H263:34]/[H263-1998:115] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:4007 Video Codec Compare [H263-1998:115]/[H263:34] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:4007 Video Codec Compare [H263-1998:115]/[H263-1998:115] 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:4020 Video Codec Compare [H263-1998:115] +++ is saved as a match 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:2293 Set VIDEO Codec sofia/internal/sip:1001@10.1.1.4:36762 H263/90000 0 ms 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:5141 AUDIO RTP [sofia/internal/sip:1001@10.1.1.4:36762] 10.1.1.1 port 25980 -> 10.1.1.4 port 62698 codec: 125 ms: 20 2015-01-08 20:37:22.558880 [DEBUG] switch_rtp.c:3548 Starting timer [soft] 960 bytes per 20ms 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:5439 Set 2833 dtmf send payload to 101 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:5445 Set 2833 dtmf receive payload to 101 2015-01-08 20:37:22.558880 [DEBUG] switch_rtp.c:3557 Not using a timer 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:5643 VIDEO RTP [sofia/internal/sip:1001@10.1.1.4:36762] 10.1.1.4:30320->10.1.1.4:49936 codec: 34 ms: 0 [SUCCESS] 2015-01-08 20:37:22.558880 [NOTICE] switch_core_media.c:4405 sofia/internal/sip:1001@10.1.1.4:36762 Starting Video thread 2015-01-08 20:37:22.558880 [INFO] switch_core_media.c:5723 Activating VIDEO RTCP PORT 0 mux -1 2015-01-08 20:37:22.558880 [DEBUG] switch_core_media.c:4329 sofia/internal/sip:1001@10.1.1.4:36762 Video thread started. Echo is off 2015-01-08 20:37:22.558880 [DEBUG] switch_rtp.c:3898 RTCP send rate is: 10000 and packet rate is: 90000 Remote Port: 49937 2015-01-08 20:37:22.558880 [DEBUG] switch_rtp.c:2354 Setting RTCP remote addr to 10.1.1.4:49937 2015-01-08 20:37:22.558880 [DEBUG] switch_channel.c:3635 Send signal sofia/internal/1004@10.1.1.1 [BREAK] 2015-01-08 20:37:22.558880 [NOTICE] sofia.c:7475 Channel [sofia/internal/sip:1001@10.1.1.4:36762] has been answered 2015-01-08 20:37:22.558880 [DEBUG] switch_channel.c:3689 (sofia/internal/sip:1001@10.1.1.4:36762) Callstate Change RINGING -> ACTIVE send 850 bytes to udp/[10.1.1.4]:36762 at 20:37:22.566368: ------------------------------------------------------------------------ INFO sip:1001@10.1.1.4:36762 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.1;rport;branch=z9hG4bK0eZZNZetKjDKa Max-Forwards: 70 From: "Extension 1004" ;tag=vBcXc0t99F3FH To: ;tag=7d1efd53 Call-ID: e24b5e56-11ea-1233-39bf-005056aa6ca1 CSeq: 70028757 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20150108T034022Z~1ed290e930~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Type: application/media_control+xml Content-Length: 175 ------------------------------------------------------------------------ recv 405 bytes from udp/[10.1.1.4]:36762 at 20:37:22.573895: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.1.1;rport=5060;branch=z9hG4bK0eZZNZetKjDKa Contact: To: ;tag=7d1efd53 From: "Extension 1004";tag=vBcXc0t99F3FH Call-ID: e24b5e56-11ea-1233-39bf-005056aa6ca1 CSeq: 70028757 INFO User-Agent: X-Lite release 4.7.1 stamp 74247 Content-Length: 0 ------------------------------------------------------------------------ 2015-01-08 20:37:22.558880 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/sip:1001@10.1.1.4:36762 [BREAK] 2015-01-08 20:37:22.578882 [DEBUG] switch_core_codec.c:246 sofia/internal/1004@10.1.1.1 Restore previous codec opus:116. 2015-01-08 20:37:22.578882 [DEBUG] mod_sofia.c:780 Local SDP sofia/internal/1004@10.1.1.1: v=0 o=FreeSWITCH 1420710602 1420710604 IN IP4 10.1.1.1 s=FreeSWITCH c=IN IP4 10.1.1.1 t=0 0 m=audio 19038 RTP/AVP 125 101 a=rtpmap:125 opus/48000/2 a=fmtp:125 useinbandfec=1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv m=video 29642 RTP/AVP 115 a=rtpmap:115 H263-1998/90000 a=fmtp:115 QCIF=2;CIF=2;VGA=2;CIF4=2;I=1;J=1;T=1 a=rtcp:29643 IN IP4 10.1.1.1 2015-01-08 20:37:22.578882 [DEBUG] switch_core_session.c:908 Send signal sofia/internal/1004@10.1.1.1 [BREAK] send 1306 bytes to udp/[10.1.1.3]:21194 at 20:37:22.580379: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.1.3:21194;branch=z9hG4bK-d8754z-7013cd70d2e6694e-1---d8754z-;rport=21194 From: ;tag=fc96497b To: ;tag=U2j4a595c7cXN Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20150108T034022Z~1ed290e930~64bit 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: 398 Remote-Party-ID: "Outbound Call" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1420710602 1420710603 IN IP4 10.1.1.1 s=FreeSWITCH c=IN IP4 10.1.1.1 t=0 0 m=audio 19038 RTP/AVP 125 101 a=rtpmap:125 opus/48000/2 a=fmtp:125 useinbandfec=1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 29642 RTP/AVP 115 a=rtpmap:115 H263-1998/90000 a=fmtp:115 QCIF=2;CIF=2;VGA=2;CIF4=2;I=1;J=1;T=1 a=rtcp:29643 IN IP4 10.1.1.1 ------------------------------------------------------------------------ 2015-01-08 20:37:22.578882 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/1004@10.1.1.1 [BREAK] 2015-01-08 20:37:22.578882 [NOTICE] switch_ivr_originate.c:3522 Channel [sofia/internal/1004@10.1.1.1] has been answered 2015-01-08 20:37:22.578882 [DEBUG] switch_channel.c:3689 (sofia/internal/1004@10.1.1.1) Callstate Change EARLY -> ACTIVE 2015-01-08 20:37:22.578882 [DEBUG] sofia.c:6614 Channel sofia/internal/1004@10.1.1.1 entering state [completed][200] 2015-01-08 20:37:22.578882 [DEBUG] switch_ivr_originate.c:3580 Originate Resulted in Success: [sofia/internal/sip:1001@10.1.1.4:36762] 2015-01-08 20:37:22.578882 [DEBUG] switch_ivr_originate.c:3580 Originate Resulted in Success: [sofia/internal/sip:1001@10.1.1.4:36762] 2015-01-08 20:37:22.578882 [DEBUG] switch_core_session.c:908 Send signal sofia/internal/sip:1001@10.1.1.4:36762 [BREAK] 2015-01-08 20:37:22.578882 [DEBUG] switch_core_session.c:908 Send signal sofia/internal/1004@10.1.1.1 [BREAK] 2015-01-08 20:37:22.578882 [DEBUG] switch_ivr_bridge.c:1465 (sofia/internal/sip:1001@10.1.1.4:36762) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2015-01-08 20:37:22.578882 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/sip:1001@10.1.1.4:36762 [BREAK] 2015-01-08 20:37:22.578882 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/sip:1001@10.1.1.4:36762) Running State Change CS_EXCHANGE_MEDIA 2015-01-08 20:37:22.578882 [DEBUG] switch_core_state_machine.c:538 (sofia/internal/sip:1001@10.1.1.4:36762) State EXCHANGE_MEDIA 2015-01-08 20:37:22.578882 [DEBUG] mod_sofia.c:594 SOFIA EXCHANGE_MEDIA 2015-01-08 20:37:22.638892 [DEBUG] mod_opus.c:287 Opus encoder set bitrate to local settings [-1000bps] 2015-01-08 20:37:22.658894 [DEBUG] switch_core_media.c:4336 sofia/internal/1004@10.1.1.1 Video thread paused. Echo is on 2015-01-08 20:37:22.658894 [DEBUG] switch_core_media.c:4336 sofia/internal/sip:1001@10.1.1.4:36762 Video thread paused. Echo is off send 1306 bytes to udp/[10.1.1.3]:21194 at 20:37:23.080509: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.1.3:21194;branch=z9hG4bK-d8754z-7013cd70d2e6694e-1---d8754z-;rport=21194 From: ;tag=fc96497b To: ;tag=U2j4a595c7cXN Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20150108T034022Z~1ed290e930~64bit 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: 398 Remote-Party-ID: "Outbound Call" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1420710602 1420710603 IN IP4 10.1.1.1 s=FreeSWITCH c=IN IP4 10.1.1.1 t=0 0 m=audio 19038 RTP/AVP 125 101 a=rtpmap:125 opus/48000/2 a=fmtp:125 useinbandfec=1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 29642 RTP/AVP 115 a=rtpmap:115 H263-1998/90000 a=fmtp:115 QCIF=2;CIF=2;VGA=2;CIF4=2;I=1;J=1;T=1 a=rtcp:29643 IN IP4 10.1.1.1 ------------------------------------------------------------------------ send 816 bytes to udp/[10.1.1.3]:21194 at 20:37:23.559502: ------------------------------------------------------------------------ INFO sip:1004@10.1.1.3:21194 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.1;rport;branch=z9hG4bKyvcej9cKS00DK Max-Forwards: 70 From: ;tag=U2j4a595c7cXN To: ;tag=fc96497b Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 70028756 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20150108T034022Z~1ed290e930~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Type: application/media_control+xml Content-Length: 175 ------------------------------------------------------------------------ send 1306 bytes to udp/[10.1.1.3]:21194 at 20:37:24.081505: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.1.3:21194;branch=z9hG4bK-d8754z-7013cd70d2e6694e-1---d8754z-;rport=21194 From: ;tag=fc96497b To: ;tag=U2j4a595c7cXN Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20150108T034022Z~1ed290e930~64bit 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: 398 Remote-Party-ID: "Outbound Call" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1420710602 1420710603 IN IP4 10.1.1.1 s=FreeSWITCH c=IN IP4 10.1.1.1 t=0 0 m=audio 19038 RTP/AVP 125 101 a=rtpmap:125 opus/48000/2 a=fmtp:125 useinbandfec=1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 29642 RTP/AVP 115 a=rtpmap:115 H263-1998/90000 a=fmtp:115 QCIF=2;CIF=2;VGA=2;CIF4=2;I=1;J=1;T=1 a=rtcp:29643 IN IP4 10.1.1.1 ------------------------------------------------------------------------ recv 280 bytes from udp/[10.1.1.3]:21194 at 20:37:24.094926: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.1.1;rport=5060;branch=z9hG4bKyvcej9cKS00DK To: ;tag=fc96497b From: ;tag=U2j4a595c7cXN Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 70028756 INFO Content-Length: 0 ------------------------------------------------------------------------ send 1306 bytes to udp/[10.1.1.3]:21194 at 20:37:26.082946: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.1.3:21194;branch=z9hG4bK-d8754z-7013cd70d2e6694e-1---d8754z-;rport=21194 From: ;tag=fc96497b To: ;tag=U2j4a595c7cXN Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20150108T034022Z~1ed290e930~64bit 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: 398 Remote-Party-ID: "Outbound Call" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1420710602 1420710603 IN IP4 10.1.1.1 s=FreeSWITCH c=IN IP4 10.1.1.1 t=0 0 m=audio 19038 RTP/AVP 125 101 a=rtpmap:125 opus/48000/2 a=fmtp:125 useinbandfec=1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 29642 RTP/AVP 115 a=rtpmap:115 H263-1998/90000 a=fmtp:115 QCIF=2;CIF=2;VGA=2;CIF4=2;I=1;J=1;T=1 a=rtcp:29643 IN IP4 10.1.1.1 ------------------------------------------------------------------------ send 816 bytes to udp/[10.1.1.3]:21194 at 20:37:27.559939: ------------------------------------------------------------------------ INFO sip:1004@10.1.1.3:21194 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.1;rport;branch=z9hG4bKyvcej9cKS00DK Max-Forwards: 70 From: ;tag=U2j4a595c7cXN To: ;tag=fc96497b Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 70028756 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20150108T034022Z~1ed290e930~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Type: application/media_control+xml Content-Length: 175 ------------------------------------------------------------------------ recv 280 bytes from udp/[10.1.1.3]:21194 at 20:37:27.563906: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.1.1;rport=5060;branch=z9hG4bKyvcej9cKS00DK To: ;tag=fc96497b From: ;tag=U2j4a595c7cXN Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 70028756 INFO Content-Length: 0 ------------------------------------------------------------------------ send 1306 bytes to udp/[10.1.1.3]:21194 at 20:37:30.082953: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.1.3:21194;branch=z9hG4bK-d8754z-7013cd70d2e6694e-1---d8754z-;rport=21194 From: ;tag=fc96497b To: ;tag=U2j4a595c7cXN Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20150108T034022Z~1ed290e930~64bit 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: 398 Remote-Party-ID: "Outbound Call" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1420710602 1420710603 IN IP4 10.1.1.1 s=FreeSWITCH c=IN IP4 10.1.1.1 t=0 0 m=audio 19038 RTP/AVP 125 101 a=rtpmap:125 opus/48000/2 a=fmtp:125 useinbandfec=1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 29642 RTP/AVP 115 a=rtpmap:115 H263-1998/90000 a=fmtp:115 QCIF=2;CIF=2;VGA=2;CIF4=2;I=1;J=1;T=1 a=rtcp:29643 IN IP4 10.1.1.1 ------------------------------------------------------------------------ 2015-01-08 20:37:30.578891 [DEBUG] switch_rtp.c:1942 rtcp_stats_init: ssrc[1815112177] base_seq[0] 2015-01-08 20:37:30.578891 [NOTICE] switch_rtp.c:5168 Receiving an RTCP packet[2015-08-00 15:07:30.589357] SSRC[1815112177]RTT[39699.102036] A[464688864] - DLSR[1297566794] - LSR[860369015] send 816 bytes to udp/[10.1.1.3]:21194 at 20:37:31.559946: ------------------------------------------------------------------------ INFO sip:1004@10.1.1.3:21194 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.1;rport;branch=z9hG4bKyvcej9cKS00DK Max-Forwards: 70 From: ;tag=U2j4a595c7cXN To: ;tag=fc96497b Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 70028756 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20150108T034022Z~1ed290e930~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Type: application/media_control+xml Content-Length: 175 ------------------------------------------------------------------------ recv 280 bytes from udp/[10.1.1.3]:21194 at 20:37:31.564058: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.1.1;rport=5060;branch=z9hG4bKyvcej9cKS00DK To: ;tag=fc96497b From: ;tag=U2j4a595c7cXN Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 70028756 INFO Content-Length: 0 ------------------------------------------------------------------------ 2015-01-08 20:37:32.538884 [DEBUG] switch_rtp.c:1942 rtcp_stats_init: ssrc[2055342500] base_seq[0] 2015-01-08 20:37:32.538884 [NOTICE] switch_rtp.c:5168 Receiving an RTCP packet[2015-08-00 15:07:32.545585] SSRC[2055342500]RTT[35804.765488] A[464817067] - DLSR[1097159535] - LSR[1316123717] send 1306 bytes to udp/[10.1.1.3]:21194 at 20:37:34.082954: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.1.3:21194;branch=z9hG4bK-d8754z-7013cd70d2e6694e-1---d8754z-;rport=21194 From: ;tag=fc96497b To: ;tag=U2j4a595c7cXN Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20150108T034022Z~1ed290e930~64bit 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: 398 Remote-Party-ID: "Outbound Call" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1420710602 1420710603 IN IP4 10.1.1.1 s=FreeSWITCH c=IN IP4 10.1.1.1 t=0 0 m=audio 19038 RTP/AVP 125 101 a=rtpmap:125 opus/48000/2 a=fmtp:125 useinbandfec=1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 29642 RTP/AVP 115 a=rtpmap:115 H263-1998/90000 a=fmtp:115 QCIF=2;CIF=2;VGA=2;CIF4=2;I=1;J=1;T=1 a=rtcp:29643 IN IP4 10.1.1.1 ------------------------------------------------------------------------ send 816 bytes to udp/[10.1.1.3]:21194 at 20:37:35.559952: ------------------------------------------------------------------------ INFO sip:1004@10.1.1.3:21194 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.1;rport;branch=z9hG4bKyvcej9cKS00DK Max-Forwards: 70 From: ;tag=U2j4a595c7cXN To: ;tag=fc96497b Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 70028756 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20150108T034022Z~1ed290e930~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Type: application/media_control+xml Content-Length: 175 ------------------------------------------------------------------------ recv 280 bytes from udp/[10.1.1.3]:21194 at 20:37:35.563829: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.1.1;rport=5060;branch=z9hG4bKyvcej9cKS00DK To: ;tag=fc96497b From: ;tag=U2j4a595c7cXN Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 70028756 INFO Content-Length: 0 ------------------------------------------------------------------------ send 1306 bytes to udp/[10.1.1.3]:21194 at 20:37:38.082944: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.1.3:21194;branch=z9hG4bK-d8754z-7013cd70d2e6694e-1---d8754z-;rport=21194 From: ;tag=fc96497b To: ;tag=U2j4a595c7cXN Call-ID: OWViNzk2ZmFlMzQ1YWFkZTY3ZDM1ODMyNmQ5ZGIwMjI CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20150108T034022Z~1ed290e930~64bit 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: 398 Remote-Party-ID: "Outbound Call" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1420710602 1420710603 IN IP4 10.1.1.1 s=FreeSWITCH c=IN IP4 10.1.1.1 t=0 0 m=audio 19038 RTP/AVP 125 101 a=rtpmap:125 opus/48000/2 a=fmtp:125 useinbandfec=1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 29642 RTP/AVP 115 a=rtpmap:115 H263-1998/90000 freeswitch@internal>