From Ungracious Pelican, 7 Years ago, written in Plain Text.
- view diff
Embed
  1. 2017-08-13 19:38:38.361522 [NOTICE] switch_channel.c:1104 New Channel sofia/external/1010@10.240.0.23 [00e94e72-805f-11e7-b4fa-b1e4f221b370]
  2. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1010@10.240.0.23) Running State Change CS_NEW (Cur 1 Tot 382)
  3. 2017-08-13 19:38:38.361522 [DEBUG] sofia.c:9873 sofia/external/1010@10.240.0.23 receiving invite from 39.40.173.218:2429 version: 1.6.19  64bit
  4. 2017-08-13 19:38:38.361522 [DEBUG] sofia.c:7084 Channel sofia/external/1010@10.240.0.23 entering state [received][100]
  5. 2017-08-13 19:38:38.361522 [DEBUG] sofia.c:7094 Remote SDP:
  6. v=0
  7. o=Z 0 0 IN IP4 192.168.10.7
  8. s=Z
  9. c=IN IP4 192.168.10.7
  10. t=0 0
  11. m=audio 35696 RTP/AVP 3 110 8 0 97 101
  12. a=rtpmap:110 speex/8000
  13. a=rtpmap:97 iLBC/8000
  14. a=fmtp:97 mode=30
  15. a=rtpmap:101 telephone-event/8000
  16. a=fmtp:101 0-16
  17.  
  18. 2017-08-13 19:38:38.361522 [DEBUG] sofia.c:7486 (sofia/external/1010@10.240.0.23) State Change CS_NEW -> CS_INIT
  19. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:603 (sofia/external/1010@10.240.0.23) State NEW
  20. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1010@10.240.0.23) Running State Change CS_INIT (Cur 1 Tot 382)
  21. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:627 (sofia/external/1010@10.240.0.23) State INIT
  22. 2017-08-13 19:38:38.361522 [DEBUG] mod_sofia.c:90 sofia/external/1010@10.240.0.23 SOFIA INIT
  23. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:40 sofia/external/1010@10.240.0.23 Standard INIT
  24. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:48 (sofia/external/1010@10.240.0.23) State Change CS_INIT -> CS_ROUTING
  25. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:627 (sofia/external/1010@10.240.0.23) State INIT going to sleep
  26. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1010@10.240.0.23) Running State Change CS_ROUTING (Cur 1 Tot 382)
  27. 2017-08-13 19:38:38.361522 [DEBUG] switch_channel.c:2249 (sofia/external/1010@10.240.0.23) Callstate Change DOWN -> RINGING
  28. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:643 (sofia/external/1010@10.240.0.23) State ROUTING
  29. 2017-08-13 19:38:38.361522 [DEBUG] mod_sofia.c:143 sofia/external/1010@10.240.0.23 SOFIA ROUTING
  30. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:236 sofia/external/1010@10.240.0.23 Standard ROUTING
  31. 2017-08-13 19:38:38.361522 [INFO] mod_dialplan_xml.c:637 Processing 1010 <1010>->9978 in context public
  32. Dialplan: sofia/external/1010@10.240.0.23 parsing [public->fax_receive] continue=false
  33. Dialplan: sofia/external/1010@10.240.0.23 Regex (PASS) [fax_receive] destination_number(9978) =~ /^9978$/ break=on-false
  34. Dialplan: sofia/external/1010@10.240.0.23 Action answer()
  35. Dialplan: sofia/external/1010@10.240.0.23 Action playback(silence_stream://2000)
  36. Dialplan: sofia/external/1010@10.240.0.23 Action set(fax_enable_t38_request=true)
  37. Dialplan: sofia/external/1010@10.240.0.23 Action set(fax_enable_t38=true)
  38. Dialplan: sofia/external/1010@10.240.0.23 Action rxfax(/tmp/FAX-${uuid}.tif)
  39. Dialplan: sofia/external/1010@10.240.0.23 Action hangup()
  40. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:286 (sofia/external/1010@10.240.0.23) State Change CS_ROUTING -> CS_EXECUTE
  41. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:643 (sofia/external/1010@10.240.0.23) State ROUTING going to sleep
  42. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1010@10.240.0.23) Running State Change CS_EXECUTE (Cur 1 Tot 382)
  43. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:650 (sofia/external/1010@10.240.0.23) State EXECUTE
  44. 2017-08-13 19:38:38.361522 [DEBUG] mod_sofia.c:198 sofia/external/1010@10.240.0.23 SOFIA EXECUTE
  45. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_state_machine.c:328 sofia/external/1010@10.240.0.23 Standard EXECUTE
  46. EXECUTE sofia/external/1010@10.240.0.23 answer()
  47. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
  48. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
  49. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
  50. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:110:8000:20:0:1]/[G722:9:8000:20:64000:1]
  51. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:110:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
  52. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:110:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
  53. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  54. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  55. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  56. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
  57. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  58. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  59. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
  60. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  61. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [iLBC:97:8000:30:0:1]/[G722:9:8000:20:64000:1]
  62. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [iLBC:97:8000:30:0:1]/[PCMU:0:8000:20:64000:1]
  63. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [iLBC:97:8000:30:0:1]/[PCMA:8:8000:20:64000:1]
  64. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
  65. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:3061 Set Codec sofia/external/1010@10.240.0.23 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
  66. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_codec.c:111 sofia/external/1010@10.240.0.23 Original read codec set to PCMA:8
  67. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
  68. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:4767 sofia/external/1010@10.240.0.23 Set 2833 dtmf send payload to 101 recv payload to 101
  69. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/external/1010@10.240.0.23] 10.240.0.23 port 20362 -> 192.168.10.7 port 35696 codec: 8 ms: 20
  70. 2017-08-13 19:38:38.361522 [DEBUG] switch_rtp.c:4111 Starting timer [soft] 160 bytes per 20ms
  71. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:7179 sofia/external/1010@10.240.0.23 Set 2833 dtmf send payload to 101
  72. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:7186 sofia/external/1010@10.240.0.23 Set 2833 dtmf receive payload to 101
  73. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:7209 sofia/external/1010@10.240.0.23 Set rtp dtmf delay to 40
  74. 2017-08-13 19:38:38.361522 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/1010@10.240.0.23!
  75. 2017-08-13 19:38:38.361522 [DEBUG] switch_channel.c:3474 (sofia/external/1010@10.240.0.23) Callstate Change RINGING -> EARLY
  76. 2017-08-13 19:38:38.361522 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/external/1010@10.240.0.23.
  77. 2017-08-13 19:38:38.361522 [DEBUG] mod_sofia.c:850 Local SDP sofia/external/1010@10.240.0.23:
  78. v=0
  79. o=FreeSWITCH 1502632756 1502632757 IN IP4 35.197.168.74
  80. s=FreeSWITCH
  81. c=IN IP4 35.197.168.74
  82. t=0 0
  83. m=audio 20362 RTP/AVP 8 101
  84. a=rtpmap:8 PCMA/8000
  85. a=rtpmap:101 telephone-event/8000
  86. a=fmtp:101 0-16
  87. a=ptime:20
  88. a=sendrecv
  89.  
  90. 2017-08-13 19:38:38.361522 [DEBUG] sofia.c:7084 Channel sofia/external/1010@10.240.0.23 entering state [completed][200]
  91. 2017-08-13 19:38:38.361522 [NOTICE] mod_dptools.c:1312 Channel [sofia/external/1010@10.240.0.23] has been answered
  92. 2017-08-13 19:38:38.361522 [DEBUG] switch_channel.c:3773 (sofia/external/1010@10.240.0.23) Callstate Change EARLY -> ACTIVE
  93. EXECUTE sofia/external/1010@10.240.0.23 playback(silence_stream://2000)
  94. 2017-08-13 19:38:38.361522 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
  95. 2017-08-13 19:38:38.861527 [DEBUG] sofia.c:7084 Channel sofia/external/1010@10.240.0.23 entering state [ready][200]
  96. 2017-08-13 19:38:39.341525 [INFO] switch_rtp.c:7231 Auto Changing audio port from 192.168.10.7:35696 to 39.40.173.218:35696
  97. 2017-08-13 19:38:39.341525 [DEBUG] sofia.c:7084 Channel sofia/external/1010@10.240.0.23 entering state [received][100]
  98. 2017-08-13 19:38:39.341525 [DEBUG] sofia.c:7094 Remote SDP:
  99. v=0
  100. o=Z 0 1 IN IP4 192.168.10.7
  101. s=Z
  102. c=IN IP4 192.168.10.7
  103. t=0 0
  104. m=image 35696 udptl t38
  105. a=T38FaxVersion:0
  106. a=T38MaxBitRate:14400
  107. a=T38FaxFillBitRemoval:0
  108. a=T38FaxTranscodingMMR:0
  109. a=T38FaxTranscodingJBIG:0
  110. a=T38FaxRateManagement:transferredTCF
  111. a=T38FaxMaxBuffer:400
  112. a=T38FaxMaxDatagram:400
  113. a=T38FaxUdpEC:t38UDPRedundancy
  114.  
  115. 2017-08-13 19:38:39.341525 [DEBUG] switch_core_media.c:4041 sofia/external/1010@10.240.0.23 T38 ACCEPT on request
  116. 2017-08-13 19:38:39.341525 [DEBUG] switch_core_media.c:4146 sofia/external/1010@10.240.0.23 T38 IS NOT POSSIBLE on request
  117. 2017-08-13 19:38:39.341525 [DEBUG] sofia.c:8007 Reinvite resulted in codec negotiation failure.
  118. 2017-08-13 19:38:39.341525 [DEBUG] sofia.c:7077 Channel sofia/external/1010@10.240.0.23 skipping state [ready][488]
  119. 2017-08-13 19:38:40.341523 [NOTICE] sofia.c:1012 Hangup sofia/external/1010@10.240.0.23 [CS_EXECUTE] [NORMAL_CLEARING]
  120. 2017-08-13 19:38:40.341523 [DEBUG] switch_ivr_play_say.c:1942 done playing file silence_stream://2000
  121. 2017-08-13 19:38:40.341523 [DEBUG] switch_core_session.c:2815 sofia/external/1010@10.240.0.23 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
  122. 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:650 (sofia/external/1010@10.240.0.23) State EXECUTE going to sleep
  123. 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1010@10.240.0.23) Running State Change CS_HANGUP (Cur 1 Tot 382)
  124. 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:850 (sofia/external/1010@10.240.0.23) Callstate Change ACTIVE -> HANGUP
  125. 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:852 (sofia/external/1010@10.240.0.23) State HANGUP
  126. 2017-08-13 19:38:40.341523 [DEBUG] mod_sofia.c:438 Channel sofia/external/1010@10.240.0.23 hanging up, cause: NORMAL_CLEARING
  127. 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:60 sofia/external/1010@10.240.0.23 Standard HANGUP, cause: NORMAL_CLEARING
  128. 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:852 (sofia/external/1010@10.240.0.23) State HANGUP going to sleep
  129. 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:619 (sofia/external/1010@10.240.0.23) State Change CS_HANGUP -> CS_REPORTING
  130. 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1010@10.240.0.23) Running State Change CS_REPORTING (Cur 1 Tot 382)
  131. 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:938 (sofia/external/1010@10.240.0.23) State REPORTING
  132. 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:174 sofia/external/1010@10.240.0.23 Standard REPORTING, cause: NORMAL_CLEARING
  133. 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:938 (sofia/external/1010@10.240.0.23) State REPORTING going to sleep
  134. 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:610 (sofia/external/1010@10.240.0.23) State Change CS_REPORTING -> CS_DESTROY
  135. 2017-08-13 19:38:40.341523 [DEBUG] switch_core_session.c:1665 Session 382 (sofia/external/1010@10.240.0.23) Locked, Waiting on external entities
  136. 2017-08-13 19:38:40.341523 [NOTICE] switch_core_session.c:1683 Session 382 (sofia/external/1010@10.240.0.23) Ended
  137. 2017-08-13 19:38:40.341523 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/1010@10.240.0.23 [CS_DESTROY]
  138. 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:741 (sofia/external/1010@10.240.0.23) Running State Change CS_DESTROY (Cur 0 Tot 382)
  139. 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:751 (sofia/external/1010@10.240.0.23) State DESTROY
  140. 2017-08-13 19:38:40.341523 [DEBUG] mod_sofia.c:343 sofia/external/1010@10.240.0.23 SOFIA DESTROY
  141. 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:181 sofia/external/1010@10.240.0.23 Standard DESTROY
  142. 2017-08-13 19:38:40.341523 [DEBUG] switch_core_state_machine.c:751 (sofia/external/1010@10.240.0.23) State DESTROY going to sleep
  143.  
  144.