[Freeswitch-users] Can't receive fax via Linksys SPA3000

13 Nov 2013

      We use hylafax + 56k modem to send/receive fax for many years.

These days, I bought a Linksys SPA3000(not support T.38) ,and want to
use freeswitch as our fax system.

After several tests, I found it's hard to make it work :(

Panasonic Fax Machine -> .....PSTN..... ->(FXO) SPA3000 -> ...LAN...
->FreeSWITCH

Error: Fax processing not successful - result (13) Unexpected message received.

FreeSWITCH (Version 1.2.14 git f47e523 2013-11-06 22:57:49Z 64bit)

here is the debug log:

2013-11-13 22:14:38.985423 [NOTICE] switch_channel.c:1052 New Channel
sofia/internal/88086822@192.168.1.77
[f1e3a2ee-6d4c-e311-a706-0013722e92ac]
2013-11-13 22:14:38.985423 [DEBUG] switch_core_session.c:1006 Send
signal sofia/internal/88086822@192.168.1.77 [BREAK]
2013-11-13 22:14:38.985423 [DEBUG] switch_core_session.c:1006 Send
signal sofia/internal/88086822@192.168.1.77 [BREAK]
2013-11-13 22:14:39.005424 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/88086822@192.168.1.77) Running State Change CS_NEW
2013-11-13 22:14:39.005424 [DEBUG] switch_core_state_machine.c:433
(sofia/internal/88086822@192.168.1.77) State NEW
2013-11-13 22:14:39.025066 [DEBUG] sofia.c:7954 IP 192.168.1.51
Rejected by acl "domains". Falling back to Digest auth.
2013-11-13 22:14:39.025066 [DEBUG] switch_core_session.c:1006 Send
signal sofia/internal/88086822@192.168.1.77 [BREAK]
2013-11-13 22:14:39.025066 [DEBUG] sofia.c:1766 detaching session
f1e3a2ee-6d4c-e311-a706-0013722e92ac
2013-11-13 22:14:39.044329 [DEBUG] sofia.c:1858 Re-attaching to
session f1e3a2ee-6d4c-e311-a706-0013722e92ac
2013-11-13 22:14:39.044329 [DEBUG] switch_core_session.c:1006 Send
signal sofia/internal/88086822@192.168.1.77 [BREAK]
2013-11-13 22:14:39.044329 [DEBUG] switch_core_session.c:1006 Send
signal sofia/internal/88086822@192.168.1.77 [BREAK]
2013-11-13 22:14:39.044329 [DEBUG] sofia.c:7954 IP 192.168.1.51
Rejected by acl "domains". Falling back to Digest auth.
2013-11-13 22:14:39.044329 [DEBUG] sofia.c:5752 Channel
sofia/internal/88086822@192.168.1.77 entering state [received][100]
2013-11-13 22:14:39.044329 [DEBUG] sofia.c:5765 Remote SDP:
v=0
o=- 2705082 2705082 IN IP4 192.168.1.51
s=-
c=IN IP4 192.168.1.51
t=0 0
m=audio 16460 RTP/AVP 0 2 4 8 18 96 97 98 100 101
a=rtpmap:0 PCMU/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:4 G723/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729a/8000
a=rtpmap:96 G726-40/8000
a=rtpmap:97 G726-24/8000
a=rtpmap:98 G726-16/8000
a=rtpmap:100 NSE/8000
a=fmtp:100 192-193
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2013-11-13 22:14:39.044329 [DEBUG] sofia.c:6012
(sofia/internal/88086822@192.168.1.77) State Change CS_NEW -> CS_INIT
2013-11-13 22:14:39.044329 [DEBUG] switch_core_session.c:1341 Send
signal sofia/internal/88086822@192.168.1.77 [BREAK]
2013-11-13 22:14:39.044329 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/88086822@192.168.1.77) Running State Change CS_INIT
2013-11-13 22:14:39.044329 [DEBUG] switch_core_state_machine.c:454
(sofia/internal/88086822@192.168.1.77) State INIT
2013-11-13 22:14:39.044329 [DEBUG] mod_sofia.c:87
sofia/internal/88086822@192.168.1.77 SOFIA INIT
2013-11-13 22:14:39.044329 [DEBUG] mod_sofia.c:127
(sofia/internal/88086822@192.168.1.77) State Change CS_INIT ->
CS_ROUTING
2013-11-13 22:14:39.044329 [DEBUG] switch_core_session.c:1341 Send
signal sofia/internal/88086822@192.168.1.77 [BREAK]
2013-11-13 22:14:39.044329 [DEBUG] switch_core_state_machine.c:454
(sofia/internal/88086822@192.168.1.77) State INIT going to sleep
2013-11-13 22:14:39.044329 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/88086822@192.168.1.77) Running State Change CS_ROUTING
2013-11-13 22:14:39.044329 [DEBUG] switch_channel.c:2164
(sofia/internal/88086822@192.168.1.77) Callstate Change DOWN ->
RINGING
2013-11-13 22:14:39.044329 [DEBUG] switch_core_state_machine.c:470
(sofia/internal/88086822@192.168.1.77) State ROUTING
2013-11-13 22:14:39.044329 [DEBUG] mod_sofia.c:150
sofia/internal/88086822@192.168.1.77 SOFIA ROUTING
2013-11-13 22:14:39.044329 [DEBUG] switch_core_state_machine.c:117
sofia/internal/88086822@192.168.1.77 Standard ROUTING
2013-11-13 22:14:39.044329 [INFO] mod_dialplan_xml.c:558 Processing
PSTN Line <88086822>->1013 in context default
Dialplan: sofia/internal/88086822@192.168.1.77 parsing
[default->unloop] continue=false
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (PASS) [unloop]
${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (FAIL) [unloop]
${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 parsing
[default->tod_example] continue=true
Dialplan: sofia/internal/88086822@192.168.1.77 Date/TimeMatch (FAIL)
[tod_example] break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 parsing
[default->holiday_example] continue=true
Dialplan: sofia/internal/88086822@192.168.1.77 Date/TimeMatch (FAIL)
[holiday_example] break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 parsing
[default->global-intercept] continue=false
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (FAIL)
[global-intercept] destination_number(1013) =~ /^886$/ break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 parsing
[default->group-intercept] continue=false
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (FAIL)
[group-intercept] destination_number(1013) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 parsing
[default->intercept-ext] continue=false
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (FAIL)
[intercept-ext] destination_number(1013) =~ /^\*\*(\d+)$/
break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 parsing
[default->redial] continue=false
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (FAIL) [redial]
destination_number(1013) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 parsing
[default->global] continue=true
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (PASS) [global]
${call_debug}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/88086822@192.168.1.77 Action info()
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (FAIL) [global]
${sip_has_crypto}() =~
/^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (PASS) [global]
${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED
NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (FAIL) [global]
${switch_r_sdp}(v=0
o=- 2705082 2705082 IN IP4 192.168.1.51
s=-
c=IN IP4 192.168.1.51
t=0 0
m=audio 16460 RTP/AVP 0 2 4 8 18 96 97 98 100 101
a=rtpmap:0 PCMU/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:4 G723/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729a/8000
a=rtpmap:96 G726-40/8000
a=rtpmap:97 G726-24/8000
a=rtpmap:98 G726-16/8000
a=rtpmap:100 NSE/8000
a=fmtp:100 192-193
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
Dialplan: sofia/internal/88086822@192.168.1.77 Absolute Condition [global]
Dialplan: sofia/internal/88086822@192.168.1.77 Action
hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/88086822@192.168.1.77 Action
hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/88086822@192.168.1.77 Action
hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/88086822@192.168.1.77 Action
export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/88086822@192.168.1.77 parsing
[default->snom-demo-2] continue=false
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (FAIL)
[snom-demo-2] destination_number(1013) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 parsing
[default->snom-demo-1] continue=false
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (FAIL)
[snom-demo-1] destination_number(1013) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 parsing
[default->eavesdrop] continue=false
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (FAIL)
[eavesdrop] destination_number(1013) =~ /^88(\d{4})$|^\*0(.*)$/
break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 parsing
[default->eavesdrop] continue=false
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (FAIL)
[eavesdrop] destination_number(1013) =~ /^779$/ break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 parsing
[default->call_return] continue=false
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (FAIL)
[call_return] destination_number(1013) =~ /^\*69$|^869$|^lcr$/
break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 parsing
[default->del-group] continue=false
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (FAIL)
[del-group] destination_number(1013) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 parsing
[default->add-group] continue=false
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (FAIL)
[add-group] destination_number(1013) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 parsing
[default->call-group-simo] continue=false
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (FAIL)
[call-group-simo] destination_number(1013) =~ /^82(\d{2})$/
break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 parsing
[default->call-group-order] continue=false
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (FAIL)
[call-group-order] destination_number(1013) =~ /^83(\d{2})$/
break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 parsing
[default->extension-intercom] continue=false
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (FAIL)
[extension-intercom] destination_number(1013) =~ /^8(10[01][0-9])$/
break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 parsing
[default->fax_receive] continue=false
Dialplan: sofia/internal/88086822@192.168.1.77 Regex (PASS)
[fax_receive] destination_number(1013) =~ /^1013$/ break=on-false
Dialplan: sofia/internal/88086822@192.168.1.77 Action answer()
Dialplan: sofia/internal/88086822@192.168.1.77 Action
playback(silence_stream://2000)
Dialplan: sofia/internal/88086822@192.168.1.77 Action
rxfax(/tmp/FAX-${uuid}.tif)
Dialplan: sofia/internal/88086822@192.168.1.77 Action hangup()
2013-11-13 22:14:39.044329 [DEBUG] switch_core_state_machine.c:167
(sofia/internal/88086822@192.168.1.77) State Change CS_ROUTING ->
CS_EXECUTE
2013-11-13 22:14:39.044329 [DEBUG] switch_core_session.c:1341 Send
signal sofia/internal/88086822@192.168.1.77 [BREAK]
2013-11-13 22:14:39.044329 [DEBUG] switch_core_state_machine.c:470
(sofia/internal/88086822@192.168.1.77) State ROUTING going to sleep
2013-11-13 22:14:39.044329 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/88086822@192.168.1.77) Running State Change CS_EXECUTE
2013-11-13 22:14:39.044329 [DEBUG] switch_core_state_machine.c:477
(sofia/internal/88086822@192.168.1.77) State EXECUTE
2013-11-13 22:14:39.044329 [DEBUG] mod_sofia.c:243
sofia/internal/88086822@192.168.1.77 SOFIA EXECUTE
2013-11-13 22:14:39.044329 [DEBUG] switch_core_state_machine.c:209
sofia/internal/88086822@192.168.1.77 Standard EXECUTE
EXECUTE sofia/internal/88086822@192.168.1.77 info()
2013-11-13 22:14:39.044329 [INFO] mod_dptools.c:1614 CHANNEL_DATA:
Channel-State: [CS_EXECUTE]
Channel-Call-State: [RINGING]
Channel-State-Number: [4]
Channel-Name: [sofia/internal/88086822@192.168.1.77]
Unique-ID: [f1e3a2ee-6d4c-e311-a706-0013722e92ac]
Call-Direction: [inbound]
Presence-Call-Direction: [inbound]
Channel-HIT-Dialplan: [true]
Channel-Presence-ID: [88086822@192.168.1.77]
Channel-Call-UUID: [f1e3a2ee-6d4c-e311-a706-0013722e92ac]
Answer-State: [ringing]
Caller-Direction: [inbound]
Caller-Username: [88086822]
Caller-Dialplan: [XML]
Caller-Caller-ID-Name: [PSTN Line]
Caller-Caller-ID-Number: [88086822]
Caller-Orig-Caller-ID-Name: [PSTN Line]
Caller-Orig-Caller-ID-Number: [88086822]
Caller-Network-Addr: [192.168.1.51]
Caller-ANI: [88086822]
Caller-Destination-Number: [1013]
Caller-Unique-ID: [f1e3a2ee-6d4c-e311-a706-0013722e92ac]
Caller-Source: [mod_sofia]
Caller-Context: [default]
Caller-Channel-Name: [sofia/internal/88086822@192.168.1.77]
Caller-Profile-Index: [1]
Caller-Profile-Created-Time: [1384352079044329]
Caller-Channel-Created-Time: [1384352079044329]
Caller-Channel-Answered-Time: [0]
Caller-Channel-Progress-Time: [0]
Caller-Channel-Progress-Media-Time: [0]
Caller-Channel-Hangup-Time: [0]
Caller-Channel-Transfer-Time: [0]
Caller-Channel-Resurrect-Time: [0]
Caller-Channel-Bridged-Time: [0]
Caller-Channel-Last-Hold: [0]
Caller-Channel-Hold-Accum: [0]
Caller-Screen-Bit: [true]
Caller-Privacy-Hide-Name: [false]
Caller-Privacy-Hide-Number: [false]
variable_direction: [inbound]
variable_uuid: [f1e3a2ee-6d4c-e311-a706-0013722e92ac]
variable_session_id: [1]
variable_sip_from_user: [88086822]
variable_sip_from_uri: [88086822@192.168.1.77]
variable_sip_from_host: [192.168.1.77]
variable_channel_name: [sofia/internal/88086822@192.168.1.77]
variable_sip_call_id: [564e359b-4112c85a@192.168.1.51]
variable_sip_local_network_addr: [192.168.1.77]
variable_sip_network_ip: [192.168.1.51]
variable_sip_network_port: [5061]
variable_sip_received_ip: [192.168.1.51]
variable_sip_received_port: [5061]
variable_sip_via_protocol: [udp]
variable_sip_authorized: [true]
variable_Event-Name: [REQUEST_PARAMS]
variable_Core-UUID: [92c6cad9-6d4c-e311-a706-0013722e92ac]
variable_FreeSWITCH-Hostname: [dev.malmam.com]
variable_FreeSWITCH-Switchname: [dev.malmam.com]
variable_FreeSWITCH-IPv4: [122.224.126.17]
variable_FreeSWITCH-IPv6: [::1]
variable_Event-Date-Local: [2013-11-13 22:14:39]
variable_Event-Date-GMT: [Wed, 13 Nov 2013 14:14:39 GMT]
variable_Event-Date-Timestamp: [1384352079044329]
variable_Event-Calling-File: [sofia.c]
variable_Event-Calling-Function: [sofia_handle_sip_i_invite]
variable_Event-Calling-Line-Number: [7996]
variable_Event-Sequence: [514]
variable_sip_number_alias: [1012]
variable_sip_auth_username: [1012]
variable_sip_auth_realm: [192.168.1.77]
variable_number_alias: [1012]
variable_requested_domain_name: [192.168.1.77]
variable_record_stereo: [true]
variable_default_gateway: [example.com]
variable_default_areacode: [571]
variable_transfer_fallback_extension: [operator]
variable_toll_allow: [domestic,international,local]
variable_accountcode: [1012]
variable_user_context: [default]
variable_outbound_caller_id_name: [FreeSWITCH]
variable_outbound_caller_id_number: [0000000000]
variable_callgroup: [techsupport]
variable_user_name: [1012]
variable_domain_name: [192.168.1.77]
variable_sip_from_user_stripped: [88086822]
variable_sip_from_tag: [cecdbca733cc0cbeo1]
variable_sofia_profile_name: [internal]
variable_recovery_profile_name: [internal]
variable_sip_Remote-Party-ID: [PSTN Line
<sip:88086822@192.168.1.77>;screen=yes;party=calling]
variable_sip_cid_type: [rpid]
variable_sip_full_via: [SIP/2.0/UDP 192.168.1.51:5061;branch=z9hG4bK-70206f7a]
variable_sip_from_display: [PSTN Line]
variable_sip_full_from: [PSTN Line
<sip:88086822@192.168.1.77>;tag=cecdbca733cc0cbeo1]
variable_sip_full_to: [<sip:1013@192.168.1.77>]
variable_sip_req_user: [1013]
variable_sip_req_uri: [1013@192.168.1.77]
variable_sip_req_host: [192.168.1.77]
variable_sip_to_user: [1013]
variable_sip_to_uri: [1013@192.168.1.77]
variable_sip_to_host: [192.168.1.77]
variable_sip_contact_user: [88086822]
variable_sip_contact_port: [5061]
variable_sip_contact_uri: [88086822@192.168.1.51:5061]
variable_sip_contact_host: [192.168.1.51]
variable_rtp_use_codec_string: [G722,PCMU,PCMA,GSM]
variable_sip_user_agent: [Linksys/SPA3000-3.1.10(GWd)]
variable_sip_via_host: [192.168.1.51]
variable_sip_via_port: [5061]
variable_max_forwards: [70]
variable_presence_id: [88086822@192.168.1.77]
variable_switch_r_sdp: [v=0
o=- 2705082 2705082 IN IP4 192.168.1.51
s=-
c=IN IP4 192.168.1.51
t=0 0
m=audio 16460 RTP/AVP 0 2 4 8 18 96 97 98 100 101
a=rtpmap:0 PCMU/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:4 G723/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729a/8000
a=rtpmap:96 G726-40/8000
a=rtpmap:97 G726-24/8000
a=rtpmap:98 G726-16/8000
a=rtpmap:100 NSE/8000
a=fmtp:100 192-193
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
]
variable_ep_codec_string: [PCMU@8000h@20i@64000b,PCMA@8000h@20i@64000b]
variable_endpoint_disposition: [DELAYED NEGOTIATION]
variable_DP_MATCH: [ARRAY::DELAYED NEGOTIATION|:DELAYED NEGOTIATION]
variable_call_uuid: [f1e3a2ee-6d4c-e311-a706-0013722e92ac]
variable_current_application: [info]

EXECUTE sofia/internal/88086822@192.168.1.77
hash(insert/192.168.1.77-spymap/88086822/f1e3a2ee-6d4c-e311-a706-0013722e92ac)
EXECUTE sofia/internal/88086822@192.168.1.77
hash(insert/192.168.1.77-last_dial/88086822/1013)
EXECUTE sofia/internal/88086822@192.168.1.77
hash(insert/192.168.1.77-last_dial/global/f1e3a2ee-6d4c-e311-a706-0013722e92ac)
EXECUTE sofia/internal/88086822@192.168.1.77 export(RFC2822_DATE=Wed,
13 Nov 2013 22:14:39 +0800)
2013-11-13 22:14:39.044329 [DEBUG] switch_channel.c:1244 EXPORT
(export_vars) [RFC2822_DATE]=[Wed, 13 Nov 2013 22:14:39 +0800]
EXECUTE sofia/internal/88086822@192.168.1.77 answer()
2013-11-13 22:14:39.044329 [DEBUG] sofia_glue.c:5262 Audio Codec
Compare [PCMU:0:8000:20:64000]/[G722:9:8000:20:64000]
2013-11-13 22:14:39.044329 [DEBUG] sofia_glue.c:5262 Audio Codec
Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2013-11-13 22:14:39.044329 [DEBUG] sofia_glue.c:3186 Set Codec
sofia/internal/88086822@192.168.1.77 PCMU/8000 20 ms 160 samples 64000
bits
2013-11-13 22:14:39.044329 [DEBUG] switch_core_codec.c:111
sofia/internal/88086822@192.168.1.77 Original read codec set to PCMU:0
2013-11-13 22:14:39.044329 [DEBUG] sofia_glue.c:5430 Set 2833 dtmf
send/recv payload to 101
2013-11-13 22:14:39.044329 [DEBUG] sofia_glue.c:3445 AUDIO RTP
[sofia/internal/88086822@192.168.1.77] 192.168.1.77 port 30426 ->
192.168.1.51 port 16460 codec: 0 ms: 20
2013-11-13 22:14:39.044329 [DEBUG] switch_rtp.c:1975 Starting timer
[soft] 160 bytes per 20ms
2013-11-13 22:14:39.083147 [DEBUG] sofia_glue.c:3712 Set 2833 dtmf
send payload to 101
2013-11-13 22:14:39.083147 [DEBUG] sofia_glue.c:3718 Set 2833 dtmf
receive payload to 101
2013-11-13 22:14:39.083147 [DEBUG] sofia_glue.c:3745
sofia/internal/88086822@192.168.1.77 Set rtp dtmf delay to 40
2013-11-13 22:14:39.083147 [NOTICE] sofia_glue.c:4356 Pre-Answer
sofia/internal/88086822@192.168.1.77!
2013-11-13 22:14:39.083147 [DEBUG] switch_channel.c:3364
(sofia/internal/88086822@192.168.1.77) Callstate Change RINGING ->
EARLY
2013-11-13 22:14:39.083147 [DEBUG] mod_sofia.c:866 Local SDP
sofia/internal/88086822@192.168.1.77:
v=0
o=FreeSWITCH 1384321653 1384321654 IN IP4 192.168.1.77
s=FreeSWITCH
c=IN IP4 192.168.1.77
t=0 0
m=audio 30426 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2013-11-13 22:14:39.083147 [DEBUG] switch_core_session.c:861 Send
signal sofia/internal/88086822@192.168.1.77 [BREAK]
2013-11-13 22:14:39.083147 [NOTICE] mod_dptools.c:1225 Channel
[sofia/internal/88086822@192.168.1.77] has been answered
2013-11-13 22:14:39.083147 [DEBUG] switch_channel.c:3643
(sofia/internal/88086822@192.168.1.77) Callstate Change EARLY ->
ACTIVE
EXECUTE sofia/internal/88086822@192.168.1.77 playback(silence_stream://2000)
2013-11-13 22:14:39.083147 [DEBUG] switch_ivr_play_say.c:1319 Codec
Activated L16@8000hz 1 channels 20ms
2013-11-13 22:14:39.098907 [DEBUG] switch_core_session.c:1006 Send
signal sofia/internal/88086822@192.168.1.77 [BREAK]
2013-11-13 22:14:39.108189 [DEBUG] sofia.c:5752 Channel
sofia/internal/88086822@192.168.1.77 entering state [completed][200]
2013-11-13 22:14:39.108189 [DEBUG] switch_core_session.c:1006 Send
signal sofia/internal/88086822@192.168.1.77 [BREAK]
2013-11-13 22:14:39.108189 [DEBUG] switch_core_session.c:1006 Send
signal sofia/internal/88086822@192.168.1.77 [BREAK]
2013-11-13 22:14:39.108189 [DEBUG] switch_core_session.c:1006 Send
signal sofia/internal/88086822@192.168.1.77 [BREAK]
2013-11-13 22:14:39.124358 [DEBUG] switch_rtp.c:3690 Correct ip/port confirmed.
2013-11-13 22:14:39.124358 [DEBUG] sofia.c:5752 Channel
sofia/internal/88086822@192.168.1.77 entering state [ready][200]
2013-11-13 22:14:41.045351 [DEBUG] switch_ivr_play_say.c:1722 done
playing file silence_stream://2000
EXECUTE sofia/internal/88086822@192.168.1.77
rxfax(/tmp/FAX-f1e3a2ee-6d4c-e311-a706-0013722e92ac.tif)
2013-11-13 22:14:41.045351 [DEBUG] mod_spandsp_fax.c:1384 Raw read
codec activation Success L16 20000
2013-11-13 22:14:41.045351 [DEBUG] switch_core_codec.c:219
sofia/internal/88086822@192.168.1.77 Push codec L16:70
2013-11-13 22:14:41.045351 [DEBUG] mod_spandsp_fax.c:1400 Raw write
codec activation Success L16
2013-11-13 22:14:41.665364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier up (-2) in state ANSWERING
2013-11-13 22:14:41.685369 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier down (-1) in state ANSWERING
2013-11-13 22:14:44.125328 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Send complete in phase A_CED, state ANSWERING
2013-11-13 22:14:44.125328 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Starting answer mode
2013-11-13 22:14:44.125328 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from phase A_CED to B_TX
2013-11-13 22:14:44.125328 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 0
2013-11-13 22:14:44.125328 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set tx type 4
2013-11-13 22:14:44.125328 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Start T2
2013-11-13 22:14:44.125328 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from state ANSWERING to R
2013-11-13 22:14:44.125328 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Sending ident 'SpanDSP Fax Ident'
2013-11-13 22:14:44.125328 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Tx:
 CSI without final frame tag
2013-11-13 22:14:44.125328 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Tx:
 ff 03 40 74 6e 65 64 49 20 78 61 46 20 50 53 44 6e 61 70 53 20 20 20
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Send complete in phase B_TX, state R
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 DIS:
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...0= Store and forward Internet fax (T.37): Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .0..= Real-time Internet fax (T.38): Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 0...= 3G mobile network: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
..0. ....= V.8 capabilities: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.0.. ....= Preferred octets: 256 octets
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...0= Ready to transmit a fax document (polling): Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..1.= Can receive fax: Set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
..10 11..= Supported data signalling rates: V.27 ter, V.29, and V.17
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= 2-D coding: Set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..10= Recording width: 215mm +- 1%, 255mm +- 1% and 303mm +- 1%
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 10..= Recording length: Unlimited
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.111 ....= Receiver's minimum scan line time: 0ms at 3.85 l/mm; T7.7 =
T3.85
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= Extension indicator: Set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..0.= Compressed/uncompressed mode: Compressed
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .1..= Error correction mode (ECM): ECM
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.1.. ....= T.6 coding: Set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= Extension indicator: Set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...0= "Field not valid" supported: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..0.= Multiple selective polling: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .0..= Polled sub-address: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 0...= T.43 coding: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
...0 ....= Plane interleave: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.0.. ....= Reserved for the use of extended voice coding set: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= Extension indicator: Set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...1= R8x15.4lines/mm: Set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..0.= 300x300pels/25.4mm: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .1..= R16x15.4lines/mm and/or 400x400pels/25.4mm: Set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 0...= Inch-based resolution preferred: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
...1 ....= Metric-based resolution preferred: Set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
..0. ....= Minimum scan line time for higher resolutions: T15.4 = T7.7
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.0.. ....= Selective polling: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= Extension indicator: Set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...0= Sub-addressing: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..0.= Password: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .0..= Ready to transmit a data file (polling): Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
...0 ....= Binary file transfer (BFT): Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
..0. ....= Document transfer mode (DTM): Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.0.. ....= Electronic data interchange (EDI): Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= Extension indicator: Set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...0= Basic transfer mode (BTM): Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .0..= Ready to transfer a character or mixed mode document
(polling): Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 0...= Character mode: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
..0. ....= Mixed mode (Annex E/T.4): Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= Extension indicator: Set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...0= Processable mode 26 (Rec. T.505): Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..0.= Digital network capability: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .0..= Duplex capability: Half only
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 0...= JPEG coding: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
...0 ....= Full colour mode: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.0.. ....= 12bits/pel component: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= Extension indicator: Set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...0= No subsampling (1:1:1): Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..0.= Custom illuminant: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .0..= Custom gamut range: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 1...= North American Letter (215.9mm x 279.4mm): Set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
...1 ....= North American Legal (215.9mm x 355.6mm): Set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
..1. ....= Single-progression sequential coding (Rec. T.85) basic: Set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.1.. ....= Single-progression sequential coding (Rec. T.85) optional
L0: Set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
0... ....= Extension indicator: Not set
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Tx:
 DIS with final frame tag
2013-11-13 22:14:45.705105 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Tx:
 ff 13 80 00 ee fa c4 80 95 80 80 80 78
2013-11-13 22:14:46.165469 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Send complete in phase B_TX, state R
2013-11-13 22:14:46.245321 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Send complete in phase B_TX, state R
2013-11-13 22:14:46.245321 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from phase B_TX to B_RX
2013-11-13 22:14:46.245321 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 4
2013-11-13 22:14:46.245321 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set tx type 0
2013-11-13 22:14:46.245321 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Start T4
2013-11-13 22:14:48.286209 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier up (-2) in state R
2013-11-13 22:14:48.784340 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier down (-1) in state R
2013-11-13 22:14:49.706142 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 T4
expired in phase B_RX, state R
2013-11-13 22:14:49.706142 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Retry number 1
2013-11-13 22:14:49.706142 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from phase B_RX to B_TX
2013-11-13 22:14:49.706142 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 0
2013-11-13 22:14:49.706142 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set tx type 4
2013-11-13 22:14:49.706142 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Sending ident 'SpanDSP Fax Ident'
2013-11-13 22:14:49.706142 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Tx:
 CSI without final frame tag
2013-11-13 22:14:49.706142 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Tx:
 ff 03 40 74 6e 65 64 49 20 78 61 46 20 50 53 44 6e 61 70 53 20 20 20
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Send complete in phase B_TX, state R
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 DIS:
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...0= Store and forward Internet fax (T.37): Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .0..= Real-time Internet fax (T.38): Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 0...= 3G mobile network: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
..0. ....= V.8 capabilities: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.0.. ....= Preferred octets: 256 octets
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...0= Ready to transmit a fax document (polling): Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..1.= Can receive fax: Set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
..10 11..= Supported data signalling rates: V.27 ter, V.29, and V.17
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= 2-D coding: Set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..10= Recording width: 215mm +- 1%, 255mm +- 1% and 303mm +- 1%
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 10..= Recording length: Unlimited
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.111 ....= Receiver's minimum scan line time: 0ms at 3.85 l/mm; T7.7 =
T3.85
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= Extension indicator: Set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..0.= Compressed/uncompressed mode: Compressed
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .1..= Error correction mode (ECM): ECM
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.1.. ....= T.6 coding: Set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= Extension indicator: Set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...0= "Field not valid" supported: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..0.= Multiple selective polling: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .0..= Polled sub-address: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 0...= T.43 coding: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
...0 ....= Plane interleave: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.0.. ....= Reserved for the use of extended voice coding set: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= Extension indicator: Set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...1= R8x15.4lines/mm: Set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..0.= 300x300pels/25.4mm: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .1..= R16x15.4lines/mm and/or 400x400pels/25.4mm: Set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 0...= Inch-based resolution preferred: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
...1 ....= Metric-based resolution preferred: Set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
..0. ....= Minimum scan line time for higher resolutions: T15.4 = T7.7
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.0.. ....= Selective polling: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= Extension indicator: Set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...0= Sub-addressing: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..0.= Password: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .0..= Ready to transmit a data file (polling): Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
...0 ....= Binary file transfer (BFT): Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
..0. ....= Document transfer mode (DTM): Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.0.. ....= Electronic data interchange (EDI): Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= Extension indicator: Set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...0= Basic transfer mode (BTM): Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .0..= Ready to transfer a character or mixed mode document
(polling): Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 0...= Character mode: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
..0. ....= Mixed mode (Annex E/T.4): Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= Extension indicator: Set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...0= Processable mode 26 (Rec. T.505): Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..0.= Digital network capability: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .0..= Duplex capability: Half only
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 0...= JPEG coding: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
...0 ....= Full colour mode: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.0.. ....= 12bits/pel component: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= Extension indicator: Set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...0= No subsampling (1:1:1): Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..0.= Custom illuminant: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .0..= Custom gamut range: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 1...= North American Letter (215.9mm x 279.4mm): Set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
...1 ....= North American Legal (215.9mm x 355.6mm): Set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
..1. ....= Single-progression sequential coding (Rec. T.85) basic: Set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.1.. ....= Single-progression sequential coding (Rec. T.85) optional
L0: Set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
0... ....= Extension indicator: Not set
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Tx:
 DIS with final frame tag
2013-11-13 22:14:51.285339 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Tx:
 ff 13 80 00 ee fa c4 80 95 80 80 80 78
2013-11-13 22:14:51.765195 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Send complete in phase B_TX, state R
2013-11-13 22:14:51.846194 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Send complete in phase B_TX, state R
2013-11-13 22:14:51.846194 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from phase B_TX to B_RX
2013-11-13 22:14:51.846194 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 4
2013-11-13 22:14:51.846194 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set tx type 0
2013-11-13 22:14:51.846194 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Start T4
2013-11-13 22:14:52.365403 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier up (-2) in state R
2013-11-13 22:14:52.564559 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Framing OK (-6) in state R
2013-11-13 22:14:52.564559 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Start T4A
2013-11-13 22:14:54.105157 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Stop T4A (11680 remaining)
2013-11-13 22:14:54.105157 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx:
 TSI without final frame tag
2013-11-13 22:14:54.105157 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx:
 ff 03 43 37 30 36 39 36 39 37 38 20 31 37 35 30 20 20 20 20 20 20 20
2013-11-13 22:14:54.105157 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Remote gave TSI as: "0571 87969607"
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Stop none (0 remaining)
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx:
 DCS with final frame tag
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx:
 ff 13 83 00 0a f8 44
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx
final frame in state R
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 DCS:
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...0= Store and forward Internet fax (T.37): Not set
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .0..= Real-time Internet fax (T.38): Not set
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 0...= 3G mobile network: Not set
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..1.= Receive fax: Set
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
..00 10..= Selected data signalling rate: V.27ter 4800bps
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.0.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Not set
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
0... ....= 2-D coding: Not set
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..00= Recording width: 215mm +- 1%
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 10..= Recording length: Unlimited
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.111 ....= Minimum scan line time: 0ms
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= Extension indicator: Set
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..0.= Compressed/uncompressed mode: Compressed
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .1..= Error correction mode (ECM): ECM
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 0...= Frame size: 256 octets
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.1.. ....= T.6 coding: Set
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
0... ....= Extension indicator: Not set
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Far
end selected compression T.6 (3)
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:328 ===
Negotiation Result
=======================================================
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:329 Remote
station id: 0571 87969607
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:330 Local station
id:  SpanDSP Fax Ident
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:331 Transfer Rate:     4800
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:333 ECM status         on
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:334 remote country:
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:335 remote vendor:
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:336 remote model:
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:338
==============================================================================
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Get
document at 4800bps, modem 5
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from state R to F_TCF
2013-11-13 22:14:54.425437 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Start T2
2013-11-13 22:14:54.545333 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier down (-1) in state F_TCF
2013-11-13 22:14:54.545333 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from phase B_RX to C_NON_ECM_RX
2013-11-13 22:14:54.545333 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 0
2013-11-13 22:14:54.545333 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 5
2013-11-13 22:14:54.545333 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set tx type 0
2013-11-13 22:14:54.626227 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Carrier up (-2) in state F_TCF
2013-11-13 22:14:54.626227 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier up (-2) in state F_TCF
2013-11-13 22:14:54.665336 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Training failed (-5) in state F_TCF
2013-11-13 22:14:54.825341 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Carrier down (-1) in state F_TCF
2013-11-13 22:14:54.825341 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Carrier up (-2) in state F_TCF
2013-11-13 22:14:54.825341 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier down (-1) in state F_TCF
2013-11-13 22:14:54.825341 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier up (-2) in state F_TCF
2013-11-13 22:14:54.866167 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Training in progress (-3) in state F_TCF
2013-11-13 22:14:55.545324 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Training succeeded (-4) in state F_TCF
2013-11-13 22:14:55.545324 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Stop T2 (47040 remaining)
2013-11-13 22:14:57.085045 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Carrier down (-1) in state F_TCF
2013-11-13 22:14:57.085045 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Trainability (TCF) test result - 7344 total bits. longest run of zeros
was 69
2013-11-13 22:14:57.085045 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Trainability (TCF) test failed - longest run of zeros was 69
2013-11-13 22:14:57.085045 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from phase C_NON_ECM_RX to B_TX
2013-11-13 22:14:57.085045 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 0
2013-11-13 22:14:57.085045 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set tx type 4
2013-11-13 22:14:57.085045 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from state F_TCF to F_FTT
2013-11-13 22:14:57.085045 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Tx:
 FTT with final frame tag
2013-11-13 22:14:57.085045 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Tx:  ff 13 44
2013-11-13 22:14:58.145338 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Send complete in phase B_TX, state F_FTT
2013-11-13 22:14:58.225403 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Send complete in phase B_TX, state F_FTT
2013-11-13 22:14:58.225403 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from phase B_TX to B_RX
2013-11-13 22:14:58.225403 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 4
2013-11-13 22:14:58.225403 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set tx type 0
2013-11-13 22:14:58.225403 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Start T2
2013-11-13 22:14:58.705090 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier up (-2) in state F_FTT
2013-11-13 22:14:58.925325 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Framing OK (-6) in state F_FTT
2013-11-13 22:14:58.925325 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Start T2A
2013-11-13 22:15:00.466050 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Stop T2A (11680 remaining)
2013-11-13 22:15:00.466050 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx:
 TSI without final frame tag
2013-11-13 22:15:00.466050 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx:
 ff 03 43 37 30 36 39 36 39 37 38 20 31 37 35 30 20 20 20 20 20 20 20
2013-11-13 22:15:00.466050 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Remote gave TSI as: "0571 87969607"
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Stop none (0 remaining)
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx:
 DCS with final frame tag
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx:
 ff 13 83 00 0a f8 44
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx
final frame in state F_FTT
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 DCS:
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...0= Store and forward Internet fax (T.37): Not set
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .0..= Real-time Internet fax (T.38): Not set
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 0...= 3G mobile network: Not set
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..1.= Receive fax: Set
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
..00 10..= Selected data signalling rate: V.27ter 4800bps
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.0.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Not set
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
0... ....= 2-D coding: Not set
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..00= Recording width: 215mm +- 1%
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 10..= Recording length: Unlimited
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.111 ....= Minimum scan line time: 0ms
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= Extension indicator: Set
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..0.= Compressed/uncompressed mode: Compressed
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .1..= Error correction mode (ECM): ECM
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 0...= Frame size: 256 octets
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.1.. ....= T.6 coding: Set
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
0... ....= Extension indicator: Not set
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Far
end selected compression T.6 (3)
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:328 ===
Negotiation Result
=======================================================
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:329 Remote
station id: 0571 87969607
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:330 Local station
id:  SpanDSP Fax Ident
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:331 Transfer Rate:     4800
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:333 ECM status         on
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:334 remote country:
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:335 remote vendor:
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:336 remote model:
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:338
==============================================================================
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Get
document at 4800bps, modem 5
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from state F_FTT to F_TCF
2013-11-13 22:15:00.785364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Start T2
2013-11-13 22:15:00.905300 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier down (-1) in state F_TCF
2013-11-13 22:15:00.905300 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from phase B_RX to C_NON_ECM_RX
2013-11-13 22:15:00.905300 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 0
2013-11-13 22:15:00.905300 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 5
2013-11-13 22:15:00.905300 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set tx type 0
2013-11-13 22:15:00.985689 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Carrier up (-2) in state F_TCF
2013-11-13 22:15:00.985689 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier up (-2) in state F_TCF
2013-11-13 22:15:01.044353 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Training failed (-5) in state F_TCF
2013-11-13 22:15:01.184353 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Carrier down (-1) in state F_TCF
2013-11-13 22:15:01.184353 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Carrier up (-2) in state F_TCF
2013-11-13 22:15:01.184353 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier down (-1) in state F_TCF
2013-11-13 22:15:01.184353 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier up (-2) in state F_TCF
2013-11-13 22:15:01.225358 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Training in progress (-3) in state F_TCF
2013-11-13 22:15:01.325362 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Abort (-8) in state F_TCF
2013-11-13 22:15:01.585358 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Abort (-8) in state F_TCF
2013-11-13 22:15:01.905403 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Training succeeded (-4) in state F_TCF
2013-11-13 22:15:01.905403 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Stop T2 (47040 remaining)
2013-11-13 22:15:03.445368 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Carrier down (-1) in state F_TCF
2013-11-13 22:15:03.445368 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Trainability (TCF) test result - 7347 total bits. longest run of zeros
was 182
2013-11-13 22:15:03.445368 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Trainability (TCF) test failed - longest run of zeros was 182
2013-11-13 22:15:03.445368 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from phase C_NON_ECM_RX to B_TX
2013-11-13 22:15:03.445368 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 0
2013-11-13 22:15:03.445368 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set tx type 4
2013-11-13 22:15:03.445368 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from state F_TCF to F_FTT
2013-11-13 22:15:03.445368 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Tx:
 FTT with final frame tag
2013-11-13 22:15:03.445368 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Tx:  ff 13 44
2013-11-13 22:15:04.525355 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Send complete in phase B_TX, state F_FTT
2013-11-13 22:15:04.605099 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Send complete in phase B_TX, state F_FTT
2013-11-13 22:15:04.605099 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from phase B_TX to B_RX
2013-11-13 22:15:04.605099 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 4
2013-11-13 22:15:04.605099 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set tx type 0
2013-11-13 22:15:04.605099 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Start T2
2013-11-13 22:15:05.086046 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier up (-2) in state F_FTT
2013-11-13 22:15:05.305386 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Framing OK (-6) in state F_FTT
2013-11-13 22:15:05.305386 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Start T2A
2013-11-13 22:15:06.824340 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Stop T2A (11840 remaining)
2013-11-13 22:15:06.824340 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx:
 TSI without final frame tag
2013-11-13 22:15:06.824340 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx:
 ff 03 43 37 30 36 39 36 39 37 38 20 31 37 35 30 20 20 20 20 20 20 20
2013-11-13 22:15:06.824340 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Remote gave TSI as: "0571 87969607"
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Stop none (0 remaining)
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx:
 DCS with final frame tag
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx:
 ff 13 83 00 02 f8 44
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx
final frame in state F_FTT
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 DCS:
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...0= Store and forward Internet fax (T.37): Not set
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .0..= Real-time Internet fax (T.38): Not set
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 0...= 3G mobile network: Not set
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..1.= Receive fax: Set
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
..00 00..= Selected data signalling rate: V.27ter 2400bps
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.0.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Not set
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
0... ....= 2-D coding: Not set
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..00= Recording width: 215mm +- 1%
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 10..= Recording length: Unlimited
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.111 ....= Minimum scan line time: 0ms
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= Extension indicator: Set
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..0.= Compressed/uncompressed mode: Compressed
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .1..= Error correction mode (ECM): ECM
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 0...= Frame size: 256 octets
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.1.. ....= T.6 coding: Set
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
0... ....= Extension indicator: Not set
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Far
end selected compression T.6 (3)
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:328 ===
Negotiation Result
=======================================================
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:329 Remote
station id: 0571 87969607
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:330 Local station
id:  SpanDSP Fax Ident
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:331 Transfer Rate:     2400
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:333 ECM status         on
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:334 remote country:
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:335 remote vendor:
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:336 remote model:
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:338
==============================================================================
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Get
document at 2400bps, modem 5
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from state F_FTT to F_TCF
2013-11-13 22:15:07.165441 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Start T2
2013-11-13 22:15:07.285365 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier down (-1) in state F_TCF
2013-11-13 22:15:07.285365 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from phase B_RX to C_NON_ECM_RX
2013-11-13 22:15:07.285365 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 0
2013-11-13 22:15:07.285365 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 5
2013-11-13 22:15:07.285365 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set tx type 0
2013-11-13 22:15:07.365364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Carrier up (-2) in state F_TCF
2013-11-13 22:15:07.365364 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier up (-2) in state F_TCF
2013-11-13 22:15:07.425331 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Training failed (-5) in state F_TCF
2013-11-13 22:15:07.545285 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier down (-1) in state F_TCF
2013-11-13 22:15:07.565325 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Carrier down (-1) in state F_TCF
2013-11-13 22:15:07.565325 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Carrier up (-2) in state F_TCF
2013-11-13 22:15:07.565325 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier up (-2) in state F_TCF
2013-11-13 22:15:07.605350 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Training in progress (-3) in state F_TCF
2013-11-13 22:15:07.605350 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Abort (-8) in state F_TCF
2013-11-13 22:15:08.525351 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Training succeeded (-4) in state F_TCF
2013-11-13 22:15:08.525351 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Stop T2 (45120 remaining)
2013-11-13 22:15:10.065345 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Carrier down (-1) in state F_TCF
2013-11-13 22:15:10.065345 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Trainability (TCF) test result - 3702 total bits. longest run of zeros
was 231
2013-11-13 22:15:10.065345 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Trainability (TCF) test failed - longest run of zeros was 231
2013-11-13 22:15:10.065345 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from phase C_NON_ECM_RX to B_TX
2013-11-13 22:15:10.065345 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 0
2013-11-13 22:15:10.065345 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set tx type 4
2013-11-13 22:15:10.065345 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from state F_TCF to F_FTT
2013-11-13 22:15:10.065345 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Tx:
 FTT with final frame tag
2013-11-13 22:15:10.065345 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Tx:  ff 13 44
2013-11-13 22:15:11.125357 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Send complete in phase B_TX, state F_FTT
2013-11-13 22:15:11.205354 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Send complete in phase B_TX, state F_FTT
2013-11-13 22:15:11.205354 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from phase B_TX to B_RX
2013-11-13 22:15:11.205354 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 4
2013-11-13 22:15:11.205354 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set tx type 0
2013-11-13 22:15:11.205354 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Start T2
2013-11-13 22:15:11.684348 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier up (-2) in state F_FTT
2013-11-13 22:15:11.905344 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Framing OK (-6) in state F_FTT
2013-11-13 22:15:11.905344 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Start T2A
2013-11-13 22:15:13.425461 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Stop T2A (11840 remaining)
2013-11-13 22:15:13.425461 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx:
 TSI without final frame tag
2013-11-13 22:15:13.425461 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx:
 ff 03 43 37 30 36 39 36 39 37 38 20 31 37 35 30 20 20 20 20 20 20 20
2013-11-13 22:15:13.425461 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Remote gave TSI as: "0571 87969607"
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Stop none (0 remaining)
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx:
 DCS with final frame tag
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx:
 ff 13 83 00 02 f8 44
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx
final frame in state F_FTT
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 DCS:
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ...0= Store and forward Internet fax (T.37): Not set
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .0..= Real-time Internet fax (T.38): Not set
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 0...= 3G mobile network: Not set
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..1.= Receive fax: Set
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
..00 00..= Selected data signalling rate: V.27ter 2400bps
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.0.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Not set
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
0... ....= 2-D coding: Not set
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..00= Recording width: 215mm +- 1%
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 10..= Recording length: Unlimited
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.111 ....= Minimum scan line time: 0ms
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
1... ....= Extension indicator: Set
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... ..0.= Compressed/uncompressed mode: Compressed
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... .1..= Error correction mode (ECM): ECM
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.... 0...= Frame size: 256 octets
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
.1.. ....= T.6 coding: Set
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
0... ....= Extension indicator: Not set
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Far
end selected compression T.6 (3)
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:328 ===
Negotiation Result
=======================================================
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:329 Remote
station id: 0571 87969607
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:330 Local station
id:  SpanDSP Fax Ident
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:331 Transfer Rate:     2400
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:333 ECM status         on
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:334 remote country:
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:335 remote vendor:
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:336 remote model:
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:338
==============================================================================
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Get
document at 2400bps, modem 5
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from state F_FTT to F_TCF
2013-11-13 22:15:13.765204 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Start T2
2013-11-13 22:15:13.885335 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier down (-1) in state F_TCF
2013-11-13 22:15:13.885335 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from phase B_RX to C_NON_ECM_RX
2013-11-13 22:15:13.885335 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 0
2013-11-13 22:15:13.885335 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 5
2013-11-13 22:15:13.885335 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set tx type 0
2013-11-13 22:15:13.965361 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Carrier up (-2) in state F_TCF
2013-11-13 22:15:13.965361 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier up (-2) in state F_TCF
2013-11-13 22:15:14.024358 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Training failed (-5) in state F_TCF
2013-11-13 22:15:14.145360 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier down (-1) in state F_TCF
2013-11-13 22:15:14.165649 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Carrier down (-1) in state F_TCF
2013-11-13 22:15:14.165649 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Carrier up (-2) in state F_TCF
2013-11-13 22:15:14.165649 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier up (-2) in state F_TCF
2013-11-13 22:15:14.205365 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Training in progress (-3) in state F_TCF
2013-11-13 22:15:14.205365 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Abort (-8) in state F_TCF
2013-11-13 22:15:15.125366 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Training succeeded (-4) in state F_TCF
2013-11-13 22:15:15.125366 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Stop T2 (45120 remaining)
2013-11-13 22:15:16.664333 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Non-ECM signal status is Carrier down (-1) in state F_TCF
2013-11-13 22:15:16.664333 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Trainability (TCF) test result - 3698 total bits. longest run of zeros
was 231
2013-11-13 22:15:16.664333 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Trainability (TCF) test failed - longest run of zeros was 231
2013-11-13 22:15:16.664333 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from phase C_NON_ECM_RX to B_TX
2013-11-13 22:15:16.664333 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 0
2013-11-13 22:15:16.664333 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set tx type 4
2013-11-13 22:15:16.664333 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from state F_TCF to F_FTT
2013-11-13 22:15:16.664333 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Tx:
 FTT with final frame tag
2013-11-13 22:15:16.664333 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Tx:  ff 13 44
2013-11-13 22:15:17.725356 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Send complete in phase B_TX, state F_FTT
2013-11-13 22:15:17.805619 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Send complete in phase B_TX, state F_FTT
2013-11-13 22:15:17.805619 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from phase B_TX to B_RX
2013-11-13 22:15:17.805619 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 4
2013-11-13 22:15:17.805619 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set tx type 0
2013-11-13 22:15:17.805619 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Start T2
2013-11-13 22:15:18.385326 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier up (-2) in state F_FTT
2013-11-13 22:15:18.604349 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Framing OK (-6) in state F_FTT
2013-11-13 22:15:18.604349 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Start T2A
2013-11-13 22:15:19.605354 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Stop T2A (16000 remaining)
2013-11-13 22:15:19.605354 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx:
 DCN with final frame tag
2013-11-13 22:15:19.605354 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx:  ff 13 fb
2013-11-13 22:15:19.605354 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Rx
final frame in state F_FTT
2013-11-13 22:15:19.605354 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Unexpected DCN frame in state F_FTT
2013-11-13 22:15:19.605354 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Status changing to 'Unexpected message received'
2013-11-13 22:15:19.605354 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from state F_FTT to C
2013-11-13 22:15:19.605354 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Tx:
 DCN with final frame tag
2013-11-13 22:15:19.605354 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Tx:  ff 13 fa
2013-11-13 22:15:19.725400 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
HDLC signal status is Carrier down (-1) in state C
2013-11-13 22:15:19.725400 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from phase B_RX to D_TX
2013-11-13 22:15:19.725400 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 0
2013-11-13 22:15:19.725400 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set tx type 4
2013-11-13 22:15:20.805346 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Send complete in phase D_TX, state C
2013-11-13 22:15:20.885361 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Send complete in phase D_TX, state C
2013-11-13 22:15:20.885361 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30 Disconnecting
2013-11-13 22:15:20.885361 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from phase D_TX to E
2013-11-13 22:15:20.885361 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 0
2013-11-13 22:15:20.885361 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set tx type 1
2013-11-13 22:15:20.885361 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from state C to B
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Send complete in phase E, state B
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:507
==============================================================================
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:520 Fax
processing not successful - result (13) Unexpected message received.
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:525 Remote
station id: 0571 87969607
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:526 Local station
id:  SpanDSP Fax Ident
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:527 Pages transferred: 0
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:529 Total fax pages:   0
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:530 Image
resolution:  8031x7700
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:531 Transfer Rate:     2400
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:533 ECM status         on
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:534 remote country:
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:535 remote vendor:
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:536 remote model:
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:538
==============================================================================
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from state B to CALL_FINISHED
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:287 FLOW T.30
Changing from phase E to CALL_FINISHED
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set rx type 9
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX FAX
exchange complete
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX Set tx type 9
2013-11-13 22:15:21.885358 [DEBUG] mod_spandsp_fax.c:287 FLOW FAX FAX
exchange complete
2013-11-13 22:15:21.905284 [DEBUG] switch_core_codec.c:244
sofia/internal/88086822@192.168.1.77 Restore previous codec PCMU:0.
EXECUTE sofia/internal/88086822@192.168.1.77 hangup()
2013-11-13 22:15:21.905284 [NOTICE] mod_dptools.c:1199 Hangup
sofia/internal/88086822@192.168.1.77 [CS_EXECUTE] [NORMAL_CLEARING]
2013-11-13 22:15:21.905284 [DEBUG] switch_channel.c:3183 Send signal
sofia/internal/88086822@192.168.1.77 [KILL]
2013-11-13 22:15:21.905284 [DEBUG] switch_core_session.c:1341 Send
signal sofia/internal/88086822@192.168.1.77 [BREAK]
2013-11-13 22:15:21.905284 [DEBUG] switch_core_session.c:2800
sofia/internal/88086822@192.168.1.77 skip receive message
[APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:477
(sofia/internal/88086822@192.168.1.77) State EXECUTE going to sleep
2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/88086822@192.168.1.77) Running State Change CS_HANGUP
2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:678
(sofia/internal/88086822@192.168.1.77) State HANGUP
2013-11-13 22:15:21.905284 [DEBUG] mod_sofia.c:506 Channel
sofia/internal/88086822@192.168.1.77 hanging up, cause:
NORMAL_CLEARING
2013-11-13 22:15:21.905284 [DEBUG] mod_sofia.c:558 Sending BYE to
sofia/internal/88086822@192.168.1.77
2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:48
sofia/internal/88086822@192.168.1.77 Standard HANGUP, cause:
NORMAL_CLEARING
2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:678
(sofia/internal/88086822@192.168.1.77) State HANGUP going to sleep
2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:689
(sofia/internal/88086822@192.168.1.77) Callstate Change ACTIVE ->
HANGUP
2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:446
(sofia/internal/88086822@192.168.1.77) State Change CS_HANGUP ->
CS_REPORTING
2013-11-13 22:15:21.905284 [DEBUG] switch_core_session.c:1341 Send
signal sofia/internal/88086822@192.168.1.77 [BREAK]
2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/88086822@192.168.1.77) Running State Change
CS_REPORTING
2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:761
(sofia/internal/88086822@192.168.1.77) State REPORTING
2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:92
sofia/internal/88086822@192.168.1.77 Standard REPORTING, cause:
NORMAL_CLEARING
2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:761
(sofia/internal/88086822@192.168.1.77) State REPORTING going to sleep
2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:440
(sofia/internal/88086822@192.168.1.77) State Change CS_REPORTING ->
CS_DESTROY
2013-11-13 22:15:21.905284 [DEBUG] switch_core_session.c:1341 Send
signal sofia/internal/88086822@192.168.1.77 [BREAK]
2013-11-13 22:15:21.905284 [DEBUG] switch_core_session.c:1549 Session
1 (sofia/internal/88086822@192.168.1.77) Locked, Waiting on external
entities
2013-11-13 22:15:21.905284 [NOTICE] switch_core_session.c:1567 Session
1 (sofia/internal/88086822@192.168.1.77) Ended
2013-11-13 22:15:21.905284 [NOTICE] switch_core_session.c:1571 Close
Channel sofia/internal/88086822@192.168.1.77 [CS_DESTROY]
2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:565
(sofia/internal/88086822@192.168.1.77) Callstate Change HANGUP -> DOWN
2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:568
(sofia/internal/88086822@192.168.1.77) Running State Change CS_DESTROY
2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:578
(sofia/internal/88086822@192.168.1.77) State DESTROY
2013-11-13 22:15:21.905284 [DEBUG] mod_sofia.c:399
sofia/internal/88086822@192.168.1.77 SOFIA DESTROY
2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:99
sofia/internal/88086822@192.168.1.77 Standard DESTROY
2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:578
(sofia/internal/88086822@192.168.1.77) State DESTROY going to sleep

[Freeswitch-users] Can't receive fax via Linksys SPA3000

Ruan Chunping