- +OK log level [7]
- freeswitch@ib-ftrle-l> sofia global siptrace on
- +OK Global siptrace on
- recv 782 bytes from udp/[192.168.1.166]:59288 at 00:02:11.711602:
- ------------------------------------------------------------------------
- INVITE sip:1001@192.168.1.166;transport=UDP SIP/2.0
- Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---90ed98a9c1765058;rport
- Max-Forwards: 70
- Contact: <sip:1000@192.168.1.166:59288;transport=UDP>
- To: <sip:1001@192.168.1.166>
- From: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
- Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
- 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: 219
- v=0
- o=Z 1639699331625 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 102
- a=rtpmap:106 opus/48000/2
- a=fmtp:106 minptime=20; useinbandfec=1
- a=rtpmap:102 G726-32/8000
- a=sendrecv
- 2021-12-17 00:02:11.704345 88.03% [NOTICE] switch_channel.c:1123 New Channel sofia/internal/1000@192.168.1.166 [824d9cb7-133b-4e0e-ac98-aa7f6e5baf39]
- 2021-12-17 00:02:11.704345 88.03% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1000@192.168.1.166) Running State Change CS_NEW (Cur 1 Tot 5)
- 2021-12-17 00:02:11.704345 88.03% [INFO] sofia.c:10462 sofia/internal/1000@192.168.1.166 receiving invite from 192.168.1.166:59288 version: 1.10.8-dev git 862a19e 2021-12-09 14:45:56Z 64bit call-id: YJcHkXNZ5c5nQ6cX7u0pZg..
- 2021-12-17 00:02:11.704345 88.03% [DEBUG] sofia.c:10556 verifying acl "domains" for ip/port 192.168.1.166:0.
- 2021-12-17 00:02:11.704345 88.03% [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]:59288 at 00:02:11.712400:
- ------------------------------------------------------------------------
- SIP/2.0 407 Proxy Authentication Required
- Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---90ed98a9c1765058;rport=59288
- From: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
- To: <sip:1001@192.168.1.166>;tag=va2HcZH0pjeZg
- Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
- CSeq: 1 INVITE
- User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~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="8707b404-07a1-4a6a-aa51-ad8f38def438", algorithm=MD5, qop="auth"
- Content-Length: 0
- 2021-12-17 00:02:11.704345 88.03% [DEBUG] sofia.c:2419 detaching session 824d9cb7-133b-4e0e-ac98-aa7f6e5baf39
- recv 331 bytes from udp/[192.168.1.166]:59288 at 00:02:11.712674:
- ------------------------------------------------------------------------
- ACK sip:1001@192.168.1.166;transport=UDP SIP/2.0
- Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---90ed98a9c1765058;rport
- Max-Forwards: 70
- To: <sip:1001@192.168.1.166>;tag=va2HcZH0pjeZg
- From: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
- Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
- CSeq: 1 ACK
- Content-Length: 0
- recv 1058 bytes from udp/[192.168.1.166]:59288 at 00:02:11.712706:
- ------------------------------------------------------------------------
- INVITE sip:1001@192.168.1.166;transport=UDP SIP/2.0
- Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---131c3416fc3e61ee;rport
- Max-Forwards: 70
- Contact: <sip:1000@192.168.1.166:59288;transport=UDP>
- To: <sip:1001@192.168.1.166>
- From: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
- Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
- 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="8707b404-07a1-4a6a-aa51-ad8f38def438",uri="sip:1001@192.168.1.166;transport=UDP",response="c12824a47f3d4b2ee781d38b90fec022",cnonce="3768cf265e780979d5f7312b07b66fe4",nc=00000001,qop=auth,algorithm=MD5
- User-Agent: Z 5.4.12 v2.10.13.2-mod
- Allow-Events: presence, kpml, talk
- Content-Length: 219
- v=0
- o=Z 1639699331625 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 102
- a=rtpmap:106 opus/48000/2
- a=fmtp:106 minptime=20; useinbandfec=1
- a=rtpmap:102 G726-32/8000
- a=sendrecv
- 2021-12-17 00:02:11.704345 88.03% [DEBUG] sofia.c:2532 Re-attaching to session 824d9cb7-133b-4e0e-ac98-aa7f6e5baf39
- 2021-12-17 00:02:11.724307 88.03% [INFO] sofia.c:10462 sofia/internal/1000@192.168.1.166 receiving invite from 192.168.1.166:59288 version: 1.10.8-dev git 862a19e 2021-12-09 14:45:56Z 64bit call-id: YJcHkXNZ5c5nQ6cX7u0pZg..
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] sofia.c:10556 verifying acl "domains" for ip/port 192.168.1.166:0.
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] sofia.c:7499 Channel sofia/internal/1000@192.168.1.166 entering state [received][100]
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] sofia.c:7509 Remote SDP:
- v=0
- o=Z 1639699331625 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 102
- a=rtpmap:106 opus/48000/2
- a=fmtp:106 minptime=20; useinbandfec=1
- a=rtpmap:102 G726-32/8000
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] sofia.c:7912 (sofia/internal/1000@192.168.1.166) State Change CS_NEW -> CS_INIT
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1000@192.168.1.166) Running State Change CS_INIT (Cur 1 Tot 5)
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/1000@192.168.1.166) State INIT
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] mod_sofia.c:97 sofia/internal/1000@192.168.1.166 SOFIA INIT
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:40 sofia/internal/1000@192.168.1.166 Standard INIT
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1000@192.168.1.166) State Change CS_INIT -> CS_ROUTING
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/1000@192.168.1.166) State INIT going to sleep
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1000@192.168.1.166) Running State Change CS_ROUTING (Cur 1 Tot 5)
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_channel.c:2380 (sofia/internal/1000@192.168.1.166) Callstate Change DOWN -> RINGING
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/1000@192.168.1.166) State ROUTING
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] mod_sofia.c:158 sofia/internal/1000@192.168.1.166 SOFIA ROUTING
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:230 sofia/internal/1000@192.168.1.166 Standard ROUTING
- 2021-12-17 00:02:11.724307 88.03% [INFO] mod_dialplan_xml.c:639 Processing 1000 <1000>->1001 in context default
- send 357 bytes to udp/[192.168.1.166]:59288 at 00:02:11.733545:
- ------------------------------------------------------------------------
- SIP/2.0 100 Trying
- Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---131c3416fc3e61ee;rport=59288
- From: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
- To: <sip:1001@192.168.1.166>
- Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
- CSeq: 2 INVITE
- User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~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/TimeMatch (FAIL) [tod_example] break=on-false
- 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 (FAIL) [global] ${default_password}(nekipassword001) =~ /^1234$/ break=never
- 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 1639699331625 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 102
- a=rtpmap:106 opus/48000/2
- a=fmtp:106 minptime=20; useinbandfec=1
- a=rtpmap:102 G726-32/8000
- ) =~ /(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(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-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:281 (sofia/internal/1000@192.168.1.166) State Change CS_ROUTING -> CS_EXECUTE
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/1000@192.168.1.166) State ROUTING going to sleep
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1000@192.168.1.166) Running State Change CS_EXECUTE (Cur 1 Tot 5)
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/1000@192.168.1.166) State EXECUTE
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] mod_sofia.c:213 sofia/internal/1000@192.168.1.166 SOFIA EXECUTE
- 2021-12-17 00:02:11.724307 88.03% [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 hash(insert/192.168.1.166-spymap/1000/824d9cb7-133b-4e0e-ac98-aa7f6e5baf39)
- 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/824d9cb7-133b-4e0e-ac98-aa7f6e5baf39)
- EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 export(RFC2822_DATE=Fri, 17 Dec 2021 00:02:11 +0000)
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [RFC2822_DATE]=[Fri, 17 Dec 2021 00:02:11 +0000]
- EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 export(dialed_extension=1001)
- 2021-12-17 00:02:11.724307 88.03% [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-17 00:02:11.724307 88.03% [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-17-00-02-11.wav)
- 2021-12-17 00:02:11.724307 88.03% [INFO] switch_ivr_async.c:4774 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/1000.2021-12-17-00-02-11.wav
- EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 bind_meta_app(3 b s execute_extension::cf XML features)
- 2021-12-17 00:02:11.724307 88.03% [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-17 00:02:11.724307 88.03% [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-17 00:02:11.724307 88.03% [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-17 00:02:11.724307 88.03% [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-17 00:02:11.724307 88.03% [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-17 00:02:11.724307 88.03% [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-17 00:02:11.724307 88.03% [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/824d9cb7-133b-4e0e-ac98-aa7f6e5baf39)
- EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 set(called_party_callgroup=techsupport)
- 2021-12-17 00:02:11.724307 88.03% [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/824d9cb7-133b-4e0e-ac98-aa7f6e5baf39)
- EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 hash(insert/192.168.1.166-last_dial_ext/global/824d9cb7-133b-4e0e-ac98-aa7f6e5baf39)
- EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 hash(insert/192.168.1.166-last_dial/techsupport/824d9cb7-133b-4e0e-ac98-aa7f6e5baf39)
- EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 bridge(user/1001@192.168.1.166)
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_channel.c:1269 sofia/internal/1000@192.168.1.166 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 17 Dec 2021 00:02:11 +0000] to event
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_channel.c:1269 sofia/internal/1000@192.168.1.166 EXPORTING[export_vars] [dialed_extension]=[1001] to event
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_channel.c:1269 sofia/internal/1000@192.168.1.166 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 17 Dec 2021 00:02:11 +0000] to event
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_channel.c:1269 sofia/internal/1000@192.168.1.166 EXPORTING[export_vars] [dialed_extension]=[1001] to event
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables
- 2021-12-17 00:02:11.724307 88.03% [NOTICE] switch_channel.c:1123 New Channel sofia/internal/1001@192.168.1.166:5090 [74ae846e-94e3-4ad7-aae2-12072e73d15c]
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] mod_sofia.c:5121 (sofia/internal/1001@192.168.1.166:5090) State Change CS_NEW -> CS_INIT
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1001@192.168.1.166:5090) Running State Change CS_INIT (Cur 2 Tot 6)
- 2021-12-17 00:02:11.724307 88.03% [NOTICE] switch_ivr_originate.c:3039 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/1001@192.168.1.166:5090) State INIT
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] mod_sofia.c:97 sofia/internal/1001@192.168.1.166:5090 SOFIA INIT
- 2021-12-17 00:02:11.724307 88.03% [INFO] sofia_glue.c:1651 sofia/internal/1001@192.168.1.166:5090 sending invite call-id: (null)
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] sofia_glue.c:1654 sofia/internal/1001@192.168.1.166:5090 sending invite version: 1.10.8-dev git 862a19e 2021-12-09 14:45:56Z 64bit
- Local SDP:
- v=0
- o=FreeSWITCH 1639676175 1639676176 IN IP4 192.168.1.166
- s=FreeSWITCH
- c=IN IP4 192.168.1.166
- t=0 0
- m=audio 23156 RTP/AVP 102 101
- a=rtpmap:102 opus/48000/2
- a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
- a=rtpmap:101 telephone-event/48000
- a=fmtp:101 0-15
- a=ptime:20
- a=sendrecv
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:40 sofia/internal/1001@192.168.1.166:5090 Standard INIT
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1001@192.168.1.166:5090) State Change CS_INIT -> CS_ROUTING
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/1001@192.168.1.166:5090) State INIT going to sleep
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1001@192.168.1.166:5090) Running State Change CS_ROUTING (Cur 2 Tot 6)
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/1001@192.168.1.166:5090) State ROUTING
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] mod_sofia.c:158 sofia/internal/1001@192.168.1.166:5090 SOFIA ROUTING
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1001@192.168.1.166:5090) State Change CS_ROUTING -> CS_CONSUME_MEDIA
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/1001@192.168.1.166:5090) State ROUTING going to sleep
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1001@192.168.1.166:5090) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 6)
- send 1343 bytes to udp/[192.168.1.166]:5090 at 00:02:11.738307:
- ------------------------------------------------------------------------
- INVITE sip:1001@192.168.1.166:5090;transport=udp SIP/2.0
- Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKar1Q5HjHe9tQg
- Max-Forwards: 69
- From: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
- To: <sip:1001@192.168.1.166:5090;transport=udp>
- Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
- CSeq: 45295873 INVITE
- Contact: <sip:mod_sofia@192.168.1.166:5060>
- User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~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: 351
- X-FS-Support: update_display,send_info
- Remote-Party-ID: "Extension 1000" <sip:1000@192.168.1.166>;party=calling;screen=yes;privacy=off
- v=0
- o=FreeSWITCH 1639676175 1639676176 IN IP4 192.168.1.166
- s=FreeSWITCH
- c=IN IP4 192.168.1.166
- t=0 0
- m=audio 23156 RTP/AVP 102 101
- a=rtpmap:102 opus/48000/2
- a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
- a=rtpmap:101 telephone-event/48000
- a=fmtp:101 0-15
- a=ptime:20
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:659 (sofia/internal/1001@192.168.1.166:5090) State CONSUME_MEDIA
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_core_state_machine.c:659 (sofia/internal/1001@192.168.1.166:5090) State CONSUME_MEDIA going to sleep
- 2021-12-17 00:02:11.724307 88.03% [DEBUG] sofia.c:7499 Channel sofia/internal/1001@192.168.1.166:5090 entering state [calling][0]
- recv 274 bytes from udp/[192.168.1.166]:5090 at 00:02:11.756061:
- ------------------------------------------------------------------------
- SIP/2.0 100 Trying
- Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKar1Q5HjHe9tQg
- From: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
- To: <sip:1001@192.168.1.166:5090;transport=udp>
- Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
- CSeq: 45295873 INVITE
- recv 365 bytes from udp/[192.168.1.166]:5090 at 00:02:11.863917:
- ------------------------------------------------------------------------
- SIP/2.0 180 Ringing
- Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKar1Q5HjHe9tQg
- From: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
- To: <sip:1001@192.168.1.166:5090;transport=udp>;tag=Ei9E0KW
- Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
- CSeq: 45295873 INVITE
- User-Agent: Linphone/3.12.0 (belle-sip/1.6.3)
- Supported: replaces, outbound
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] sofia.c:7499 Channel sofia/internal/1001@192.168.1.166:5090 entering state [proceeding][180]
- 2021-12-17 00:02:11.864299 88.03% [NOTICE] sofia.c:7610 Ring-Ready sofia/internal/1001@192.168.1.166:5090!
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_channel.c:3494 (sofia/internal/1001@192.168.1.166:5090) Callstate Change DOWN -> RINGING
- 2021-12-17 00:02:11.864299 88.03% [INFO] switch_ivr_originate.c:1295 Sending early media
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:106:48000:20:0:1]/[opus:116:48000:20:0:1]
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_core_media.c:5707 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:106:48000:20:0:1]/[G722:9:8000:20:64000:1]
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:106:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:106:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [G726-32:102:8000:20:0:1]/[opus:116:48000:20:0:1]
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [G726-32:102:8000:20:0:1]/[G722:9:8000:20:64000:1]
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [G726-32:102:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [G726-32:102:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] mod_opus.c:619 Opus encoder: set bitrate to local settings [72000bps]
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] mod_opus.c:619 Opus encoder: set bitrate to local settings [72000bps]
- 2021-12-17 00:02:11.864299 88.03% [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-17 00:02:11.864299 88.03% [DEBUG] switch_core_codec.c:111 sofia/internal/1000@192.168.1.166 Original read codec set to opus:116
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_core_media.c:5946 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event.
- 2021-12-17 00:02:11.864299 88.03% [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-17 00:02:11.864299 88.03% [DEBUG] switch_core_media.c:8779 AUDIO RTP [sofia/internal/1000@192.168.1.166] 192.168.1.166 port 17898 -> 192.168.1.166 port 8000 codec: 106 ms: 20
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_rtp.c:4619 Starting timer [soft] 960 bytes per 20ms
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_core_media.c:9091 sofia/internal/1000@192.168.1.166 Set 2833 dtmf send payload to 101
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_core_media.c:9098 sofia/internal/1000@192.168.1.166 Set 2833 dtmf receive payload to 101
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_core_media.c:9121 sofia/internal/1000@192.168.1.166 Set rtp dtmf delay to 40
- 2021-12-17 00:02:11.864299 88.03% [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1000@192.168.1.166!
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_channel.c:3622 (sofia/internal/1000@192.168.1.166) Callstate Change RINGING -> EARLY
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_core_media.c:8761 Audio params are unchanged for sofia/internal/1000@192.168.1.166.
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] mod_sofia.c:2610 Ring SDP:
- v=0
- o=FreeSWITCH 1639681433 1639681434 IN IP4 192.168.1.166
- s=FreeSWITCH
- c=IN IP4 192.168.1.166
- t=0 0
- m=audio 17898 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-17 00:02:11.864299 88.03% [DEBUG] switch_ivr_originate.c:1353 Raw Codec Activation Success L16@48000hz 1 channel 20ms
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_core_codec.c:223 sofia/internal/1000@192.168.1.166 Push codec L16:100
- 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_ivr_originate.c:1427 Play Ringback Tone [%(2000,4000,440,480)]
- send 1197 bytes to udp/[192.168.1.166]:59288 at 00:02:11.883668:
- ------------------------------------------------------------------------
- SIP/2.0 183 Session Progress
- Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---131c3416fc3e61ee;rport=59288
- From: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
- To: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
- Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
- CSeq: 2 INVITE
- Contact: <sip:1001@192.168.1.166:5060;transport=udp>
- User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~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" <sip:1001@192.168.1.166>;party=calling;privacy=off;screen=no
- v=0
- o=FreeSWITCH 1639681433 1639681434 IN IP4 192.168.1.166
- s=FreeSWITCH
- c=IN IP4 192.168.1.166
- t=0 0
- m=audio 17898 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-17 00:02:11.904312 88.03% [DEBUG] sofia.c:7499 Channel sofia/internal/1000@192.168.1.166 entering state [early][183]
- 2021-12-17 00:02:11.924300 88.03% [DEBUG] switch_rtp.c:7934 Correct audio ip/port confirmed.
- recv 835 bytes from udp/[192.168.1.166]:5090 at 00:02:14.788475:
- ------------------------------------------------------------------------
- SIP/2.0 200 Ok
- Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKar1Q5HjHe9tQg
- From: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
- To: <sip:1001@192.168.1.166:5090;transport=udp>;tag=Ei9E0KW
- Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
- CSeq: 45295873 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:9999@192.168.1.166:5090;transport=udp>;+sip.instance="<urn:uuid:b8fee09a-4790-44f6-88d1-69c76cc5c84a>"
- Content-Type: application/sdp
- Content-Length: 209
- v=0
- o=98765432100 404 3779 IN IP4 192.168.1.166
- s=Talk
- c=IN IP4 192.168.1.166
- t=0 0
- m=audio 7078 RTP/AVP 102 101
- a=rtpmap:102 opus/48000/2
- a=fmtp:102 useinbandfec=1
- a=rtpmap:101 telephone-event/48000
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] sofia.c:7499 Channel sofia/internal/1001@192.168.1.166:5090 entering state [completing][200]
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] sofia.c:7509 Remote SDP:
- v=0
- o=98765432100 404 3779 IN IP4 192.168.1.166
- s=Talk
- c=IN IP4 192.168.1.166
- t=0 0
- m=audio 7078 RTP/AVP 102 101
- a=rtpmap:102 opus/48000/2
- a=fmtp:102 useinbandfec=1
- a=rtpmap:101 telephone-event/48000
- send 400 bytes to udp/[192.168.1.166]:5090 at 00:02:14.789563:
- ------------------------------------------------------------------------
- ACK sip:9999@192.168.1.166:5090;transport=udp SIP/2.0
- Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKB1tg7c3mBjHac
- Max-Forwards: 70
- From: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
- To: <sip:1001@192.168.1.166:5090;transport=udp>;tag=Ei9E0KW
- Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
- CSeq: 45295873 ACK
- Contact: <sip:mod_sofia@192.168.1.166:5060>
- Content-Length: 0
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] sofia.c:7499 Channel sofia/internal/1001@192.168.1.166:5090 entering state [ready][200]
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:2]
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_core_media.c:5707 Audio Codec Compare [opus:116:48000:20:0:2] ++++ is saved as a match
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_core_media.c:5568 Set telephone-event payload to 101@48000
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] mod_opus.c:619 Opus encoder: set bitrate to local settings [72000bps]
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] mod_opus.c:619 Opus encoder: set bitrate to local settings [72000bps]
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_core_media.c:3872 Set Codec sofia/internal/1001@192.168.1.166:5090 opus/48000 20 ms 960 samples 0 bits 1 channels
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_core_codec.c:111 sofia/internal/1001@192.168.1.166:5090 Original read codec set to opus:116
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_core_media.c:5917 Set telephone-event payload to 101@48000
- 2021-12-17 00:02:14.784299 87.57% [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-17 00:02:14.784299 87.57% [DEBUG] switch_core_media.c:8779 AUDIO RTP [sofia/internal/1001@192.168.1.166:5090] 192.168.1.166 port 23156 -> 192.168.1.166 port 7078 codec: 102 ms: 20
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_rtp.c:4619 Starting timer [soft] 960 bytes per 20ms
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_core_media.c:9091 sofia/internal/1001@192.168.1.166:5090 Set 2833 dtmf send payload to 101
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_core_media.c:9098 sofia/internal/1001@192.168.1.166:5090 Set 2833 dtmf receive payload to 101
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_core_media.c:9121 sofia/internal/1001@192.168.1.166:5090 Set rtp dtmf delay to 40
- 2021-12-17 00:02:14.784299 87.57% [NOTICE] sofia.c:8683 Channel [sofia/internal/1001@192.168.1.166:5090] has been answered
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_channel.c:3950 (sofia/internal/1001@192.168.1.166:5090) Callstate Change RINGING -> ACTIVE
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_core_codec.c:248 sofia/internal/1000@192.168.1.166 Restore previous codec opus:116.
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_core_media.c:8761 Audio params are unchanged for sofia/internal/1000@192.168.1.166.
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] mod_sofia.c:913 Local SDP sofia/internal/1000@192.168.1.166:
- v=0
- o=FreeSWITCH 1639681433 1639681435 IN IP4 192.168.1.166
- s=FreeSWITCH
- c=IN IP4 192.168.1.166
- t=0 0
- m=audio 17898 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-17 00:02:14.784299 87.57% [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]:59288 at 00:02:14.801617:
- ------------------------------------------------------------------------
- SIP/2.0 200 OK
- Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---131c3416fc3e61ee;rport=59288
- From: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
- To: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
- Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
- CSeq: 2 INVITE
- Contact: <sip:1001@192.168.1.166:5060;transport=udp>
- User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~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" <sip:1001@192.168.1.166>;party=calling;privacy=off;screen=no
- v=0
- o=FreeSWITCH 1639681433 1639681434 IN IP4 192.168.1.166
- s=FreeSWITCH
- c=IN IP4 192.168.1.166
- t=0 0
- m=audio 17898 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-17 00:02:14.784299 87.57% [DEBUG] switch_channel.c:3950 (sofia/internal/1000@192.168.1.166) Callstate Change EARLY -> ACTIVE
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] sofia.c:7499 Channel sofia/internal/1000@192.168.1.166 entering state [completed][200]
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_ivr_originate.c:3892 Originate Resulted in Success: [sofia/internal/1001@192.168.1.166:5090] Peer UUID: 74ae846e-94e3-4ad7-aae2-12072e73d15c
- recv 428 bytes from udp/[192.168.1.166]:59288 at 00:02:14.802048:
- ------------------------------------------------------------------------
- ACK sip:1001@192.168.1.166:5060;transport=udp SIP/2.0
- Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---b677280fdbb70809;rport
- Max-Forwards: 70
- Contact: <sip:1000@192.168.1.166:59288;transport=UDP>
- To: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
- From: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
- Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
- CSeq: 2 ACK
- User-Agent: Z 5.4.12 v2.10.13.2-mod
- Content-Length: 0
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] sofia.c:7499 Channel sofia/internal/1000@192.168.1.166 entering state [ready][200]
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_ivr_originate.c:3892 Originate Resulted in Success: [sofia/internal/1001@192.168.1.166:5090] Peer UUID: 74ae846e-94e3-4ad7-aae2-12072e73d15c
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_ivr_bridge.c:1793 (sofia/internal/1001@192.168.1.166:5090) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1001@192.168.1.166:5090) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 6)
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1001@192.168.1.166:5090) State EXCHANGE_MEDIA
- 2021-12-17 00:02:14.784299 87.57% [DEBUG] mod_sofia.c:671 SOFIA EXCHANGE_MEDIA
- 2021-12-17 00:02:14.844336 87.57% [DEBUG] switch_rtp.c:7934 Correct audio ip/port confirmed.
- 2021-12-17 00:02:14.844336 87.57% [DEBUG] switch_rtp.c:7934 Correct audio ip/port confirmed.
- 2021-12-17 00:02:14.844336 87.57% [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
- 2021-12-17 00:02:14.844336 87.57% [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
- 2021-12-17 00:02:14.844336 87.57% [DEBUG] mod_opus.c:619 Opus encoder: set bitrate to local settings [72000bps]
- 2021-12-17 00:02:14.864333 87.57% [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
- 2021-12-17 00:02:14.864333 87.57% [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
- 2021-12-17 00:02:14.864333 87.57% [DEBUG] mod_opus.c:619 Opus encoder: set bitrate to local settings [72000bps]
- recv 991 bytes from udp/[192.168.1.166]:5090 at 00:02:18.744944:
- ------------------------------------------------------------------------
- INVITE sip:mod_sofia@192.168.1.166:5060 SIP/2.0
- Via: SIP/2.0/UDP 192.168.1.166:5090;branch=z9hG4bK.kpCrA45jY;rport
- From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
- To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
- CSeq: 111 INVITE
- Call-ID: 6cf0a92a-d96f-123a-35ae-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: 344
- Contact: "Li" <sip:9999@192.168.1.166:5090;transport=udp>;+sip.instance="<urn:uuid:b8fee09a-4790-44f6-88d1-69c76cc5c84a>"
- User-Agent: Linphone/3.12.0 (belle-sip/1.6.3)
- v=0
- o=98765432100 404 3780 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 102 101
- a=rtpmap:102 opus/48000/2
- a=fmtp:102 useinbandfec=1
- a=rtpmap:101 telephone-event/48000
- a=sendonly
- a=rtcp-fb:* trr-int 5000
- a=rtcp-fb:* ccm tmmbr
- send 371 bytes to udp/[192.168.1.166]:5090 at 00:02:18.750743:
- ------------------------------------------------------------------------
- SIP/2.0 100 Trying
- Via: SIP/2.0/UDP 192.168.1.166:5090;branch=z9hG4bK.kpCrA45jY;rport=5090
- From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
- To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
- Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
- CSeq: 111 INVITE
- User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
- Content-Length: 0
- 2021-12-17 00:02:18.744298 87.70% [DEBUG] sofia.c:7499 Channel sofia/internal/1001@192.168.1.166:5090 entering state [received][100]
- 2021-12-17 00:02:18.744298 87.70% [DEBUG] sofia.c:7509 Remote SDP:
- v=0
- o=98765432100 404 3780 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 102 101
- a=rtpmap:102 opus/48000/2
- a=fmtp:102 useinbandfec=1
- a=rtpmap:101 telephone-event/48000
- a=sendonly
- a=rtcp-fb:* trr-int 5000
- a=rtcp-fb:* ccm tmmbr
- 2021-12-17 00:02:18.744298 87.70% [DEBUG] switch_channel.c:1975 (sofia/internal/1001@192.168.1.166:5090) Callstate Change ACTIVE -> HELD
- 2021-12-17 00:02:18.884324 87.70% [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-17 00:02:18.884324 87.70% [WARNING] mod_local_stream.c:874 Unknown source moh, trying 'default'
- 2021-12-17 00:02:18.884324 87.70% [ERR] mod_local_stream.c:882 Unknown source default
- 2021-12-17 00:02:18.984346 87.70% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:1]
- 2021-12-17 00:02:18.984346 87.70% [DEBUG] switch_core_media.c:5707 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
- 2021-12-17 00:02:18.984346 87.70% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:102:48000:20:0:1]/[G722:9:8000:20:64000:1]
- 2021-12-17 00:02:18.984346 87.70% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:102:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
- 2021-12-17 00:02:18.984346 87.70% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:102:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
- 2021-12-17 00:02:18.984346 87.70% [DEBUG] switch_core_media.c:5568 Set telephone-event payload to 101@48000
- 2021-12-17 00:02:18.984346 87.70% [DEBUG] switch_core_media.c:5917 Set telephone-event payload to 101@48000
- 2021-12-17 00:02:18.984346 87.70% [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-17 00:02:18.984346 87.70% [DEBUG] switch_core_media.c:8761 Audio params are unchanged for sofia/internal/1001@192.168.1.166:5090.
- 2021-12-17 00:02:18.984346 87.70% [DEBUG] sofia.c:8454 Processing updated SDP
- 2021-12-17 00:02:19.004345 87.70% [INFO] sofia_glue.c:1651 sofia/internal/1000@192.168.1.166 sending invite call-id: (null)
- 2021-12-17 00:02:19.004345 87.70% [DEBUG] sofia_glue.c:1654 sofia/internal/1000@192.168.1.166 sending invite version: 1.10.8-dev git 862a19e 2021-12-09 14:45:56Z 64bit
- Local SDP:
- v=0
- o=FreeSWITCH 1639681433 1639681437 IN IP4 192.168.1.166
- s=FreeSWITCH
- c=IN IP4 192.168.1.166
- t=0 0
- m=audio 17898 RTP/AVP 106 101
- a=rtpmap:106 opus/48000/2
- a=fmtp:106 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
- a=rtpmap:101 telephone-event/48000
- a=fmtp:101 0-15
- a=ptime:20
- a=sendonly
- send 1046 bytes to udp/[192.168.1.166]:59288 at 00:02:19.021075:
- ------------------------------------------------------------------------
- INVITE sip:1000@192.168.1.166:59288;transport=UDP SIP/2.0
- Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKcam987Kr8t7vQ
- Max-Forwards: 70
- From: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
- To: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
- Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
- CSeq: 45295877 INVITE
- Contact: <sip:1001@192.168.1.166:5060;transport=udp>
- User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~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: 363
- X-FS-Support: update_display,send_info
- v=0
- o=FreeSWITCH 1639681433 1639681437 IN IP4 192.168.1.166
- s=FreeSWITCH
- c=IN IP4 192.168.1.166
- t=0 0
- m=audio 17898 RTP/AVP 106 101
- a=rtpmap:106 opus/48000/2
- a=fmtp:106 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
- a=rtpmap:101 telephone-event/48000
- a=fmtp:101 0-15
- a=ptime:20
- a=sendonly
- recv 724 bytes from udp/[192.168.1.166]:59288 at 00:02:19.021654:
- ------------------------------------------------------------------------
- SIP/2.0 200 OK
- Via: SIP/2.0/UDP 192.168.1.166;rport=5060;branch=z9hG4bKcam987Kr8t7vQ
- Contact: <sip:1000@192.168.1.166:59288;transport=UDP>
- To: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
- From: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
- Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
- CSeq: 45295877 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: 207
- v=0
- o=Z 0 2 IN IP4 192.168.1.166
- s=Z
- c=IN IP4 192.168.1.166
- t=0 0
- m=audio 8000 RTP/AVP 106 102
- a=rtpmap:106 opus/48000/2
- a=fmtp:106 minptime=10; useinbandfec=1
- a=rtpmap:102 G726-32/8000
- a=inactive
- 2021-12-17 00:02:19.024304 87.70% [DEBUG] sofia.c:7499 Channel sofia/internal/1000@192.168.1.166 entering state [calling][0]
- 2021-12-17 00:02:19.024304 87.70% [DEBUG] sofia.c:7499 Channel sofia/internal/1000@192.168.1.166 entering state [completing][200]
- 2021-12-17 00:02:19.024304 87.70% [DEBUG] sofia.c:7509 Remote SDP:
- v=0
- o=Z 0 2 IN IP4 192.168.1.166
- s=Z
- c=IN IP4 192.168.1.166
- t=0 0
- m=audio 8000 RTP/AVP 106 102
- a=rtpmap:106 opus/48000/2
- a=fmtp:106 minptime=10; useinbandfec=1
- a=rtpmap:102 G726-32/8000
- a=inactive
- send 323 bytes to udp/[192.168.1.166]:59288 at 00:02:19.042185:
- ------------------------------------------------------------------------
- ACK sip:1000@192.168.1.166:59288;transport=UDP SIP/2.0
- Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKDKD2a34U53XFK
- Max-Forwards: 70
- From: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
- To: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
- Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
- CSeq: 45295877 ACK
- Content-Length: 0
- 2021-12-17 00:02:19.044347 87.70% [DEBUG] sofia.c:7499 Channel sofia/internal/1000@192.168.1.166 entering state [ready][200]
- 2021-12-17 00:02:19.044347 87.70% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:106:48000:20:0:1]/[opus:116:48000:20:0:2]
- 2021-12-17 00:02:19.044347 87.70% [DEBUG] switch_core_media.c:5707 Audio Codec Compare [opus:116:48000:20:0:2] ++++ is saved as a match
- 2021-12-17 00:02:19.044347 87.70% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [G726-32:102:8000:20:0:1]/[opus:116:48000:20:0:2]
- 2021-12-17 00:02:19.044347 87.70% [DEBUG] switch_core_media.c:5946 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event.
- 2021-12-17 00:02:19.044347 87.70% [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-17 00:02:19.044347 87.70% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:1]
- 2021-12-17 00:02:19.044347 87.70% [DEBUG] switch_core_media.c:5707 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
- 2021-12-17 00:02:19.044347 87.70% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:2]
- 2021-12-17 00:02:19.044347 87.70% [DEBUG] switch_core_media.c:5707 Audio Codec Compare [opus:116:48000:20:0:2] ++++ is saved as a match
- 2021-12-17 00:02:19.044347 87.70% [DEBUG] switch_core_media.c:5568 Set telephone-event payload to 101@48000
- 2021-12-17 00:02:19.044347 87.70% [DEBUG] switch_core_media.c:5917 Set telephone-event payload to 101@48000
- 2021-12-17 00:02:19.044347 87.70% [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-17 00:02:19.044347 87.70% [DEBUG] switch_core_media.c:8761 Audio params are unchanged for sofia/internal/1001@192.168.1.166:5090.
- 2021-12-17 00:02:19.044347 87.70% [DEBUG] switch_core_media.c:8761 Audio params are unchanged for sofia/internal/1000@192.168.1.166.
- send 913 bytes to udp/[192.168.1.166]:5090 at 00:02:19.062788:
- ------------------------------------------------------------------------
- SIP/2.0 200 OK
- Via: SIP/2.0/UDP 192.168.1.166:5090;branch=z9hG4bK.kpCrA45jY;rport=5090
- From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
- To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
- Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
- CSeq: 111 INVITE
- Contact: <sip:mod_sofia@192.168.1.166:5060>
- User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
- Accept: application/sdp
- Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
- Supported: timer, path, replaces
- Content-Type: application/sdp
- Content-Disposition: session
- Content-Length: 269
- v=0
- o=FreeSWITCH 1639676175 1639676177 IN IP4 192.168.1.166
- s=FreeSWITCH
- c=IN IP4 192.168.1.166
- t=0 0
- m=audio 23156 RTP/AVP 102 101
- a=rtpmap:102 opus/48000/2
- a=fmtp:102 useinbandfec=1
- a=rtpmap:101 telephone-event/48000
- a=fmtp:101 0-15
- a=recvonly
- a=ptime:20
- recv 352 bytes from udp/[192.168.1.166]:5090 at 00:02:19.073423:
- ------------------------------------------------------------------------
- ACK sip:mod_sofia@192.168.1.166:5060 SIP/2.0
- Via: SIP/2.0/UDP 192.168.1.166:5090;rport;branch=z9hG4bK.stoY2noCJ
- From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
- To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
- CSeq: 111 ACK
- Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
- Max-Forwards: 70
- User-Agent: Linphone/3.12.0 (belle-sip/1.6.3)
- 2021-12-17 00:02:19.064298 87.70% [DEBUG] sofia.c:7499 Channel sofia/internal/1001@192.168.1.166:5090 entering state [completed][200]
- 2021-12-17 00:02:19.064298 87.70% [DEBUG] sofia.c:7499 Channel sofia/internal/1001@192.168.1.166:5090 entering state [ready][200]
- recv 849 bytes from udp/[192.168.1.166]:59288 at 00:02:19.678485:
- ------------------------------------------------------------------------
- REGISTER sip:192.168.1.166;transport=UDP SIP/2.0
- Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---0de007e033a26c39;rport
- Max-Forwards: 70
- Contact: <sip:1000@192.168.1.166:59288;rinstance=62ef940e00368058;transport=UDP>
- To: <sip:1000@192.168.1.166;transport=UDP>
- From: <sip:1000@192.168.1.166;transport=UDP>;tag=82ac1e74
- Call-ID: nB_ORf_VDWOygeHg5Zv_7A..
- CSeq: 22 REGISTER
- Expires: 60
- Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
- User-Agent: Z 5.4.12 v2.10.13.2-mod
- Authorization: Digest username="1000",realm="192.168.1.166",nonce="0a701d6a-caad-4496-ae13-32cec36f8c52",uri="sip:192.168.1.166;transport=UDP",response="907555048d9d7f5315758b8621c7289b",cnonce="e803f50ec2ea17d4f5968d9485c20f60",nc=00000015,qop=auth,algorithm=MD5
- Allow-Events: presence, kpml, talk
- Content-Length: 0
- send 662 bytes to udp/[192.168.1.166]:59288 at 00:02:19.679997:
- ------------------------------------------------------------------------
- SIP/2.0 200 OK
- Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---0de007e033a26c39;rport=59288
- From: <sip:1000@192.168.1.166;transport=UDP>;tag=82ac1e74
- To: <sip:1000@192.168.1.166;transport=UDP>;tag=Z5DvHg4aeDHQK
- Call-ID: nB_ORf_VDWOygeHg5Zv_7A..
- CSeq: 22 REGISTER
- Contact: <sip:1000@192.168.1.166:59288;rinstance=62ef940e00368058;transport=UDP>;expires=60
- Date: Fri, 17 Dec 2021 00:02:19 GMT
- User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
- Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
- Supported: timer, path, replaces
- Content-Length: 0
- recv 980 bytes from udp/[192.168.1.166]:5090 at 00:02:21.672533:
- ------------------------------------------------------------------------
- INVITE sip:mod_sofia@192.168.1.166:5060 SIP/2.0
- Via: SIP/2.0/UDP 192.168.1.166:5090;branch=z9hG4bK.6xCKL0Ct4;rport
- From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
- To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
- CSeq: 112 INVITE
- Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
- Max-Forwards: 70
- Subject: Call resuming
- Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
- Content-Type: application/sdp
- Content-Length: 332
- Contact: "Li" <sip:9999@192.168.1.166:5090;transport=udp>;+sip.instance="<urn:uuid:b8fee09a-4790-44f6-88d1-69c76cc5c84a>"
- User-Agent: Linphone/3.12.0 (belle-sip/1.6.3)
- v=0
- o=98765432100 404 3781 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 102 101
- a=rtpmap:102 opus/48000/2
- a=fmtp:102 useinbandfec=1
- a=rtpmap:101 telephone-event/48000
- a=rtcp-fb:* trr-int 5000
- a=rtcp-fb:* ccm tmmbr
- send 371 bytes to udp/[192.168.1.166]:5090 at 00:02:21.679922:
- ------------------------------------------------------------------------
- SIP/2.0 100 Trying
- Via: SIP/2.0/UDP 192.168.1.166:5090;branch=z9hG4bK.6xCKL0Ct4;rport=5090
- From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
- To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
- Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
- CSeq: 112 INVITE
- User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
- Content-Length: 0
- 2021-12-17 00:02:21.664341 87.37% [DEBUG] sofia.c:7499 Channel sofia/internal/1001@192.168.1.166:5090 entering state [received][100]
- 2021-12-17 00:02:21.664341 87.37% [DEBUG] sofia.c:7509 Remote SDP:
- v=0
- o=98765432100 404 3781 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 102 101
- a=rtpmap:102 opus/48000/2
- a=fmtp:102 useinbandfec=1
- a=rtpmap:101 telephone-event/48000
- a=rtcp-fb:* trr-int 5000
- a=rtcp-fb:* ccm tmmbr
- 2021-12-17 00:02:21.924324 87.37% [DEBUG] switch_channel.c:2160 (sofia/internal/1001@192.168.1.166:5090) Callstate Change HELD -> UNHELD
- 2021-12-17 00:02:21.924324 87.37% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:1]
- 2021-12-17 00:02:21.924324 87.37% [DEBUG] switch_core_media.c:5707 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
- 2021-12-17 00:02:21.924324 87.37% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:2]
- 2021-12-17 00:02:21.924324 87.37% [DEBUG] switch_core_media.c:5707 Audio Codec Compare [opus:116:48000:20:0:2] ++++ is saved as a match
- 2021-12-17 00:02:21.924324 87.37% [DEBUG] switch_core_media.c:5568 Set telephone-event payload to 101@48000
- 2021-12-17 00:02:21.924324 87.37% [DEBUG] switch_core_media.c:5917 Set telephone-event payload to 101@48000
- 2021-12-17 00:02:21.924324 87.37% [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-17 00:02:21.924324 87.37% [DEBUG] switch_core_media.c:8761 Audio params are unchanged for sofia/internal/1001@192.168.1.166:5090.
- 2021-12-17 00:02:21.924324 87.37% [DEBUG] sofia.c:8454 Processing updated SDP
- 2021-12-17 00:02:21.924324 87.37% [DEBUG] switch_core_io.c:941 (sofia/internal/1001@192.168.1.166:5090) Callstate Change UNHELD -> ACTIVE
- 2021-12-17 00:02:21.924324 87.37% [INFO] sofia_glue.c:1651 sofia/internal/1000@192.168.1.166 sending invite call-id: (null)
- 2021-12-17 00:02:21.924324 87.37% [DEBUG] sofia_glue.c:1654 sofia/internal/1000@192.168.1.166 sending invite version: 1.10.8-dev git 862a19e 2021-12-09 14:45:56Z 64bit
- Local SDP:
- v=0
- o=FreeSWITCH 1639681433 1639681439 IN IP4 192.168.1.166
- s=FreeSWITCH
- c=IN IP4 192.168.1.166
- t=0 0
- m=audio 17898 RTP/AVP 106 101
- a=rtpmap:106 opus/48000/2
- a=fmtp:106 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
- a=rtpmap:101 telephone-event/48000
- a=fmtp:101 0-15
- a=ptime:20
- a=sendrecv
- send 1046 bytes to udp/[192.168.1.166]:59288 at 00:02:21.941782:
- ------------------------------------------------------------------------
- INVITE sip:1000@192.168.1.166:59288;transport=UDP SIP/2.0
- Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKev6tcyNZ2cm2e
- Max-Forwards: 70
- From: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
- To: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
- Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
- CSeq: 45295878 INVITE
- Contact: <sip:1001@192.168.1.166:5060;transport=udp>
- User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~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: 363
- X-FS-Support: update_display,send_info
- v=0
- o=FreeSWITCH 1639681433 1639681439 IN IP4 192.168.1.166
- s=FreeSWITCH
- c=IN IP4 192.168.1.166
- t=0 0
- m=audio 17898 RTP/AVP 106 101
- a=rtpmap:106 opus/48000/2
- a=fmtp:106 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
- a=rtpmap:101 telephone-event/48000
- a=fmtp:101 0-15
- a=ptime:20
- a=sendrecv
- recv 724 bytes from udp/[192.168.1.166]:59288 at 00:02:21.943553:
- ------------------------------------------------------------------------
- SIP/2.0 200 OK
- Via: SIP/2.0/UDP 192.168.1.166;rport=5060;branch=z9hG4bKev6tcyNZ2cm2e
- Contact: <sip:1000@192.168.1.166:59288;transport=UDP>
- To: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
- From: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
- Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
- CSeq: 45295878 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: 207
- v=0
- o=Z 0 3 IN IP4 192.168.1.166
- s=Z
- c=IN IP4 192.168.1.166
- t=0 0
- m=audio 8000 RTP/AVP 106 102
- a=rtpmap:106 opus/48000/2
- a=fmtp:106 minptime=10; useinbandfec=1
- a=rtpmap:102 G726-32/8000
- a=sendrecv
- 2021-12-17 00:02:21.944327 87.37% [DEBUG] switch_rtp.c:7934 Correct audio ip/port confirmed.
- 2021-12-17 00:02:21.944327 87.37% [DEBUG] sofia.c:7499 Channel sofia/internal/1000@192.168.1.166 entering state [calling][0]
- 2021-12-17 00:02:21.965752 87.37% [DEBUG] sofia.c:7499 Channel sofia/internal/1000@192.168.1.166 entering state [completing][200]
- 2021-12-17 00:02:21.965752 87.37% [DEBUG] sofia.c:7509 Remote SDP:
- v=0
- o=Z 0 3 IN IP4 192.168.1.166
- s=Z
- c=IN IP4 192.168.1.166
- t=0 0
- m=audio 8000 RTP/AVP 106 102
- a=rtpmap:106 opus/48000/2
- a=fmtp:106 minptime=10; useinbandfec=1
- a=rtpmap:102 G726-32/8000
- a=sendrecv
- send 323 bytes to udp/[192.168.1.166]:59288 at 00:02:21.967327:
- ------------------------------------------------------------------------
- ACK sip:1000@192.168.1.166:59288;transport=UDP SIP/2.0
- Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKF5ZKeS62ZNaNa
- Max-Forwards: 70
- From: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
- To: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
- Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
- CSeq: 45295878 ACK
- Content-Length: 0
- 2021-12-17 00:02:21.965752 87.37% [DEBUG] sofia.c:7499 Channel sofia/internal/1000@192.168.1.166 entering state [ready][200]
- 2021-12-17 00:02:21.965752 87.37% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:106:48000:20:0:1]/[opus:116:48000:20:0:2]
- 2021-12-17 00:02:21.965752 87.37% [DEBUG] switch_core_media.c:5707 Audio Codec Compare [opus:116:48000:20:0:2] ++++ is saved as a match
- 2021-12-17 00:02:21.965752 87.37% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [G726-32:102:8000:20:0:1]/[opus:116:48000:20:0:2]
- 2021-12-17 00:02:21.965752 87.37% [DEBUG] switch_core_media.c:5946 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event.
- 2021-12-17 00:02:21.965752 87.37% [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-17 00:02:21.965752 87.37% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:1]
- 2021-12-17 00:02:21.965752 87.37% [DEBUG] switch_core_media.c:5707 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
- 2021-12-17 00:02:21.965752 87.37% [DEBUG] switch_core_media.c:5652 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:2]
- 2021-12-17 00:02:21.965752 87.37% [DEBUG] switch_core_media.c:5707 Audio Codec Compare [opus:116:48000:20:0:2] ++++ is saved as a match
- 2021-12-17 00:02:21.965752 87.37% [DEBUG] switch_core_media.c:5568 Set telephone-event payload to 101@48000
- 2021-12-17 00:02:21.965752 87.37% [DEBUG] switch_core_media.c:5917 Set telephone-event payload to 101@48000
- 2021-12-17 00:02:21.965752 87.37% [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-17 00:02:21.965752 87.37% [DEBUG] switch_core_media.c:8761 Audio params are unchanged for sofia/internal/1001@192.168.1.166:5090.
- 2021-12-17 00:02:21.965752 87.37% [DEBUG] switch_core_media.c:8761 Audio params are unchanged for sofia/internal/1000@192.168.1.166.
- send 901 bytes to udp/[192.168.1.166]:5090 at 00:02:21.971644:
- ------------------------------------------------------------------------
- SIP/2.0 200 OK
- Via: SIP/2.0/UDP 192.168.1.166:5090;branch=z9hG4bK.6xCKL0Ct4;rport=5090
- From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
- To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
- Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
- CSeq: 112 INVITE
- Contact: <sip:mod_sofia@192.168.1.166:5060>
- User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
- Accept: application/sdp
- Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
- Supported: timer, path, replaces
- Content-Type: application/sdp
- Content-Disposition: session
- Content-Length: 257
- v=0
- o=FreeSWITCH 1639676175 1639676178 IN IP4 192.168.1.166
- s=FreeSWITCH
- c=IN IP4 192.168.1.166
- t=0 0
- m=audio 23156 RTP/AVP 102 101
- a=rtpmap:102 opus/48000/2
- a=fmtp:102 useinbandfec=1
- a=rtpmap:101 telephone-event/48000
- a=fmtp:101 0-15
- a=ptime:20
- recv 352 bytes from udp/[192.168.1.166]:5090 at 00:02:21.986686:
- ------------------------------------------------------------------------
- ACK sip:mod_sofia@192.168.1.166:5060 SIP/2.0
- Via: SIP/2.0/UDP 192.168.1.166:5090;rport;branch=z9hG4bK.wa9dbc61E
- From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
- To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
- CSeq: 112 ACK
- Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
- Max-Forwards: 70
- User-Agent: Linphone/3.12.0 (belle-sip/1.6.3)
- 2021-12-17 00:02:21.965752 87.37% [DEBUG] sofia.c:7499 Channel sofia/internal/1001@192.168.1.166:5090 entering state [completed][200]
- 2021-12-17 00:02:21.965752 87.37% [DEBUG] sofia.c:7499 Channel sofia/internal/1001@192.168.1.166:5090 entering state [ready][200]
- recv 352 bytes from udp/[192.168.1.166]:5090 at 00:02:24.228829:
- ------------------------------------------------------------------------
- BYE sip:mod_sofia@192.168.1.166:5060 SIP/2.0
- Via: SIP/2.0/UDP 192.168.1.166:5090;branch=z9hG4bK.4552BGQnd;rport
- From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
- To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
- CSeq: 113 BYE
- Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
- Max-Forwards: 70
- User-Agent: Linphone/3.12.0 (belle-sip/1.6.3)
- 2021-12-17 00:02:24.224324 87.17% [NOTICE] sofia.c:1065 Hangup sofia/internal/1001@192.168.1.166:5090 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
- send 508 bytes to udp/[192.168.1.166]:5090 at 00:02:24.231447:
- ------------------------------------------------------------------------
- SIP/2.0 200 OK
- Via: SIP/2.0/UDP 192.168.1.166:5090;branch=z9hG4bK.4552BGQnd;rport=5090
- From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
- To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
- Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
- CSeq: 113 BYE
- User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
- Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
- Supported: timer, path, replaces
- Content-Length: 0
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_ivr_bridge.c:912 BRIDGE THREAD DONE [sofia/internal/1001@192.168.1.166:5090]
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1001@192.168.1.166:5090) State EXCHANGE_MEDIA going to sleep
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1001@192.168.1.166:5090) Running State Change CS_HANGUP (Cur 2 Tot 6)
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/1001@192.168.1.166:5090) Callstate Change ACTIVE -> HANGUP
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/1001@192.168.1.166:5090) State HANGUP
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_sofia.c:468 Channel sofia/internal/1001@192.168.1.166:5090 hanging up, cause: NORMAL_CLEARING
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:59 sofia/internal/1001@192.168.1.166:5090 Standard HANGUP, cause: NORMAL_CLEARING
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/1001@192.168.1.166:5090) State HANGUP going to sleep
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/1001@192.168.1.166:5090) State Change CS_HANGUP -> CS_REPORTING
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1001@192.168.1.166:5090) Running State Change CS_REPORTING (Cur 2 Tot 6)
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/1001@192.168.1.166:5090) State REPORTING
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:168 sofia/internal/1001@192.168.1.166:5090 Standard REPORTING, cause: NORMAL_CLEARING
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/1001@192.168.1.166:5090) State REPORTING going to sleep
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/1001@192.168.1.166:5090) State Change CS_REPORTING -> CS_DESTROY
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_session.c:1753 Session 6 (sofia/internal/1001@192.168.1.166:5090) Locked, Waiting on external entities
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_ivr_bridge.c:820 sofia/internal/1001@192.168.1.166:5090 ending bridge by request from write function
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_ivr_bridge.c:912 BRIDGE THREAD DONE [sofia/internal/1000@192.168.1.166]
- 2021-12-17 00:02:24.224324 87.17% [NOTICE] switch_ivr_bridge.c:1944 Hangup sofia/internal/1000@192.168.1.166 [CS_EXECUTE] [NORMAL_CLEARING]
- 2021-12-17 00:02:24.224324 87.17% [NOTICE] switch_core_session.c:1771 Session 6 (sofia/internal/1001@192.168.1.166:5090) Ended
- 2021-12-17 00:02:24.224324 87.17% [NOTICE] switch_core_session.c:1775 Close Channel sofia/internal/1001@192.168.1.166:5090 [CS_DESTROY]
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_session.c:2983 sofia/internal/1000@192.168.1.166 skip receive message [PHONE_EVENT] (channel is hungup already)
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/1000@192.168.1.166) State EXECUTE going to sleep
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1000@192.168.1.166) Running State Change CS_HANGUP (Cur 1 Tot 6)
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/1001@192.168.1.166:5090) Running State Change CS_DESTROY (Cur 1 Tot 6)
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/1001@192.168.1.166:5090) State DESTROY
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_sofia.c:379 sofia/internal/1001@192.168.1.166:5090 SOFIA DESTROY
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:175 sofia/internal/1001@192.168.1.166:5090 Standard DESTROY
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/1001@192.168.1.166:5090) State DESTROY going to sleep
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/1000@192.168.1.166) Callstate Change ACTIVE -> HANGUP
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/1000@192.168.1.166) State HANGUP
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_sofia.c:462 sofia/internal/1000@192.168.1.166 Overriding SIP cause 480 with 200 from the other leg
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_sofia.c:468 Channel sofia/internal/1000@192.168.1.166 hanging up, cause: NORMAL_CLEARING
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_sofia.c:522 Sending BYE to sofia/internal/1000@192.168.1.166
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:59 sofia/internal/1000@192.168.1.166 Standard HANGUP, cause: NORMAL_CLEARING
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/1000@192.168.1.166) State HANGUP going to sleep
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/1000@192.168.1.166) State Change CS_HANGUP -> CS_REPORTING
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1000@192.168.1.166) Running State Change CS_REPORTING (Cur 1 Tot 6)
- send 597 bytes to udp/[192.168.1.166]:59288 at 00:02:24.242071:
- ------------------------------------------------------------------------
- BYE sip:1000@192.168.1.166:59288;transport=UDP SIP/2.0
- Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKgeScgmQ6vy07N
- Max-Forwards: 70
- From: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
- To: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
- Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
- CSeq: 45295879 BYE
- User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
- Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
- Supported: timer, path, replaces
- Reason: Q.850;cause=16;text="NORMAL_CLEARING"
- Content-Length: 0
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/1000@192.168.1.166) State REPORTING
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:168 sofia/internal/1000@192.168.1.166 Standard REPORTING, cause: NORMAL_CLEARING
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/1000@192.168.1.166) State REPORTING going to sleep
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/1000@192.168.1.166) State Change CS_REPORTING -> CS_DESTROY
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_session.c:1753 Session 5 (sofia/internal/1000@192.168.1.166) Locked, Waiting on external entities
- 2021-12-17 00:02:24.224324 87.17% [NOTICE] switch_core_session.c:1771 Session 5 (sofia/internal/1000@192.168.1.166) Ended
- 2021-12-17 00:02:24.224324 87.17% [NOTICE] switch_core_session.c:1775 Close Channel sofia/internal/1000@192.168.1.166 [CS_DESTROY]
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/1000@192.168.1.166) Running State Change CS_DESTROY (Cur 0 Tot 6)
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/1000@192.168.1.166) State DESTROY
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_sofia.c:379 sofia/internal/1000@192.168.1.166 SOFIA DESTROY
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[140] PLC[0] FEC[0]
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[146] Bytes encoded[13358] Encoded length ms[2920] Average encoded bitrate bps[53432]
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:175 sofia/internal/1000@192.168.1.166 Standard DESTROY
- 2021-12-17 00:02:24.224324 87.17% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/1000@192.168.1.166) State DESTROY going to sleep
- recv 362 bytes from udp/[192.168.1.166]:59288 at 00:02:24.252972:
- ------------------------------------------------------------------------
- SIP/2.0 200 OK
- Via: SIP/2.0/UDP 192.168.1.166;rport=5060;branch=z9hG4bKgeScgmQ6vy07N
- Contact: <sip:1000@192.168.1.166:59288;transport=UDP>
- To: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
- From: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
- Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
- CSeq: 45295879 BYE
- User-Agent: Z 5.4.12 v2.10.13.2-mod
- Content-Length: 0