From jungle-boogie, 3 Years ago, written in FreeSWITCH.
- view diff
Embed
  1. span style="color: cornflowerblue; font-weight: bold;"> 2016-08-02 02:28:14.710556 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/2600@192.168.0.137 [c3d65838-5858-11e6-b12a-adaf8bea1064]
  2. 2016-08-02 02:28:14.710556 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.137) Running State Change CS_NEW
  3. 2016-08-02 02:28:14.710556 [DEBUG] sofia.c:9518 sofia/internal/2600@192.168.0.137 receiving invite from 192.168.0.12:60409 version: 1.7.0 git 9fe7c48 2016-07-28 21:27:17Z 32bit
  4. 2016-08-02 02:28:14.710556 [DEBUG] sofia.c:9685 IP 192.168.0.12 Rejected by acl "domains". Falling back to Digest auth.
  5. 2016-08-02 02:28:14.710556 [WARNING] sofia_reg.c:1787 SIP auth challenge (INVITE) on sofia profile 'internal' for [2001@192.168.0.137] from ip 192.168.0.12
  6. 2016-08-02 02:28:14.710556 [DEBUG] switch_core_state_machine.c:562 (sofia/internal/2600@192.168.0.137) State NEW
  7. 2016-08-02 02:28:14.710556 [DEBUG] sofia.c:2248 detaching session c3d65838-5858-11e6-b12a-adaf8bea1064
  8. 2016-08-02 02:28:14.890175 [DEBUG] sofia.c:2356 Re-attaching to session c3d65838-5858-11e6-b12a-adaf8bea1064
  9. 2016-08-02 02:28:14.890175 [DEBUG] sofia.c:9518 sofia/internal/2600@192.168.0.137 receiving invite from 192.168.0.12:60409 version: 1.7.0 git 9fe7c48 2016-07-28 21:27:17Z 32bit
  10. 2016-08-02 02:28:14.890175 [DEBUG] sofia.c:9685 IP 192.168.0.12 Rejected by acl "domains". Falling back to Digest auth.
  11. 2016-08-02 02:28:14.910179 [DEBUG] sofia.c:6937 Channel sofia/internal/2600@192.168.0.137 entering state [received][100]
  12. 2016-08-02 02:28:14.910179 [DEBUG] sofia.c:6947 Remote SDP:
  13. v=0
  14. o=- 1470104894 1470104894 IN IP4 192.168.0.12
  15. s=Polycom IP Phone
  16. c=IN IP4 192.168.0.12
  17. t=0 0
  18. a=sendrecv
  19. m=audio 2224 RTP/AVP 9 102 0 8 18 127
  20. a=rtpmap:9 G722/8000
  21. a=rtpmap:102 G7221/16000
  22. a=fmtp:102 bitrate=32000
  23. a=rtpmap:0 PCMU/8000
  24. a=rtpmap:8 PCMA/8000
  25. a=rtpmap:18 G729/8000
  26. a=fmtp:18 annexb=no
  27. a=rtpmap:127 telephone-event/8000
  28.  
  29. 2016-08-02 02:28:14.910179 [DEBUG] sofia.c:7315 (sofia/internal/2600@192.168.0.137) State Change CS_NEW -> CS_INIT
  30. 2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.137) Running State Change CS_INIT
  31. 2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/2600@192.168.0.137) State INIT
  32. 2016-08-02 02:28:14.910179 [DEBUG] mod_sofia.c:90 sofia/internal/2600@192.168.0.137 SOFIA INIT
  33. 2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:40 sofia/internal/2600@192.168.0.137 Standard INIT
  34. 2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/2600@192.168.0.137) State Change CS_INIT -> CS_ROUTING
  35. 2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/2600@192.168.0.137) State INIT going to sleep
  36. 2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.137) Running State Change CS_ROUTING
  37. 2016-08-02 02:28:14.910179 [DEBUG] switch_channel.c:2249 (sofia/internal/2600@192.168.0.137) Callstate Change DOWN -> RINGING
  38. 2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/2600@192.168.0.137) State ROUTING
  39. 2016-08-02 02:28:14.910179 [DEBUG] mod_sofia.c:143 sofia/internal/2600@192.168.0.137 SOFIA ROUTING
  40. 2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:236 sofia/internal/2600@192.168.0.137 Standard ROUTING
  41. 2016-08-02 02:28:14.910179 [INFO] mod_dialplan_xml.c:637 Processing jungle boogie <2600>->2001 in context default
  42. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->unloop] continue=false
  43. Dialplan: sofia/internal/2600@192.168.0.137 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
  44. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
  45. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->tod_example] continue=true
  46. Dialplan: sofia/internal/2600@192.168.0.137 Date/TimeMatch (FAIL) [tod_example] break=on-false
  47. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->holiday_example] continue=true
  48. Dialplan: sofia/internal/2600@192.168.0.137 Date/TimeMatch (FAIL) [holiday_example] break=on-false
  49. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->global-intercept] continue=false
  50. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [global-intercept] destination_number(2001) =~ /^886$/ break=on-false
  51. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->group-intercept] continue=false
  52. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [group-intercept] destination_number(2001) =~ /^\*8$/ break=on-false
  53. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->intercept-ext] continue=false                                                                                                                                          
  54. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [intercept-ext] destination_number(2001) =~ /^\*\*(\d+)$/ break=on-false
  55. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->redial] continue=false
  56. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [redial] destination_number(2001) =~ /^(redial|870)$/ break=on-false
  57. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->global] continue=true
  58. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
  59. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [global] ${default_password}(lfklsnfknjfhfh843^$(0&^fsjklaCoI4_3944/*) =~ /^1234$/ break=never
  60. Dialplan: sofia/internal/2600@192.168.0.137 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_HM
  61. AC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=never
  62. Dialplan: sofia/internal/2600@192.168.0.137 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
  63. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [global] ${switch_r_sdp}(v=0
  64. o=- 1470104894 1470104894 IN IP4 192.168.0.12
  65. s=Polycom IP Phone
  66. c=IN IP4 192.168.0.12
  67. t=0 0
  68. a=sendrecv
  69. m=audio 2224 RTP/AVP 9 102 0 8 18 127
  70. a=rtpmap:9 G722/8000
  71. a=rtpmap:102 G7221/16000
  72. a=fmtp:102 bitrate=32000
  73. a=rtpmap:0 PCMU/8000
  74. a=rtpmap:8 PCMA/8000
  75. a=rtpmap:18 G729/8000
  76. a=fmtp:18 annexb=no
  77. a=rtpmap:127 telephone-event/8000
  78. ) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
  79. Dialplan: sofia/internal/2600@192.168.0.137 Absolute Condition [global]
  80. Dialplan: sofia/internal/2600@192.168.0.137 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
  81. Dialplan: sofia/internal/2600@192.168.0.137 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
  82. Dialplan: sofia/internal/2600@192.168.0.137 Action hash(insert/${domain_name}-last_dial/global/${uuid})
  83. Dialplan: sofia/internal/2600@192.168.0.137 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
  84. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->snom-demo-2] continue=false
  85. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [snom-demo-2] destination_number(2001) =~ /^9001$/ break=on-false
  86. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->snom-demo-1] continue=false
  87. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [snom-demo-1] destination_number(2001) =~ /^9000$/ break=on-false
  88. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->eavesdrop] continue=false
  89. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [eavesdrop] destination_number(2001) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
  90. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->eavesdrop] continue=false
  91. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [eavesdrop] destination_number(2001) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false                                                                                              [170/1813]
  92. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->eavesdrop] continue=false
  93. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [eavesdrop] destination_number(2001) =~ /^779$/ break=on-false
  94. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->call_return] continue=false
  95. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [call_return] destination_number(2001) =~ /^\*69$|^869$|^lcr$/ break=on-false
  96. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->del-group] continue=false
  97. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [del-group] destination_number(2001) =~ /^80(\d{2})$/ break=on-false
  98. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->add-group] continue=false
  99. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [add-group] destination_number(2001) =~ /^81(\d{2})$/ break=on-false
  100. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->call-group-simo] continue=false
  101. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [call-group-simo] destination_number(2001) =~ /^82(\d{2})$/ break=on-false
  102. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->call-group-order] continue=false
  103. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [call-group-order] destination_number(2001) =~ /^83(\d{2})$/ break=on-false
  104. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->extension-intercom] continue=false
  105. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [extension-intercom] destination_number(2001) =~ /^8(10[01][0-9])$/ break=on-false
  106. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->Local_Extension] continue=false
  107. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [Local_Extension] destination_number(2001) =~ /^(26[01][0-9]|phone|mobile)$/ break=on-false
  108. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->Local_Extension_Skinny] continue=false
  109. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [Local_Extension_Skinny] destination_number(2001) =~ /^(11[01][0-9])$/ break=on-false
  110. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->group_dial_sales] continue=false
  111. Dialplan: sofia/internal/2600@192.168.0.137 Regex (FAIL) [group_dial_sales] destination_number(2001) =~ /^2000$/ break=on-false
  112. Dialplan: sofia/internal/2600@192.168.0.137 parsing [default->group_dial_support] continue=false
  113. Dialplan: sofia/internal/2600@192.168.0.137 Regex (PASS) [group_dial_support] destination_number(2001) =~ /^2001$/ break=on-false
  114. Dialplan: sofia/internal/2600@192.168.0.137 Action set(call_timeout=20)
  115. Dialplan: sofia/internal/2600@192.168.0.137 Action set(continue_on_fail=true)
  116. Dialplan: sofia/internal/2600@192.168.0.137 Action set(hangup_after_bridge=true)
  117. Dialplan: sofia/internal/2600@192.168.0.137 Action bridge(group/support@${domain_name})
  118. Dialplan: sofia/internal/2600@192.168.0.137 Action answer()
  119. Dialplan: sofia/internal/2600@192.168.0.137 Action sleep(2000)
  120. Dialplan: sofia/internal/2600@192.168.0.137 Action voicemail(default 2600)
  121. 2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/2600@192.168.0.137) State Change CS_ROUTING -> CS_EXECUTE
  122. 2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/2600@192.168.0.137) State ROUTING going to sleep
  123. 2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.137) Running State Change CS_EXECUTE
  124. 2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:609 (sofia/internal/2600@192.168.0.137) State EXECUTE
  125. 2016-08-02 02:28:14.910179 [DEBUG] mod_sofia.c:198 sofia/internal/2600@192.168.0.137 SOFIA EXECUTE
  126. 2016-08-02 02:28:14.910179 [DEBUG] switch_core_state_machine.c:328 sofia/internal/2600@192.168.0.137 Standard EXECUTE
  127. EXECUTE sofia/internal/2600@192.168.0.137 hash(insert/192.168.0.137-spymap/2600/c3d65838-5858-11e6-b12a-adaf8bea1064)
  128. EXECUTE sofia/internal/2600@192.168.0.137 hash(insert/192.168.0.137-last_dial/2600/2001)
  129. EXECUTE sofia/internal/2600@192.168.0.137 hash(insert/192.168.0.137-last_dial/global/c3d65838-5858-11e6-b12a-adaf8bea1064)                                                                                                           [132/1813]
  130. EXECUTE sofia/internal/2600@192.168.0.137 export(RFC2822_DATE=Tue, 02 Aug 2016 02:28:14 +0000)
  131. 2016-08-02 02:28:14.910179 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Tue, 02 Aug 2016 02:28:14 +0000]
  132. EXECUTE sofia/internal/2600@192.168.0.137 set(call_timeout=20)
  133. 2016-08-02 02:28:14.930226 [DEBUG] mod_dptools.c:1519 SET sofia/internal/2600@192.168.0.137 [call_timeout]=[20]
  134. EXECUTE sofia/internal/2600@192.168.0.137 set(continue_on_fail=true)
  135. 2016-08-02 02:28:14.930226 [DEBUG] mod_dptools.c:1519 SET sofia/internal/2600@192.168.0.137 [continue_on_fail]=[true]
  136. EXECUTE sofia/internal/2600@192.168.0.137 set(hangup_after_bridge=true)
  137. 2016-08-02 02:28:14.930226 [DEBUG] mod_dptools.c:1519 SET sofia/internal/2600@192.168.0.137 [hangup_after_bridge]=[true]
  138. EXECUTE sofia/internal/2600@192.168.0.137 bridge(group/support@192.168.0.137)
  139. 2016-08-02 02:28:14.930226 [DEBUG] switch_channel.c:1250 sofia/internal/2600@192.168.0.137 EXPORTING[export_vars] [RFC2822_DATE]=[Tue, 02 Aug 2016 02:28:14 +0000] to event
  140. 2016-08-02 02:28:14.930226 [DEBUG] switch_ivr_originate.c:2136 Parsing global variables
  141. 2016-08-02 02:28:14.950217 [DEBUG] switch_channel.c:1250 sofia/internal/2600@192.168.0.137 EXPORTING[export_vars] [RFC2822_DATE]=[Tue, 02 Aug 2016 02:28:14 +0000] to event
  142. 2016-08-02 02:28:14.950217 [DEBUG] switch_ivr_originate.c:2136 Parsing global variables
  143. 2016-08-02 02:28:14.950217 [DEBUG] switch_ivr_originate.c:2589 Parsing session specific variables
  144. 2016-08-02 02:28:14.950217 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/2600@192.168.0.12 [c3f965da-5858-11e6-b13b-adaf8bea1064]
  145. 2016-08-02 02:28:14.950217 [DEBUG] mod_sofia.c:4754 (sofia/internal/2600@192.168.0.12) State Change CS_NEW -> CS_INIT
  146. 2016-08-02 02:28:14.950217 [DEBUG] switch_ivr_originate.c:2589 Parsing session specific variables
  147. 2016-08-02 02:28:14.950217 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.12) Running State Change CS_INIT
  148. 2016-08-02 02:28:14.950217 [NOTICE] switch_ivr_originate.c:2771 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
  149. 2016-08-02 02:28:14.950217 [DEBUG] switch_ivr_originate.c:2589 Parsing session specific variables
  150. 2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/2600@192.168.0.12) State INIT
  151. 2016-08-02 02:28:14.970210 [DEBUG] mod_sofia.c:90 sofia/internal/2600@192.168.0.12 SOFIA INIT
  152. 2016-08-02 02:28:14.970210 [NOTICE] switch_ivr_originate.c:2771 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
  153. 2016-08-02 02:28:14.970210 [DEBUG] switch_ivr_originate.c:2589 Parsing session specific variables
  154. 2016-08-02 02:28:14.970210 [NOTICE] switch_ivr_originate.c:2771 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
  155. 2016-08-02 02:28:14.970210 [DEBUG] sofia_glue.c:1249 sofia/internal/2600@192.168.0.12 sending invite version: 1.7.0 git 9fe7c48 2016-07-28 21:27:17Z 32bit
  156. Local SDP:
  157. v=0
  158. o=FreeSWITCH 1470081874 1470081875 IN IP4 192.168.0.137
  159. s=FreeSWITCH
  160. c=IN IP4 192.168.0.137
  161. t=0 0
  162. m=audio 23020 RTP/AVP 9 0 8 101
  163. a=rtpmap:9 G722/8000
  164. a=rtpmap:0 PCMU/8000
  165. a=rtpmap:8 PCMA/8000
  166. a=rtpmap:101 telephone-event/8000
  167.  
  168. a=fmtp:101 0-16                                                                                                                                                                                                                      
  169. a=ptime:20
  170. a=sendrecv
  171.  
  172. 2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:40 sofia/internal/2600@192.168.0.12 Standard INIT
  173. 2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/2600@192.168.0.12) State Change CS_INIT -> CS_ROUTING
  174. 2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/2600@192.168.0.12) State INIT going to sleep
  175. 2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.12) Running State Change CS_ROUTING
  176. 2016-08-02 02:28:14.970210 [DEBUG] sofia.c:6937 Channel sofia/internal/2600@192.168.0.12 entering state [calling][0]
  177. 2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/2600@192.168.0.12) State ROUTING
  178. 2016-08-02 02:28:14.970210 [DEBUG] mod_sofia.c:143 sofia/internal/2600@192.168.0.12 SOFIA ROUTING
  179. 2016-08-02 02:28:14.970210 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/2600@192.168.0.12) State Change CS_ROUTING -> CS_CONSUME_MEDIA
  180. 2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/2600@192.168.0.12) State ROUTING going to sleep
  181. 2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.12) Running State Change CS_CONSUME_MEDIA
  182. 2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:621 (sofia/internal/2600@192.168.0.12) State CONSUME_MEDIA
  183. 2016-08-02 02:28:14.970210 [DEBUG] switch_core_state_machine.c:621 (sofia/internal/2600@192.168.0.12) State CONSUME_MEDIA going to sleep
  184. 2016-08-02 02:28:15.030162 [DEBUG] sofia.c:6937 Channel sofia/internal/2600@192.168.0.12 entering state [terminated][486]
  185. 2016-08-02 02:28:15.030162 [NOTICE] sofia.c:8023 Hangup sofia/internal/2600@192.168.0.12 [CS_CONSUME_MEDIA] [USER_BUSY]
  186. 2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.12) Running State Change CS_HANGUP
  187. 2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:809 (sofia/internal/2600@192.168.0.12) Callstate Change DOWN -> HANGUP
  188. 2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:811 (sofia/internal/2600@192.168.0.12) State HANGUP
  189. 2016-08-02 02:28:15.030162 [DEBUG] mod_sofia.c:438 Channel sofia/internal/2600@192.168.0.12 hanging up, cause: USER_BUSY
  190. 2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:60 sofia/internal/2600@192.168.0.12 Standard HANGUP, cause: USER_BUSY
  191. 2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:811 (sofia/internal/2600@192.168.0.12) State HANGUP going to sleep
  192. 2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/2600@192.168.0.12) State Change CS_HANGUP -> CS_REPORTING
  193. 2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.12) Running State Change CS_REPORTING
  194. 2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:897 (sofia/internal/2600@192.168.0.12) State REPORTING
  195. 2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:174 sofia/internal/2600@192.168.0.12 Standard REPORTING, cause: USER_BUSY
  196. 2016-08-02 02:28:15.030162 [DEBUG] switch_core_state_machine.c:897 (sofia/internal/2600@192.168.0.12) State REPORTING going to sleep
  197. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/2600@192.168.0.12) State Change CS_REPORTING -> CS_DESTROY
  198. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_session.c:1647 Session 83 (sofia/internal/2600@192.168.0.12) Locked, Waiting on external entities
  199. 2016-08-02 02:28:15.050206 [DEBUG] switch_ivr_originate.c:3759 Originate Resulted in Error Cause: 17 [USER_BUSY]
  200. 2016-08-02 02:28:15.050206 [NOTICE] switch_core_session.c:1665 Session 83 (sofia/internal/2600@192.168.0.12) Ended
  201. 2016-08-02 02:28:15.050206 [NOTICE] switch_core_session.c:1669 Close Channel sofia/internal/2600@192.168.0.12 [CS_DESTROY]
  202. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_state_machine.c:700 (sofia/internal/2600@192.168.0.12) Running State Change CS_DESTROY
  203. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_state_machine.c:710 (sofia/internal/2600@192.168.0.12) State DESTROY
  204. 2016-08-02 02:28:15.050206 [DEBUG] mod_sofia.c:343 sofia/internal/2600@192.168.0.12 SOFIA DESTROY
  205. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_state_machine.c:181 sofia/internal/2600@192.168.0.12 Standard DESTROY
  206. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_state_machine.c:710 (sofia/internal/2600@192.168.0.12) State DESTROY going to sleep                                                                                                    [56/1813]
  207. 2016-08-02 02:28:15.050206 [NOTICE] switch_ivr_originate.c:2771 Cannot create outgoing channel of type [group] cause: [USER_BUSY]
  208. 2016-08-02 02:28:15.050206 [DEBUG] switch_ivr_originate.c:3759 Originate Resulted in Error Cause: 17 [USER_BUSY]
  209. 2016-08-02 02:28:15.050206 [INFO] mod_dptools.c:3401 Originate Failed.  Cause: USER_BUSY
  210. EXECUTE sofia/internal/2600@192.168.0.137 answer()
  211. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1]
  212. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  213. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4366 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
  214. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  215. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  216. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G7221:102:16000:20:0:1]/[opus:116:48000:20:0:1]
  217. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G7221:102:16000:20:0:1]/[G722:9:8000:20:64000:1]
  218. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G7221:102:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
  219. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G7221:102:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
  220. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
  221. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  222. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  223. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4366 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
  224. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  225. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
  226. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  227. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  228. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  229. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4366 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
  230. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1]
  231. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
  232. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
  233. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
  234. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4227 Set telephone-event payload to 127@8000
  235. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:3018 Set Codec sofia/internal/2600@192.168.0.137 G722/8000 20 ms 160 samples 64000 bits 1 channels
  236. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_codec.c:111 sofia/internal/2600@192.168.0.137 Original read codec set to G722:9
  237. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4580 Set telephone-event payload to 127@8000
  238. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:4639 sofia/internal/2600@192.168.0.137 Set 2833 dtmf send payload to 127 recv payload to 127
  239. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:6465 AUDIO RTP [sofia/internal/2600@192.168.0.137] 192.168.0.137 port 29450 -> 192.168.0.12 port 2224 codec: 9 ms: 20
  240. 2016-08-02 02:28:15.050206 [DEBUG] switch_rtp.c:3833 Starting timer [soft] 160 bytes per 20ms
  241. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:6764 sofia/internal/2600@192.168.0.137 Set 2833 dtmf send payload to 127
  242. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:6771 sofia/internal/2600@192.168.0.137 Set 2833 dtmf receive payload to 127
  243. 2016-08-02 02:28:15.050206 [DEBUG] switch_core_media.c:6794 sofia/internal/2600@192.168.0.137 Set rtp dtmf delay to 40
  244.  
  245. 2016-08-02 02:28:15.050206 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/2600@192.168.0.137!                                                                                                                                    
  246. 2016-08-02 02:28:15.070584 [DEBUG] switch_channel.c:3471 (sofia/internal/2600@192.168.0.137) Callstate Change RINGING -> EARLY
  247. 2016-08-02 02:28:15.070584 [DEBUG] mod_sofia.c:822 Local SDP sofia/internal/2600@192.168.0.137:
  248. v=0
  249. o=FreeSWITCH 1470075445 1470075446 IN IP4 192.168.0.137
  250. s=FreeSWITCH
  251. c=IN IP4 192.168.0.137
  252. t=0 0
  253. m=audio 29450 RTP/AVP 9 127
  254. a=rtpmap:9 G722/8000
  255. a=rtpmap:127 telephone-event/8000
  256. a=fmtp:127 0-16
  257. a=ptime:20
  258. a=sendrecv
  259.  
  260. 2016-08-02 02:28:15.070584 [NOTICE] mod_dptools.c:1309 Channel [sofia/internal/2600@192.168.0.137] has been answered
  261. 2016-08-02 02:28:15.070584 [DEBUG] switch_channel.c:3770 (sofia/internal/2600@192.168.0.137) Callstate Change EARLY -> ACTIVE
  262. 2016-08-02 02:28:15.070584 [DEBUG] sofia.c:6937 Channel sofia/internal/2600@192.168.0.137 entering state [completed][200]
  263. EXECUTE sofia/internal/2600@192.168.0.137 sleep(2000)
  264. 2016-08-02 02:28:15.070584 [DEBUG] sofia.c:6937 Channel sofia/internal/2600@192.168.0.137 entering state [ready][200]
  265. 2016-08-02 02:28:15.170161 [DEBUG] switch_rtp.c:6718 Correct audio ip/port confirmed.
  266. EXECUTE sofia/internal/2600@192.168.0.137 voicemail(default 2600)
  267. 2016-08-02 02:28:17.230160 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]
  268. 2016-08-02 02:28:17.290184 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-person.wav] (en:en)
  269. 2016-08-02 02:28:17.290184 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@16000hz 1 channels 20ms
  270. 2016-08-02 02:28:18.630198 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-person.wav
  271. 2016-08-02 02:28:18.750172 [DEBUG] switch_ivr_play_say.c:250 Handle say:[] (en:en)
  272. 2016-08-02 02:28:18.870206 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]
  273. 2016-08-02 02:28:18.950176 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-goodbye.wav] (en:en)
  274. 2016-08-02 02:28:18.950176 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@16000hz 1 channels 20ms
  275. 2016-08-02 02:28:19.090194 [NOTICE] sofia.c:988 Hangup sofia/internal/2600@192.168.0.137 [CS_EXECUTE] [NORMAL_CLEARING]
  276. 2016-08-02 02:28:19.090194 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-goodbye.wav
  277. 2016-08-02 02:28:19.090194 [DEBUG] switch_core_session.c:2797 sofia/internal/2600@192.168.0.137 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
  278. 2016-08-02 02:28:19.090194 [DEBUG] switch_core_state_machine.c:609 (sofia/internal/2600@192.168.0.137) State EXECUTE going to sleep
  279. 2016-08-02 02:28:19.090194 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.137) Running State Change CS_HANGUP
  280. 2016-08-02 02:28:19.090194 [DEBUG] switch_core_state_machine.c:809 (sofia/internal/2600@192.168.0.137) Callstate Change ACTIVE -> HANGUP
  281. 2016-08-02 02:28:19.090194 [DEBUG] switch_core_state_machine.c:811 (sofia/internal/2600@192.168.0.137) State HANGUP
  282. 2016-08-02 02:28:19.090194 [DEBUG] mod_sofia.c:432 sofia/internal/2600@192.168.0.137 Overriding SIP cause 480 with 486 from the other leg
  283. 2016-08-02 02:28:19.090194 [DEBUG] mod_sofia.c:438 Channel sofia/internal/2600@192.168.0.137 hanging up, cause: NORMAL_CLEARING
  284. 2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:60 sofia/internal/2600@192.168.0.137 Standard HANGUP, cause: NORMAL_CLEARING
  285. 2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:811 (sofia/internal/2600@192.168.0.137) State HANGUP going to sleep
  286. 2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/2600@192.168.0.137) State Change CS_HANGUP -> CS_REPORTING
  287. 2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/2600@192.168.0.137) Running State Change CS_REPORTING
  288. 2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:897 (sofia/internal/2600@192.168.0.137) State REPORTING
  289. 2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:174 sofia/internal/2600@192.168.0.137 Standard REPORTING, cause: NORMAL_CLEARING
  290. 2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:897 (sofia/internal/2600@192.168.0.137) State REPORTING going to sleep
  291. 2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/2600@192.168.0.137) State Change CS_REPORTING -> CS_DESTROY
  292. 2016-08-02 02:28:19.110195 [DEBUG] switch_core_session.c:1647 Session 82 (sofia/internal/2600@192.168.0.137) Locked, Waiting on external entities
  293. 2016-08-02 02:28:19.110195 [NOTICE] switch_core_session.c:1665 Session 82 (sofia/internal/2600@192.168.0.137) Ended
  294. 2016-08-02 02:28:19.110195 [NOTICE] switch_core_session.c:1669 Close Channel sofia/internal/2600@192.168.0.137 [CS_DESTROY]
  295. 2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:700 (sofia/internal/2600@192.168.0.137) Running State Change CS_DESTROY
  296. 2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:710 (sofia/internal/2600@192.168.0.137) State DESTROY
  297. 2016-08-02 02:28:19.110195 [DEBUG] mod_sofia.c:343 sofia/internal/2600@192.168.0.137 SOFIA DESTROY
  298. 2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:181 sofia/internal/2600@192.168.0.137 Standard DESTROY
  299. 2016-08-02 02:28:19.110195 [DEBUG] switch_core_state_machine.c:710 (sofia/internal/2600@192.168.0.137) State DESTROY going to sleep