FreeSWITCH Pastebin

with siptrace

From Francesco Facco de Lagarda, 5 Years ago, written in Plain Text.
- view diff
URL https://pastebin.freeswitch.org/view/70e46c3f
Embed
Download Paste or View Raw
  1. freeswitch@telispe3>
  2. freeswitch@telispe3>
  3. recv 729 bytes from udp/[192.168.1.230]:5060 at 22:14:40.280686:
  4.    ------------------------------------------------------------------------
  5.    INVITE sip:064114551@192.168.1.234:5080 SIP/2.0
  6.    Via: SIP/2.0/UDP 192.168.1.230:5060;branch=z9hG4bK6e3ebcf06a8d7e774
  7.    Max-Forwards: 70
  8.    From: <sip:06412213225@192.168.1.230:5060>;tag=7558602bde
  9.    To: <sip:064114551@192.168.1.234:5080>
  10.    Call-ID: ef49db865bb82982
  11.    CSeq: 30729 INVITE
  12.    Contact: <sip:06412213225@192.168.1.230:5060>
  13.    Supported: replaces
  14.    User-Agent: Patton SN4120 1BIS2V 00A0BA09175F R6.T 2011-09-26_RFE1675 H323 SIP M5T SIP Stack/4.0.30.30
  15.    Content-Type: application/sdp
  16.    Content-Length: 221
  17.  
  18.    v=0
  19.    o=MxSIP 0 55 IN IP4 192.168.1.230
  20.    s=SIP Call
  21.    c=IN IP4 192.168.1.230
  22.    t=0 0
  23.    m=audio 4918 RTP/AVP 8 0 101
  24.    a=rtpmap:8 PCMA/8000
  25.    a=rtpmap:0 PCMU/8000
  26.    a=rtpmap:101 telephone-event/8000
  27.    a=fmtp:101 0-16
  28.    a=sendrecv
  29.    ------------------------------------------------------------------------
  30. send 314 bytes to udp/[192.168.1.230]:5060 at 22:14:40.281245:
  31.    ------------------------------------------------------------------------
  32.    SIP/2.0 100 Trying
  33.    Via: SIP/2.0/UDP 192.168.1.230:5060;branch=z9hG4bK6e3ebcf06a8d7e774
  34.    From: <sip:06412213225@192.168.1.230:5060>;tag=7558602bde
  35.    To: <sip:064114551@192.168.1.234:5080>
  36.    Call-ID: ef49db865bb82982
  37.    CSeq: 30729 INVITE
  38.    User-Agent: FreeSWITCH-mod_sofia/1.6.20-37-987c9b9~64bit
  39.    Content-Length: 0
  40.  
  41.    ------------------------------------------------------------------------
  42. 2018-12-05 22:14:40.272170 [NOTICE] switch_channel.c:1104 New Channel sofia/external/06412213225@192.168.1.230:5060 [8849f41c-e903-4550-a81f-cf680410b911]
  43. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:584 (sofia/external/06412213225@192.168.1.230:5060) Running State Change CS_NEW (Cur 1 Tot 1)
  44. 2018-12-05 22:14:40.272170 [DEBUG] sofia.c:9873 sofia/external/06412213225@192.168.1.230:5060 receiving invite from 192.168.1.230:5060 version: 1.6.20 -37-987c9b9 64bit
  45. 2018-12-05 22:14:40.272170 [DEBUG] sofia.c:7084 Channel sofia/external/06412213225@192.168.1.230:5060 entering state [received][100]
  46. 2018-12-05 22:14:40.272170 [DEBUG] sofia.c:7094 Remote SDP:
  47. v=0
  48. o=MxSIP 0 55 IN IP4 192.168.1.230
  49. s=SIP Call
  50. c=IN IP4 192.168.1.230
  51. t=0 0
  52. m=audio 4918 RTP/AVP 8 0 101
  53. a=rtpmap:8 PCMA/8000
  54. a=rtpmap:0 PCMU/8000
  55. a=rtpmap:101 telephone-event/8000
  56. a=fmtp:101 0-16
  57.  
  58. 2018-12-05 22:14:40.272170 [DEBUG] sofia.c:7486 (sofia/external/06412213225@192.168.1.230:5060) State Change CS_NEW -> CS_INIT
  59. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:603 (sofia/external/06412213225@192.168.1.230:5060) State NEW
  60. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:584 (sofia/external/06412213225@192.168.1.230:5060) Running State Change CS_INIT (Cur 1 Tot 1)
  61. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:627 (sofia/external/06412213225@192.168.1.230:5060) State INIT
  62. 2018-12-05 22:14:40.272170 [DEBUG] mod_sofia.c:90 sofia/external/06412213225@192.168.1.230:5060 SOFIA INIT
  63. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:40 sofia/external/06412213225@192.168.1.230:5060 Standard INIT
  64. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:48 (sofia/external/06412213225@192.168.1.230:5060) State Change CS_INIT -> CS_ROUTING
  65. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:627 (sofia/external/06412213225@192.168.1.230:5060) State INIT going to sleep
  66. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:584 (sofia/external/06412213225@192.168.1.230:5060) Running State Change CS_ROUTING (Cur 1 Tot 1)
  67. 2018-12-05 22:14:40.272170 [DEBUG] switch_channel.c:2249 (sofia/external/06412213225@192.168.1.230:5060) Callstate Change DOWN -> RINGING
  68. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:643 (sofia/external/06412213225@192.168.1.230:5060) State ROUTING
  69. 2018-12-05 22:14:40.272170 [DEBUG] mod_sofia.c:143 sofia/external/06412213225@192.168.1.230:5060 SOFIA ROUTING
  70. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:236 sofia/external/06412213225@192.168.1.230:5060 Standard ROUTING
  71. 2018-12-05 22:14:40.272170 [INFO] mod_dialplan_xml.c:637 Processing 06412213225 <06412213225>->064114551 in context public
  72. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [public->unloop] continue=false
  73. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
  74. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
  75. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [public->outside_call] continue=true
  76. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Absolute Condition [outside_call]
  77. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action set(outside_call=true)
  78. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
  79. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [public->call_debug] continue=true
  80. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never
  81. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [public->public_extensions] continue=false
  82. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [public_extensions] destination_number(064114551) =~ /^(10[01][0-9])$/ break=on-false
  83. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [public->public_did] continue=false
  84. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (PASS) [public_did] destination_number(064114551) =~ /^(064114551)$/ break=on-false
  85. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action set(domain_name=192.168.1.234)
  86. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action transfer(400 XML default)
  87. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:286 (sofia/external/06412213225@192.168.1.230:5060) State Change CS_ROUTING -> CS_EXECUTE
  88. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:643 (sofia/external/06412213225@192.168.1.230:5060) State ROUTING going to sleep
  89. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:584 (sofia/external/06412213225@192.168.1.230:5060) Running State Change CS_EXECUTE (Cur 1 Tot 1)
  90. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:650 (sofia/external/06412213225@192.168.1.230:5060) State EXECUTE
  91. 2018-12-05 22:14:40.272170 [DEBUG] mod_sofia.c:198 sofia/external/06412213225@192.168.1.230:5060 SOFIA EXECUTE
  92. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:328 sofia/external/06412213225@192.168.1.230:5060 Standard EXECUTE
  93. EXECUTE sofia/external/06412213225@192.168.1.230:5060 set(outside_call=true)
  94. 2018-12-05 22:14:40.272170 [DEBUG] mod_dptools.c:1548 SET sofia/external/06412213225@192.168.1.230:5060 [outside_call]=[true]
  95. EXECUTE sofia/external/06412213225@192.168.1.230:5060 export(RFC2822_DATE=Wed, 05 Dec 2018 22:14:40 +0100)
  96. 2018-12-05 22:14:40.272170 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Wed, 05 Dec 2018 22:14:40 +0100]
  97. EXECUTE sofia/external/06412213225@192.168.1.230:5060 set(domain_name=192.168.1.234)
  98. 2018-12-05 22:14:40.272170 [DEBUG] mod_dptools.c:1548 SET sofia/external/06412213225@192.168.1.230:5060 [domain_name]=[192.168.1.234]
  99. EXECUTE sofia/external/06412213225@192.168.1.230:5060 transfer(400 XML default)
  100. 2018-12-05 22:14:40.272170 [DEBUG] switch_ivr.c:2165 (sofia/external/06412213225@192.168.1.230:5060) State Change CS_EXECUTE -> CS_ROUTING
  101. 2018-12-05 22:14:40.272170 [NOTICE] switch_ivr.c:2172 Transfer sofia/external/06412213225@192.168.1.230:5060 to XML[400@default]
  102. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:650 (sofia/external/06412213225@192.168.1.230:5060) State EXECUTE going to sleep
  103. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:584 (sofia/external/06412213225@192.168.1.230:5060) Running State Change CS_ROUTING (Cur 1 Tot 1)
  104. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:643 (sofia/external/06412213225@192.168.1.230:5060) State ROUTING
  105. 2018-12-05 22:14:40.272170 [DEBUG] mod_sofia.c:143 sofia/external/06412213225@192.168.1.230:5060 SOFIA ROUTING
  106. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:236 sofia/external/06412213225@192.168.1.230:5060 Standard ROUTING
  107. 2018-12-05 22:14:40.272170 [INFO] mod_dialplan_xml.c:637 Processing 06412213225 <06412213225>->400 in context default
  108. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->unloop] continue=false
  109. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
  110. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
  111. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->tod_example] continue=true
  112. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Date/TimeMatch (FAIL) [tod_example] break=on-false
  113. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->holiday_example] continue=true
  114. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Date/TimeMatch (FAIL) [holiday_example] break=on-false
  115. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->global-intercept] continue=false
  116. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [global-intercept] destination_number(400) =~ /^886$/ break=on-false
  117. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->group-intercept] continue=false
  118. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [group-intercept] destination_number(400) =~ /^\*8$/ break=on-false
  119. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->intercept-ext] continue=false
  120. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [intercept-ext] destination_number(400) =~ /^\*\*(\d+)$/ break=on-false
  121. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->redial] continue=false
  122. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [redial] destination_number(400) =~ /^(redial|870)$/ break=on-false
  123. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->global] continue=true
  124. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
  125. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [global] ${default_password}(passw0rd) =~ /^1234$/ break=never
  126. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [global] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=never
  127. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
  128. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [global] ${switch_r_sdp}(v=0
  129. o=MxSIP 0 55 IN IP4 192.168.1.230
  130. s=SIP Call
  131. c=IN IP4 192.168.1.230
  132. t=0 0
  133. m=audio 4918 RTP/AVP 8 0 101
  134. a=rtpmap:8 PCMA/8000
  135. a=rtpmap:0 PCMU/8000
  136. a=rtpmap:101 telephone-event/8000
  137. a=fmtp:101 0-16
  138. ) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
  139. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Absolute Condition [global]
  140. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
  141. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
  142. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action hash(insert/${domain_name}-last_dial/global/${uuid})
  143. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
  144. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->t3block] continue=false
  145. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [t3block] destination_number(400) =~ /^66$/ break=on-false
  146. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->tvision1] continue=false
  147. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [tvision1] destination_number(400) =~ /^9111$/ break=on-false
  148. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->playMOH] continue=false
  149. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [playMOH] destination_number(400) =~ /^9211$/ break=on-false
  150. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->tvision2] continue=false
  151. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [tvision2] destination_number(400) =~ /^9112$/ break=on-false
  152. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->tvisionConf] continue=false
  153. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [tvisionConf] destination_number(400) =~ /^9113$/ break=on-false
  154. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->tvTest] continue=false
  155. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [tvTest] destination_number(400) =~ /^9114$/ break=on-false
  156. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->digitsIT] continue=false
  157. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [digitsIT] destination_number(400) =~ /^9119$/ break=on-false
  158. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->hello_world] continue=false
  159. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [hello_world] destination_number(400) =~ /^9022$/ break=on-false
  160. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->snom-demo-2] continue=false
  161. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [snom-demo-2] destination_number(400) =~ /^9001$/ break=on-false
  162. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->snom-demo-1] continue=false
  163. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [snom-demo-1] destination_number(400) =~ /^9000$/ break=on-false
  164. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->eavesdrop] continue=false
  165. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [eavesdrop] destination_number(400) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
  166. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->eavesdrop] continue=false
  167. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [eavesdrop] destination_number(400) =~ /^779$/ break=on-false
  168. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->call_return] continue=false
  169. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [call_return] destination_number(400) =~ /^\*69$|^869$|^lcr$/ break=on-false
  170. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->del-group] continue=false
  171. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [del-group] destination_number(400) =~ /^80(\d{2})$/ break=on-false
  172. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->add-group] continue=false
  173. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [add-group] destination_number(400) =~ /^81(\d{2})$/ break=on-false
  174. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->call-group-simo] continue=false
  175. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [call-group-simo] destination_number(400) =~ /^82(\d{2})$/ break=on-false
  176. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->call-group-order] continue=false
  177. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [call-group-order] destination_number(400) =~ /^83(\d{2})$/ break=on-false
  178. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->extension-intercom] continue=false
  179. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [extension-intercom] destination_number(400) =~ /^8(10[01][0-9])$/ break=on-false
  180. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->Local_Extension] continue=false
  181. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (FAIL) [Local_Extension] destination_number(400) =~ /^(10[01][0-9])$/ break=on-false
  182. Dialplan: sofia/external/06412213225@192.168.1.230:5060 parsing [default->Local_Extension_300] continue=false
  183. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Regex (PASS) [Local_Extension_300] destination_number(400) =~ /^([3-4][0-9][0-9])$/ break=on-false
  184. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action export(dialed_extension=400)
  185. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action bind_meta_app(1 b s execute_extension::dx XML features)
  186. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action bind_meta_app(2 b s record_session::/var/lib/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav)
  187. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action bind_meta_app(3 b s execute_extension::cf XML features)
  188. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action bind_meta_app(4 b s execute_extension::att_xfer XML features)
  189. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action set(ringback=${us-ring})
  190. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action set(transfer_ringback=local_stream://moh)
  191. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action set(call_timeout=30)
  192. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action set(hangup_after_bridge=true)
  193. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action set(continue_on_fail=true)
  194. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
  195. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
  196. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)})
  197. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid})
  198. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid})
  199. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
  200. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action bridge(user/${dialed_extension}@${domain_name})
  201. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action answer()
  202. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action sleep(1000)
  203. Dialplan: sofia/external/06412213225@192.168.1.230:5060 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension})
  204. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:286 (sofia/external/06412213225@192.168.1.230:5060) State Change CS_ROUTING -> CS_EXECUTE
  205. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:643 (sofia/external/06412213225@192.168.1.230:5060) State ROUTING going to sleep
  206. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:584 (sofia/external/06412213225@192.168.1.230:5060) Running State Change CS_EXECUTE (Cur 1 Tot 1)
  207. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:650 (sofia/external/06412213225@192.168.1.230:5060) State EXECUTE
  208. 2018-12-05 22:14:40.272170 [DEBUG] mod_sofia.c:198 sofia/external/06412213225@192.168.1.230:5060 SOFIA EXECUTE
  209. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:328 sofia/external/06412213225@192.168.1.230:5060 Standard EXECUTE
  210. EXECUTE sofia/external/06412213225@192.168.1.230:5060 hash(insert/192.168.1.234-spymap/06412213225/8849f41c-e903-4550-a81f-cf680410b911)
  211. EXECUTE sofia/external/06412213225@192.168.1.230:5060 hash(insert/192.168.1.234-last_dial/06412213225/400)
  212. EXECUTE sofia/external/06412213225@192.168.1.230:5060 hash(insert/192.168.1.234-last_dial/global/8849f41c-e903-4550-a81f-cf680410b911)
  213. EXECUTE sofia/external/06412213225@192.168.1.230:5060 export(RFC2822_DATE=Wed, 05 Dec 2018 22:14:40 +0100)
  214. 2018-12-05 22:14:40.272170 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Wed, 05 Dec 2018 22:14:40 +0100]
  215. EXECUTE sofia/external/06412213225@192.168.1.230:5060 export(dialed_extension=400)
  216. 2018-12-05 22:14:40.272170 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[400]
  217. EXECUTE sofia/external/06412213225@192.168.1.230:5060 bind_meta_app(1 b s execute_extension::dx XML features)
  218. 2018-12-05 22:14:40.272170 [INFO] switch_ivr_async.c:4173 Bound B-Leg: *1 execute_extension::dx XML features
  219. EXECUTE sofia/external/06412213225@192.168.1.230:5060 bind_meta_app(2 b s record_session::/var/lib/freeswitch/recordings/06412213225.2018-12-05-22-14-40.wav)
  220. 2018-12-05 22:14:40.272170 [INFO] switch_ivr_async.c:4173 Bound B-Leg: *2 record_session::/var/lib/freeswitch/recordings/06412213225.2018-12-05-22-14-40.wav
  221. EXECUTE sofia/external/06412213225@192.168.1.230:5060 bind_meta_app(3 b s execute_extension::cf XML features)
  222. 2018-12-05 22:14:40.272170 [INFO] switch_ivr_async.c:4173 Bound B-Leg: *3 execute_extension::cf XML features
  223. EXECUTE sofia/external/06412213225@192.168.1.230:5060 bind_meta_app(4 b s execute_extension::att_xfer XML features)
  224. 2018-12-05 22:14:40.272170 [INFO] switch_ivr_async.c:4173 Bound B-Leg: *4 execute_extension::att_xfer XML features
  225. EXECUTE sofia/external/06412213225@192.168.1.230:5060 set(ringback=%(2000,4000,440,480))
  226. 2018-12-05 22:14:40.272170 [DEBUG] mod_dptools.c:1548 SET sofia/external/06412213225@192.168.1.230:5060 [ringback]=[%(2000,4000,440,480)]
  227. EXECUTE sofia/external/06412213225@192.168.1.230:5060 set(transfer_ringback=local_stream://moh)
  228. 2018-12-05 22:14:40.272170 [DEBUG] mod_dptools.c:1548 SET sofia/external/06412213225@192.168.1.230:5060 [transfer_ringback]=[local_stream://moh]
  229. EXECUTE sofia/external/06412213225@192.168.1.230:5060 set(call_timeout=30)
  230. 2018-12-05 22:14:40.272170 [DEBUG] mod_dptools.c:1548 SET sofia/external/06412213225@192.168.1.230:5060 [call_timeout]=[30]
  231. EXECUTE sofia/external/06412213225@192.168.1.230:5060 set(hangup_after_bridge=true)
  232. 2018-12-05 22:14:40.272170 [DEBUG] mod_dptools.c:1548 SET sofia/external/06412213225@192.168.1.230:5060 [hangup_after_bridge]=[true]
  233. EXECUTE sofia/external/06412213225@192.168.1.230:5060 set(continue_on_fail=true)
  234. 2018-12-05 22:14:40.272170 [DEBUG] mod_dptools.c:1548 SET sofia/external/06412213225@192.168.1.230:5060 [continue_on_fail]=[true]
  235. EXECUTE sofia/external/06412213225@192.168.1.230:5060 hash(insert/192.168.1.234-call_return/400/06412213225)
  236. EXECUTE sofia/external/06412213225@192.168.1.230:5060 hash(insert/192.168.1.234-last_dial_ext/400/8849f41c-e903-4550-a81f-cf680410b911)
  237. EXECUTE sofia/external/06412213225@192.168.1.230:5060 set(called_party_callgroup=techsupport)
  238. 2018-12-05 22:14:40.272170 [DEBUG] mod_dptools.c:1548 SET sofia/external/06412213225@192.168.1.230:5060 [called_party_callgroup]=[techsupport]
  239. EXECUTE sofia/external/06412213225@192.168.1.230:5060 hash(insert/192.168.1.234-last_dial_ext/techsupport/8849f41c-e903-4550-a81f-cf680410b911)
  240. EXECUTE sofia/external/06412213225@192.168.1.230:5060 hash(insert/192.168.1.234-last_dial_ext/global/8849f41c-e903-4550-a81f-cf680410b911)
  241. EXECUTE sofia/external/06412213225@192.168.1.230:5060 hash(insert/192.168.1.234-last_dial/techsupport/8849f41c-e903-4550-a81f-cf680410b911)
  242. EXECUTE sofia/external/06412213225@192.168.1.230:5060 bridge(user/400@192.168.1.234)
  243. 2018-12-05 22:14:40.272170 [DEBUG] switch_channel.c:1250 sofia/external/06412213225@192.168.1.230:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Wed, 05 Dec 2018 22:14:40 +0100] to event
  244. 2018-12-05 22:14:40.272170 [DEBUG] switch_channel.c:1250 sofia/external/06412213225@192.168.1.230:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Wed, 05 Dec 2018 22:14:40 +0100] to event
  245. 2018-12-05 22:14:40.272170 [DEBUG] switch_channel.c:1250 sofia/external/06412213225@192.168.1.230:5060 EXPORTING[export_vars] [dialed_extension]=[400] to event
  246. 2018-12-05 22:14:40.272170 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
  247. 2018-12-05 22:14:40.272170 [DEBUG] switch_channel.c:1250 sofia/external/06412213225@192.168.1.230:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Wed, 05 Dec 2018 22:14:40 +0100] to event
  248. 2018-12-05 22:14:40.272170 [DEBUG] switch_channel.c:1250 sofia/external/06412213225@192.168.1.230:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Wed, 05 Dec 2018 22:14:40 +0100] to event
  249. 2018-12-05 22:14:40.272170 [DEBUG] switch_channel.c:1250 sofia/external/06412213225@192.168.1.230:5060 EXPORTING[export_vars] [dialed_extension]=[400] to event
  250. 2018-12-05 22:14:40.272170 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
  251. 2018-12-05 22:14:40.272170 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/400@192.168.1.249:2048 [9245920f-330a-4abf-9942-ac8d5cc10f5a]
  252. 2018-12-05 22:14:40.272170 [DEBUG] mod_sofia.c:4819 (sofia/internal/400@192.168.1.249:2048) State Change CS_NEW -> CS_INIT
  253. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/400@192.168.1.249:2048) Running State Change CS_INIT (Cur 2 Tot 2)
  254. 2018-12-05 22:14:40.272170 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
  255. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/400@192.168.1.249:2048) State INIT
  256. 2018-12-05 22:14:40.272170 [DEBUG] mod_sofia.c:90 sofia/internal/400@192.168.1.249:2048 SOFIA INIT
  257. 2018-12-05 22:14:40.272170 [DEBUG] sofia_glue.c:1295 sofia/internal/400@192.168.1.249:2048 sending invite version: 1.6.20 -37-987c9b9 64bit
  258. Local SDP:
  259. v=0
  260. o=FreeSWITCH 1544016856 1544016857 IN IP4 192.168.1.234
  261. s=FreeSWITCH
  262. c=IN IP4 192.168.1.234
  263. t=0 0
  264. m=audio 27624 RTP/AVP 8 0 101
  265. a=rtpmap:8 PCMA/8000
  266. a=rtpmap:0 PCMU/8000
  267. a=rtpmap:101 telephone-event/8000
  268. a=fmtp:101 0-16
  269. a=ptime:20
  270. a=sendrecv
  271.  
  272. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:40 sofia/internal/400@192.168.1.249:2048 Standard INIT
  273. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/400@192.168.1.249:2048) State Change CS_INIT -> CS_ROUTING
  274. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/400@192.168.1.249:2048) State INIT going to sleep
  275. send 1220 bytes to udp/[192.168.1.249]:2048 at 22:14:40.307302:
  276.    ------------------------------------------------------------------------
  277.    INVITE sip:400@192.168.1.249:2048;line=ab6s4d5m SIP/2.0
  278.    Via: SIP/2.0/UDP 192.168.1.234;rport;branch=z9hG4bKj68B0vXK55X4S
  279.    Max-Forwards: 68
  280.    From: "06412213225" <sip:06412213225@192.168.1.234>;tag=KeyZmaQeZvtjm
  281.    To: <sip:400@192.168.1.249:2048;line=ab6s4d5m>
  282.    Call-ID: 9e88b8f8-7375-1237-72a2-d485646a6cbc
  283.    CSeq: 131686176 INVITE
  284.    Contact: <sip:mod_sofia@192.168.1.234:5060>
  285.    User-Agent: FreeSWITCH-mod_sofia/1.6.20-37-987c9b9~64bit
  286.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  287.    Supported: timer, path, replaces
  288.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
  289.    Content-Type: application/sdp
  290.    Content-Disposition: session
  291.    Content-Length: 246
  292.    X-FS-Support: update_display,send_info
  293.    Remote-Party-ID: "06412213225" <sip:06412213225@192.168.1.234>;party=calling;screen=yes;privacy=off
  294.  
  295.    v=0
  296.    o=FreeSWITCH 1544016856 1544016857 IN IP4 192.168.1.234
  297.    s=FreeSWITCH
  298.    c=IN IP4 192.168.1.234
  299. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/400@192.168.1.249:2048) Running State Change CS_ROUTING (Cur 2 Tot 2)
  300.    t=0 0
  301.    m=audio 27624 RTP/AVP 8 0 101
  302.    a=rtpmap:8 PCMA/8000
  303.    a=rtpmap:0 PCMU/8000
  304.    a=rtpmap:101 telephone-event/8000
  305.    a=fmtp:101 0-16
  306.    a=ptime:20
  307.    ------------------------------------------------------------------------
  308. 2018-12-05 22:14:40.272170 [DEBUG] sofia.c:7084 Channel sofia/internal/400@192.168.1.249:2048 entering state [calling][0]
  309. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/400@192.168.1.249:2048) State ROUTING
  310. 2018-12-05 22:14:40.272170 [DEBUG] mod_sofia.c:143 sofia/internal/400@192.168.1.249:2048 SOFIA ROUTING
  311. 2018-12-05 22:14:40.272170 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/400@192.168.1.249:2048) State Change CS_ROUTING -> CS_CONSUME_MEDIA
  312. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/400@192.168.1.249:2048) State ROUTING going to sleep
  313. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/400@192.168.1.249:2048) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 2)
  314. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/400@192.168.1.249:2048) State CONSUME_MEDIA
  315. 2018-12-05 22:14:40.272170 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/400@192.168.1.249:2048) State CONSUME_MEDIA going to sleep
  316. recv 514 bytes from udp/[192.168.1.249]:2048 at 22:14:40.351915:
  317.    ------------------------------------------------------------------------
  318.    SIP/2.0 180 Ringing
  319.    Via: SIP/2.0/UDP 192.168.1.234;rport=5060;branch=z9hG4bKj68B0vXK55X4S
  320.    From: "06412213225" <sip:06412213225@192.168.1.234>;tag=KeyZmaQeZvtjm
  321.    To: <sip:400@192.168.1.249:2048;line=ab6s4d5m>;tag=5erhr7w222
  322.    Call-ID: 9e88b8f8-7375-1237-72a2-d485646a6cbc
  323.    CSeq: 131686176 INVITE
  324.    Contact: <sip:400@192.168.1.249:2048;line=ab6s4d5m>;reg-id=1
  325.    Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO
  326.    Allow-Events: talk, hold, refer, call-info
  327.    Content-Length: 0
  328.  
  329.    ------------------------------------------------------------------------
  330. 2018-12-05 22:14:40.352036 [DEBUG] sofia.c:7084 Channel sofia/internal/400@192.168.1.249:2048 entering state [proceeding][180]
  331. 2018-12-05 22:14:40.352036 [NOTICE] sofia.c:7192 Ring-Ready sofia/internal/400@192.168.1.249:2048!
  332. 2018-12-05 22:14:40.352036 [DEBUG] switch_channel.c:3346 (sofia/internal/400@192.168.1.249:2048) Callstate Change DOWN -> RINGING
  333. 2018-12-05 22:14:40.352036 [INFO] switch_ivr_originate.c:1215 Sending early media
  334. 2018-12-05 22:14:40.352036 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
  335. 2018-12-05 22:14:40.352036 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  336. 2018-12-05 22:14:40.352036 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  337. 2018-12-05 22:14:40.352036 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  338. 2018-12-05 22:14:40.352036 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
  339. 2018-12-05 22:14:40.352036 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
  340. 2018-12-05 22:14:40.352036 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  341. 2018-12-05 22:14:40.352036 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  342. 2018-12-05 22:14:40.352036 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
  343. 2018-12-05 22:14:40.352036 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  344. 2018-12-05 22:14:40.352036 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
  345. 2018-12-05 22:14:40.352036 [DEBUG] switch_core_media.c:3061 Set Codec sofia/external/06412213225@192.168.1.230:5060 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
  346. 2018-12-05 22:14:40.352036 [DEBUG] switch_core_codec.c:111 sofia/external/06412213225@192.168.1.230:5060 Original read codec set to PCMA:8
  347. 2018-12-05 22:14:40.352036 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
  348. 2018-12-05 22:14:40.352036 [DEBUG] switch_core_media.c:4767 sofia/external/06412213225@192.168.1.230:5060 Set 2833 dtmf send payload to 101 recv payload to 101
  349. 2018-12-05 22:14:40.352036 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/external/06412213225@192.168.1.230:5060] 192.168.1.234 port 18926 -> 192.168.1.230 port 4918 codec: 8 ms: 20
  350. 2018-12-05 22:14:40.352036 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms
  351. 2018-12-05 22:14:40.352036 [DEBUG] switch_core_media.c:7180 sofia/external/06412213225@192.168.1.230:5060 Set 2833 dtmf send payload to 101
  352. 2018-12-05 22:14:40.352036 [DEBUG] switch_core_media.c:7187 sofia/external/06412213225@192.168.1.230:5060 Set 2833 dtmf receive payload to 101
  353. 2018-12-05 22:14:40.352036 [DEBUG] switch_core_media.c:7210 sofia/external/06412213225@192.168.1.230:5060 Set rtp dtmf delay to 40
  354. 2018-12-05 22:14:40.352036 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/06412213225@192.168.1.230:5060!
  355. 2018-12-05 22:14:40.372040 [DEBUG] switch_channel.c:3474 (sofia/external/06412213225@192.168.1.230:5060) Callstate Change RINGING -> EARLY
  356. 2018-12-05 22:14:40.372040 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/external/06412213225@192.168.1.230:5060.
  357. 2018-12-05 22:14:40.372040 [DEBUG] mod_sofia.c:2364 Ring SDP:
  358. v=0
  359. o=FreeSWITCH 1544025554 1544025555 IN IP4 192.168.1.234
  360. s=FreeSWITCH
  361. c=IN IP4 192.168.1.234
  362. t=0 0
  363. m=audio 18926 RTP/AVP 8 101
  364. a=rtpmap:8 PCMA/8000
  365. a=rtpmap:101 telephone-event/8000
  366. a=fmtp:101 0-16
  367. a=ptime:20
  368. a=sendrecv
  369.  
  370. 2018-12-05 22:14:40.372040 [DEBUG] switch_ivr_originate.c:1273 Raw Codec Activation Success L16@8000hz 1 channel 20ms
  371. 2018-12-05 22:14:40.372040 [DEBUG] switch_core_codec.c:223 sofia/external/06412213225@192.168.1.230:5060 Push codec L16:100
  372. 2018-12-05 22:14:40.372040 [DEBUG] switch_ivr_originate.c:1342 Play Ringback Tone [%(2000,4000,440,480)]
  373. send 976 bytes to udp/[192.168.1.230]:5060 at 22:14:40.374028:
  374.    ------------------------------------------------------------------------
  375.    SIP/2.0 183 Session Progress
  376.    Via: SIP/2.0/UDP 192.168.1.230:5060;branch=z9hG4bK6e3ebcf06a8d7e774
  377.    From: <sip:06412213225@192.168.1.230:5060>;tag=7558602bde
  378.    To: <sip:064114551@192.168.1.234:5080>;tag=QHrvHNSvvg8BN
  379.    Call-ID: ef49db865bb82982
  380.    CSeq: 30729 INVITE
  381.    Contact: <sip:064114551@192.168.1.234:5080;transport=udp>
  382.    User-Agent: FreeSWITCH-mod_sofia/1.6.20-37-987c9b9~64bit
  383.    Accept: application/sdp
  384.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
  385.    Supported: timer, path, replaces
  386.    Allow-Events: talk, hold, conference, refer
  387.    Content-Type: application/sdp
  388.    Content-Disposition: session
  389.    Content-Length: 222
  390.    Remote-Party-ID: "064114551" <sip:064114551@192.168.1.234>;party=calling;privacy=off;screen=no
  391.  
  392.    v=0
  393.    o=FreeSWITCH 1544025554 1544025555 IN IP4 192.168.1.234
  394.    s=FreeSWITCH
  395.    c=IN IP4 192.168.1.234
  396.    t=0 0
  397.    m=audio 18926 RTP/AVP 8 101
  398.    a=rtpmap:8 PCMA/8000
  399.    a=rtpmap:101 telephone-event/8000
  400.    a=fmtp:101 0-16
  401.    a=ptime:20
  402.    ------------------------------------------------------------------------
  403. 2018-12-05 22:14:40.392108 [DEBUG] sofia.c:7084 Channel sofia/external/06412213225@192.168.1.230:5060 entering state [early][183]
  404. 2018-12-05 22:14:40.512174 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
  405. recv 514 bytes from udp/[192.168.1.249]:2048 at 22:14:40.865222:
  406.    ------------------------------------------------------------------------
  407.    SIP/2.0 180 Ringing
  408.    Via: SIP/2.0/UDP 192.168.1.234;rport=5060;branch=z9hG4bKj68B0vXK55X4S
  409.    From: "06412213225" <sip:06412213225@192.168.1.234>;tag=KeyZmaQeZvtjm
  410.    To: <sip:400@192.168.1.249:2048;line=ab6s4d5m>;tag=5erhr7w222
  411.    Call-ID: 9e88b8f8-7375-1237-72a2-d485646a6cbc
  412.    CSeq: 131686176 INVITE
  413.    Contact: <sip:400@192.168.1.249:2048;line=ab6s4d5m>;reg-id=1
  414.    Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO
  415.    Allow-Events: talk, hold, refer, call-info
  416.    Content-Length: 0
  417.  
  418.    ------------------------------------------------------------------------
  419. 2018-12-05 22:14:40.852170 [DEBUG] sofia.c:7084 Channel sofia/internal/400@192.168.1.249:2048 entering state [proceeding][180]
  420. recv 514 bytes from udp/[192.168.1.249]:2048 at 22:14:41.876402:
  421.    ------------------------------------------------------------------------
  422.    SIP/2.0 180 Ringing
  423.    Via: SIP/2.0/UDP 192.168.1.234;rport=5060;branch=z9hG4bKj68B0vXK55X4S
  424.    From: "06412213225" <sip:06412213225@192.168.1.234>;tag=KeyZmaQeZvtjm
  425.    To: <sip:400@192.168.1.249:2048;line=ab6s4d5m>;tag=5erhr7w222
  426.    Call-ID: 9e88b8f8-7375-1237-72a2-d485646a6cbc
  427.    CSeq: 131686176 INVITE
  428.    Contact: <sip:400@192.168.1.249:2048;line=ab6s4d5m>;reg-id=1
  429.    Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO
  430.    Allow-Events: talk, hold, refer, call-info
  431.    Content-Length: 0
  432.  
  433.    ------------------------------------------------------------------------
  434. 2018-12-05 22:14:41.872141 [DEBUG] sofia.c:7084 Channel sofia/internal/400@192.168.1.249:2048 entering state [proceeding][180]
  435. recv 407 bytes from udp/[192.168.1.230]:5060 at 22:14:42.253192:
  436.    ------------------------------------------------------------------------
  437.    CANCEL sip:064114551@192.168.1.234:5080 SIP/2.0
  438.    Via: SIP/2.0/UDP 192.168.1.230:5060;branch=z9hG4bK6e3ebcf06a8d7e774
  439.    Max-Forwards: 70
  440.    From: <sip:06412213225@192.168.1.230:5060>;tag=7558602bde
  441.    To: <sip:064114551@192.168.1.234:5080>
  442.    Call-ID: ef49db865bb82982
  443.    CSeq: 30729 CANCEL
  444.    User-Agent: Patton SN4120 1BIS2V 00A0BA09175F R6.T 2011-09-26_RFE1675 H323 SIP M5T SIP Stack/4.0.30.30
  445.    Content-Length: 0
  446.  
  447.    ------------------------------------------------------------------------
  448. send 270 bytes to udp/[192.168.1.230]:5060 at 22:14:42.253499:
  449.    ------------------------------------------------------------------------
  450.    SIP/2.0 200 OK
  451.    Via: SIP/2.0/UDP 192.168.1.230:5060;branch=z9hG4bK6e3ebcf06a8d7e774
  452.    From: <sip:06412213225@192.168.1.230:5060>;tag=7558602bde
  453.    To: <sip:064114551@192.168.1.234:5080>;tag=QHrvHNSvvg8BN
  454.    Call-ID: ef49db865bb82982
  455.    CSeq: 30729 CANCEL
  456.    Content-Length: 0
  457.  
  458.    ------------------------------------------------------------------------
  459. send 513 bytes to udp/[192.168.1.230]:5060 at 22:14:42.253683:
  460.    ------------------------------------------------------------------------
  461.    SIP/2.0 487 Request Terminated
  462.    Via: SIP/2.0/UDP 192.168.1.230:5060;branch=z9hG4bK6e3ebcf06a8d7e774
  463.    From: <sip:06412213225@192.168.1.230:5060>;tag=7558602bde
  464.    To: <sip:064114551@192.168.1.234:5080>;tag=QHrvHNSvvg8BN
  465.    Call-ID: ef49db865bb82982
  466.    CSeq: 30729 INVITE
  467.    User-Agent: FreeSWITCH-mod_sofia/1.6.20-37-987c9b9~64bit
  468.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
  469.    Supported: timer, path, replaces
  470.    Allow-Events: talk, hold, conference, refer
  471.    Content-Length: 0
  472.  
  473.    ------------------------------------------------------------------------
  474. 2018-12-05 22:14:42.252191 [DEBUG] sofia.c:7084 Channel sofia/external/06412213225@192.168.1.230:5060 entering state [terminated][487]
  475. 2018-12-05 22:14:42.252191 [NOTICE] sofia.c:8273 Hangup sofia/external/06412213225@192.168.1.230:5060 [CS_EXECUTE] [ORIGINATOR_CANCEL]
  476. 2018-12-05 22:14:42.252191 [DEBUG] switch_core_codec.c:248 sofia/external/06412213225@192.168.1.230:5060 Restore previous codec PCMA:8.
  477. 2018-12-05 22:14:42.252191 [NOTICE] switch_ivr_originate.c:3612 Hangup sofia/internal/400@192.168.1.249:2048 [CS_CONSUME_MEDIA] [ORIGINATOR_CANCEL]
  478. 2018-12-05 22:14:42.252191 [DEBUG] switch_ivr_originate.c:3837 Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL]
  479. 2018-12-05 22:14:42.252191 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [user] cause: [ORIGINATOR_CANCEL]
  480. 2018-12-05 22:14:42.252191 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 487 [ORIGINATOR_CANCEL]
  481. 2018-12-05 22:14:42.252191 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/400@192.168.1.249:2048) Running State Change CS_HANGUP (Cur 2 Tot 2)
  482. 2018-12-05 22:14:42.252191 [INFO] mod_dptools.c:3436 Originate Failed.  Cause: ORIGINATOR_CANCEL
  483. 2018-12-05 22:14:42.252191 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/400@192.168.1.249:2048) Callstate Change RINGING -> HANGUP
  484. 2018-12-05 22:14:42.252191 [DEBUG] switch_core_session.c:2815 sofia/external/06412213225@192.168.1.230:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
  485. 2018-12-05 22:14:42.252191 [DEBUG] switch_core_state_machine.c:650 (sofia/external/06412213225@192.168.1.230:5060) State EXECUTE going to sleep
  486. 2018-12-05 22:14:42.252191 [DEBUG] switch_core_state_machine.c:584 (sofia/external/06412213225@192.168.1.230:5060) Running State Change CS_HANGUP (Cur 2 Tot 2)
  487. 2018-12-05 22:14:42.252191 [DEBUG] switch_core_state_machine.c:850 (sofia/external/06412213225@192.168.1.230:5060) Callstate Change EARLY -> HANGUP
  488. 2018-12-05 22:14:42.252191 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/400@192.168.1.249:2048) State HANGUP
  489. 2018-12-05 22:14:42.252191 [DEBUG] mod_sofia.c:432 sofia/internal/400@192.168.1.249:2048 Overriding SIP cause 487 with 487 from the other leg
  490. 2018-12-05 22:14:42.252191 [DEBUG] mod_sofia.c:438 Channel sofia/internal/400@192.168.1.249:2048 hanging up, cause: ORIGINATOR_CANCEL
  491. recv 419 bytes from udp/[192.168.1.230]:5060 at 22:14:42.274553:
  492.    ------------------------------------------------------------------------
  493.    ACK sip:064114551@192.168.1.234:5080 SIP/2.0
  494.    Via: SIP/2.0/UDP 192.168.1.230:5060;branch=z9hG4bK6e3ebcf06a8d7e774
  495.    Max-Forwards: 70
  496.    From: <sip:06412213225@192.168.1.230:5060>;tag=7558602bde
  497.    To: <sip:064114551@192.168.1.234:5080>;tag=QHrvHNSvvg8BN
  498.    Call-ID: ef49db865bb82982
  499.    CSeq: 30729 ACK
  500.    User-Agent: Patton SN4120 1BIS2V 00A0BA09175F R6.T 2011-09-26_RFE1675 H323 SIP M5T SIP Stack/4.0.30.30
  501.    Content-Length: 0
  502.  
  503.    ------------------------------------------------------------------------
  504. 2018-12-05 22:14:42.252191 [DEBUG] switch_core_state_machine.c:852 (sofia/external/06412213225@192.168.1.230:5060) State HANGUP
  505. 2018-12-05 22:14:42.252191 [DEBUG] mod_sofia.c:438 Channel sofia/external/06412213225@192.168.1.230:5060 hanging up, cause: ORIGINATOR_CANCEL
  506. 2018-12-05 22:14:42.252191 [DEBUG] switch_core_state_machine.c:60 sofia/external/06412213225@192.168.1.230:5060 Standard HANGUP, cause: ORIGINATOR_CANCEL
  507. 2018-12-05 22:14:42.252191 [DEBUG] switch_core_state_machine.c:852 (sofia/external/06412213225@192.168.1.230:5060) State HANGUP going to sleep
  508. 2018-12-05 22:14:42.252191 [DEBUG] switch_core_state_machine.c:619 (sofia/external/06412213225@192.168.1.230:5060) State Change CS_HANGUP -> CS_REPORTING
  509. 2018-12-05 22:14:42.252191 [DEBUG] switch_core_state_machine.c:584 (sofia/external/06412213225@192.168.1.230:5060) Running State Change CS_REPORTING (Cur 2 Tot 2)
  510. 2018-12-05 22:14:42.252191 [DEBUG] switch_core_state_machine.c:938 (sofia/external/06412213225@192.168.1.230:5060) State REPORTING
  511. 2018-12-05 22:14:42.252191 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/internal/400@192.168.1.249:2048
  512. send 400 bytes to udp/[192.168.1.249]:2048 at 22:14:42.276026:
  513.    ------------------------------------------------------------------------
  514.    CANCEL sip:400@192.168.1.249:2048;line=ab6s4d5m SIP/2.0
  515.    Via: SIP/2.0/UDP 192.168.1.234;rport;branch=z9hG4bKj68B0vXK55X4S
  516.    Max-Forwards: 68
  517.    From: "06412213225" <sip:06412213225@192.168.1.234>;tag=KeyZmaQeZvtjm
  518.    To: <sip:400@192.168.1.249:2048;line=ab6s4d5m>
  519.    Call-ID: 9e88b8f8-7375-1237-72a2-d485646a6cbc
  520.    CSeq: 131686176 CANCEL
  521.    Reason: SIP;cause=487;text="ORIGINATOR_CANCEL"
  522.    Content-Length: 0
  523.  
  524.    ------------------------------------------------------------------------
  525. 2018-12-05 22:14:42.252191 [DEBUG] switch_core_state_machine.c:60 sofia/internal/400@192.168.1.249:2048 Standard HANGUP, cause: ORIGINATOR_CANCEL
  526. 2018-12-05 22:14:42.252191 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/400@192.168.1.249:2048) State HANGUP going to sleep
  527. 2018-12-05 22:14:42.252191 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/400@192.168.1.249:2048) State Change CS_HANGUP -> CS_REPORTING
  528. 2018-12-05 22:14:42.252191 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/400@192.168.1.249:2048) Running State Change CS_REPORTING (Cur 2 Tot 2)
  529. 2018-12-05 22:14:42.252191 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/400@192.168.1.249:2048) State REPORTING
  530. 2018-12-05 22:14:42.252191 [DEBUG] mod_odbc_cdr.c:309 sql INSERT INTO cdr_table_both (CallId, TEST_id) VALUES ('9245920f-330a-4abf-9942-ac8d5cc10f5a', '06412213225@192.168.1.234')
  531. recv 313 bytes from udp/[192.168.1.249]:2048 at 22:14:42.291595:
  532.    ------------------------------------------------------------------------
  533.    SIP/2.0 200 OK
  534.    Via: SIP/2.0/UDP 192.168.1.234;rport=5060;branch=z9hG4bKj68B0vXK55X4S
  535.    From: "06412213225" <sip:06412213225@192.168.1.234>;tag=KeyZmaQeZvtjm
  536.    To: <sip:400@192.168.1.249:2048;line=ab6s4d5m>;tag=5erhr7w222
  537.    Call-ID: 9e88b8f8-7375-1237-72a2-d485646a6cbc
  538.    CSeq: 131686176 CANCEL
  539.    Content-Length: 0
  540.  
  541.    ------------------------------------------------------------------------
  542. 2018-12-05 22:14:42.292033 [DEBUG] mod_odbc_cdr.c:309 sql INSERT INTO cdr_table_both (CallId, TEST_id) VALUES ('8849f41c-e903-4550-a81f-cf680410b911', '06412213225@192.168.1.230:5060')
  543. recv 391 bytes from udp/[192.168.1.249]:2048 at 22:14:42.302673:
  544.    ------------------------------------------------------------------------
  545.    SIP/2.0 487 Request Terminated
  546.    Via: SIP/2.0/UDP 192.168.1.234;rport=5060;branch=z9hG4bKj68B0vXK55X4S
  547.    From: "06412213225" <sip:06412213225@192.168.1.234>;tag=KeyZmaQeZvtjm
  548.    To: <sip:400@192.168.1.249:2048;line=ab6s4d5m>;tag=5erhr7w222
  549.    Call-ID: 9e88b8f8-7375-1237-72a2-d485646a6cbc
  550.    CSeq: 131686176 INVITE
  551.    Contact: <sip:400@192.168.1.249:2048;line=ab6s4d5m>;reg-id=1
  552.    Content-Length: 0
  553.  
  554.    ------------------------------------------------------------------------
  555. send 361 bytes to udp/[192.168.1.249]:2048 at 22:14:42.302846:
  556.    ------------------------------------------------------------------------
  557.    ACK sip:400@192.168.1.249:2048;line=ab6s4d5m SIP/2.0
  558.    Via: SIP/2.0/UDP 192.168.1.234;rport;branch=z9hG4bKj68B0vXK55X4S
  559.    Max-Forwards: 68
  560.    From: "06412213225" <sip:06412213225@192.168.1.234>;tag=KeyZmaQeZvtjm
  561.    To: <sip:400@192.168.1.249:2048;line=ab6s4d5m>;tag=5erhr7w222
  562.    Call-ID: 9e88b8f8-7375-1237-72a2-d485646a6cbc
  563.    CSeq: 131686176 ACK
  564.    Content-Length: 0
  565.  
  566.    ------------------------------------------------------------------------
  567. 2018-12-05 22:14:42.352082 [DEBUG] mod_odbc_cdr.c:309 sql INSERT INTO cdr_table_b_leg (TelNumberFull, CallId, orig_id, CallerID, IP, term_id, ClientId) VALUES ('400', '8849f41c-e903-4550-a81f-cf680410b911', '9245920f-330a-4abf-9942-ac8d5cc10f5a', '06412213225', '192.168.1.249', '9e88b8f8-7375-1237-72a2-d485646a6cbc', '9245920f-330a-4abf-9942-ac8d5cc10f5a')
  568. 2018-12-05 22:14:42.412142 [DEBUG] mod_odbc_cdr.c:309 sql INSERT INTO cdr_table_a_leg (TelNumberFull, TelNumber, CallId, sip_endpoint_disposition, orig_id, CallerID, CODEC, sip_current_application, directGateway, IPInternal, IP, term_id, ClientId) VALUES ('064114551', '064114551', '8849f41c-e903-4550-a81f-cf680410b911', 'EARLY MEDIA', '8849f41c-e903-4550-a81f-cf680410b911', '06412213225', 'PCMA', 'bridge', '192.168.1.234', '192.168.1.230', '192.168.1.230', 'ef49db865bb82982', '8849f41c-e903-4550-a81f-cf680410b911')
  569. 2018-12-05 22:14:42.472101 [DEBUG] switch_core_state_machine.c:174 sofia/internal/400@192.168.1.249:2048 Standard REPORTING, cause: ORIGINATOR_CANCEL
  570. 2018-12-05 22:14:42.472101 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/400@192.168.1.249:2048) State REPORTING going to sleep
  571. 2018-12-05 22:14:42.472101 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/400@192.168.1.249:2048) State Change CS_REPORTING -> CS_DESTROY
  572. 2018-12-05 22:14:42.472101 [DEBUG] switch_core_session.c:1665 Session 2 (sofia/internal/400@192.168.1.249:2048) Locked, Waiting on external entities
  573. 2018-12-05 22:14:42.472101 [NOTICE] switch_core_session.c:1683 Session 2 (sofia/internal/400@192.168.1.249:2048) Ended
  574. 2018-12-05 22:14:42.472101 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/400@192.168.1.249:2048 [CS_DESTROY]
  575. 2018-12-05 22:14:42.472101 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/400@192.168.1.249:2048) Running State Change CS_DESTROY (Cur 1 Tot 2)
  576. 2018-12-05 22:14:42.472101 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/400@192.168.1.249:2048) State DESTROY
  577. 2018-12-05 22:14:42.472101 [DEBUG] mod_sofia.c:343 sofia/internal/400@192.168.1.249:2048 SOFIA DESTROY
  578. 2018-12-05 22:14:42.472101 [DEBUG] switch_core_state_machine.c:181 sofia/internal/400@192.168.1.249:2048 Standard DESTROY
  579. 2018-12-05 22:14:42.472101 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/400@192.168.1.249:2048) State DESTROY going to sleep
  580. 2018-12-05 22:14:42.512092 [DEBUG] switch_core_state_machine.c:174 sofia/external/06412213225@192.168.1.230:5060 Standard REPORTING, cause: ORIGINATOR_CANCEL
  581. 2018-12-05 22:14:42.512092 [DEBUG] switch_core_state_machine.c:938 (sofia/external/06412213225@192.168.1.230:5060) State REPORTING going to sleep
  582. 2018-12-05 22:14:42.512092 [DEBUG] switch_core_state_machine.c:610 (sofia/external/06412213225@192.168.1.230:5060) State Change CS_REPORTING -> CS_DESTROY
  583. 2018-12-05 22:14:42.512092 [DEBUG] switch_core_session.c:1665 Session 1 (sofia/external/06412213225@192.168.1.230:5060) Locked, Waiting on external entities
  584. 2018-12-05 22:14:42.512092 [NOTICE] switch_core_session.c:1683 Session 1 (sofia/external/06412213225@192.168.1.230:5060) Ended
  585. 2018-12-05 22:14:42.512092 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/06412213225@192.168.1.230:5060 [CS_DESTROY]
  586. 2018-12-05 22:14:42.512092 [DEBUG] switch_core_state_machine.c:741 (sofia/external/06412213225@192.168.1.230:5060) Running State Change CS_DESTROY (Cur 0 Tot 2)
  587. 2018-12-05 22:14:42.512092 [DEBUG] switch_core_state_machine.c:751 (sofia/external/06412213225@192.168.1.230:5060) State DESTROY
  588. 2018-12-05 22:14:42.512092 [DEBUG] mod_sofia.c:343 sofia/external/06412213225@192.168.1.230:5060 SOFIA DESTROY
  589. 2018-12-05 22:14:42.512092 [DEBUG] switch_core_state_machine.c:181 sofia/external/06412213225@192.168.1.230:5060 Standard DESTROY
  590. 2018-12-05 22:14:42.512092 [DEBUG] switch_core_state_machine.c:751 (sofia/external/06412213225@192.168.1.230:5060) State DESTROY going to sleep
  591.  

Reply to "with siptrace"