Can't receive fax via Linksys SPA3000
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
participants (1)
-
Ruan Chunping