FreeSWITCH Pastebin

t38-negotiation-failure

From Ramon, 7 Years ago, written in FreeSWITCH.
- go back
URL https://pastebin.freeswitch.org/view/54e17bb7
Embed
Viewing differences between and t38-negotiation-failure
  1.    ------------------------------------------------------------------------
  2.    INVITE sip:18003799180@10.31.1.5:5070 SIP/2.0
  3.    Record-Route: <sip:10.15.7.7;r2=on;lr;ftag=3708710826-841185>
  4.    Record-Route: <sip:192.76.120.11;r2=on;lr;ftag=3708710826-841185>
  5.    Max-Forwards: 67
  6.    Session-Expires: 7200;refresher=uac
  7.    Min-SE: 600
  8.    Supported: timer, 100rel
  9.    To: <sip:18003799180@192.168.250.45:5060>
  10.    From: <sip:9712751300@64.125.111.10;isup-oli=23>;tag=3708710826-841185
  11.    P-Asserted-Identity: <sip:9712751300@69.87.154.208;rn=971319>
  12.    Call-ID: 45872803-3708710826-841179@msc1.382COM.COM
  13.    CSeq: 1 INVITE
  14.   Allow: CANCEL, ACK, INVITE, BYE, OPTIONS, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE, MESSAGE, PUBLISH
  15.    Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK11ab.8fd8cbf6d75cec349558389bb71d4c60.0
  16.    Via: SIP/2.0/UDP 64.125.111.10:5060;rport=5060;branch=z9hG4bKff4ba30d164e547a34c7adac5db6677c
  17.    Contact: <sip:9712751300@64.125.111.10:5060>
  18.    Expires: 180
  19.    Allow-Events: telephone-event
  20.    Content-Type: application/sdp
  21.    Accept: application/sdp
  22.    Content-Length: 260
  23.    X-AUTH-IP: 64.125.111.10
  24.    
  25.    v=0
  26.    o=msc1 1018 686 IN IP4 64.125.111.10
  27.    s=sip call
  28.    c=IN IP4 69.87.154.208
  29.    t=0 0
  30.    m=audio 17262 RTP/AVP 0 8 18 101
  31.    a=rtpmap:0 PCMU/8000
  32.    a=rtpmap:8 PCMA/8000
  33.    a=rtpmap:18 G729/8000
  34.    a=fmtp:18 annexb=no
  35.    a=rtpmap:101 telephone-event/8000
  36.    a=fmtp:101 0-16
  37.    ------------------------------------------------------------------------
  38. send 532 bytes to udp/[10.15.7.7]:5060 at 21:27:06.922343:
  39.    ------------------------------------------------------------------------
  40.    SIP/2.0 100 Trying
  41.    Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK11ab.8fd8cbf6d75cec349558389bb71d4c60.0
  42.    Via: SIP/2.0/UDP 64.125.111.10:5060;rport=5060;branch=z9hG4bKff4ba30d164e547a34c7adac5db6677c
  43.    Record-Route: <sip:10.15.7.7;r2=on;lr;ftag=3708710826-841185>
  44.    Record-Route: <sip:192.76.120.11;r2=on;lr;ftag=3708710826-841185>
  45.    From: <sip:9712751300@64.125.111.10;isup-oli=23>;tag=3708710826-841185
  46.    To: <sip:18003799180@192.168.250.45:5060>
  47.    Call-ID: 45872803-3708710826-841179@msc1.382COM.COM
  48.    CSeq: 1 INVITE
  49.    Content-Length: 0
  50.    
  51.    ------------------------------------------------------------------------
  52. 2017-07-10 21:27:06.908959 [NOTICE] switch_channel.c:1104 New Channel sofia/inbound/9712751300@64.125.111.10 [2b04f60c-4eea-4516-b079-2772d3fd681f]
  53. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/9712751300@64.125.111.10) Running State Change CS_NEW (Cur 1 Tot 29)
  54. 2017-07-10 21:27:06.908959 [DEBUG] sofia.c:9837 sofia/inbound/9712751300@64.125.111.10 receiving invite from 10.15.7.7:5060 version: 1.6.18 git 3da0ad0 2017-06-28 17:17:04Z 64bit
  55. 2017-07-10 21:27:06.908959 [DEBUG] sofia.c:7048 Channel sofia/inbound/9712751300@64.125.111.10 entering state [received][100]
  56. 2017-07-10 21:27:06.908959 [DEBUG] sofia.c:7058 Remote SDP:
  57. v=0
  58. o=msc1 1018 686 IN IP4 64.125.111.10
  59. s=sip call
  60. c=IN IP4 69.87.154.208
  61. t=0 0
  62. m=audio 17262 RTP/AVP 0 8 18 101
  63. a=rtpmap:0 PCMU/8000
  64. a=rtpmap:8 PCMA/8000
  65. a=rtpmap:18 G729/8000
  66. a=fmtp:18 annexb=no
  67. a=rtpmap:101 telephone-event/8000
  68. a=fmtp:101 0-16
  69.  
  70. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  71. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  72. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
  73. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  74. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G729:18:8000:20:8000:1]
  75. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
  76. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  77. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  78. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  79. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
  80. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1]
  81. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
  82. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
  83. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
  84. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
  85. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1]
  86. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match
  87. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1]
  88. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4361 Set telephone-event payload to 101@8000
  89. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:3057 Set Codec sofia/inbound/9712751300@64.125.111.10 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
  90. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_codec.c:111 sofia/inbound/9712751300@64.125.111.10 Original read codec set to PCMU:0
  91. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4704 Set telephone-event payload to 101@8000
  92. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4763 sofia/inbound/9712751300@64.125.111.10 Set 2833 dtmf send payload to 101 recv payload to 101
  93. 2017-07-10 21:27:06.908959 [DEBUG] sofia.c:7471 (sofia/inbound/9712751300@64.125.111.10) State Change CS_NEW -> CS_INIT
  94. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:603 (sofia/inbound/9712751300@64.125.111.10) State NEW
  95. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/9712751300@64.125.111.10) Running State Change CS_INIT (Cur 1 Tot 29)
  96. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:627 (sofia/inbound/9712751300@64.125.111.10) State INIT
  97. 2017-07-10 21:27:06.908959 [DEBUG] mod_sofia.c:90 sofia/inbound/9712751300@64.125.111.10 SOFIA INIT
  98. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:40 sofia/inbound/9712751300@64.125.111.10 Standard INIT
  99. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:48 (sofia/inbound/9712751300@64.125.111.10) State Change CS_INIT -> CS_ROUTING
  100. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:627 (sofia/inbound/9712751300@64.125.111.10) State INIT going to sleep
  101. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/9712751300@64.125.111.10) Running State Change CS_ROUTING (Cur 1 Tot 29)
  102. 2017-07-10 21:27:06.908959 [DEBUG] switch_channel.c:2249 (sofia/inbound/9712751300@64.125.111.10) Callstate Change DOWN -> RINGING
  103. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:643 (sofia/inbound/9712751300@64.125.111.10) State ROUTING
  104. 2017-07-10 21:27:06.908959 [DEBUG] mod_sofia.c:143 sofia/inbound/9712751300@64.125.111.10 SOFIA ROUTING
  105. 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:236 sofia/inbound/9712751300@64.125.111.10 Standard ROUTING
  106. 2017-07-10 21:27:06.908959 [INFO] mod_dialplan_xml.c:637 Processing 9712751300 <9712751300>->18003799180 in context public
  107. Dialplan: sofia/inbound/9712751300@64.125.111.10 parsing [public->UNKNOWN] continue=false
  108. Dialplan: sofia/inbound/9712751300@64.125.111.10 Absolute Condition [UNKNOWN]
  109. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action set(telnyx_uuid=8646b9cf-65b6-11e7-a6aa-02420a1f010f)
  110. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(telnyx_session_uuid=8646bcd1-65b6-11e7-8f37-02420a1f010f)
  111. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(e164_cld=+18003799180)
  112. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(e164_cli=+19712751300)
  113. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(counterparty_a=382com)
  114. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(counterparty_b=telnyx)
  115. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(on_net=false)
  116. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(nolocal:connection_id=306330846174905419)
  117. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(nolocal:user_type=public-api)
  118. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(nolocal:user_id=127)
  119. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(nolocal:tags=)
  120. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(nolocal:usage_payment_method=pay-per-minute)
  121. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(user_data={"origination": {"user_id": "127", "tn_type": "TF", "tags": [], "DID": "+18003799180", "user_type": "public-api", "connection_id": "306330846174905419", "tn": "+18003799180"}})
  122. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(planned=true)
  123. Dialplan: sofia/inbound/9712751300@64.125.111.10 Absolute Condition [UNKNOWN]
  124. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action unset(sip_h_X-FS-Support)
  125. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action ring_ready()
  126. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action set(call_timeout=600)
  127. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action set(continue_on_fail=false)
  128. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(sip_cid_type=pid)
  129. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action set(sip_copy_multipart=false)
  130. Dialplan: sofia/inbound/9712751300@64.125.111.10 Action bridge({local_var_clobber=true,originate_continue_on_timeout=true,sip_invite_domain=sip.telnyx.com,origination_caller_id_number=19712751300}[leg_timeout=300,leg_progress_timeout=5,orig_auth=ip-authentication,absolute_codec_string=^^:G722:PCMU:PCMA:G729:OPUS,sip_execute_on_image='t38_gateway self nocng',fax_enable_t38=true,sip_h_X-USE-UDP=1,ip_port=54.165.139.136:5061,sip_h_X-KIBP=10.15.7.7,telnyx_uuid=864a5a7a-65b6-11e7-8c94-02420a1f010f]sofia/priv-external-compact/222218003799180@54.165.139.136:5061;fs_path=sip%3A10.15.7.7%3A5060%3Btransport%3DUDP)
  131. 2017-07-10 21:27:06.948913 [DEBUG] switch_core_state_machine.c:286 (sofia/inbound/9712751300@64.125.111.10) State Change CS_ROUTING -> CS_EXECUTE
  132. 2017-07-10 21:27:06.948913 [DEBUG] switch_core_state_machine.c:643 (sofia/inbound/9712751300@64.125.111.10) State ROUTING going to sleep
  133. 2017-07-10 21:27:06.948913 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/9712751300@64.125.111.10) Running State Change CS_EXECUTE (Cur 1 Tot 29)
  134. 2017-07-10 21:27:06.948913 [DEBUG] switch_core_state_machine.c:650 (sofia/inbound/9712751300@64.125.111.10) State EXECUTE
  135. 2017-07-10 21:27:06.948913 [DEBUG] mod_sofia.c:198 sofia/inbound/9712751300@64.125.111.10 SOFIA EXECUTE
  136. 2017-07-10 21:27:06.948913 [DEBUG] switch_core_state_machine.c:328 sofia/inbound/9712751300@64.125.111.10 Standard EXECUTE
  137. EXECUTE sofia/inbound/9712751300@64.125.111.10 set(telnyx_uuid=8646b9cf-65b6-11e7-a6aa-02420a1f010f)
  138. 2017-07-10 21:27:06.948913 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/9712751300@64.125.111.10 [telnyx_uuid]=[8646b9cf-65b6-11e7-a6aa-02420a1f010f]
  139. EXECUTE sofia/inbound/9712751300@64.125.111.10 export(telnyx_session_uuid=8646bcd1-65b6-11e7-8f37-02420a1f010f)
  140. 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [telnyx_session_uuid]=[8646bcd1-65b6-11e7-8f37-02420a1f010f]
  141. EXECUTE sofia/inbound/9712751300@64.125.111.10 export(e164_cld=+18003799180)
  142. 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [e164_cld]=[+18003799180]
  143. EXECUTE sofia/inbound/9712751300@64.125.111.10 export(e164_cli=+19712751300)
  144. 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [e164_cli]=[+19712751300]
  145. EXECUTE sofia/inbound/9712751300@64.125.111.10 export(counterparty_a=382com)
  146. 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [counterparty_a]=[382com]
  147. EXECUTE sofia/inbound/9712751300@64.125.111.10 export(counterparty_b=telnyx)
  148. 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [counterparty_b]=[telnyx]
  149. EXECUTE sofia/inbound/9712751300@64.125.111.10 export(on_net=false)
  150. 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [on_net]=[false]
  151. EXECUTE sofia/inbound/9712751300@64.125.111.10 export(nolocal:connection_id=306330846174905419)
  152. 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [connection_id]=[306330846174905419]
  153. EXECUTE sofia/inbound/9712751300@64.125.111.10 export(nolocal:user_type=public-api)
  154. 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [user_type]=[public-api]
  155. EXECUTE sofia/inbound/9712751300@64.125.111.10 export(nolocal:user_id=127)
  156. 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [user_id]=[127]
  157. EXECUTE sofia/inbound/9712751300@64.125.111.10 export(nolocal:tags=)
  158. 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [tags]=[UNDEF]
  159. EXECUTE sofia/inbound/9712751300@64.125.111.10 export(nolocal:usage_payment_method=pay-per-minute)
  160. 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [usage_payment_method]=[pay-per-minute]
  161. EXECUTE sofia/inbound/9712751300@64.125.111.10 export(user_data={"origination": {"user_id": "127", "tn_type": "TF", "tags": [], "DID": "+18003799180", "user_type": "public-api", "connection_id": "306330846174905419", "tn": "+18003799180"}})
  162. 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [user_data]=[{"origination": {"user_id": "127", "tn_type": "TF", "tags": [], "DID": "+18003799180", "user_type": "public-api", "connection_id": "306330846174905419", "tn": "+18003799180"}}]
  163. EXECUTE sofia/inbound/9712751300@64.125.111.10 export(planned=true)
  164. 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [planned]=[true]
  165. EXECUTE sofia/inbound/9712751300@64.125.111.10 unset(sip_h_X-FS-Support)
  166. 2017-07-10 21:27:06.968912 [DEBUG] mod_dptools.c:1675 UNSET [sip_h_X-FS-Support]
  167. EXECUTE sofia/inbound/9712751300@64.125.111.10 ring_ready()
  168. 2017-07-10 21:27:06.968912 [NOTICE] mod_sofia.c:2273 Ring-Ready sofia/inbound/9712751300@64.125.111.10!
  169. send 778 bytes to udp/[10.15.7.7]:5060 at 21:27:06.969610:
  170.    ------------------------------------------------------------------------
  171.    SIP/2.0 180 Ringing
  172.    Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK11ab.8fd8cbf6d75cec349558389bb71d4c60.0
  173.    Via: SIP/2.0/UDP 64.125.111.10:5060;rport=5060;branch=z9hG4bKff4ba30d164e547a34c7adac5db6677c
  174.    Record-Route: <sip:10.15.7.7;r2=on;lr;ftag=3708710826-841185>
  175.    Record-Route: <sip:192.76.120.11;r2=on;lr;ftag=3708710826-841185>
  176.    From: <sip:9712751300@64.125.111.10;isup-oli=23>;tag=3708710826-841185
  177.    To: <sip:18003799180@192.168.250.45:5060>;tag=DpSK0jS771cjD
  178.    Call-ID: 45872803-3708710826-841179@msc1.382COM.COM
  179.    CSeq: 1 INVITE
  180.    Contact: <sip:18003799180@10.31.1.5:5070;transport=udp>
  181.    Accept: application/sdp
  182.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, NOTIFY
  183.    Supported: path, replaces
  184.    Allow-Events: talk, hold, conference, refer
  185.    Content-Length: 0
  186.    
  187.    ------------------------------------------------------------------------
  188. 2017-07-10 21:27:06.968912 [DEBUG] sofia.c:7048 Channel sofia/inbound/9712751300@64.125.111.10 entering state [early][180]
  189. 2017-07-10 21:27:06.968912 [NOTICE] mod_dptools.c:1028 Ring Ready sofia/inbound/9712751300@64.125.111.10!
  190. EXECUTE sofia/inbound/9712751300@64.125.111.10 set(call_timeout=600)
  191. 2017-07-10 21:27:06.968912 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/9712751300@64.125.111.10 [call_timeout]=[600]
  192. EXECUTE sofia/inbound/9712751300@64.125.111.10 set(continue_on_fail=false)
  193. 2017-07-10 21:27:06.968912 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/9712751300@64.125.111.10 [continue_on_fail]=[false]
  194. EXECUTE sofia/inbound/9712751300@64.125.111.10 export(sip_cid_type=pid)
  195. 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [sip_cid_type]=[pid]
  196. EXECUTE sofia/inbound/9712751300@64.125.111.10 set(sip_copy_multipart=false)
  197. 2017-07-10 21:27:06.968912 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/9712751300@64.125.111.10 [sip_copy_multipart]=[false]
  198. EXECUTE sofia/inbound/9712751300@64.125.111.10 bridge({local_var_clobber=true,originate_continue_on_timeout=true,sip_invite_domain=sip.telnyx.com,origination_caller_id_number=19712751300}[leg_timeout=300,leg_progress_timeout=5,orig_auth=ip-authentication,absolute_codec_string=^^:G722:PCMU:PCMA:G729:OPUS,sip_execute_on_image='t38_gateway self nocng',fax_enable_t38=true,sip_h_X-USE-UDP=1,ip_port=54.165.139.136:5061,sip_h_X-KIBP=10.15.7.7,telnyx_uuid=864a5a7a-65b6-11e7-8c94-02420a1f010f]sofia/priv-external-compact/222218003799180@54.165.139.136:5061;fs_path=sip%3A10.15.7.7%3A5060%3Btransport%3DUDP)
  199. 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [telnyx_session_uuid]=[8646bcd1-65b6-11e7-8f37-02420a1f010f] to event
  200. 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [e164_cld]=[+18003799180] to event
  201. 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [e164_cli]=[+19712751300] to event
  202. 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [counterparty_a]=[382com] to event
  203. 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [counterparty_b]=[telnyx] to event
  204. 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [on_net]=[false] to event
  205. 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [connection_id]=[306330846174905419] to event
  206. 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [user_type]=[public-api] to event
  207. 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [user_id]=[127] to event
  208. 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [usage_payment_method]=[pay-per-minute] to event
  209. 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [user_data]=[{"origination": {"user_id": "127", "tn_type": "TF", "tags": [], "DID": "+18003799180", "user_type": "public-api", "connection_id": "306330846174905419", "tn": "+18003799180"}}] to event
  210. 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [planned]=[true] to event
  211. 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [sip_cid_type]=[pid] to event
  212. 2017-07-10 21:27:06.968912 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
  213. 2017-07-10 21:27:06.968912 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables
  214. 2017-07-10 21:27:06.968912 [NOTICE] switch_channel.c:1104 New Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 [79a7fdc3-c238-4fad-b6be-0cd418866fca]
  215. 2017-07-10 21:27:06.968912 [DEBUG] mod_sofia.c:4819 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State Change CS_NEW -> CS_INIT
  216. 2017-07-10 21:27:06.968912 [DEBUG] switch_ivr_originate.c:2963 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Setting leg timeout to 300
  217. 2017-07-10 21:27:06.968912 [DEBUG] switch_ivr_originate.c:2972 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Setting leg progress timeout to 5
  218. 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:584 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Running State Change CS_INIT (Cur 2 Tot 30)
  219. 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:627 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State INIT
  220. 2017-07-10 21:27:06.968912 [DEBUG] mod_sofia.c:90 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 SOFIA INIT
  221. 2017-07-10 21:27:06.968912 [DEBUG] sofia_glue.c:1264 sip:10.15.7.7:5060;transport=UDP Setting proxy route to sofia/priv-external-compact/222218003799180@54.165.139.136:5061
  222. 2017-07-10 21:27:06.968912 [DEBUG] sofia_glue.c:1295 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 sending invite version: 1.6.18 git 3da0ad0 2017-06-28 17:17:04Z 64bit
  223. Local SDP:
  224. v=0
  225. o=Telnyx 1499696646 1499696647 IN IP4 64.16.249.20
  226. s=Telnyx
  227. c=IN IP4 64.16.249.20
  228. t=0 0
  229. m=audio 25380 RTP/AVP 9 0 8 18 102 101 103
  230. a=rtpmap:9 G722/8000
  231. a=rtpmap:0 PCMU/8000
  232. a=rtpmap:8 PCMA/8000
  233. a=rtpmap:18 G729/8000
  234. a=rtpmap:102 opus/48000/2
  235. a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40
  236. a=rtpmap:101 telephone-event/8000
  237. a=fmtp:101 0-16
  238. a=rtpmap:103 telephone-event/48000
  239. a=fmtp:103 0-16
  240. a=rtcp-mux
  241. a=rtcp:25380 IN IP4 64.16.249.20
  242. a=fmtp:18 annexb=no
  243. a=ptime:20
  244. a=sendrecv
  245.  
  246. 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:40 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Standard INIT
  247. 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:48 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State Change CS_INIT -> CS_ROUTING
  248. 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:627 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State INIT going to sleep
  249. 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:584 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Running State Change CS_ROUTING (Cur 2 Tot 30)
  250. 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:643 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State ROUTING
  251. 2017-07-10 21:27:06.968912 [DEBUG] mod_sofia.c:143 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 SOFIA ROUTING
  252. 2017-07-10 21:27:06.968912 [DEBUG] switch_ivr_originate.c:67 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State Change CS_ROUTING -> CS_CONSUME_MEDIA
  253. 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:643 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State ROUTING going to sleep
  254. 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:584 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 30)
  255. send 1224 bytes to udp/[10.15.7.7]:5060 at 21:27:06.973842:
  256.    ------------------------------------------------------------------------
  257.    INVITE sip:222218003799180@54.165.139.136:5061 SIP/2.0
  258.    v:SIP/2.0/UDP 10.31.1.5:5082;rport;branch=z9hG4bKD9aQ57eB0XZ9c
  259.    Route:<sip:10.15.7.7:5060>;transport=UDP
  260.    Max-Forwards:66
  261.    f:"9712751300"<sip:19712751300@sip.telnyx.com>;tag=K8ptv8N0N6gvD
  262.    t:<sip:222218003799180@54.165.139.136:5061>
  263.    i:5dab431b-e059-1235-0baf-02420a1f0105
  264.    CSeq:109524949 INVITE
  265.    m:<sip:mod_sofia@10.31.1.5:5082>
  266.   Allow:INVITE,ACK,BYE,CANCEL,OPTIONS,MESSAGE,INFO,UPDATE,NOTIFY
  267.    k:timer,path,replaces
  268.    u:talk,hold,conference,refer
  269.    Privacy:none
  270. 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:662 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State CONSUME_MEDIA
  271.    c:application/sdp
  272. 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:662 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State CONSUME_MEDIA going to sleep
  273.    Content-Disposition:session
  274.    l:552
  275.    X-USE-UDP:1
  276.    X-KIBP:10.15.7.7
  277.    P-Asserted-Identity:"9712751300"<sip:19712751300@sip.telnyx.com>
  278.    
  279.    v=0
  280.    o=Telnyx 1499696646 1499696647 IN IP4 64.16.249.20
  281.    s=Telnyx
  282.    c=IN IP4 64.16.249.20
  283.    t=0 0
  284.    m=audio 25380 RTP/AVP 9 0 8 18 102 101 103
  285.    a=rtpmap:9 G722/8000
  286.    a=rtpmap:0 PCMU/8000
  287.    a=rtpmap:8 PCMA/8000
  288.    a=rtpmap:18 G729/8000
  289.    a=fmtp:18 annexb=no
  290.    a=rtpmap:102 opus/48000/2
  291.    a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40
  292.    a=rtpmap:101 telephone-event/8000
  293.    a=fmtp:101 0-16
  294.    a=rtpmap:103 telephone-event/48000
  295.    a=fmtp:103 0-16
  296.    a=rtcp-mux
  297.    a=rtcp:25380 IN IP4 64.16.249.20
  298.    a=ptime:20
  299.    ------------------------------------------------------------------------
  300. 2017-07-10 21:27:06.968912 [DEBUG] sofia.c:7048 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 entering state [calling][0]
  301. recv 351 bytes from udp/[10.15.7.7]:5060 at 21:27:07.128010:
  302.    ------------------------------------------------------------------------
  303.    SIP/2.0 100 Telnyx trying
  304.    v:SIP/2.0/UDP 10.31.1.5:5082;rport=5082;branch=z9hG4bKD9aQ57eB0XZ9c;received=10.31.1.5
  305.    f:"9712751300"<sip:19712751300@sip.telnyx.com>;tag=K8ptv8N0N6gvD
  306.    t:<sip:222218003799180@54.165.139.136:5061>
  307.    i:5dab431b-e059-1235-0baf-02420a1f0105
  308.    CSeq:109524949 INVITE
  309.    Server: kamailio (4.4.5 (x86_64/linux))
  310.    Content-Length: 0
  311.    
  312.    ------------------------------------------------------------------------
  313. recv 1135 bytes from udp/[10.15.7.7]:5060 at 21:27:07.200444:
  314.    ------------------------------------------------------------------------
  315.    SIP/2.0 200 OK
  316.    Via: SIP/2.0/UDP 10.31.1.5:5082;received=10.31.1.5;rport=5082;branch=z9hG4bKD9aQ57eB0XZ9c
  317.    Record-Route: <sip:192.76.120.11;r2=on;lr;ftag=K8ptv8N0N6gvD>
  318.    Record-Route: <sip:10.15.7.7;r2=on;lr;ftag=K8ptv8N0N6gvD>
  319.    From: "9712751300"<sip:19712751300@sip.telnyx.com>;tag=K8ptv8N0N6gvD
  320.    To: <sip:222218003799180@54.165.139.136:5061>;tag=as1c8c2222
  321.    Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105
  322.    CSeq: 109524949 INVITE
  323.    Server: Asterisk PBX 13.16.0
  324.   Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
  325.    Supported: replaces, timer
  326.    Session-Expires: 1800;refresher=uas
  327.    Contact: <sip:222218003799180@54.165.139.136:5061>
  328.    Content-Type: application/sdp
  329.    Require: timer
  330.    Content-Length: 394
  331.    
  332.    v=0
  333.    o=root 209604850 209604850 IN IP4 54.165.139.136
  334.    s=Asterisk PBX 13.16.0
  335.    c=IN IP4 54.165.139.136
  336.    t=0 0
  337.    m=audio 17476 RTP/AVP 18 9 8 0 102 101
  338.    a=rtpmap:18 G729/8000
  339.    a=rtpmap:9 G722/8000
  340.    a=rtpmap:8 PCMA/8000
  341.    a=rtpmap:0 PCMU/8000
  342.    a=rtpmap:102 opus/48000/2
  343.    a=fmtp:102 maxaveragebitrate=30000
  344.    a=rtpmap:101 telephone-event/8000
  345.    a=fmtp:101 0-16
  346.    a=ptime:20
  347.    a=maxptime:20
  348.    a=sendrecv
  349.    ------------------------------------------------------------------------
  350. 2017-07-10 21:27:07.188913 [DEBUG] sofia.c:7048 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 entering state [completing][200]
  351. 2017-07-10 21:27:07.188913 [DEBUG] sofia.c:7058 Remote SDP:
  352. v=0
  353. o=root 209604850 209604850 IN IP4 54.165.139.136
  354. s=Asterisk PBX 13.16.0
  355. c=IN IP4 54.165.139.136
  356. t=0 0
  357. m=audio 17476 RTP/AVP 18 9 8 0 102 101
  358. a=rtpmap:18 G729/8000
  359. a=rtpmap:9 G722/8000
  360. a=rtpmap:8 PCMA/8000
  361. a=rtpmap:0 PCMU/8000
  362. a=rtpmap:102 opus/48000/2
  363. a=fmtp:102 maxaveragebitrate=30000
  364. a=rtpmap:101 telephone-event/8000
  365. a=fmtp:101 0-16
  366. a=ptime:20
  367. a=maxptime:20
  368.  
  369. send 460 bytes to udp/[10.15.7.7]:5060 at 21:27:07.201367:
  370.    ------------------------------------------------------------------------
  371.    ACK sip:222218003799180@54.165.139.136:5061 SIP/2.0
  372.    v:SIP/2.0/UDP 10.31.1.5:5082;rport;branch=z9hG4bKej4F72ZeX6Nvr
  373.    Route:<sip:10.15.7.7;r2=on;lr;ftag=K8ptv8N0N6gvD>,<sip:192.76.120.11;r2=on;lr;ftag=K8ptv8N0N6gvD>
  374.    Max-Forwards:70
  375.    f:"9712751300"<sip:19712751300@sip.telnyx.com>;tag=K8ptv8N0N6gvD
  376.    t:<sip:222218003799180@54.165.139.136:5061>;tag=as1c8c2222
  377.    i:5dab431b-e059-1235-0baf-02420a1f0105
  378.    CSeq:109524949 ACK
  379.    m:<sip:mod_sofia@10.31.1.5:5082>
  380.    l:0
  381.    
  382.    ------------------------------------------------------------------------
  383. 2017-07-10 21:27:07.188913 [DEBUG] sofia.c:7048 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 entering state [ready][200]
  384. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
  385. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
  386. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
  387. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1]
  388. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match
  389. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1]
  390. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  391. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
  392. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  393. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  394. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G722:9:8000:20:64000:1]/[G729:18:8000:20:8000:1]
  395. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1]
  396. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  397. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  398. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  399. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
  400. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1]
  401. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
  402. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  403. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  404. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
  405. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  406. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G729:18:8000:20:8000:1]
  407. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
  408. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [opus:102:48000:20:0:1]/[G722:9:8000:20:64000:1]
  409. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [opus:102:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
  410. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [opus:102:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
  411. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [opus:102:48000:20:0:1]/[G729:18:8000:20:8000:1]
  412. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:1]
  413. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
  414. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4361 Set telephone-event payload to 101@8000
  415. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:3057 Set Codec sofia/priv-external-compact/222218003799180@54.165.139.136:5061 G729/8000 20 ms 160 samples 8000 bits 1 channels
  416. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_codec.c:111 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Original read codec set to G729:18
  417. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4704 Set telephone-event payload to 101@8000
  418. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4763 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Set 2833 dtmf send payload to 101 recv payload to 101
  419. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:6874 AUDIO RTP [sofia/priv-external-compact/222218003799180@54.165.139.136:5061] 64.16.249.20 port 25380 -> 54.165.139.136 port 17476 codec: 18 ms: 20
  420. 2017-07-10 21:27:07.188913 [DEBUG] switch_rtp.c:4112 Starting timer [soft] 160 bytes per 20ms
  421. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:7094 Activating RTCP PORT 0
  422. 2017-07-10 21:27:07.188913 [DEBUG] switch_rtp.c:4508 RTCP send rate is: 10000 and packet rate is: 20000 Remote Port: 17477
  423. 2017-07-10 21:27:07.188913 [DEBUG] switch_rtp.c:2568 Setting RTCP remote addr to 54.165.139.136:17477 2
  424. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:7175 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Set 2833 dtmf send payload to 101
  425. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:7182 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Set 2833 dtmf receive payload to 101
  426. 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:7205 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Set rtp dtmf delay to 40
  427. 2017-07-10 21:27:07.188913 [NOTICE] sofia.c:8182 Channel [sofia/priv-external-compact/222218003799180@54.165.139.136:5061] has been answered
  428. 2017-07-10 21:27:07.188913 [DEBUG] switch_channel.c:3773 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Callstate Change DOWN -> ACTIVE
  429. 2017-07-10 21:27:07.208941 [DEBUG] switch_core_media.c:6874 AUDIO RTP [sofia/inbound/9712751300@64.125.111.10] 64.16.249.20 port 30698 -> 69.87.154.208 port 17262 codec: 0 ms: 20
  430. 2017-07-10 21:27:07.208941 [DEBUG] switch_rtp.c:4112 Starting timer [soft] 160 bytes per 20ms
  431. 2017-07-10 21:27:07.208941 [DEBUG] switch_core_media.c:7094 Activating RTCP PORT 0
  432. 2017-07-10 21:27:07.208941 [DEBUG] switch_rtp.c:4508 RTCP send rate is: 10000 and packet rate is: 20000 Remote Port: 17263
  433. 2017-07-10 21:27:07.208941 [DEBUG] switch_rtp.c:2568 Setting RTCP remote addr to 69.87.154.208:17263 2
  434. 2017-07-10 21:27:07.208941 [DEBUG] switch_core_media.c:7175 sofia/inbound/9712751300@64.125.111.10 Set 2833 dtmf send payload to 101
  435. 2017-07-10 21:27:07.208941 [DEBUG] switch_core_media.c:7182 sofia/inbound/9712751300@64.125.111.10 Set 2833 dtmf receive payload to 101
  436. 2017-07-10 21:27:07.208941 [DEBUG] switch_core_media.c:7205 sofia/inbound/9712751300@64.125.111.10 Set rtp dtmf delay to 40
  437. 2017-07-10 21:27:07.208941 [DEBUG] mod_sofia.c:850 Local SDP sofia/inbound/9712751300@64.125.111.10:
  438. v=0
  439. o=FreeSWITCH 1499691329 1499691330 IN IP4 64.16.249.20
  440. s=FreeSWITCH
  441. c=IN IP4 64.16.249.20
  442. t=0 0
  443. m=audio 30698 RTP/AVP 0 101
  444. a=rtpmap:0 PCMU/8000
  445. a=rtpmap:101 telephone-event/8000
  446. a=fmtp:101 0-16
  447. a=fmtp:18 annexb=no
  448. a=ptime:20
  449. a=sendrecv
  450. a=rtcp:30699 IN IP4 64.16.249.20
  451.  
  452. 2017-07-10 21:27:07.208941 [NOTICE] switch_ivr_originate.c:3647 Channel [sofia/inbound/9712751300@64.125.111.10] has been answered
  453. send 1065 bytes to udp/[10.15.7.7]:5060 at 21:27:07.216217:
  454.    ------------------------------------------------------------------------
  455.    SIP/2.0 200 OK
  456.    Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK11ab.8fd8cbf6d75cec349558389bb71d4c60.0
  457.    Via: SIP/2.0/UDP 64.125.111.10:5060;rport=5060;branch=z9hG4bKff4ba30d164e547a34c7adac5db6677c
  458.    Record-Route: <sip:10.15.7.7;r2=on;lr;ftag=3708710826-841185>
  459.    Record-Route: <sip:192.76.120.11;r2=on;lr;ftag=3708710826-841185>
  460.    From: <sip:9712751300@64.125.111.10;isup-oli=23>;tag=3708710826-841185
  461.    To: <sip:18003799180@192.168.250.45:5060>;tag=DpSK0jS771cjD
  462.    Call-ID: 45872803-3708710826-841179@msc1.382COM.COM
  463.    CSeq: 1 INVITE
  464.    Contact: <sip:18003799180@10.31.1.5:5070;transport=udp>
  465.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, NOTIFY
  466.    Supported: path, replaces
  467.    Allow-Events: talk, hold, conference, refer
  468.    Content-Type: application/sdp
  469.    Content-Disposition: session
  470.    Content-Length: 254
  471.    
  472.    v=0
  473.    o=FreeSWITCH 1499691329 1499691330 IN IP4 64.16.249.20
  474.    s=FreeSWITCH
  475.    c=IN IP4 64.16.249.20
  476.    t=0 0
  477.    m=audio 30698 RTP/AVP 0 101
  478.    a=rtpmap:0 PCMU/8000
  479.    a=rtpmap:101 telephone-event/8000
  480.    a=fmtp:101 0-16
  481.    a=ptime:20
  482.    a=rtcp:30699 IN IP4 64.16.249.20
  483.    ------------------------------------------------------------------------
  484. 2017-07-10 21:27:07.208941 [DEBUG] switch_channel.c:3773 (sofia/inbound/9712751300@64.125.111.10) Callstate Change RINGING -> ACTIVE
  485. 2017-07-10 21:27:07.208941 [DEBUG] sofia.c:7048 Channel sofia/inbound/9712751300@64.125.111.10 entering state [completed][200]
  486. 2017-07-10 21:27:07.208941 [DEBUG] switch_ivr_originate.c:3705 Originate Resulted in Success: [sofia/priv-external-compact/222218003799180@54.165.139.136:5061]
  487. 2017-07-10 21:27:07.208941 [DEBUG] switch_ivr_bridge.c:1614 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
  488. 2017-07-10 21:27:07.208941 [DEBUG] switch_core_state_machine.c:584 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 30)
  489. 2017-07-10 21:27:07.208941 [DEBUG] switch_core_state_machine.c:653 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State EXCHANGE_MEDIA
  490. 2017-07-10 21:27:07.208941 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA
  491. recv 653 bytes from udp/[10.15.7.7]:5060 at 21:27:07.504009:
  492.    ------------------------------------------------------------------------
  493.    ACK sip:18003799180@10.31.1.5:5070 SIP/2.0
  494.    Max-Forwards: 67
  495.    To: <sip:18003799180@192.168.250.45:5060>;tag=DpSK0jS771cjD
  496.    From: <sip:9712751300@64.125.111.10;isup-oli=23>;tag=3708710826-841185
  497.    Call-ID: 45872803-3708710826-841179@msc1.382COM.COM
  498.    CSeq: 1 ACK
  499.   Allow: CANCEL, ACK, INVITE, BYE, OPTIONS, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE, MESSAGE, PUBLISH
  500.    Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK11ab.3f3d30898355e8148c15f6dcf09d5b7a.0
  501.    Via: SIP/2.0/UDP 64.125.111.10:5060;rport=5060;branch=z9hG4bK617eeab2961a3b98cdb2e083812a0f07
  502.    Contact: <sip:9712751300@64.125.111.10:5060>
  503.    Allow-Events: telephone-event
  504.    Content-Length: 0
  505.    
  506.    ------------------------------------------------------------------------
  507. 2017-07-10 21:27:07.508949 [DEBUG] sofia.c:7048 Channel sofia/inbound/9712751300@64.125.111.10 entering state [ready][200]
  508. 2017-07-10 21:27:07.668947 [DEBUG] switch_rtp.c:1888 rtcp_stats_init: audio ssrc[139244306] base_seq[13517]
  509. 2017-07-10 21:27:07.688950 [DEBUG] switch_rtp.c:7272 Correct audio ip/port confirmed.
  510. 2017-07-10 21:27:07.688950 [DEBUG] switch_rtp.c:7272 Correct audio ip/port confirmed.
  511. 2017-07-10 21:27:07.708913 [DEBUG] switch_rtp.c:1888 rtcp_stats_init: audio ssrc[368286416] base_seq[44715]
  512. 2017-07-10 21:27:08.748952 [DEBUG] switch_rtp.c:6722 Correct audio RTCP ip/port confirmed.
  513. recv 1021 bytes from udp/[10.15.7.7]:5060 at 21:27:10.701903:
  514.    ------------------------------------------------------------------------
  515.    INVITE sip:mod_sofia@10.31.1.5:5082 SIP/2.0
  516.    Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK3171.72f7c3785f532d4e1676884afe18e88f.0
  517.    Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK42e59504;rport=5061
  518.    Max-Forwards: 69
  519.    From: <sip:222218003799180@54.165.139.136:5061>;tag=as1c8c2222
  520.    To: "9712751300"<sip:19712751300@sip.telnyx.com>;tag=K8ptv8N0N6gvD
  521.    Contact: <sip:222218003799180@54.165.139.136:5061>
  522.    Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105
  523.    CSeq: 102 INVITE
  524.    User-Agent: Asterisk PBX 13.16.0
  525.    Session-Expires: 1800;refresher=uac
  526.    Min-SE: 90
  527.   Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
  528.    Supported: replaces, timer
  529.    Content-Type: application/sdp
  530.    Content-Length: 274
  531.    
  532.    v=0
  533.    o=root 209604850 209604851 IN IP4 54.165.139.136
  534.    s=Asterisk PBX 13.16.0
  535.    c=IN IP4 54.165.139.136
  536.    t=0 0
  537.    m=image 4827 udptl t38
  538.    a=T38FaxVersion:0
  539.    a=T38MaxBitRate:14400
  540.    a=T38FaxRateManagement:transferredTCF
  541.    a=T38FaxMaxDatagram:1400
  542.    a=T38FaxUdpEC:t38UDPRedundancy
  543.    ------------------------------------------------------------------------
  544. send 402 bytes to udp/[10.15.7.7]:5060 at 21:27:10.702244:
  545.    ------------------------------------------------------------------------
  546.    SIP/2.0 100 Trying
  547.    Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK3171.72f7c3785f532d4e1676884afe18e88f.0
  548.    Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK42e59504;rport=5061
  549.    From: <sip:222218003799180@54.165.139.136:5061>;tag=as1c8c2222
  550.    To: "9712751300"<sip:19712751300@sip.telnyx.com>;tag=K8ptv8N0N6gvD
  551.    Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105
  552.    CSeq: 102 INVITE
  553.    l:0
  554.    
  555.    ------------------------------------------------------------------------
  556. 2017-07-10 21:27:10.708921 [DEBUG] sofia.c:7048 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 entering state [received][100]
  557. 2017-07-10 21:27:10.708921 [DEBUG] sofia.c:7058 Remote SDP:
  558. v=0
  559. o=root 209604850 209604851 IN IP4 54.165.139.136
  560. s=Asterisk PBX 13.16.0
  561. c=IN IP4 54.165.139.136
  562. t=0 0
  563. m=image 4827 udptl t38
  564. a=T38FaxVersion:0
  565. a=T38MaxBitRate:14400
  566. a=T38FaxRateManagement:transferredTCF
  567. a=T38FaxMaxDatagram:1400
  568. a=T38FaxUdpEC:t38UDPRedundancy
  569.  
  570. EXECUTE sofia/priv-external-compact/222218003799180@54.165.139.136:5061 t38_gateway(self nocng)
  571. 2017-07-10 21:27:10.708921 [DEBUG] mod_spandsp_fax.c:2080 sofia/inbound/9712751300@64.125.111.10 starting gateway mode to sofia/priv-external-compact/222218003799180@54.165.139.136:5061
  572. 2017-07-10 21:27:10.708921 [DEBUG] mod_spandsp_fax.c:2098 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State Change CS_EXCHANGE_MEDIA -> CS_RESET
  573. 2017-07-10 21:27:10.708921 [DEBUG] mod_spandsp_fax.c:2101 (sofia/inbound/9712751300@64.125.111.10) State Change CS_EXECUTE -> CS_RESET
  574. 2017-07-10 21:27:10.708921 [DEBUG] switch_core_media.c:4037 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 T38 ACCEPT on request
  575. 2017-07-10 21:27:10.708921 [DEBUG] switch_core_media.c:4142 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 T38 IS POSSIBLE on request
  576. 2017-07-10 21:27:10.728914 [DEBUG] switch_ivr_bridge.c:706 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 ending bridge by request from write function
  577. 2017-07-10 21:27:10.728914 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/inbound/9712751300@64.125.111.10]
  578. 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:650 (sofia/inbound/9712751300@64.125.111.10) State EXECUTE going to sleep
  579. 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/9712751300@64.125.111.10) Running State Change CS_RESET (Cur 2 Tot 30)
  580. 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:646 (sofia/inbound/9712751300@64.125.111.10) State RESET
  581. 2017-07-10 21:27:10.728914 [DEBUG] mod_sofia.c:161 sofia/inbound/9712751300@64.125.111.10 SOFIA RESET
  582. 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:2040 (sofia/inbound/9712751300@64.125.111.10) State Change CS_RESET -> CS_CONSUME_MEDIA
  583. 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:646 (sofia/inbound/9712751300@64.125.111.10) State RESET going to sleep
  584. 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/9712751300@64.125.111.10) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 30)
  585. 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:662 (sofia/inbound/9712751300@64.125.111.10) State CONSUME_MEDIA
  586. 2017-07-10 21:27:10.728914 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/priv-external-compact/222218003799180@54.165.139.136:5061]
  587. 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:653 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State EXCHANGE_MEDIA going to sleep
  588. 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:584 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Running State Change CS_RESET (Cur 2 Tot 30)
  589. 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:646 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State RESET
  590. 2017-07-10 21:27:10.728914 [DEBUG] mod_sofia.c:161 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 SOFIA RESET
  591. 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:2042 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State Change CS_RESET -> CS_SOFT_EXECUTE
  592. 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:646 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State RESET going to sleep
  593. 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:584 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Running State Change CS_SOFT_EXECUTE (Cur 2 Tot 30)
  594. 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:656 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State SOFT_EXECUTE
  595. 2017-07-10 21:27:10.728914 [DEBUG] mod_sofia.c:637 SOFIA SOFT_EXECUTE
  596. 2017-07-10 21:27:10.728914 [WARNING] mod_spandsp_fax.c:1138 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 already has T.38 data
  597. 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1040 T38 SDP Origin = root
  598. 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1041 T38FaxVersion = 0
  599. 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1042 T38MaxBitRate = 14400
  600. 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1043 T38FaxFillBitRemoval = 0
  601. 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1044 T38FaxTranscodingMMR = 0
  602. 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1045 T38FaxTranscodingJBIG = 0
  603. 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1046 T38FaxRateManagement = 'transferredTCF'
  604. 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1047 T38FaxMaxBuffer = 500
  605. 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1048 T38FaxMaxDatagram = 1400
  606. 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1049 T38FaxUdpEC = 't38UDPRedundancy'
  607. 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1050 T38VendorInfo = ''
  608. 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1051 ip = '54.165.139.136'
  609. 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1053 port = 4827
  610. 2017-07-10 21:27:10.728914 [DEBUG] switch_core_media.c:9755 IMAGE UDPTL CHANGING DEST TO: [54.165.139.136:4827]
  611. 2017-07-10 21:27:10.728914 [DEBUG] switch_core_media.c:9385 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 image media sdp:
  612. v=0
  613. o=Telnyx 1499696646 1499696648 IN IP4 64.16.249.20
  614. s=Telnyx
  615. c=IN IP4 64.16.249.20
  616. t=0 0
  617. m=image 25380 udptl t38
  618. a=T38FaxVersion:0
  619. a=T38MaxBitRate:14400
  620. a=T38FaxRateManagement:transferredTCF
  621. a=T38FaxMaxBuffer:500
  622. a=T38FaxMaxDatagram:400
  623. a=T38FaxUdpEC:t38UDPRedundancy
  624.  
  625. 2017-07-10 21:27:10.728914 [DEBUG] switch_core_media.c:9746 Remote address:port [54.165.139.136:4827] has not changed.
  626. send 913 bytes to udp/[10.15.7.7]:5060 at 21:27:10.744303:
  627.    ------------------------------------------------------------------------
  628.    SIP/2.0 200 OK
  629.    Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK3171.72f7c3785f532d4e1676884afe18e88f.0
  630.    Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK42e59504;rport=5061
  631.    From: <sip:222218003799180@54.165.139.136:5061>;tag=as1c8c2222
  632.    To: "9712751300"<sip:19712751300@sip.telnyx.com>;tag=K8ptv8N0N6gvD
  633.    Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105
  634.    CSeq: 102 INVITE
  635.    m:<sip:mod_sofia@10.31.1.5:5082>
  636.    Accept:application/sdp
  637.   Allow:INVITE,ACK,BYE,CANCEL,OPTIONS,MESSAGE,INFO,UPDATE,NOTIFY
  638.    Require:timer
  639.    k:timer,path,replaces
  640.    x:1800;refresher=uac
  641.    c:application/sdp
  642.    Content-Disposition:session
  643.    l:283
  644.    
  645.    v=0
  646.    o=Telnyx 1499696646 1499696648 IN IP4 64.16.249.20
  647.    s=Telnyx
  648.    c=IN IP4 64.16.249.20
  649.    t=0 0
  650.    m=image 25380 udptl t38
  651.    a=T38FaxVersion:0
  652.    a=T38MaxBitRate:14400
  653.    a=T38FaxRateManagement:transferredTCF
  654.    a=T38FaxMaxBuffer:500
  655.    a=T38FaxMaxDatagram:400
  656.    a=T38FaxUdpEC:t38UDPRedundancy
  657.    ------------------------------------------------------------------------
  658. 2017-07-10 21:27:10.728914 [DEBUG] sofia.c:7048 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 entering state [completed][200]
  659. 2017-07-10 21:27:10.748914 [DEBUG] mod_spandsp_fax.c:1886 Raw read codec activation Success L16 20000
  660. 2017-07-10 21:27:10.748914 [DEBUG] switch_core_codec.c:223 sofia/inbound/9712751300@64.125.111.10 Push codec L16:100
  661. 2017-07-10 21:27:10.748914 [DEBUG] mod_spandsp_fax.c:1903 Raw write codec activation Success L16
  662. 2017-07-10 21:27:10.908951 [DEBUG] switch_rtp.c:7272 Correct audio ip/port confirmed.
  663. recv 539 bytes from udp/[10.15.7.7]:5060 at 21:27:10.968706:
  664.    ------------------------------------------------------------------------
  665.    ACK sip:mod_sofia@10.31.1.5:5082 SIP/2.0
  666.    Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK3171.24f09dce17b0209fb1f79f3b1c212d86.0
  667.    Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK7359fa10;rport=5061
  668.    Max-Forwards: 69
  669.    From: <sip:222218003799180@54.165.139.136:5061>;tag=as1c8c2222
  670.    To: "9712751300"<sip:19712751300@sip.telnyx.com>;tag=K8ptv8N0N6gvD
  671.    Contact: <sip:222218003799180@54.165.139.136:5061>
  672.    Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105
  673.    CSeq: 102 ACK
  674.    User-Agent: Asterisk PBX 13.16.0
  675.    Content-Length: 0
  676.    
  677.    ------------------------------------------------------------------------
  678. 2017-07-10 21:27:10.968952 [DEBUG] sofia.c:7048 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 entering state [ready][200]
  679. recv 1212 bytes from udp/[10.15.7.7]:5060 at 21:27:18.189771:
  680.    ------------------------------------------------------------------------
  681.    INVITE sip:18003799180@10.31.1.5:5070 SIP/2.0
  682.    Max-Forwards: 67
  683.    Session-Expires: 7200;refresher=uas
  684.    Min-SE: 1800
  685.    Supported: timer, 100rel
  686.    To: <sip:18003799180@192.168.250.45:5060>;tag=DpSK0jS771cjD
  687.    From: <sip:9712751300@64.125.111.10;isup-oli=23>;tag=3708710826-841185
  688.    P-Asserted-Identity: <sip:9712751300@69.87.154.208>
  689.    Call-ID: 45872803-3708710826-841179@msc1.382COM.COM
  690.    CSeq: 2 INVITE
  691.   Allow: CANCEL, ACK, INVITE, BYE, OPTIONS, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE, MESSAGE, PUBLISH
  692.    Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bKe0ab.5beba73224a631d3b2129355986b58d2.0
  693.    Via: SIP/2.0/UDP 64.125.111.10:5060;rport=5060;branch=z9hG4bK89e5399d5dc0785adf1c92fe13857f4b
  694.    Contact: <sip:9712751300@64.125.111.10:5060>
  695.    Expires: 180
  696.    Allow-Events: telephone-event
  697.    Content-Type: application/sdp
  698.    Accept: application/sdp
  699.    Content-Length: 351
  700.    
  701.    v=0
  702.    o=msc1 1018 687 IN IP4 64.125.111.10
  703.    s=sip call
  704.    c=IN IP4 69.87.154.208
  705.    t=0 0
  706.    m=image 17262 udptl t38
  707.    a=T38FaxVersion:0
  708.    a=T38MaxBitRate:14400
  709.    a=T38FaxFillBitRemoval:0
  710.    a=T38FaxTranscodingMMR:0
  711.    a=T38FaxTranscodingJBIG:0
  712.    a=T38FaxRateManagement:transferredTCF
  713.    a=T38FaxMaxBuffer:200
  714.    a=T38FaxMaxDatagram:320
  715.    a=T38FaxUdpEC:t38UDPRedundancy
  716.    ------------------------------------------------------------------------
  717. send 420 bytes to udp/[10.15.7.7]:5060 at 21:27:18.190175:
  718.    ------------------------------------------------------------------------
  719.    SIP/2.0 100 Trying
  720.    Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bKe0ab.5beba73224a631d3b2129355986b58d2.0
  721.    Via: SIP/2.0/UDP 64.125.111.10:5060;rport=5060;branch=z9hG4bK89e5399d5dc0785adf1c92fe13857f4b
  722.    From: <sip:9712751300@64.125.111.10;isup-oli=23>;tag=3708710826-841185
  723.    To: <sip:18003799180@192.168.250.45:5060>;tag=DpSK0jS771cjD
  724.    Call-ID: 45872803-3708710826-841179@msc1.382COM.COM
  725.    CSeq: 2 INVITE
  726.    Content-Length: 0
  727.    
  728.    ------------------------------------------------------------------------
  729. 2017-07-10 21:27:18.188950 [DEBUG] sofia.c:7048 Channel sofia/inbound/9712751300@64.125.111.10 entering state [received][100]
  730. 2017-07-10 21:27:18.188950 [DEBUG] sofia.c:7058 Remote SDP:
  731. v=0
  732. o=msc1 1018 687 IN IP4 64.125.111.10
  733. s=sip call
  734. c=IN IP4 69.87.154.208
  735. t=0 0
  736. m=image 17262 udptl t38
  737. a=T38FaxVersion:0
  738. a=T38MaxBitRate:14400
  739. a=T38FaxFillBitRemoval:0
  740. a=T38FaxTranscodingMMR:0
  741. a=T38FaxTranscodingJBIG:0
  742. a=T38FaxRateManagement:transferredTCF
  743. a=T38FaxMaxBuffer:200
  744. a=T38FaxMaxDatagram:320
  745. a=T38FaxUdpEC:t38UDPRedundancy
  746.  
  747. 2017-07-10 21:27:18.188950 [DEBUG] switch_core_media.c:4024 sofia/inbound/9712751300@64.125.111.10 T38 REFUSE on request
  748. 2017-07-10 21:27:18.188950 [DEBUG] sofia.c:7971 Reinvite resulted in codec negotiation failure.
  749. send 558 bytes to udp/[10.15.7.7]:5060 at 21:27:18.196396:
  750.    ------------------------------------------------------------------------
  751.    SIP/2.0 488 Not Acceptable Here
  752.    Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bKe0ab.5beba73224a631d3b2129355986b58d2.0
  753.    Via: SIP/2.0/UDP 64.125.111.10:5060;rport=5060;branch=z9hG4bK89e5399d5dc0785adf1c92fe13857f4b
  754.    From: <sip:9712751300@64.125.111.10;isup-oli=23>;tag=3708710826-841185
  755.    To: <sip:18003799180@192.168.250.45:5060>;tag=DpSK0jS771cjD
  756.    Call-ID: 45872803-3708710826-841179@msc1.382COM.COM
  757.    CSeq: 2 INVITE
  758.    Accept: application/sdp
  759.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, NOTIFY
  760.    Supported: path, replaces
  761.    Content-Length: 0
  762.    
  763.    ------------------------------------------------------------------------
  764. 2017-07-10 21:27:18.208922 [DEBUG] sofia.c:7041 Channel sofia/inbound/9712751300@64.125.111.10 skipping state [ready][488]
  765. recv 364 bytes from udp/[10.15.7.7]:5060 at 21:27:18.350221:
  766.    ------------------------------------------------------------------------
  767.    ACK sip:18003799180@10.31.1.5:5070 SIP/2.0
  768.    Max-Forwards: 67
  769.    To: <sip:18003799180@192.168.250.45:5060>;tag=DpSK0jS771cjD
  770.    From: <sip:9712751300@64.125.111.10;isup-oli=23>;tag=3708710826-841185
  771.    Call-ID: 45872803-3708710826-841179@msc1.382COM.COM
  772.    CSeq: 2 ACK
  773.    Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bKe0ab.5beba73224a631d3b2129355986b58d2.0
  774.    Content-Length: 0
  775.    
  776.    ------------------------------------------------------------------------
  777. send 449 bytes to udp/[50.97.255.73]:5060 at 21:28:00.216831:
  778.    ------------------------------------------------------------------------
  779.    OPTIONS sip:50.97.255.73;transport=udp SIP/2.0
  780.    Via: SIP/2.0/UDP 64.16.249.20:5072;rport;branch=z9hG4bK8gZgUgpj8F4cF
  781.    Max-Forwards: 70
  782.    From: <sip:50.97.255.73>;tag=8Nr5Zg1ZXK0jH
  783.    To: <sip:50.97.255.73>
  784.    Call-ID: 7d678335-e059-1235-0baf-02420a1f0105
  785.    CSeq: 109524526 OPTIONS
  786.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, NOTIFY
  787.    Supported: timer, path, replaces
  788.    Allow-Events: talk, hold, conference, refer
  789.    Content-Length: 0
  790.    
  791.    ------------------------------------------------------------------------
  792. send 452 bytes to udp/[184.172.33.74]:5060 at 21:28:00.217054:
  793.    ------------------------------------------------------------------------
  794.    OPTIONS sip:184.172.33.74;transport=udp SIP/2.0
  795.    Via: SIP/2.0/UDP 64.16.249.20:5072;rport;branch=z9hG4bK9Sr9vB7N5rtZa
  796.    Max-Forwards: 70
  797.    From: <sip:184.172.33.74>;tag=9yHy1Bj3tvp5c
  798.    To: <sip:184.172.33.74>
  799.    Call-ID: 7d678cd0-e059-1235-0baf-02420a1f0105
  800.    CSeq: 109524527 OPTIONS
  801.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, NOTIFY
  802.    Supported: timer, path, replaces
  803.    Allow-Events: talk, hold, conference, refer
  804.    Content-Length: 0
  805.    
  806.    ------------------------------------------------------------------------
  807. recv 332 bytes from udp/[184.172.33.74]:5060 at 21:28:00.330779:
  808.    ------------------------------------------------------------------------
  809.    SIP/2.0 200 OK
  810.    Via: SIP/2.0/UDP 64.16.249.20:5072;rport=5072;branch=z9hG4bK9Sr9vB7N5rtZa
  811.    From: <sip:184.172.33.74>;tag=9yHy1Bj3tvp5c
  812.    To: <sip:184.172.33.74>;tag=61ca04ab316dd595563aff0006b39e03.cecd
  813.    Call-ID: 7d678cd0-e059-1235-0baf-02420a1f0105
  814.    CSeq: 109524527 OPTIONS
  815.    Server: Telnyx v4.5-PRODUCTION.177
  816.    Content-Length: 0
  817.    
  818.    ------------------------------------------------------------------------
  819. recv 330 bytes from udp/[50.97.255.73]:5060 at 21:28:00.361679:
  820.    ------------------------------------------------------------------------
  821.    SIP/2.0 200 OK
  822.    Via: SIP/2.0/UDP 64.16.249.20:5072;rport=5072;branch=z9hG4bK8gZgUgpj8F4cF
  823.    From: <sip:50.97.255.73>;tag=8Nr5Zg1ZXK0jH
  824.    To: <sip:50.97.255.73>;tag=8dec4f3770a90d58c5e7e223daf3aecc.bcb5
  825.    Call-ID: 7d678335-e059-1235-0baf-02420a1f0105
  826.    CSeq: 109524526 OPTIONS
  827.    Server: Telnyx v4.5-PRODUCTION.177
  828.    Content-Length: 0
  829.    
  830.    ------------------------------------------------------------------------
  831. recv 1141 bytes from udp/[10.15.7.7]:5060 at 21:28:01.348690:
  832.    ------------------------------------------------------------------------
  833.    INVITE sip:mod_sofia@10.31.1.5:5082 SIP/2.0
  834.    Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK4171.63ef3e0cc8d31370a0f485c8f5a38a9a.0
  835.    Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK7b8f90cd;rport=5061
  836.    Max-Forwards: 69
  837.    From: <sip:222218003799180@54.165.139.136:5061>;tag=as1c8c2222
  838.    To: "9712751300"<sip:19712751300@sip.telnyx.com>;tag=K8ptv8N0N6gvD
  839.    Contact: <sip:222218003799180@54.165.139.136:5061>
  840.    Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105
  841.    CSeq: 103 INVITE
  842.    User-Agent: Asterisk PBX 13.16.0
  843.    Session-Expires: 1800;refresher=uac
  844.    Min-SE: 90
  845.   Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
  846.    Supported: replaces, timer
  847.    Content-Type: application/sdp
  848.    Content-Length: 394
  849.    
  850.    v=0
  851.    o=root 209604850 209604852 IN IP4 54.165.139.136
  852.    s=Asterisk PBX 13.16.0
  853.    c=IN IP4 54.165.139.136
  854.    t=0 0
  855.    m=audio 17476 RTP/AVP 18 9 8 0 102 101
  856.    a=rtpmap:18 G729/8000
  857.    a=rtpmap:9 G722/8000
  858.    a=rtpmap:8 PCMA/8000
  859.    a=rtpmap:0 PCMU/8000
  860.    a=rtpmap:102 opus/48000/2
  861.    a=fmtp:102 maxaveragebitrate=30000
  862.    a=rtpmap:101 telephone-event/8000
  863.    a=fmtp:101 0-16
  864.    a=ptime:20
  865.    a=maxptime:20
  866.    a=sendrecv
  867.    ------------------------------------------------------------------------
  868. send 402 bytes to udp/[10.15.7.7]:5060 at 21:28:01.349057:
  869.    ------------------------------------------------------------------------
  870.    SIP/2.0 100 Trying
  871.    Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK4171.63ef3e0cc8d31370a0f485c8f5a38a9a.0
  872.    Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK7b8f90cd;rport=5061
  873.    From: <sip:222218003799180@54.165.139.136:5061>;tag=as1c8c2222
  874.    To: "9712751300"<sip:19712751300@sip.telnyx.com>;tag=K8ptv8N0N6gvD
  875.    Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105
  876.    CSeq: 103 INVITE
  877.    l:0
  878.    
  879.    ------------------------------------------------------------------------
  880. 2017-07-10 21:28:01.348956 [DEBUG] sofia.c:7048 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 entering state [received][100]
  881. 2017-07-10 21:28:01.348956 [DEBUG] sofia.c:7058 Remote SDP:
  882. v=0
  883. o=root 209604850 209604852 IN IP4 54.165.139.136
  884. s=Asterisk PBX 13.16.0
  885. c=IN IP4 54.165.139.136
  886. t=0 0
  887. m=audio 17476 RTP/AVP 18 9 8 0 102 101
  888. a=rtpmap:18 G729/8000
  889. a=rtpmap:9 G722/8000
  890. a=rtpmap:8 PCMA/8000
  891. a=rtpmap:0 PCMU/8000
  892. a=rtpmap:102 opus/48000/2
  893. a=fmtp:102 maxaveragebitrate=30000
  894. a=rtpmap:101 telephone-event/8000
  895. a=fmtp:101 0-16
  896. a=ptime:20
  897. a=maxptime:20
  898.  
  899. send 913 bytes to udp/[10.15.7.7]:5060 at 21:28:01.350772:
  900.    ------------------------------------------------------------------------
  901.    SIP/2.0 200 OK
  902.    Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK4171.63ef3e0cc8d31370a0f485c8f5a38a9a.0
  903.    Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK7b8f90cd;rport=5061
  904.    From: <sip:222218003799180@54.165.139.136:5061>;tag=as1c8c2222
  905.    To: "9712751300"<sip:19712751300@sip.telnyx.com>;tag=K8ptv8N0N6gvD
  906.    Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105
  907.    CSeq: 103 INVITE
  908.    m:<sip:mod_sofia@10.31.1.5:5082>
  909.    Accept:application/sdp
  910.   Allow:INVITE,ACK,BYE,CANCEL,OPTIONS,MESSAGE,INFO,UPDATE,NOTIFY
  911.    Require:timer
  912.    k:timer,path,replaces
  913.    x:1800;refresher=uac
  914.    c:application/sdp
  915.    Content-Disposition:session
  916.    l:283
  917.    
  918.    v=0
  919.    o=Telnyx 1499696646 1499696648 IN IP4 64.16.249.20
  920.    s=Telnyx
  921.    c=IN IP4 64.16.249.20
  922.    t=0 0
  923.    m=image 25380 udptl t38
  924.    a=T38FaxVersion:0
  925.    a=T38MaxBitRate:14400
  926.    a=T38FaxRateManagement:transferredTCF
  927.    a=T38FaxMaxBuffer:500
  928.    a=T38FaxMaxDatagram:400
  929.    a=T38FaxUdpEC:t38UDPRedundancy
  930.    ------------------------------------------------------------------------
  931. 2017-07-10 21:28:01.348956 [DEBUG] sofia.c:7048 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 entering state [completed][200]
  932. recv 539 bytes from udp/[10.15.7.7]:5060 at 21:28:01.575235:
  933.    ------------------------------------------------------------------------
  934.    ACK sip:mod_sofia@10.31.1.5:5082 SIP/2.0
  935.    Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK4171.5e38420ad3c2bd3f52d1b69cedbaf396.0
  936.    Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK24f79e47;rport=5061
  937.    Max-Forwards: 69
  938.    From: <sip:222218003799180@54.165.139.136:5061>;tag=as1c8c2222
  939.    To: "9712751300"<sip:19712751300@sip.telnyx.com>;tag=K8ptv8N0N6gvD
  940.    Contact: <sip:222218003799180@54.165.139.136:5061>
  941.    Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105
  942.    CSeq: 103 ACK
  943.    User-Agent: Asterisk PBX 13.16.0
  944.    Content-Length: 0
  945.    
  946.    ------------------------------------------------------------------------
  947. recv 560 bytes from udp/[10.15.7.7]:5060 at 21:28:01.575353:
  948.    ------------------------------------------------------------------------
  949.    BYE sip:mod_sofia@10.31.1.5:5082 SIP/2.0
  950.    Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK1171.ee969f78348ab7369993261c93571443.0
  951.    Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK18ba4499;rport=5061
  952.    Max-Forwards: 69
  953.    From: <sip:222218003799180@54.165.139.136:5061>;tag=as1c8c2222
  954.    To: "9712751300"<sip:19712751300@sip.telnyx.com>;tag=K8ptv8N0N6gvD
  955.    Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105
  956.    CSeq: 104 BYE
  957.    User-Agent: Asterisk PBX 13.16.0
  958.    X-Asterisk-HangupCause: Normal Clearing
  959.    X-Asterisk-HangupCauseCode: 16
  960.    Content-Length: 0
  961.    
  962.    ------------------------------------------------------------------------
  963. 2017-07-10 21:28:01.568955 [DEBUG] sofia.c:7048 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 entering state [ready][200]
  964. 2017-07-10 21:28:01.568955 [NOTICE] sofia.c:1012 Hangup sofia/priv-external-compact/222218003799180@54.165.139.136:5061 [CS_SOFT_EXECUTE] [NORMAL_CLEARING]
  965. 2017-07-10 21:28:01.568955 [WARNING] mod_spandsp_fax.c:1767 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Premature exit while negotiating (1)
  966. 2017-07-10 21:28:01.568955 [DEBUG] mod_spandsp_fax.c:1789 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 skip receive message [UNBRIDGE] (channel is hungup already)
  967. 2017-07-10 21:28:01.568955 [NOTICE] mod_spandsp_fax.c:1791 Hangup sofia/inbound/9712751300@64.125.111.10 [CS_CONSUME_MEDIA] [NORMAL_CLEARING]
  968. send 482 bytes to udp/[10.15.7.7]:5060 at 21:28:01.577772:
  969.    ------------------------------------------------------------------------
  970.    SIP/2.0 200 OK
  971.    Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK1171.ee969f78348ab7369993261c93571443.0
  972.    Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK18ba4499;rport=5061
  973.    From: <sip:222218003799180@54.165.139.136:5061>;tag=as1c8c2222
  974.    To: "9712751300"<sip:19712751300@sip.telnyx.com>;tag=K8ptv8N0N6gvD
  975.    Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105
  976.    CSeq: 104 BYE
  977.   Allow:INVITE,ACK,BYE,CANCEL,OPTIONS,MESSAGE,INFO,UPDATE,NOTIFY
  978.    k:timer,path,replaces
  979.    l:0
  980.    
  981.    ------------------------------------------------------------------------
  982. 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:656 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State SOFT_EXECUTE going to sleep
  983. 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:584 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Running State Change CS_HANGUP (Cur 2 Tot 30)
  984. 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:850 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Callstate Change ACTIVE -> HANGUP
  985. 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:852 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State HANGUP
  986. 2017-07-10 21:28:01.568955 [DEBUG] mod_sofia.c:438 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 hanging up, cause: NORMAL_CLEARING
  987. 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:60 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Standard HANGUP, cause: NORMAL_CLEARING
  988. 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:852 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State HANGUP going to sleep
  989. 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:619 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State Change CS_HANGUP -> CS_REPORTING
  990. 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:584 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Running State Change CS_REPORTING (Cur 2 Tot 30)
  991. 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:938 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State REPORTING
  992. 2017-07-10 21:28:01.568955 [INFO] mod_json_cdr.c:271 Process [79a7fdc3-c238-4fad-b6be-0cd418866fca.cdr.json]
  993. 2017-07-10 21:28:01.568955 [INFO] mod_json_cdr.c:275 Log to disk [/var/log/freeswitch/json_cdr/79a7fdc3-c238-4fad-b6be-0cd418866fca.cdr.json]
  994. 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:174 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Standard REPORTING, cause: NORMAL_CLEARING
  995. 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:938 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State REPORTING going to sleep
  996. 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:610 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State Change CS_REPORTING -> CS_DESTROY
  997. 2017-07-10 21:28:01.568955 [DEBUG] switch_core_session.c:1665 Session 30 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Locked, Waiting on external entities
  998. 2017-07-10 21:28:01.588947 [DEBUG] mod_spandsp_fax.c:1988 sofia/inbound/9712751300@64.125.111.10 skip receive message [UNBRIDGE] (channel is hungup already)
  999. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_codec.c:248 sofia/inbound/9712751300@64.125.111.10 Restore previous codec PCMU:0.
  1000. 2017-07-10 21:28:01.588947 [NOTICE] switch_core_session.c:1683 Session 30 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Ended
  1001. 2017-07-10 21:28:01.588947 [NOTICE] switch_core_session.c:1687 Close Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 [CS_DESTROY]
  1002. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:662 (sofia/inbound/9712751300@64.125.111.10) State CONSUME_MEDIA going to sleep
  1003. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/9712751300@64.125.111.10) Running State Change CS_HANGUP (Cur 1 Tot 30)
  1004. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:741 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Running State Change CS_DESTROY (Cur 1 Tot 30)
  1005. 2017-07-10 21:28:01.588947 [DEBUG] switch_ivr.c:217 sofia/inbound/9712751300@64.125.111.10 skip receive message [AUDIO_SYNC] (channel is hungup already)
  1006. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:850 (sofia/inbound/9712751300@64.125.111.10) Callstate Change ACTIVE -> HANGUP
  1007. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:751 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State DESTROY
  1008. 2017-07-10 21:28:01.588947 [DEBUG] mod_sofia.c:343 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 SOFIA DESTROY
  1009. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:852 (sofia/inbound/9712751300@64.125.111.10) State HANGUP
  1010. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:181 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Standard DESTROY
  1011. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:751 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State DESTROY going to sleep
  1012. 2017-07-10 21:28:01.588947 [DEBUG] mod_sofia.c:432 sofia/inbound/9712751300@64.125.111.10 Overriding SIP cause 480 with 200 from the other leg
  1013. 2017-07-10 21:28:01.588947 [DEBUG] mod_sofia.c:438 Channel sofia/inbound/9712751300@64.125.111.10 hanging up, cause: NORMAL_CLEARING
  1014. 2017-07-10 21:28:01.588947 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/inbound/9712751300@64.125.111.10
  1015. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:60 sofia/inbound/9712751300@64.125.111.10 Standard HANGUP, cause: NORMAL_CLEARING
  1016. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:852 (sofia/inbound/9712751300@64.125.111.10) State HANGUP going to sleep
  1017. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:619 (sofia/inbound/9712751300@64.125.111.10) State Change CS_HANGUP -> CS_REPORTING
  1018. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/9712751300@64.125.111.10) Running State Change CS_REPORTING (Cur 1 Tot 30)
  1019. send 623 bytes to udp/[10.15.7.7]:5060 at 21:28:01.595926:
  1020.    ------------------------------------------------------------------------
  1021.    BYE sip:9712751300@64.125.111.10:5060 SIP/2.0
  1022.    Via: SIP/2.0/UDP 10.31.1.5:5070;rport;branch=z9hG4bK0N0BF0DKZXFFQ
  1023. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:938 (sofia/inbound/9712751300@64.125.111.10) State REPORTING
  1024.    Route: <sip:10.15.7.7;r2=on;lr;ftag=3708710826-841185>
  1025.    Route: <sip:192.76.120.11;r2=on;lr;ftag=3708710826-841185>
  1026.    Max-Forwards: 70
  1027.    From: <sip:18003799180@192.168.250.45:5060>;tag=DpSK0jS771cjD
  1028.    To: <sip:9712751300@64.125.111.10;isup-oli=23>;tag=3708710826-841185
  1029.    Call-ID: 45872803-3708710826-841179@msc1.382COM.COM
  1030.    CSeq: 109524976 BYE
  1031.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, NOTIFY
  1032.    Supported: path, replaces
  1033.    Reason: Q.850;cause=16;text="NORMAL_CLEARING"
  1034.    Content-Length: 0
  1035.    
  1036.    ------------------------------------------------------------------------
  1037. 2017-07-10 21:28:01.588947 [INFO] mod_json_cdr.c:271 Process [a_2b04f60c-4eea-4516-b079-2772d3fd681f.cdr.json]
  1038. 2017-07-10 21:28:01.588947 [INFO] mod_json_cdr.c:275 Log to disk [/var/log/freeswitch/json_cdr/a_2b04f60c-4eea-4516-b079-2772d3fd681f.cdr.json]
  1039. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:174 sofia/inbound/9712751300@64.125.111.10 Standard REPORTING, cause: NORMAL_CLEARING
  1040. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:938 (sofia/inbound/9712751300@64.125.111.10) State REPORTING going to sleep
  1041. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:610 (sofia/inbound/9712751300@64.125.111.10) State Change CS_REPORTING -> CS_DESTROY
  1042. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_session.c:1665 Session 29 (sofia/inbound/9712751300@64.125.111.10) Locked, Waiting on external entities
  1043. 2017-07-10 21:28:01.588947 [NOTICE] switch_core_session.c:1683 Session 29 (sofia/inbound/9712751300@64.125.111.10) Ended
  1044. 2017-07-10 21:28:01.588947 [NOTICE] switch_core_session.c:1687 Close Channel sofia/inbound/9712751300@64.125.111.10 [CS_DESTROY]
  1045. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:741 (sofia/inbound/9712751300@64.125.111.10) Running State Change CS_DESTROY (Cur 0 Tot 30)
  1046. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:751 (sofia/inbound/9712751300@64.125.111.10) State DESTROY
  1047. 2017-07-10 21:28:01.588947 [DEBUG] mod_sofia.c:343 sofia/inbound/9712751300@64.125.111.10 SOFIA DESTROY
  1048. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:181 sofia/inbound/9712751300@64.125.111.10 Standard DESTROY
  1049. 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:751 (sofia/inbound/9712751300@64.125.111.10) State DESTROY going to sleep
  1050. recv 522 bytes from udp/[10.15.7.7]:5060 at 21:28:01.900749:
  1051.    ------------------------------------------------------------------------
  1052.    SIP/2.0 200 OK
  1053.    Via: SIP/2.0/UDP 10.31.1.5:5070;received=10.31.1.5;rport=5070;branch=z9hG4bK0N0BF0DKZXFFQ
  1054.    To: <sip:9712751300@64.125.111.10;isup-oli=23>;tag=3708710826-841185
  1055.    From: <sip:18003799180@192.168.250.45:5060>;tag=DpSK0jS771cjD
  1056.    Call-ID: 45872803-3708710826-841179@msc1.382COM.COM
  1057.    CSeq: 109524976 BYE
  1058.   Allow: CANCEL, ACK, INVITE, BYE, OPTIONS, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE, MESSAGE, PUBLISH
  1059.    Contact: <sip:9712751300@64.125.111.10:5060>
  1060.    Reason: Q.850;cause=16
  1061.    Content-Length: 0
  1062.    
  1063.    ------------------------------------------------------------------------
  1064.  

Reply to "t38-negotiation-failure"