FreeSWITCH Pastebin

Inbound Transfer Issue

From Stephen Barry, 5 Years ago, written in FreeSWITCH.
- go back
URL https://pastebin.freeswitch.org/view/214d3b21
Embed
Viewing differences between and Inbound Transfer Issue
  1. root@fpbx01:~# fs_cli
  2. .=======================================================.
  3. |            _____ ____     ____ _     ___              |
  4. |           |  ___/ ___|   / ___| |   |_ _|             |
  5. |           | |_  \___ \  | |   | |    | |              |
  6. |           |  _|  ___) | | |___| |___ | |              |
  7. |           |_|   |____/   \____|_____|___|             |
  8. |                                                       |
  9. .=======================================================.
  10. | Anthony Minessale II, Ken Rice,                       |
  11. | Michael Jerris, Travis Cross                          |
  12. | FreeSWITCH (http://www.freeswitch.org)                |
  13. | Paypal Donations Appreciated: paypal@freeswitch.org   |
  14. | Brought to you by ClueCon http://www.cluecon.com/     |
  15. .=======================================================.
  16.  
  17. .=======================================================================================================.
  18. |       _                            _    ____ _             ____                                       |
  19. |      / \   _ __  _ __  _   _  __ _| |  / ___| |_   _  ___ / ___|___  _ __                             |
  20. |     / _ \ | '_ \| '_ \| | | |/ _` | | | |   | | | | |/ _ \ |   / _ \| '_ \                            |
  21. |    / ___ \| | | | | | | |_| | (_| | | | |___| | |_| |  __/ |__| (_) | | | |                           |
  22. |   /_/   \_\_| |_|_| |_|\__,_|\__,_|_|  \____|_|\__,_|\___|\____\___/|_| |_|                           |
  23. |                                                                                                       |
  24. |    ____ _____ ____    ____             __                                                             |
  25. |   |  _ \_   _/ ___|  / ___|___  _ __  / _| ___ _ __ ___ _ __   ___ ___                                |
  26. |   | |_) || || |     | |   / _ \| '_ \| |_ / _ \ '__/ _ \ '_ \ / __/ _ \                               |
  27. |   |  _ < | || |___  | |__| (_) | | | |  _|  __/ | |  __/ | | | (_|  __/                               |
  28. |   |_| \_\|_| \____|  \____\___/|_| |_|_|  \___|_|  \___|_| |_|\___\___|                               |
  29. |                                                                                                       |
  30. |     ____ _             ____                                                                           |
  31. |    / ___| |_   _  ___ / ___|___  _ __         ___ ___  _ __ ___                                       |
  32. |   | |   | | | | |/ _ \ |   / _ \| '_ \       / __/ _ \| '_ ` _ \                                      |
  33. |   | |___| | |_| |  __/ |__| (_) | | | |  _  | (_| (_) | | | | | |                                     |
  34. |    \____|_|\__,_|\___|\____\___/|_| |_| (_)  \___\___/|_| |_| |_|                                     |
  35. |                                                                                                       |
  36. .=======================================================================================================.
  37.  
  38. Type /help <enter> to see a list of commands
  39.  
  40.  
  41.  
  42. +OK log level  [7]
  43. freeswitch@fpbx01> hello
  44. -ERR hello Command not found!
  45.  
  46. freeswitch@fpbx01> sofia loglevel all 9
  47. Sofia log level for component [all] has been set to [9]
  48. freeswitch@fpbx01> sofia global siptrace on
  49. +OK Global siptrace on
  50. nua.c:575 nua_set_params() nua: nua_set_params: entering
  51. freeswitch@fpbx01>
  52. nua_stack.c:529 nua_signal() nua((nil)): sent signal r_set_params
  53. freeswitch@fpbx01>
  54. nua.c:575 nua_set_params() nua: nua_set_params: entering
  55. freeswitch@fpbx01>
  56. nua_stack.c:569 nua_stack_signal() nua((nil)): recv signal r_set_params
  57. freeswitch@fpbx01>
  58. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  59. freeswitch@fpbx01>
  60. nua_stack.c:569 nua_stack_signal() nua((nil)): recv signal r_set_params
  61. freeswitch@fpbx01>
  62. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  63. freeswitch@fpbx01>
  64. soa.c:403 soa_set_params() soa_set_params(static::0x7fce54084150, ...) called
  65. freeswitch@fpbx01>
  66. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74005a30, ...) called
  67. freeswitch@fpbx01>
  68. nua_stack.c:271 nua_stack_event() nua((nil)): event r_set_params 200 OK
  69. freeswitch@fpbx01>
  70. nua_stack.c:271 nua_stack_event() nua((nil)): event r_set_params 200 OK
  71. freeswitch@fpbx01>
  72. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  73. freeswitch@fpbx01>
  74. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  75. freeswitch@fpbx01>
  76. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  77. freeswitch@fpbx01>
  78. nua_stack.c:529 nua_signal() nua((nil)): sent signal r_set_params
  79. freeswitch@fpbx01>
  80. nua.c:575 nua_set_params() nua: nua_set_params: entering
  81. freeswitch@fpbx01>
  82. nua_stack.c:529 nua_signal() nua((nil)): sent signal r_set_params
  83. freeswitch@fpbx01>
  84. nua.c:575 nua_set_params() nua: nua_set_params: entering
  85. freeswitch@fpbx01>
  86. nua_stack.c:569 nua_stack_signal() nua((nil)): recv signal r_set_params
  87. freeswitch@fpbx01>
  88. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  89. freeswitch@fpbx01>
  90. soa.c:403 soa_set_params() soa_set_params(static::0x7fce40001930, ...) called
  91. freeswitch@fpbx01>
  92. nua_stack.c:569 nua_stack_signal() nua((nil)): recv signal r_set_params
  93. freeswitch@fpbx01>
  94. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  95. freeswitch@fpbx01>
  96. soa.c:403 soa_set_params() soa_set_params(static::0x7fce60096e10, ...) called
  97. freeswitch@fpbx01>
  98. nua_stack.c:271 nua_stack_event() nua((nil)): event r_set_params 200 OK
  99. freeswitch@fpbx01>
  100. nua_stack.c:271 nua_stack_event() nua((nil)): event r_set_params 200 OK
  101. freeswitch@fpbx01>
  102. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  103. freeswitch@fpbx01>
  104. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  105. freeswitch@fpbx01>
  106. nua_stack.c:529 nua_signal() nua((nil)): sent signal r_set_params
  107. freeswitch@fpbx01>
  108. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  109. freeswitch@fpbx01>
  110. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  111. freeswitch@fpbx01>
  112. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  113. freeswitch@fpbx01>
  114. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce6007ac40): events IN
  115. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce6007ac40)
  116. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce6007ac40): tls_read() returned 4
  117. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce6007ac40) msg 0x7fce60036740 from (tls/185.39.248.196:2658) has 4 bytes, veclen = 1
  118. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
  119. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce60055b50): events IN
  120. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce60055b50)
  121. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce60055b50): tls_read() returned 4
  122. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce60055b50) msg 0x7fce600332f0 from (tls/185.39.250.164:41117) has 4 bytes, veclen = 1
  123. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer
  124. freeswitch@fpbx01>
  125. freeswitch@fpbx01>
  126. freeswitch@fpbx01>
  127. nta.c:1296 agent_timer() nta: timer set next to 6609 ms
  128. nta.c:9107 outgoing_timer_dk() nta: timer D fired, terminate INVITE (5318782)
  129. nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7fce6b73ed30)
  130. nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/1 term, 1/2 free
  131. nta.c:1296 agent_timer() nta: timer set next to 1 ms
  132. nta.c:8988 outgoing_timer_bf() nta: timer F fired, terminating ACK (5318782)
  133. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
  134. nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7fce6b73ed30)
  135. nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/1 tout, 0/0 term, 1/1 free
  136. nta.c:1289 agent_timer() nta: timer not set
  137. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce6007ac40): events IN
  138. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce6007ac40)
  139. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce6007ac40): tls_read() returned 4
  140. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce6007ac40) msg 0x7fce60036740 from (tls/185.39.248.196:2658) has 4 bytes, veclen = 1
  141. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
  142. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN
  143. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0)
  144. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74008dc0 from (tcp/10.55.4.5:55848) has 1248 bytes, veclen = 1
  145. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  146. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN
  147. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0)
  148. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74008dc0 from (tcp/10.55.4.5:55848) has 259 bytes, veclen = 1
  149. recv 1507 bytes from tcp/[10.55.4.5]:55848 at 15:33:16.358341:
  150.    ------------------------------------------------------------------------
  151.    INVITE sip:7667398@10.55.4.7:5080 SIP/2.0
  152.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60c3af46a1f
  153.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  154.    To: <sip:7667398@10.55.4.7>
  155.    Date: Wed, 05 Jun 2019 14:33:16 GMT
  156.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  157.    Supported: timer,resource-priority,replaces
  158.    Min-SE:  1800
  159.    User-Agent: Cisco-CUCM10.5
  160.   Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
  161.    CSeq: 101 INVITE
  162.    Expires: 180
  163.    Allow-Events: presence, kpml
  164.    Supported: X-cisco-srtp-fallback,X-cisco-original-called
  165.    Call-Info: <sip:10.55.4.5:5060>;method="NOTIFY;Event=telephone-event;Duration=500"
  166.    Call-Info: <urn:x-cisco-remotecc:callinfo>;x-cisco-video-traffic-class=VIDEO_UNSPECIFIED
  167.    Cisco-Guid: 3653460864-0000065536-0000003112-0084162314
  168.    Session-Expires:  1800
  169.    P-Asserted-Identity: "Stephen Barry" <sip:7398@10.55.4.5>
  170.    Remote-Party-ID: "Stephen Barry" <sip:7398@10.55.4.5>;party=calling;screen=yes;privacy=off
  171.    Contact: <sip:7398@10.55.4.5:5060;transport=tcp>
  172.    Max-Forwards: 70
  173.    Content-Type: application/sdp
  174.    Content-Length: 360
  175.  
  176.    v=0
  177.    o=CiscoSystemsCCM-SIP 3080835 1 IN IP4 10.55.4.5
  178.    s=SIP Call
  179.    c=IN IP4 10.55.102.51
  180.    b=TIAS:64000
  181.    b=AS:64
  182.    t=0 0
  183.    m=audio 16670 RTP/AVP 9 8 0 116 18 101
  184.    a=rtpmap:9 G722/8000
  185.    a=rtpmap:8 PCMA/8000
  186.    a=rtpmap:0 PCMU/8000
  187.    a=rtpmap:116 iLBC/8000
  188.    a=maxptime:60
  189.    a=fmtp:116 mode=20
  190.    a=rtpmap:18 G729/8000
  191.    a=rtpmap:101 telephone-event/8000
  192.    a=fmtp:101 0-15
  193.    ------------------------------------------------------------------------
  194. tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74008dc0 (1507 bytes) from tcp/10.55.4.5:55848/sip next=(nil)
  195. nta.c:2880 agent_recv_request() nta: received INVITE sip:7667398@10.55.4.7:5080 SIP/2.0 (CSeq 101)
  196. nta.c:3248 agent_aliases() nta: canonizing sip:7667398@10.55.4.7:5080 with contact
  197. nta.c:3085 agent_recv_request() nta: INVITE (101) going to a default leg
  198. nta.c:1350 set_timeout() nta: timer set to 2000 ms
  199. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
  200. nua_stack.c:899 nh_create() nua: nh_create: entering
  201. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
  202. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  203. soa.c:280 soa_clone() soa_clone(static::0x7fce74005a30, 0x7fce7400d770, 0x7fce74002fd0) called
  204. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called
  205. nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7fce740033f0)
  206. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fce74014690) called
  207. soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7fce74014690, (nil), 0x7fce74003a9b, 360) called
  208. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fce74002fd0): adding session usage
  209. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_invite 100 Trying
  210. nua_session.c:4139 signal_call_state_change() nua(0x7fce74002fd0): call state changed: init -> received, received offer
  211. soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7fce74014690, [0x7fce6b5ea8d8], [0x7fce6b5ea8e0], [(nil)]) called
  212. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 100 Trying
  213. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  214. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  215. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
  216. 2019-06-05 15:33:16.509165 [NOTICE] switch_channel.c:1104 New Channel sofia/external-lan/7398@10.55.4.5 [6efa6b88-248e-4a15-afca-09df2beb867e]
  217. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  218. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_NEW (Cur 1 Tot 313)
  219. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  220. 2019-06-05 15:33:16.509165 [DEBUG] sofia.c:10092 sofia/external-lan/7398@10.55.4.5 receiving invite from 10.55.4.5:55848 version: 1.8.5 -6-31281a0bf1 64bit
  221. 2019-06-05 15:33:16.509165 [DEBUG] sofia.c:10208 IP 10.55.4.5 Approved by acl "domains[]". Access Granted.
  222. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  223. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  224. 2019-06-05 15:33:16.509165 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [received][100]
  225. 2019-06-05 15:33:16.509165 [DEBUG] sofia.c:7301 Remote SDP:
  226. v=0
  227. o=CiscoSystemsCCM-SIP 3080835 1 IN IP4 10.55.4.5
  228. s=SIP Call
  229. c=IN IP4 10.55.102.51
  230. b=TIAS:64000
  231. b=AS:64
  232. t=0 0
  233. m=audio 16670 RTP/AVP 9 8 0 116 18 101
  234. a=rtpmap:9 G722/8000
  235. a=rtpmap:8 PCMA/8000
  236. a=rtpmap:0 PCMU/8000
  237. a=rtpmap:116 iLBC/8000
  238. a=fmtp:116 mode=20
  239. a=rtpmap:18 G729/8000
  240. a=rtpmap:101 telephone-event/8000
  241. a=fmtp:101 0-15
  242. a=maxptime:60
  243.  
  244. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1]
  245. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1]
  246. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1]
  247. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[G722:9:8000:20:64000:1]
  248. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
  249. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[PCMA:8:8000:20:64000:1]
  250. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[PCMU:0:8000:20:64000:1]
  251. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1]
  252. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1]
  253. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1]
  254. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[G722:9:8000:20:64000:1]
  255. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[PCMA:8:8000:20:64000:1]
  256. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
  257. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[PCMU:0:8000:20:64000:1]
  258. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1]
  259. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1]
  260. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1]
  261. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[G722:9:8000:20:64000:1]
  262. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[PCMA:8:8000:20:64000:1]
  263. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[PCMU:0:8000:20:64000:1]
  264. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
  265. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[opus:116:48000:20:0:1]
  266. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[opus:116:48000:20:0:1]
  267. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[opus:116:48000:20:0:1]
  268. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[G722:9:8000:20:64000:1]
  269. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[PCMA:8:8000:20:64000:1]
  270. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[PCMU:0:8000:20:64000:1]
  271. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[opus:116:48000:20:0:1]
  272. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[opus:116:48000:20:0:1]
  273. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[opus:116:48000:20:0:1]
  274. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[G722:9:8000:20:64000:1]
  275. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[PCMA:8:8000:20:64000:1]
  276. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[PCMU:0:8000:20:64000:1]
  277. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000
  278. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:3781 Set Codec sofia/external-lan/7398@10.55.4.5 G722/8000 20 ms 160 samples 64000 bits 1 channels
  279. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_codec.c:111 sofia/external-lan/7398@10.55.4.5 Original read codec set to G722:9
  280. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5737 Set telephone-event payload to 101@8000
  281. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5795 sofia/external-lan/7398@10.55.4.5 Set 2833 dtmf send payload to 101 recv payload to 101
  282. 2019-06-05 15:33:16.509165 [DEBUG] sofia.c:7716 (sofia/external-lan/7398@10.55.4.5) State Change CS_NEW -> CS_INIT
  283. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  284. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:603 (sofia/external-lan/7398@10.55.4.5) State NEW
  285. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_INIT (Cur 1 Tot 313)
  286. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:627 (sofia/external-lan/7398@10.55.4.5) State INIT
  287. 2019-06-05 15:33:16.509165 [DEBUG] mod_sofia.c:93 sofia/external-lan/7398@10.55.4.5 SOFIA INIT
  288. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:40 sofia/external-lan/7398@10.55.4.5 Standard INIT
  289. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:48 (sofia/external-lan/7398@10.55.4.5) State Change CS_INIT -> CS_ROUTING
  290. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:627 (sofia/external-lan/7398@10.55.4.5) State INIT going to sleep
  291. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_ROUTING (Cur 1 Tot 313)
  292. 2019-06-05 15:33:16.509165 [DEBUG] switch_channel.c:2249 (sofia/external-lan/7398@10.55.4.5) Callstate Change DOWN -> RINGING
  293. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:643 (sofia/external-lan/7398@10.55.4.5) State ROUTING
  294. nua.c:879 nua_respond() nua: nua_respond: entering
  295. nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 100 Trying
  296. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  297. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called
  298. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
  299. nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond
  300. 2019-06-05 15:33:16.509165 [DEBUG] mod_sofia.c:154 sofia/external-lan/7398@10.55.4.5 SOFIA ROUTING
  301. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:236 sofia/external-lan/7398@10.55.4.5 Standard ROUTING
  302. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 337 bytes of 337 to tcp/10.55.4.5:55848
  303. tport.c:3496 tport_send_msg() tport_vsend returned 337
  304. 2019-06-05 15:33:16.509165 [INFO] mod_dialplan_xml.c:637 Processing Stephen Barry <7398>->7667398 in context public
  305. send 337 bytes to tcp/[10.55.4.5]:55848 at 15:33:16.359409:
  306.    ------------------------------------------------------------------------
  307.    SIP/2.0 100 Trying
  308.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60c3af46a1f;rport=55848
  309.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  310.    To: <sip:7667398@10.55.4.7>
  311.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  312.    CSeq: 101 INVITE
  313.    User-Agent: FreeSWITCH
  314.    Content-Length: 0
  315.  
  316.    ------------------------------------------------------------------------
  317. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  318. nta.c:6797 incoming_reply() nta: sent 100 Trying for INVITE (101)
  319. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [public->caller-details] continue=true
  320. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [caller-details] () =~ // break=never
  321. Dialplan: sofia/external-lan/7398@10.55.4.5 Action export(call_direction=inbound) INLINE
  322. EXECUTE sofia/external-lan/7398@10.55.4.5 export(call_direction=inbound)
  323. 2019-06-05 15:33:16.509165 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[inbound]
  324. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(caller_destination=${destination_number}) INLINE
  325. EXECUTE sofia/external-lan/7398@10.55.4.5 set(caller_destination=7667398)
  326. 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [caller_destination]=[7667398]
  327. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(caller_id_name=${caller_id_name}) INLINE
  328. EXECUTE sofia/external-lan/7398@10.55.4.5 set(caller_id_name=Stephen Barry)
  329. 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [caller_id_name]=[Stephen Barry]
  330. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(caller_id_number=${caller_id_number})
  331. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [public->7667398] continue=false
  332. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [7667398] destination_number(7667398) =~ /^(7667398)$/ break=on-false
  333. Dialplan: sofia/external-lan/7398@10.55.4.5 Action export(call_direction=inbound) INLINE
  334. EXECUTE sofia/external-lan/7398@10.55.4.5 export(call_direction=inbound)
  335. 2019-06-05 15:33:16.509165 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[inbound]
  336. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(domain_uuid=4772272a-5245-454d-8520-d9e852b4c5a2) INLINE
  337. EXECUTE sofia/external-lan/7398@10.55.4.5 set(domain_uuid=4772272a-5245-454d-8520-d9e852b4c5a2)
  338. 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [domain_uuid]=[4772272a-5245-454d-8520-d9e852b4c5a2]
  339. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(domain_name=voip.mydomain.com) INLINE
  340. EXECUTE sofia/external-lan/7398@10.55.4.5 set(domain_name=voip.mydomain.com)
  341. 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [domain_name]=[voip.mydomain.com]
  342. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(hangup_after_bridge=true)
  343. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(continue_on_fail=true)
  344. Dialplan: sofia/external-lan/7398@10.55.4.5 Action transfer(7667398 XML voip.mydomain.com)
  345. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:286 (sofia/external-lan/7398@10.55.4.5) State Change CS_ROUTING -> CS_EXECUTE
  346. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:643 (sofia/external-lan/7398@10.55.4.5) State ROUTING going to sleep
  347. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_EXECUTE (Cur 1 Tot 313)
  348. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:650 (sofia/external-lan/7398@10.55.4.5) State EXECUTE
  349. 2019-06-05 15:33:16.509165 [DEBUG] mod_sofia.c:209 sofia/external-lan/7398@10.55.4.5 SOFIA EXECUTE
  350. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:328 sofia/external-lan/7398@10.55.4.5 Standard EXECUTE
  351. EXECUTE sofia/external-lan/7398@10.55.4.5 set(caller_id_number=7398)
  352. 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [caller_id_number]=[7398]
  353. EXECUTE sofia/external-lan/7398@10.55.4.5 set(hangup_after_bridge=true)
  354. 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [hangup_after_bridge]=[true]
  355. EXECUTE sofia/external-lan/7398@10.55.4.5 set(continue_on_fail=true)
  356. 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [continue_on_fail]=[true]
  357. EXECUTE sofia/external-lan/7398@10.55.4.5 transfer(7667398 XML voip.mydomain.com)
  358. 2019-06-05 15:33:16.509165 [DEBUG] switch_ivr.c:2207 (sofia/external-lan/7398@10.55.4.5) State Change CS_EXECUTE -> CS_ROUTING
  359. 2019-06-05 15:33:16.509165 [NOTICE] switch_ivr.c:2214 Transfer sofia/external-lan/7398@10.55.4.5 to XML[7667398@voip.mydomain.com]
  360. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:650 (sofia/external-lan/7398@10.55.4.5) State EXECUTE going to sleep
  361. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_ROUTING (Cur 1 Tot 313)
  362. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:643 (sofia/external-lan/7398@10.55.4.5) State ROUTING
  363. 2019-06-05 15:33:16.509165 [DEBUG] mod_sofia.c:145 Call appears to be already acknowledged
  364. 2019-06-05 15:33:16.509165 [DEBUG] mod_sofia.c:154 sofia/external-lan/7398@10.55.4.5 SOFIA ROUTING
  365. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:236 sofia/external-lan/7398@10.55.4.5 Standard ROUTING
  366. 2019-06-05 15:33:16.509165 [INFO] mod_dialplan_xml.c:637 Processing Stephen Barry <7398>->7667398 in context voip.mydomain.com
  367. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->user_exists] continue=true
  368. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_exists] () =~ // break=on-false
  369. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
  370. EXECUTE sofia/external-lan/7398@10.55.4.5 set(user_exists=true)
  371. 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [user_exists]=[true]
  372. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_exists] ${user_exists}(true) =~ /^true$/ break=on-false
  373. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(extension_uuid=${user_data ${destination_number}@${domain_name} var extension_uuid}) INLINE
  374. EXECUTE sofia/external-lan/7398@10.55.4.5 set(extension_uuid=d268f1c9-32b4-46c7-8c22-74012c9929ac)
  375. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [extension_uuid]=[d268f1c9-32b4-46c7-8c22-74012c9929ac]
  376. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(hold_music=${user_data ${destination_number}@${domain_name} var hold_music}) INLINE
  377. EXECUTE sofia/external-lan/7398@10.55.4.5 set(hold_music=)
  378. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [hold_music]=[UNDEF]
  379. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) INLINE
  380. EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_all_enabled=)
  381. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_all_enabled]=[UNDEF]
  382. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_all_destination=${user_data ${destination_number}@${domain_name} var forward_all_destination}) INLINE
  383. EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_all_destination=)
  384. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_all_destination]=[UNDEF]
  385. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_busy_enabled=${user_data ${destination_number}@${domain_name} var forward_busy_enabled}) INLINE
  386. EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_busy_enabled=)
  387. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_busy_enabled]=[UNDEF]
  388. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_busy_destination=${user_data ${destination_number}@${domain_name} var forward_busy_destination}) INLINE
  389. EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_busy_destination=)
  390. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_busy_destination]=[UNDEF]
  391. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_no_answer_enabled=${user_data ${destination_number}@${domain_name} var forward_no_answer_enabled}) INLINE
  392. EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_no_answer_enabled=)
  393. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_no_answer_enabled]=[UNDEF]
  394. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_no_answer_destination=${user_data ${destination_number}@${domain_name} var forward_no_answer_destination}) INLINE
  395. EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_no_answer_destination=)
  396. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_no_answer_destination]=[UNDEF]
  397. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_user_not_registered_enabled=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_enabled}) INLINE
  398. EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_user_not_registered_enabled=)
  399. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_user_not_registered_enabled]=[UNDEF]
  400. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_user_not_registered_destination=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_destination}) INLINE
  401. EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_user_not_registered_destination=)
  402. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_user_not_registered_destination]=[UNDEF]
  403. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) INLINE
  404. EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_all_enabled=)
  405. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_all_enabled]=[UNDEF]
  406. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(do_not_disturb=${user_data ${destination_number}@${domain_name} var do_not_disturb}) INLINE
  407. EXECUTE sofia/external-lan/7398@10.55.4.5 set(do_not_disturb=)
  408. 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [do_not_disturb]=[UNDEF]
  409. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(call_timeout=${user_data ${destination_number}@${domain_name} var call_timeout}) INLINE
  410. EXECUTE sofia/external-lan/7398@10.55.4.5 set(call_timeout=30)
  411. 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [call_timeout]=[30]
  412. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(missed_call_app=${user_data ${destination_number}@${domain_name} var missed_call_app}) INLINE
  413. EXECUTE sofia/external-lan/7398@10.55.4.5 set(missed_call_app=)
  414. 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [missed_call_app]=[UNDEF]
  415. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(missed_call_data=${user_data ${destination_number}@${domain_name} var missed_call_data}) INLINE
  416. EXECUTE sofia/external-lan/7398@10.55.4.5 set(missed_call_data=)
  417. 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [missed_call_data]=[UNDEF]
  418. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(toll_allow=${user_data ${destination_number}@${domain_name} var toll_allow}) INLINE
  419. EXECUTE sofia/external-lan/7398@10.55.4.5 set(toll_allow=)
  420. 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [toll_allow]=[UNDEF]
  421. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(call_screen_enabled=${user_data ${destination_number}@${domain_name} var call_screen_enabled}) INLINE
  422. EXECUTE sofia/external-lan/7398@10.55.4.5 set(call_screen_enabled=false)
  423. 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [call_screen_enabled]=[false]
  424. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE
  425. EXECUTE sofia/external-lan/7398@10.55.4.5 set(user_record=)
  426. 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [user_record]=[UNDEF]
  427. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->caller-details] continue=true
  428. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [caller-details] ${caller_destination}(7667398) =~ /^$/ break=never
  429. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->call-direction] continue=true
  430. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [call-direction] ${call_direction}(inbound) =~ /^(inbound|outbound|local)$/ break=never
  431. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->variables] continue=true
  432. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [variables] () =~ // break=on-false
  433. Dialplan: sofia/external-lan/7398@10.55.4.5 Action export(origination_callee_id_name=${destination_number})
  434. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
  435. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->user_record] continue=true
  436. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] () =~ // break=on-false
  437. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
  438. EXECUTE sofia/external-lan/7398@10.55.4.5 set(from_user_exists=false)
  439. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [from_user_exists]=[false]
  440. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
  441. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
  442. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
  443. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
  444. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
  445. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
  446. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
  447. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
  448. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
  449. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
  450. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
  451. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
  452. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
  453. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
  454. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
  455. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
  456. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
  457. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
  458. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
  459. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
  460. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
  461. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
  462. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
  463. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
  464. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->redial] continue=true
  465. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [redial] destination_number(7667398) =~ /^(redial|\*870)$/ break=on-true
  466. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [redial] () =~ // break=never
  467. Dialplan: sofia/external-lan/7398@10.55.4.5 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
  468. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->speed_dial] continue=false
  469. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [speed_dial] destination_number(7667398) =~ /^\*0(.*)$/ break=on-false
  470. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->default_caller_id] continue=true
  471. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [default_caller_id] ${emergency_caller_id_number}() =~ /^$/ break=never
  472. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(emergency_caller_id_name=${default_emergency_caller_id_name}) INLINE
  473. EXECUTE sofia/external-lan/7398@10.55.4.5 set(emergency_caller_id_name=)
  474. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [emergency_caller_id_name]=[UNDEF]
  475. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(emergency_caller_id_number=${default_emergency_caller_id_number}) INLINE
  476. EXECUTE sofia/external-lan/7398@10.55.4.5 set(emergency_caller_id_number=)
  477. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [emergency_caller_id_number]=[UNDEF]
  478. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [default_caller_id] ${outbound_caller_id_number}() =~ /^$/ break=never
  479. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(outbound_caller_id_name=${default_outbound_caller_id_name}) INLINE
  480. EXECUTE sofia/external-lan/7398@10.55.4.5 set(outbound_caller_id_name=)
  481. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [outbound_caller_id_name]=[UNDEF]
  482. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(outbound_caller_id_number=${default_outbound_caller_id_number}) INLINE
  483. EXECUTE sofia/external-lan/7398@10.55.4.5 set(outbound_caller_id_number=)
  484. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [outbound_caller_id_number]=[UNDEF]
  485. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->bxrp-ln5-cucm02.d4] continue=false
  486. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [bxrp-ln5-cucm02.d4] ${user_exists}(true) =~ /false/ break=on-false
  487. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->bxrp-ln5-cucm02.uk.local.11] continue=false
  488. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [bxrp-ln5-cucm02.uk.local.11] ${user_exists}(true) =~ /false/ break=on-false
  489. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->bxrp-ln5-cucm02.uk.local.11] continue=false
  490. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [bxrp-ln5-cucm02.uk.local.11] ${user_exists}(true) =~ /false/ break=on-false
  491. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->bxrp-ln5-cucm02.uk.local.10.05800] continue=false
  492. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [bxrp-ln5-cucm02.uk.local.10.05800] ${user_exists}(true) =~ /false/ break=on-false
  493. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->agent_status] continue=false
  494. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [agent_status] destination_number(7667398) =~ /^\*22$/ break=on-false
  495. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->agent_status_id] continue=false
  496. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [agent_status_id] destination_number(7667398) =~ /^\*23$/ break=on-false
  497. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->group-intercept] continue=false
  498. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [group-intercept] destination_number(7667398) =~ /^\*8$/ break=on-false
  499. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->page-extension] continue=false
  500. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [page-extension] destination_number(7667398) =~ /^\*8(\d{2,7})$/ break=on-false
  501. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->eavesdrop] continue=false
  502. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [eavesdrop] destination_number(7667398) =~ /^\*33(\d{2,7})$/ break=on-false
  503. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->call_privacy] continue=false
  504. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call_privacy] destination_number(7667398) =~ /^\*67(\d+)$/ break=on-false
  505. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->call_return] continue=false
  506. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call_return] destination_number(7667398) =~ /^\*69$/ break=on-false
  507. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->intercept-ext-polycom] continue=false
  508. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [intercept-ext-polycom] destination_number(7667398) =~ /^\*97(\d+)$/ break=on-false
  509. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->intercept-ext] continue=false
  510. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [intercept-ext] destination_number(7667398) =~ /^\*\*(\d+)$/ break=on-true
  511. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [intercept-ext] destination_number(7667398) =~ /^\*\*$/ break=on-false
  512. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->extension_queue] continue=false
  513. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [extension_queue] destination_number(7667398) =~ /^\*800(.*)$/ break=on-false
  514. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->dx] continue=false
  515. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [dx] destination_number(7667398) =~ /^dx$/ break=on-false
  516. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->att_xfer] continue=false
  517. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [att_xfer] destination_number(7667398) =~ /^att_xfer$/ break=on-false
  518. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->send_to_voicemail] continue=false
  519. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [send_to_voicemail] destination_number(7667398) =~ /^\*99(\d{2,10})$/ break=on-false
  520. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->extension-to-voicemail] continue=false
  521. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [extension-to-voicemail] ${user_exists}(true) =~ /^true$/ break=on-false
  522. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [extension-to-voicemail] username(7398) =~ /^7398$/ break=on-false
  523. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [extension-to-voicemail] destination_number(7667398) =~ /^7398$/ break=on-false
  524. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->xfer_vm] continue=false
  525. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [xfer_vm] destination_number(7667398) =~ /^xfer_vm$/ break=on-false
  526. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->vmain] continue=false
  527. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [vmain] destination_number(7667398) =~ /^vmain$|^\*4000$|^\*98$/ break=never
  528. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [vmain] destination_number(7667398) =~ /^(vmain$|^\*4000$|^\*98)(\d{2,12})$/ break=on-false
  529. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->vmain_user] continue=false
  530. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [vmain_user] destination_number(7667398) =~ /^\*97$/ break=on-false
  531. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->is_transfer] continue=false
  532. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [is_transfer] destination_number(7667398) =~ /^is_transfer$/ break=on-false
  533. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->delay_echo] continue=false
  534. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [delay_echo] destination_number(7667398) =~ /^\*9195$/ break=on-false
  535. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->cf] continue=false
  536. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [cf] destination_number(7667398) =~ /^cf$/ break=on-false
  537. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->echo] continue=false
  538. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [echo] destination_number(7667398) =~ /^\*9196$/ break=on-false
  539. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->milliwatt] continue=false
  540. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [milliwatt] destination_number(7667398) =~ /^\*9197$/ break=on-false
  541. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->is_zrtp_secure] continue=true
  542. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [is_zrtp_secure] ${zrtp_secure_media_confirmed}() =~ /^true$/ break=on-false
  543. Dialplan: sofia/external-lan/7398@10.55.4.5 ANTI-Action eval(not_secure)
  544. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->is_secure] continue=true
  545. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [is_secure] ${sip_via_protocol}(tcp) =~ /tls/ break=on-false
  546. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->tone_stream] continue=false
  547. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [tone_stream] destination_number(7667398) =~ /^\*9198$/ break=on-false
  548. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->hold_music] continue=false
  549. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [hold_music] destination_number(7667398) =~ /^\*9664$/ break=on-false
  550. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->recordings] continue=false
  551. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [recordings] destination_number(7667398) =~ /^\*(732)$/ break=on-false
  552. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->directory] continue=false
  553. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [directory] destination_number(7667398) =~ /^\*411$/ break=on-false
  554. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->wake-up] continue=false
  555. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [wake-up] destination_number(7667398) =~ /^\*(925)$/ break=on-false
  556. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->valet_park] continue=false
  557. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [valet_park] destination_number(7667398) =~ /^(park\+)?\*(59[0-9][0-9])$/ break=never
  558. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [valet_park] ${sip_h_Referred-By}() =~ /sip:(.*)@.*/ break=never
  559. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [valet_park] destination_number(7667398) =~ /^(park\+)?\*(59[0-9][0-9])$/ break=never
  560. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [valet_park] destination_number(7667398) =~ /^(park\+)?\*(59[0-9][0-9])$/ break=on-false
  561. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->operator] continue=false
  562. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [operator] destination_number(7667398) =~ /^0$|^operator$/ break=on-false
  563. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->operator-forward] continue=false
  564. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [operator-forward] destination_number(7667398) =~ /^\*000$/ break=on-false
  565. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->do-not-disturb] continue=false
  566. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [do-not-disturb] destination_number(7667398) =~ /^\*77$/ break=on-true
  567. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [do-not-disturb] destination_number(7667398) =~ /^\*78$|\*363$/ break=on-true
  568. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [do-not-disturb] destination_number(7667398) =~ /^\*79$/ break=on-true
  569. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [do-not-disturb] destination_number(7667398) =~ /^dnd\+7398$/ break=on-true
  570. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->call-forward] continue=false
  571. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call-forward] destination_number(7667398) =~ /^\*72$/ break=on-true
  572. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call-forward] destination_number(7667398) =~ /^\*73$/ break=on-true
  573. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call-forward] destination_number(7667398) =~ /^\*74$/ break=on-true
  574. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call-forward] destination_number(7667398) =~ /^forward\+(\Q7398\E)(?:\/(\d+))?$/ break=on-true
  575. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->call forward all] continue=false
  576. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [call forward all] ${user_exists}(true) =~ /true/ break=on-false
  577. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call forward all] ${forward_all_enabled}() =~ /true/ break=on-false
  578. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->follow-me] continue=false
  579. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [follow-me] destination_number(7667398) =~ /^\*21$/ break=on-false
  580. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->clear_sip_auto_answer] continue=true
  581. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [clear_sip_auto_answer] ${click_to_call}() =~ /true/ break=on-false
  582. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->talking clock date and time] continue=true
  583. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [talking clock date and time] destination_number(7667398) =~ /^\*9172$/ break=on-false
  584. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->talking clock time] continue=true
  585. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [talking clock time] destination_number(7667398) =~ /^\*9170$/ break=on-false
  586. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->talking clock date] continue=true
  587. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [talking clock date] destination_number(7667398) =~ /^\*9171$/ break=on-false
  588. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->call_screen] continue=true
  589. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call_screen] ${call_screen_enabled}(false) =~ /^true$/ break=on-false
  590. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->local_extension] continue=true
  591. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [local_extension] ${user_exists}(true) =~ /true/ break=on-false
  592. Dialplan: sofia/external-lan/7398@10.55.4.5 Action export(dialed_extension=${destination_number}) INLINE
  593. EXECUTE sofia/external-lan/7398@10.55.4.5 export(dialed_extension=7667398)
  594. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[7667398]
  595. Dialplan: sofia/external-lan/7398@10.55.4.5 Action limit(hash ${domain_name} ${destination_number} ${limit_max} ${limit_destination})
  596. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(rtp_secure_media=true)
  597. Dialplan: sofia/external-lan/7398@10.55.4.5 Action export(rtp_secure_media=true)
  598. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [local_extension] () =~ // break=on-false
  599. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(hangup_after_bridge=true)
  600. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(continue_on_fail=true)
  601. Dialplan: sofia/external-lan/7398@10.55.4.5 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
  602. Dialplan: sofia/external-lan/7398@10.55.4.5 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
  603. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(called_party_call_group=${user_data(${dialed_extension}@${domain_name} var call_group)})
  604. Dialplan: sofia/external-lan/7398@10.55.4.5 Action hash(insert/${domain_name}-last_dial/${called_party_call_group}/${uuid})
  605. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(api_hangup_hook=lua app.lua hangup)
  606. Dialplan: sofia/external-lan/7398@10.55.4.5 Action export(domain_name=${domain_name})
  607. Dialplan: sofia/external-lan/7398@10.55.4.5 Action bridge(user/${destination_number}@${domain_name})
  608. Dialplan: sofia/external-lan/7398@10.55.4.5 Action lua(app.lua failure_handler)
  609. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->voicemail] continue=false
  610. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [voicemail] ${user_exists}(true) =~ /true/ break=on-false
  611. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(record_append=false)
  612. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(voicemail_action=save)
  613. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(voicemail_id=${destination_number})
  614. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(voicemail_profile=default)
  615. Dialplan: sofia/external-lan/7398@10.55.4.5 Action lua(app.lua voicemail)
  616. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:286 (sofia/external-lan/7398@10.55.4.5) State Change CS_ROUTING -> CS_EXECUTE
  617. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:643 (sofia/external-lan/7398@10.55.4.5) State ROUTING going to sleep
  618. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_EXECUTE (Cur 1 Tot 313)
  619. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:650 (sofia/external-lan/7398@10.55.4.5) State EXECUTE
  620. 2019-06-05 15:33:16.569170 [DEBUG] mod_sofia.c:209 sofia/external-lan/7398@10.55.4.5 SOFIA EXECUTE
  621. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:328 sofia/external-lan/7398@10.55.4.5 Standard EXECUTE
  622. EXECUTE sofia/external-lan/7398@10.55.4.5 export(origination_callee_id_name=7667398)
  623. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[7667398]
  624. EXECUTE sofia/external-lan/7398@10.55.4.5 set(RFC2822_DATE=Wed, 05 Jun 2019 15:33:16 +0100)
  625. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [RFC2822_DATE]=[Wed, 05 Jun 2019 15:33:16 +0100]
  626. EXECUTE sofia/external-lan/7398@10.55.4.5 hash(insert/voip.mydomain.com-last_dial/7398/7667398)
  627. EXECUTE sofia/external-lan/7398@10.55.4.5 eval(not_secure)
  628. EXECUTE sofia/external-lan/7398@10.55.4.5 limit(hash voip.mydomain.com 7667398  )
  629. 2019-06-05 15:33:16.569170 [DEBUG] switch_limit.c:126 incr called: voip.mydomain.com_7667398 max:-1, interval:0
  630. 2019-06-05 15:33:16.569170 [DEBUG] mod_hash.c:194 Usage for voip.mydomain.com_7667398 is now 1
  631. EXECUTE sofia/external-lan/7398@10.55.4.5 set(rtp_secure_media=true)
  632. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [rtp_secure_media]=[true]
  633. EXECUTE sofia/external-lan/7398@10.55.4.5 export(rtp_secure_media=true)
  634. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [rtp_secure_media]=[true]
  635. EXECUTE sofia/external-lan/7398@10.55.4.5 set(hangup_after_bridge=true)
  636. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [hangup_after_bridge]=[true]
  637. EXECUTE sofia/external-lan/7398@10.55.4.5 set(continue_on_fail=true)
  638. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [continue_on_fail]=[true]
  639. EXECUTE sofia/external-lan/7398@10.55.4.5 hash(insert/voip.mydomain.com-call_return/7667398/7398)
  640. EXECUTE sofia/external-lan/7398@10.55.4.5 hash(insert/voip.mydomain.com-last_dial_ext/7667398/6efa6b88-248e-4a15-afca-09df2beb867e)
  641. EXECUTE sofia/external-lan/7398@10.55.4.5 set(called_party_call_group=)
  642. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [called_party_call_group]=[UNDEF]
  643. EXECUTE sofia/external-lan/7398@10.55.4.5 hash(insert/voip.mydomain.com-last_dial//6efa6b88-248e-4a15-afca-09df2beb867e)
  644. EXECUTE sofia/external-lan/7398@10.55.4.5 set(api_hangup_hook=lua app.lua hangup)
  645. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [api_hangup_hook]=[lua app.lua hangup]
  646. EXECUTE sofia/external-lan/7398@10.55.4.5 export(domain_name=voip.mydomain.com)
  647. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [domain_name]=[voip.mydomain.com]
  648. EXECUTE sofia/external-lan/7398@10.55.4.5 bridge(user/7667398@voip.mydomain.com)
  649. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [call_direction]=[inbound] to event
  650. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [call_direction]=[inbound] to event
  651. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [dialed_extension]=[7667398] to event
  652. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [origination_callee_id_name]=[7667398] to event
  653. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [rtp_secure_media]=[true] to event
  654. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [domain_name]=[voip.mydomain.com] to event
  655. 2019-06-05 15:33:16.569170 [DEBUG] switch_ivr_originate.c:2204 Parsing global variables
  656. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [call_direction]=[inbound] to event
  657. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [call_direction]=[inbound] to event
  658. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [dialed_extension]=[7667398] to event
  659. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [origination_callee_id_name]=[7667398] to event
  660. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [rtp_secure_media]=[true] to event
  661. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [domain_name]=[voip.mydomain.com] to event
  662. 2019-06-05 15:33:16.569170 [DEBUG] switch_ivr_originate.c:2204 Parsing global variables
  663. 2019-06-05 15:33:16.569170 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/7667398@185.39.248.196:2658 [ed928a3a-dd04-4402-979f-fafeb5f358be]
  664. 2019-06-05 15:33:16.569170 [DEBUG] mod_sofia.c:5019 (sofia/internal/7667398@185.39.248.196:2658) State Change CS_NEW -> CS_INIT
  665. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_INIT (Cur 2 Tot 314)
  666. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/7667398@185.39.248.196:2658) State INIT
  667. 2019-06-05 15:33:16.569170 [DEBUG] mod_sofia.c:93 sofia/internal/7667398@185.39.248.196:2658 SOFIA INIT
  668. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [1 AEAD_AES_256_GCM_8 inline:joxzIiOnMXQSer1e+gE4ojRBThpOdCB43dKiLSqImbfVJ/22f1BqVp6LaSw=]
  669. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [1 AEAD_AES_256_GCM_8 inline:faMAxHTT6xDoJK8DG73nmIUiV6vOV5VlZoIbT3R78Sheqtqx/wHBkkCyYPo=]
  670. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [1 AEAD_AES_256_GCM_8 inline:QrHLk+2xbt+WkyRhJS83PIvqTPYaOVIhxFWkuON5ouNG/9N+M9dZWic9gbI=]
  671. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [2 AEAD_AES_128_GCM_8 inline:B9xOOteDHBIOuFVnpn+EhGDf/p0v4D5wsK0Ofg==]
  672. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [2 AEAD_AES_128_GCM_8 inline:4tayk1/aJmWWBCPxKb6uc/oGDK7xoBldZYU9yw==]
  673. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [2 AEAD_AES_128_GCM_8 inline:LnAqV/YThGG5+O+aaIYB9eTBv5jbwa+EMqer4w==]
  674. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [3 AES_256_CM_HMAC_SHA1_80 inline:CRKhSQX3TQb0Yaq2myBlt72OVJWtOgT4eeh3cX56N9xaPaRw6sWCFJzX+7QWkw==]
  675. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [3 AES_256_CM_HMAC_SHA1_80 inline:azOC6kxeppg9ZO09Qg+mw/7YWCVvx93U3HiKGUqY1ZP2bE/L0IPgmbtAE5gyaQ==]
  676. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [3 AES_256_CM_HMAC_SHA1_80 inline:ztZhc1/jJ7zSRK7co49aXvAXdd7A5d4c46Yl9eEDlc++s6mtpZqTvyIEoBKT/g==]
  677. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [4 AES_192_CM_HMAC_SHA1_80 inline:FHcYFnm81ZxtPNipVZ4h5rWBFmfLKwUC0GBT9j5eX5UHXKhM/AU=]
  678. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [4 AES_192_CM_HMAC_SHA1_80 inline:S3fooEDZ43IEd93bwM4y/lAKHIFwjgc1Oa8yCl9YrAelsD99uGE=]
  679. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [4 AES_192_CM_HMAC_SHA1_80 inline:uaOx/NSQpRl9+UbNiAC3p6N2cYjavh/ai7LCm42DdacMXJH7d7g=]
  680. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [5 AES_CM_128_HMAC_SHA1_80 inline:kt/kEwS1HZb3cDc9dO3lMeVMSVNrphk7xDzOjP61]
  681. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [5 AES_CM_128_HMAC_SHA1_80 inline:2GqvJpVS1GbdKdRWRCxHFrPklrTBXn1N6u8DyA/Q]
  682. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [5 AES_CM_128_HMAC_SHA1_80 inline:Lk2H537S/4alzeJJM/7olJj7K0XcPBx7GkUmnEvM]
  683. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [6 AES_256_CM_HMAC_SHA1_32 inline:a/N0PngYZ61YZ2qnqlpZiZVjg0kaOIzie+C7x1J/HH6SEbu1h4GtVDB7PML9pA==]
  684. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [6 AES_256_CM_HMAC_SHA1_32 inline:yL1fqzga6CRH1TCisIgdgNkrtCkr1IKAOj+NOsGvJA7CWio8vQTnE5Wtx8keHQ==]
  685. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [6 AES_256_CM_HMAC_SHA1_32 inline:rhqYIdU+/AtoDOvLtpw6xBnuyoIz2gQc/hppkjM+kPi4F2R5dxlQZK0UlvNUlQ==]
  686. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [7 AES_192_CM_HMAC_SHA1_32 inline:t2ajot1NVJWiHu7bKwirL9wCY6IXrwD/5GR+pP/VeI8+6dhkSbE=]
  687. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [7 AES_192_CM_HMAC_SHA1_32 inline:GmJdY0oDa1u5KXLocLT38x3ybXHkDDzDFo8HewOk0uZqvR2et6M=]
  688. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [7 AES_192_CM_HMAC_SHA1_32 inline:6ueP5qf7Tdj/PLHI0Nb0pTFrMTlT1qj2weBcrLMF/X/t9c9Y3Ss=]
  689. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [8 AES_CM_128_HMAC_SHA1_32 inline:+mmPBRkPSQd95WZQh8yADqwPO7tUlwEvy6NV+wcT]
  690. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [8 AES_CM_128_HMAC_SHA1_32 inline:EbCU7W6c2iU5bDSIGdEaXJJCBbooZVNE6yHAKegu]
  691. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [8 AES_CM_128_HMAC_SHA1_32 inline:PsTZCAm6QE5Uyp2B8TK5qhmmwGAC9gD89JYRFCxE]
  692. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [9 AES_CM_128_NULL_AUTH inline:uxnfyhaXMQp1ZYtMc6XSG3EMsTw7xXKCrbTr5YNH]
  693. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [9 AES_CM_128_NULL_AUTH inline:WPUvScKp4hkNaGVgmwQZrSoIhsmi88d6KmVYTRu9]
  694. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [9 AES_CM_128_NULL_AUTH inline:u2vFsaUv8vSDHNufV+j1Hc374p+Jqyv0cfMY7r8v]
  695. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
  696. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
  697. 2019-06-05 15:33:16.569170 [DEBUG] sofia_glue.c:1271 sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls Setting proxy route to sofia/internal/7667398@185.39.248.196:2658
  698. 2019-06-05 15:33:16.569170 [DEBUG] sofia_glue.c:1302 sofia/internal/7667398@185.39.248.196:2658 sending invite version: 1.8.5 -6-31281a0bf1 64bit
  699. Local SDP:
  700. v=0
  701. o=FreeSWITCH 1559728248 1559728249 IN IP4 185.39.250.165
  702. s=FreeSWITCH
  703. c=IN IP4 185.39.250.165
  704. t=0 0
  705. m=audio 16948 RTP/SAVP 9 102 103 104 8 0 101 13 105 106
  706. a=rtpmap:9 G722/8000
  707. a=rtpmap:102 opus/48000/2
  708. a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40
  709. a=rtpmap:103 opus/48000/2
  710. a=fmtp:103 useinbandfec=1; maxaveragebitrate=20000; maxplaybackrate=16000; sprop-maxcapturerate=16000; ptime=20; minptime=10; maxptime=60
  711. a=rtpmap:104 opus/48000/2
  712. a=fmtp:104 useinbandfec=1; maxaveragebitrate=14000; maxplaybackrate=8000; sprop-maxcapturerate=8000; ptime=20; minptime=10; maxptime=120
  713. a=rtpmap:8 PCMA/8000
  714. a=rtpmap:0 PCMU/8000
  715. a=rtpmap:101 telephone-event/8000
  716. a=fmtp:101 0-16
  717. a=rtpmap:105 telephone-event/48000
  718. a=fmtp:105 0-16
  719. a=crypto:1 AEAD_AES_256_GCM_8 inline:joxzIiOnMXQSer1e+gE4ojRBThpOdCB43dKiLSqImbfVJ/22f1BqVp6LaSw=
  720. a=crypto:2 AEAD_AES_128_GCM_8 inline:B9xOOteDHBIOuFVnpn+EhGDf/p0v4D5wsK0Ofg==
  721. a=crypto:3 AES_256_CM_HMAC_SHA1_80 inline:CRKhSQX3TQb0Yaq2myBlt72OVJWtOgT4eeh3cX56N9xaPaRw6sWCFJzX+7QWkw==
  722. a=crypto:4 AES_192_CM_HMAC_SHA1_80 inline:FHcYFnm81ZxtPNipVZ4h5rWBFmfLKwUC0GBT9j5eX5UHXKhM/AU=
  723. a=crypto:5 AES_CM_128_HMAC_SHA1_80 inline:kt/kEwS1HZb3cDc9dO3lMeVMSVNrphk7xDzOjP61
  724. a=crypto:6 AES_256_CM_HMAC_SHA1_32 inline:a/N0PngYZ61YZ2qnqlpZiZVjg0kaOIzie+C7x1J/HH6SEbu1h4GtVDB7PML9pA==
  725. a=crypto:7 AES_192_CM_HMAC_SHA1_32 inline:t2ajot1NVJWiHu7bKwirL9wCY6IXrwD/5GR+pP/VeI8+6dhkSbE=
  726. a=crypto:8 AES_CM_128_HMAC_SHA1_32 inline:+mmPBRkPSQd95WZQh8yADqwPO7tUlwEvy6NV+wcT
  727. a=crypto:9 AES_CM_128_NULL_AUTH inline:uxnfyhaXMQp1ZYtMc6XSG3EMsTw7xXKCrbTr5YNH
  728. a=rtpmap:13 CN/8000
  729. a=rtpmap:106 CN/48000
  730. a=ptime:20
  731. a=sendrecv
  732.  
  733. nua.c:633 nua_invite() nua: nua_invite: entering
  734. nua_stack.c:569 nua_stack_signal() nua(0x7fce6c02f9a0): recv signal r_invite
  735. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  736. soa.c:280 soa_clone() soa_clone(static::0x7fce60096e10, 0x7fce6007dde0, 0x7fce6c02f9a0) called
  737. soa.c:403 soa_set_params() soa_set_params(static::0x7fce600921a0, ...) called
  738. soa.c:403 soa_set_params() soa_set_params(static::0x7fce600921a0, ...) called
  739. soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fce600921a0, (nil), 0x7fce6c147ba2, -1) called
  740. soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7fce600921a0, (nil), 0x7fce6c147ba2, -1) called
  741. nua_stack.c:529 nua_signal() nua(0x7fce6c02f9a0): sent signal r_invite
  742. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:40 sofia/internal/7667398@185.39.248.196:2658 Standard INIT
  743. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/7667398@185.39.248.196:2658) State Change CS_INIT -> CS_ROUTING
  744. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/7667398@185.39.248.196:2658) State INIT going to sleep
  745. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fce6c02f9a0): adding session usage
  746. nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7fce60050880)
  747. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fce600921a0) called
  748. soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7fce600921a0, 0) called
  749. soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fce600921a0, soa_generate_offer): called
  750. soa_static.c:1189 offer_answer_step() soa_static(0x7fce600921a0, soa_generate_offer): generating local description
  751. soa_static.c:1217 offer_answer_step() soa_static(0x7fce600921a0, soa_generate_offer): upgrade with local description
  752. soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fce6b73ca70, (nil), ""): called
  753. soa_static.c:1446 offer_answer_step() soa_static(0x7fce600921a0, soa_generate_offer): storing local description
  754. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce600921a0, [(nil)], [0x7fce6b73ebf8], [0x7fce6b73ebf4]) called
  755. nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
  756. tport.c:4592 tport_by_name() tport(0x7fce600466b0): found 0x7fce6007ac40 by name tls/185.39.248.196:2658
  757. tport.c:3261 tport_tsend() tport_tsend(0x7fce6007ac40) tpn = tls/185.39.248.196:2658
  758. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce6007ba80 0x7fce60061910 993 (993)
  759. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce6007ba80 0x7fce6005b1c0 68 (68)
  760. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce6007ba80 0x7fce60074d90 1697 (1697)
  761. tport.c:3598 tport_vsend() tport_vsend(0x7fce6007ac40): 2758 bytes of 2758 to tls/185.39.248.196:2658
  762. tport.c:3496 tport_send_msg() tport_vsend returned 2758
  763. send 2758 bytes to tls/[185.39.248.196]:2658 at 15:33:16.418836:
  764.    ------------------------------------------------------------------------
  765.    INVITE sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls SIP/2.0
  766.    Via: SIP/2.0/TLS 185.39.250.165:5061;rport;branch=z9hG4bKaFrX8FtHvD96Q
  767.    Route: <sip:7667398@185.39.248.196:2658>;rinstance=117BFF20;transport=tls
  768.    Max-Forwards: 68
  769.    From: "Stephen Barry" <sip:7398@voip.mydomain.com>;tag=pU8rDB8DUHjFe
  770.    To: <sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls>
  771. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_ROUTING (Cur 2 Tot 314)
  772.    Call-ID: b2998455-0241-1238-e9ba-005056860fd6
  773.    CSeq: 5318806 INVITE
  774.    Contact: <sip:mod_sofia@185.39.250.165:5061;transport=tls>
  775.    User-Agent: FreeSWITCH
  776.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  777.    Supported: timer, path, replaces
  778.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
  779.    Privacy: none
  780.    Content-Type: application/sdp
  781.    Content-Disposition: session
  782.    Content-Length: 1697
  783.    X-FS-Support: update_display,send_info
  784.    P-Asserted-Identity: "Stephen Barry" <sip:7398@voip.mydomain.com>
  785.  
  786.    v=0
  787.    o=FreeSWITCH 1559728248 1559728249 IN IP4 185.39.250.165
  788.    s=FreeSWITCH
  789.    c=IN IP4 185.39.250.165
  790.    t=0 0
  791.    m=audio 16948 RTP/SAVP 9 102 103 104 8 0 101 13 105 106
  792.    a=rtpmap:9 G722/8000
  793.    a=rtpmap:102 opus/48000/2
  794.    a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40
  795.    a=rtpmap:103 opus/48000/2
  796.    a=fmtp:103 useinbandfec=1; maxaveragebitrate=20000; maxplaybackrate=16000; sprop-maxcapturerate=16000; ptime=20; minptime=10; maxptime=60
  797.    a=rtpmap:104 opus/48000/2
  798.    a=fmtp:104 useinbandfec=1; maxaveragebitrate=14000; maxplaybackrate=8000; sprop-maxcapturerate=8000; ptime=20; minptime=10; maxptime=120
  799.    a=rtpmap:8 PCMA/8000
  800.    a=rtpmap:0 PCMU/8000
  801.    a=rtpmap:101 telephone-event/8000
  802.    a=fmtp:101 0-16
  803.    a=rtpmap:13 CN/8000
  804.    a=rtpmap:105 telephone-event/48000
  805.    a=fmtp:105 0-16
  806.    a=rtpmap:106 CN/48000
  807.    a=crypto:1 AEAD_AES_256_GCM_8 inline:joxzIiOnMXQSer1e+gE4ojRBThpOdCB43dKiLSqImbfVJ/22f1BqVp6LaSw=
  808.    a=crypto:2 AEAD_AES_128_GCM_8 inline:B9xOOteDHBIOuFVnpn+EhGDf/p0v4D5wsK0Ofg==
  809.    a=crypto:3 AES_256_CM_HMAC_SHA1_80 inline:CRKhSQX3TQb0Yaq2myBlt72OVJWtOgT4eeh3cX56N9xaPaRw6sWCFJzX+7QWkw==
  810.    a=crypto:4 AES_192_CM_HMAC_SHA1_80 inline:FHcYFnm81ZxtPNipVZ4h5rWBFmfLKwUC0GBT9j5eX5UHXKhM/AU=
  811.    a=crypto:5 AES_CM_128_HMAC_SHA1_80 inline:kt/kEwS1HZb3cDc9dO3lMeVMSVNrphk7xDzOjP61
  812.    a=crypto:6 AES_256_CM_HMAC_SHA1_32 inline:a/N0PngYZ61YZ2qnqlpZiZVjg0kaOIzie+C7x1J/HH6SEbu1h4GtVDB7PML9pA==
  813.    a=crypto:7 AES_192_CM_HMAC_SHA1_32 inline:t2ajot1NVJWiHu7bKwirL9wCY6IXrwD/5GR+pP/VeI8+6dhkSbE=
  814.    a=crypto:8 AES_CM_128_HMAC_SHA1_32 inline:+mmPBRkPSQd95WZQh8yADqwPO7tUlwEvy6NV+wcT
  815.    a=crypto:9 AES_CM_128_NULL_AUTH inline:uxnfyhaXMQp1ZYtMc6XSG3EMsTw7xXKCrbTr5YNH
  816.    a=ptime:20
  817.    ------------------------------------------------------------------------
  818. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
  819. nta.c:8310 outgoing_send() nta: sent INVITE (5318806) to tls/185.39.248.196:2658
  820. tport.c:4164 tport_pend() tport_pend(0x7fce6007ac40): pending 0x7fce6008f8c0 for tls/185.39.248.196:2658 (already 0)
  821. nta.c:1350 set_timeout() nta: timer set to 32000 ms
  822. nua_session.c:4139 signal_call_state_change() nua(0x7fce6c02f9a0): call state changed: init -> calling, sent offer
  823. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce600921a0, [0x7fce6b73ebd8], [0x7fce6b73ebe0], [(nil)]) called
  824. nua_stack.c:269 nua_stack_event() nua(0x7fce6c02f9a0): event i_state INVITE sent
  825. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/7667398@185.39.248.196:2658) State ROUTING
  826. 2019-06-05 15:33:16.569170 [DEBUG] mod_sofia.c:154 sofia/internal/7667398@185.39.248.196:2658 SOFIA ROUTING
  827. 2019-06-05 15:33:16.569170 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/7667398@185.39.248.196:2658) State Change CS_ROUTING -> CS_CONSUME_MEDIA
  828. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/7667398@185.39.248.196:2658) State ROUTING going to sleep
  829. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  830. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 314)
  831. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  832. 2019-06-05 15:33:16.569170 [DEBUG] sofia.c:7291 Channel sofia/internal/7667398@185.39.248.196:2658 entering state [calling][0]
  833. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  834. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/7667398@185.39.248.196:2658) State CONSUME_MEDIA
  835. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/7667398@185.39.248.196:2658) State CONSUME_MEDIA going to sleep
  836. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce6007ac40): events IN
  837. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce6007ac40)
  838. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce6007ac40): tls_read() returned 421
  839. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce6007ac40) msg 0x7fce60036740 from (tls/185.39.248.196:2658) has 421 bytes, veclen = 1
  840. recv 421 bytes from tls/[185.39.248.196]:2658 at 15:33:16.593739:
  841.    ------------------------------------------------------------------------
  842.    SIP/2.0 100 Trying
  843.    Via: SIP/2.0/TLS 185.39.250.165:5061;rport=5061;branch=z9hG4bKaFrX8FtHvD96Q;received=185.39.250.165
  844.    From: "Stephen Barry" <sip:7398@voip.mydomain.com>;tag=pU8rDB8DUHjFe
  845.    Call-ID: b2998455-0241-1238-e9ba-005056860fd6
  846.    CSeq: 5318806 INVITE
  847.    To: <sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls>
  848.    User-Agent: Groundwire/5.2.14 (build 1243766; Android 9; arm64-v8a)
  849.    Content-Length: 0
  850.  
  851.    ------------------------------------------------------------------------
  852. tport.c:3027 tport_deliver() tport_deliver(0x7fce6007ac40): msg 0x7fce60036740 (421 bytes) from tls/185.39.248.196:2658/sips next=(nil)
  853. nta.c:3299 agent_recv_response() nta: received 100 Trying for INVITE (5318806)
  854. nta.c:3366 agent_recv_response() nta: 100 Trying is going to a transaction
  855. nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 174.962 ms
  856. tport.c:4226 tport_release() tport_release(0x7fce6007ac40): 0x7fce6008f8c0 by 0x7fce600336a0 with 0x7fce60036740 (preliminary)
  857. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
  858. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce6007ac40): events IN
  859. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce6007ac40)
  860. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce6007ac40): tls_read() returned 607
  861. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce6007ac40) msg 0x7fce60036740 from (tls/185.39.248.196:2658) has 607 bytes, veclen = 1
  862. recv 607 bytes from tls/[185.39.248.196]:2658 at 15:33:16.663273:
  863.    ------------------------------------------------------------------------
  864.    SIP/2.0 180 Ringing
  865.    Via: SIP/2.0/TLS 185.39.250.165:5061;rport=5061;branch=z9hG4bKaFrX8FtHvD96Q;received=185.39.250.165
  866.    Contact: <sip:7667398@185.39.248.196:2658;transport=tls>
  867.    From: "Stephen Barry" <sip:7398@voip.mydomain.com>;tag=pU8rDB8DUHjFe
  868.    Call-ID: b2998455-0241-1238-e9ba-005056860fd6
  869.    CSeq: 5318806 INVITE
  870.    To: <sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls>;tag=AFAB2EFC86E53DF36B3DE9E22393BB2C
  871.   Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
  872.    Supported: replaces, path
  873.    User-Agent: Groundwire/5.2.14 (build 1243766; Android 9; arm64-v8a)
  874.    Content-Length: 0
  875.  
  876.    ------------------------------------------------------------------------
  877. tport.c:3027 tport_deliver() tport_deliver(0x7fce6007ac40): msg 0x7fce60036740 (607 bytes) from tls/185.39.248.196:2658/sips next=(nil)
  878. nta.c:3299 agent_recv_response() nta: received 180 Ringing for INVITE (5318806)
  879. nta.c:3366 agent_recv_response() nta: 180 Ringing is going to a transaction
  880. tport.c:4226 tport_release() tport_release(0x7fce6007ac40): 0x7fce6008f8c0 by 0x7fce600336a0 with 0x7fce60036740 (preliminary)
  881. nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event r_invite 180 Ringing
  882. nua_session.c:4139 signal_call_state_change() nua(0x7fce6c02f9a0): call state changed: calling -> proceeding
  883. nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event i_state 180 Ringing
  884. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
  885. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  886. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  887. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  888. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  889. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  890. 2019-06-05 15:33:16.809164 [DEBUG] sofia.c:7291 Channel sofia/internal/7667398@185.39.248.196:2658 entering state [proceeding][180]
  891. 2019-06-05 15:33:16.809164 [NOTICE] sofia.c:7401 Ring-Ready sofia/internal/7667398@185.39.248.196:2658!
  892. 2019-06-05 15:33:16.809164 [DEBUG] switch_channel.c:3354 (sofia/internal/7667398@185.39.248.196:2658) Callstate Change DOWN -> RINGING
  893. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  894. 2019-06-05 15:33:16.829170 [INFO] switch_ivr_originate.c:1246 Sending early media
  895. 2019-06-05 15:33:16.829170 [DEBUG] switch_core_media.c:8511 AUDIO RTP [sofia/external-lan/7398@10.55.4.5] 10.55.4.7 port 26324 -> 10.55.102.51 port 16670 codec: 9 ms: 20
  896. 2019-06-05 15:33:16.829170 [DEBUG] switch_rtp.c:4300 Starting timer [soft] 160 bytes per 20ms
  897. 2019-06-05 15:33:16.829170 [DEBUG] switch_core_media.c:8815 sofia/external-lan/7398@10.55.4.5 Set 2833 dtmf send payload to 101
  898. 2019-06-05 15:33:16.829170 [DEBUG] switch_core_media.c:8822 sofia/external-lan/7398@10.55.4.5 Set 2833 dtmf receive payload to 101
  899. 2019-06-05 15:33:16.829170 [DEBUG] switch_core_media.c:8845 sofia/external-lan/7398@10.55.4.5 Set rtp dtmf delay to 40
  900. 2019-06-05 15:33:16.829170 [DEBUG] mod_sofia.c:2505 Ring SDP:
  901. v=0
  902. o=FreeSWITCH 1559718872 1559718873 IN IP4 10.55.4.7
  903. s=FreeSWITCH
  904. c=IN IP4 10.55.4.7
  905. t=0 0
  906. m=audio 26324 RTP/AVP 9
  907. a=rtpmap:9 G722/8000
  908. a=ptime:20
  909. a=sendrecv
  910.  
  911. 2019-06-05 15:33:16.829170 [NOTICE] mod_sofia.c:2508 Pre-Answer sofia/external-lan/7398@10.55.4.5!
  912. 2019-06-05 15:33:16.829170 [DEBUG] switch_channel.c:3482 (sofia/external-lan/7398@10.55.4.5) Callstate Change RINGING -> EARLY
  913. nua.c:879 nua_respond() nua: nua_respond: entering
  914. nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond
  915. nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 183 Session Progress
  916. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  917. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called
  918. soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fce74014690, (nil), 0x7fce70015cfd, -1) called
  919. 2019-06-05 15:33:16.829170 [DEBUG] switch_ivr_originate.c:1304 Raw Codec Activation Success L16@16000hz 1 channel 20ms
  920. 2019-06-05 15:33:16.829170 [DEBUG] switch_core_codec.c:223 sofia/external-lan/7398@10.55.4.5 Push codec L16:100
  921. soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7fce74014690, (nil), 0x7fce70015cfd, -1) called
  922. nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
  923. soa.c:1515 soa_generate_answer() soa_generate_answer(static::0x7fce74014690) called
  924. soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fce74014690, soa_generate_answer): called
  925. soa_static.c:1189 offer_answer_step() soa_static(0x7fce74014690, soa_generate_answer): generating local description
  926. soa_static.c:1230 offer_answer_step() soa_static(0x7fce74014690, soa_generate_answer): upgrade with remote description
  927. soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fce6b5e8ab0, 0x7fce74015680, ""): called
  928. soa_static.c:1446 offer_answer_step() soa_static(0x7fce74014690, soa_generate_answer): storing local description
  929. 2019-06-05 15:33:16.829170 [DEBUG] switch_ivr_originate.c:1373 Play Ringback Tone [%(2000,4000,440,480)]
  930. soa.c:1730 soa_activate() soa_activate(static::0x7fce74014690, (nil)) called
  931. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce74014690, [(nil)], [0x7fce6b5eac38], [0x7fce6b5eac34]) called
  932. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
  933. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 889 bytes of 889 to tcp/10.55.4.5:55848
  934. tport.c:3496 tport_send_msg() tport_vsend returned 889
  935. send 889 bytes to tcp/[10.55.4.5]:55848 at 15:33:16.682014:
  936.    ------------------------------------------------------------------------
  937.    SIP/2.0 183 Session Progress
  938.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60c3af46a1f;rport=55848
  939.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  940.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
  941.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  942.    CSeq: 101 INVITE
  943.    Contact: <sip:7667398@10.55.4.7:5080;transport=tcp>
  944.    User-Agent: FreeSWITCH
  945.    Accept: application/sdp
  946.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
  947.    Supported: timer, path, replaces
  948.    Allow-Events: talk, hold, conference, refer
  949.    Content-Type: application/sdp
  950.    Content-Disposition: session
  951.    Content-Length: 158
  952.    P-Asserted-Identity: "7667398" <sip:7667398@10.55.4.7>
  953.  
  954.    v=0
  955.    o=FreeSWITCH 1559718872 1559718873 IN IP4 10.55.4.7
  956.    s=FreeSWITCH
  957.    c=IN IP4 10.55.4.7
  958.    t=0 0
  959.    m=audio 26324 RTP/AVP 9
  960.    a=rtpmap:9 G722/8000
  961.    a=ptime:20
  962.    ------------------------------------------------------------------------
  963. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  964. nta.c:6797 incoming_reply() nta: sent 183 Session Progress for INVITE (101)
  965. nua_session.c:4139 signal_call_state_change() nua(0x7fce74002fd0): call state changed: received -> early, sent answer
  966. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce74014690, [0x7fce6b5eace8], [0x7fce6b5eacf0], [(nil)]) called
  967. soa.c:616 soa_get_params() soa_get_params(static::0x7fce74014690, ...) called
  968. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 183 Session Progress
  969. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  970. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  971. 2019-06-05 15:33:16.849171 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [early][183]
  972. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  973. 2019-06-05 15:33:16.949164 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed.
  974. nta.c:1296 agent_timer() nta: timer set next to 58323 ms
  975. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce6007ac40): events IN
  976. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce6007ac40)
  977. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce6007ac40): tls_read() returned 1017
  978. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce6007ac40) msg 0x7fce60078270 from (tls/185.39.248.196:2658) has 1017 bytes, veclen = 1
  979. recv 1017 bytes from tls/[185.39.248.196]:2658 at 15:33:21.582934:
  980.    ------------------------------------------------------------------------
  981.    SIP/2.0 200 OK
  982.    Via: SIP/2.0/TLS 185.39.250.165:5061;rport=5061;branch=z9hG4bKaFrX8FtHvD96Q;received=185.39.250.165
  983.    Contact: <sip:7667398@185.39.248.196:2658;transport=tls>
  984.    From: "Stephen Barry" <sip:7398@voip.mydomain.com>;tag=pU8rDB8DUHjFe
  985.    Call-ID: b2998455-0241-1238-e9ba-005056860fd6
  986.    CSeq: 5318806 INVITE
  987.    To: <sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls>;tag=AFAB2EFC86E53DF36B3DE9E22393BB2C
  988.   Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
  989.    Supported: replaces, path
  990.    Content-Type: application/sdp
  991.    User-Agent: Groundwire/5.2.14 (build 1243766; Android 9; arm64-v8a)
  992.    Content-Length: 382
  993.  
  994.    v=0
  995.    o=- 2214276607 13634 IN IP4 172.26.170.170
  996.    s=qdusifw
  997.    c=IN IP4 10.71.172.74
  998.    t=0 0
  999.    m=audio 23288 RTP/SAVP 102 101
  1000.    a=rtpmap:101 telephone-event/8000
  1001.    a=rtpmap:102 opus/48000/2
  1002.    a=fmtp:101 0-15
  1003.    a=fmtp:102 maxplaybackrate=16000;maxaveragebitrate=30000;useinbandfec=1
  1004.    a=crypto:5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D
  1005.    a=ptime:20
  1006.    a=sendrecv
  1007.    ------------------------------------------------------------------------
  1008. tport.c:3027 tport_deliver() tport_deliver(0x7fce6007ac40): msg 0x7fce60078270 (1017 bytes) from tls/185.39.248.196:2658/sips next=(nil)
  1009. nta.c:3299 agent_recv_response() nta: received 200 OK for INVITE (5318806)
  1010. nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
  1011. tport.c:4226 tport_release() tport_release(0x7fce6007ac40): 0x7fce6008f8c0 by 0x7fce600336a0 with 0x7fce60078270
  1012. soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7fce600921a0, (nil), 0x7fce60060d2b, 382) called
  1013. soa.c:1595 soa_process_answer() soa_process_answer(static::0x7fce600921a0) called
  1014. soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fce600921a0, soa_process_answer): called
  1015. soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fce6005fff0, 0x7fce6007cb80, ""): called
  1016. soa_static.c:1304 offer_answer_step() soa_static(0x7fce600921a0, soa_process_answer): upgrade codecs with remote description
  1017. soa_static.c:1446 offer_answer_step() soa_static(0x7fce600921a0, soa_process_answer): storing local description
  1018. soa.c:1730 soa_activate() soa_activate(static::0x7fce600921a0, (nil)) called
  1019. nua_session.c:988 nua_session_client_response() nua(0x7fce6c02f9a0): INVITE: processed SDP answer in 200 OK
  1020. nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event r_invite 200 OK
  1021. nua_session.c:4139 signal_call_state_change() nua(0x7fce6c02f9a0): call state changed: proceeding -> completing, received answer
  1022. soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7fce600921a0, [0x7fce6b73e5e8], [0x7fce6b73e5f0], [(nil)]) called
  1023. soa.c:616 soa_get_params() soa_get_params(static::0x7fce600921a0, ...) called
  1024. nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event i_state 200 OK
  1025. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1026. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
  1027. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1028. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1029. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1030. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1031. 2019-06-05 15:33:21.729164 [DEBUG] sofia.c:7291 Channel sofia/internal/7667398@185.39.248.196:2658 entering state [completing][200]
  1032. 2019-06-05 15:33:21.729164 [DEBUG] sofia.c:7301 Remote SDP:
  1033. v=0
  1034. o=- 2214276607 13634 IN IP4 172.26.170.170
  1035. s=qdusifw
  1036. c=IN IP4 10.71.172.74
  1037. t=0 0
  1038. m=audio 23288 RTP/SAVP 102 101
  1039. a=rtpmap:102 opus/48000/2
  1040. a=fmtp:102 maxplaybackrate=16000;maxaveragebitrate=30000;useinbandfec=1
  1041. a=rtpmap:101 telephone-event/8000
  1042. a=fmtp:101 0-15
  1043. a=crypto:5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D
  1044. a=ptime:20
  1045.  
  1046. 2019-06-05 15:33:21.729164 [NOTICE] sofia.c:7304 Pre-Answer sofia/internal/7667398@185.39.248.196:2658!
  1047. 2019-06-05 15:33:21.729164 [DEBUG] switch_channel.c:3482 (sofia/internal/7667398@185.39.248.196:2658) Callstate Change RINGING -> EARLY
  1048. nua.c:639 nua_ack() nua: nua_ack: entering
  1049. nua_stack.c:569 nua_stack_signal() nua(0x7fce6c02f9a0): recv signal r_ack
  1050. nua_stack.c:529 nua_signal() nua(0x7fce6c02f9a0): sent signal r_ack
  1051. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  1052. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1053. soa.c:403 soa_set_params() soa_set_params(static::0x7fce600921a0, ...) called
  1054. soa.c:1730 soa_activate() soa_activate(static::0x7fce600921a0, (nil)) called
  1055. nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
  1056. tport.c:4592 tport_by_name() tport(0x7fce600466b0): found 0x7fce6007ac40 by name tls/185.39.248.196:2658
  1057. tport.c:3261 tport_tsend() tport_tsend(0x7fce6007ac40) tpn = tls/185.39.248.196:2658
  1058. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce6007ba80 0x7fce60052100 474 (474)
  1059. tport.c:3598 tport_vsend() tport_vsend(0x7fce6007ac40): 474 bytes of 474 to tls/185.39.248.196:2658
  1060. tport.c:3496 tport_send_msg() tport_vsend returned 474
  1061. send 474 bytes to tls/[185.39.248.196]:2658 at 15:33:21.584434:
  1062.    ------------------------------------------------------------------------
  1063.    ACK sip:7667398@185.39.248.196:2658;transport=tls SIP/2.0
  1064.    Via: SIP/2.0/TLS 185.39.250.165:5061;rport;branch=z9hG4bKBrHpaBBNSpZSK
  1065.    Max-Forwards: 70
  1066.    From: "Stephen Barry" <sip:7398@voip.mydomain.com>;tag=pU8rDB8DUHjFe
  1067.    To: <sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls>;tag=AFAB2EFC86E53DF36B3DE9E22393BB2C
  1068.    Call-ID: b2998455-0241-1238-e9ba-005056860fd6
  1069.    CSeq: 5318806 ACK
  1070.    Contact: <sip:mod_sofia@185.39.250.165:5061;transport=tls>
  1071.    Content-Length: 0
  1072.  
  1073.    ------------------------------------------------------------------------
  1074. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
  1075. nta.c:8310 outgoing_send() nta: sent ACK (5318806) to tls/185.39.248.196:2658
  1076. nua_session.c:4139 signal_call_state_change() nua(0x7fce6c02f9a0): call state changed: completing -> ready
  1077. nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event i_state 200 ACK sent
  1078. nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event i_active 200 Call active
  1079. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1080. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1081. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1082. 2019-06-05 15:33:21.729164 [DEBUG] sofia.c:7291 Channel sofia/internal/7667398@185.39.248.196:2658 entering state [ready][200]
  1083. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AEAD_AES_256_GCM_8]alias=[] in [5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D]
  1084. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AEAD_AES_128_GCM_8]alias=[] in [5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D]
  1085. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AES_256_CM_HMAC_SHA1_80]alias=[AES_CM_256_HMAC_SHA1_80] in [5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D]
  1086. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AES_192_CM_HMAC_SHA1_80]alias=[AES_CM_192_HMAC_SHA1_80] in [5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D]
  1087. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AES_CM_128_HMAC_SHA1_80]alias=[] in [5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D]
  1088. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1813 Found suite AES_CM_128_HMAC_SHA1_80
  1089. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1883 Set Remote Key [5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D]
  1090. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:102:48000:20:0:1]/[G722:9:8000:20:64000:1]
  1091. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:1]
  1092. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
  1093. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:1]
  1094. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
  1095. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:1]
  1096. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
  1097. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:102:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
  1098. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:102:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
  1099. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000
  1100. 2019-06-05 15:33:21.729164 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [32000bps]
  1101. 2019-06-05 15:33:21.729164 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [32000bps]
  1102. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:3781 Set Codec sofia/internal/7667398@185.39.248.196:2658 opus/8000 20 ms 960 samples 0 bits 1 channels
  1103. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_codec.c:111 sofia/internal/7667398@185.39.248.196:2658 Original read codec set to opus:116
  1104. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5795 sofia/internal/7667398@185.39.248.196:2658 Set 2833 dtmf send payload to 101 recv payload to 101
  1105. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:8511 AUDIO RTP [sofia/internal/7667398@185.39.248.196:2658] 10.66.4.7 port 16948 -> 10.71.172.74 port 23288 codec: 102 ms: 20
  1106. 2019-06-05 15:33:21.729164 [DEBUG] switch_rtp.c:4300 Starting timer [soft] 960 bytes per 20ms
  1107. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:8815 sofia/internal/7667398@185.39.248.196:2658 Set 2833 dtmf send payload to 101
  1108. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:8822 sofia/internal/7667398@185.39.248.196:2658 Set 2833 dtmf receive payload to 101
  1109. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:8845 sofia/internal/7667398@185.39.248.196:2658 Set rtp dtmf delay to 40
  1110. 2019-06-05 15:33:21.729164 [INFO] switch_rtp.c:4104 Activating audio Secure RTP SEND
  1111. 2019-06-05 15:33:21.729164 [INFO] switch_rtp.c:4082 Activating audio Secure RTP RECV
  1112. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_sqldb.c:2617 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
  1113. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_sqldb.c:2617 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
  1114. 2019-06-05 15:33:21.729164 [NOTICE] sofia.c:8429 Channel [sofia/internal/7667398@185.39.248.196:2658] has been answered
  1115. 2019-06-05 15:33:21.729164 [DEBUG] switch_channel.c:3781 (sofia/internal/7667398@185.39.248.196:2658) Callstate Change EARLY -> ACTIVE
  1116. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1117. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1118. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1119. 2019-06-05 15:33:21.749169 [DEBUG] switch_core_codec.c:248 sofia/external-lan/7398@10.55.4.5 Restore previous codec G722:9.
  1120. 2019-06-05 15:33:21.749169 [DEBUG] switch_core_media.c:8494 Audio params are unchanged for sofia/external-lan/7398@10.55.4.5.
  1121. 2019-06-05 15:33:21.749169 [DEBUG] mod_sofia.c:882 Local SDP sofia/external-lan/7398@10.55.4.5:
  1122. v=0
  1123. o=FreeSWITCH 1559718872 1559718874 IN IP4 10.55.4.7
  1124. s=FreeSWITCH
  1125. c=IN IP4 10.55.4.7
  1126. t=0 0
  1127. m=audio 26324 RTP/AVP 9
  1128. a=rtpmap:9 G722/8000
  1129. a=ptime:20
  1130. a=sendrecv
  1131.  
  1132. nua.c:879 nua_respond() nua: nua_respond: entering
  1133. nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 200 OK
  1134. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  1135. nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond
  1136. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called
  1137. soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fce74014690, (nil), 0x7fce700443d3, -1) called
  1138. nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
  1139. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce74014690, [(nil)], [0x7fce6b5eac38], [0x7fce6b5eac34]) called
  1140. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
  1141. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 903 bytes of 903 to tcp/10.55.4.5:55848
  1142. tport.c:3496 tport_send_msg() tport_vsend returned 903
  1143. send 903 bytes to tcp/[10.55.4.5]:55848 at 15:33:21.600438:
  1144.    ------------------------------------------------------------------------
  1145.    SIP/2.0 200 OK
  1146.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60c3af46a1f;rport=55848
  1147.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  1148.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
  1149.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  1150.    CSeq: 101 INVITE
  1151.    Contact: <sip:7667398@10.55.4.7:5080;transport=tcp>
  1152.    User-Agent: FreeSWITCH
  1153.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
  1154.    Require: timer
  1155.    Supported: timer, path, replaces
  1156.    Allow-Events: talk, hold, conference, refer
  1157.    Session-Expires: 1800;refresher=uac
  1158.    Content-Type: application/sdp
  1159.    Content-Disposition: session
  1160.    Content-Length: 158
  1161.    P-Asserted-Identity: "7667398" <sip:7667398@10.55.4.7>
  1162.  
  1163.    v=0
  1164.    o=FreeSWITCH 1559718872 1559718873 IN IP4 10.55.4.7
  1165.    s=FreeSWITCH
  1166.    c=IN IP4 10.55.4.7
  1167.    t=0 0
  1168.    m=audio 26324 RTP/AVP 9
  1169.    a=rtpmap:9 G722/8000
  1170.    a=ptime:20
  1171.    ------------------------------------------------------------------------
  1172. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  1173. nta.c:6797 incoming_reply() nta: sent 200 OK for INVITE (101)
  1174. nta.c:1348 set_timeout() nta: timer shortened to 500 ms
  1175. 2019-06-05 15:33:21.749169 [NOTICE] switch_ivr_originate.c:3740 Channel [sofia/external-lan/7398@10.55.4.5] has been answered
  1176. nua_session.c:4139 signal_call_state_change() nua(0x7fce74002fd0): call state changed: early -> completed, sent answer
  1177. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce74014690, [0x7fce6b5eace8], [0x7fce6b5eacf0], [(nil)]) called
  1178. soa.c:616 soa_get_params() soa_get_params(static::0x7fce74014690, ...) called
  1179. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 200 OK
  1180. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1181. 2019-06-05 15:33:21.749169 [DEBUG] switch_channel.c:3781 (sofia/external-lan/7398@10.55.4.5) Callstate Change EARLY -> ACTIVE
  1182. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1183. 2019-06-05 15:33:21.749169 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [completed][200]
  1184. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1185. 2019-06-05 15:33:21.749169 [DEBUG] switch_ivr_originate.c:3798 Originate Resulted in Success: [sofia/internal/7667398@185.39.248.196:2658]
  1186. 2019-06-05 15:33:21.749169 [DEBUG] switch_ivr_originate.c:3798 Originate Resulted in Success: [sofia/internal/7667398@185.39.248.196:2658]
  1187. 2019-06-05 15:33:21.749169 [DEBUG] switch_ivr_bridge.c:1782 (sofia/internal/7667398@185.39.248.196:2658) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
  1188. 2019-06-05 15:33:21.749169 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 314)
  1189. 2019-06-05 15:33:21.749169 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/7667398@185.39.248.196:2658) State EXCHANGE_MEDIA
  1190. 2019-06-05 15:33:21.749169 [DEBUG] mod_sofia.c:646 SOFIA EXCHANGE_MEDIA
  1191. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN
  1192. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0)
  1193. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74013db0 from (tcp/10.55.4.5:55848) has 463 bytes, veclen = 1
  1194. recv 463 bytes from tcp/[10.55.4.5]:55848 at 15:33:21.602290:
  1195.    ------------------------------------------------------------------------
  1196.    ACK sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0
  1197.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60d6ac3319b
  1198.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  1199.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
  1200.    Date: Wed, 05 Jun 2019 14:33:16 GMT
  1201.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  1202.    User-Agent: Cisco-CUCM10.5
  1203.    Max-Forwards: 70
  1204.    CSeq: 101 ACK
  1205.    Allow-Events: presence, kpml
  1206.    Content-Length: 0
  1207.  
  1208.    ------------------------------------------------------------------------
  1209. tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74013db0 (463 bytes) from tcp/10.55.4.5:55848/sip next=(nil)
  1210. nta.c:2880 agent_recv_request() nta: received ACK sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 (CSeq 101)
  1211. nta.c:3019 agent_recv_request() nta: ACK (101) is going to INVITE (101)
  1212. nua_session.c:2569 process_ack_or_cancel() nua: process_ack_or_cancel: entering
  1213. soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7fce74014690) called
  1214. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_ack 200 OK
  1215. nua_session.c:4139 signal_call_state_change() nua(0x7fce74002fd0): call state changed: completed -> ready
  1216. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 200 OK
  1217. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_active 200 Call active
  1218. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1219. nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh session after 1768 seconds (in [1768..1768])
  1220. nta.c:5744 incoming_free() nta: incoming_free(0x7fce74003c30)
  1221. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1222. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1223. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  1224. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  1225. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1226. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1227. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1228. 2019-06-05 15:33:21.749169 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [ready][200]
  1229. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1230. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1231. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1232. 2019-06-05 15:33:21.789165 [NOTICE] switch_core_media.c:15578 Activating write resampler
  1233. 2019-06-05 15:33:21.809171 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed.
  1234. 2019-06-05 15:33:21.809171 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
  1235. 2019-06-05 15:33:21.809171 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
  1236. 2019-06-05 15:33:21.809171 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [32000bps]
  1237. 2019-06-05 15:33:21.809171 [NOTICE] switch_core_media.c:15578 Activating write resampler
  1238. 2019-06-05 15:33:21.809171 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[1] PLC[0] FEC[0]
  1239. 2019-06-05 15:33:21.809171 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
  1240. 2019-06-05 15:33:21.809171 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [32000bps]
  1241. 2019-06-05 15:33:22.009176 [INFO] switch_rtp.c:7510 Auto Changing audio port from 10.71.172.74:23288 to 185.39.248.196:23288
  1242. nta.c:1289 agent_timer() nta: timer not set
  1243. freeswitch@fpbx01>
  1244. freeswitch@fpbx01>
  1245. freeswitch@fpbx01>
  1246. freeswitch@fpbx01>
  1247. freeswitch@fpbx01>
  1248. freeswitch@fpbx01>
  1249. freeswitch@fpbx01>
  1250. freeswitch@fpbx01>
  1251. freeswitch@fpbx01>
  1252. freeswitch@fpbx01>
  1253. freeswitch@fpbx01>
  1254. freeswitch@fpbx01>
  1255. freeswitch@fpbx01>
  1256. tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fce600466b0): events IN
  1257. tport.c:862 tport_alloc_secondary() tport_alloc_secondary(0x7fce600466b0): new secondary tport 0x7fce60053a50
  1258. tport_type_tcp.c:203 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7fce60053a50): Setting TCP_KEEPIDLE to 30
  1259. tport_type_tcp.c:209 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7fce60053a50): Setting TCP_KEEPINTVL to 30
  1260. tport_type_tls.c:610 tport_tls_accept() tport_tls_accept(0x7fce60053a50): new connection from tls/162.243.35.55:64178/sips
  1261. tport_tls.c:960 tls_connect() tls_connect(0x7fce60053a50): events NEGOTIATING
  1262. freeswitch@fpbx01>
  1263. tport_tls.c:960 tls_connect() tls_connect(0x7fce60053a50): events NEGOTIATING
  1264. tport_tls.c:960 tls_connect() tls_connect(0x7fce60053a50): events NEGOTIATING
  1265. tport_tls.c:603 tls_post_connection_check() tls_post_connection_check(0x7fce60053a50): TLS cipher chosen (name): ECDHE-RSA-AES256-SHA
  1266. tport_tls.c:605 tls_post_connection_check() tls_post_connection_check(0x7fce60053a50): TLS cipher chosen (version): TLSv1/SSLv3
  1267. tport_tls.c:608 tls_post_connection_check() tls_post_connection_check(0x7fce60053a50): TLS cipher chosen (bits/alg_bits): 256/256
  1268. tport_tls.c:611 tls_post_connection_check() tls_post_connection_check(0x7fce60053a50): TLS cipher chosen (description): ECDHE-RSA-AES256-SHA    SSLv3 Kx=ECDH     Au=RSA  Enc=AES(256)  Mac=SHA1
  1269.  
  1270. tport_tls.c:616 tls_post_connection_check() tls_post_connection_check(0x7fce60053a50): Peer did not provide X.509 Certificate.
  1271. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer
  1272. freeswitch@fpbx01>
  1273. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce60053a50): events IN
  1274. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce60053a50)
  1275. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce60053a50): tls_read() returned 542
  1276. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce60053a50) msg 0x7fce600aefb0 from (tls/162.243.35.55:64178) has 542 bytes, veclen = 1
  1277. recv 542 bytes from tls/[162.243.35.55]:64178 at 15:33:27.091213:
  1278.    ------------------------------------------------------------------------
  1279.    REGISTER sip:voip.mydomain.com SIP/2.0
  1280.    Via: SIP/2.0/TLS 162.243.35.55:64178;branch=z9hG4bKDTnvBCgWYgCf4htH;rport
  1281.    Contact: <sip:766@162.243.35.55:64178;rinstance=FB4BBA12;transport=tls>;expires=600
  1282.    Max-Forwards: 70
  1283.    From: <sip:766@voip.mydomain.com>;tag=0379E1A1DB270E77E864F1CC563F5582
  1284.   Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
  1285.    Supported: replaces, path
  1286.    To: <sip:766@voip.mydomain.com>
  1287.    Expires: 600
  1288.    Call-ID: 2D3450B0F4D400EB567B897821A37D9F82A0EA3A
  1289.    CSeq: 3 REGISTER
  1290.    User-Agent: Acrobits SIPIS
  1291.    Content-Length: 0
  1292.  
  1293.    ------------------------------------------------------------------------
  1294. tport.c:3027 tport_deliver() tport_deliver(0x7fce60053a50): msg 0x7fce600aefb0 (542 bytes) from tls/162.243.35.55:64178/sips next=(nil)
  1295. nta.c:2880 agent_recv_request() nta: received REGISTER sip:voip.mydomain.com SIP/2.0 (CSeq 3)
  1296. nta.c:3085 agent_recv_request() nta: REGISTER (3) going to a default leg
  1297. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
  1298. nua_stack.c:899 nh_create() nua: nh_create: entering
  1299. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
  1300. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  1301. soa.c:280 soa_clone() soa_clone(static::0x7fce60096e10, 0x7fce6007dde0, 0x7fce600ae8c0) called
  1302. soa.c:403 soa_set_params() soa_set_params(static::0x7fce60083780, ...) called
  1303. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fce600ae8c0): adding registrar usage
  1304. tport.c:4164 tport_pend() tport_pend(0x7fce60053a50): pending (nil) for tls/162.243.35.55:64178 (already 0)
  1305. nua_stack.c:271 nua_stack_event() nua(0x7fce600ae8c0): event i_register 100 Trying
  1306. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer
  1307. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1308. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1309. nua.c:879 nua_respond() nua: nua_respond: entering
  1310. nua_stack.c:529 nua_signal() nua(0x7fce600ae8c0): sent signal r_respond
  1311. nua_stack.c:573 nua_stack_signal() nua(0x7fce600ae8c0): recv signal r_respond 401 Unauthorized
  1312. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  1313. 2019-06-05 15:33:27.249166 [WARNING] sofia_reg.c:1798 SIP auth challenge (REGISTER) on sofia profile 'internal' for [766@voip.mydomain.com] from ip 162.243.35.55
  1314. soa.c:403 soa_set_params() soa_set_params(static::0x7fce60083780, ...) called
  1315. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1316. nua_stack.c:529 nua_signal() nua(0x7fce600ae8c0): sent signal r_destroy
  1317. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1318. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1319. tport.c:3261 tport_tsend() tport_tsend(0x7fce60053a50) tpn = TLS/162.243.35.55:64178
  1320. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600b08b0 107 (107)
  1321. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600af679 71 (71)
  1322. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600b091b 50 (50)
  1323. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600af748 69 (69)
  1324. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600b094d 313 (313)
  1325. tport.c:3598 tport_vsend() tport_vsend(0x7fce60053a50): 610 bytes of 610 to tls/162.243.35.55:64178
  1326. tport.c:3496 tport_send_msg() tport_vsend returned 610
  1327. send 610 bytes to tls/[162.243.35.55]:64178 at 15:33:27.091551:
  1328.    ------------------------------------------------------------------------
  1329.    SIP/2.0 401 Unauthorized
  1330.    Via: SIP/2.0/TLS 162.243.35.55:64178;branch=z9hG4bKDTnvBCgWYgCf4htH;rport=64178
  1331.    From: <sip:766@voip.mydomain.com>;tag=0379E1A1DB270E77E864F1CC563F5582
  1332.    To: <sip:766@voip.mydomain.com>;tag=Q41HF6rHrt81S
  1333.    Call-ID: 2D3450B0F4D400EB567B897821A37D9F82A0EA3A
  1334.    CSeq: 3 REGISTER
  1335.    User-Agent: FreeSWITCH
  1336.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  1337.    Supported: timer, path, replaces
  1338.    WWW-Authenticate: Digest realm="voip.mydomain.com", nonce="33412b5e-8a70-4ccf-99e4-385b0439701d", algorithm=MD5, qop="auth"
  1339.    Content-Length: 0
  1340.  
  1341.    ------------------------------------------------------------------------
  1342. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer
  1343. nta.c:6797 incoming_reply() nta: sent 401 Unauthorized for REGISTER (3)
  1344. nta.c:5744 incoming_free() nta: incoming_free(0x7fce600af360)
  1345. nua_stack.c:569 nua_stack_signal() nua(0x7fce600ae8c0): recv signal r_destroy
  1346. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fce600ae8c0): removing registrar usage
  1347. tport.c:4226 tport_release() tport_release(0x7fce60053a50): (nil) by 0x7fce600ae8c0 with (nil)
  1348. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer
  1349. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
  1350. soa.c:356 soa_destroy() soa_destroy(static::0x7fce60083780) called
  1351. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce60053a50): events IN
  1352. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce60053a50)
  1353. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce60053a50): tls_read() returned 790
  1354. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce60053a50) msg 0x7fce600ae4a0 from (tls/162.243.35.55:64178) has 790 bytes, veclen = 1
  1355. recv 790 bytes from tls/[162.243.35.55]:64178 at 15:33:27.163818:
  1356.    ------------------------------------------------------------------------
  1357.    REGISTER sip:voip.mydomain.com SIP/2.0
  1358.    Via: SIP/2.0/TLS 162.243.35.55:64178;branch=z9hG4bK7VZrGlJs0ipKKRkF;rport
  1359.    Contact: <sip:766@162.243.35.55:64178;rinstance=FB4BBA12;transport=tls>;expires=600
  1360.    Max-Forwards: 70
  1361.    From: <sip:766@voip.mydomain.com>;tag=0379E1A1DB270E77E864F1CC563F5582
  1362.   Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
  1363.    Supported: replaces, path
  1364.    To: <sip:766@voip.mydomain.com>
  1365.    Expires: 600
  1366.    Call-ID: 2D3450B0F4D400EB567B897821A37D9F82A0EA3A
  1367.    CSeq: 4 REGISTER
  1368.    Authorization: Digest username="766",realm="voip.mydomain.com",algorithm=MD5,uri="sip:voip.mydomain.com",nonce="33412b5e-8a70-4ccf-99e4-385b0439701d",qop=auth,cnonce="XPfSt9oi6WwqwF0s3uKNQX1I",nc=00000001,response="17317ab4aecbbf1ebd439a089ca22355"
  1369.    User-Agent: Acrobits SIPIS
  1370.    Content-Length: 0
  1371.  
  1372.    ------------------------------------------------------------------------
  1373. tport.c:3027 tport_deliver() tport_deliver(0x7fce60053a50): msg 0x7fce600ae4a0 (790 bytes) from tls/162.243.35.55:64178/sips next=(nil)
  1374. nta.c:2880 agent_recv_request() nta: received REGISTER sip:voip.mydomain.com SIP/2.0 (CSeq 4)
  1375. nta.c:3085 agent_recv_request() nta: REGISTER (4) going to a default leg
  1376. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
  1377. nua_stack.c:899 nh_create() nua: nh_create: entering
  1378. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
  1379. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  1380. soa.c:280 soa_clone() soa_clone(static::0x7fce60096e10, 0x7fce6007dde0, 0x7fce600832c0) called
  1381. soa.c:403 soa_set_params() soa_set_params(static::0x7fce60083700, ...) called
  1382. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fce600832c0): adding registrar usage
  1383. tport.c:4164 tport_pend() tport_pend(0x7fce60053a50): pending (nil) for tls/162.243.35.55:64178 (already 0)
  1384. nua_stack.c:271 nua_stack_event() nua(0x7fce600832c0): event i_register 100 Trying
  1385. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer
  1386. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1387. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1388. 2019-06-05 15:33:27.309167 [WARNING] sofia_reg.c:2935 Can't find user [766@voip.mydomain.com] from 162.243.35.55
  1389. You must define a domain called 'voip.mydomain.com' in your directory and add a user with the id="766" attribute
  1390. and you must configure your device to use the proper domain in it's authentication credentials.
  1391. nua.c:879 nua_respond() nua: nua_respond: entering
  1392. nua_stack.c:573 nua_stack_signal() nua(0x7fce600832c0): recv signal r_respond 403 Forbidden
  1393. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  1394. soa.c:403 soa_set_params() soa_set_params(static::0x7fce60083700, ...) called
  1395. nua_stack.c:529 nua_signal() nua(0x7fce600832c0): sent signal r_respond
  1396. 2019-06-05 15:33:27.309167 [WARNING] sofia_reg.c:1743 SIP auth failure (REGISTER) on sofia profile 'internal' for [766@voip.mydomain.com] from ip 162.243.35.55
  1397. tport.c:3261 tport_tsend() tport_tsend(0x7fce60053a50) tpn = TLS/162.243.35.55:64178
  1398. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1399. nua_stack.c:529 nua_signal() nua(0x7fce600832c0): sent signal r_destroy
  1400. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1401. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1402. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600b0b20 104 (104)
  1403. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600ad929 71 (71)
  1404. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600b0b88 50 (50)
  1405. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600ad9f8 69 (69)
  1406. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600b0bba 189 (189)
  1407. tport.c:3598 tport_vsend() tport_vsend(0x7fce60053a50): 483 bytes of 483 to tls/162.243.35.55:64178
  1408. tport.c:3496 tport_send_msg() tport_vsend returned 483
  1409. send 483 bytes to tls/[162.243.35.55]:64178 at 15:33:27.167172:
  1410.    ------------------------------------------------------------------------
  1411.    SIP/2.0 403 Forbidden
  1412.    Via: SIP/2.0/TLS 162.243.35.55:64178;branch=z9hG4bK7VZrGlJs0ipKKRkF;rport=64178
  1413.    From: <sip:766@voip.mydomain.com>;tag=0379E1A1DB270E77E864F1CC563F5582
  1414.    To: <sip:766@voip.mydomain.com>;tag=rDUaH19mN3ymN
  1415.    Call-ID: 2D3450B0F4D400EB567B897821A37D9F82A0EA3A
  1416.    CSeq: 4 REGISTER
  1417.    User-Agent: FreeSWITCH
  1418.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  1419.    Supported: timer, path, replaces
  1420.    Content-Length: 0
  1421.  
  1422.    ------------------------------------------------------------------------
  1423. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer
  1424. nta.c:6797 incoming_reply() nta: sent 403 Forbidden for REGISTER (4)
  1425. nta.c:5744 incoming_free() nta: incoming_free(0x7fce600afd50)
  1426. nua_stack.c:569 nua_stack_signal() nua(0x7fce600832c0): recv signal r_destroy
  1427. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fce600832c0): removing registrar usage
  1428. tport.c:4226 tport_release() tport_release(0x7fce60053a50): (nil) by 0x7fce600832c0 with (nil)
  1429. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer
  1430. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
  1431. soa.c:356 soa_destroy() soa_destroy(static::0x7fce60083700) called
  1432. freeswitch@fpbx01>
  1433. freeswitch@fpbx01>
  1434. freeswitch@fpbx01>
  1435. freeswitch@fpbx01>
  1436. freeswitch@fpbx01>
  1437. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN
  1438. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0)
  1439. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74008dc0 from (tcp/10.55.4.5:55848) has 1413 bytes, veclen = 1
  1440. recv 1413 bytes from tcp/[10.55.4.5]:55848 at 15:33:30.019210:
  1441.    ------------------------------------------------------------------------
  1442.    INVITE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0
  1443.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60e747a318f
  1444.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  1445.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
  1446.    Date: Wed, 05 Jun 2019 14:33:30 GMT
  1447.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  1448.    Supported: timer,resource-priority,replaces
  1449.    User-Agent: Cisco-CUCM10.5
  1450.   Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
  1451.    CSeq: 102 INVITE
  1452.    Max-Forwards: 70
  1453.    Expires: 180
  1454.    Allow-Events: presence
  1455.    Call-Info: <urn:x-cisco-remotecc:callinfo>;x-cisco-video-traffic-class=VIDEO_UNSPECIFIED
  1456.    Supported: X-cisco-srtp-fallback
  1457.    Supported: Geolocation
  1458.    Session-Expires:  1800;refresher=uac
  1459.    Min-SE:  1800
  1460.    P-Asserted-Identity: "Stephen Barry" <sip:7398@10.55.4.5>
  1461.    Remote-Party-ID: "Stephen Barry" <sip:7398@10.55.4.5>;party=calling;screen=yes;privacy=off
  1462.    Contact: <sip:7398@10.55.4.5:5060;transport=tcp>
  1463.    Content-Type: application/sdp
  1464.    Content-Length: 367
  1465.  
  1466.    v=0
  1467.    o=CiscoSystemsCCM-SIP 3080835 2 IN IP4 10.55.4.5
  1468.    s=SIP Call
  1469.    c=IN IP4 0.0.0.0
  1470.    b=TIAS:64000
  1471.    b=AS:64
  1472.    t=0 0
  1473.    m=audio 16670 RTP/AVP 9 8 0 116 18 101
  1474.    a=rtpmap:9 G722/8000
  1475.    a=rtpmap:8 PCMA/8000
  1476.    a=rtpmap:0 PCMU/8000
  1477.    a=rtpmap:116 iLBC/8000
  1478.    a=maxptime:60
  1479.    a=fmtp:116 mode=20
  1480.    a=rtpmap:18 G729/8000
  1481.    a=inactive
  1482.    a=rtpmap:101 telephone-event/8000
  1483.    a=fmtp:101 0-15
  1484.    ------------------------------------------------------------------------
  1485. tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74008dc0 (1413 bytes) from tcp/10.55.4.5:55848/sip next=(nil)
  1486. nta.c:2880 agent_recv_request() nta: received INVITE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 (CSeq 102)
  1487. nta.c:3248 agent_aliases() nta: canonizing sip:7667398@10.55.4.7:5080 with contact
  1488. nta.c:3060 agent_recv_request() nta: INVITE (102) going to existing leg
  1489. nta.c:1350 set_timeout() nta: timer set to 2000 ms
  1490. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
  1491. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fce74014690) called
  1492. soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7fce74014690, (nil), 0x7fce74003a36, 367) called
  1493. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_invite 100 Trying
  1494. nua_session.c:4145 signal_call_state_change() nua(0x7fce74002fd0): ready call updated: received received offer
  1495. soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7fce74014690, [0x7fce6b5ea8d8], [0x7fce6b5ea8e0], [(nil)]) called
  1496. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 100 Trying
  1497. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1498. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  1499. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1500. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1501. nua.c:879 nua_respond() nua: nua_respond: entering
  1502. nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond
  1503. nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 100 Trying
  1504. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  1505. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called
  1506. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
  1507. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 355 bytes of 355 to tcp/10.55.4.5:55848
  1508. tport.c:3496 tport_send_msg() tport_vsend returned 355
  1509. send 355 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.020262:
  1510.    ------------------------------------------------------------------------
  1511.    SIP/2.0 100 Trying
  1512.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60e747a318f;rport=55848
  1513.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  1514.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
  1515.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  1516.    CSeq: 102 INVITE
  1517.    User-Agent: FreeSWITCH
  1518.    Content-Length: 0
  1519.  
  1520.    ------------------------------------------------------------------------
  1521. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  1522. nta.c:6797 incoming_reply() nta: sent 100 Trying for INVITE (102)
  1523. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1524. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1525. 2019-06-05 15:33:30.169172 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [received][100]
  1526. 2019-06-05 15:33:30.169172 [DEBUG] sofia.c:7301 Remote SDP:
  1527. v=0
  1528. o=CiscoSystemsCCM-SIP 3080835 2 IN IP4 10.55.4.5
  1529. s=SIP Call
  1530. c=IN IP4 0.0.0.0
  1531. b=TIAS:64000
  1532. b=AS:64
  1533. t=0 0
  1534. m=audio 16670 RTP/AVP 9 8 0 116 18 101
  1535. a=rtpmap:9 G722/8000
  1536. a=rtpmap:8 PCMA/8000
  1537. a=rtpmap:0 PCMU/8000
  1538. a=rtpmap:116 iLBC/8000
  1539. a=fmtp:116 mode=20
  1540. a=rtpmap:18 G729/8000
  1541. a=rtpmap:101 telephone-event/8000
  1542. a=fmtp:101 0-15
  1543. a=inactive
  1544. a=maxptime:60
  1545.  
  1546. 2019-06-05 15:33:30.169172 [WARNING] switch_core_media.c:4877 RFC2543 from March 1999 called; They want their 0.0.0.0 hold method back.....
  1547. 2019-06-05 15:33:30.169172 [DEBUG] switch_channel.c:1844 (sofia/external-lan/7398@10.55.4.5) Callstate Change ACTIVE -> HELD
  1548. 2019-06-05 15:33:30.309180 [DEBUG] switch_ivr.c:625 sofia/internal/7667398@185.39.248.196:2658 Command Execute playback(local_stream://default)
  1549. EXECUTE sofia/internal/7667398@185.39.248.196:2658 playback(local_stream://default)
  1550. 2019-06-05 15:33:30.309180 [DEBUG] mod_local_stream.c:907 Opening Stream [default/8000] 8000hz
  1551. 2019-06-05 15:33:30.309180 [DEBUG] switch_ivr_play_say.c:1497 Codec Activated L16@8000hz 1 channels 20ms
  1552. 2019-06-05 15:33:30.329170 [NOTICE] switch_core_media.c:15605 Deactivating write resampler
  1553. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1]
  1554. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1]
  1555. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1]
  1556. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[G722:9:8000:20:64000:1]
  1557. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
  1558. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[PCMA:8:8000:20:64000:1]
  1559. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[PCMU:0:8000:20:64000:1]
  1560. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1]
  1561. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1]
  1562. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1]
  1563. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[G722:9:8000:20:64000:1]
  1564. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[PCMA:8:8000:20:64000:1]
  1565. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
  1566. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[PCMU:0:8000:20:64000:1]
  1567. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1]
  1568. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1]
  1569. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1]
  1570. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[G722:9:8000:20:64000:1]
  1571. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[PCMA:8:8000:20:64000:1]
  1572. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[PCMU:0:8000:20:64000:1]
  1573. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
  1574. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[opus:116:48000:20:0:1]
  1575. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[opus:116:48000:20:0:1]
  1576. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[opus:116:48000:20:0:1]
  1577. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[G722:9:8000:20:64000:1]
  1578. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[PCMA:8:8000:20:64000:1]
  1579. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[PCMU:0:8000:20:64000:1]
  1580. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[opus:116:48000:20:0:1]
  1581. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[opus:116:48000:20:0:1]
  1582. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[opus:116:48000:20:0:1]
  1583. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[G722:9:8000:20:64000:1]
  1584. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[PCMA:8:8000:20:64000:1]
  1585. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[PCMU:0:8000:20:64000:1]
  1586. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000
  1587. 2019-06-05 15:33:30.429173 [WARNING] switch_core_media.c:5551 Crypto not negotiated but required.
  1588. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5737 Set telephone-event payload to 101@8000
  1589. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5795 sofia/external-lan/7398@10.55.4.5 Set 2833 dtmf send payload to 101 recv payload to 101
  1590. 2019-06-05 15:33:30.429173 [DEBUG] sofia.c:8216 Reinvite resulted in codec negotiation failure.
  1591. nua.c:879 nua_respond() nua: nua_respond: entering
  1592. nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 488 Not Acceptable Here
  1593. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  1594. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called
  1595. nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
  1596. soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7fce74014690) called
  1597. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
  1598. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 517 bytes of 517 to tcp/10.55.4.5:55848
  1599. tport.c:3496 tport_send_msg() tport_vsend returned 517
  1600. send 517 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.270906:
  1601.    ------------------------------------------------------------------------
  1602.    SIP/2.0 488 Not Acceptable Here
  1603.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60e747a318f;rport=55848
  1604.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  1605.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
  1606.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  1607.    CSeq: 102 INVITE
  1608.    User-Agent: FreeSWITCH
  1609.    Accept: application/sdp
  1610.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
  1611.    Supported: timer, path, replaces
  1612.    Content-Length: 0
  1613.  
  1614.    ------------------------------------------------------------------------
  1615. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  1616. nta.c:6797 incoming_reply() nta: sent 488 Not Acceptable Here for INVITE (102)
  1617. nua_session.c:4145 signal_call_state_change() nua(0x7fce74002fd0): ready call updated: init
  1618. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 488 Not Acceptable Here
  1619. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_active 488 Call active
  1620. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fce74014690) called
  1621. nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond
  1622. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1623. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1624. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1625. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN
  1626. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0)
  1627. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74085a80 from (tcp/10.55.4.5:55848) has 457 bytes, veclen = 1
  1628. recv 457 bytes from tcp/[10.55.4.5]:55848 at 15:33:30.271982:
  1629.    ------------------------------------------------------------------------
  1630.    ACK sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0
  1631.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60e747a318f
  1632.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  1633.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
  1634.    Date: Wed, 05 Jun 2019 14:33:30 GMT
  1635.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  1636.    User-Agent: Cisco-CUCM10.5
  1637.    Max-Forwards: 70
  1638.    CSeq: 102 ACK
  1639.    Allow-Events: presence
  1640.    Content-Length: 0
  1641.  
  1642.    ------------------------------------------------------------------------
  1643. tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74085a80 (457 bytes) from tcp/10.55.4.5:55848/sip next=(nil)
  1644. nta.c:2880 agent_recv_request() nta: received ACK sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 (CSeq 102)
  1645. nta.c:3019 agent_recv_request() nta: ACK (102) is going to INVITE (102)
  1646. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  1647. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1648. 2019-06-05 15:33:30.489166 [DEBUG] sofia.c:7284 Channel sofia/external-lan/7398@10.55.4.5 skipping state [ready][488]
  1649. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1650. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1651. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1652. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN
  1653. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0)
  1654. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74085a80 from (tcp/10.55.4.5:55848) has 975 bytes, veclen = 1
  1655. recv 975 bytes from tcp/[10.55.4.5]:55848 at 15:33:30.405514:
  1656.    ------------------------------------------------------------------------
  1657.    UPDATE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0
  1658.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60f5cf0f029
  1659.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  1660.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
  1661.    Date: Wed, 05 Jun 2019 14:33:30 GMT
  1662.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  1663.    User-Agent: Cisco-CUCM10.5
  1664.    Max-Forwards: 70
  1665.    Supported: timer,resource-priority,replaces
  1666.   Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
  1667.    CSeq: 103 UPDATE
  1668.    Call-Info: <urn:x-cisco-remotecc:callinfo>;x-cisco-video-traffic-class=MIXED
  1669.    Supported: X-cisco-srtp-fallback
  1670.    Supported: Geolocation
  1671.    Session-Expires:  1800;refresher=uac
  1672.    Min-SE:  1800
  1673.    P-Asserted-Identity: "Stephen Barry" <sip:2036964422@10.55.4.5>
  1674.    Remote-Party-ID: "Stephen Barry" <sip:2036964422@10.55.4.5>;party=calling;screen=yes;privacy=off
  1675.    Contact: <sip:8081@10.55.4.5:5060;transport=tcp>
  1676.    Content-Length: 0
  1677.  
  1678.    ------------------------------------------------------------------------
  1679. tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74085a80 (975 bytes) from tcp/10.55.4.5:55848/sip next=(nil)
  1680. nta.c:2880 agent_recv_request() nta: received UPDATE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 (CSeq 103)
  1681. nta.c:3248 agent_aliases() nta: canonizing sip:7667398@10.55.4.7:5080 with contact
  1682. nta.c:3060 agent_recv_request() nta: UPDATE (103) going to existing leg
  1683. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
  1684. nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh session after 1768 seconds (in [1768..1768])
  1685. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
  1686. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 606 bytes of 606 to tcp/10.55.4.5:55848
  1687. tport.c:3496 tport_send_msg() tport_vsend returned 606
  1688. send 606 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.405641:
  1689.    ------------------------------------------------------------------------
  1690.    SIP/2.0 200 OK
  1691.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60f5cf0f029;rport=55848
  1692.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  1693.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
  1694.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  1695.    CSeq: 103 UPDATE
  1696.    Contact: <sip:7667398@10.55.4.7:5080;transport=tcp>
  1697.    User-Agent: FreeSWITCH
  1698.    Accept: application/sdp
  1699.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
  1700.    Require: timer
  1701.    Supported: timer, path, replaces
  1702.    Session-Expires: 1800;refresher=uac
  1703.    Content-Length: 0
  1704.  
  1705.    ------------------------------------------------------------------------
  1706. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  1707. nta.c:6797 incoming_reply() nta: sent 200 OK for UPDATE (103)
  1708. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_update 200 OK
  1709. nta.c:5744 incoming_free() nta: incoming_free(0x7fce740885c0)
  1710. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  1711. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1712. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN
  1713. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0)
  1714. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74089e30 from (tcp/10.55.4.5:55848) has 1013 bytes, veclen = 1
  1715. recv 1013 bytes from tcp/[10.55.4.5]:55848 at 15:33:30.410746:
  1716.    ------------------------------------------------------------------------
  1717.    INVITE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0
  1718.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4
  1719.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  1720.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
  1721.    Date: Wed, 05 Jun 2019 14:33:30 GMT
  1722.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  1723.    Supported: timer,resource-priority,replaces
  1724.    User-Agent: Cisco-CUCM10.5
  1725.   Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
  1726.    CSeq: 104 INVITE
  1727.    Max-Forwards: 70
  1728.    Expires: 180
  1729.    Allow-Events: presence
  1730.    Call-Info: <urn:x-cisco-remotecc:callinfo>;x-cisco-video-traffic-class=MIXED
  1731.    Supported: X-cisco-srtp-fallback
  1732.    Supported: Geolocation
  1733.    Session-Expires:  1800;refresher=uac
  1734.    Min-SE:  1800
  1735.    P-Asserted-Identity: "Stephen Barry" <sip:2036964422@10.55.4.5>
  1736.    Remote-Party-ID: "Stephen Barry" <sip:2036964422@10.55.4.5>;party=calling;screen=yes;privacy=off
  1737.    Contact: <sip:8081@10.55.4.5:5060;transport=tcp>
  1738.    Content-Length: 0
  1739.  
  1740.    ------------------------------------------------------------------------
  1741. tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74089e30 (1013 bytes) from tcp/10.55.4.5:55848/sip next=(nil)
  1742. nta.c:2880 agent_recv_request() nta: received INVITE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 (CSeq 104)
  1743. nta.c:3248 agent_aliases() nta: canonizing sip:7667398@10.55.4.7:5080 with contact
  1744. nta.c:3060 agent_recv_request() nta: INVITE (104) going to existing leg
  1745. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
  1746. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fce74014690) called
  1747. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_invite 100 Trying
  1748. nua_session.c:4145 signal_call_state_change() nua(0x7fce74002fd0): ready call updated: received
  1749. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 100 Trying
  1750. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  1751. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1752. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1753. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1754. 2019-06-05 15:33:30.569165 [INFO] sofia.c:1345 sofia/external-lan/7398@10.55.4.5 Update Caller ID to "Stephen Barry" <2036964422>
  1755. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1756. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1757. nua.c:879 nua_respond() nua: nua_respond: entering
  1758. nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 100 Trying
  1759. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  1760. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called
  1761. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
  1762. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 355 bytes of 355 to tcp/10.55.4.5:55848
  1763. tport.c:3496 tport_send_msg() tport_vsend returned 355
  1764. send 355 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.411215:
  1765.    ------------------------------------------------------------------------
  1766.    SIP/2.0 100 Trying
  1767.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4;rport=55848
  1768.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  1769.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
  1770.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  1771.    CSeq: 104 INVITE
  1772.    User-Agent: FreeSWITCH
  1773.    Content-Length: 0
  1774.  
  1775.    ------------------------------------------------------------------------
  1776. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  1777. nta.c:6797 incoming_reply() nta: sent 100 Trying for INVITE (104)
  1778. nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond
  1779. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1780. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1781. 2019-06-05 15:33:30.569165 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [received][100]
  1782. nua.c:879 nua_respond() nua: nua_respond: entering
  1783. nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 200 OK
  1784. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  1785. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called
  1786. soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fce74014690, (nil), 0x7fce7009f09b, -1) called
  1787. nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond
  1788. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1789. nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
  1790. soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7fce74014690, 0) called
  1791. soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fce74014690, soa_generate_offer): called
  1792. soa_static.c:1217 offer_answer_step() soa_static(0x7fce74014690, soa_generate_offer): upgrade with local description
  1793. soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fce6b5e8ab0, (nil), ""): called
  1794. soa_static.c:1446 offer_answer_step() soa_static(0x7fce74014690, soa_generate_offer): storing local description
  1795. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce74014690, [(nil)], [0x7fce6b5eac38], [0x7fce6b5eac34]) called
  1796. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
  1797. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 839 bytes of 839 to tcp/10.55.4.5:55848
  1798. tport.c:3496 tport_send_msg() tport_vsend returned 839
  1799. send 839 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.411597:
  1800.    ------------------------------------------------------------------------
  1801.    SIP/2.0 200 OK
  1802.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4;rport=55848
  1803.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  1804.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
  1805.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  1806.    CSeq: 104 INVITE
  1807.    Contact: <sip:7667398@10.55.4.7:5080;transport=tcp>
  1808.    User-Agent: FreeSWITCH
  1809.    Accept: application/sdp
  1810.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
  1811.    Require: timer
  1812.    Supported: timer, path, replaces
  1813.    Session-Expires: 1800;refresher=uac
  1814.    Content-Type: application/sdp
  1815.    Content-Disposition: session
  1816.    Content-Length: 170
  1817.  
  1818.    v=0
  1819.    o=FreeSWITCH 1559718872 1559718874 IN IP4 10.55.4.7
  1820.    s=FreeSWITCH
  1821.    c=IN IP4 10.55.4.7
  1822.    t=0 0
  1823.    m=audio 26324 RTP/AVP 9
  1824.    a=rtpmap:9 G722/8000
  1825.    a=inactive
  1826.    a=ptime:20
  1827.    ------------------------------------------------------------------------
  1828. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  1829. nta.c:6797 incoming_reply() nta: sent 200 OK for INVITE (104)
  1830. nta.c:1348 set_timeout() nta: timer shortened to 500 ms
  1831. nua_session.c:4145 signal_call_state_change() nua(0x7fce74002fd0): ready call updated: completed sent offer
  1832. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce74014690, [0x7fce6b5eace8], [0x7fce6b5eacf0], [(nil)]) called
  1833. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 200 OK
  1834. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1835. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1836. 2019-06-05 15:33:30.629163 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [completed][200]
  1837. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1838. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN
  1839. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0)
  1840. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74088210 from (tcp/10.55.4.5:55848) has 516 bytes, veclen = 1
  1841. recv 516 bytes from tcp/[10.55.4.5]:55848 at 15:33:30.491968:
  1842.    ------------------------------------------------------------------------
  1843.    BYE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0
  1844.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb61177ff7dcb
  1845.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  1846.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
  1847.    Date: Wed, 05 Jun 2019 14:33:30 GMT
  1848.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  1849.    User-Agent: Cisco-CUCM10.5
  1850.    Max-Forwards: 70
  1851.    P-Asserted-Identity: "Stephen Barry" <sip:7398@10.55.4.5>
  1852.    CSeq: 105 BYE
  1853.    Reason: Q.850;cause=47
  1854.    Content-Length: 0
  1855.  
  1856.    ------------------------------------------------------------------------
  1857. tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74088210 (516 bytes) from tcp/10.55.4.5:55848/sip next=(nil)
  1858. nta.c:2880 agent_recv_request() nta: received BYE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 (CSeq 105)
  1859. nta.c:3248 agent_aliases() nta: canonizing sip:7667398@10.55.4.7:5080 with contact
  1860. nta.c:3060 agent_recv_request() nta: BYE (105) going to existing leg
  1861. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
  1862. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_bye 100 Trying
  1863. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  1864. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  1865. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  1866. 2019-06-05 15:33:30.709163 [DEBUG] switch_channel.c:2029 (sofia/external-lan/7398@10.55.4.5) Callstate Change HELD -> UNHELD
  1867. 2019-06-05 15:33:30.709163 [NOTICE] sofia.c:1079 Hangup sofia/external-lan/7398@10.55.4.5 [CS_EXECUTE] [UNKNOWN]
  1868. 2019-06-05 15:33:30.709163 [DEBUG] mod_hash.c:297 Usage for voip.mydomain.com_7667398 is now 0
  1869. nua.c:879 nua_respond() nua: nua_respond: entering
  1870. nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 200 OK
  1871. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  1872. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called
  1873. nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond
  1874. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
  1875. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
  1876. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  1877. nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_destroy
  1878. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 472 bytes of 472 to tcp/10.55.4.5:55848
  1879. tport.c:3496 tport_send_msg() tport_vsend returned 472
  1880. send 472 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.552443:
  1881.    ------------------------------------------------------------------------
  1882.    SIP/2.0 200 OK
  1883.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb61177ff7dcb;rport=55848
  1884.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  1885.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
  1886.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  1887.    CSeq: 105 BYE
  1888.    User-Agent: FreeSWITCH
  1889.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
  1890.    Supported: timer, path, replaces
  1891.    Content-Length: 0
  1892.  
  1893.    ------------------------------------------------------------------------
  1894. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  1895. nta.c:6797 incoming_reply() nta: sent 200 OK for BYE (105)
  1896. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fce74002fd0): removing session usage
  1897. nua_session.c:4139 signal_call_state_change() nua(0x7fce74002fd0): call state changed: ready -> terminated
  1898. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 200 Session Terminated
  1899. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_terminated 200 Session Terminated
  1900. soa.c:356 soa_destroy() soa_destroy(static::0x7fce74014690) called
  1901. nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7fce740033f0)
  1902. nta.c:5744 incoming_free() nta: incoming_free(0x7fce74014f80)
  1903. nua_stack.c:569 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_destroy
  1904. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
  1905. 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/external-lan/7398@10.55.4.5]
  1906. 2019-06-05 15:33:30.709163 [NOTICE] switch_ivr_bridge.c:932 Hangup sofia/internal/7667398@185.39.248.196:2658 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
  1907. 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_bridge.c:1881 sofia/internal/7667398@185.39.248.196:2658 skip receive message [UNBRIDGE] (channel is hungup already)
  1908. 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_bridge.c:1884 sofia/external-lan/7398@10.55.4.5 skip receive message [UNBRIDGE] (channel is hungup already)
  1909. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_session.c:2887 sofia/external-lan/7398@10.55.4.5 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
  1910. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:650 (sofia/external-lan/7398@10.55.4.5) State EXECUTE going to sleep
  1911. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_HANGUP (Cur 2 Tot 314)
  1912. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:847 (sofia/external-lan/7398@10.55.4.5) Callstate Change UNHELD -> HANGUP
  1913. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:849 (sofia/external-lan/7398@10.55.4.5) State HANGUP
  1914. 2019-06-05 15:33:30.709163 [DEBUG] mod_sofia.c:449 Channel sofia/external-lan/7398@10.55.4.5 hanging up, cause: UNKNOWN
  1915. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:60 sofia/external-lan/7398@10.55.4.5 Standard HANGUP, cause: UNKNOWN
  1916. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:849 (sofia/external-lan/7398@10.55.4.5) State HANGUP going to sleep
  1917. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:780 Hangup Command with no Session lua(app.lua hangup):
  1918.  
  1919. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:619 (sofia/external-lan/7398@10.55.4.5) State Change CS_HANGUP -> CS_REPORTING
  1920. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_REPORTING (Cur 2 Tot 314)
  1921. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:935 (sofia/external-lan/7398@10.55.4.5) State REPORTING
  1922. 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_play_say.c:1941 done playing file local_stream://default
  1923. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_session.c:2887 sofia/internal/7667398@185.39.248.196:2658 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
  1924. 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_bridge.c:572 sofia/internal/7667398@185.39.248.196:2658 skip receive message [BRIDGE] (channel is hungup already)
  1925. 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr.c:669 sofia/internal/7667398@185.39.248.196:2658 skip receive message [AUDIO_SYNC] (channel is hungup already)
  1926. 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_bridge.c:831 sofia/internal/7667398@185.39.248.196:2658 ending bridge by request from read function
  1927. 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/internal/7667398@185.39.248.196:2658]
  1928. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/7667398@185.39.248.196:2658) State EXCHANGE_MEDIA going to sleep
  1929. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_HANGUP (Cur 2 Tot 314)
  1930. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:847 (sofia/internal/7667398@185.39.248.196:2658) Callstate Change ACTIVE -> HANGUP
  1931. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/7667398@185.39.248.196:2658) State HANGUP
  1932. 2019-06-05 15:33:30.709163 [DEBUG] mod_sofia.c:443 sofia/internal/7667398@185.39.248.196:2658 Overriding SIP cause 480 with 200 from the other leg
  1933. 2019-06-05 15:33:30.709163 [DEBUG] mod_sofia.c:449 Channel sofia/internal/7667398@185.39.248.196:2658 hanging up, cause: NORMAL_CLEARING
  1934. 2019-06-05 15:33:30.709163 [DEBUG] mod_sofia.c:502 Sending BYE to sofia/internal/7667398@185.39.248.196:2658
  1935. nua.c:645 nua_bye() nua: nua_bye: entering
  1936. nua_stack.c:569 nua_stack_signal() nua(0x7fce6c02f9a0): recv signal r_bye
  1937. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  1938. soa.c:403 soa_set_params() soa_set_params(static::0x7fce600921a0, ...) called
  1939. nua_stack.c:529 nua_signal() nua(0x7fce6c02f9a0): sent signal r_bye
  1940. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:60 sofia/internal/7667398@185.39.248.196:2658 Standard HANGUP, cause: NORMAL_CLEARING
  1941. soa.c:1784 soa_terminate() soa_terminate(static::0x7fce600921a0) called
  1942. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fce600921a0) called
  1943. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/7667398@185.39.248.196:2658) State HANGUP going to sleep
  1944. nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
  1945. tport.c:4592 tport_by_name() tport(0x7fce600466b0): found 0x7fce6007ac40 by name tls/185.39.248.196:2658
  1946. tport.c:3261 tport_tsend() tport_tsend(0x7fce6007ac40) tpn = tls/185.39.248.196:2658
  1947. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/7667398@185.39.248.196:2658) State Change CS_HANGUP -> CS_REPORTING
  1948. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce6007ba80 0x7fce6005b5c0 606 (606)
  1949. tport.c:3598 tport_vsend() tport_vsend(0x7fce6007ac40): 606 bytes of 606 to tls/185.39.248.196:2658
  1950. tport.c:3496 tport_send_msg() tport_vsend returned 606
  1951. send 606 bytes to tls/[185.39.248.196]:2658 at 15:33:30.566247:
  1952.    ------------------------------------------------------------------------
  1953.    BYE sip:7667398@185.39.248.196:2658;transport=tls SIP/2.0
  1954.    Via: SIP/2.0/TLS 185.39.250.165:5061;rport;branch=z9hG4bKc1aFc6UrpZNcF
  1955.    Max-Forwards: 70
  1956.    From: "Stephen Barry" <sip:7398@voip.mydomain.com>;tag=pU8rDB8DUHjFe
  1957.    To: <sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls>;tag=AFAB2EFC86E53DF36B3DE9E22393BB2C
  1958.    Call-ID: b2998455-0241-1238-e9ba-005056860fd6
  1959.    CSeq: 5318807 BYE
  1960.    User-Agent: FreeSWITCH
  1961.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  1962.    Supported: timer, path, replaces
  1963.    Reason: Q.850;cause=47
  1964.    Content-Length: 0
  1965.  
  1966.    ------------------------------------------------------------------------
  1967. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
  1968. nta.c:8310 outgoing_send() nta: sent BYE (5318807) to tls/185.39.248.196:2658
  1969. tport.c:4164 tport_pend() tport_pend(0x7fce6007ac40): pending 0x7fce6007dec0 for tls/185.39.248.196:2658 (already 0)
  1970. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_REPORTING (Cur 2 Tot 314)
  1971. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/7667398@185.39.248.196:2658) State REPORTING
  1972. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:174 sofia/internal/7667398@185.39.248.196:2658 Standard REPORTING, cause: NORMAL_CLEARING
  1973. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/7667398@185.39.248.196:2658) State REPORTING going to sleep
  1974. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/7667398@185.39.248.196:2658) State Change CS_REPORTING -> CS_DESTROY
  1975. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_session.c:1715 Session 314 (sofia/internal/7667398@185.39.248.196:2658) Locked, Waiting on external entities
  1976. 2019-06-05 15:33:30.709163 [NOTICE] switch_core_session.c:1733 Session 314 (sofia/internal/7667398@185.39.248.196:2658) Ended
  1977. 2019-06-05 15:33:30.709163 [NOTICE] switch_core_session.c:1737 Close Channel sofia/internal/7667398@185.39.248.196:2658 [CS_DESTROY]
  1978. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:738 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_DESTROY (Cur 1 Tot 314)
  1979. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/7667398@185.39.248.196:2658) State DESTROY
  1980. 2019-06-05 15:33:30.709163 [DEBUG] mod_sofia.c:354 sofia/internal/7667398@185.39.248.196:2658 SOFIA DESTROY
  1981. 2019-06-05 15:33:30.709163 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[416] PLC[0] FEC[0]
  1982. 2019-06-05 15:33:30.709163 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
  1983. 2019-06-05 15:33:30.709163 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
  1984. 2019-06-05 15:33:30.709163 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[436] Bytes encoded[12371] Encoded length ms[8720] Average encoded bitrate bps[12371]
  1985. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:181 sofia/internal/7667398@185.39.248.196:2658 Standard DESTROY
  1986. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/7667398@185.39.248.196:2658) State DESTROY going to sleep
  1987. 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:174 sofia/external-lan/7398@10.55.4.5 Standard REPORTING, cause: UNKNOWN
  1988. 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:935 (sofia/external-lan/7398@10.55.4.5) State REPORTING going to sleep
  1989. 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:610 (sofia/external-lan/7398@10.55.4.5) State Change CS_REPORTING -> CS_DESTROY
  1990. 2019-06-05 15:33:30.729171 [DEBUG] switch_core_session.c:1715 Session 313 (sofia/external-lan/7398@10.55.4.5) Locked, Waiting on external entities
  1991. 2019-06-05 15:33:30.729171 [NOTICE] switch_core_session.c:1733 Session 313 (sofia/external-lan/7398@10.55.4.5) Ended
  1992. 2019-06-05 15:33:30.729171 [NOTICE] switch_core_session.c:1737 Close Channel sofia/external-lan/7398@10.55.4.5 [CS_DESTROY]
  1993. 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:738 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_DESTROY (Cur 0 Tot 314)
  1994. 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:748 (sofia/external-lan/7398@10.55.4.5) State DESTROY
  1995. 2019-06-05 15:33:30.729171 [DEBUG] mod_sofia.c:354 sofia/external-lan/7398@10.55.4.5 SOFIA DESTROY
  1996. 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:181 sofia/external-lan/7398@10.55.4.5 Standard DESTROY
  1997. 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:748 (sofia/external-lan/7398@10.55.4.5) State DESTROY going to sleep
  1998. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce6007ac40): events IN
  1999. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce6007ac40)
  2000. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce6007ac40): tls_read() returned 599
  2001. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce6007ac40) msg 0x7fce60082d70 from (tls/185.39.248.196:2658) has 599 bytes, veclen = 1
  2002. recv 599 bytes from tls/[185.39.248.196]:2658 at 15:33:30.640195:
  2003.    ------------------------------------------------------------------------
  2004.    SIP/2.0 200 OK
  2005.    Via: SIP/2.0/TLS 185.39.250.165:5061;rport=5061;branch=z9hG4bKc1aFc6UrpZNcF;received=185.39.250.165
  2006.    Contact: <sip:7667398@185.39.248.196:2658;transport=tls>
  2007.    From: "Stephen Barry" <sip:7398@voip.mydomain.com>;tag=pU8rDB8DUHjFe
  2008.    Call-ID: b2998455-0241-1238-e9ba-005056860fd6
  2009.    CSeq: 5318807 BYE
  2010.    To: <sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls>;tag=AFAB2EFC86E53DF36B3DE9E22393BB2C
  2011.   Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
  2012.    Supported: replaces, path
  2013.    User-Agent: Groundwire/5.2.14 (build 1243766; Android 9; arm64-v8a)
  2014.    Content-Length: 0
  2015.  
  2016.    ------------------------------------------------------------------------
  2017. tport.c:3027 tport_deliver() tport_deliver(0x7fce6007ac40): msg 0x7fce60082d70 (599 bytes) from tls/185.39.248.196:2658/sips next=(nil)
  2018. nta.c:3299 agent_recv_response() nta: received 200 OK for BYE (5318807)
  2019. nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
  2020. nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 74.007 ms
  2021. tport.c:4226 tport_release() tport_release(0x7fce6007ac40): 0x7fce6007dec0 by 0x7fce6007cd00 with 0x7fce60082d70
  2022. nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event r_bye 200 OK
  2023. nua_session.c:4139 signal_call_state_change() nua(0x7fce6c02f9a0): call state changed: terminating -> terminated
  2024. nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event i_state 200 to BYE
  2025. nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event i_terminated 200 to BYE
  2026. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fce6c02f9a0): removing session usage
  2027. soa.c:356 soa_destroy() soa_destroy(static::0x7fce600921a0) called
  2028. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  2029. nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7fce60050880)
  2030. nua_session.c:351 nua_session_usage_destroy() nua: terminated session 0x7fce6c02f9a0
  2031. nta.c:8728 outgoing_free() nta: outgoing_free(0x7fce6007cd00)
  2032. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  2033. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  2034. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
  2035. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  2036. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  2037. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  2038. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  2039. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
  2040. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  2041. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  2042. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  2043. nua_stack.c:569 nua_stack_signal() nua(0x7fce6c02f9a0): recv signal r_destroy
  2044. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
  2045. nua_stack.c:529 nua_signal() nua(0x7fce6c02f9a0): sent signal r_destroy
  2046. nta.c:7002 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
  2047. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
  2048. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 839 bytes of 839 to tcp/10.55.4.5:55848
  2049. tport.c:3496 tport_send_msg() tport_vsend returned 839
  2050. send 839 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.911677:
  2051.    ------------------------------------------------------------------------
  2052.    SIP/2.0 200 OK
  2053.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4;rport=55848
  2054.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  2055.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
  2056.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  2057.    CSeq: 104 INVITE
  2058.    Contact: <sip:7667398@10.55.4.7:5080;transport=tcp>
  2059.    User-Agent: FreeSWITCH
  2060.    Accept: application/sdp
  2061.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
  2062.    Require: timer
  2063.    Supported: timer, path, replaces
  2064.    Session-Expires: 1800;refresher=uac
  2065.    Content-Type: application/sdp
  2066.    Content-Disposition: session
  2067.    Content-Length: 170
  2068.  
  2069.    v=0
  2070.    o=FreeSWITCH 1559718872 1559718874 IN IP4 10.55.4.7
  2071.    s=FreeSWITCH
  2072.    c=IN IP4 10.55.4.7
  2073.    t=0 0
  2074.    m=audio 26324 RTP/AVP 9
  2075.    a=rtpmap:9 G722/8000
  2076.    a=inactive
  2077.    a=ptime:20
  2078.    ------------------------------------------------------------------------
  2079. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  2080. nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7fce6b5eac50)
  2081. nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/0 term, 1/2 free
  2082. nta.c:1296 agent_timer() nta: timer set next to 1000 ms
  2083. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce60053a50): events IN
  2084. tport.c:2159 tport_shutdown0() tport_shutdown0(0x7fce60053a50, 2)
  2085. tport.c:2092 tport_close() tport_close(0x7fce60053a50): tls/162.243.35.55:64178/sips
  2086. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce60055b50): events IN
  2087. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce60055b50)
  2088. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce60055b50): tls_read() returned 594
  2089. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce60055b50) msg 0x7fce600332f0 from (tls/185.39.250.164:41117) has 594 bytes, veclen = 1
  2090. recv 594 bytes from tls/[185.39.250.164]:41117 at 15:33:31.430496:
  2091.    ------------------------------------------------------------------------
  2092.    REGISTER sip:voip.mydomain.com SIP/2.0
  2093.    Via: SIP/2.0/TLS 10.44.4.218:41117;branch=z9hG4bK76hEepoHW5dMPtUM;rport
  2094.    Contact: <sip:766@185.39.250.164:41117;rinstance=599D32E4;transport=tls>;expires=600;video
  2095.    Max-Forwards: 70
  2096.    From: <sip:766@voip.mydomain.com>;tag=FE14135E45D208D6CE5AC4C4FC9EE551
  2097.   Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
  2098.    Supported: replaces, path
  2099.    To: <sip:766@voip.mydomain.com>
  2100.    Expires: 600
  2101.    Call-ID: B5922A752C0F91D4693A3EC8E2E8C612282D6CEA
  2102.    CSeq: 503 REGISTER
  2103.    User-Agent: Groundwire/5.2.14 (build 1243766; Android 8.1.0; arm64-v8a)
  2104.    Content-Length: 0
  2105.  
  2106.    ------------------------------------------------------------------------
  2107. tport.c:3027 tport_deliver() tport_deliver(0x7fce60055b50): msg 0x7fce600332f0 (594 bytes) from tls/185.39.250.164:41117/sips next=(nil)
  2108. nta.c:2880 agent_recv_request() nta: received REGISTER sip:voip.mydomain.com SIP/2.0 (CSeq 503)
  2109. nta.c:3174 agent_check_request_via() nta: Via check: received=185.39.250.164
  2110. nta.c:3085 agent_recv_request() nta: REGISTER (503) going to a default leg
  2111. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
  2112. nua_stack.c:899 nh_create() nua: nh_create: entering
  2113. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
  2114. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  2115. soa.c:280 soa_clone() soa_clone(static::0x7fce60096e10, 0x7fce6007dde0, 0x7fce60037d30) called
  2116. soa.c:403 soa_set_params() soa_set_params(static::0x7fce6007cb80, ...) called
  2117. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fce60037d30): adding registrar usage
  2118. tport.c:4164 tport_pend() tport_pend(0x7fce60055b50): pending (nil) for tls/185.39.250.164:41117 (already 0)
  2119. nua_stack.c:271 nua_stack_event() nua(0x7fce60037d30): event i_register 100 Trying
  2120. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer
  2121. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  2122. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  2123. nua.c:879 nua_respond() nua: nua_respond: entering
  2124. nua_stack.c:529 nua_signal() nua(0x7fce60037d30): sent signal r_respond
  2125. nua_stack.c:573 nua_stack_signal() nua(0x7fce60037d30): recv signal r_respond 401 Unauthorized
  2126. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  2127. soa.c:403 soa_set_params() soa_set_params(static::0x7fce6007cb80, ...) called
  2128. 2019-06-05 15:33:31.589166 [WARNING] sofia_reg.c:1798 SIP auth challenge (REGISTER) on sofia profile 'internal' for [766@voip.mydomain.com] from ip 185.39.250.164
  2129. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  2130. nua_stack.c:529 nua_signal() nua(0x7fce60037d30): sent signal r_destroy
  2131. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  2132. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  2133. tport.c:3261 tport_tsend() tport_tsend(0x7fce60055b50) tpn = TLS/185.39.250.164:41117
  2134. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce600722a0 129 (129)
  2135. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce600c074e 71 (71)
  2136. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce60072321 50 (50)
  2137. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce600c081d 71 (71)
  2138. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce60072353 313 (313)
  2139. tport.c:3598 tport_vsend() tport_vsend(0x7fce60055b50): 634 bytes of 634 to tls/185.39.250.164:41117
  2140. tport.c:3496 tport_send_msg() tport_vsend returned 634
  2141. send 634 bytes to tls/[185.39.250.164]:41117 at 15:33:31.430888:
  2142.    ------------------------------------------------------------------------
  2143.    SIP/2.0 401 Unauthorized
  2144.    Via: SIP/2.0/TLS 10.44.4.218:41117;branch=z9hG4bK76hEepoHW5dMPtUM;rport=41117;received=185.39.250.164
  2145.    From: <sip:766@voip.mydomain.com>;tag=FE14135E45D208D6CE5AC4C4FC9EE551
  2146.    To: <sip:766@voip.mydomain.com>;tag=Spm3jvtrjcN7g
  2147.    Call-ID: B5922A752C0F91D4693A3EC8E2E8C612282D6CEA
  2148.    CSeq: 503 REGISTER
  2149.    User-Agent: FreeSWITCH
  2150.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  2151.    Supported: timer, path, replaces
  2152.    WWW-Authenticate: Digest realm="voip.mydomain.com", nonce="831c4ee7-39bc-4fab-95f9-57906f1cd317", algorithm=MD5, qop="auth"
  2153.    Content-Length: 0
  2154.  
  2155.    ------------------------------------------------------------------------
  2156. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer
  2157. nta.c:6797 incoming_reply() nta: sent 401 Unauthorized for REGISTER (503)
  2158. nta.c:5744 incoming_free() nta: incoming_free(0x7fce60052510)
  2159. nua_stack.c:569 nua_stack_signal() nua(0x7fce60037d30): recv signal r_destroy
  2160. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fce60037d30): removing registrar usage
  2161. tport.c:4226 tport_release() tport_release(0x7fce60055b50): (nil) by 0x7fce60037d30 with (nil)
  2162. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer
  2163. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
  2164. soa.c:356 soa_destroy() soa_destroy(static::0x7fce6007cb80) called
  2165. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce60055b50): events IN
  2166. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce60055b50)
  2167. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce60055b50): tls_read() returned 842
  2168. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce60055b50) msg 0x7fce600332f0 from (tls/185.39.250.164:41117) has 842 bytes, veclen = 1
  2169. recv 842 bytes from tls/[185.39.250.164]:41117 at 15:33:31.442976:
  2170.    ------------------------------------------------------------------------
  2171.    REGISTER sip:voip.mydomain.com SIP/2.0
  2172.    Via: SIP/2.0/TLS 10.44.4.218:41117;branch=z9hG4bKWFMe5vUSuAcJS5LP;rport
  2173.    Contact: <sip:766@185.39.250.164:41117;rinstance=599D32E4;transport=tls>;expires=600;video
  2174.    Max-Forwards: 70
  2175.    From: <sip:766@voip.mydomain.com>;tag=FE14135E45D208D6CE5AC4C4FC9EE551
  2176.   Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
  2177.    Supported: replaces, path
  2178.    To: <sip:766@voip.mydomain.com>
  2179.    Expires: 600
  2180.    Call-ID: B5922A752C0F91D4693A3EC8E2E8C612282D6CEA
  2181.    CSeq: 504 REGISTER
  2182.    Authorization: Digest username="766",realm="voip.mydomain.com",algorithm=MD5,uri="sip:voip.mydomain.com",nonce="831c4ee7-39bc-4fab-95f9-57906f1cd317",qop=auth,cnonce="XPfSu8WgFUtrKcJ1eXtLtrUz",nc=00000001,response="41f1e87f8e30cd2b0d5cf1b807f361b4"
  2183.    User-Agent: Groundwire/5.2.14 (build 1243766; Android 8.1.0; arm64-v8a)
  2184.    Content-Length: 0
  2185.  
  2186.    ------------------------------------------------------------------------
  2187. tport.c:3027 tport_deliver() tport_deliver(0x7fce60055b50): msg 0x7fce600332f0 (842 bytes) from tls/185.39.250.164:41117/sips next=(nil)
  2188. nta.c:2880 agent_recv_request() nta: received REGISTER sip:voip.mydomain.com SIP/2.0 (CSeq 504)
  2189. nta.c:3174 agent_check_request_via() nta: Via check: received=185.39.250.164
  2190. nta.c:3085 agent_recv_request() nta: REGISTER (504) going to a default leg
  2191. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
  2192. nua_stack.c:899 nh_create() nua: nh_create: entering
  2193. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
  2194. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  2195. soa.c:280 soa_clone() soa_clone(static::0x7fce60096e10, 0x7fce6007dde0, 0x7fce6005d220) called
  2196. soa.c:403 soa_set_params() soa_set_params(static::0x7fce600921a0, ...) called
  2197. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fce6005d220): adding registrar usage
  2198. tport.c:4164 tport_pend() tport_pend(0x7fce60055b50): pending (nil) for tls/185.39.250.164:41117 (already 0)
  2199. nua_stack.c:271 nua_stack_event() nua(0x7fce6005d220): event i_register 100 Trying
  2200. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer
  2201. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
  2202. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  2203. 2019-06-05 15:33:31.589166 [WARNING] sofia_reg.c:2935 Can't find user [766@voip.mydomain.com] from 185.39.250.164
  2204. You must define a domain called 'voip.mydomain.com' in your directory and add a user with the id="766" attribute
  2205. and you must configure your device to use the proper domain in it's authentication credentials.
  2206. nua.c:879 nua_respond() nua: nua_respond: entering
  2207. nua_stack.c:573 nua_stack_signal() nua(0x7fce6005d220): recv signal r_respond 403 Forbidden
  2208. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
  2209. soa.c:403 soa_set_params() soa_set_params(static::0x7fce600921a0, ...) called
  2210. tport.c:3261 tport_tsend() tport_tsend(0x7fce60055b50) tpn = TLS/185.39.250.164:41117
  2211. nua_stack.c:529 nua_signal() nua(0x7fce6005d220): sent signal r_respond
  2212. 2019-06-05 15:33:31.589166 [WARNING] sofia_reg.c:1743 SIP auth failure (REGISTER) on sofia profile 'internal' for [766@voip.mydomain.com] from ip 185.39.250.164
  2213. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce60072230 126 (126)
  2214. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  2215. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce60072ece 71 (71)
  2216. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce600722ae 50 (50)
  2217. nua_stack.c:529 nua_signal() nua(0x7fce6005d220): sent signal r_destroy
  2218. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
  2219. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce60072f9d 71 (71)
  2220. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
  2221. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce600722e0 189 (189)
  2222. tport.c:3598 tport_vsend() tport_vsend(0x7fce60055b50): 507 bytes of 507 to tls/185.39.250.164:41117
  2223. tport.c:3496 tport_send_msg() tport_vsend returned 507
  2224. send 507 bytes to tls/[185.39.250.164]:41117 at 15:33:31.446079:
  2225.    ------------------------------------------------------------------------
  2226.    SIP/2.0 403 Forbidden
  2227.    Via: SIP/2.0/TLS 10.44.4.218:41117;branch=z9hG4bKWFMe5vUSuAcJS5LP;rport=41117;received=185.39.250.164
  2228.    From: <sip:766@voip.mydomain.com>;tag=FE14135E45D208D6CE5AC4C4FC9EE551
  2229.    To: <sip:766@voip.mydomain.com>;tag=tZDvmQBvFNBtc
  2230.    Call-ID: B5922A752C0F91D4693A3EC8E2E8C612282D6CEA
  2231.    CSeq: 504 REGISTER
  2232.    User-Agent: FreeSWITCH
  2233.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  2234.    Supported: timer, path, replaces
  2235.    Content-Length: 0
  2236.  
  2237.    ------------------------------------------------------------------------
  2238. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer
  2239. nta.c:6797 incoming_reply() nta: sent 403 Forbidden for REGISTER (504)
  2240. nta.c:5744 incoming_free() nta: incoming_free(0x7fce60037d30)
  2241. nua_stack.c:569 nua_stack_signal() nua(0x7fce6005d220): recv signal r_destroy
  2242. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fce6005d220): removing registrar usage
  2243. tport.c:4226 tport_release() tport_release(0x7fce60055b50): (nil) by 0x7fce6005d220 with (nil)
  2244. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer
  2245. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
  2246. soa.c:356 soa_destroy() soa_destroy(static::0x7fce600921a0) called
  2247. nta.c:7002 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
  2248. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
  2249. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 839 bytes of 839 to tcp/10.55.4.5:55848
  2250. tport.c:3496 tport_send_msg() tport_vsend returned 839
  2251. send 839 bytes to tcp/[10.55.4.5]:55848 at 15:33:31.911851:
  2252.    ------------------------------------------------------------------------
  2253.    SIP/2.0 200 OK
  2254.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4;rport=55848
  2255.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  2256.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
  2257.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  2258.    CSeq: 104 INVITE
  2259.    Contact: <sip:7667398@10.55.4.7:5080;transport=tcp>
  2260.    User-Agent: FreeSWITCH
  2261.    Accept: application/sdp
  2262.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
  2263.    Require: timer
  2264.    Supported: timer, path, replaces
  2265.    Session-Expires: 1800;refresher=uac
  2266.    Content-Type: application/sdp
  2267.    Content-Disposition: session
  2268.    Content-Length: 170
  2269.  
  2270.    v=0
  2271.    o=FreeSWITCH 1559718872 1559718874 IN IP4 10.55.4.7
  2272.    s=FreeSWITCH
  2273.    c=IN IP4 10.55.4.7
  2274.    t=0 0
  2275.    m=audio 26324 RTP/AVP 9
  2276.    a=rtpmap:9 G722/8000
  2277.    a=inactive
  2278.    a=ptime:20
  2279.    ------------------------------------------------------------------------
  2280. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  2281. nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/1 free
  2282. nta.c:1296 agent_timer() nta: timer set next to 2000 ms
  2283. nta.c:7002 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
  2284. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
  2285. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 839 bytes of 839 to tcp/10.55.4.5:55848
  2286. tport.c:3496 tport_send_msg() tport_vsend returned 839
  2287. send 839 bytes to tcp/[10.55.4.5]:55848 at 15:33:33.911871:
  2288.    ------------------------------------------------------------------------
  2289.    SIP/2.0 200 OK
  2290.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4;rport=55848
  2291.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  2292.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
  2293.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  2294.    CSeq: 104 INVITE
  2295.    Contact: <sip:7667398@10.55.4.7:5080;transport=tcp>
  2296.    User-Agent: FreeSWITCH
  2297.    Accept: application/sdp
  2298.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
  2299.    Require: timer
  2300.    Supported: timer, path, replaces
  2301.    Session-Expires: 1800;refresher=uac
  2302.    Content-Type: application/sdp
  2303.    Content-Disposition: session
  2304.    Content-Length: 170
  2305.  
  2306.    v=0
  2307.    o=FreeSWITCH 1559718872 1559718874 IN IP4 10.55.4.7
  2308.    s=FreeSWITCH
  2309.    c=IN IP4 10.55.4.7
  2310.    t=0 0
  2311.    m=audio 26324 RTP/AVP 9
  2312.    a=rtpmap:9 G722/8000
  2313.    a=inactive
  2314.    a=ptime:20
  2315.    ------------------------------------------------------------------------
  2316. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  2317. nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/1 free
  2318. nta.c:1296 agent_timer() nta: timer set next to 4000 ms
  2319. nta.c:7002 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
  2320. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
  2321. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 839 bytes of 839 to tcp/10.55.4.5:55848
  2322. tport.c:3496 tport_send_msg() tport_vsend returned 839
  2323. send 839 bytes to tcp/[10.55.4.5]:55848 at 15:33:37.911921:
  2324.    ------------------------------------------------------------------------
  2325.    SIP/2.0 200 OK
  2326.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4;rport=55848
  2327.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
  2328.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
  2329.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
  2330.    CSeq: 104 INVITE
  2331.    Contact: <sip:7667398@10.55.4.7:5080;transport=tcp>
  2332.    User-Agent: FreeSWITCH
  2333.    Accept: application/sdp
  2334.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
  2335.    Require: timer
  2336.    Supported: timer, path, replaces
  2337.    Session-Expires: 1800;refresher=uac
  2338.    Content-Type: application/sdp
  2339.    Content-Disposition: session
  2340.    Content-Length: 170
  2341.  
  2342.    v=0
  2343.    o=FreeSWITCH 1559718872 1559718874 IN IP4 10.55.4.7
  2344.    s=FreeSWITCH
  2345.    c=IN IP4 10.55.4.7
  2346.    t=0 0
  2347.    m=audio 26324 RTP/AVP 9
  2348.    a=rtpmap:9 G722/8000
  2349.    a=inactive
  2350.    a=ptime:20
  2351.    ------------------------------------------------------------------------
  2352. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
  2353. nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/1 free
  2354. nta.c:1296 agent_timer() nta: timer set next to 4000 ms
  2355. freeswitch@fpbx01>
  2356.  

Reply to "Inbound Transfer Issue"

captcha