From awalin, 7 Years ago, written in Plain Text.
- view diff
Embed
  1. 2017-03-14 16:10:15.227400 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1002@192.168.0.104:5060 [693e04e7-7fe7-414b-ac7c-74bdc3422141]
  2. 2017-03-14 16:10:15.227400 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@192.168.0.104:5060) Running State Change CS_NEW (Cur 1 Tot 16)
  3. 2017-03-14 16:10:15.227400 [DEBUG] sofia.c:10016 sofia/internal/1002@192.168.0.104:5060 receiving invite from 192.168.0.105:59753 version: 1.9.0 git 91d62b7 2017-02-24 22:49:43Z 64bit
  4. 2017-03-14 16:10:15.227400 [DEBUG] sofia.c:10187 IP 192.168.0.105 Rejected by acl "domains". Falling back to Digest auth.
  5. 2017-03-14 16:10:15.227400 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1002@192.168.0.104:5060) State NEW
  6. 2017-03-14 16:10:15.237401 [DEBUG] sofia.c:2405 detaching session 693e04e7-7fe7-414b-ac7c-74bdc3422141
  7. 2017-03-14 16:10:15.237401 [DEBUG] sofia.c:2514 Re-attaching to session 693e04e7-7fe7-414b-ac7c-74bdc3422141
  8. 2017-03-14 16:10:15.247407 [DEBUG] sofia.c:10016 sofia/internal/1002@192.168.0.104:5060 receiving invite from 192.168.0.105:59753 version: 1.9.0 git 91d62b7 2017-02-24 22:49:43Z 64bit
  9. 2017-03-14 16:10:15.257443 [DEBUG] sofia.c:10187 IP 192.168.0.105 Rejected by acl "domains". Falling back to Digest auth.
  10. 2017-03-14 16:10:15.257443 [DEBUG] sofia.c:7241 Channel sofia/internal/1002@192.168.0.104:5060 entering state [received][100]
  11. 2017-03-14 16:10:15.257443 [DEBUG] sofia.c:7251 Remote SDP:
  12. v=0
  13. o=Zoiper 0 0 IN IP4 192.168.0.105
  14. s=Zoiper
  15. c=IN IP4 192.168.0.105
  16. t=0 0
  17. m=audio 54518 RTP/AVP 3 0 8 101
  18. a=rtpmap:3 GSM/8000
  19. a=rtpmap:0 PCMU/8000
  20. a=rtpmap:8 PCMA/8000
  21. a=rtpmap:101 telephone-event/8000
  22. a=fmtp:101 0-16
  23.  
  24. 2017-03-14 16:10:15.257443 [DEBUG] sofia.c:7643 (sofia/internal/1002@192.168.0.104:5060) State Change CS_NEW -> CS_INIT
  25. 2017-03-14 16:10:15.257443 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@192.168.0.104:5060) Running State Change CS_INIT (Cur 1 Tot 16)
  26. 2017-03-14 16:10:15.257443 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1002@192.168.0.104:5060) State INIT
  27. 2017-03-14 16:10:15.257443 [DEBUG] mod_sofia.c:93 sofia/internal/1002@192.168.0.104:5060 SOFIA INIT
  28. 2017-03-14 16:10:15.257443 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1002@192.168.0.104:5060 Standard INIT
  29. 2017-03-14 16:10:15.257443 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1002@192.168.0.104:5060) State Change CS_INIT -> CS_ROUTING
  30. 2017-03-14 16:10:15.257443 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1002@192.168.0.104:5060) State INIT going to sleep
  31. 2017-03-14 16:10:15.257443 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@192.168.0.104:5060) Running State Change CS_ROUTING (Cur 1 Tot 16)
  32. 2017-03-14 16:10:15.257443 [DEBUG] switch_channel.c:2249 (sofia/internal/1002@192.168.0.104:5060) Callstate Change DOWN -> RINGING
  33. 2017-03-14 16:10:15.257443 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1002@192.168.0.104:5060) State ROUTING
  34. 2017-03-14 16:10:15.257443 [DEBUG] mod_sofia.c:154 sofia/internal/1002@192.168.0.104:5060 SOFIA ROUTING
  35. 2017-03-14 16:10:15.257443 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1002@192.168.0.104:5060 Standard ROUTING
  36. 2017-03-14 16:10:15.257443 [INFO] mod_dialplan_xml.c:637 Processing 1002 <1002>->1000 in context default
  37. Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->unloop] continue=false
  38. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
  39. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
  40. Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->tod_example] continue=true
  41. Dialplan: sofia/internal/1002@192.168.0.104:5060 Date/Time Match (PASS) [tod_example] break=on-false
  42. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action set(open=true)
  43. Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->holiday_example] continue=true
  44. Dialplan: sofia/internal/1002@192.168.0.104:5060 Date/TimeMatch (FAIL) [holiday_example] break=on-false
  45. Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->global-intercept] continue=false
  46. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [global-intercept] destination_number(1000) =~ /^886$/ break=on-false
  47. Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->group-intercept] continue=false
  48. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [group-intercept] destination_number(1000) =~ /^\*8$/ break=on-false
  49. Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->intercept-ext] continue=false
  50. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [intercept-ext] destination_number(1000) =~ /^\*\*(\d+)$/ break=on-false
  51. Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->redial] continue=false
  52. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [redial] destination_number(1000) =~ /^(redial|870)$/ break=on-false
  53. Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->global] continue=true
  54. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
  55. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [global] ${default_password}(12345) =~ /^1234$/ break=never
  56. Dialplan: sofia/internal/1002@192.168.0.104: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
  57. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
  58. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [global] ${switch_r_sdp}(v=0
  59. o=Zoiper 0 0 IN IP4 192.168.0.105
  60. s=Zoiper
  61. c=IN IP4 192.168.0.105
  62. t=0 0
  63. m=audio 54518 RTP/AVP 3 0 8 101
  64. a=rtpmap:3 GSM/8000
  65. a=rtpmap:0 PCMU/8000
  66. a=rtpmap:8 PCMA/8000
  67. a=rtpmap:101 telephone-event/8000
  68. a=fmtp:101 0-16
  69. ) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
  70. Dialplan: sofia/internal/1002@192.168.0.104:5060 Absolute Condition [global]
  71. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
  72. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
  73. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action hash(insert/${domain_name}-last_dial/global/${uuid})
  74. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
  75. Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->snom-demo-2] continue=false
  76. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [snom-demo-2] destination_number(1000) =~ /^9001$/ break=on-false
  77. Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->snom-demo-1] continue=false
  78. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [snom-demo-1] destination_number(1000) =~ /^9000$/ break=on-false
  79. Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->eavesdrop] continue=false
  80. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [eavesdrop] destination_number(1000) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
  81. Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->eavesdrop] continue=false
  82. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [eavesdrop] destination_number(1000) =~ /^779$/ break=on-false
  83. Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->call_return] continue=false
  84. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [call_return] destination_number(1000) =~ /^\*69$|^869$|^lcr$/ break=on-false
  85. Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->del-group] continue=false
  86. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [del-group] destination_number(1000) =~ /^80(\d{2})$/ break=on-false
  87. Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->add-group] continue=false
  88. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [add-group] destination_number(1000) =~ /^81(\d{2})$/ break=on-false
  89. Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->call-group-simo] continue=false
  90. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [call-group-simo] destination_number(1000) =~ /^82(\d{2})$/ break=on-false
  91. Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->call-group-order] continue=false
  92. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [call-group-order] destination_number(1000) =~ /^83(\d{2})$/ break=on-false
  93. Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->extension-intercom] continue=false
  94. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [extension-intercom] destination_number(1000) =~ /^8(10[01][0-9])$/ break=on-false
  95. Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->Local_Extension] continue=false
  96. Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (PASS) [Local_Extension] destination_number(1000) =~ /^(10[01][0-9])$/ break=on-false
  97. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action export(dialed_extension=1000)
  98. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action bind_meta_app(1 b s execute_extension::dx XML features)
  99. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav)
  100. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action bind_meta_app(3 b s execute_extension::cf XML features)
  101. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action bind_meta_app(4 b s execute_extension::att_xfer XML features)
  102. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action set(ringback=${us-ring})
  103. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action set(transfer_ringback=local_stream://moh)
  104. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action set(call_timeout=30)
  105. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action set(hangup_after_bridge=true)
  106. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action set(continue_on_fail=true)
  107. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
  108. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
  109. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)})
  110. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid})
  111. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid})
  112. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
  113. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action bridge(user/${dialed_extension}@${domain_name})
  114. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action answer()
  115. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action sleep(1000)
  116. Dialplan: sofia/internal/1002@192.168.0.104:5060 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension})
  117. 2017-03-14 16:10:15.267391 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/1002@192.168.0.104:5060) State Change CS_ROUTING -> CS_EXECUTE
  118. 2017-03-14 16:10:15.267391 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1002@192.168.0.104:5060) State ROUTING going to sleep
  119. 2017-03-14 16:10:15.267391 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@192.168.0.104:5060) Running State Change CS_EXECUTE (Cur 1 Tot 16)
  120. 2017-03-14 16:10:15.267391 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1002@192.168.0.104:5060) State EXECUTE
  121. 2017-03-14 16:10:15.267391 [DEBUG] mod_sofia.c:209 sofia/internal/1002@192.168.0.104:5060 SOFIA EXECUTE
  122. 2017-03-14 16:10:15.267391 [DEBUG] switch_core_state_machine.c:328 sofia/internal/1002@192.168.0.104:5060 Standard EXECUTE
  123. EXECUTE sofia/internal/1002@192.168.0.104:5060 set(open=true)
  124. 2017-03-14 16:10:15.267391 [DEBUG] mod_dptools.c:1567 SET sofia/internal/1002@192.168.0.104:5060 [open]=[true]
  125. EXECUTE sofia/internal/1002@192.168.0.104:5060 hash(insert/192.168.0.104-spymap/1002/693e04e7-7fe7-414b-ac7c-74bdc3422141)
  126. EXECUTE sofia/internal/1002@192.168.0.104:5060 hash(insert/192.168.0.104-last_dial/1002/1000)
  127. EXECUTE sofia/internal/1002@192.168.0.104:5060 hash(insert/192.168.0.104-last_dial/global/693e04e7-7fe7-414b-ac7c-74bdc3422141)
  128. EXECUTE sofia/internal/1002@192.168.0.104:5060 export(RFC2822_DATE=Tue, 14 Mar 2017 16:10:15 +0000)
  129. 2017-03-14 16:10:15.267391 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Tue, 14 Mar 2017 16:10:15 +0000]
  130. EXECUTE sofia/internal/1002@192.168.0.104:5060 export(dialed_extension=1000)
  131. 2017-03-14 16:10:15.267391 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[1000]
  132. EXECUTE sofia/internal/1002@192.168.0.104:5060 bind_meta_app(1 b s execute_extension::dx XML features)
  133. 2017-03-14 16:10:15.267391 [INFO] switch_ivr_async.c:4247 Bound B-Leg: *1 execute_extension::dx XML features
  134. EXECUTE sofia/internal/1002@192.168.0.104:5060 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/1002.2017-03-14-16-10-15.wav)
  135. 2017-03-14 16:10:15.267391 [INFO] switch_ivr_async.c:4247 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/1002.2017-03-14-16-10-15.wav
  136. EXECUTE sofia/internal/1002@192.168.0.104:5060 bind_meta_app(3 b s execute_extension::cf XML features)
  137. 2017-03-14 16:10:15.277399 [INFO] switch_ivr_async.c:4247 Bound B-Leg: *3 execute_extension::cf XML features
  138. EXECUTE sofia/internal/1002@192.168.0.104:5060 bind_meta_app(4 b s execute_extension::att_xfer XML features)
  139. 2017-03-14 16:10:15.277399 [INFO] switch_ivr_async.c:4247 Bound B-Leg: *4 execute_extension::att_xfer XML features
  140. EXECUTE sofia/internal/1002@192.168.0.104:5060 set(ringback=%(2000,4000,440,480))
  141. 2017-03-14 16:10:15.277399 [DEBUG] mod_dptools.c:1567 SET sofia/internal/1002@192.168.0.104:5060 [ringback]=[%(2000,4000,440,480)]
  142. EXECUTE sofia/internal/1002@192.168.0.104:5060 set(transfer_ringback=local_stream://moh)
  143. 2017-03-14 16:10:15.277399 [DEBUG] mod_dptools.c:1567 SET sofia/internal/1002@192.168.0.104:5060 [transfer_ringback]=[local_stream://moh]
  144. EXECUTE sofia/internal/1002@192.168.0.104:5060 set(call_timeout=30)
  145. 2017-03-14 16:10:15.277399 [DEBUG] mod_dptools.c:1567 SET sofia/internal/1002@192.168.0.104:5060 [call_timeout]=[30]
  146. EXECUTE sofia/internal/1002@192.168.0.104:5060 set(hangup_after_bridge=true)
  147. 2017-03-14 16:10:15.277399 [DEBUG] mod_dptools.c:1567 SET sofia/internal/1002@192.168.0.104:5060 [hangup_after_bridge]=[true]
  148. EXECUTE sofia/internal/1002@192.168.0.104:5060 set(continue_on_fail=true)
  149. 2017-03-14 16:10:15.277399 [DEBUG] mod_dptools.c:1567 SET sofia/internal/1002@192.168.0.104:5060 [continue_on_fail]=[true]
  150. EXECUTE sofia/internal/1002@192.168.0.104:5060 hash(insert/192.168.0.104-call_return/1000/1002)
  151. EXECUTE sofia/internal/1002@192.168.0.104:5060 hash(insert/192.168.0.104-last_dial_ext/1000/693e04e7-7fe7-414b-ac7c-74bdc3422141)
  152. EXECUTE sofia/internal/1002@192.168.0.104:5060 set(called_party_callgroup=techsupport)
  153. 2017-03-14 16:10:15.287426 [DEBUG] mod_dptools.c:1567 SET sofia/internal/1002@192.168.0.104:5060 [called_party_callgroup]=[techsupport]
  154. EXECUTE sofia/internal/1002@192.168.0.104:5060 hash(insert/192.168.0.104-last_dial_ext/techsupport/693e04e7-7fe7-414b-ac7c-74bdc3422141)
  155. EXECUTE sofia/internal/1002@192.168.0.104:5060 hash(insert/192.168.0.104-last_dial_ext/global/693e04e7-7fe7-414b-ac7c-74bdc3422141)
  156. EXECUTE sofia/internal/1002@192.168.0.104:5060 hash(insert/192.168.0.104-last_dial/techsupport/693e04e7-7fe7-414b-ac7c-74bdc3422141)
  157. EXECUTE sofia/internal/1002@192.168.0.104:5060 bridge(user/1000@192.168.0.104)
  158. 2017-03-14 16:10:15.287426 [DEBUG] switch_channel.c:1250 sofia/internal/1002@192.168.0.104:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Tue, 14 Mar 2017 16:10:15 +0000] to event
  159. 2017-03-14 16:10:15.287426 [DEBUG] switch_channel.c:1250 sofia/internal/1002@192.168.0.104:5060 EXPORTING[export_vars] [dialed_extension]=[1000] to event
  160. 2017-03-14 16:10:15.287426 [DEBUG] switch_ivr_originate.c:2143 Parsing global variables
  161. 2017-03-14 16:10:15.297424 [DEBUG] switch_channel.c:1250 sofia/internal/1002@192.168.0.104:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Tue, 14 Mar 2017 16:10:15 +0000] to event
  162. 2017-03-14 16:10:15.297424 [DEBUG] switch_channel.c:1250 sofia/internal/1002@192.168.0.104:5060 EXPORTING[export_vars] [dialed_extension]=[1000] to event
  163. 2017-03-14 16:10:15.297424 [DEBUG] switch_ivr_originate.c:2143 Parsing global variables
  164. 2017-03-14 16:10:15.297424 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1000@df7jal23ls0d.invalid [3c8be0a6-04bd-4dbe-bdb8-591b291a690d]
  165. 2017-03-14 16:10:15.297424 [DEBUG] mod_sofia.c:5002 (sofia/internal/1000@df7jal23ls0d.invalid) State Change CS_NEW -> CS_INIT
  166. 2017-03-14 16:10:15.297424 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@df7jal23ls0d.invalid) Running State Change CS_INIT (Cur 2 Tot 17)
  167. 2017-03-14 16:10:15.297424 [NOTICE] switch_ivr_originate.c:2846 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
  168. 2017-03-14 16:10:15.297424 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1000@df7jal23ls0d.invalid) State INIT
  169. 2017-03-14 16:10:15.297424 [DEBUG] mod_sofia.c:93 sofia/internal/1000@df7jal23ls0d.invalid SOFIA INIT
  170. 2017-03-14 16:10:15.307415 [DEBUG] sofia_glue.c:1267 sips:1000@192.168.0.108:54417;rtcweb-breaker=yes;transport=wss Setting proxy route to sofia/internal/1000@df7jal23ls0d.invalid
  171. 2017-03-14 16:10:15.307415 [DEBUG] sofia_glue.c:1296 sofia/internal/1000@df7jal23ls0d.invalid sending invite version: 1.9.0 git 91d62b7 2017-02-24 22:49:43Z 64bit
  172. Local SDP:
  173. v=0
  174. o=FreeSWITCH 1489481037 1489481038 IN IP4 192.168.0.104
  175. s=FreeSWITCH
  176. c=IN IP4 192.168.0.104
  177. t=0 0
  178. a=msid-semantic: WMS UhujOL2NXyzeJCda1YFCSMeQvIaqHZxs
  179. m=audio 26778 RTP/SAVPF 0 8 101
  180. a=rtpmap:0 PCMU/8000
  181. a=rtpmap:8 PCMA/8000
  182. a=rtpmap:101 telephone-event/8000
  183. a=fingerprint:sha-256 18:87:44:40:A4:B1:1B:D2:30:EC:DD:94:D7:73:09:EA:90:12:88:69:9F:15:0A:1B:A9:1A:C7:FD:07:48:82:72
  184. a=setup:actpass
  185. a=rtcp-mux
  186. a=rtcp:26778 IN IP4 192.168.0.104
  187. a=ssrc:2899064633 cname:7RCMtvphTOmthqu9
  188. a=ssrc:2899064633 msid:UhujOL2NXyzeJCda1YFCSMeQvIaqHZxs a0
  189. a=ssrc:2899064633 mslabel:UhujOL2NXyzeJCda1YFCSMeQvIaqHZxs
  190. a=ssrc:2899064633 label:UhujOL2NXyzeJCda1YFCSMeQvIaqHZxsa0
  191. a=ice-ufrag:eZBXCFDXeDeMtC5r
  192. a=ice-pwd:ky3ETiLDXXX5dh4i7w5z2zn7
  193. a=candidate:4650138928 1 udp 659136 192.168.0.104 26778 typ host generation 0
  194. a=candidate:4650138928 2 udp 659136 192.168.0.104 26778 typ host generation 0
  195. a=ptime:20
  196. a=sendrecv
  197.  
  198. 2017-03-14 16:10:15.307415 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1000@df7jal23ls0d.invalid Standard INIT
  199. 2017-03-14 16:10:15.307415 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1000@df7jal23ls0d.invalid) State Change CS_INIT -> CS_ROUTING
  200. 2017-03-14 16:10:15.307415 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1000@df7jal23ls0d.invalid) State INIT going to sleep
  201. 2017-03-14 16:10:15.307415 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@df7jal23ls0d.invalid) Running State Change CS_ROUTING (Cur 2 Tot 17)
  202. 2017-03-14 16:10:15.307415 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1000@df7jal23ls0d.invalid) State ROUTING
  203. 2017-03-14 16:10:15.307415 [DEBUG] mod_sofia.c:154 sofia/internal/1000@df7jal23ls0d.invalid SOFIA ROUTING
  204. 2017-03-14 16:10:15.307415 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1000@df7jal23ls0d.invalid) State Change CS_ROUTING -> CS_CONSUME_MEDIA
  205. 2017-03-14 16:10:15.307415 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1000@df7jal23ls0d.invalid) State ROUTING going to sleep
  206. 2017-03-14 16:10:15.307415 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@df7jal23ls0d.invalid) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 17)
  207. 2017-03-14 16:10:15.307415 [DEBUG] sofia.c:7241 Channel sofia/internal/1000@df7jal23ls0d.invalid entering state [calling][0]
  208. 2017-03-14 16:10:15.307415 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1000@df7jal23ls0d.invalid) State CONSUME_MEDIA
  209. 2017-03-14 16:10:15.307415 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1000@df7jal23ls0d.invalid) State CONSUME_MEDIA going to sleep
  210. 2017-03-14 16:10:15.957397 [DEBUG] sofia.c:7241 Channel sofia/internal/1000@df7jal23ls0d.invalid entering state [proceeding][180]
  211. 2017-03-14 16:10:15.957397 [NOTICE] sofia.c:7349 Ring-Ready sofia/internal/1000@df7jal23ls0d.invalid!
  212. 2017-03-14 16:10:15.967419 [DEBUG] switch_channel.c:3353 (sofia/internal/1000@df7jal23ls0d.invalid) Callstate Change DOWN -> RINGING
  213. 2017-03-14 16:10:15.967419 [INFO] switch_ivr_originate.c:1220 Sending early media
  214. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [GSM:3:8000:20:13200:1]/[opus:116:48000:20:0:1]
  215. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
  216. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
  217. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
  218. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
  219. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  220. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  221. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5113 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
  222. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  223. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
  224. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  225. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  226. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  227. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5113 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
  228. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:4974 Set telephone-event payload to 101@8000
  229. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:3414 Set Codec sofia/internal/1002@192.168.0.104:5060 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
  230. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_codec.c:111 sofia/internal/1002@192.168.0.104:5060 Original read codec set to PCMU:0
  231. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5317 Set telephone-event payload to 101@8000
  232. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5376 sofia/internal/1002@192.168.0.104:5060 Set 2833 dtmf send payload to 101 recv payload to 101
  233. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:7978 AUDIO RTP [sofia/internal/1002@192.168.0.104:5060] 192.168.0.104 port 19080 -> 192.168.0.105 port 54518 codec: 0 ms: 20
  234. 2017-03-14 16:10:15.967419 [DEBUG] switch_rtp.c:3888 Starting timer [soft] 160 bytes per 20ms
  235. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:8286 sofia/internal/1002@192.168.0.104:5060 Set 2833 dtmf send payload to 101
  236. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:8293 sofia/internal/1002@192.168.0.104:5060 Set 2833 dtmf receive payload to 101
  237. 2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:8316 sofia/internal/1002@192.168.0.104:5060 Set rtp dtmf delay to 40
  238. 2017-03-14 16:10:15.967419 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1002@192.168.0.104:5060!
  239. 2017-03-14 16:10:15.977391 [DEBUG] switch_channel.c:3481 (sofia/internal/1002@192.168.0.104:5060) Callstate Change RINGING -> EARLY
  240. 2017-03-14 16:10:15.977391 [DEBUG] switch_core_media.c:7961 Audio params are unchanged for sofia/internal/1002@192.168.0.104:5060.
  241. 2017-03-14 16:10:15.977391 [DEBUG] mod_sofia.c:2502 Ring SDP:
  242. v=0
  243. o=FreeSWITCH 1489488735 1489488736 IN IP4 192.168.0.104
  244. s=FreeSWITCH
  245. c=IN IP4 192.168.0.104
  246. t=0 0
  247. m=audio 19080 RTP/AVP 0 101
  248. a=rtpmap:0 PCMU/8000
  249. a=rtpmap:101 telephone-event/8000
  250. a=fmtp:101 0-16
  251. a=ptime:20
  252. a=sendrecv
  253.  
  254. 2017-03-14 16:10:15.977391 [DEBUG] switch_ivr_originate.c:1278 Raw Codec Activation Success L16@8000hz 1 channel 20ms
  255. 2017-03-14 16:10:15.977391 [DEBUG] switch_core_codec.c:223 sofia/internal/1002@192.168.0.104:5060 Push codec L16:100
  256. 2017-03-14 16:10:15.977391 [DEBUG] switch_ivr_originate.c:1347 Play Ringback Tone [%(2000,4000,440,480)]
  257. 2017-03-14 16:10:15.997389 [DEBUG] sofia.c:7241 Channel sofia/internal/1002@192.168.0.104:5060 entering state [early][183]
  258. 2017-03-14 16:10:16.367406 [DEBUG] switch_rtp.c:7020 Correct audio ip/port confirmed.
  259. 2017-03-14 16:10:45.007401 [DEBUG] switch_core_codec.c:248 sofia/internal/1002@192.168.0.104:5060 Restore previous codec PCMU:0.
  260. 2017-03-14 16:10:45.007401 [NOTICE] switch_ivr_originate.c:3606 Hangup sofia/internal/1000@df7jal23ls0d.invalid [CS_CONSUME_MEDIA] [NO_ANSWER]
  261. 2017-03-14 16:10:45.007401 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@df7jal23ls0d.invalid) Running State Change CS_HANGUP (Cur 2 Tot 17)
  262. 2017-03-14 16:10:45.007401 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1000@df7jal23ls0d.invalid) Callstate Change RINGING -> HANGUP
  263. 2017-03-14 16:10:45.007401 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1000@df7jal23ls0d.invalid) State HANGUP
  264. 2017-03-14 16:10:45.007401 [DEBUG] mod_sofia.c:449 Channel sofia/internal/1000@df7jal23ls0d.invalid hanging up, cause: NO_ANSWER
  265. 2017-03-14 16:10:45.017409 [NOTICE] switch_ivr_originate.c:2846 Cannot create outgoing channel of type [user] cause: [NO_ANSWER]
  266. 2017-03-14 16:10:45.017409 [DEBUG] switch_ivr_originate.c:3834 Originate Resulted in Error Cause: 19 [NO_ANSWER]
  267. 2017-03-14 16:10:45.017409 [DEBUG] mod_sofia.c:513 Sending CANCEL to sofia/internal/1000@df7jal23ls0d.invalid
  268. 2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1000@df7jal23ls0d.invalid Standard HANGUP, cause: NO_ANSWER
  269. 2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1000@df7jal23ls0d.invalid) State HANGUP going to sleep
  270. 2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1000@df7jal23ls0d.invalid) State Change CS_HANGUP -> CS_REPORTING
  271. 2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@df7jal23ls0d.invalid) Running State Change CS_REPORTING (Cur 2 Tot 17)
  272. 2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1000@df7jal23ls0d.invalid) State REPORTING
  273. 2017-03-14 16:10:45.017409 [INFO] mod_dptools.c:3481 Originate Failed.  Cause: NO_ANSWER
  274. 2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1000@df7jal23ls0d.invalid Standard REPORTING, cause: NO_ANSWER
  275. 2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1000@df7jal23ls0d.invalid) State REPORTING going to sleep
  276. 2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1000@df7jal23ls0d.invalid) State Change CS_REPORTING -> CS_DESTROY
  277. 2017-03-14 16:10:45.017409 [DEBUG] switch_core_session.c:1712 Session 17 (sofia/internal/1000@df7jal23ls0d.invalid) Locked, Waiting on external entities
  278. EXECUTE sofia/internal/1002@192.168.0.104:5060 answer()
  279. 2017-03-14 16:10:45.017409 [NOTICE] switch_core_session.c:1730 Session 17 (sofia/internal/1000@df7jal23ls0d.invalid) Ended
  280. 2017-03-14 16:10:45.017409 [NOTICE] switch_core_session.c:1734 Close Channel sofia/internal/1000@df7jal23ls0d.invalid [CS_DESTROY]
  281. 2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1000@df7jal23ls0d.invalid) Running State Change CS_DESTROY (Cur 1 Tot 17)
  282. 2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1000@df7jal23ls0d.invalid) State DESTROY
  283. 2017-03-14 16:10:45.017409 [DEBUG] mod_sofia.c:354 sofia/internal/1000@df7jal23ls0d.invalid SOFIA DESTROY
  284. 2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1000@df7jal23ls0d.invalid Standard DESTROY
  285. 2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1000@df7jal23ls0d.invalid) State DESTROY going to sleep
  286. 2017-03-14 16:10:45.017409 [DEBUG] switch_core_media.c:7961 Audio params are unchanged for sofia/internal/1002@192.168.0.104:5060.
  287. 2017-03-14 16:10:45.017409 [DEBUG] mod_sofia.c:881 Local SDP sofia/internal/1002@192.168.0.104:5060:
  288. v=0
  289. o=FreeSWITCH 1489488735 1489488737 IN IP4 192.168.0.104
  290. s=FreeSWITCH
  291. c=IN IP4 192.168.0.104
  292. t=0 0
  293. m=audio 19080 RTP/AVP 0 101
  294. a=rtpmap:0 PCMU/8000
  295. a=rtpmap:101 telephone-event/8000
  296. a=fmtp:101 0-16
  297. a=ptime:20
  298. a=sendrecv
  299.  
  300. 2017-03-14 16:10:45.017409 [NOTICE] mod_dptools.c:1349 Channel [sofia/internal/1002@192.168.0.104:5060] has been answered
  301. 2017-03-14 16:10:45.017409 [DEBUG] switch_channel.c:3780 (sofia/internal/1002@192.168.0.104:5060) Callstate Change EARLY -> ACTIVE
  302. 2017-03-14 16:10:45.017409 [DEBUG] sofia.c:7241 Channel sofia/internal/1002@192.168.0.104:5060 entering state [completed][200]
  303. EXECUTE sofia/internal/1002@192.168.0.104:5060 sleep(1000)
  304. 2017-03-14 16:10:45.047403 [DEBUG] sofia.c:7241 Channel sofia/internal/1002@192.168.0.104:5060 entering state [ready][200]
  305. 2017-03-14 16:10:45.347407 [DEBUG] sofia.c:7241 Channel sofia/internal/1002@192.168.0.104:5060 entering state [received][100]
  306. 2017-03-14 16:10:45.347407 [DEBUG] sofia.c:7251 Remote SDP:
  307. v=0
  308. o=Zoiper 0 1 IN IP4 192.168.0.105
  309. s=Zoiper
  310. c=IN IP4 192.168.0.105
  311. t=0 0
  312. m=audio 54518 RTP/AVP 0 3 8 101
  313. a=rtpmap:0 PCMU/8000
  314. a=rtpmap:3 GSM/8000
  315. a=rtpmap:8 PCMA/8000
  316. a=rtpmap:101 telephone-event/8000
  317. a=fmtp:101 0-16
  318. m=video 54520 RTP/AVP 116 115
  319. a=rtpmap:116 VP8/90000
  320. a=rtpmap:115 H263-1998/90000
  321.  
  322. 2017-03-14 16:10:45.347407 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
  323. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  324. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  325. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5113 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
  326. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  327. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [GSM:3:8000:20:13200:1]/[opus:116:48000:20:0:1]
  328. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
  329. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
  330. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
  331. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
  332. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  333. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  334. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  335. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5113 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
  336. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:4974 Set telephone-event payload to 101@8000
  337. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5317 Set telephone-event payload to 101@8000
  338. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5376 sofia/internal/1002@192.168.0.104:5060 Set 2833 dtmf send payload to 101 recv payload to 101
  339. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5659 Video Codec Compare [VP8:116]/[VP8:99]
  340. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5691 Video Codec Compare [VP8:116] +++ is saved as a match
  341. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5659 Video Codec Compare [H263-1998:115]/[VP8:99]
  342. 2017-03-14 16:10:45.357402 [DEBUG] switch_vpx.c:627 VPX VER:v1.6.0 VPX_IMAGE_ABI_VERSION:4 VPX_CODEC_ABI_VERSION:7
  343. 2017-03-14 16:10:45.357402 [DEBUG] switch_vpx.c:627 VPX VER:v1.6.0 VPX_IMAGE_ABI_VERSION:4 VPX_CODEC_ABI_VERSION:7
  344. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:3224 Set VIDEO Codec sofia/internal/1002@192.168.0.104:5060 VP8/90000 0 ms
  345. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:7961 Audio params are unchanged for sofia/internal/1002@192.168.0.104:5060.
  346. 2017-03-14 16:10:45.357402 [DEBUG] switch_rtp.c:3899 Starting video timer.
  347. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:8816 VIDEO RTP [sofia/internal/1002@192.168.0.104:5060] 192.168.0.104:32376->192.168.0.105:54520 codec: 116 ms: 0 [SUCCESS]
  348. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:6977 sofia/internal/1002@192.168.0.104:5060 Starting Video thread
  349. 2017-03-14 16:10:45.357402 [DEBUG] sofia.c:8144 Processing updated SDP
  350. 2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:6843 sofia/internal/1002@192.168.0.104:5060 Video thread started. Echo is off
  351. 2017-03-14 16:10:45.367394 [DEBUG] sofia.c:7241 Channel sofia/internal/1002@192.168.0.104:5060 entering state [completed][200]
  352. 2017-03-14 16:10:45.407397 [DEBUG] sofia.c:7241 Channel sofia/internal/1002@192.168.0.104:5060 entering state [ready][200]
  353. 2017-03-14 16:10:45.407397 [NOTICE] switch_vpx.c:402 VPX reset encoder picture from 320x240 to 352x288 1024 BW
  354. 2017-03-14 16:10:45.807396 [DEBUG] switch_rtp.c:7020 Correct video ip/port confirmed.
  355. 2017-03-14 16:10:45.827399 [DEBUG] switch_rtp.c:7020 Correct audio ip/port confirmed.
  356. EXECUTE sofia/internal/1002@192.168.0.104:5060 bridge(loopback/app=voicemail:default 192.168.0.104 1000)
  357. 2017-03-14 16:10:46.027393 [DEBUG] switch_channel.c:1823 (sofia/internal/1002@192.168.0.104:5060) Callstate Change ACTIVE -> RING_WAIT
  358. 2017-03-14 16:10:46.037416 [DEBUG] switch_channel.c:1250 sofia/internal/1002@192.168.0.104:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Tue, 14 Mar 2017 16:10:15 +0000] to event
  359. 2017-03-14 16:10:46.037416 [DEBUG] switch_channel.c:1250 sofia/internal/1002@192.168.0.104:5060 EXPORTING[export_vars] [dialed_extension]=[1000] to event
  360. 2017-03-14 16:10:46.037416 [DEBUG] switch_ivr_originate.c:2143 Parsing global variables
  361. 2017-03-14 16:10:46.037416 [NOTICE] switch_channel.c:1104 New Channel loopback/app=voicemail:default 192.168.0.104 1000-a [40d5a7ce-344b-42df-8c28-b4f8dd5c2d0f]
  362. 2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:158 loopback/app=voicemail:default 192.168.0.104 1000-a setup codec PCMU/8000/20
  363. 2017-03-14 16:10:46.037416 [NOTICE] switch_channel.c:1102 Rename Channel loopback/app=voicemail:default 192.168.0.104 1000-a->loopback/voicemail-a [40d5a7ce-344b-42df-8c28-b4f8dd5c2d0f]
  364. 2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:1176 (loopback/voicemail-a) State Change CS_NEW -> CS_INIT
  365. 2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
  366. 2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_INIT (Cur 2 Tot 18)
  367. 2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:627 (loopback/voicemail-a) State INIT
  368. 2017-03-14 16:10:46.037416 [NOTICE] switch_channel.c:1104 New Channel loopback/voicemail-b [25db1ead-5b83-4bc1-b5bd-7c78e6661bc5]
  369. 2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:158 loopback/voicemail-b setup codec PCMU/8000/20
  370. 2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:276 (loopback/voicemail-b) State Change CS_NEW -> CS_INIT
  371. 2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
  372. 2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:364 (loopback/voicemail-a) State Change CS_INIT -> CS_ROUTING
  373. 2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
  374. 2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_INIT (Cur 3 Tot 19)
  375. 2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:627 (loopback/voicemail-a) State INIT going to sleep
  376. 2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:627 (loopback/voicemail-b) State INIT
  377. 2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:364 (loopback/voicemail-b) State Change CS_INIT -> CS_ROUTING
  378. 2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
  379. 2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:627 (loopback/voicemail-b) State INIT going to sleep
  380. 2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_ROUTING (Cur 3 Tot 19)
  381. 2017-03-14 16:10:46.037416 [DEBUG] switch_channel.c:2249 (loopback/voicemail-b) Callstate Change DOWN -> RINGING
  382. 2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_ROUTING (Cur 3 Tot 19)
  383. 2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:643 (loopback/voicemail-b) State ROUTING
  384. 2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:396 loopback/voicemail-b CHANNEL ROUTING
  385. 2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:643 (loopback/voicemail-a) State ROUTING
  386. 2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:415 (loopback/voicemail-b) State Change CS_ROUTING -> CS_EXECUTE
  387. 2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
  388. 2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:396 loopback/voicemail-a CHANNEL ROUTING
  389. 2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:643 (loopback/voicemail-b) State ROUTING going to sleep
  390. 2017-03-14 16:10:46.037416 [DEBUG] switch_ivr_originate.c:67 (loopback/voicemail-a) State Change CS_ROUTING -> CS_CONSUME_MEDIA
  391. 2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
  392. 2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_EXECUTE (Cur 3 Tot 19)
  393. 2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:643 (loopback/voicemail-a) State ROUTING going to sleep
  394. 2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_CONSUME_MEDIA (Cur 3 Tot 19)
  395. 2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:650 (loopback/voicemail-b) State EXECUTE
  396. 2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:438 loopback/voicemail-b CHANNEL EXECUTE
  397. 2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:328 loopback/voicemail-b Standard EXECUTE
  398. 2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:662 (loopback/voicemail-a) State CONSUME_MEDIA
  399. EXECUTE loopback/voicemail-b pre_answer()
  400. 2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:663 CHANNEL CONSUME_MEDIA
  401. 2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:662 (loopback/voicemail-a) State CONSUME_MEDIA going to sleep
  402. 2017-03-14 16:10:46.037416 [NOTICE] mod_loopback.c:963 Pre-Answer loopback/voicemail-a!
  403. 2017-03-14 16:10:46.047392 [DEBUG] switch_channel.c:3481 (loopback/voicemail-a) Callstate Change DOWN -> EARLY
  404. 2017-03-14 16:10:46.047392 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
  405. 2017-03-14 16:10:46.047392 [NOTICE] mod_dptools.c:1392 Pre-Answer loopback/voicemail-b!
  406. 2017-03-14 16:10:46.047392 [DEBUG] switch_channel.c:3481 (loopback/voicemail-b) Callstate Change RINGING -> EARLY
  407. 2017-03-14 16:10:46.047392 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
  408. EXECUTE loopback/voicemail-b voicemail(default 192.168.0.104 1000)
  409. 2017-03-14 16:10:46.047392 [DEBUG] switch_ivr_originate.c:3691 Originate Resulted in Success: [loopback/voicemail-a]
  410. 2017-03-14 16:10:46.047392 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
  411. 2017-03-14 16:10:46.057401 [DEBUG] switch_channel.c:2047 (sofia/internal/1002@192.168.0.104:5060) Callstate Change RING_WAIT -> ACTIVE
  412. 2017-03-14 16:10:46.057401 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
  413. 2017-03-14 16:10:46.057401 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
  414. 2017-03-14 16:10:46.057401 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
  415. 2017-03-14 16:10:46.057401 [DEBUG] switch_ivr_bridge.c:1696 (loopback/voicemail-a) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
  416. 2017-03-14 16:10:46.057401 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
  417. 2017-03-14 16:10:46.057401 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_EXCHANGE_MEDIA (Cur 3 Tot 19)
  418. 2017-03-14 16:10:46.057401 [DEBUG] switch_core_state_machine.c:653 (loopback/voicemail-a) State EXCHANGE_MEDIA
  419. 2017-03-14 16:10:46.057401 [DEBUG] mod_loopback.c:625 CHANNEL LOOPBACK
  420. 2017-03-14 16:10:46.157407 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]
  421. 2017-03-14 16:10:46.207422 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-person.wav] (en:en)
  422. 2017-03-14 16:10:46.207422 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
  423. 2017-03-14 16:10:46.207422 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
  424. 2017-03-14 16:10:47.537399 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-person.wav
  425. 2017-03-14 16:10:47.637403 [DEBUG] switch_ivr_play_say.c:250 Handle say:[1000] (en:en)
  426. 2017-03-14 16:10:47.647409 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
  427. 2017-03-14 16:10:47.647409 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
  428. 2017-03-14 16:10:49.937414 [DEBUG] switch_ivr_play_say.c:1942 done playing file file_string://digits/1.wav!digits/0.wav!digits/0.wav!digits/0.wav
  429. 2017-03-14 16:10:50.057402 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-not_available.wav] (en:en)
  430. 2017-03-14 16:10:50.067409 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
  431. 2017-03-14 16:10:50.067409 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
  432. 2017-03-14 16:10:51.037398 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-not_available.wav
  433. 2017-03-14 16:10:51.137427 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]
  434. 2017-03-14 16:10:51.187391 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-record_message.wav] (en:en)
  435. 2017-03-14 16:10:51.187391 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
  436. 2017-03-14 16:10:51.187391 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
  437. 2017-03-14 16:10:52.497420 [NOTICE] sofia.c:1079 Hangup sofia/internal/1002@192.168.0.104:5060 [CS_EXECUTE] [NORMAL_CLEARING]
  438. 2017-03-14 16:10:52.497420 [DEBUG] switch_ivr_bridge.c:792 sofia/internal/1002@192.168.0.104:5060 ending bridge by request from write function
  439. 2017-03-14 16:10:52.497420 [DEBUG] switch_ivr_bridge.c:882 BRIDGE THREAD DONE [loopback/voicemail-a]
  440. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_media.c:13560 sofia/internal/1002@192.168.0.104:5060 skip receive message [DISPLAY] (channel is hungup already)
  441. 2017-03-14 16:10:52.497420 [NOTICE] switch_ivr_bridge.c:984 Hangup loopback/voicemail-a [CS_EXCHANGE_MEDIA] [ORIGINATOR_CANCEL]
  442. 2017-03-14 16:10:52.497420 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
  443. 2017-03-14 16:10:52.497420 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
  444. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:653 (loopback/voicemail-a) State EXCHANGE_MEDIA going to sleep
  445. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_HANGUP (Cur 3 Tot 19)
  446. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_media.c:6944 sofia/internal/1002@192.168.0.104:5060 Video thread ended
  447. 2017-03-14 16:10:52.497420 [DEBUG] switch_ivr_bridge.c:882 BRIDGE THREAD DONE [sofia/internal/1002@192.168.0.104:5060]
  448. 2017-03-14 16:10:52.497420 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
  449. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:850 (loopback/voicemail-a) Callstate Change EARLY -> HANGUP
  450. 2017-03-14 16:10:52.497420 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-record_message.wav
  451. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:852 (loopback/voicemail-a) State HANGUP
  452. 2017-03-14 16:10:52.497420 [DEBUG] mod_loopback.c:550 loopback/voicemail-a CHANNEL HANGUP
  453. 2017-03-14 16:10:52.497420 [NOTICE] mod_loopback.c:566 Hangup loopback/voicemail-b [CS_EXECUTE] [ORIGINATOR_CANCEL]
  454. 2017-03-14 16:10:52.497420 [DEBUG] switch_ivr_bridge.c:1795 loopback/voicemail-a skip receive message [TRANSFER] (channel is hungup already)
  455. 2017-03-14 16:10:52.497420 [DEBUG] switch_ivr_bridge.c:1798 sofia/internal/1002@192.168.0.104:5060 skip receive message [TRANSFER] (channel is hungup already)
  456. 2017-03-14 16:10:52.497420 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
  457. 2017-03-14 16:10:52.497420 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
  458. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:60 loopback/voicemail-a Standard HANGUP, cause: ORIGINATOR_CANCEL
  459. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:852 (loopback/voicemail-a) State HANGUP going to sleep
  460. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:619 (loopback/voicemail-a) State Change CS_HANGUP -> CS_REPORTING
  461. 2017-03-14 16:10:52.497420 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
  462. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_REPORTING (Cur 3 Tot 19)
  463. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:938 (loopback/voicemail-a) State REPORTING
  464. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:174 loopback/voicemail-a Standard REPORTING, cause: ORIGINATOR_CANCEL
  465. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_session.c:2884 sofia/internal/1002@192.168.0.104:5060 skip receive message [PHONE_EVENT] (channel is hungup already)
  466. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:938 (loopback/voicemail-a) State REPORTING going to sleep
  467. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1002@192.168.0.104:5060) State EXECUTE going to sleep
  468. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@192.168.0.104:5060) Running State Change CS_HANGUP (Cur 3 Tot 19)
  469. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:610 (loopback/voicemail-a) State Change CS_REPORTING -> CS_DESTROY
  470. 2017-03-14 16:10:52.497420 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
  471. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_session.c:1712 Session 18 (loopback/voicemail-a) Locked, Waiting on external entities
  472. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1002@192.168.0.104:5060) Callstate Change ACTIVE -> HANGUP
  473. 2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1002@192.168.0.104:5060) State HANGUP
  474. 2017-03-14 16:10:52.497420 [DEBUG] mod_sofia.c:449 Channel sofia/internal/1002@192.168.0.104:5060 hanging up, cause: NORMAL_CLEARING
  475. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_session.c:2884 loopback/voicemail-b skip receive message [PHONE_EVENT] (channel is hungup already)
  476. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:650 (loopback/voicemail-b) State EXECUTE going to sleep
  477. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_HANGUP (Cur 3 Tot 19)
  478. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1002@192.168.0.104:5060 Standard HANGUP, cause: NORMAL_CLEARING
  479. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:850 (loopback/voicemail-b) Callstate Change EARLY -> HANGUP
  480. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1002@192.168.0.104:5060) State HANGUP going to sleep
  481. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:852 (loopback/voicemail-b) State HANGUP
  482. 2017-03-14 16:10:52.507397 [DEBUG] mod_loopback.c:550 loopback/voicemail-b CHANNEL HANGUP
  483. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:60 loopback/voicemail-b Standard HANGUP, cause: ORIGINATOR_CANCEL
  484. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:852 (loopback/voicemail-b) State HANGUP going to sleep
  485. 2017-03-14 16:10:52.507397 [NOTICE] switch_core_session.c:1730 Session 18 (loopback/voicemail-a) Ended
  486. 2017-03-14 16:10:52.507397 [NOTICE] switch_core_session.c:1734 Close Channel loopback/voicemail-a [CS_DESTROY]
  487. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:619 (loopback/voicemail-b) State Change CS_HANGUP -> CS_REPORTING
  488. 2017-03-14 16:10:52.507397 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
  489. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_REPORTING (Cur 2 Tot 19)
  490. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1002@192.168.0.104:5060) State Change CS_HANGUP -> CS_REPORTING
  491. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:938 (loopback/voicemail-b) State REPORTING
  492. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:174 loopback/voicemail-b Standard REPORTING, cause: ORIGINATOR_CANCEL
  493. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:938 (loopback/voicemail-b) State REPORTING going to sleep
  494. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@192.168.0.104:5060) Running State Change CS_REPORTING (Cur 2 Tot 19)
  495. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:741 (loopback/voicemail-a) Running State Change CS_DESTROY (Cur 2 Tot 19)
  496. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:751 (loopback/voicemail-a) State DESTROY
  497. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:610 (loopback/voicemail-b) State Change CS_REPORTING -> CS_DESTROY
  498. 2017-03-14 16:10:52.507397 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
  499. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_session.c:1712 Session 19 (loopback/voicemail-b) Locked, Waiting on external entities
  500. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:181 loopback/voicemail-a Standard DESTROY
  501. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:751 (loopback/voicemail-a) State DESTROY going to sleep
  502. 2017-03-14 16:10:52.507397 [NOTICE] switch_core_session.c:1730 Session 19 (loopback/voicemail-b) Ended
  503. 2017-03-14 16:10:52.507397 [NOTICE] switch_core_session.c:1734 Close Channel loopback/voicemail-b [CS_DESTROY]
  504. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1002@192.168.0.104:5060) State REPORTING
  505. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:741 (loopback/voicemail-b) Running State Change CS_DESTROY (Cur 1 Tot 19)
  506. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1002@192.168.0.104:5060 Standard REPORTING, cause: NORMAL_CLEARING
  507. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1002@192.168.0.104:5060) State REPORTING going to sleep
  508. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:751 (loopback/voicemail-b) State DESTROY
  509. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:181 loopback/voicemail-b Standard DESTROY
  510. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:751 (loopback/voicemail-b) State DESTROY going to sleep
  511. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1002@192.168.0.104:5060) State Change CS_REPORTING -> CS_DESTROY
  512. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_session.c:1712 Session 16 (sofia/internal/1002@192.168.0.104:5060) Locked, Waiting on external entities
  513. 2017-03-14 16:10:52.507397 [NOTICE] switch_core_session.c:1730 Session 16 (sofia/internal/1002@192.168.0.104:5060) Ended
  514. 2017-03-14 16:10:52.507397 [NOTICE] switch_core_session.c:1734 Close Channel sofia/internal/1002@192.168.0.104:5060 [CS_DESTROY]
  515. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1002@192.168.0.104:5060) Running State Change CS_DESTROY (Cur 0 Tot 19)
  516. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1002@192.168.0.104:5060) State DESTROY
  517. 2017-03-14 16:10:52.507397 [DEBUG] mod_sofia.c:354 sofia/internal/1002@192.168.0.104:5060 SOFIA DESTROY
  518. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1002@192.168.0.104:5060 Standard DESTROY
  519. 2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1002@192.168.0.104:5060) State DESTROY going to sleep
  520.