From Francesco Facco de Lagarda, 5 Years ago, written in Plain Text.
- view diff
Embed
  1. 2018-12-05 17:39:00.287633 [DEBUG] mod_dptools.c:1548 SET sofia/external/069087651@192.168.1.230:5060 [ringback]=[%(2000,4000,440,480)]
  2. EXECUTE sofia/external/069087651@192.168.1.230:5060 set(transfer_ringback=local_stream://moh)
  3. 2018-12-05 17:39:00.287633 [DEBUG] mod_dptools.c:1548 SET sofia/external/069087651@192.168.1.230:5060 [transfer_ringback]=[local_stream://moh]
  4. EXECUTE sofia/external/069087651@192.168.1.230:5060 set(call_timeout=30)
  5. 2018-12-05 17:39:00.287633 [DEBUG] mod_dptools.c:1548 SET sofia/external/069087651@192.168.1.230:5060 [call_timeout]=[30]
  6. EXECUTE sofia/external/069087651@192.168.1.230:5060 set(hangup_after_bridge=true)
  7. 2018-12-05 17:39:00.287633 [DEBUG] mod_dptools.c:1548 SET sofia/external/069087651@192.168.1.230:5060 [hangup_after_bridge]=[true]
  8. EXECUTE sofia/external/069087651@192.168.1.230:5060 set(continue_on_fail=true)
  9. 2018-12-05 17:39:00.287633 [DEBUG] mod_dptools.c:1548 SET sofia/external/069087651@192.168.1.230:5060 [continue_on_fail]=[true]
  10. EXECUTE sofia/external/069087651@192.168.1.230:5060 hash(insert/192.168.1.234-call_return/400/069087651)
  11. EXECUTE sofia/external/069087651@192.168.1.230:5060 hash(insert/192.168.1.234-last_dial_ext/400/77f40c04-6cde-490c-854b-763037c57548)
  12. EXECUTE sofia/external/069087651@192.168.1.230:5060 set(called_party_callgroup=techsupport)
  13. 2018-12-05 17:39:00.287633 [DEBUG] mod_dptools.c:1548 SET sofia/external/069087651@192.168.1.230:5060 [called_party_callgroup]=[techsupport]
  14. EXECUTE sofia/external/069087651@192.168.1.230:5060 hash(insert/192.168.1.234-last_dial_ext/techsupport/77f40c04-6cde-490c-854b-763037c57548)
  15. EXECUTE sofia/external/069087651@192.168.1.230:5060 hash(insert/192.168.1.234-last_dial_ext/global/77f40c04-6cde-490c-854b-763037c57548)
  16. EXECUTE sofia/external/069087651@192.168.1.230:5060 hash(insert/192.168.1.234-last_dial/techsupport/77f40c04-6cde-490c-854b-763037c57548)
  17. EXECUTE sofia/external/069087651@192.168.1.230:5060 bridge(user/400@192.168.1.234)
  18. 2018-12-05 17:39:00.287633 [DEBUG] switch_channel.c:1250 sofia/external/069087651@192.168.1.230:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Wed, 05 Dec 2018 17:39:00 +0100] to event
  19. 2018-12-05 17:39:00.287633 [DEBUG] switch_channel.c:1250 sofia/external/069087651@192.168.1.230:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Wed, 05 Dec 2018 17:39:00 +0100] to event
  20. 2018-12-05 17:39:00.287633 [DEBUG] switch_channel.c:1250 sofia/external/069087651@192.168.1.230:5060 EXPORTING[export_vars] [dialed_extension]=[400] to event
  21. 2018-12-05 17:39:00.287633 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
  22. 2018-12-05 17:39:00.287633 [DEBUG] switch_channel.c:1250 sofia/external/069087651@192.168.1.230:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Wed, 05 Dec 2018 17:39:00 +0100] to event
  23. 2018-12-05 17:39:00.287633 [DEBUG] switch_channel.c:1250 sofia/external/069087651@192.168.1.230:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Wed, 05 Dec 2018 17:39:00 +0100] to event
  24. 2018-12-05 17:39:00.287633 [DEBUG] switch_channel.c:1250 sofia/external/069087651@192.168.1.230:5060 EXPORTING[export_vars] [dialed_extension]=[400] to event
  25. 2018-12-05 17:39:00.287633 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
  26. 2018-12-05 17:39:00.287633 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/400@192.168.1.249:2052 [a65dd1b4-f82d-481e-a2fe-30224a5bff96]
  27. 2018-12-05 17:39:00.287633 [DEBUG] mod_sofia.c:4819 (sofia/internal/400@192.168.1.249:2052) State Change CS_NEW -> CS_INIT
  28. 2018-12-05 17:39:00.287633 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/400@192.168.1.249:2052) Running State Change CS_INIT (Cur 2 Tot 27)
  29. 2018-12-05 17:39:00.287633 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
  30. 2018-12-05 17:39:00.287633 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/400@192.168.1.249:2052) State INIT
  31. 2018-12-05 17:39:00.287633 [DEBUG] mod_sofia.c:90 sofia/internal/400@192.168.1.249:2052 SOFIA INIT
  32. 2018-12-05 17:39:00.327496 [DEBUG] sofia_glue.c:1295 sofia/internal/400@192.168.1.249:2052 sending invite version: 1.6.20 -37-987c9b9 64bit
  33. Local SDP:
  34. v=0
  35. o=FreeSWITCH 1544008162 1544008163 IN IP4 192.168.1.234
  36. s=FreeSWITCH
  37. c=IN IP4 192.168.1.234
  38. t=0 0
  39. m=audio 19778 RTP/AVP 8 0 101
  40. a=rtpmap:8 PCMA/8000
  41. a=rtpmap:0 PCMU/8000
  42. a=rtpmap:101 telephone-event/8000
  43. a=fmtp:101 0-16
  44. a=ptime:20
  45. a=sendrecv
  46.  
  47. 2018-12-05 17:39:00.327496 [DEBUG] switch_core_state_machine.c:40 sofia/internal/400@192.168.1.249:2052 Standard INIT
  48. 2018-12-05 17:39:00.327496 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/400@192.168.1.249:2052) State Change CS_INIT -> CS_ROUTING
  49. 2018-12-05 17:39:00.327496 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/400@192.168.1.249:2052) State INIT going to sleep
  50. 2018-12-05 17:39:00.327496 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/400@192.168.1.249:2052) Running State Change CS_ROUTING (Cur 2 Tot 27)
  51. 2018-12-05 17:39:00.327496 [DEBUG] sofia.c:7084 Channel sofia/internal/400@192.168.1.249:2052 entering state [calling][0]
  52. 2018-12-05 17:39:00.327496 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/400@192.168.1.249:2052) State ROUTING
  53. 2018-12-05 17:39:00.327496 [DEBUG] mod_sofia.c:143 sofia/internal/400@192.168.1.249:2052 SOFIA ROUTING
  54. 2018-12-05 17:39:00.327496 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/400@192.168.1.249:2052) State Change CS_ROUTING -> CS_CONSUME_MEDIA
  55. 2018-12-05 17:39:00.327496 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/400@192.168.1.249:2052) State ROUTING going to sleep
  56. 2018-12-05 17:39:00.327496 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/400@192.168.1.249:2052) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 27)
  57. 2018-12-05 17:39:00.327496 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/400@192.168.1.249:2052) State CONSUME_MEDIA
  58. 2018-12-05 17:39:00.327496 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/400@192.168.1.249:2052) State CONSUME_MEDIA going to sleep
  59. 2018-12-05 17:39:00.367572 [DEBUG] sofia.c:7084 Channel sofia/internal/400@192.168.1.249:2052 entering state [proceeding][180]
  60. 2018-12-05 17:39:00.367572 [NOTICE] sofia.c:7192 Ring-Ready sofia/internal/400@192.168.1.249:2052!
  61. 2018-12-05 17:39:00.367572 [DEBUG] switch_channel.c:3346 (sofia/internal/400@192.168.1.249:2052) Callstate Change DOWN -> RINGING
  62. 2018-12-05 17:39:00.387668 [INFO] switch_ivr_originate.c:1215 Sending early media
  63. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
  64. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  65. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  66. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  67. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
  68. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
  69. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  70. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  71. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
  72. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  73. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
  74. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_media.c:3061 Set Codec sofia/external/069087651@192.168.1.230:5060 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
  75. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_codec.c:111 sofia/external/069087651@192.168.1.230:5060 Original read codec set to PCMA:8
  76. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
  77. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_media.c:4767 sofia/external/069087651@192.168.1.230:5060 Set 2833 dtmf send payload to 101 recv payload to 101
  78. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/external/069087651@192.168.1.230:5060] 192.168.1.234 port 26840 -> 192.168.1.230 port 4884 codec: 8 ms: 20
  79. 2018-12-05 17:39:00.387668 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms
  80. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_media.c:7180 sofia/external/069087651@192.168.1.230:5060 Set 2833 dtmf send payload to 101
  81. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_media.c:7187 sofia/external/069087651@192.168.1.230:5060 Set 2833 dtmf receive payload to 101
  82. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_media.c:7210 sofia/external/069087651@192.168.1.230:5060 Set rtp dtmf delay to 40
  83. 2018-12-05 17:39:00.387668 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/069087651@192.168.1.230:5060!
  84. 2018-12-05 17:39:00.387668 [DEBUG] switch_channel.c:3474 (sofia/external/069087651@192.168.1.230:5060) Callstate Change RINGING -> EARLY
  85. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/external/069087651@192.168.1.230:5060.
  86. 2018-12-05 17:39:00.387668 [DEBUG] mod_sofia.c:2364 Ring SDP:
  87. v=0
  88. o=FreeSWITCH 1544001100 1544001101 IN IP4 192.168.1.234
  89. s=FreeSWITCH
  90. c=IN IP4 192.168.1.234
  91. t=0 0
  92. m=audio 26840 RTP/AVP 8 101
  93. a=rtpmap:8 PCMA/8000
  94. a=rtpmap:101 telephone-event/8000
  95. a=fmtp:101 0-16
  96. a=ptime:20
  97. a=sendrecv
  98.  
  99. 2018-12-05 17:39:00.387668 [DEBUG] switch_ivr_originate.c:1273 Raw Codec Activation Success L16@8000hz 1 channel 20ms
  100. 2018-12-05 17:39:00.387668 [DEBUG] switch_core_codec.c:223 sofia/external/069087651@192.168.1.230:5060 Push codec L16:100
  101. 2018-12-05 17:39:00.387668 [DEBUG] switch_ivr_originate.c:1342 Play Ringback Tone [%(2000,4000,440,480)]
  102. 2018-12-05 17:39:00.407597 [DEBUG] sofia.c:7084 Channel sofia/external/069087651@192.168.1.230:5060 entering state [early][183]
  103. 2018-12-05 17:39:00.607524 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
  104. 2018-12-05 17:39:00.867636 [DEBUG] sofia.c:7084 Channel sofia/internal/400@192.168.1.249:2052 entering state [proceeding][180]
  105. 2018-12-05 17:39:01.887630 [DEBUG] sofia.c:7084 Channel sofia/internal/400@192.168.1.249:2052 entering state [proceeding][180]
  106. 2018-12-05 17:39:01.987508 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/069087651@192.168.1.234 [b0a5c1dd-1015-4f75-a077-e919e907fdb7]
  107. 2018-12-05 17:39:01.987508 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/069087651@192.168.1.234) Running State Change CS_NEW (Cur 3 Tot 28)
  108. 2018-12-05 17:39:01.987508 [DEBUG] sofia.c:9873 sofia/internal/069087651@192.168.1.234 receiving invite from 192.168.1.240:5060 version: 1.6.20 -37-987c9b9 64bit
  109. 2018-12-05 17:39:01.987508 [DEBUG] sofia.c:10044 IP 192.168.1.240 Rejected by acl "domains". Falling back to Digest auth.
  110. 2018-12-05 17:39:01.987508 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/069087651@192.168.1.234) State NEW
  111. 2018-12-05 17:39:01.987508 [DEBUG] sofia.c:2334 detaching session b0a5c1dd-1015-4f75-a077-e919e907fdb7
  112. 2018-12-05 17:39:02.087550 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/069087651@192.168.1.234 [403c079e-ee01-47e9-a9fd-6c71537ecbcd]
  113. 2018-12-05 17:39:02.087550 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/069087651@192.168.1.234) Running State Change CS_NEW (Cur 4 Tot 29)
  114. 2018-12-05 17:39:02.087550 [DEBUG] sofia.c:9873 sofia/internal/069087651@192.168.1.234 receiving invite from 192.168.1.240:5060 version: 1.6.20 -37-987c9b9 64bit
  115. 2018-12-05 17:39:02.087550 [DEBUG] sofia.c:10044 IP 192.168.1.240 Rejected by acl "domains". Falling back to Digest auth.
  116. 2018-12-05 17:39:02.087550 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/069087651@192.168.1.234) State NEW
  117. 2018-12-05 17:39:02.087550 [DEBUG] sofia.c:2334 detaching session 403c079e-ee01-47e9-a9fd-6c71537ecbcd
  118. 2018-12-05 17:39:02.227633 [DEBUG] sofia.c:2442 Re-attaching to session b0a5c1dd-1015-4f75-a077-e919e907fdb7
  119. 2018-12-05 17:39:02.227633 [DEBUG] sofia.c:9873 sofia/internal/069087651@192.168.1.234 receiving invite from 192.168.1.240:5060 version: 1.6.20 -37-987c9b9 64bit
  120. 2018-12-05 17:39:02.227633 [DEBUG] sofia.c:10044 IP 192.168.1.240 Rejected by acl "domains". Falling back to Digest auth.
  121. 2018-12-05 17:39:02.227633 [WARNING] sofia_reg.c:2906 Can't find user [069087651@192.168.1.234] from 192.168.1.240
  122. You must define a domain called '192.168.1.234' in your directory and add a user with the id="069087651" attribute
  123. and you must configure your device to use the proper domain in it's authentication credentials.
  124. 2018-12-05 17:39:02.227633 [NOTICE] sofia.c:2332 Hangup sofia/internal/069087651@192.168.1.234 [CS_NEW] [CALL_REJECTED]
  125. 2018-12-05 17:39:02.227633 [DEBUG] sofia.c:2442 Re-attaching to session 403c079e-ee01-47e9-a9fd-6c71537ecbcd
  126. 2018-12-05 17:39:02.227633 [DEBUG] sofia.c:9873 sofia/internal/069087651@192.168.1.234 receiving invite from 192.168.1.240:5060 version: 1.6.20 -37-987c9b9 64bit
  127. 2018-12-05 17:39:02.227633 [DEBUG] sofia.c:10044 IP 192.168.1.240 Rejected by acl "domains". Falling back to Digest auth.
  128. 2018-12-05 17:39:02.227633 [WARNING] sofia_reg.c:2906 Can't find user [069087651@192.168.1.234] from 192.168.1.240
  129. You must define a domain called '192.168.1.234' in your directory and add a user with the id="069087651" attribute
  130. and you must configure your device to use the proper domain in it's authentication credentials.
  131. 2018-12-05 17:39:02.227633 [NOTICE] sofia.c:2332 Hangup sofia/internal/069087651@192.168.1.234 [CS_NEW] [CALL_REJECTED]
  132. 2018-12-05 17:39:02.227633 [DEBUG] sofia.c:1453 Channel is already hungup.
  133. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/069087651@192.168.1.234) Running State Change CS_HANGUP (Cur 4 Tot 29)
  134. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/069087651@192.168.1.234) Callstate Change DOWN -> HANGUP
  135. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/069087651@192.168.1.234) State HANGUP
  136. 2018-12-05 17:39:02.227633 [DEBUG] mod_sofia.c:438 Channel sofia/internal/069087651@192.168.1.234 hanging up, cause: CALL_REJECTED
  137. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:60 sofia/internal/069087651@192.168.1.234 Standard HANGUP, cause: CALL_REJECTED
  138. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/069087651@192.168.1.234) State HANGUP going to sleep
  139. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/069087651@192.168.1.234) State Change CS_HANGUP -> CS_REPORTING
  140. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/069087651@192.168.1.234) Running State Change CS_REPORTING (Cur 4 Tot 29)
  141. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/069087651@192.168.1.234) State REPORTING
  142. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:174 sofia/internal/069087651@192.168.1.234 Standard REPORTING, cause: CALL_REJECTED
  143. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/069087651@192.168.1.234) State REPORTING going to sleep
  144. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/069087651@192.168.1.234) State Change CS_REPORTING -> CS_DESTROY
  145. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_session.c:1665 Session 29 (sofia/internal/069087651@192.168.1.234) Locked, Waiting on external entities
  146. 2018-12-05 17:39:02.227633 [NOTICE] switch_core_session.c:1683 Session 29 (sofia/internal/069087651@192.168.1.234) Ended
  147. 2018-12-05 17:39:02.227633 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/069087651@192.168.1.234 [CS_DESTROY]
  148. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/069087651@192.168.1.234) Running State Change CS_DESTROY (Cur 3 Tot 29)
  149. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/069087651@192.168.1.234) State DESTROY
  150. 2018-12-05 17:39:02.227633 [DEBUG] mod_sofia.c:343 sofia/internal/069087651@192.168.1.234 SOFIA DESTROY
  151. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:181 sofia/internal/069087651@192.168.1.234 Standard DESTROY
  152. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/069087651@192.168.1.234) State DESTROY going to sleep
  153. 2018-12-05 17:39:02.227633 [DEBUG] sofia.c:1453 Channel is already hungup.
  154. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/069087651@192.168.1.234) Running State Change CS_HANGUP (Cur 3 Tot 29)
  155. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/069087651@192.168.1.234) Callstate Change DOWN -> HANGUP
  156. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/069087651@192.168.1.234) State HANGUP
  157. 2018-12-05 17:39:02.227633 [DEBUG] mod_sofia.c:438 Channel sofia/internal/069087651@192.168.1.234 hanging up, cause: CALL_REJECTED
  158. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:60 sofia/internal/069087651@192.168.1.234 Standard HANGUP, cause: CALL_REJECTED
  159. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/069087651@192.168.1.234) State HANGUP going to sleep
  160. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/069087651@192.168.1.234) State Change CS_HANGUP -> CS_REPORTING
  161. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/069087651@192.168.1.234) Running State Change CS_REPORTING (Cur 3 Tot 29)
  162. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/069087651@192.168.1.234) State REPORTING
  163. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:174 sofia/internal/069087651@192.168.1.234 Standard REPORTING, cause: CALL_REJECTED
  164. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/069087651@192.168.1.234) State REPORTING going to sleep
  165. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/069087651@192.168.1.234) State Change CS_REPORTING -> CS_DESTROY
  166. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_session.c:1665 Session 28 (sofia/internal/069087651@192.168.1.234) Locked, Waiting on external entities
  167. 2018-12-05 17:39:02.227633 [NOTICE] switch_core_session.c:1683 Session 28 (sofia/internal/069087651@192.168.1.234) Ended
  168. 2018-12-05 17:39:02.227633 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/069087651@192.168.1.234 [CS_DESTROY]
  169. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/069087651@192.168.1.234) Running State Change CS_DESTROY (Cur 2 Tot 29)
  170. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/069087651@192.168.1.234) State DESTROY
  171. 2018-12-05 17:39:02.227633 [DEBUG] mod_sofia.c:343 sofia/internal/069087651@192.168.1.234 SOFIA DESTROY
  172. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:181 sofia/internal/069087651@192.168.1.234 Standard DESTROY
  173. 2018-12-05 17:39:02.227633 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/069087651@192.168.1.234) State DESTROY going to sleep
  174. 2018-12-05 17:39:02.667648 [DEBUG] sofia.c:7084 Channel sofia/external/069087651@192.168.1.230:5060 entering state [terminated][487]
  175. 2018-12-05 17:39:02.667648 [NOTICE] sofia.c:8273 Hangup sofia/external/069087651@192.168.1.230:5060 [CS_EXECUTE] [ORIGINATOR_CANCEL]
  176. 2018-12-05 17:39:02.667648 [DEBUG] switch_core_codec.c:248 sofia/external/069087651@192.168.1.230:5060 Restore previous codec PCMA:8.
  177. 2018-12-05 17:39:02.667648 [NOTICE] switch_ivr_originate.c:3612 Hangup sofia/internal/400@192.168.1.249:2052 [CS_CONSUME_MEDIA] [ORIGINATOR_CANCEL]
  178. 2018-12-05 17:39:02.667648 [DEBUG] switch_ivr_originate.c:3837 Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL]
  179. 2018-12-05 17:39:02.667648 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/400@192.168.1.249:2052) Running State Change CS_HANGUP (Cur 2 Tot 29)
  180. 2018-12-05 17:39:02.667648 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/400@192.168.1.249:2052) Callstate Change RINGING -> HANGUP
  181. 2018-12-05 17:39:02.667648 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [user] cause: [ORIGINATOR_CANCEL]
  182. 2018-12-05 17:39:02.667648 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 487 [ORIGINATOR_CANCEL]
  183. 2018-12-05 17:39:02.667648 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/400@192.168.1.249:2052) State HANGUP
  184. 2018-12-05 17:39:02.667648 [DEBUG] mod_sofia.c:432 sofia/internal/400@192.168.1.249:2052 Overriding SIP cause 487 with 487 from the other leg
  185. 2018-12-05 17:39:02.667648 [DEBUG] mod_sofia.c:438 Channel sofia/internal/400@192.168.1.249:2052 hanging up, cause: ORIGINATOR_CANCEL
  186. 2018-12-05 17:39:02.667648 [INFO] mod_dptools.c:3436 Originate Failed.  Cause: ORIGINATOR_CANCEL
  187. 2018-12-05 17:39:02.667648 [DEBUG] switch_core_session.c:2815 sofia/external/069087651@192.168.1.230:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
  188. 2018-12-05 17:39:02.667648 [DEBUG] switch_core_state_machine.c:650 (sofia/external/069087651@192.168.1.230:5060) State EXECUTE going to sleep
  189. 2018-12-05 17:39:02.667648 [DEBUG] switch_core_state_machine.c:584 (sofia/external/069087651@192.168.1.230:5060) Running State Change CS_HANGUP (Cur 2 Tot 29)
  190. 2018-12-05 17:39:02.667648 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/internal/400@192.168.1.249:2052
  191. 2018-12-05 17:39:02.667648 [DEBUG] switch_core_state_machine.c:850 (sofia/external/069087651@192.168.1.230:5060) Callstate Change EARLY -> HANGUP
  192. 2018-12-05 17:39:02.667648 [DEBUG] switch_core_state_machine.c:852 (sofia/external/069087651@192.168.1.230:5060) State HANGUP
  193. 2018-12-05 17:39:02.667648 [DEBUG] mod_sofia.c:438 Channel sofia/external/069087651@192.168.1.230:5060 hanging up, cause: ORIGINATOR_CANCEL
  194. 2018-12-05 17:39:02.667648 [DEBUG] switch_core_state_machine.c:60 sofia/external/069087651@192.168.1.230:5060 Standard HANGUP, cause: ORIGINATOR_CANCEL
  195. 2018-12-05 17:39:02.667648 [DEBUG] switch_core_state_machine.c:60 sofia/internal/400@192.168.1.249:2052 Standard HANGUP, cause: ORIGINATOR_CANCEL
  196. 2018-12-05 17:39:02.667648 [DEBUG] switch_core_state_machine.c:852 (sofia/external/069087651@192.168.1.230:5060) State HANGUP going to sleep
  197. 2018-12-05 17:39:02.667648 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/400@192.168.1.249:2052) State HANGUP going to sleep
  198. 2018-12-05 17:39:02.667648 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/400@192.168.1.249:2052) State Change CS_HANGUP -> CS_REPORTING
  199. 2018-12-05 17:39:02.667648 [DEBUG] switch_core_state_machine.c:619 (sofia/external/069087651@192.168.1.230:5060) State Change CS_HANGUP -> CS_REPORTING
  200. 2018-12-05 17:39:02.667648 [DEBUG] switch_core_state_machine.c:584 (sofia/external/069087651@192.168.1.230:5060) Running State Change CS_REPORTING (Cur 2 Tot 29)
  201. 2018-12-05 17:39:02.667648 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/400@192.168.1.249:2052) Running State Change CS_REPORTING (Cur 2 Tot 29)
  202. 2018-12-05 17:39:02.667648 [DEBUG] switch_core_state_machine.c:938 (sofia/external/069087651@192.168.1.230:5060) State REPORTING
  203. 2018-12-05 17:39:02.667648 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/400@192.168.1.249:2052) State REPORTING
  204. 2018-12-05 17:39:02.667648 [DEBUG] mod_odbc_cdr.c:309 sql INSERT INTO cdr_table_both (CallId, TEST_id) VALUES ('a65dd1b4-f82d-481e-a2fe-30224a5bff96', '069087651@192.168.1.234')
  205. 2018-12-05 17:39:02.667648 [DEBUG] mod_odbc_cdr.c:309 sql INSERT INTO cdr_table_both (CallId, TEST_id) VALUES ('77f40c04-6cde-490c-854b-763037c57548', '069087651@192.168.1.230:5060')
  206. 2018-12-05 17:39:02.727612 [DEBUG] mod_odbc_cdr.c:309 sql INSERT INTO cdr_table_b_leg (TelNumberFull, CallId, orig_id, CallerID, IP, term_id, ClientId) VALUES ('400', '77f40c04-6cde-490c-854b-763037c57548', 'a65dd1b4-f82d-481e-a2fe-30224a5bff96', '069087651', '192.168.1.249', '1bf02f25-734f-1237-4fa8-d485646a6cbc', 'a65dd1b4-f82d-481e-a2fe-30224a5bff96')
  207. 2018-12-05 17:39:02.807652 [DEBUG] mod_odbc_cdr.c:309 sql INSERT INTO cdr_table_a_leg (TelNumberFull, TelNumber, CallId, sip_endpoint_disposition, orig_id, CallerID, CODEC, sip_current_application, directGateway, IPInternal, IP, term_id, ClientId) VALUES ('064114551', '064114551', '77f40c04-6cde-490c-854b-763037c57548', 'EARLY MEDIA', '77f40c04-6cde-490c-854b-763037c57548', '069087651', 'PCMA', 'bridge', '192.168.1.234', '192.168.1.230', '192.168.1.230', '9783f9bad781b650', '77f40c04-6cde-490c-854b-763037c57548')
  208. 2018-12-05 17:39:02.867646 [DEBUG] switch_core_state_machine.c:174 sofia/internal/400@192.168.1.249:2052 Standard REPORTING, cause: ORIGINATOR_CANCEL
  209. 2018-12-05 17:39:02.867646 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/400@192.168.1.249:2052) State REPORTING going to sleep
  210. 2018-12-05 17:39:02.867646 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/400@192.168.1.249:2052) State Change CS_REPORTING -> CS_DESTROY
  211. 2018-12-05 17:39:02.867646 [DEBUG] switch_core_session.c:1665 Session 27 (sofia/internal/400@192.168.1.249:2052) Locked, Waiting on external entities
  212. 2018-12-05 17:39:02.867646 [NOTICE] switch_core_session.c:1683 Session 27 (sofia/internal/400@192.168.1.249:2052) Ended
  213. 2018-12-05 17:39:02.867646 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/400@192.168.1.249:2052 [CS_DESTROY]
  214. 2018-12-05 17:39:02.867646 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/400@192.168.1.249:2052) Running State Change CS_DESTROY (Cur 1 Tot 29)
  215. 2018-12-05 17:39:02.867646 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/400@192.168.1.249:2052) State DESTROY
  216. 2018-12-05 17:39:02.867646 [DEBUG] mod_sofia.c:343 sofia/internal/400@192.168.1.249:2052 SOFIA DESTROY
  217. 2018-12-05 17:39:02.867646 [DEBUG] switch_core_state_machine.c:181 sofia/internal/400@192.168.1.249:2052 Standard DESTROY
  218. 2018-12-05 17:39:02.867646 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/400@192.168.1.249:2052) State DESTROY going to sleep
  219. 2018-12-05 17:39:02.907656 [DEBUG] switch_core_state_machine.c:174 sofia/external/069087651@192.168.1.230:5060 Standard REPORTING, cause: ORIGINATOR_CANCEL
  220. 2018-12-05 17:39:02.907656 [DEBUG] switch_core_state_machine.c:938 (sofia/external/069087651@192.168.1.230:5060) State REPORTING going to sleep
  221. 2018-12-05 17:39:02.907656 [DEBUG] switch_core_state_machine.c:610 (sofia/external/069087651@192.168.1.230:5060) State Change CS_REPORTING -> CS_DESTROY
  222. 2018-12-05 17:39:02.907656 [DEBUG] switch_core_session.c:1665 Session 26 (sofia/external/069087651@192.168.1.230:5060) Locked, Waiting on external entities
  223. 2018-12-05 17:39:02.907656 [NOTICE] switch_core_session.c:1683 Session 26 (sofia/external/069087651@192.168.1.230:5060) Ended
  224. 2018-12-05 17:39:02.907656 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/069087651@192.168.1.230:5060 [CS_DESTROY]
  225. 2018-12-05 17:39:02.907656 [DEBUG] switch_core_state_machine.c:741 (sofia/external/069087651@192.168.1.230:5060) Running State Change CS_DESTROY (Cur 0 Tot 29)
  226. 2018-12-05 17:39:02.907656 [DEBUG] switch_core_state_machine.c:751 (sofia/external/069087651@192.168.1.230:5060) State DESTROY
  227. 2018-12-05 17:39:02.907656 [DEBUG] mod_sofia.c:343 sofia/external/069087651@192.168.1.230:5060 SOFIA DESTROY
  228. 2018-12-05 17:39:02.907656 [DEBUG] switch_core_state_machine.c:181 sofia/external/069087651@192.168.1.230:5060 Standard DESTROY
  229. 2018-12-05 17:39:02.907656 [DEBUG] switch_core_state_machine.c:751 (sofia/external/069087651@192.168.1.230:5060) State DESTROY going to sleep