freeswitch@test> sofia global siptrace on +OK Global siptrace on recv 751 bytes from udp/[192.168.1.166]:52290 at 17:03:19.386127: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.166;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.166:52290;branch=z9hG4bK-524287-1---8600afbc9bef3bae;rport Max-Forwards: 70 Contact: To: From: ;tag=6544b655 Call-ID: jYevjHAm1_ygYqwyPAyFbQ.. CSeq: 1 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE Content-Type: application/sdp User-Agent: Z 5.4.12 v2.10.13.2-mod Allow-Events: presence, kpml, talk Content-Length: 188 v=0 o=Z 1639587799318 1 IN IP4 192.168.1.166 s=Z c=IN IP4 192.168.1.166 t=0 0 m=audio 8000 RTP/AVP 106 a=rtpmap:106 opus/48000/2 a=fmtp:106 minptime=20; useinbandfec=1 a=sendrecv 2021-12-15 17:03:19.380771 96.50% [NOTICE] switch_channel.c:1123 New Channel sofia/internal/1000@192.168.1.166 [4c46c0fd-19c3-4c49-ba6f-c8f7f286f93b] 2021-12-15 17:03:19.380771 96.50% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1000@192.168.1.166) Running State Change CS_NEW (Cur 1 Tot 3) 2021-12-15 17:03:19.380771 96.50% [INFO] sofia.c:10462 sofia/internal/1000@192.168.1.166 receiving invite from 192.168.1.166:52290 version: 1.10.8-dev git e428be3 2021-11-17 19:23:28Z 64bit call-id: jYevjHAm1_ygYqwyPAyFbQ.. 2021-12-15 17:03:19.380771 96.50% [DEBUG] sofia.c:10556 verifying acl "domains" for ip/port 192.168.1.166:0. 2021-12-15 17:03:19.380771 96.50% [DEBUG] switch_core_state_machine.c:600 (sofia/internal/1000@192.168.1.166) State NEW send 861 bytes to udp/[192.168.1.166]:52290 at 17:03:19.386962: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.166:52290;branch=z9hG4bK-524287-1---8600afbc9bef3bae;rport=52290 From: ;tag=6544b655 To: ;tag=j6r09BX2XXH8H Call-ID: jYevjHAm1_ygYqwyPAyFbQ.. CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211117T192328Z~e428be3f1a~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="192.168.1.166", nonce="8f8b8c68-6c09-49fb-a04a-bbf41670c893", algorithm=MD5, qop="auth" Content-Length: 0 2021-12-15 17:03:19.380771 96.50% [DEBUG] sofia.c:2419 detaching session 4c46c0fd-19c3-4c49-ba6f-c8f7f286f93b recv 331 bytes from udp/[192.168.1.166]:52290 at 17:03:19.387264: ------------------------------------------------------------------------ ACK sip:1001@192.168.1.166;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.166:52290;branch=z9hG4bK-524287-1---8600afbc9bef3bae;rport Max-Forwards: 70 To: ;tag=j6r09BX2XXH8H From: ;tag=6544b655 Call-ID: jYevjHAm1_ygYqwyPAyFbQ.. CSeq: 1 ACK Content-Length: 0 recv 1027 bytes from udp/[192.168.1.166]:52290 at 17:03:19.387366: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.166;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.166:52290;branch=z9hG4bK-524287-1---7fd5c555ce774478;rport Max-Forwards: 70 Contact: To: From: ;tag=6544b655 Call-ID: jYevjHAm1_ygYqwyPAyFbQ.. CSeq: 2 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE Content-Type: application/sdp Proxy-Authorization: Digest username="1000",realm="192.168.1.166",nonce="8f8b8c68-6c09-49fb-a04a-bbf41670c893",uri="sip:1001@192.168.1.166;transport=UDP",response="613a4ec442386ecfccf8a34411da8f73",cnonce="20d2c9c110b3b5de3a43ed3c3727e74d",nc=00000001,qop=auth,algorithm=MD5 User-Agent: Z 5.4.12 v2.10.13.2-mod Allow-Events: presence, kpml, talk Content-Length: 188 v=0 o=Z 1639587799318 1 IN IP4 192.168.1.166 s=Z c=IN IP4 192.168.1.166 t=0 0 m=audio 8000 RTP/AVP 106 a=rtpmap:106 opus/48000/2 a=fmtp:106 minptime=20; useinbandfec=1 a=sendrecv 2021-12-15 17:03:19.380771 96.50% [DEBUG] sofia.c:2532 Re-attaching to session 4c46c0fd-19c3-4c49-ba6f-c8f7f286f93b 2021-12-15 17:03:19.400733 96.50% [INFO] sofia.c:10462 sofia/internal/1000@192.168.1.166 receiving invite from 192.168.1.166:52290 version: 1.10.8-dev git e428be3 2021-11-17 19:23:28Z 64bit call-id: jYevjHAm1_ygYqwyPAyFbQ.. 2021-12-15 17:03:19.400733 96.50% [DEBUG] sofia.c:10556 verifying acl "domains" for ip/port 192.168.1.166:0. 2021-12-15 17:03:19.400733 96.50% [DEBUG] sofia.c:7499 Channel sofia/internal/1000@192.168.1.166 entering state [received][100] 2021-12-15 17:03:19.400733 96.50% [DEBUG] sofia.c:7509 Remote SDP: v=0 o=Z 1639587799318 1 IN IP4 192.168.1.166 s=Z c=IN IP4 192.168.1.166 t=0 0 m=audio 8000 RTP/AVP 106 a=rtpmap:106 opus/48000/2 a=fmtp:106 minptime=20; useinbandfec=1 2021-12-15 17:03:19.400733 96.50% [DEBUG] sofia.c:7912 (sofia/internal/1000@192.168.1.166) State Change CS_NEW -> CS_INIT 2021-12-15 17:03:19.400733 96.50% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1000@192.168.1.166) Running State Change CS_INIT (Cur 1 Tot 3) 2021-12-15 17:03:19.400733 96.50% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/1000@192.168.1.166) State INIT 2021-12-15 17:03:19.400733 96.50% [DEBUG] mod_sofia.c:97 sofia/internal/1000@192.168.1.166 SOFIA INIT 2021-12-15 17:03:19.400733 96.50% [DEBUG] switch_core_state_machine.c:40 sofia/internal/1000@192.168.1.166 Standard INIT 2021-12-15 17:03:19.400733 96.50% [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1000@192.168.1.166) State Change CS_INIT -> CS_ROUTING 2021-12-15 17:03:19.400733 96.50% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/1000@192.168.1.166) State INIT going to sleep 2021-12-15 17:03:19.400733 96.50% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1000@192.168.1.166) Running State Change CS_ROUTING (Cur 1 Tot 3) 2021-12-15 17:03:19.400733 96.50% [DEBUG] switch_channel.c:2380 (sofia/internal/1000@192.168.1.166) Callstate Change DOWN -> RINGING 2021-12-15 17:03:19.400733 96.50% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/1000@192.168.1.166) State ROUTING 2021-12-15 17:03:19.400733 96.50% [DEBUG] mod_sofia.c:158 sofia/internal/1000@192.168.1.166 SOFIA ROUTING 2021-12-15 17:03:19.400733 96.50% [DEBUG] switch_core_state_machine.c:230 sofia/internal/1000@192.168.1.166 Standard ROUTING 2021-12-15 17:03:19.400733 96.50% [INFO] mod_dialplan_xml.c:639 Processing 1000 <1000>->1001 in context default send 357 bytes to udp/[192.168.1.166]:52290 at 17:03:19.409407: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.166:52290;branch=z9hG4bK-524287-1---7fd5c555ce774478;rport=52290 From: ;tag=6544b655 To: Call-ID: jYevjHAm1_ygYqwyPAyFbQ.. CSeq: 2 INVITE User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211117T192328Z~e428be3f1a~64bit Content-Length: 0 Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->unloop] continue=false Dialplan: sofia/internal/1000@192.168.1.166 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->tod_example] continue=true Dialplan: sofia/internal/1000@192.168.1.166 Date/Time Match (PASS) [tod_example] break=on-false Dialplan: sofia/internal/1000@192.168.1.166 Action set(open=true) Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->holiday_example] continue=true Dialplan: sofia/internal/1000@192.168.1.166 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->global-intercept] continue=false Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [global-intercept] destination_number(1001) =~ /^886$/ break=on-false Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->group-intercept] continue=false Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [group-intercept] destination_number(1001) =~ /^\*8$/ break=on-false Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->intercept-ext] continue=false Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [intercept-ext] destination_number(1001) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->redial] continue=false Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [redial] destination_number(1001) =~ /^(redial|870)$/ break=on-false Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->global] continue=true Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/1000@192.168.1.166 Regex (PASS) [global] ${default_password}(1234) =~ /^1234$/ break=never Dialplan: sofia/internal/1000@192.168.1.166 Action log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING ) Dialplan: sofia/internal/1000@192.168.1.166 Action log(CRIT Open /usr/local/freeswitch/conf/vars.xml and change the default_password.) Dialplan: sofia/internal/1000@192.168.1.166 Action log(CRIT Once changed type 'reloadxml' at the console.) Dialplan: sofia/internal/1000@192.168.1.166 Action log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING ) Dialplan: sofia/internal/1000@192.168.1.166 Action sleep(10000) Dialplan: sofia/internal/1000@192.168.1.166 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/1000@192.168.1.166 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [global] ${switch_r_sdp}(v=0 o=Z 1639587799318 1 IN IP4 192.168.1.166 s=Z c=IN IP4 192.168.1.166 t=0 0 m=audio 8000 RTP/AVP 106 a=rtpmap:106 opus/48000/2 a=fmtp:106 minptime=20; useinbandfec=1 ) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never Dialplan: sofia/internal/1000@192.168.1.166 Absolute Condition [global] Dialplan: sofia/internal/1000@192.168.1.166 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) Dialplan: sofia/internal/1000@192.168.1.166 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/internal/1000@192.168.1.166 Action hash(insert/${domain_name}-last_dial/global/${uuid}) Dialplan: sofia/internal/1000@192.168.1.166 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->snom-demo-2] continue=false Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [snom-demo-2] destination_number(1001) =~ /^9001$/ break=on-false Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->snom-demo-1] continue=false Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [snom-demo-1] destination_number(1001) =~ /^9000$/ break=on-false Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^779$/ break=on-false Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->call_return] continue=false Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [call_return] destination_number(1001) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->del-group] continue=false Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [del-group] destination_number(1001) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->add-group] continue=false Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [add-group] destination_number(1001) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->call-group-simo] continue=false Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [call-group-simo] destination_number(1001) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->call-group-order] continue=false Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [call-group-order] destination_number(1001) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->extension-intercom] continue=false Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [extension-intercom] destination_number(1001) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->Local_Extension] continue=false Dialplan: sofia/internal/1000@192.168.1.166 Regex (PASS) [Local_Extension] destination_number(1001) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1000@192.168.1.166 Action export(dialed_extension=1001) Dialplan: sofia/internal/1000@192.168.1.166 Action bind_meta_app(1 b s execute_extension::dx XML features) Dialplan: sofia/internal/1000@192.168.1.166 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/1000@192.168.1.166 Action bind_meta_app(3 b s execute_extension::cf XML features) Dialplan: sofia/internal/1000@192.168.1.166 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) Dialplan: sofia/internal/1000@192.168.1.166 Action set(ringback=${us-ring}) Dialplan: sofia/internal/1000@192.168.1.166 Action set(transfer_ringback=local_stream://moh) Dialplan: sofia/internal/1000@192.168.1.166 Action set(call_timeout=30) Dialplan: sofia/internal/1000@192.168.1.166 Action set(hangup_after_bridge=true) Dialplan: sofia/internal/1000@192.168.1.166 Action set(continue_on_fail=true) Dialplan: sofia/internal/1000@192.168.1.166 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) Dialplan: sofia/internal/1000@192.168.1.166 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/internal/1000@192.168.1.166 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) Dialplan: sofia/internal/1000@192.168.1.166 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1000@192.168.1.166 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) Dialplan: sofia/internal/1000@192.168.1.166 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1000@192.168.1.166 Action bridge({absolute_codec_string=PCMA}user/${dialed_extension}@${domain_name}) Dialplan: sofia/internal/1000@192.168.1.166 Action answer() Dialplan: sofia/internal/1000@192.168.1.166 Action sleep(1000) Dialplan: sofia/internal/1000@192.168.1.166 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 2021-12-15 17:03:19.400733 96.50% [DEBUG] switch_core_state_machine.c:281 (sofia/internal/1000@192.168.1.166) State Change CS_ROUTING -> CS_EXECUTE 2021-12-15 17:03:19.400733 96.50% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/1000@192.168.1.166) State ROUTING going to sleep 2021-12-15 17:03:19.400733 96.50% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1000@192.168.1.166) Running State Change CS_EXECUTE (Cur 1 Tot 3) 2021-12-15 17:03:19.400733 96.50% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/1000@192.168.1.166) State EXECUTE 2021-12-15 17:03:19.400733 96.50% [DEBUG] mod_sofia.c:213 sofia/internal/1000@192.168.1.166 SOFIA EXECUTE 2021-12-15 17:03:19.400733 96.50% [DEBUG] switch_core_state_machine.c:323 sofia/internal/1000@192.168.1.166 Standard EXECUTE EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 set(open=true) 2021-12-15 17:03:19.400733 96.50% [DEBUG] mod_dptools.c:1685 SET sofia/internal/1000@192.168.1.166 [open]=[true] EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING ) 2021-12-15 17:03:19.400733 96.50% [CRIT] mod_dptools.c:1879 WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 log(CRIT Open /usr/local/freeswitch/conf/vars.xml and change the default_password.) 2021-12-15 17:03:19.400733 96.50% [CRIT] mod_dptools.c:1879 Open /usr/local/freeswitch/conf/vars.xml and change the default_password. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 log(CRIT Once changed type 'reloadxml' at the console.) 2021-12-15 17:03:19.400733 96.50% [CRIT] mod_dptools.c:1879 Once changed type 'reloadxml' at the console. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING ) 2021-12-15 17:03:19.400733 96.50% [CRIT] mod_dptools.c:1879 WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 sleep(10000) EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 hash(insert/192.168.1.166-spymap/1000/4c46c0fd-19c3-4c49-ba6f-c8f7f286f93b) EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 hash(insert/192.168.1.166-last_dial/1000/1001) EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 hash(insert/192.168.1.166-last_dial/global/4c46c0fd-19c3-4c49-ba6f-c8f7f286f93b) EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 export(RFC2822_DATE=Wed, 15 Dec 2021 17:03:29 +0000) 2021-12-15 17:03:29.460819 95.73% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [RFC2822_DATE]=[Wed, 15 Dec 2021 17:03:29 +0000] EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 export(dialed_extension=1001) 2021-12-15 17:03:29.480752 95.73% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [dialed_extension]=[1001] EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 bind_meta_app(1 b s execute_extension::dx XML features) 2021-12-15 17:03:29.480752 95.73% [INFO] switch_ivr_async.c:4774 Bound B-Leg: *1 execute_extension::dx XML features EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/1000.2021-12-15-17-03-29.wav) 2021-12-15 17:03:29.480752 95.73% [INFO] switch_ivr_async.c:4774 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/1000.2021-12-15-17-03-29.wav EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 bind_meta_app(3 b s execute_extension::cf XML features) 2021-12-15 17:03:29.480752 95.73% [INFO] switch_ivr_async.c:4774 Bound B-Leg: *3 execute_extension::cf XML features EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 bind_meta_app(4 b s execute_extension::att_xfer XML features) 2021-12-15 17:03:29.480752 95.73% [INFO] switch_ivr_async.c:4774 Bound B-Leg: *4 execute_extension::att_xfer XML features EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 set(ringback=%(2000,4000,440,480)) 2021-12-15 17:03:29.480752 95.73% [DEBUG] mod_dptools.c:1685 SET sofia/internal/1000@192.168.1.166 [ringback]=[%(2000,4000,440,480)] EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 set(transfer_ringback=local_stream://moh) 2021-12-15 17:03:29.480752 95.73% [DEBUG] mod_dptools.c:1685 SET sofia/internal/1000@192.168.1.166 [transfer_ringback]=[local_stream://moh] EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 set(call_timeout=30) 2021-12-15 17:03:29.480752 95.73% [DEBUG] mod_dptools.c:1685 SET sofia/internal/1000@192.168.1.166 [call_timeout]=[30] EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 set(hangup_after_bridge=true) 2021-12-15 17:03:29.480752 95.73% [DEBUG] mod_dptools.c:1685 SET sofia/internal/1000@192.168.1.166 [hangup_after_bridge]=[true] EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 set(continue_on_fail=true) 2021-12-15 17:03:29.480752 95.73% [DEBUG] mod_dptools.c:1685 SET sofia/internal/1000@192.168.1.166 [continue_on_fail]=[true] EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 hash(insert/192.168.1.166-call_return/1001/1000) EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 hash(insert/192.168.1.166-last_dial_ext/1001/4c46c0fd-19c3-4c49-ba6f-c8f7f286f93b) EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 set(called_party_callgroup=techsupport) 2021-12-15 17:03:29.480752 95.73% [DEBUG] mod_dptools.c:1685 SET sofia/internal/1000@192.168.1.166 [called_party_callgroup]=[techsupport] EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 hash(insert/192.168.1.166-last_dial_ext/techsupport/4c46c0fd-19c3-4c49-ba6f-c8f7f286f93b) EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 hash(insert/192.168.1.166-last_dial_ext/global/4c46c0fd-19c3-4c49-ba6f-c8f7f286f93b) EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 hash(insert/192.168.1.166-last_dial/techsupport/4c46c0fd-19c3-4c49-ba6f-c8f7f286f93b) EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 bridge({absolute_codec_string=PCMA}user/1001@192.168.1.166) 2021-12-15 17:03:29.480752 95.73% [DEBUG] switch_channel.c:1269 sofia/internal/1000@192.168.1.166 EXPORTING[export_vars] [RFC2822_DATE]=[Wed, 15 Dec 2021 17:03:29 +0000] to event 2021-12-15 17:03:29.480752 95.73% [DEBUG] switch_channel.c:1269 sofia/internal/1000@192.168.1.166 EXPORTING[export_vars] [dialed_extension]=[1001] to event 2021-12-15 17:03:29.480752 95.73% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables 2021-12-15 17:03:29.480752 95.73% [DEBUG] switch_channel.c:1269 sofia/internal/1000@192.168.1.166 EXPORTING[export_vars] [RFC2822_DATE]=[Wed, 15 Dec 2021 17:03:29 +0000] to event 2021-12-15 17:03:29.480752 95.73% [DEBUG] switch_channel.c:1269 sofia/internal/1000@192.168.1.166 EXPORTING[export_vars] [dialed_extension]=[1001] to event 2021-12-15 17:03:29.480752 95.73% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables 2021-12-15 17:03:29.480752 95.73% [NOTICE] switch_channel.c:1123 New Channel sofia/internal/1001@192.168.1.166:5090 [a867ec4e-35fc-4103-8b68-232a3626577c] 2021-12-15 17:03:29.480752 95.73% [DEBUG] mod_sofia.c:5121 (sofia/internal/1001@192.168.1.166:5090) State Change CS_NEW -> CS_INIT 2021-12-15 17:03:29.480752 95.73% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1001@192.168.1.166:5090) Running State Change CS_INIT (Cur 2 Tot 4) 2021-12-15 17:03:29.480752 95.73% [NOTICE] switch_ivr_originate.c:3039 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED] 2021-12-15 17:03:29.480752 95.73% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/1001@192.168.1.166:5090) State INIT 2021-12-15 17:03:29.480752 95.73% [DEBUG] mod_sofia.c:97 sofia/internal/1001@192.168.1.166:5090 SOFIA INIT 2021-12-15 17:03:29.480752 95.73% [INFO] sofia_glue.c:1651 sofia/internal/1001@192.168.1.166:5090 sending invite call-id: (null) 2021-12-15 17:03:29.480752 95.73% [DEBUG] sofia_glue.c:1654 sofia/internal/1001@192.168.1.166:5090 sending invite version: 1.10.8-dev git e428be3 2021-11-17 19:23:28Z 64bit Local SDP: v=0 o=FreeSWITCH 1639570095 1639570096 IN IP4 192.168.1.166 s=FreeSWITCH c=IN IP4 192.168.1.166 t=0 0 m=audio 17714 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 2021-12-15 17:03:29.480752 95.73% [DEBUG] switch_core_state_machine.c:40 sofia/internal/1001@192.168.1.166:5090 Standard INIT 2021-12-15 17:03:29.480752 95.73% [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1001@192.168.1.166:5090) State Change CS_INIT -> CS_ROUTING 2021-12-15 17:03:29.480752 95.73% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/1001@192.168.1.166:5090) State INIT going to sleep 2021-12-15 17:03:29.480752 95.73% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1001@192.168.1.166:5090) Running State Change CS_ROUTING (Cur 2 Tot 4) send 1214 bytes to udp/[192.168.1.166]:5090 at 17:03:29.496729: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.166:5090;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKgmj5BZ57HD72p Max-Forwards: 69 From: "Extension 1000" ;tag=mrBjD2y9QFyDS To: Call-ID: c4810aa7-d86b-123a-3585-dc1ba1ed361d CSeq: 45240112 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211117T192328Z~e428be3f1a~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: 222 X-FS-Support: update_display,send_info Remote-Party-ID: "Extension 1000" ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1639570095 1639570096 IN IP4 192.168.1.166 s=FreeSWITCH c=IN IP4 192.168.1.166 t=0 0 m=audio 17714 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 2021-12-15 17:03:29.480752 95.73% [DEBUG] sofia.c:7499 Channel sofia/internal/1001@192.168.1.166:5090 entering state [calling][0] 2021-12-15 17:03:29.480752 95.73% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/1001@192.168.1.166:5090) State ROUTING 2021-12-15 17:03:29.480752 95.73% [DEBUG] mod_sofia.c:158 sofia/internal/1001@192.168.1.166:5090 SOFIA ROUTING 2021-12-15 17:03:29.480752 95.73% [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1001@192.168.1.166:5090) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2021-12-15 17:03:29.480752 95.73% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/1001@192.168.1.166:5090) State ROUTING going to sleep 2021-12-15 17:03:29.480752 95.73% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1001@192.168.1.166:5090) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 4) 2021-12-15 17:03:29.480752 95.73% [DEBUG] switch_core_state_machine.c:659 (sofia/internal/1001@192.168.1.166:5090) State CONSUME_MEDIA 2021-12-15 17:03:29.480752 95.73% [DEBUG] switch_core_state_machine.c:659 (sofia/internal/1001@192.168.1.166:5090) State CONSUME_MEDIA going to sleep recv 274 bytes from udp/[192.168.1.166]:5090 at 17:03:29.510806: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKgmj5BZ57HD72p From: "Extension 1000" ;tag=mrBjD2y9QFyDS To: Call-ID: c4810aa7-d86b-123a-3585-dc1ba1ed361d CSeq: 45240112 INVITE recv 365 bytes from udp/[192.168.1.166]:5090 at 17:03:29.733151: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKgmj5BZ57HD72p From: "Extension 1000" ;tag=mrBjD2y9QFyDS To: ;tag=UHPPvfh Call-ID: c4810aa7-d86b-123a-3585-dc1ba1ed361d CSeq: 45240112 INVITE User-Agent: Linphone/3.12.0 (belle-sip/1.6.3) Supported: replaces, outbound 2021-12-15 17:03:29.720738 95.73% [DEBUG] sofia.c:7499 Channel sofia/internal/1001@192.168.1.166:5090 entering state [proceeding][180] 2021-12-15 17:03:29.720738 95.73% [NOTICE] sofia.c:7610 Ring-Ready sofia/internal/1001@192.168.1.166:5090! 2021-12-15 17:03:29.720738 95.73% [DEBUG] switch_channel.c:3494 (sofia/internal/1001@192.168.1.166:5090) Callstate Change DOWN -> RINGING 2021-12-15 17:03:29.720738 95.73% [INFO] switch_ivr_originate.c:1295 Sending early media 2021-12-15 17:03:29.720738 95.73% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:106:48000:20:0:1]/[opus:116:48000:20:0:1] 2021-12-15 17:03:29.720738 95.73% [DEBUG] switch_core_media.c:5707 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match 2021-12-15 17:03:29.720738 95.73% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:106:48000:20:0:1]/[G722:9:8000:20:64000:1] 2021-12-15 17:03:29.720738 95.73% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:106:48000:20:0:1]/[PCMU:0:8000:20:64000:1] 2021-12-15 17:03:29.720738 95.73% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:106:48000:20:0:1]/[PCMA:8:8000:20:64000:1] 2021-12-15 17:03:29.720738 95.73% [DEBUG] mod_opus.c:619 Opus encoder: set bitrate to local settings [72000bps] 2021-12-15 17:03:29.720738 95.73% [DEBUG] mod_opus.c:619 Opus encoder: set bitrate to local settings [72000bps] 2021-12-15 17:03:29.720738 95.73% [DEBUG] switch_core_media.c:3872 Set Codec sofia/internal/1000@192.168.1.166 opus/48000 20 ms 960 samples 0 bits 1 channels 2021-12-15 17:03:29.720738 95.73% [DEBUG] switch_core_codec.c:111 sofia/internal/1000@192.168.1.166 Original read codec set to opus:116 2021-12-15 17:03:29.720738 95.73% [DEBUG] switch_core_media.c:5946 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event. 2021-12-15 17:03:29.720738 95.73% [DEBUG] switch_core_media.c:5975 sofia/internal/1000@192.168.1.166 Set 2833 dtmf send payload to 101 recv payload to 101 2021-12-15 17:03:29.720738 95.73% [DEBUG] switch_core_media.c:8779 AUDIO RTP [sofia/internal/1000@192.168.1.166] 192.168.1.166 port 31558 -> 192.168.1.166 port 8000 codec: 106 ms: 20 2021-12-15 17:03:29.720738 95.73% [DEBUG] switch_rtp.c:4619 Starting timer [soft] 960 bytes per 20ms 2021-12-15 17:03:29.720738 95.73% [DEBUG] switch_core_media.c:9091 sofia/internal/1000@192.168.1.166 Set 2833 dtmf send payload to 101 2021-12-15 17:03:29.720738 95.73% [DEBUG] switch_core_media.c:9098 sofia/internal/1000@192.168.1.166 Set 2833 dtmf receive payload to 101 2021-12-15 17:03:29.720738 95.73% [DEBUG] switch_core_media.c:9121 sofia/internal/1000@192.168.1.166 Set rtp dtmf delay to 40 2021-12-15 17:03:29.720738 95.73% [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1000@192.168.1.166! 2021-12-15 17:03:29.720738 95.73% [DEBUG] switch_channel.c:3622 (sofia/internal/1000@192.168.1.166) Callstate Change RINGING -> EARLY 2021-12-15 17:03:29.740740 95.73% [DEBUG] switch_core_media.c:8761 Audio params are unchanged for sofia/internal/1000@192.168.1.166. 2021-12-15 17:03:29.740740 95.73% [DEBUG] mod_sofia.c:2610 Ring SDP: v=0 o=FreeSWITCH 1639556251 1639556252 IN IP4 192.168.1.166 s=FreeSWITCH c=IN IP4 192.168.1.166 t=0 0 m=audio 31558 RTP/AVP 106 101 a=rtpmap:106 opus/48000/2 a=fmtp:106 useinbandfec=1; minptime=20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv 2021-12-15 17:03:29.740740 95.73% [DEBUG] switch_ivr_originate.c:1353 Raw Codec Activation Success L16@48000hz 1 channel 20ms 2021-12-15 17:03:29.740740 95.73% [DEBUG] switch_core_codec.c:223 sofia/internal/1000@192.168.1.166 Push codec L16:100 2021-12-15 17:03:29.740740 95.73% [DEBUG] switch_ivr_originate.c:1427 Play Ringback Tone [%(2000,4000,440,480)] send 1197 bytes to udp/[192.168.1.166]:52290 at 17:03:29.740968: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 192.168.1.166:52290;branch=z9hG4bK-524287-1---7fd5c555ce774478;rport=52290 From: ;tag=6544b655 To: ;tag=KFjSB7D6t67tD Call-ID: jYevjHAm1_ygYqwyPAyFbQ.. CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211117T192328Z~e428be3f1a~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: 269 Remote-Party-ID: "1001" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1639556251 1639556252 IN IP4 192.168.1.166 s=FreeSWITCH c=IN IP4 192.168.1.166 t=0 0 m=audio 31558 RTP/AVP 106 101 a=rtpmap:106 opus/48000/2 a=fmtp:106 useinbandfec=1; minptime=20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 2021-12-15 17:03:29.760732 95.73% [DEBUG] sofia.c:7499 Channel sofia/internal/1000@192.168.1.166 entering state [early][183] 2021-12-15 17:03:30.000733 95.67% [DEBUG] switch_rtp.c:7934 Correct audio ip/port confirmed. recv 772 bytes from udp/[192.168.1.166]:5090 at 17:03:31.052910: ------------------------------------------------------------------------ SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKgmj5BZ57HD72p From: "Extension 1000" ;tag=mrBjD2y9QFyDS To: ;tag=UHPPvfh Call-ID: c4810aa7-d86b-123a-3585-dc1ba1ed361d CSeq: 45240112 INVITE User-Agent: Linphone/3.12.0 (belle-sip/1.6.3) Supported: replaces, outbound Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE Contact: "Li" ;+sip.instance="" Content-Type: application/sdp Content-Length: 146 v=0 o=9999 3273 1710 IN IP4 192.168.1.166 s=Talk c=IN IP4 192.168.1.166 t=0 0 m=audio 7078 RTP/AVP 8 101 a=rtpmap:101 telephone-event/8000 2021-12-15 17:03:31.040777 95.33% [DEBUG] sofia.c:7499 Channel sofia/internal/1001@192.168.1.166:5090 entering state [completing][200] 2021-12-15 17:03:31.040777 95.33% [DEBUG] sofia.c:7509 Remote SDP: v=0 o=9999 3273 1710 IN IP4 192.168.1.166 s=Talk c=IN IP4 192.168.1.166 t=0 0 m=audio 7078 RTP/AVP 8 101 a=rtpmap:101 telephone-event/8000 send 400 bytes to udp/[192.168.1.166]:5090 at 17:03:31.054907: ------------------------------------------------------------------------ ACK sip:9999@192.168.1.166:5090;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKHXByDtpBFpXNj Max-Forwards: 70 From: "Extension 1000" ;tag=mrBjD2y9QFyDS To: ;tag=UHPPvfh Call-ID: c4810aa7-d86b-123a-3585-dc1ba1ed361d CSeq: 45240112 ACK Contact: Content-Length: 0 2021-12-15 17:03:31.040777 95.33% [DEBUG] sofia.c:7499 Channel sofia/internal/1001@192.168.1.166:5090 entering state [ready][200] 2021-12-15 17:03:31.040777 95.33% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2021-12-15 17:03:31.040777 95.33% [DEBUG] switch_core_media.c:5707 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2021-12-15 17:03:31.040777 95.33% [DEBUG] switch_core_media.c:5568 Set telephone-event payload to 101@8000 2021-12-15 17:03:31.040777 95.33% [DEBUG] switch_core_media.c:3872 Set Codec sofia/internal/1001@192.168.1.166:5090 PCMA/8000 20 ms 160 samples 64000 bits 1 channels 2021-12-15 17:03:31.040777 95.33% [DEBUG] switch_core_codec.c:111 sofia/internal/1001@192.168.1.166:5090 Original read codec set to PCMA:8 2021-12-15 17:03:31.040777 95.33% [DEBUG] switch_core_media.c:5917 Set telephone-event payload to 101@8000 2021-12-15 17:03:31.040777 95.33% [DEBUG] switch_core_media.c:5975 sofia/internal/1001@192.168.1.166:5090 Set 2833 dtmf send payload to 101 recv payload to 101 2021-12-15 17:03:31.040777 95.33% [DEBUG] switch_core_media.c:8779 AUDIO RTP [sofia/internal/1001@192.168.1.166:5090] 192.168.1.166 port 17714 -> 192.168.1.166 port 7078 codec: 8 ms: 20 2021-12-15 17:03:31.040777 95.33% [DEBUG] switch_rtp.c:4619 Starting timer [soft] 160 bytes per 20ms 2021-12-15 17:03:31.040777 95.33% [DEBUG] switch_core_media.c:9091 sofia/internal/1001@192.168.1.166:5090 Set 2833 dtmf send payload to 101 2021-12-15 17:03:31.040777 95.33% [DEBUG] switch_core_media.c:9098 sofia/internal/1001@192.168.1.166:5090 Set 2833 dtmf receive payload to 101 2021-12-15 17:03:31.040777 95.33% [DEBUG] switch_core_media.c:9121 sofia/internal/1001@192.168.1.166:5090 Set rtp dtmf delay to 40 2021-12-15 17:03:31.040777 95.33% [NOTICE] sofia.c:8683 Channel [sofia/internal/1001@192.168.1.166:5090] has been answered 2021-12-15 17:03:31.040777 95.33% [DEBUG] switch_channel.c:3950 (sofia/internal/1001@192.168.1.166:5090) Callstate Change RINGING -> ACTIVE 2021-12-15 17:03:31.040777 95.33% [DEBUG] switch_core_codec.c:248 sofia/internal/1000@192.168.1.166 Restore previous codec opus:116. 2021-12-15 17:03:31.060758 95.33% [DEBUG] switch_core_media.c:8761 Audio params are unchanged for sofia/internal/1000@192.168.1.166. 2021-12-15 17:03:31.060758 95.33% [DEBUG] mod_sofia.c:913 Local SDP sofia/internal/1000@192.168.1.166: v=0 o=FreeSWITCH 1639556251 1639556253 IN IP4 192.168.1.166 s=FreeSWITCH c=IN IP4 192.168.1.166 t=0 0 m=audio 31558 RTP/AVP 106 101 a=rtpmap:106 opus/48000/2 a=fmtp:106 useinbandfec=1; minptime=20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv 2021-12-15 17:03:31.060758 95.33% [NOTICE] switch_ivr_originate.c:3834 Channel [sofia/internal/1000@192.168.1.166] has been answered send 1167 bytes to udp/[192.168.1.166]:52290 at 17:03:31.061297: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.166:52290;branch=z9hG4bK-524287-1---7fd5c555ce774478;rport=52290 From: ;tag=6544b655 To: ;tag=KFjSB7D6t67tD Call-ID: jYevjHAm1_ygYqwyPAyFbQ.. CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211117T192328Z~e428be3f1a~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: 269 Remote-Party-ID: "Outbound Call" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1639556251 1639556252 IN IP4 192.168.1.166 s=FreeSWITCH c=IN IP4 192.168.1.166 t=0 0 m=audio 31558 RTP/AVP 106 101 a=rtpmap:106 opus/48000/2 a=fmtp:106 useinbandfec=1; minptime=20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 2021-12-15 17:03:31.060758 95.33% [DEBUG] switch_channel.c:3950 (sofia/internal/1000@192.168.1.166) Callstate Change EARLY -> ACTIVE 2021-12-15 17:03:31.060758 95.33% [DEBUG] sofia.c:7499 Channel sofia/internal/1000@192.168.1.166 entering state [completed][200] 2021-12-15 17:03:31.060758 95.33% [DEBUG] switch_ivr_originate.c:3892 Originate Resulted in Success: [sofia/internal/1001@192.168.1.166:5090] Peer UUID: a867ec4e-35fc-4103-8b68-232a3626577c recv 428 bytes from udp/[192.168.1.166]:52290 at 17:03:31.061723: ------------------------------------------------------------------------ ACK sip:1001@192.168.1.166:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.1.166:52290;branch=z9hG4bK-524287-1---08d023c7b637dc0e;rport Max-Forwards: 70 Contact: To: ;tag=KFjSB7D6t67tD From: ;tag=6544b655 Call-ID: jYevjHAm1_ygYqwyPAyFbQ.. CSeq: 2 ACK User-Agent: Z 5.4.12 v2.10.13.2-mod Content-Length: 0 2021-12-15 17:03:31.060758 95.33% [DEBUG] sofia.c:7499 Channel sofia/internal/1000@192.168.1.166 entering state [ready][200] 2021-12-15 17:03:31.060758 95.33% [DEBUG] switch_ivr_originate.c:3892 Originate Resulted in Success: [sofia/internal/1001@192.168.1.166:5090] Peer UUID: a867ec4e-35fc-4103-8b68-232a3626577c 2021-12-15 17:03:31.060758 95.33% [DEBUG] switch_ivr_bridge.c:1793 (sofia/internal/1001@192.168.1.166:5090) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2021-12-15 17:03:31.060758 95.33% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1001@192.168.1.166:5090) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 4) 2021-12-15 17:03:31.060758 95.33% [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1001@192.168.1.166:5090) State EXCHANGE_MEDIA 2021-12-15 17:03:31.060758 95.33% [DEBUG] mod_sofia.c:671 SOFIA EXCHANGE_MEDIA 2021-12-15 17:03:31.100843 95.33% [DEBUG] switch_rtp.c:7934 Correct audio ip/port confirmed. 2021-12-15 17:03:31.100843 95.33% [NOTICE] switch_core_media.c:16153 Activating write resampler 2021-12-15 17:03:31.100843 95.33% [DEBUG] switch_rtp.c:7934 Correct audio ip/port confirmed. 2021-12-15 17:03:31.100843 95.33% [NOTICE] switch_core_media.c:16153 Activating write resampler recv 928 bytes from udp/[192.168.1.166]:5090 at 17:03:36.911648: ------------------------------------------------------------------------ INVITE sip:mod_sofia@192.168.1.166:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.166:5090;branch=z9hG4bK.SfSowul~m;rport From: ;tag=UHPPvfh To: "Extension 1000" ;tag=mrBjD2y9QFyDS CSeq: 111 INVITE Call-ID: c4810aa7-d86b-123a-3585-dc1ba1ed361d Max-Forwards: 70 Subject: Call on hold Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE Content-Type: application/sdp Content-Length: 281 Contact: "Li" ;+sip.instance="" User-Agent: Linphone/3.12.0 (belle-sip/1.6.3) v=0 o=9999 3273 1711 IN IP4 192.168.1.166 s=Talk c=IN IP4 192.168.1.166 t=0 0 a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics m=audio 7078 RTP/AVP 8 101 a=rtpmap:101 telephone-event/8000 a=sendonly a=rtcp-fb:* trr-int 5000 a=rtcp-fb:* ccm tmmbr send 371 bytes to udp/[192.168.1.166]:5090 at 17:03:36.918184: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.166:5090;branch=z9hG4bK.SfSowul~m;rport=5090 From: ;tag=UHPPvfh To: "Extension 1000" ;tag=mrBjD2y9QFyDS Call-ID: c4810aa7-d86b-123a-3585-dc1ba1ed361d CSeq: 111 INVITE User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211117T192328Z~e428be3f1a~64bit Content-Length: 0 2021-12-15 17:03:36.900851 93.23% [DEBUG] sofia.c:7499 Channel sofia/internal/1001@192.168.1.166:5090 entering state [received][100] 2021-12-15 17:03:36.900851 93.23% [DEBUG] sofia.c:7509 Remote SDP: v=0 o=9999 3273 1711 IN IP4 192.168.1.166 s=Talk c=IN IP4 192.168.1.166 t=0 0 a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics m=audio 7078 RTP/AVP 8 101 a=rtpmap:101 telephone-event/8000 a=sendonly a=rtcp-fb:* trr-int 5000 a=rtcp-fb:* ccm tmmbr 2021-12-15 17:03:36.900851 93.23% [DEBUG] switch_channel.c:1975 (sofia/internal/1001@192.168.1.166:5090) Callstate Change ACTIVE -> HELD 2021-12-15 17:03:37.060765 93.23% [DEBUG] switch_ivr.c:632 sofia/internal/1000@192.168.1.166 Command Execute [depth=0] playback(local_stream://moh) EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 playback(local_stream://moh) 2021-12-15 17:03:37.060765 93.23% [WARNING] mod_local_stream.c:874 Unknown source moh, trying 'default' 2021-12-15 17:03:37.060765 93.23% [ERR] mod_local_stream.c:882 Unknown source default 2021-12-15 17:03:37.160800 93.23% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2021-12-15 17:03:37.160800 93.23% [DEBUG] switch_core_media.c:5707 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2021-12-15 17:03:37.160800 93.23% [DEBUG] switch_core_media.c:5568 Set telephone-event payload to 101@8000 2021-12-15 17:03:37.160800 93.23% [DEBUG] switch_core_media.c:5917 Set telephone-event payload to 101@8000 2021-12-15 17:03:37.160800 93.23% [DEBUG] switch_core_media.c:5975 sofia/internal/1001@192.168.1.166:5090 Set 2833 dtmf send payload to 101 recv payload to 101 2021-12-15 17:03:37.160800 93.23% [DEBUG] switch_core_media.c:8761 Audio params are unchanged for sofia/internal/1001@192.168.1.166:5090. 2021-12-15 17:03:37.160800 93.23% [DEBUG] sofia.c:8454 Processing updated SDP 2021-12-15 17:03:37.160800 93.23% [INFO] sofia_glue.c:1651 sofia/internal/1000@192.168.1.166 sending invite call-id: (null) 2021-12-15 17:03:37.160800 93.23% [DEBUG] sofia_glue.c:1654 sofia/internal/1000@192.168.1.166 sending invite version: 1.10.8-dev git e428be3 2021-11-17 19:23:28Z 64bit Local SDP: v=0 o=FreeSWITCH 1639556251 1639556255 IN IP4 192.168.1.166 s=FreeSWITCH c=IN IP4 192.168.1.166 t=0 0 m=audio 31558 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendonly send 917 bytes to udp/[192.168.1.166]:52290 at 17:03:37.179829: ------------------------------------------------------------------------ INVITE sip:1000@192.168.1.166:52290;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKj64pFN7ecZK8D Max-Forwards: 70 From: ;tag=KFjSB7D6t67tD To: ;tag=6544b655 Call-ID: jYevjHAm1_ygYqwyPAyFbQ.. CSeq: 45240116 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211117T192328Z~e428be3f1a~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Type: application/sdp Content-Length: 234 X-FS-Support: update_display,send_info v=0 o=FreeSWITCH 1639556251 1639556255 IN IP4 192.168.1.166 s=FreeSWITCH c=IN IP4 192.168.1.166 t=0 0 m=audio 31558 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendonly recv 330 bytes from udp/[192.168.1.166]:52290 at 17:03:37.181142: ------------------------------------------------------------------------ SIP/2.0 415 Unsupported Media Type Via: SIP/2.0/UDP 192.168.1.166;rport=5060;branch=z9hG4bKj64pFN7ecZK8D To: ;tag=6544b655 From: ;tag=KFjSB7D6t67tD Call-ID: jYevjHAm1_ygYqwyPAyFbQ.. CSeq: 45240116 INVITE User-Agent: Z 5.4.12 v2.10.13.2-mod Content-Length: 0 send 323 bytes to udp/[192.168.1.166]:52290 at 17:03:37.181313: ------------------------------------------------------------------------ ACK sip:1000@192.168.1.166:52290;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKj64pFN7ecZK8D Max-Forwards: 70 From: ;tag=KFjSB7D6t67tD To: ;tag=6544b655 Call-ID: jYevjHAm1_ygYqwyPAyFbQ.. CSeq: 45240116 ACK Content-Length: 0 2021-12-15 17:03:37.180812 93.23% [DEBUG] sofia.c:7499 Channel sofia/internal/1000@192.168.1.166 entering state [calling][0] 2021-12-15 17:03:37.180812 93.23% [DEBUG] sofia.c:7492 Channel sofia/internal/1000@192.168.1.166 skipping state [ready][415]