From ft, 2 Years ago, written in Plain Text.
- view diff
Embed
  1. +OK log level  [7]
  2. freeswitch@ib-ftrle-l> sofia global siptrace on
  3. +OK Global siptrace on
  4. recv 782 bytes from udp/[192.168.1.166]:59288 at 00:02:11.711602:
  5. ------------------------------------------------------------------------
  6. INVITE sip:1001@192.168.1.166;transport=UDP SIP/2.0
  7. Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---90ed98a9c1765058;rport
  8. Max-Forwards: 70
  9. Contact: <sip:1000@192.168.1.166:59288;transport=UDP>
  10. To: <sip:1001@192.168.1.166>
  11. From: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
  12. Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
  13. CSeq: 1 INVITE
  14. Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
  15. Content-Type: application/sdp
  16. User-Agent: Z 5.4.12 v2.10.13.2-mod
  17. Allow-Events: presence, kpml, talk
  18. Content-Length: 219
  19.  
  20. v=0
  21. o=Z 1639699331625 1 IN IP4 192.168.1.166
  22. s=Z
  23. c=IN IP4 192.168.1.166
  24. t=0 0
  25. m=audio 8000 RTP/AVP 106 102
  26. a=rtpmap:106 opus/48000/2
  27. a=fmtp:106 minptime=20; useinbandfec=1
  28. a=rtpmap:102 G726-32/8000
  29. a=sendrecv
  30. 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]
  31. 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)
  32. 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..
  33. 2021-12-17 00:02:11.704345 88.03% [DEBUG] sofia.c:10556 verifying acl "domains" for ip/port 192.168.1.166:0.
  34. 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
  35. send 861 bytes to udp/[192.168.1.166]:59288 at 00:02:11.712400:
  36. ------------------------------------------------------------------------
  37. SIP/2.0 407 Proxy Authentication Required
  38. Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---90ed98a9c1765058;rport=59288
  39. From: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
  40. To: <sip:1001@192.168.1.166>;tag=va2HcZH0pjeZg
  41. Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
  42. CSeq: 1 INVITE
  43. User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
  44. Accept: application/sdp
  45. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  46. Supported: timer, path, replaces
  47. Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
  48. Proxy-Authenticate: Digest realm="192.168.1.166", nonce="8707b404-07a1-4a6a-aa51-ad8f38def438", algorithm=MD5, qop="auth"
  49. Content-Length: 0
  50.  
  51. 2021-12-17 00:02:11.704345 88.03% [DEBUG] sofia.c:2419 detaching session 824d9cb7-133b-4e0e-ac98-aa7f6e5baf39
  52. recv 331 bytes from udp/[192.168.1.166]:59288 at 00:02:11.712674:
  53. ------------------------------------------------------------------------
  54. ACK sip:1001@192.168.1.166;transport=UDP SIP/2.0
  55. Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---90ed98a9c1765058;rport
  56. Max-Forwards: 70
  57. To: <sip:1001@192.168.1.166>;tag=va2HcZH0pjeZg
  58. From: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
  59. Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
  60. CSeq: 1 ACK
  61. Content-Length: 0
  62.  
  63. recv 1058 bytes from udp/[192.168.1.166]:59288 at 00:02:11.712706:
  64. ------------------------------------------------------------------------
  65. INVITE sip:1001@192.168.1.166;transport=UDP SIP/2.0
  66. Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---131c3416fc3e61ee;rport
  67. Max-Forwards: 70
  68. Contact: <sip:1000@192.168.1.166:59288;transport=UDP>
  69. To: <sip:1001@192.168.1.166>
  70. From: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
  71. Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
  72. CSeq: 2 INVITE
  73. Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
  74. Content-Type: application/sdp
  75. 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
  76. User-Agent: Z 5.4.12 v2.10.13.2-mod
  77. Allow-Events: presence, kpml, talk
  78. Content-Length: 219
  79.  
  80. v=0
  81. o=Z 1639699331625 1 IN IP4 192.168.1.166
  82. s=Z
  83. c=IN IP4 192.168.1.166
  84. t=0 0
  85. m=audio 8000 RTP/AVP 106 102
  86. a=rtpmap:106 opus/48000/2
  87. a=fmtp:106 minptime=20; useinbandfec=1
  88. a=rtpmap:102 G726-32/8000
  89. a=sendrecv
  90. 2021-12-17 00:02:11.704345 88.03% [DEBUG] sofia.c:2532 Re-attaching to session 824d9cb7-133b-4e0e-ac98-aa7f6e5baf39
  91. 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..
  92. 2021-12-17 00:02:11.724307 88.03% [DEBUG] sofia.c:10556 verifying acl "domains" for ip/port 192.168.1.166:0.
  93. 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]
  94. 2021-12-17 00:02:11.724307 88.03% [DEBUG] sofia.c:7509 Remote SDP:
  95. v=0
  96. o=Z 1639699331625 1 IN IP4 192.168.1.166
  97. s=Z
  98. c=IN IP4 192.168.1.166
  99. t=0 0
  100. m=audio 8000 RTP/AVP 106 102
  101. a=rtpmap:106 opus/48000/2
  102. a=fmtp:106 minptime=20; useinbandfec=1
  103. a=rtpmap:102 G726-32/8000
  104.  
  105. 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
  106. 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)
  107. 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
  108. 2021-12-17 00:02:11.724307 88.03% [DEBUG] mod_sofia.c:97 sofia/internal/1000@192.168.1.166 SOFIA INIT
  109. 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
  110. 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
  111. 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
  112. 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)
  113. 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
  114. 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
  115. 2021-12-17 00:02:11.724307 88.03% [DEBUG] mod_sofia.c:158 sofia/internal/1000@192.168.1.166 SOFIA ROUTING
  116. 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
  117. 2021-12-17 00:02:11.724307 88.03% [INFO] mod_dialplan_xml.c:639 Processing 1000 <1000>->1001 in context default
  118. send 357 bytes to udp/[192.168.1.166]:59288 at 00:02:11.733545:
  119. ------------------------------------------------------------------------
  120. SIP/2.0 100 Trying
  121. Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---131c3416fc3e61ee;rport=59288
  122. From: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
  123. To: <sip:1001@192.168.1.166>
  124. Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
  125. CSeq: 2 INVITE
  126. User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
  127. Content-Length: 0
  128.  
  129. Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->unloop] continue=false
  130. Dialplan: sofia/internal/1000@192.168.1.166 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
  131. Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
  132. Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->tod_example] continue=true
  133. Dialplan: sofia/internal/1000@192.168.1.166 Date/TimeMatch (FAIL) [tod_example] break=on-false
  134. Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->holiday_example] continue=true
  135. Dialplan: sofia/internal/1000@192.168.1.166 Date/TimeMatch (FAIL) [holiday_example] break=on-false
  136. Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->global-intercept] continue=false
  137. Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [global-intercept] destination_number(1001) =~ /^886$/ break=on-false
  138. Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->group-intercept] continue=false
  139. Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [group-intercept] destination_number(1001) =~ /^\*8$/ break=on-false
  140. Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->intercept-ext] continue=false
  141. Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [intercept-ext] destination_number(1001) =~ /^\*\*(\d+)$/ break=on-false
  142. Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->redial] continue=false
  143. Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [redial] destination_number(1001) =~ /^(redial|870)$/ break=on-false
  144. Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->global] continue=true
  145. Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
  146. Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [global] ${default_password}(nekipassword001) =~ /^1234$/ break=never
  147. 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
  148. Dialplan: sofia/internal/1000@192.168.1.166 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
  149. Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [global] ${switch_r_sdp}(v=0
  150. o=Z 1639699331625 1 IN IP4 192.168.1.166
  151. s=Z
  152. c=IN IP4 192.168.1.166
  153. t=0 0
  154. m=audio 8000 RTP/AVP 106 102
  155. a=rtpmap:106 opus/48000/2
  156. a=fmtp:106 minptime=20; useinbandfec=1
  157. a=rtpmap:102 G726-32/8000
  158. ) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
  159. Dialplan: sofia/internal/1000@192.168.1.166 Absolute Condition [global]
  160. Dialplan: sofia/internal/1000@192.168.1.166 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
  161. Dialplan: sofia/internal/1000@192.168.1.166 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
  162. Dialplan: sofia/internal/1000@192.168.1.166 Action hash(insert/${domain_name}-last_dial/global/${uuid})
  163. Dialplan: sofia/internal/1000@192.168.1.166 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
  164. Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->snom-demo-2] continue=false
  165. Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [snom-demo-2] destination_number(1001) =~ /^9001$/ break=on-false
  166. Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->snom-demo-1] continue=false
  167. Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [snom-demo-1] destination_number(1001) =~ /^9000$/ break=on-false
  168. Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->eavesdrop] continue=false
  169. Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
  170. Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->eavesdrop] continue=false
  171. Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^779$/ break=on-false
  172. Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->call_return] continue=false
  173. Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [call_return] destination_number(1001) =~ /^\*69$|^869$|^lcr$/ break=on-false
  174. Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->del-group] continue=false
  175. Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [del-group] destination_number(1001) =~ /^80(\d{2})$/ break=on-false
  176. Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->add-group] continue=false
  177. Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [add-group] destination_number(1001) =~ /^81(\d{2})$/ break=on-false
  178. Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->call-group-simo] continue=false
  179. Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [call-group-simo] destination_number(1001) =~ /^82(\d{2})$/ break=on-false
  180. Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->call-group-order] continue=false
  181. Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [call-group-order] destination_number(1001) =~ /^83(\d{2})$/ break=on-false
  182. Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->extension-intercom] continue=false
  183. Dialplan: sofia/internal/1000@192.168.1.166 Regex (FAIL) [extension-intercom] destination_number(1001) =~ /^8(10[01][0-9])$/ break=on-false
  184. Dialplan: sofia/internal/1000@192.168.1.166 parsing [default->Local_Extension] continue=false
  185. Dialplan: sofia/internal/1000@192.168.1.166 Regex (PASS) [Local_Extension] destination_number(1001) =~ /^(10[01][0-9])$/ break=on-false
  186. Dialplan: sofia/internal/1000@192.168.1.166 Action export(dialed_extension=1001)
  187. Dialplan: sofia/internal/1000@192.168.1.166 Action bind_meta_app(1 b s execute_extension::dx XML features)
  188. 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)
  189. Dialplan: sofia/internal/1000@192.168.1.166 Action bind_meta_app(3 b s execute_extension::cf XML features)
  190. Dialplan: sofia/internal/1000@192.168.1.166 Action bind_meta_app(4 b s execute_extension::att_xfer XML features)
  191. Dialplan: sofia/internal/1000@192.168.1.166 Action set(ringback=${us-ring})
  192. Dialplan: sofia/internal/1000@192.168.1.166 Action set(transfer_ringback=local_stream://moh)
  193. Dialplan: sofia/internal/1000@192.168.1.166 Action set(call_timeout=30)
  194. Dialplan: sofia/internal/1000@192.168.1.166 Action set(hangup_after_bridge=true)
  195. Dialplan: sofia/internal/1000@192.168.1.166 Action set(continue_on_fail=true)
  196. Dialplan: sofia/internal/1000@192.168.1.166 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
  197. Dialplan: sofia/internal/1000@192.168.1.166 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
  198. Dialplan: sofia/internal/1000@192.168.1.166 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)})
  199. Dialplan: sofia/internal/1000@192.168.1.166 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid})
  200. Dialplan: sofia/internal/1000@192.168.1.166 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid})
  201. Dialplan: sofia/internal/1000@192.168.1.166 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
  202. Dialplan: sofia/internal/1000@192.168.1.166 Action bridge(user/${dialed_extension}@${domain_name})
  203. Dialplan: sofia/internal/1000@192.168.1.166 Action answer()
  204. Dialplan: sofia/internal/1000@192.168.1.166 Action sleep(1000)
  205. Dialplan: sofia/internal/1000@192.168.1.166 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension})
  206. 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
  207. 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
  208. 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)
  209. 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
  210. 2021-12-17 00:02:11.724307 88.03% [DEBUG] mod_sofia.c:213 sofia/internal/1000@192.168.1.166 SOFIA EXECUTE
  211. 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
  212. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 hash(insert/192.168.1.166-spymap/1000/824d9cb7-133b-4e0e-ac98-aa7f6e5baf39)
  213. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 hash(insert/192.168.1.166-last_dial/1000/1001)
  214. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 hash(insert/192.168.1.166-last_dial/global/824d9cb7-133b-4e0e-ac98-aa7f6e5baf39)
  215. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 export(RFC2822_DATE=Fri, 17 Dec 2021 00:02:11 +0000)
  216. 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]
  217. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 export(dialed_extension=1001)
  218. 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [dialed_extension]=[1001]
  219. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 bind_meta_app(1 b s execute_extension::dx XML features)
  220. 2021-12-17 00:02:11.724307 88.03% [INFO] switch_ivr_async.c:4774 Bound B-Leg: *1 execute_extension::dx XML features
  221. 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)
  222. 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
  223. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 bind_meta_app(3 b s execute_extension::cf XML features)
  224. 2021-12-17 00:02:11.724307 88.03% [INFO] switch_ivr_async.c:4774 Bound B-Leg: *3 execute_extension::cf XML features
  225. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 bind_meta_app(4 b s execute_extension::att_xfer XML features)
  226. 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
  227. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 set(ringback=%(2000,4000,440,480))
  228. 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)]
  229. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 set(transfer_ringback=local_stream://moh)
  230. 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]
  231. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 set(call_timeout=30)
  232. 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]
  233. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 set(hangup_after_bridge=true)
  234. 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]
  235. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 set(continue_on_fail=true)
  236. 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]
  237. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 hash(insert/192.168.1.166-call_return/1001/1000)
  238. 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)
  239. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 set(called_party_callgroup=techsupport)
  240. 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]
  241. 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)
  242. 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)
  243. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 hash(insert/192.168.1.166-last_dial/techsupport/824d9cb7-133b-4e0e-ac98-aa7f6e5baf39)
  244. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 bridge(user/1001@192.168.1.166)
  245. 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
  246. 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
  247. 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables
  248. 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
  249. 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
  250. 2021-12-17 00:02:11.724307 88.03% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables
  251. 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]
  252. 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
  253. 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)
  254. 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]
  255. 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
  256. 2021-12-17 00:02:11.724307 88.03% [DEBUG] mod_sofia.c:97 sofia/internal/1001@192.168.1.166:5090 SOFIA INIT
  257. 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)
  258. 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
  259. Local SDP:
  260. v=0
  261. o=FreeSWITCH 1639676175 1639676176 IN IP4 192.168.1.166
  262. s=FreeSWITCH
  263. c=IN IP4 192.168.1.166
  264. t=0 0
  265. m=audio 23156 RTP/AVP 102 101
  266. a=rtpmap:102 opus/48000/2
  267. a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
  268. a=rtpmap:101 telephone-event/48000
  269. a=fmtp:101 0-15
  270. a=ptime:20
  271. a=sendrecv
  272.  
  273. 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
  274. 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
  275. 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
  276. 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)
  277. 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
  278. 2021-12-17 00:02:11.724307 88.03% [DEBUG] mod_sofia.c:158 sofia/internal/1001@192.168.1.166:5090 SOFIA ROUTING
  279. 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
  280. 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
  281. 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)
  282. send 1343 bytes to udp/[192.168.1.166]:5090 at 00:02:11.738307:
  283. ------------------------------------------------------------------------
  284. INVITE sip:1001@192.168.1.166:5090;transport=udp SIP/2.0
  285. Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKar1Q5HjHe9tQg
  286. Max-Forwards: 69
  287. From: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
  288. To: <sip:1001@192.168.1.166:5090;transport=udp>
  289. Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
  290. CSeq: 45295873 INVITE
  291. Contact: <sip:mod_sofia@192.168.1.166:5060>
  292. User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
  293. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  294. Supported: timer, path, replaces
  295. Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
  296. Content-Type: application/sdp
  297. Content-Disposition: session
  298. Content-Length: 351
  299. X-FS-Support: update_display,send_info
  300. Remote-Party-ID: "Extension 1000" <sip:1000@192.168.1.166>;party=calling;screen=yes;privacy=off
  301.  
  302. v=0
  303. o=FreeSWITCH 1639676175 1639676176 IN IP4 192.168.1.166
  304. s=FreeSWITCH
  305. c=IN IP4 192.168.1.166
  306. t=0 0
  307. m=audio 23156 RTP/AVP 102 101
  308. a=rtpmap:102 opus/48000/2
  309. a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
  310. a=rtpmap:101 telephone-event/48000
  311. a=fmtp:101 0-15
  312. a=ptime:20
  313. 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
  314. 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
  315. 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]
  316. recv 274 bytes from udp/[192.168.1.166]:5090 at 00:02:11.756061:
  317. ------------------------------------------------------------------------
  318. SIP/2.0 100 Trying
  319. Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKar1Q5HjHe9tQg
  320. From: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
  321. To: <sip:1001@192.168.1.166:5090;transport=udp>
  322. Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
  323. CSeq: 45295873 INVITE
  324.  
  325. recv 365 bytes from udp/[192.168.1.166]:5090 at 00:02:11.863917:
  326. ------------------------------------------------------------------------
  327. SIP/2.0 180 Ringing
  328. Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKar1Q5HjHe9tQg
  329. From: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
  330. To: <sip:1001@192.168.1.166:5090;transport=udp>;tag=Ei9E0KW
  331. Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
  332. CSeq: 45295873 INVITE
  333. User-Agent: Linphone/3.12.0 (belle-sip/1.6.3)
  334. Supported: replaces, outbound
  335.  
  336. 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]
  337. 2021-12-17 00:02:11.864299 88.03% [NOTICE] sofia.c:7610 Ring-Ready sofia/internal/1001@192.168.1.166:5090!
  338. 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
  339. 2021-12-17 00:02:11.864299 88.03% [INFO] switch_ivr_originate.c:1295 Sending early media
  340. 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]
  341. 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
  342. 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]
  343. 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]
  344. 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]
  345. 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]
  346. 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]
  347. 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]
  348. 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]
  349. 2021-12-17 00:02:11.864299 88.03% [DEBUG] mod_opus.c:619 Opus encoder: set bitrate to local settings [72000bps]
  350. 2021-12-17 00:02:11.864299 88.03% [DEBUG] mod_opus.c:619 Opus encoder: set bitrate to local settings [72000bps]
  351. 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
  352. 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
  353. 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.
  354. 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
  355. 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
  356. 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_rtp.c:4619 Starting timer [soft] 960 bytes per 20ms
  357. 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
  358. 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
  359. 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
  360. 2021-12-17 00:02:11.864299 88.03% [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1000@192.168.1.166!
  361. 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
  362. 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.
  363. 2021-12-17 00:02:11.864299 88.03% [DEBUG] mod_sofia.c:2610 Ring SDP:
  364. v=0
  365. o=FreeSWITCH 1639681433 1639681434 IN IP4 192.168.1.166
  366. s=FreeSWITCH
  367. c=IN IP4 192.168.1.166
  368. t=0 0
  369. m=audio 17898 RTP/AVP 106 101
  370. a=rtpmap:106 opus/48000/2
  371. a=fmtp:106 useinbandfec=1; minptime=20
  372. a=rtpmap:101 telephone-event/8000
  373. a=fmtp:101 0-15
  374. a=ptime:20
  375. a=sendrecv
  376.  
  377. 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_ivr_originate.c:1353 Raw Codec Activation Success L16@48000hz 1 channel 20ms
  378. 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
  379. 2021-12-17 00:02:11.864299 88.03% [DEBUG] switch_ivr_originate.c:1427 Play Ringback Tone [%(2000,4000,440,480)]
  380. send 1197 bytes to udp/[192.168.1.166]:59288 at 00:02:11.883668:
  381. ------------------------------------------------------------------------
  382. SIP/2.0 183 Session Progress
  383. Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---131c3416fc3e61ee;rport=59288
  384. From: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
  385. To: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
  386. Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
  387. CSeq: 2 INVITE
  388. Contact: <sip:1001@192.168.1.166:5060;transport=udp>
  389. User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
  390. Accept: application/sdp
  391. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  392. Supported: timer, path, replaces
  393. Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
  394. Content-Type: application/sdp
  395. Content-Disposition: session
  396. Content-Length: 269
  397. Remote-Party-ID: "1001" <sip:1001@192.168.1.166>;party=calling;privacy=off;screen=no
  398.  
  399. v=0
  400. o=FreeSWITCH 1639681433 1639681434 IN IP4 192.168.1.166
  401. s=FreeSWITCH
  402. c=IN IP4 192.168.1.166
  403. t=0 0
  404. m=audio 17898 RTP/AVP 106 101
  405. a=rtpmap:106 opus/48000/2
  406. a=fmtp:106 useinbandfec=1; minptime=20
  407. a=rtpmap:101 telephone-event/8000
  408. a=fmtp:101 0-15
  409. a=ptime:20
  410. 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]
  411. 2021-12-17 00:02:11.924300 88.03% [DEBUG] switch_rtp.c:7934 Correct audio ip/port confirmed.
  412. recv 835 bytes from udp/[192.168.1.166]:5090 at 00:02:14.788475:
  413. ------------------------------------------------------------------------
  414. SIP/2.0 200 Ok
  415. Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKar1Q5HjHe9tQg
  416. From: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
  417. To: <sip:1001@192.168.1.166:5090;transport=udp>;tag=Ei9E0KW
  418. Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
  419. CSeq: 45295873 INVITE
  420. User-Agent: Linphone/3.12.0 (belle-sip/1.6.3)
  421. Supported: replaces, outbound
  422. Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
  423. Contact: "Li" <sip:9999@192.168.1.166:5090;transport=udp>;+sip.instance="<urn:uuid:b8fee09a-4790-44f6-88d1-69c76cc5c84a>"
  424. Content-Type: application/sdp
  425. Content-Length: 209
  426.  
  427. v=0
  428. o=98765432100 404 3779 IN IP4 192.168.1.166
  429. s=Talk
  430. c=IN IP4 192.168.1.166
  431. t=0 0
  432. m=audio 7078 RTP/AVP 102 101
  433. a=rtpmap:102 opus/48000/2
  434. a=fmtp:102 useinbandfec=1
  435. a=rtpmap:101 telephone-event/48000
  436. 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]
  437. 2021-12-17 00:02:14.784299 87.57% [DEBUG] sofia.c:7509 Remote SDP:
  438. v=0
  439. o=98765432100 404 3779 IN IP4 192.168.1.166
  440. s=Talk
  441. c=IN IP4 192.168.1.166
  442. t=0 0
  443. m=audio 7078 RTP/AVP 102 101
  444. a=rtpmap:102 opus/48000/2
  445. a=fmtp:102 useinbandfec=1
  446. a=rtpmap:101 telephone-event/48000
  447.  
  448. send 400 bytes to udp/[192.168.1.166]:5090 at 00:02:14.789563:
  449. ------------------------------------------------------------------------
  450. ACK sip:9999@192.168.1.166:5090;transport=udp SIP/2.0
  451. Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKB1tg7c3mBjHac
  452. Max-Forwards: 70
  453. From: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
  454. To: <sip:1001@192.168.1.166:5090;transport=udp>;tag=Ei9E0KW
  455. Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
  456. CSeq: 45295873 ACK
  457. Contact: <sip:mod_sofia@192.168.1.166:5060>
  458. Content-Length: 0
  459.  
  460. 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]
  461. 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]
  462. 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
  463. 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_core_media.c:5568 Set telephone-event payload to 101@48000
  464. 2021-12-17 00:02:14.784299 87.57% [DEBUG] mod_opus.c:619 Opus encoder: set bitrate to local settings [72000bps]
  465. 2021-12-17 00:02:14.784299 87.57% [DEBUG] mod_opus.c:619 Opus encoder: set bitrate to local settings [72000bps]
  466. 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
  467. 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
  468. 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_core_media.c:5917 Set telephone-event payload to 101@48000
  469. 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
  470. 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
  471. 2021-12-17 00:02:14.784299 87.57% [DEBUG] switch_rtp.c:4619 Starting timer [soft] 960 bytes per 20ms
  472. 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
  473. 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
  474. 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
  475. 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
  476. 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
  477. 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.
  478. 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.
  479. 2021-12-17 00:02:14.784299 87.57% [DEBUG] mod_sofia.c:913 Local SDP sofia/internal/1000@192.168.1.166:
  480. v=0
  481. o=FreeSWITCH 1639681433 1639681435 IN IP4 192.168.1.166
  482. s=FreeSWITCH
  483. c=IN IP4 192.168.1.166
  484. t=0 0
  485. m=audio 17898 RTP/AVP 106 101
  486. a=rtpmap:106 opus/48000/2
  487. a=fmtp:106 useinbandfec=1; minptime=20
  488. a=rtpmap:101 telephone-event/8000
  489. a=fmtp:101 0-15
  490. a=ptime:20
  491. a=sendrecv
  492.  
  493. 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
  494. send 1167 bytes to udp/[192.168.1.166]:59288 at 00:02:14.801617:
  495. ------------------------------------------------------------------------
  496. SIP/2.0 200 OK
  497. Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---131c3416fc3e61ee;rport=59288
  498. From: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
  499. To: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
  500. Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
  501. CSeq: 2 INVITE
  502. Contact: <sip:1001@192.168.1.166:5060;transport=udp>
  503. User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
  504. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  505. Supported: timer, path, replaces
  506. Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
  507. Content-Type: application/sdp
  508. Content-Disposition: session
  509. Content-Length: 269
  510. Remote-Party-ID: "Outbound Call" <sip:1001@192.168.1.166>;party=calling;privacy=off;screen=no
  511.  
  512. v=0
  513. o=FreeSWITCH 1639681433 1639681434 IN IP4 192.168.1.166
  514. s=FreeSWITCH
  515. c=IN IP4 192.168.1.166
  516. t=0 0
  517. m=audio 17898 RTP/AVP 106 101
  518. a=rtpmap:106 opus/48000/2
  519. a=fmtp:106 useinbandfec=1; minptime=20
  520. a=rtpmap:101 telephone-event/8000
  521. a=fmtp:101 0-15
  522. a=ptime:20
  523. 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
  524. 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]
  525. 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
  526. recv 428 bytes from udp/[192.168.1.166]:59288 at 00:02:14.802048:
  527. ------------------------------------------------------------------------
  528. ACK sip:1001@192.168.1.166:5060;transport=udp SIP/2.0
  529. Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---b677280fdbb70809;rport
  530. Max-Forwards: 70
  531. Contact: <sip:1000@192.168.1.166:59288;transport=UDP>
  532. To: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
  533. From: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
  534. Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
  535. CSeq: 2 ACK
  536. User-Agent: Z 5.4.12 v2.10.13.2-mod
  537. Content-Length: 0
  538.  
  539. 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]
  540. 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
  541. 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
  542. 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)
  543. 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
  544. 2021-12-17 00:02:14.784299 87.57% [DEBUG] mod_sofia.c:671 SOFIA EXCHANGE_MEDIA
  545. 2021-12-17 00:02:14.844336 87.57% [DEBUG] switch_rtp.c:7934 Correct audio ip/port confirmed.
  546. 2021-12-17 00:02:14.844336 87.57% [DEBUG] switch_rtp.c:7934 Correct audio ip/port confirmed.
  547. 2021-12-17 00:02:14.844336 87.57% [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
  548. 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]
  549. 2021-12-17 00:02:14.844336 87.57% [DEBUG] mod_opus.c:619 Opus encoder: set bitrate to local settings [72000bps]
  550. 2021-12-17 00:02:14.864333 87.57% [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
  551. 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]
  552. 2021-12-17 00:02:14.864333 87.57% [DEBUG] mod_opus.c:619 Opus encoder: set bitrate to local settings [72000bps]
  553. recv 991 bytes from udp/[192.168.1.166]:5090 at 00:02:18.744944:
  554. ------------------------------------------------------------------------
  555. INVITE sip:mod_sofia@192.168.1.166:5060 SIP/2.0
  556. Via: SIP/2.0/UDP 192.168.1.166:5090;branch=z9hG4bK.kpCrA45jY;rport
  557. From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
  558. To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
  559. CSeq: 111 INVITE
  560. Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
  561. Max-Forwards: 70
  562. Subject: Call on hold
  563. Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
  564. Content-Type: application/sdp
  565. Content-Length: 344
  566. Contact: "Li" <sip:9999@192.168.1.166:5090;transport=udp>;+sip.instance="<urn:uuid:b8fee09a-4790-44f6-88d1-69c76cc5c84a>"
  567. User-Agent: Linphone/3.12.0 (belle-sip/1.6.3)
  568.  
  569. v=0
  570. o=98765432100 404 3780 IN IP4 192.168.1.166
  571. s=Talk
  572. c=IN IP4 192.168.1.166
  573. t=0 0
  574. a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
  575. m=audio 7078 RTP/AVP 102 101
  576. a=rtpmap:102 opus/48000/2
  577. a=fmtp:102 useinbandfec=1
  578. a=rtpmap:101 telephone-event/48000
  579. a=sendonly
  580. a=rtcp-fb:* trr-int 5000
  581. a=rtcp-fb:* ccm tmmbr
  582. send 371 bytes to udp/[192.168.1.166]:5090 at 00:02:18.750743:
  583. ------------------------------------------------------------------------
  584. SIP/2.0 100 Trying
  585. Via: SIP/2.0/UDP 192.168.1.166:5090;branch=z9hG4bK.kpCrA45jY;rport=5090
  586. From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
  587. To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
  588. Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
  589. CSeq: 111 INVITE
  590. User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
  591. Content-Length: 0
  592.  
  593. 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]
  594. 2021-12-17 00:02:18.744298 87.70% [DEBUG] sofia.c:7509 Remote SDP:
  595. v=0
  596. o=98765432100 404 3780 IN IP4 192.168.1.166
  597. s=Talk
  598. c=IN IP4 192.168.1.166
  599. t=0 0
  600. a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
  601. m=audio 7078 RTP/AVP 102 101
  602. a=rtpmap:102 opus/48000/2
  603. a=fmtp:102 useinbandfec=1
  604. a=rtpmap:101 telephone-event/48000
  605. a=sendonly
  606. a=rtcp-fb:* trr-int 5000
  607. a=rtcp-fb:* ccm tmmbr
  608.  
  609. 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
  610. 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)
  611. EXECUTE [depth=0] sofia/internal/1000@192.168.1.166 playback(local_stream://moh)
  612. 2021-12-17 00:02:18.884324 87.70% [WARNING] mod_local_stream.c:874 Unknown source moh, trying 'default'
  613. 2021-12-17 00:02:18.884324 87.70% [ERR] mod_local_stream.c:882 Unknown source default
  614. 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]
  615. 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
  616. 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]
  617. 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]
  618. 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]
  619. 2021-12-17 00:02:18.984346 87.70% [DEBUG] switch_core_media.c:5568 Set telephone-event payload to 101@48000
  620. 2021-12-17 00:02:18.984346 87.70% [DEBUG] switch_core_media.c:5917 Set telephone-event payload to 101@48000
  621. 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
  622. 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.
  623. 2021-12-17 00:02:18.984346 87.70% [DEBUG] sofia.c:8454 Processing updated SDP
  624. 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)
  625. 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
  626. Local SDP:
  627. v=0
  628. o=FreeSWITCH 1639681433 1639681437 IN IP4 192.168.1.166
  629. s=FreeSWITCH
  630. c=IN IP4 192.168.1.166
  631. t=0 0
  632. m=audio 17898 RTP/AVP 106 101
  633. a=rtpmap:106 opus/48000/2
  634. a=fmtp:106 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
  635. a=rtpmap:101 telephone-event/48000
  636. a=fmtp:101 0-15
  637. a=ptime:20
  638. a=sendonly
  639.  
  640. send 1046 bytes to udp/[192.168.1.166]:59288 at 00:02:19.021075:
  641. ------------------------------------------------------------------------
  642. INVITE sip:1000@192.168.1.166:59288;transport=UDP SIP/2.0
  643. Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKcam987Kr8t7vQ
  644. Max-Forwards: 70
  645. From: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
  646. To: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
  647. Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
  648. CSeq: 45295877 INVITE
  649. Contact: <sip:1001@192.168.1.166:5060;transport=udp>
  650. User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
  651. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  652. Supported: timer, path, replaces
  653. Content-Type: application/sdp
  654. Content-Length: 363
  655. X-FS-Support: update_display,send_info
  656.  
  657. v=0
  658. o=FreeSWITCH 1639681433 1639681437 IN IP4 192.168.1.166
  659. s=FreeSWITCH
  660. c=IN IP4 192.168.1.166
  661. t=0 0
  662. m=audio 17898 RTP/AVP 106 101
  663. a=rtpmap:106 opus/48000/2
  664. a=fmtp:106 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
  665. a=rtpmap:101 telephone-event/48000
  666. a=fmtp:101 0-15
  667. a=ptime:20
  668. a=sendonly
  669. recv 724 bytes from udp/[192.168.1.166]:59288 at 00:02:19.021654:
  670. ------------------------------------------------------------------------
  671. SIP/2.0 200 OK
  672. Via: SIP/2.0/UDP 192.168.1.166;rport=5060;branch=z9hG4bKcam987Kr8t7vQ
  673. Contact: <sip:1000@192.168.1.166:59288;transport=UDP>
  674. To: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
  675. From: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
  676. Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
  677. CSeq: 45295877 INVITE
  678. Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
  679. Content-Type: application/sdp
  680. User-Agent: Z 5.4.12 v2.10.13.2-mod
  681. Allow-Events: presence, kpml, talk
  682. Content-Length: 207
  683.  
  684. v=0
  685. o=Z 0 2 IN IP4 192.168.1.166
  686. s=Z
  687. c=IN IP4 192.168.1.166
  688. t=0 0
  689. m=audio 8000 RTP/AVP 106 102
  690. a=rtpmap:106 opus/48000/2
  691. a=fmtp:106 minptime=10; useinbandfec=1
  692. a=rtpmap:102 G726-32/8000
  693. a=inactive
  694. 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]
  695. 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]
  696. 2021-12-17 00:02:19.024304 87.70% [DEBUG] sofia.c:7509 Remote SDP:
  697. v=0
  698. o=Z 0 2 IN IP4 192.168.1.166
  699. s=Z
  700. c=IN IP4 192.168.1.166
  701. t=0 0
  702. m=audio 8000 RTP/AVP 106 102
  703. a=rtpmap:106 opus/48000/2
  704. a=fmtp:106 minptime=10; useinbandfec=1
  705. a=rtpmap:102 G726-32/8000
  706. a=inactive
  707.  
  708. send 323 bytes to udp/[192.168.1.166]:59288 at 00:02:19.042185:
  709. ------------------------------------------------------------------------
  710. ACK sip:1000@192.168.1.166:59288;transport=UDP SIP/2.0
  711. Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKDKD2a34U53XFK
  712. Max-Forwards: 70
  713. From: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
  714. To: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
  715. Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
  716. CSeq: 45295877 ACK
  717. Content-Length: 0
  718.  
  719. 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]
  720. 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]
  721. 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
  722. 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]
  723. 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.
  724. 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
  725. 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]
  726. 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
  727. 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]
  728. 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
  729. 2021-12-17 00:02:19.044347 87.70% [DEBUG] switch_core_media.c:5568 Set telephone-event payload to 101@48000
  730. 2021-12-17 00:02:19.044347 87.70% [DEBUG] switch_core_media.c:5917 Set telephone-event payload to 101@48000
  731. 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
  732. 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.
  733. 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.
  734. send 913 bytes to udp/[192.168.1.166]:5090 at 00:02:19.062788:
  735. ------------------------------------------------------------------------
  736. SIP/2.0 200 OK
  737. Via: SIP/2.0/UDP 192.168.1.166:5090;branch=z9hG4bK.kpCrA45jY;rport=5090
  738. From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
  739. To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
  740. Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
  741. CSeq: 111 INVITE
  742. Contact: <sip:mod_sofia@192.168.1.166:5060>
  743. User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
  744. Accept: application/sdp
  745. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  746. Supported: timer, path, replaces
  747. Content-Type: application/sdp
  748. Content-Disposition: session
  749. Content-Length: 269
  750.  
  751. v=0
  752. o=FreeSWITCH 1639676175 1639676177 IN IP4 192.168.1.166
  753. s=FreeSWITCH
  754. c=IN IP4 192.168.1.166
  755. t=0 0
  756. m=audio 23156 RTP/AVP 102 101
  757. a=rtpmap:102 opus/48000/2
  758. a=fmtp:102 useinbandfec=1
  759. a=rtpmap:101 telephone-event/48000
  760. a=fmtp:101 0-15
  761. a=recvonly
  762. a=ptime:20
  763. recv 352 bytes from udp/[192.168.1.166]:5090 at 00:02:19.073423:
  764. ------------------------------------------------------------------------
  765. ACK sip:mod_sofia@192.168.1.166:5060 SIP/2.0
  766. Via: SIP/2.0/UDP 192.168.1.166:5090;rport;branch=z9hG4bK.stoY2noCJ
  767. From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
  768. To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
  769. CSeq: 111 ACK
  770. Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
  771. Max-Forwards: 70
  772. User-Agent: Linphone/3.12.0 (belle-sip/1.6.3)
  773.  
  774. 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]
  775. 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]
  776. recv 849 bytes from udp/[192.168.1.166]:59288 at 00:02:19.678485:
  777. ------------------------------------------------------------------------
  778. REGISTER sip:192.168.1.166;transport=UDP SIP/2.0
  779. Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---0de007e033a26c39;rport
  780. Max-Forwards: 70
  781. Contact: <sip:1000@192.168.1.166:59288;rinstance=62ef940e00368058;transport=UDP>
  782. To: <sip:1000@192.168.1.166;transport=UDP>
  783. From: <sip:1000@192.168.1.166;transport=UDP>;tag=82ac1e74
  784. Call-ID: nB_ORf_VDWOygeHg5Zv_7A..
  785. CSeq: 22 REGISTER
  786. Expires: 60
  787. Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
  788. User-Agent: Z 5.4.12 v2.10.13.2-mod
  789. 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
  790. Allow-Events: presence, kpml, talk
  791. Content-Length: 0
  792.  
  793. send 662 bytes to udp/[192.168.1.166]:59288 at 00:02:19.679997:
  794. ------------------------------------------------------------------------
  795. SIP/2.0 200 OK
  796. Via: SIP/2.0/UDP 192.168.1.166:59288;branch=z9hG4bK-524287-1---0de007e033a26c39;rport=59288
  797. From: <sip:1000@192.168.1.166;transport=UDP>;tag=82ac1e74
  798. To: <sip:1000@192.168.1.166;transport=UDP>;tag=Z5DvHg4aeDHQK
  799. Call-ID: nB_ORf_VDWOygeHg5Zv_7A..
  800. CSeq: 22 REGISTER
  801. Contact: <sip:1000@192.168.1.166:59288;rinstance=62ef940e00368058;transport=UDP>;expires=60
  802. Date: Fri, 17 Dec 2021 00:02:19 GMT
  803. User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
  804. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  805. Supported: timer, path, replaces
  806. Content-Length: 0
  807.  
  808. recv 980 bytes from udp/[192.168.1.166]:5090 at 00:02:21.672533:
  809. ------------------------------------------------------------------------
  810. INVITE sip:mod_sofia@192.168.1.166:5060 SIP/2.0
  811. Via: SIP/2.0/UDP 192.168.1.166:5090;branch=z9hG4bK.6xCKL0Ct4;rport
  812. From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
  813. To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
  814. CSeq: 112 INVITE
  815. Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
  816. Max-Forwards: 70
  817. Subject: Call resuming
  818. Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
  819. Content-Type: application/sdp
  820. Content-Length: 332
  821. Contact: "Li" <sip:9999@192.168.1.166:5090;transport=udp>;+sip.instance="<urn:uuid:b8fee09a-4790-44f6-88d1-69c76cc5c84a>"
  822. User-Agent: Linphone/3.12.0 (belle-sip/1.6.3)
  823.  
  824. v=0
  825. o=98765432100 404 3781 IN IP4 192.168.1.166
  826. s=Talk
  827. c=IN IP4 192.168.1.166
  828. t=0 0
  829. a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
  830. m=audio 7078 RTP/AVP 102 101
  831. a=rtpmap:102 opus/48000/2
  832. a=fmtp:102 useinbandfec=1
  833. a=rtpmap:101 telephone-event/48000
  834. a=rtcp-fb:* trr-int 5000
  835. a=rtcp-fb:* ccm tmmbr
  836. send 371 bytes to udp/[192.168.1.166]:5090 at 00:02:21.679922:
  837. ------------------------------------------------------------------------
  838. SIP/2.0 100 Trying
  839. Via: SIP/2.0/UDP 192.168.1.166:5090;branch=z9hG4bK.6xCKL0Ct4;rport=5090
  840. From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
  841. To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
  842. Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
  843. CSeq: 112 INVITE
  844. User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
  845. Content-Length: 0
  846.  
  847. 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]
  848. 2021-12-17 00:02:21.664341 87.37% [DEBUG] sofia.c:7509 Remote SDP:
  849. v=0
  850. o=98765432100 404 3781 IN IP4 192.168.1.166
  851. s=Talk
  852. c=IN IP4 192.168.1.166
  853. t=0 0
  854. a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
  855. m=audio 7078 RTP/AVP 102 101
  856. a=rtpmap:102 opus/48000/2
  857. a=fmtp:102 useinbandfec=1
  858. a=rtpmap:101 telephone-event/48000
  859. a=rtcp-fb:* trr-int 5000
  860. a=rtcp-fb:* ccm tmmbr
  861.  
  862. 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
  863. 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]
  864. 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
  865. 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]
  866. 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
  867. 2021-12-17 00:02:21.924324 87.37% [DEBUG] switch_core_media.c:5568 Set telephone-event payload to 101@48000
  868. 2021-12-17 00:02:21.924324 87.37% [DEBUG] switch_core_media.c:5917 Set telephone-event payload to 101@48000
  869. 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
  870. 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.
  871. 2021-12-17 00:02:21.924324 87.37% [DEBUG] sofia.c:8454 Processing updated SDP
  872. 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
  873. 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)
  874. 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
  875. Local SDP:
  876. v=0
  877. o=FreeSWITCH 1639681433 1639681439 IN IP4 192.168.1.166
  878. s=FreeSWITCH
  879. c=IN IP4 192.168.1.166
  880. t=0 0
  881. m=audio 17898 RTP/AVP 106 101
  882. a=rtpmap:106 opus/48000/2
  883. a=fmtp:106 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
  884. a=rtpmap:101 telephone-event/48000
  885. a=fmtp:101 0-15
  886. a=ptime:20
  887. a=sendrecv
  888.  
  889. send 1046 bytes to udp/[192.168.1.166]:59288 at 00:02:21.941782:
  890. ------------------------------------------------------------------------
  891. INVITE sip:1000@192.168.1.166:59288;transport=UDP SIP/2.0
  892. Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKev6tcyNZ2cm2e
  893. Max-Forwards: 70
  894. From: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
  895. To: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
  896. Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
  897. CSeq: 45295878 INVITE
  898. Contact: <sip:1001@192.168.1.166:5060;transport=udp>
  899. User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
  900. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  901. Supported: timer, path, replaces
  902. Content-Type: application/sdp
  903. Content-Length: 363
  904. X-FS-Support: update_display,send_info
  905.  
  906. v=0
  907. o=FreeSWITCH 1639681433 1639681439 IN IP4 192.168.1.166
  908. s=FreeSWITCH
  909. c=IN IP4 192.168.1.166
  910. t=0 0
  911. m=audio 17898 RTP/AVP 106 101
  912. a=rtpmap:106 opus/48000/2
  913. a=fmtp:106 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
  914. a=rtpmap:101 telephone-event/48000
  915. a=fmtp:101 0-15
  916. a=ptime:20
  917. a=sendrecv
  918. recv 724 bytes from udp/[192.168.1.166]:59288 at 00:02:21.943553:
  919. ------------------------------------------------------------------------
  920. SIP/2.0 200 OK
  921. Via: SIP/2.0/UDP 192.168.1.166;rport=5060;branch=z9hG4bKev6tcyNZ2cm2e
  922. Contact: <sip:1000@192.168.1.166:59288;transport=UDP>
  923. To: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
  924. From: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
  925. Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
  926. CSeq: 45295878 INVITE
  927. Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
  928. Content-Type: application/sdp
  929. User-Agent: Z 5.4.12 v2.10.13.2-mod
  930. Allow-Events: presence, kpml, talk
  931. Content-Length: 207
  932.  
  933. v=0
  934. o=Z 0 3 IN IP4 192.168.1.166
  935. s=Z
  936. c=IN IP4 192.168.1.166
  937. t=0 0
  938. m=audio 8000 RTP/AVP 106 102
  939. a=rtpmap:106 opus/48000/2
  940. a=fmtp:106 minptime=10; useinbandfec=1
  941. a=rtpmap:102 G726-32/8000
  942. a=sendrecv
  943. 2021-12-17 00:02:21.944327 87.37% [DEBUG] switch_rtp.c:7934 Correct audio ip/port confirmed.
  944. 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]
  945. 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]
  946. 2021-12-17 00:02:21.965752 87.37% [DEBUG] sofia.c:7509 Remote SDP:
  947. v=0
  948. o=Z 0 3 IN IP4 192.168.1.166
  949. s=Z
  950. c=IN IP4 192.168.1.166
  951. t=0 0
  952. m=audio 8000 RTP/AVP 106 102
  953. a=rtpmap:106 opus/48000/2
  954. a=fmtp:106 minptime=10; useinbandfec=1
  955. a=rtpmap:102 G726-32/8000
  956. a=sendrecv
  957.  
  958. send 323 bytes to udp/[192.168.1.166]:59288 at 00:02:21.967327:
  959. ------------------------------------------------------------------------
  960. ACK sip:1000@192.168.1.166:59288;transport=UDP SIP/2.0
  961. Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKF5ZKeS62ZNaNa
  962. Max-Forwards: 70
  963. From: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
  964. To: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
  965. Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
  966. CSeq: 45295878 ACK
  967. Content-Length: 0
  968.  
  969. 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]
  970. 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]
  971. 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
  972. 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]
  973. 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.
  974. 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
  975. 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]
  976. 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
  977. 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]
  978. 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
  979. 2021-12-17 00:02:21.965752 87.37% [DEBUG] switch_core_media.c:5568 Set telephone-event payload to 101@48000
  980. 2021-12-17 00:02:21.965752 87.37% [DEBUG] switch_core_media.c:5917 Set telephone-event payload to 101@48000
  981. 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
  982. 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.
  983. 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.
  984. send 901 bytes to udp/[192.168.1.166]:5090 at 00:02:21.971644:
  985. ------------------------------------------------------------------------
  986. SIP/2.0 200 OK
  987. Via: SIP/2.0/UDP 192.168.1.166:5090;branch=z9hG4bK.6xCKL0Ct4;rport=5090
  988. From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
  989. To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
  990. Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
  991. CSeq: 112 INVITE
  992. Contact: <sip:mod_sofia@192.168.1.166:5060>
  993. User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
  994. Accept: application/sdp
  995. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  996. Supported: timer, path, replaces
  997. Content-Type: application/sdp
  998. Content-Disposition: session
  999. Content-Length: 257
  1000.  
  1001. v=0
  1002. o=FreeSWITCH 1639676175 1639676178 IN IP4 192.168.1.166
  1003. s=FreeSWITCH
  1004. c=IN IP4 192.168.1.166
  1005. t=0 0
  1006. m=audio 23156 RTP/AVP 102 101
  1007. a=rtpmap:102 opus/48000/2
  1008. a=fmtp:102 useinbandfec=1
  1009. a=rtpmap:101 telephone-event/48000
  1010. a=fmtp:101 0-15
  1011. a=ptime:20
  1012. recv 352 bytes from udp/[192.168.1.166]:5090 at 00:02:21.986686:
  1013. ------------------------------------------------------------------------
  1014. ACK sip:mod_sofia@192.168.1.166:5060 SIP/2.0
  1015. Via: SIP/2.0/UDP 192.168.1.166:5090;rport;branch=z9hG4bK.wa9dbc61E
  1016. From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
  1017. To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
  1018. CSeq: 112 ACK
  1019. Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
  1020. Max-Forwards: 70
  1021. User-Agent: Linphone/3.12.0 (belle-sip/1.6.3)
  1022.  
  1023. 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]
  1024. 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]
  1025. recv 352 bytes from udp/[192.168.1.166]:5090 at 00:02:24.228829:
  1026. ------------------------------------------------------------------------
  1027. BYE sip:mod_sofia@192.168.1.166:5060 SIP/2.0
  1028. Via: SIP/2.0/UDP 192.168.1.166:5090;branch=z9hG4bK.4552BGQnd;rport
  1029. From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
  1030. To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
  1031. CSeq: 113 BYE
  1032. Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
  1033. Max-Forwards: 70
  1034. User-Agent: Linphone/3.12.0 (belle-sip/1.6.3)
  1035.  
  1036. 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]
  1037. send 508 bytes to udp/[192.168.1.166]:5090 at 00:02:24.231447:
  1038. ------------------------------------------------------------------------
  1039. SIP/2.0 200 OK
  1040. Via: SIP/2.0/UDP 192.168.1.166:5090;branch=z9hG4bK.4552BGQnd;rport=5090
  1041. From: <sip:1001@192.168.1.166>;tag=Ei9E0KW
  1042. To: "Extension 1000" <sip:1000@192.168.1.166>;tag=yvm3FNK7g4t4Q
  1043. Call-ID: 6cf0a92a-d96f-123a-35ae-dc1ba1ed361d
  1044. CSeq: 113 BYE
  1045. User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
  1046. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  1047. Supported: timer, path, replaces
  1048. Content-Length: 0
  1049.  
  1050. 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]
  1051. 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
  1052. 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)
  1053. 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
  1054. 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
  1055. 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
  1056. 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
  1057. 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
  1058. 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
  1059. 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)
  1060. 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
  1061. 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
  1062. 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
  1063. 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
  1064. 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
  1065. 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
  1066. 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]
  1067. 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]
  1068. 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
  1069. 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]
  1070. 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)
  1071. 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
  1072. 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)
  1073. 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)
  1074. 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
  1075. 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_sofia.c:379 sofia/internal/1001@192.168.1.166:5090 SOFIA DESTROY
  1076. 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
  1077. 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]
  1078. 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
  1079. 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]
  1080. 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
  1081. 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
  1082. 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
  1083. 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
  1084. 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
  1085. 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
  1086. 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_sofia.c:522 Sending BYE to sofia/internal/1000@192.168.1.166
  1087. 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
  1088. 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
  1089. 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
  1090. 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)
  1091. send 597 bytes to udp/[192.168.1.166]:59288 at 00:02:24.242071:
  1092. ------------------------------------------------------------------------
  1093. BYE sip:1000@192.168.1.166:59288;transport=UDP SIP/2.0
  1094. Via: SIP/2.0/UDP 192.168.1.166;rport;branch=z9hG4bKgeScgmQ6vy07N
  1095. Max-Forwards: 70
  1096. From: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
  1097. To: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
  1098. Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
  1099. CSeq: 45295879 BYE
  1100. User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20211209T144556Z~862a19e103~64bit
  1101. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  1102. Supported: timer, path, replaces
  1103. Reason: Q.850;cause=16;text="NORMAL_CLEARING"
  1104. Content-Length: 0
  1105.  
  1106. 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
  1107. 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
  1108. 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
  1109. 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
  1110. 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
  1111. 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
  1112. 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]
  1113. 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)
  1114. 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
  1115. 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_sofia.c:379 sofia/internal/1000@192.168.1.166 SOFIA DESTROY
  1116. 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[140] PLC[0] FEC[0]
  1117. 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]
  1118. 2021-12-17 00:02:24.224324 87.17% [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
  1119. 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]
  1120. 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
  1121. 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
  1122. recv 362 bytes from udp/[192.168.1.166]:59288 at 00:02:24.252972:
  1123. ------------------------------------------------------------------------
  1124. SIP/2.0 200 OK
  1125. Via: SIP/2.0/UDP 192.168.1.166;rport=5060;branch=z9hG4bKgeScgmQ6vy07N
  1126. Contact: <sip:1000@192.168.1.166:59288;transport=UDP>
  1127. To: <sip:1000@192.168.1.166;transport=UDP>;tag=02bb7546
  1128. From: <sip:1001@192.168.1.166>;tag=XKUaet23KU4Hc
  1129. Call-ID: YJcHkXNZ5c5nQ6cX7u0pZg..
  1130. CSeq: 45295879 BYE
  1131. User-Agent: Z 5.4.12 v2.10.13.2-mod
  1132. Content-Length: 0
  1133.  
  1134.