FreeSWITCH Pastebin

txfax unexpected message received

From antonio, 6 Years ago, written in Plain Text.
- view diff
URL https://pastebin.freeswitch.org/view/3c433ca6
Embed
Download Paste or View Raw
  1. Sending the fax:
  2. originate {fax_verbose=true}sofia/gateway/CS2K/939165135 &txfax(/root/txfax.tiff)
  3.  
  4.  
  5. LOG:
  6. 2017-11-24 18:29:32.325313 [DEBUG] switch_ivr_originate.c:2147 Parsing global variables
  7. 2017-11-24 18:29:32.325313 [NOTICE] switch_channel.c:1104 New Channel sofia/publico/939165135 [bce7f5cc-f2e2-4ec6-9798-27a00b660b43]
  8. 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [cm_context]=[incoming]
  9. 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [cm_transfer_context]=[incoming]
  10. 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [cm_channel_name]=[line/CS2K]
  11. 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [cm_channel_type]=[line]
  12. 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [cm_line_name]=[CS2K]
  13. 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [dtmf_type]=[rfc2833]
  14. 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [rtp_info_when_no_2833]=[false]
  15. 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [rtp_liberal_dtmf]=[true]
  16. 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [refuse_t38]=[true]
  17. 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [t38_passthru]=[false]
  18. 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [absolute_codec_string]=[PCMA,PCMU]
  19. 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5010 sofia/publico/939165135 setting variable [codec_string]=[PCMA,PCMU]
  20. 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:5026 (sofia/publico/939165135) State Change CS_NEW -> CS_INIT
  21. 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:584 (sofia/publico/939165135) Running State Change CS_INIT (Cur 1 Tot 15351)
  22. 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:627 (sofia/publico/939165135) State INIT
  23. 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:93 sofia/publico/939165135 SOFIA INIT
  24. 2017-11-24 18:29:32.325313 [DEBUG] switch_core_port_allocator.c:183 UDP port robustness check for port 10822 pass
  25. 2017-11-24 18:29:32.325313 [DEBUG] sofia_glue.c:1298 sofia/publico/939165135 sending invite version: 1.9.0 git 4c78733 2017-05-16 19:50:21Z 64bit
  26. Local SDP:
  27. v=0
  28. o=FreeSWITCH 1511533750 1511533751 IN IP4 100.10.10.10
  29. s=FreeSWITCH
  30. c=IN IP4 100.10.10.10
  31. t=0 0
  32. m=audio 10822 RTP/AVP 8 0 101
  33. a=rtpmap:8 PCMA/8000
  34. a=rtpmap:0 PCMU/8000
  35. a=rtpmap:101 telephone-event/8000
  36. a=fmtp:101 0-16
  37. a=silenceSupp:off - - - -
  38. a=ptime:20
  39. a=sendrecv
  40.  
  41. 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:40 sofia/publico/939165135 Standard INIT
  42. 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:48 (sofia/publico/939165135) State Change CS_INIT -> CS_ROUTING
  43. 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:627 (sofia/publico/939165135) State INIT going to sleep
  44. 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:584 (sofia/publico/939165135) Running State Change CS_ROUTING (Cur 1 Tot 15351)
  45. 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:643 (sofia/publico/939165135) State ROUTING
  46. 2017-11-24 18:29:32.325313 [DEBUG] mod_sofia.c:154 sofia/publico/939165135 SOFIA ROUTING
  47. 2017-11-24 18:29:32.325313 [DEBUG] switch_ivr_originate.c:67 (sofia/publico/939165135) State Change CS_ROUTING -> CS_CONSUME_MEDIA
  48. 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:643 (sofia/publico/939165135) State ROUTING going to sleep
  49. 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:584 (sofia/publico/939165135) Running State Change CS_CONSUME_MEDIA (Cur 1 Tot 15351)
  50. 2017-11-24 18:29:32.325313 [DEBUG] sofia.c:7249 Channel sofia/publico/939165135 entering state [calling][0]
  51. 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:662 (sofia/publico/939165135) State CONSUME_MEDIA
  52. 2017-11-24 18:29:32.325313 [DEBUG] switch_core_state_machine.c:662 (sofia/publico/939165135) State CONSUME_MEDIA going to sleep
  53. 2017-11-24 18:29:34.205294 [DEBUG] sofia.c:7249 Channel sofia/publico/939165135 entering state [proceeding][183]
  54. 2017-11-24 18:29:34.205294 [DEBUG] sofia.c:7259 Remote SDP:
  55. v=0
  56. o=genband 294525952 1511544573 IN IP4 100.10.100.10
  57. s=-
  58. c=IN IP4 100.10.100.10
  59. t=0 0
  60. m=audio 41814 RTP/AVP 8 0 101
  61. a=rtpmap:8 PCMA/8000
  62. a=rtpmap:0 PCMU/8000
  63. a=rtpmap:101 telephone-event/8000
  64. a=fmtp:101 0-15
  65. a=silenceSupp:off - - - -
  66. a=ptime:20
  67. a=maxptime:30
  68. a=sqn: 0
  69. a=cdsc:1 image udptl t38
  70.  
  71. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  72. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:5165 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
  73. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  74. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  75. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  76. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:5165 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
  77. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:5026 Set telephone-event payload to 101@8000
  78. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:3425 Set Codec sofia/publico/939165135 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
  79. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_codec.c:111 sofia/publico/939165135 Original read codec set to PCMA:8
  80. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:5369 Set telephone-event payload to 101@8000
  81. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:5427 sofia/publico/939165135 Set 2833 dtmf send payload to 101 recv payload to 101
  82. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:8144 AUDIO RTP [sofia/publico/939165135] 100.10.10.10 port 10822 -> 100.10.100.10 port 41814 codec: 8 ms: 20
  83. 2017-11-24 18:29:34.205294 [DEBUG] switch_rtp.c:4107 Starting timer [soft] 160 bytes per 20ms
  84. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:8447 sofia/publico/939165135 Set 2833 dtmf send payload to 101
  85. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:8454 sofia/publico/939165135 Set 2833 dtmf receive payload to 101
  86. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_media.c:8477 sofia/publico/939165135 Set rtp dtmf delay to 40
  87. 2017-11-24 18:29:34.205294 [NOTICE] sofia_media.c:92 Pre-Answer sofia/publico/939165135!
  88. 2017-11-24 18:29:34.205294 [DEBUG] switch_channel.c:3490 (sofia/publico/939165135) Callstate Change DOWN -> EARLY
  89. 2017-11-24 18:29:34.205294 [DEBUG] switch_ivr_originate.c:3695 Originate Resulted in Success: [sofia/publico/939165135]
  90. 2017-11-24 18:29:34.205294 [INFO] switch_channel.c:3139 sofia/publico/939165135 Flipping CID from "" <0000000000> to "Outbound Call" <939165135>
  91. 2017-11-24 18:29:34.205294 [DEBUG] mod_commands.c:4865 (sofia/publico/939165135) State Change CS_CONSUME_MEDIA -> CS_EXECUTE
  92. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_state_machine.c:584 (sofia/publico/939165135) Running State Change CS_EXECUTE (Cur 1 Tot 15351)
  93. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_state_machine.c:650 (sofia/publico/939165135) State EXECUTE
  94. 2017-11-24 18:29:34.205294 [DEBUG] mod_sofia.c:209 sofia/publico/939165135 SOFIA EXECUTE
  95. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_state_machine.c:328 sofia/publico/939165135 Standard EXECUTE
  96. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_session.c:2806 EXECUTE sofia/publico/939165135 txfax(/root/txfax.tiff)
  97. 2017-11-24 18:29:34.205294 [DEBUG] mod_spandsp_fax.c:1459 Raw read codec activation Success L16 20000
  98. 2017-11-24 18:29:34.205294 [DEBUG] switch_core_codec.c:223 sofia/publico/939165135 Push codec L16:100
  99. 2017-11-24 18:29:34.205294 [DEBUG] mod_spandsp_fax.c:1477 Raw write codec activation Success L16
  100. 2017-11-24 18:29:34.265321 [DEBUG] switch_rtp.c:7266 Correct audio ip/port confirmed.
  101. 2017-11-24 18:29:34.645315 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T
  102. 2017-11-24 18:29:36.185314 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T
  103. 2017-11-24 18:29:39.165314 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T
  104. 2017-11-24 18:29:40.685313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T
  105. 2017-11-24 18:29:41.265295 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T
  106. 2017-11-24 18:29:41.265295 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T
  107. 2017-11-24 18:29:41.265295 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T
  108. 2017-11-24 18:29:41.285310 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T
  109. 2017-11-24 18:29:41.505307 [DEBUG] sofia.c:7249 Channel sofia/publico/939165135 entering state [completing][200]
  110. 2017-11-24 18:29:41.505307 [DEBUG] sofia.c:7256 Duplicate SDP
  111. v=0
  112. o=genband 294525952 1511544573 IN IP4 100.10.100.10
  113. s=-
  114. c=IN IP4 100.10.100.10
  115. t=0 0
  116. m=audio 41814 RTP/AVP 8 0 101
  117. a=rtpmap:8 PCMA/8000
  118. a=rtpmap:0 PCMU/8000
  119. a=rtpmap:101 telephone-event/8000
  120. a=fmtp:101 0-15
  121. a=silenceSupp:off - - - -
  122. a=ptime:20
  123. a=maxptime:30
  124. a=sqn: 0
  125. a=cdsc:1 image udptl t38
  126.  
  127. 2017-11-24 18:29:41.525326 [DEBUG] sofia.c:7249 Channel sofia/publico/939165135 entering state [ready][200]
  128. 2017-11-24 18:29:41.525326 [NOTICE] sofia.c:8327 Channel [sofia/publico/939165135] has been answered
  129. 2017-11-24 18:29:41.525326 [DEBUG] switch_channel.c:3789 (sofia/publico/939165135) Callstate Change EARLY -> ACTIVE
  130. 2017-11-24 18:29:41.565310 [DEBUG] switch_rtp.c:7266 Correct audio ip/port confirmed.
  131. 2017-11-24 18:29:42.605320 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T
  132. 2017-11-24 18:29:43.785309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Abort (-8) in state T
  133. 2017-11-24 18:29:44.065316 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T
  134. 2017-11-24 18:29:44.085313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T
  135. 2017-11-24 18:29:44.085313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T
  136. 2017-11-24 18:29:44.085313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T
  137. 2017-11-24 18:29:44.105312 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T
  138. 2017-11-24 18:29:44.165313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T
  139. 2017-11-24 18:29:46.245310 [WARNING] sofia.c:6270 Ping succeeded euskaltel with code 200 - count 1/1/1, state UP
  140. 2017-11-24 18:29:46.625305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T
  141. 2017-11-24 18:29:47.085320 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T
  142. 2017-11-24 18:29:47.305315 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state T
  143. 2017-11-24 18:29:47.305315 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase A_CNG to B_RX
  144. 2017-11-24 18:29:47.305315 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 4
  145. 2017-11-24 18:29:47.305315 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 0
  146. 2017-11-24 18:29:47.325312 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T
  147. 2017-11-24 18:29:47.465303 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T
  148. 2017-11-24 18:29:47.885318 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T
  149. 2017-11-24 18:29:47.965313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T
  150. 2017-11-24 18:29:48.165318 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state T
  151. 2017-11-24 18:29:48.265308 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Bad HDLC CRC received
  152. 2017-11-24 18:29:48.265308 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Bad CRC and timer is 0
  153. 2017-11-24 18:29:48.365308 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T
  154. 2017-11-24 18:29:48.385310 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T
  155. 2017-11-24 18:29:48.385310 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T
  156. 2017-11-24 18:29:48.445320 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T
  157. 2017-11-24 18:29:48.465319 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T
  158. 2017-11-24 18:29:55.345320 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T
  159. 2017-11-24 18:29:55.605316 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state T
  160. 2017-11-24 18:29:57.025313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop none (0 remaining)
  161. 2017-11-24 18:29:57.025313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  CSI without final frame tag
  162. 2017-11-24 18:29:57.025313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  ff 03 40 35 36 31 39 33 39 31 35 39 20 20 20 20 20 20 20 20 20 20 20
  163. 2017-11-24 18:29:57.025313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Remote gave CSI as: "939165135"
  164. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop none (0 remaining)
  165. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  DIS with final frame tag
  166. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  ff 13 80 00 4e 9a c4 80 d9 80 80 80 80 00 00 00 00
  167. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx final frame in state T
  168. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase B_TX
  169. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 DIS:
  170. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= Store and forward Internet fax (T.37): Not set
  171. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= Real-time Internet fax (T.38): Not set
  172. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 0...= 3G mobile network: Not set
  173. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..0. ....= V.8 capabilities: Not set
  174. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .0.. ....= Preferred octets: 256 octets
  175. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= Ready to transmit a fax document (polling): Not set
  176. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..1.= Can receive fax: Set
  177. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..00 11..= Supported data signalling rates: V.27 ter and V.29
  178. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set
  179. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   0... ....= 2-D coding: Not set
  180. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..10= Recording width: 215mm +- 1%, 255mm +- 1% and 303mm +- 1%
  181. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 10..= Recording length: Unlimited
  182. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .001 ....= Receiver's minimum scan line time: 5ms at 3.85 l/mm; T7.7 = T3.85
  183. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= Extension indicator: Set
  184. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..0.= Compressed/uncompressed mode: Compressed
  185. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .1..= Error correction mode (ECM): ECM
  186. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .1.. ....= T.6 coding: Set
  187. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= Extension indicator: Set
  188. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= "Field not valid" supported: Not set
  189. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..0.= Multiple selective polling: Not set
  190. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= Polled sub-address: Not set
  191. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 0...= T.43 coding: Not set
  192. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ...0 ....= Plane interleave: Not set
  193. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set
  194. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .0.. ....= Reserved for the use of extended voice coding set: Not set
  195. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= Extension indicator: Set
  196. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...1= R8x15.4lines/mm: Set
  197. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..0.= 300x300pels/25.4mm: Not set
  198. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= R16x15.4lines/mm and/or 400x400pels/25.4mm: Not set
  199. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 1...= Inch-based resolution preferred: Set
  200. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ...1 ....= Metric-based resolution preferred: Set
  201. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..0. ....= Minimum scan line time for higher resolutions: T15.4 = T7.7
  202. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .1.. ....= Selective polling: Set
  203. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= Extension indicator: Set
  204. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= Sub-addressing: Not set
  205. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..0.= Password: Not set
  206. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= Ready to transmit a data file (polling): Not set
  207. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ...0 ....= Binary file transfer (BFT): Not set
  208. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..0. ....= Document transfer mode (DTM): Not set
  209. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .0.. ....= Electronic data interchange (EDI): Not set
  210. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= Extension indicator: Set
  211. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= Basic transfer mode (BTM): Not set
  212. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= Ready to transfer a character or mixed mode document (polling): Not set
  213. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 0...= Character mode: Not set
  214. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..0. ....= Mixed mode (Annex E/T.4): Not set
  215. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= Extension indicator: Set
  216. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= Processable mode 26 (Rec. T.505): Not set
  217. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..0.= Digital network capability: Not set
  218. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= Duplex capability: Half only
  219. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 0...= JPEG coding: Not set
  220. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ...0 ....= Full colour mode: Not set
  221. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .0.. ....= 12bits/pel component: Not set
  222. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= Extension indicator: Set
  223. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= No subsampling (1:1:1): Not set
  224. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..0.= Custom illuminant: Not set
  225. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= Custom gamut range: Not set
  226. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 0...= North American Letter (215.9mm x 279.4mm): Not set
  227. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ...0 ....= North American Legal (215.9mm x 355.6mm): Not set
  228. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..0. ....= Single-progression sequential coding (Rec. T.85) basic: Not set
  229. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .0.. ....= Single-progression sequential coding (Rec. T.85) optional L0: Not set
  230. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= Extension indicator: Set
  231. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= HKM key management: Not set
  232. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..0.= RSA key management: Not set
  233. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= Override: Not set
  234. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 0...= HFX40 cipher: Not set
  235. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ...0 ....= Alternative cipher number 2: Not set
  236. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..0. ....= Alternative cipher number 3: Not set
  237. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .0.. ....= HFX40-I hashing: Not set
  238. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   0... ....= Extension indicator: Not set
  239. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:317 === Negotiation Result =======================================================
  240. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:318 Remote station id: 939165135
  241. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:319 Local station id:  
  242. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:320 Transfer Rate:     9600
  243. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:322 ECM status         on
  244. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:323 remote country:  
  245. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:324 remote vendor:    
  246. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:325 remote model:    
  247. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:327 ==============================================================================
  248. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Trying to send file '/root/txfax.tiff'
  249. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start sending document
  250. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Choose image type bi-level (0), compression T.6 (8)
  251. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Minimum bits per row will be 0
  252. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Starting page 1 of transfer
  253. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Partial document buffer contains 25 frames (256 per frame)
  254. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Image width is A4 at 8040dpm x 3850dpm
  255. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Put document with modem (6) V.29 at 9600bps
  256. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state T to D
  257. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 DCS:
  258. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= Store and forward Internet fax (T.37): Not set
  259. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= Real-time Internet fax (T.38): Not set
  260. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 0...= 3G mobile network: Not set
  261. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..1.= Receive fax: Set
  262. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..00 01..= Selected data signalling rate: V.29, 9600bps
  263. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .0.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Not set
  264. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   0... ....= 2-D coding: Not set
  265. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..00= Recording width: 215mm +- 1%
  266. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 10..= Recording length: Unlimited
  267. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .111 ....= Minimum scan line time: 0ms
  268. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= Extension indicator: Set
  269. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..0.= Compressed/uncompressed mode: Compressed
  270. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .1..= Error correction mode (ECM): ECM
  271. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 0...= Frame size: 256 octets
  272. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .1.. ....= T.6 coding: Set
  273. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   0... ....= Extension indicator: Not set
  274. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx:  DCS with final frame tag
  275. 2017-11-24 18:29:57.565305 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx:  ff 13 83 00 06 f8 44
  276. 2017-11-24 18:29:57.605294 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state D
  277. 2017-11-24 18:29:57.605294 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_RX to B_TX
  278. 2017-11-24 18:29:57.605294 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0
  279. 2017-11-24 18:29:57.605294 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 4
  280. 2017-11-24 18:29:58.765307 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase B_TX, state D
  281. 2017-11-24 18:29:58.845313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase B_TX, state D
  282. 2017-11-24 18:29:58.845313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state D to D_TCF
  283. 2017-11-24 18:29:58.845313 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_TX to C_NON_ECM_TX
  284. 2017-11-24 18:29:58.845313 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0
  285. 2017-11-24 18:29:58.845313 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0
  286. 2017-11-24 18:29:58.845313 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 6
  287. 2017-11-24 18:30:00.705317 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase C_NON_ECM_TX, state D_TCF
  288. 2017-11-24 18:30:00.705317 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase C_NON_ECM_TX to B_RX
  289. 2017-11-24 18:30:00.705317 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 4
  290. 2017-11-24 18:30:00.705317 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 0
  291. 2017-11-24 18:30:00.705317 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T4
  292. 2017-11-24 18:30:00.705317 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state D_TCF to D_POST_TCF
  293. 2017-11-24 18:30:04.025321 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state D_POST_TCF
  294. 2017-11-24 18:30:04.065319 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Abort (-8) in state D_POST_TCF
  295. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Retry number 1
  296. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase B_TX
  297. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state D_POST_TCF to D
  298. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 DCS:
  299. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= Store and forward Internet fax (T.37): Not set
  300. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= Real-time Internet fax (T.38): Not set
  301. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 0...= 3G mobile network: Not set
  302. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..1.= Receive fax: Set
  303. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..00 01..= Selected data signalling rate: V.29, 9600bps
  304. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .0.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Not set
  305. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   0... ....= 2-D coding: Not set
  306. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..00= Recording width: 215mm +- 1%
  307. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 10..= Recording length: Unlimited
  308. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .111 ....= Minimum scan line time: 0ms
  309. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= Extension indicator: Set
  310. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..0.= Compressed/uncompressed mode: Compressed
  311. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .1..= Error correction mode (ECM): ECM
  312. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 0...= Frame size: 256 octets
  313. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .1.. ....= T.6 coding: Set
  314. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   0... ....= Extension indicator: Not set
  315. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx:  DCS with final frame tag
  316. 2017-11-24 18:30:04.165296 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx:  ff 13 83 00 06 f8 44
  317. 2017-11-24 18:30:04.285294 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state D
  318. 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop none (0 remaining)
  319. 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  CFR with final frame tag
  320. 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  ff 13 84
  321. 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx final frame in state D
  322. 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Unexpected CFR frame in state D
  323. 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Status changing to 'Unexpected message received'
  324. 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Flushing queued phase B_TX
  325. 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase D_TX
  326. 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state D to C
  327. 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx:  DCN with final frame tag
  328. 2017-11-24 18:30:05.625309 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx:  ff 13 fb
  329. 2017-11-24 18:30:05.645293 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Abort (-8) in state C
  330. 2017-11-24 18:30:05.665314 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state C
  331. 2017-11-24 18:30:05.665314 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_RX to D_TX
  332. 2017-11-24 18:30:05.665314 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0
  333. 2017-11-24 18:30:05.665314 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 4
  334. 2017-11-24 18:30:06.725308 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase D_TX, state C
  335. 2017-11-24 18:30:06.805318 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase D_TX, state C
  336. 2017-11-24 18:30:06.805318 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Starting final pause before disconnecting
  337. 2017-11-24 18:30:06.805318 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase D_TX to E
  338. 2017-11-24 18:30:06.805318 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 0
  339. 2017-11-24 18:30:06.805318 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 1
  340. 2017-11-24 18:30:06.805318 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state C to B
  341. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase E, state B
  342. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:496 ==============================================================================
  343. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:508 Fax processing not successful - result (13) Unexpected message received.
  344. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:513 Remote station id: 939165135
  345. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:514 Local station id:  
  346. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:515 Pages transferred: 0
  347. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:517 Total fax pages:   1
  348. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:518 Image resolution:  8040x3850
  349. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:519 Transfer Rate:     9600
  350. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:521 ECM status         on
  351. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:522 remote country:  
  352. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:523 remote vendor:    
  353. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:524 remote model:    
  354. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:526 ==============================================================================
  355. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state B to CALL_FINISHED
  356. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase E to CALL_FINISHED
  357. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 9
  358. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX FAX exchange complete
  359. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 9
  360. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX FAX exchange complete
  361. 2017-11-24 18:30:07.805310 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Call completed
  362. 2017-11-24 18:30:07.825300 [DEBUG] switch_core_codec.c:248 sofia/publico/939165135 Restore previous codec PCMA:8.
  363. 2017-11-24 18:30:07.825300 [NOTICE] switch_core_state_machine.c:385 sofia/publico/939165135 has executed the last dialplan instruction, hanging up.
  364. 2017-11-24 18:30:07.825300 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/publico/939165135 [CS_EXECUTE] [NORMAL_CLEARING]
  365. 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:650 (sofia/publico/939165135) State EXECUTE going to sleep
  366. 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:584 (sofia/publico/939165135) Running State Change CS_HANGUP (Cur 1 Tot 15351)
  367. 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:850 (sofia/publico/939165135) Callstate Change ACTIVE -> HANGUP
  368. 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:852 (sofia/publico/939165135) State HANGUP
  369. 2017-11-24 18:30:07.825300 [DEBUG] mod_sofia.c:449 Channel sofia/publico/939165135 hanging up, cause: NORMAL_CLEARING
  370. 2017-11-24 18:30:07.825300 [DEBUG] mod_sofia.c:502 Sending BYE to sofia/publico/939165135
  371. 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:60 sofia/publico/939165135 Standard HANGUP, cause: NORMAL_CLEARING
  372. 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:852 (sofia/publico/939165135) State HANGUP going to sleep
  373. 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:619 (sofia/publico/939165135) State Change CS_HANGUP -> CS_REPORTING
  374. 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:584 (sofia/publico/939165135) Running State Change CS_REPORTING (Cur 1 Tot 15351)
  375. 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:938 (sofia/publico/939165135) State REPORTING
  376. 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:174 sofia/publico/939165135 Standard REPORTING, cause: NORMAL_CLEARING
  377. 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:938 (sofia/publico/939165135) State REPORTING going to sleep
  378. 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:610 (sofia/publico/939165135) State Change CS_REPORTING -> CS_DESTROY
  379. 2017-11-24 18:30:07.825300 [DEBUG] switch_core_session.c:1712 Session 15351 (sofia/publico/939165135) Locked, Waiting on external entities
  380. 2017-11-24 18:30:07.825300 [NOTICE] switch_core_session.c:1730 Session 15351 (sofia/publico/939165135) Ended
  381. 2017-11-24 18:30:07.825300 [NOTICE] switch_core_session.c:1734 Close Channel sofia/publico/939165135 [CS_DESTROY]
  382. 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:741 (sofia/publico/939165135) Running State Change CS_DESTROY (Cur 0 Tot 15351)
  383. 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:751 (sofia/publico/939165135) State DESTROY
  384. 2017-11-24 18:30:07.825300 [DEBUG] mod_sofia.c:354 sofia/publico/939165135 SOFIA DESTROY
  385. 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:181 sofia/publico/939165135 Standard DESTROY
  386. 2017-11-24 18:30:07.825300 [DEBUG] switch_core_state_machine.c:751 (sofia/publico/939165135) State DESTROY going to sleep
  387.  

Reply to "txfax unexpected message received"