FreeSWITCH Pastebin

Untitled

From Joshua Young, 6 Years ago, written in Plain Text.
- view diff
URL https://pastebin.freeswitch.org/view/74e8bff5
Embed
Download Paste or View Raw
  1. freeswitch@freeswitch>
  2. 2017-05-09 14:23:49.533653 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1010@192.168.1.8 [e95860dc-cfa6-414d-b52b-b4fd2e30330a]
  3. 2017-05-09 14:23:49.533653 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1010@192.168.1.8) Running State Change CS_NEW (Cur 1 Tot 72)
  4. 2017-05-09 14:23:49.533653 [DEBUG] sofia.c:9834 sofia/internal/1010@192.168.1.8 receiving invite from 192.168.1.213:5060 version: 1.6.17 -34-0fc0946 64bit
  5. 2017-05-09 14:23:49.533653 [DEBUG] sofia.c:10005 IP 192.168.1.213 Rejected by acl "domains". Falling back to Digest auth.
  6. 2017-05-09 14:23:49.533653 [DEBUG] sofia.c:2334 detaching session e95860dc-cfa6-414d-b52b-b4fd2e30330a
  7. 2017-05-09 14:23:49.533653 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1010@192.168.1.8) State NEW
  8. 2017-05-09 14:23:49.543653 [DEBUG] sofia.c:2442 Re-attaching to session e95860dc-cfa6-414d-b52b-b4fd2e30330a
  9. 2017-05-09 14:23:49.553629 [DEBUG] sofia.c:9834 sofia/internal/1010@192.168.1.8 receiving invite from 192.168.1.213:5060 version: 1.6.17 -34-0fc0946 64bit
  10. 2017-05-09 14:23:49.553629 [DEBUG] sofia.c:10005 IP 192.168.1.213 Rejected by acl "domains". Falling back to Digest auth.
  11. 2017-05-09 14:23:49.553629 [DEBUG] sofia.c:7048 Channel sofia/internal/1010@192.168.1.8 entering state [received][100]
  12. 2017-05-09 14:23:49.553629 [DEBUG] sofia.c:7058 Remote SDP:
  13. v=0
  14. o=1010 8000 8001 IN IP4 192.168.1.213
  15. s=SIP Call
  16. c=IN IP4 192.168.1.213
  17. t=0 0
  18. m=audio 5004 RTP/AVP 0 8 4 18 3 2
  19. a=rtpmap:0 PCMU/8000
  20. a=rtpmap:8 PCMA/8000
  21. a=rtpmap:4 G723/8000
  22. a=rtpmap:18 G729/8000
  23. a=rtpmap:3 GSM/8000
  24. a=rtpmap:2 G726-32/8000
  25. a=ptime:20
  26. m=video 5006 RTP/AVP 99
  27. a=rtpmap:99 H264/90000
  28. a=fmtp:99 profile-level-id=428014; packetization-mode=0; sprop-parameter-sets=Z0KADJWgUH5A,aM4Eco==
  29. a=framerate:15
  30.  
  31. 2017-05-09 14:23:49.553629 [DEBUG] sofia.c:7450 (sofia/internal/1010@192.168.1.8) State Change CS_NEW -> CS_INIT
  32. 2017-05-09 14:23:49.553629 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1010@192.168.1.8) Running State Change CS_INIT (Cur 1 Tot 72)
  33. 2017-05-09 14:23:49.553629 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1010@192.168.1.8) State INIT
  34. 2017-05-09 14:23:49.553629 [DEBUG] mod_sofia.c:90 sofia/internal/1010@192.168.1.8 SOFIA INIT
  35. 2017-05-09 14:23:49.553629 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1010@192.168.1.8 Standard INIT
  36. 2017-05-09 14:23:49.553629 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1010@192.168.1.8) State Change CS_INIT -> CS_ROUTING
  37. 2017-05-09 14:23:49.553629 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1010@192.168.1.8) State INIT going to sleep
  38. 2017-05-09 14:23:49.553629 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1010@192.168.1.8) Running State Change CS_ROUTING (Cur 1 Tot 72)
  39. 2017-05-09 14:23:49.553629 [DEBUG] switch_channel.c:2249 (sofia/internal/1010@192.168.1.8) Callstate Change DOWN -> RINGING
  40. 2017-05-09 14:23:49.553629 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1010@192.168.1.8) State ROUTING
  41. 2017-05-09 14:23:49.553629 [DEBUG] mod_sofia.c:143 sofia/internal/1010@192.168.1.8 SOFIA ROUTING
  42. 2017-05-09 14:23:49.553629 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1010@192.168.1.8 Standard ROUTING
  43. 2017-05-09 14:23:49.553629 [INFO] mod_dialplan_xml.c:637 Processing 1010 <1010>->1005 in context default
  44. Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->unloop] continue=false
  45. Dialplan: sofia/internal/1010@192.168.1.8 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
  46. Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
  47. Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->tod_example] continue=true
  48. Dialplan: sofia/internal/1010@192.168.1.8 Date/Time Match (PASS) [tod_example] break=on-false
  49. Dialplan: sofia/internal/1010@192.168.1.8 Action set(open=true)
  50. Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->holiday_example] continue=true
  51. Dialplan: sofia/internal/1010@192.168.1.8 Date/TimeMatch (FAIL) [holiday_example] break=on-false
  52. Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->global-intercept] continue=false
  53. Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [global-intercept] destination_number(1005) =~ /^886$/ break=on-false
  54. Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->group-intercept] continue=false
  55. Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [group-intercept] destination_number(1005) =~ /^\*8$/ break=on-false
  56. Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->intercept-ext] continue=false
  57. Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [intercept-ext] destination_number(1005) =~ /^\*\*(\d+)$/ break=on-false
  58. Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->redial] continue=false
  59. Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [redial] destination_number(1005) =~ /^(redial|870)$/ break=on-false
  60. Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->global] continue=true
  61. Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
  62. Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [global] ${default_password}(12345) =~ /^1234$/ break=never
  63. Dialplan: sofia/internal/1010@192.168.1.8 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
  64. Dialplan: sofia/internal/1010@192.168.1.8 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
  65. Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [global] ${switch_r_sdp}(v=0
  66. o=1010 8000 8001 IN IP4 192.168.1.213
  67. s=SIP Call
  68. c=IN IP4 192.168.1.213
  69. t=0 0
  70. m=audio 5004 RTP/AVP 0 8 4 18 3 2
  71. a=rtpmap:0 PCMU/8000
  72. a=rtpmap:8 PCMA/8000
  73. a=rtpmap:4 G723/8000
  74. a=rtpmap:18 G729/8000
  75. a=rtpmap:3 GSM/8000
  76. a=rtpmap:2 G726-32/8000
  77. a=ptime:20
  78. m=video 5006 RTP/AVP 99
  79. a=rtpmap:99 H264/90000
  80. a=fmtp:99 profile-level-id=428014; packetization-mode=0; sprop-parameter-sets=Z0KADJWgUH5A,aM4Eco==
  81. a=framerate:15
  82. ) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
  83. Dialplan: sofia/internal/1010@192.168.1.8 Absolute Condition [global]
  84. Dialplan: sofia/internal/1010@192.168.1.8 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
  85. Dialplan: sofia/internal/1010@192.168.1.8 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
  86. Dialplan: sofia/internal/1010@192.168.1.8 Action hash(insert/${domain_name}-last_dial/global/${uuid})
  87. Dialplan: sofia/internal/1010@192.168.1.8 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
  88. Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->snom-demo-2] continue=false
  89. Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [snom-demo-2] destination_number(1005) =~ /^9001$/ break=on-false
  90. Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->snom-demo-1] continue=false
  91. Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [snom-demo-1] destination_number(1005) =~ /^9000$/ break=on-false
  92. Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->eavesdrop] continue=false
  93. Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [eavesdrop] destination_number(1005) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
  94. Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->eavesdrop] continue=false
  95. Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [eavesdrop] destination_number(1005) =~ /^779$/ break=on-false
  96. Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->call_return] continue=false
  97. Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [call_return] destination_number(1005) =~ /^\*69$|^869$|^lcr$/ break=on-false
  98. Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->del-group] continue=false
  99. Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [del-group] destination_number(1005) =~ /^80(\d{2})$/ break=on-false
  100. Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->add-group] continue=false
  101. Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [add-group] destination_number(1005) =~ /^81(\d{2})$/ break=on-false
  102. Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->call-group-simo] continue=false
  103. Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [call-group-simo] destination_number(1005) =~ /^82(\d{2})$/ break=on-false
  104. Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->call-group-order] continue=false
  105. Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [call-group-order] destination_number(1005) =~ /^83(\d{2})$/ break=on-false
  106. Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->extension-intercom] continue=false
  107. Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [extension-intercom] destination_number(1005) =~ /^8(10[01][0-9])$/ break=on-false
  108. Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->Local_Extension] continue=false
  109. Dialplan: sofia/internal/1010@192.168.1.8 Regex (PASS) [Local_Extension] destination_number(1005) =~ /^(10[01][0-9])$/ break=on-false
  110. Dialplan: sofia/internal/1010@192.168.1.8 Action export(dialed_extension=1005)
  111. Dialplan: sofia/internal/1010@192.168.1.8 Action bind_meta_app(1 b s execute_extension::dx XML features)
  112. Dialplan: sofia/internal/1010@192.168.1.8 Action bind_meta_app(2 b s record_session::/var/lib/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav)
  113. Dialplan: sofia/internal/1010@192.168.1.8 Action bind_meta_app(3 b s execute_extension::cf XML features)
  114. Dialplan: sofia/internal/1010@192.168.1.8 Action bind_meta_app(4 b s execute_extension::att_xfer XML features)
  115. Dialplan: sofia/internal/1010@192.168.1.8 Action set(ringback=${us-ring})
  116. Dialplan: sofia/internal/1010@192.168.1.8 Action set(transfer_ringback=local_stream://moh)
  117. Dialplan: sofia/internal/1010@192.168.1.8 Action set(call_timeout=30)
  118. Dialplan: sofia/internal/1010@192.168.1.8 Action set(hangup_after_bridge=true)
  119. Dialplan: sofia/internal/1010@192.168.1.8 Action set(continue_on_fail=true)
  120. Dialplan: sofia/internal/1010@192.168.1.8 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
  121. Dialplan: sofia/internal/1010@192.168.1.8 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
  122. Dialplan: sofia/internal/1010@192.168.1.8 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)})
  123. Dialplan: sofia/internal/1010@192.168.1.8 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid})
  124. Dialplan: sofia/internal/1010@192.168.1.8 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid})
  125. Dialplan: sofia/internal/1010@192.168.1.8 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
  126. Dialplan: sofia/internal/1010@192.168.1.8 Action bridge(user/${dialed_extension}@${domain_name})
  127. Dialplan: sofia/internal/1010@192.168.1.8 Action answer()
  128. Dialplan: sofia/internal/1010@192.168.1.8 Action sleep(1000)
  129. Dialplan: sofia/internal/1010@192.168.1.8 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension})
  130. 2017-05-09 14:23:49.563642 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/1010@192.168.1.8) State Change CS_ROUTING -> CS_EXECUTE
  131. 2017-05-09 14:23:49.563642 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1010@192.168.1.8) State ROUTING going to sleep
  132. 2017-05-09 14:23:49.563642 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1010@192.168.1.8) Running State Change CS_EXECUTE (Cur 1 Tot 72)
  133. 2017-05-09 14:23:49.563642 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1010@192.168.1.8) State EXECUTE
  134. 2017-05-09 14:23:49.563642 [DEBUG] mod_sofia.c:198 sofia/internal/1010@192.168.1.8 SOFIA EXECUTE
  135. 2017-05-09 14:23:49.563642 [DEBUG] switch_core_state_machine.c:328 sofia/internal/1010@192.168.1.8 Standard EXECUTE
  136. EXECUTE sofia/internal/1010@192.168.1.8 set(open=true)
  137. 2017-05-09 14:23:49.563642 [DEBUG] mod_dptools.c:1530 SET sofia/internal/1010@192.168.1.8 [open]=[true]
  138. EXECUTE sofia/internal/1010@192.168.1.8 hash(insert/192.168.1.8-spymap/1010/e95860dc-cfa6-414d-b52b-b4fd2e30330a)
  139. EXECUTE sofia/internal/1010@192.168.1.8 hash(insert/192.168.1.8-last_dial/1010/1005)
  140. EXECUTE sofia/internal/1010@192.168.1.8 hash(insert/192.168.1.8-last_dial/global/e95860dc-cfa6-414d-b52b-b4fd2e30330a)
  141. EXECUTE sofia/internal/1010@192.168.1.8 export(RFC2822_DATE=Tue, 09 May 2017 14:23:49 -0400)
  142. 2017-05-09 14:23:49.563642 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Tue, 09 May 2017 14:23:49 -0400]
  143. EXECUTE sofia/internal/1010@192.168.1.8 export(dialed_extension=1005)
  144. 2017-05-09 14:23:49.563642 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[1005]
  145. EXECUTE sofia/internal/1010@192.168.1.8 bind_meta_app(1 b s execute_extension::dx XML features)
  146. 2017-05-09 14:23:49.563642 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *1 execute_extension::dx XML features
  147. EXECUTE sofia/internal/1010@192.168.1.8 bind_meta_app(2 b s record_session::/var/lib/freeswitch/recordings/1010.2017-05-09-14-23-49.wav)
  148. 2017-05-09 14:23:49.563642 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *2 record_session::/var/lib/freeswitch/recordings/1010.2017-05-09-14-23-49.wav
  149. EXECUTE sofia/internal/1010@192.168.1.8 bind_meta_app(3 b s execute_extension::cf XML features)
  150. 2017-05-09 14:23:49.563642 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *3 execute_extension::cf XML features
  151. EXECUTE sofia/internal/1010@192.168.1.8 bind_meta_app(4 b s execute_extension::att_xfer XML features)
  152. 2017-05-09 14:23:49.563642 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *4 execute_extension::att_xfer XML features
  153. EXECUTE sofia/internal/1010@192.168.1.8 set(ringback=%(2000,4000,440,480))
  154. 2017-05-09 14:23:49.563642 [DEBUG] mod_dptools.c:1530 SET sofia/internal/1010@192.168.1.8 [ringback]=[%(2000,4000,440,480)]
  155. EXECUTE sofia/internal/1010@192.168.1.8 set(transfer_ringback=local_stream://moh)
  156. 2017-05-09 14:23:49.563642 [DEBUG] mod_dptools.c:1530 SET sofia/internal/1010@192.168.1.8 [transfer_ringback]=[local_stream://moh]
  157. EXECUTE sofia/internal/1010@192.168.1.8 set(call_timeout=30)
  158. 2017-05-09 14:23:49.563642 [DEBUG] mod_dptools.c:1530 SET sofia/internal/1010@192.168.1.8 [call_timeout]=[30]
  159. EXECUTE sofia/internal/1010@192.168.1.8 set(hangup_after_bridge=true)
  160. 2017-05-09 14:23:49.563642 [DEBUG] mod_dptools.c:1530 SET sofia/internal/1010@192.168.1.8 [hangup_after_bridge]=[true]
  161. EXECUTE sofia/internal/1010@192.168.1.8 set(continue_on_fail=true)
  162. 2017-05-09 14:23:49.563642 [DEBUG] mod_dptools.c:1530 SET sofia/internal/1010@192.168.1.8 [continue_on_fail]=[true]
  163. EXECUTE sofia/internal/1010@192.168.1.8 hash(insert/192.168.1.8-call_return/1005/1010)
  164. EXECUTE sofia/internal/1010@192.168.1.8 hash(insert/192.168.1.8-last_dial_ext/1005/e95860dc-cfa6-414d-b52b-b4fd2e30330a)
  165. EXECUTE sofia/internal/1010@192.168.1.8 set(called_party_callgroup=techsupport)
  166. 2017-05-09 14:23:49.563642 [DEBUG] mod_dptools.c:1530 SET sofia/internal/1010@192.168.1.8 [called_party_callgroup]=[techsupport]
  167. EXECUTE sofia/internal/1010@192.168.1.8 hash(insert/192.168.1.8-last_dial_ext/techsupport/e95860dc-cfa6-414d-b52b-b4fd2e30330a)
  168. EXECUTE sofia/internal/1010@192.168.1.8 hash(insert/192.168.1.8-last_dial_ext/global/e95860dc-cfa6-414d-b52b-b4fd2e30330a)
  169. EXECUTE sofia/internal/1010@192.168.1.8 hash(insert/192.168.1.8-last_dial/techsupport/e95860dc-cfa6-414d-b52b-b4fd2e30330a)
  170. EXECUTE sofia/internal/1010@192.168.1.8 bridge(user/1005@192.168.1.8)
  171. 2017-05-09 14:23:49.563642 [DEBUG] switch_channel.c:1250 sofia/internal/1010@192.168.1.8 EXPORTING[export_vars] [RFC2822_DATE]=[Tue, 09 May 2017 14:23:49 -0400] to event
  172. 2017-05-09 14:23:49.563642 [DEBUG] switch_channel.c:1250 sofia/internal/1010@192.168.1.8 EXPORTING[export_vars] [dialed_extension]=[1005] to event
  173. 2017-05-09 14:23:49.563642 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
  174. 2017-05-09 14:23:49.563642 [DEBUG] switch_channel.c:1250 sofia/internal/1010@192.168.1.8 EXPORTING[export_vars] [RFC2822_DATE]=[Tue, 09 May 2017 14:23:49 -0400] to event
  175. 2017-05-09 14:23:49.563642 [DEBUG] switch_channel.c:1250 sofia/internal/1010@192.168.1.8 EXPORTING[export_vars] [dialed_extension]=[1005] to event
  176. 2017-05-09 14:23:49.563642 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
  177. 2017-05-09 14:23:49.563642 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1005@192.168.1.46:36346 [7c5ea937-e572-434b-943e-13415cb59b2f]
  178. 2017-05-09 14:23:49.563642 [DEBUG] mod_sofia.c:4818 (sofia/internal/1005@192.168.1.46:36346) State Change CS_NEW -> CS_INIT
  179. 2017-05-09 14:23:49.563642 [NOTICE] switch_ivr_originate.c:2845 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
  180. 2017-05-09 14:23:49.563642 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1005@192.168.1.46:36346) Running State Change CS_INIT (Cur 2 Tot 73)
  181. 2017-05-09 14:23:49.563642 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1005@192.168.1.46:36346) State INIT
  182. 2017-05-09 14:23:49.563642 [DEBUG] mod_sofia.c:90 sofia/internal/1005@192.168.1.46:36346 SOFIA INIT
  183. 2017-05-09 14:23:49.563642 [DEBUG] sofia_glue.c:1295 sofia/internal/1005@192.168.1.46:36346 sending invite version: 1.6.17 -34-0fc0946 64bit
  184. Local SDP:
  185. v=0
  186. o=FreeSWITCH 1494323881 1494323882 IN IP4 192.168.1.8
  187. s=FreeSWITCH
  188. c=IN IP4 192.168.1.8
  189. t=0 0
  190. m=audio 30348 RTP/AVP 0 8 101
  191. a=rtpmap:0 PCMU/8000
  192. a=rtpmap:8 PCMA/8000
  193. a=rtpmap:101 telephone-event/8000
  194. a=fmtp:101 0-16
  195. a=ptime:20
  196. a=sendrecv
  197. m=video 17476 RTP/AVP 102
  198. b=AS:1024
  199. a=rtpmap:102 H264/90000
  200. a=fmtp:102 profile-level-id=428014; packetization-mode=0; sprop-parameter-sets=Z0KADJWgUH5A
  201. a=rtcp-fb:102 ccm fir
  202. a=rtcp-fb:102 ccm tmmbr
  203. a=rtcp-fb:102 nack
  204. a=rtcp-fb:102 nack pli
  205.  
  206. 2017-05-09 14:23:49.563642 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1005@192.168.1.46:36346 Standard INIT
  207. 2017-05-09 14:23:49.563642 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1005@192.168.1.46:36346) State Change CS_INIT -> CS_ROUTING
  208. 2017-05-09 14:23:49.563642 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1005@192.168.1.46:36346) State INIT going to sleep
  209. 2017-05-09 14:23:49.563642 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1005@192.168.1.46:36346) Running State Change CS_ROUTING (Cur 2 Tot 73)
  210. 2017-05-09 14:23:49.563642 [DEBUG] sofia.c:7048 Channel sofia/internal/1005@192.168.1.46:36346 entering state [calling][0]
  211. 2017-05-09 14:23:49.563642 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1005@192.168.1.46:36346) State ROUTING
  212. 2017-05-09 14:23:49.563642 [DEBUG] mod_sofia.c:143 sofia/internal/1005@192.168.1.46:36346 SOFIA ROUTING
  213. 2017-05-09 14:23:49.563642 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1005@192.168.1.46:36346) State Change CS_ROUTING -> CS_CONSUME_MEDIA
  214. 2017-05-09 14:23:49.563642 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1005@192.168.1.46:36346) State ROUTING going to sleep
  215. 2017-05-09 14:23:49.573660 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1005@192.168.1.46:36346) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 73)
  216. 2017-05-09 14:23:49.573660 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1005@192.168.1.46:36346) State CONSUME_MEDIA
  217. 2017-05-09 14:23:49.573660 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1005@192.168.1.46:36346) State CONSUME_MEDIA going to sleep
  218. 2017-05-09 14:23:49.633667 [DEBUG] sofia.c:7048 Channel sofia/internal/1005@192.168.1.46:36346 entering state [terminated][503]
  219. 2017-05-09 14:23:49.633667 [NOTICE] sofia.c:8237 Hangup sofia/internal/1005@192.168.1.46:36346 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE]
  220. 2017-05-09 14:23:49.633667 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1005@192.168.1.46:36346) Running State Change CS_HANGUP (Cur 2 Tot 73)
  221. 2017-05-09 14:23:49.633667 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1005@192.168.1.46:36346) Callstate Change DOWN -> HANGUP
  222. 2017-05-09 14:23:49.633667 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1005@192.168.1.46:36346) State HANGUP
  223. 2017-05-09 14:23:49.633667 [DEBUG] mod_sofia.c:438 Channel sofia/internal/1005@192.168.1.46:36346 hanging up, cause: NORMAL_TEMPORARY_FAILURE
  224. 2017-05-09 14:23:49.633667 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1005@192.168.1.46:36346 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
  225. 2017-05-09 14:23:49.633667 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1005@192.168.1.46:36346) State HANGUP going to sleep
  226. 2017-05-09 14:23:49.633667 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1005@192.168.1.46:36346) State Change CS_HANGUP -> CS_REPORTING
  227. 2017-05-09 14:23:49.633667 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1005@192.168.1.46:36346) Running State Change CS_REPORTING (Cur 2 Tot 73)
  228. 2017-05-09 14:23:49.633667 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1005@192.168.1.46:36346) State REPORTING
  229. 2017-05-09 14:23:49.633667 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1005@192.168.1.46:36346 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE
  230. 2017-05-09 14:23:49.633667 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1005@192.168.1.46:36346) State REPORTING going to sleep
  231. 2017-05-09 14:23:49.633667 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1005@192.168.1.46:36346) State Change CS_REPORTING -> CS_DESTROY
  232. 2017-05-09 14:23:49.633667 [DEBUG] switch_core_session.c:1664 Session 73 (sofia/internal/1005@192.168.1.46:36346) Locked, Waiting on external entities
  233. 2017-05-09 14:23:49.653641 [DEBUG] switch_ivr_originate.c:3833 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
  234. 2017-05-09 14:23:49.653641 [NOTICE] switch_ivr_originate.c:2845 Cannot create outgoing channel of type [user] cause: [NORMAL_TEMPORARY_FAILURE]
  235. 2017-05-09 14:23:49.653641 [DEBUG] switch_ivr_originate.c:3833 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
  236. 2017-05-09 14:23:49.653641 [INFO] mod_dptools.c:3418 Originate Failed.  Cause: NORMAL_TEMPORARY_FAILURE
  237. EXECUTE sofia/internal/1010@192.168.1.8 answer()
  238. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
  239. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  240. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  241. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
  242. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  243. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
  244. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  245. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  246. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  247. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
  248. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G723:4:8000:20:6300:1]/[opus:116:48000:20:0:1]
  249. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G723:4:8000:20:6300:1]/[G722:9:8000:20:64000:1]
  250. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMU:0:8000:20:64000:1]
  251. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMA:8:8000:20:64000:1]
  252. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1]
  253. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
  254. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
  255. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
  256. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [GSM:3:8000:20:13200:1]/[opus:116:48000:20:0:1]
  257. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
  258. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
  259. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
  260. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G726-32:2:8000:20:0:1]/[opus:116:48000:20:0:1]
  261. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G726-32:2:8000:20:0:1]/[G722:9:8000:20:64000:1]
  262. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G726-32:2:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
  263. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G726-32:2:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
  264. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:3056 Set Codec sofia/internal/1010@192.168.1.8 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
  265. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_codec.c:111 sofia/internal/1010@192.168.1.8 Original read codec set to PCMU:0
  266. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4725 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event.
  267. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4754 sofia/internal/1010@192.168.1.8 Set 2833 dtmf send payload to 101 recv payload to 101
  268. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4937 Video Codec Compare [H264:99]/[VP8:99]
  269. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4937 Video Codec Compare [H264:99]/[H264:99]
  270. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4969 Video Codec Compare [H264:99] +++ is saved as a match
  271. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:4937 Video Codec Compare [H264:99]/[H263:34]
  272. 2017-05-09 14:23:49.653641 [NOTICE] avcodec.c:1011 codec: id=28 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
  273. 2017-05-09 14:23:49.653641 [NOTICE] avcodec.c:1011 codec: id=28 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
  274. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:2866 Set VIDEO Codec sofia/internal/1010@192.168.1.8 H264/90000 0 ms
  275. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:6865 AUDIO RTP [sofia/internal/1010@192.168.1.8] 192.168.1.8 port 31124 -> 192.168.1.213 port 5004 codec: 0 ms: 20
  276. 2017-05-09 14:23:49.653641 [NOTICE] switch_core_session.c:1682 Session 73 (sofia/internal/1005@192.168.1.46:36346) Ended
  277. 2017-05-09 14:23:49.653641 [NOTICE] switch_core_session.c:1686 Close Channel sofia/internal/1005@192.168.1.46:36346 [CS_DESTROY]
  278. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1005@192.168.1.46:36346) Running State Change CS_DESTROY (Cur 1 Tot 73)
  279. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1005@192.168.1.46:36346) State DESTROY
  280. 2017-05-09 14:23:49.653641 [DEBUG] mod_sofia.c:343 sofia/internal/1005@192.168.1.46:36346 SOFIA DESTROY
  281. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1005@192.168.1.46:36346 Standard DESTROY
  282. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1005@192.168.1.46:36346) State DESTROY going to sleep
  283. 2017-05-09 14:23:49.653641 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms
  284. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:7166 sofia/internal/1010@192.168.1.8 Set 2833 dtmf send payload to 101
  285. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:7173 sofia/internal/1010@192.168.1.8 Set 2833 dtmf receive payload to 101
  286. 2017-05-09 14:23:49.653641 [DEBUG] switch_core_media.c:7196 sofia/internal/1010@192.168.1.8 Set rtp dtmf delay to 40
  287. 2017-05-09 14:23:49.653641 [DEBUG] switch_rtp.c:4107 Starting video timer.
  288. 2017-05-09 14:23:49.663713 [DEBUG] switch_core_media.c:7385 VIDEO RTP [sofia/internal/1010@192.168.1.8] 192.168.1.8:28494->192.168.1.213:5006 codec: 99 ms: 0 [SUCCESS]
  289. 2017-05-09 14:23:49.663713 [DEBUG] switch_core_media.c:5990 sofia/internal/1010@192.168.1.8 Starting Video thread
  290. 2017-05-09 14:23:49.663713 [DEBUG] switch_core_media.c:5856 sofia/internal/1010@192.168.1.8 Video thread started. Echo is off
  291. 2017-05-09 14:23:49.663713 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1010@192.168.1.8!
  292. 2017-05-09 14:23:49.663713 [DEBUG] switch_channel.c:3473 (sofia/internal/1010@192.168.1.8) Callstate Change RINGING -> EARLY
  293. 2017-05-09 14:23:49.663713 [DEBUG] switch_core_media.c:6848 Audio params are unchanged for sofia/internal/1010@192.168.1.8.
  294. 2017-05-09 14:23:49.663713 [DEBUG] switch_core_media.c:7243 Video params are unchanged for sofia/internal/1010@192.168.1.8.
  295. 2017-05-09 14:23:49.663713 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/1010@192.168.1.8:
  296. v=0
  297. o=FreeSWITCH 1494323105 1494323106 IN IP4 192.168.1.8
  298. s=FreeSWITCH
  299. c=IN IP4 192.168.1.8
  300. t=0 0
  301. m=audio 31124 RTP/AVP 0 101
  302. a=rtpmap:0 PCMU/8000
  303. a=rtpmap:101 telephone-event/8000
  304. a=fmtp:101 0-16
  305. a=ptime:20
  306. a=sendrecv
  307. m=video 28494 RTP/AVP 99
  308. b=AS:1024
  309. a=rtpmap:99 H264/90000
  310. a=fmtp:99 profile-level-id=428014; packetization-mode=0; sprop-parameter-sets=Z0KADJWgUH5A,aM4Eco==
  311.  
  312. 2017-05-09 14:23:49.663713 [DEBUG] sofia.c:7048 Channel sofia/internal/1010@192.168.1.8 entering state [completed][200]
  313. 2017-05-09 14:23:49.663713 [NOTICE] mod_dptools.c:1312 Channel [sofia/internal/1010@192.168.1.8] has been answered
  314. 2017-05-09 14:23:49.663713 [DEBUG] switch_channel.c:3772 (sofia/internal/1010@192.168.1.8) Callstate Change EARLY -> ACTIVE
  315. EXECUTE sofia/internal/1010@192.168.1.8 sleep(1000)
  316. 2017-05-09 14:23:49.673541 [DEBUG] sofia.c:7048 Channel sofia/internal/1010@192.168.1.8 entering state [ready][200]
  317. 2017-05-09 14:23:49.683665 [INFO] avcodec.c:1069 initializing encoder 352x288
  318. 2017-05-09 14:23:49.683665 [DEBUG] avcodec.c:831 NVENC HW CODEC NOT PRESENT
  319. 2017-05-09 14:23:49.693707 [DEBUG] switch_rtp.c:7229 Correct audio ip/port confirmed.
  320. 2017-05-09 14:23:50.253748 [DEBUG] switch_rtp.c:7229 Correct video ip/port confirmed.
  321. EXECUTE sofia/internal/1010@192.168.1.8 bridge(loopback/app=voicemail:default 192.168.1.8 1005)
  322. 2017-05-09 14:23:50.673830 [DEBUG] switch_channel.c:1823 (sofia/internal/1010@192.168.1.8) Callstate Change ACTIVE -> RING_WAIT
  323. 2017-05-09 14:23:50.673830 [DEBUG] switch_channel.c:1250 sofia/internal/1010@192.168.1.8 EXPORTING[export_vars] [RFC2822_DATE]=[Tue, 09 May 2017 14:23:49 -0400] to event
  324. 2017-05-09 14:23:50.673830 [DEBUG] switch_channel.c:1250 sofia/internal/1010@192.168.1.8 EXPORTING[export_vars] [dialed_extension]=[1005] to event
  325. 2017-05-09 14:23:50.673830 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
  326. 2017-05-09 14:23:50.673830 [NOTICE] switch_channel.c:1104 New Channel loopback/app=voicemail:default 192.168.1.8 1005-a [70374c30-c004-4aba-ac45-0035fb7a2c6e]
  327. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:158 loopback/app=voicemail:default 192.168.1.8 1005-a setup codec PCMU/8000/20
  328. 2017-05-09 14:23:50.673830 [NOTICE] switch_channel.c:1102 Rename Channel loopback/app=voicemail:default 192.168.1.8 1005-a->loopback/voicemail-a [70374c30-c004-4aba-ac45-0035fb7a2c6e]
  329. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:1174 (loopback/voicemail-a) State Change CS_NEW -> CS_INIT
  330. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:601 loopback/voicemail-a CHANNEL KILL
  331. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_INIT (Cur 2 Tot 74)
  332. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:627 (loopback/voicemail-a) State INIT
  333. 2017-05-09 14:23:50.673830 [NOTICE] switch_channel.c:1104 New Channel loopback/voicemail-b [0edd3f95-2892-4470-b470-fea551b09229]
  334. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:158 loopback/voicemail-b setup codec PCMU/8000/20
  335. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:276 (loopback/voicemail-b) State Change CS_NEW -> CS_INIT
  336. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:601 loopback/voicemail-b CHANNEL KILL
  337. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:362 (loopback/voicemail-a) State Change CS_INIT -> CS_ROUTING
  338. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:601 loopback/voicemail-a CHANNEL KILL
  339. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:627 (loopback/voicemail-a) State INIT going to sleep
  340. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_ROUTING (Cur 3 Tot 75)
  341. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:643 (loopback/voicemail-a) State ROUTING
  342. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:394 loopback/voicemail-a CHANNEL ROUTING
  343. 2017-05-09 14:23:50.673830 [DEBUG] switch_ivr_originate.c:67 (loopback/voicemail-a) State Change CS_ROUTING -> CS_CONSUME_MEDIA
  344. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:601 loopback/voicemail-a CHANNEL KILL
  345. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:643 (loopback/voicemail-a) State ROUTING going to sleep
  346. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_CONSUME_MEDIA (Cur 3 Tot 75)
  347. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:662 (loopback/voicemail-a) State CONSUME_MEDIA
  348. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:661 CHANNEL CONSUME_MEDIA
  349. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:662 (loopback/voicemail-a) State CONSUME_MEDIA going to sleep
  350. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_INIT (Cur 3 Tot 75)
  351. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:627 (loopback/voicemail-b) State INIT
  352. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:362 (loopback/voicemail-b) State Change CS_INIT -> CS_ROUTING
  353. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:601 loopback/voicemail-b CHANNEL KILL
  354. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:627 (loopback/voicemail-b) State INIT going to sleep
  355. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_ROUTING (Cur 3 Tot 75)
  356. 2017-05-09 14:23:50.673830 [DEBUG] switch_channel.c:2249 (loopback/voicemail-b) Callstate Change DOWN -> RINGING
  357. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:643 (loopback/voicemail-b) State ROUTING
  358. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:394 loopback/voicemail-b CHANNEL ROUTING
  359. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:413 (loopback/voicemail-b) State Change CS_ROUTING -> CS_EXECUTE
  360. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:601 loopback/voicemail-b CHANNEL KILL
  361. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:643 (loopback/voicemail-b) State ROUTING going to sleep
  362. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_EXECUTE (Cur 3 Tot 75)
  363. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:650 (loopback/voicemail-b) State EXECUTE
  364. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:436 loopback/voicemail-b CHANNEL EXECUTE
  365. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:328 loopback/voicemail-b Standard EXECUTE
  366. EXECUTE loopback/voicemail-b pre_answer()
  367. 2017-05-09 14:23:50.673830 [NOTICE] mod_loopback.c:961 Pre-Answer loopback/voicemail-a!
  368. 2017-05-09 14:23:50.673830 [DEBUG] switch_channel.c:3473 (loopback/voicemail-a) Callstate Change DOWN -> EARLY
  369. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:601 loopback/voicemail-b CHANNEL KILL
  370. 2017-05-09 14:23:50.673830 [NOTICE] mod_dptools.c:1355 Pre-Answer loopback/voicemail-b!
  371. 2017-05-09 14:23:50.673830 [DEBUG] switch_channel.c:3473 (loopback/voicemail-b) Callstate Change RINGING -> EARLY
  372. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:601 loopback/voicemail-b CHANNEL KILL
  373. EXECUTE loopback/voicemail-b voicemail(default 192.168.1.8 1005)
  374. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:601 loopback/voicemail-b CHANNEL KILL
  375. 2017-05-09 14:23:50.673830 [DEBUG] switch_ivr_originate.c:3690 Originate Resulted in Success: [loopback/voicemail-a]
  376. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:601 loopback/voicemail-a CHANNEL KILL
  377. 2017-05-09 14:23:50.673830 [DEBUG] switch_channel.c:2047 (sofia/internal/1010@192.168.1.8) Callstate Change RING_WAIT -> ACTIVE
  378. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:601 loopback/voicemail-a CHANNEL KILL
  379. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:601 loopback/voicemail-a CHANNEL KILL
  380. 2017-05-09 14:23:50.673830 [DEBUG] switch_ivr_bridge.c:1601 (loopback/voicemail-a) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
  381. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:601 loopback/voicemail-a CHANNEL KILL
  382. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_EXCHANGE_MEDIA (Cur 3 Tot 75)
  383. 2017-05-09 14:23:50.673830 [DEBUG] switch_core_state_machine.c:653 (loopback/voicemail-a) State EXCHANGE_MEDIA
  384. 2017-05-09 14:23:50.673830 [DEBUG] mod_loopback.c:623 CHANNEL LOOPBACK
  385. 2017-05-09 14:23:50.783835 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]
  386. 2017-05-09 14:23:50.803820 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-person.wav] (en:en)
  387. 2017-05-09 14:23:50.803820 [DEBUG] mod_loopback.c:601 loopback/voicemail-b CHANNEL KILL
  388. 2017-05-09 14:23:50.803820 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
  389. 2017-05-09 14:23:52.153544 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/share/freeswitch/sounds/en/us/callie/voicemail/vm-person.wav
  390. 2017-05-09 14:23:52.273536 [DEBUG] switch_ivr_play_say.c:250 Handle say:[1005] (en:en)
  391. 2017-05-09 14:23:52.273536 [DEBUG] mod_loopback.c:601 loopback/voicemail-b CHANNEL KILL
  392. 2017-05-09 14:23:52.273536 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
  393. 2017-05-09 14:23:54.553537 [DEBUG] switch_ivr_play_say.c:1942 done playing file file_string://digits/1.wav!digits/0.wav!digits/0.wav!digits/5.wav
  394. 2017-05-09 14:23:54.663842 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-not_available.wav] (en:en)
  395. 2017-05-09 14:23:54.663842 [DEBUG] mod_loopback.c:601 loopback/voicemail-b CHANNEL KILL
  396. 2017-05-09 14:23:54.663842 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
  397. 2017-05-09 14:23:55.093719 [NOTICE] sofia.c:1012 Hangup sofia/internal/1010@192.168.1.8 [CS_EXECUTE] [NORMAL_CLEARING]
  398. 2017-05-09 14:23:55.093719 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/1010@192.168.1.8]
  399. 2017-05-09 14:23:55.093719 [DEBUG] mod_loopback.c:601 loopback/voicemail-a CHANNEL KILL
  400. 2017-05-09 14:23:55.093719 [DEBUG] switch_core_media.c:11605 sofia/internal/1010@192.168.1.8 skip receive message [VIDEO_REFRESH_REQ] (channel is hungup already)
  401. 2017-05-09 14:23:55.093719 [DEBUG] switch_ivr_bridge.c:706 sofia/internal/1010@192.168.1.8 ending bridge by request from write function
  402. 2017-05-09 14:23:55.093719 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [loopback/voicemail-a]
  403. 2017-05-09 14:23:55.093719 [NOTICE] switch_ivr_bridge.c:889 Hangup loopback/voicemail-a [CS_EXCHANGE_MEDIA] [ORIGINATOR_CANCEL]
  404. 2017-05-09 14:23:55.093719 [DEBUG] mod_loopback.c:601 loopback/voicemail-a CHANNEL KILL
  405. 2017-05-09 14:23:55.093719 [DEBUG] mod_loopback.c:601 loopback/voicemail-a CHANNEL KILL
  406. 2017-05-09 14:23:55.093719 [DEBUG] switch_core_state_machine.c:653 (loopback/voicemail-a) State EXCHANGE_MEDIA going to sleep
  407. 2017-05-09 14:23:55.093719 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_HANGUP (Cur 3 Tot 75)
  408. 2017-05-09 14:23:55.093719 [DEBUG] switch_core_state_machine.c:850 (loopback/voicemail-a) Callstate Change EARLY -> HANGUP
  409. 2017-05-09 14:23:55.093719 [DEBUG] switch_core_state_machine.c:852 (loopback/voicemail-a) State HANGUP
  410. 2017-05-09 14:23:55.093719 [DEBUG] mod_loopback.c:548 loopback/voicemail-a CHANNEL HANGUP
  411. 2017-05-09 14:23:55.093719 [NOTICE] mod_loopback.c:564 Hangup loopback/voicemail-b [CS_EXECUTE] [ORIGINATOR_CANCEL]
  412. 2017-05-09 14:23:55.093719 [DEBUG] mod_loopback.c:601 loopback/voicemail-b CHANNEL KILL
  413. 2017-05-09 14:23:55.093719 [DEBUG] mod_loopback.c:601 loopback/voicemail-b CHANNEL KILL
  414. 2017-05-09 14:23:55.093719 [DEBUG] switch_core_state_machine.c:60 loopback/voicemail-a Standard HANGUP, cause: ORIGINATOR_CANCEL
  415. 2017-05-09 14:23:55.093719 [DEBUG] switch_core_state_machine.c:852 (loopback/voicemail-a) State HANGUP going to sleep
  416. 2017-05-09 14:23:55.093719 [DEBUG] switch_core_state_machine.c:619 (loopback/voicemail-a) State Change CS_HANGUP -> CS_REPORTING
  417. 2017-05-09 14:23:55.093719 [DEBUG] mod_loopback.c:601 loopback/voicemail-a CHANNEL KILL
  418. 2017-05-09 14:23:55.093719 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_REPORTING (Cur 3 Tot 75)
  419. 2017-05-09 14:23:55.093719 [DEBUG] switch_core_state_machine.c:938 (loopback/voicemail-a) State REPORTING
  420. 2017-05-09 14:23:55.093719 [DEBUG] switch_core_state_machine.c:174 loopback/voicemail-a Standard REPORTING, cause: ORIGINATOR_CANCEL
  421. 2017-05-09 14:23:55.093719 [DEBUG] switch_core_state_machine.c:938 (loopback/voicemail-a) State REPORTING going to sleep
  422. 2017-05-09 14:23:55.093719 [DEBUG] switch_core_state_machine.c:610 (loopback/voicemail-a) State Change CS_REPORTING -> CS_DESTROY
  423. 2017-05-09 14:23:55.093719 [DEBUG] mod_loopback.c:601 loopback/voicemail-a CHANNEL KILL
  424. 2017-05-09 14:23:55.093719 [DEBUG] switch_core_session.c:1664 Session 74 (loopback/voicemail-a) Locked, Waiting on external entities
  425. 2017-05-09 14:23:55.093719 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/share/freeswitch/sounds/en/us/callie/voicemail/vm-not_available.wav
  426. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_session.c:2814 loopback/voicemail-b skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
  427. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:650 (loopback/voicemail-b) State EXECUTE going to sleep
  428. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_HANGUP (Cur 3 Tot 75)
  429. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:850 (loopback/voicemail-b) Callstate Change EARLY -> HANGUP
  430. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:852 (loopback/voicemail-b) State HANGUP
  431. 2017-05-09 14:23:55.103863 [DEBUG] mod_loopback.c:548 loopback/voicemail-b CHANNEL HANGUP
  432. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:60 loopback/voicemail-b Standard HANGUP, cause: ORIGINATOR_CANCEL
  433. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:852 (loopback/voicemail-b) State HANGUP going to sleep
  434. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:619 (loopback/voicemail-b) State Change CS_HANGUP -> CS_REPORTING
  435. 2017-05-09 14:23:55.103863 [DEBUG] mod_loopback.c:601 loopback/voicemail-b CHANNEL KILL
  436. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_REPORTING (Cur 3 Tot 75)
  437. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:938 (loopback/voicemail-b) State REPORTING
  438. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:174 loopback/voicemail-b Standard REPORTING, cause: ORIGINATOR_CANCEL
  439. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:938 (loopback/voicemail-b) State REPORTING going to sleep
  440. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:610 (loopback/voicemail-b) State Change CS_REPORTING -> CS_DESTROY
  441. 2017-05-09 14:23:55.103863 [DEBUG] mod_loopback.c:601 loopback/voicemail-b CHANNEL KILL
  442. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_session.c:1664 Session 75 (loopback/voicemail-b) Locked, Waiting on external entities
  443. 2017-05-09 14:23:55.103863 [NOTICE] switch_core_session.c:1682 Session 75 (loopback/voicemail-b) Ended
  444. 2017-05-09 14:23:55.103863 [NOTICE] switch_core_session.c:1686 Close Channel loopback/voicemail-b [CS_DESTROY]
  445. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:741 (loopback/voicemail-b) Running State Change CS_DESTROY (Cur 2 Tot 75)
  446. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:751 (loopback/voicemail-b) State DESTROY
  447. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:181 loopback/voicemail-b Standard DESTROY
  448. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:751 (loopback/voicemail-b) State DESTROY going to sleep
  449. 2017-05-09 14:23:55.103863 [DEBUG] switch_ivr_bridge.c:1702 sofia/internal/1010@192.168.1.8 skip receive message [UNBRIDGE] (channel is hungup already)
  450. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_session.c:2814 sofia/internal/1010@192.168.1.8 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
  451. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1010@192.168.1.8) State EXECUTE going to sleep
  452. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1010@192.168.1.8) Running State Change CS_HANGUP (Cur 2 Tot 75)
  453. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1010@192.168.1.8) Callstate Change ACTIVE -> HANGUP
  454. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1010@192.168.1.8) State HANGUP
  455. 2017-05-09 14:23:55.103863 [DEBUG] mod_sofia.c:432 sofia/internal/1010@192.168.1.8 Overriding SIP cause 480 with 503 from the other leg
  456. 2017-05-09 14:23:55.103863 [DEBUG] mod_sofia.c:438 Channel sofia/internal/1010@192.168.1.8 hanging up, cause: NORMAL_CLEARING
  457. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1010@192.168.1.8 Standard HANGUP, cause: NORMAL_CLEARING
  458. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1010@192.168.1.8) State HANGUP going to sleep
  459. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1010@192.168.1.8) State Change CS_HANGUP -> CS_REPORTING
  460. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1010@192.168.1.8) Running State Change CS_REPORTING (Cur 2 Tot 75)
  461. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1010@192.168.1.8) State REPORTING
  462. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1010@192.168.1.8 Standard REPORTING, cause: NORMAL_CLEARING
  463. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1010@192.168.1.8) State REPORTING going to sleep
  464. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1010@192.168.1.8) State Change CS_REPORTING -> CS_DESTROY
  465. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_session.c:1664 Session 72 (sofia/internal/1010@192.168.1.8) Locked, Waiting on external entities
  466. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_media.c:5957 sofia/internal/1010@192.168.1.8 Video thread ended
  467. 2017-05-09 14:23:55.103863 [NOTICE] switch_core_session.c:1682 Session 74 (loopback/voicemail-a) Ended
  468. 2017-05-09 14:23:55.103863 [NOTICE] switch_core_session.c:1686 Close Channel loopback/voicemail-a [CS_DESTROY]
  469. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:741 (loopback/voicemail-a) Running State Change CS_DESTROY (Cur 1 Tot 75)
  470. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:751 (loopback/voicemail-a) State DESTROY
  471. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:181 loopback/voicemail-a Standard DESTROY
  472. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:751 (loopback/voicemail-a) State DESTROY going to sleep
  473. 2017-05-09 14:23:55.103863 [NOTICE] switch_core_session.c:1682 Session 72 (sofia/internal/1010@192.168.1.8) Ended
  474. 2017-05-09 14:23:55.103863 [NOTICE] switch_core_session.c:1686 Close Channel sofia/internal/1010@192.168.1.8 [CS_DESTROY]
  475. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1010@192.168.1.8) Running State Change CS_DESTROY (Cur 0 Tot 75)
  476. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1010@192.168.1.8) State DESTROY
  477. 2017-05-09 14:23:55.103863 [DEBUG] mod_sofia.c:343 sofia/internal/1010@192.168.1.8 SOFIA DESTROY
  478. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1010@192.168.1.8 Standard DESTROY
  479. 2017-05-09 14:23:55.103863 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1010@192.168.1.8) State DESTROY going to sleep
  480. freeswitch@freeswitch>
  481.  

Reply to "Untitled"