November 2013 - FreeSWITCH-users - FreeSWITCH Mailing Lists

Update callee id in pickup
by Andrew Cassidy 14 Nov '13

14 Nov '13

Hi guys, I've just posted this on Jira (http://jira.freeswitch.org/browse/FS-5967) but I might get more discussion here: I want to update the calling phone's display with the details of the user that picked up the call when using directed pickup via the pickup endpoint and application. What I've done in mod_dptools.c is: - check a new variable pickup_update_aleg - read effective caller id from channel - update effective callee id on pickup channel I've also added 2 log statement that show the variables do have the correct values, and that the test for the variable worked, but the original caller's display is not updated. Thanks, -- *Andrew Cassidy BSc (Hons) MBCS SSCA* Managing Director *T <info(a)cassidywebservices.co.uk> *03300 100 960 *F <info(a)cassidywebservices.co.uk> *03300 100 961 *E <info(a)cassidywebservices.co.uk> *andrew(a)cassidywebservices.co.uk *W <info(a)cassidywebservices.co.uk> *www.cassidywebservices.co.uk

1 0

Re: [Freeswitch-users] How to add PCMA/H263 to outgoing INVITE SDP
by Eugene Prokopiev 14 Nov '13

14 Nov '13

> How to add PCMA/H263 to FreeSWITCH INVITE? verbose_sdp=true helps -- WBR, Eugene Prokopiev

1 0

FS limit
by Juan Antonio Ibañez Santorum 13 Nov '13

13 Nov '13

Hello guys, I am doing some test in my FS box and I found it does not accept more than 300 calls. It is a 12 core E5-1650 Xeon server and I can see in 'top' that FS cpu goes to 140% (over 1200%). Once 300 calls is reached, FS starts responding 480 Temporary Unavailable: http://i.tinyuploads.com/to7Amt.png Do you know where the bottleneck is? I can see low disk activity, low memory consuption... Regards

9 17

lua 5.2
by François 13 Nov '13

13 Nov '13

Thanks Anthony for THE lua update we've been waiting for! Will it be included in 1.4-stable? François.

2 1

cdr fields description
by vad fabi 13 Nov '13

13 Nov '13

Hi all, I am interesting in cdr fields descriptions, such as : RTP_AUDIO_IN(OUT)_PACKET_COUNT RTP_AUDIO_IN(OUT)_MEDIA_PACKET_COUNT RTP_AUDIO_IN(OUT)_SKIP_PACKET_COUNT RTP_AUDIO_IN(OUT)_JB_PACKET_COUNT RTP_AUDIO_IN(OUT)_CNG_PACKET_COUNT Could you please help and explain the meaning of these fields. Thx

1 0

call groups using pointers
by Jason Holden 13 Nov '13

13 Nov '13

Hi. I am currently using the group call feature and have found that when the group is called it only rings the first pointer in the list. Any suggestions to have it ring all pointers at the same time?

2 1

Conference not working
by Joli Martinez 13 Nov '13

13 Nov '13

Hello, I am new to FreeSwitch and I have followed the following instruction to get Freeswitch working with Kamailio. I have three extension registered 101,102,103. If I call them they work, but I would like to put them on a conference. I dial 433101 and it hangs up. I do see the call hitting FS through the cli. I would like to get some type of message saying the conference does not exist or something. But not sure where to set it up. http://kb.asipto.com/freeswitch:kamailio-3.3.x-freeswitch-1.2.x-sbc This is what I get from the cli [code] 2013-11-11 09:44:09.112958 [NOTICE] switch_channel.c:1034 New Channel sofia/internal/103(a)209.151.253.234 [9f7f3fc9-4ad1-40a5-bd34-8712db6d937f] 2013-11-11 09:44:09.112958 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/103(a)209.151.253.234 [BREAK] 2013-11-11 09:44:09.112958 [DEBUG] switch_core_session.c:1003 Send signal sofia/internal/103(a)209.151.253.234 [BREAK] 2013-11-11 09:44:09.112958 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/103(a)209.151.253.234) Running State Change CS_NEW 2013-11-11 09:44:09.112958 [DEBUG] switch_core_state_machine.c:433 (sofia/internal/103(a)209.151.253.234) State NEW 2013-11-11 09:44:09.132913 [DEBUG] sofia.c:5752 Channel sofia/internal/103(a)209.151.253.234 entering state [received][100] 2013-11-11 09:44:09.132913 [DEBUG] sofia.c:5765 Remote SDP: v=0 o=- 3593180648 3593180648 IN IP4 108.73.158.140 s=pjmedia c=IN IP4 108.73.158.140 t=0 0 m=audio 4018 RTP/AVP 99 0 8 101 c=IN IP4 108.73.158.140 a=rtpmap:99 SILK/24000 a=fmtp:99 useinbandfec=0 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=rtcp:4019 IN IP4 108.73.158.140 2013-11-11 09:44:09.132913 [DEBUG] sofia.c:5979 (sofia/internal/103(a)209.151.253.234) State Change CS_NEW -> CS_INIT 2013-11-11 09:44:09.132913 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/103(a)209.151.253.234 [BREAK] 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/103(a)209.151.253.234) Running State Change CS_INIT 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/103(a)209.151.253.234) State INIT 2013-11-11 09:44:09.132913 [DEBUG] mod_sofia.c:87 sofia/internal/103(a)209.151.253.234 SOFIA INIT 2013-11-11 09:44:09.132913 [DEBUG] mod_sofia.c:127 (sofia/internal/103(a)209.151.253.234) State Change CS_INIT -> CS_ROUTING 2013-11-11 09:44:09.132913 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/103(a)209.151.253.234 [BREAK] 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/103(a)209.151.253.234) State INIT going to sleep 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/103(a)209.151.253.234) Running State Change CS_ROUTING 2013-11-11 09:44:09.132913 [DEBUG] switch_channel.c:2115 (sofia/internal/103(a)209.151.253.234) Callstate Change DOWN -> RINGING 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/103(a)209.151.253.234) State ROUTING 2013-11-11 09:44:09.132913 [DEBUG] mod_sofia.c:150 sofia/internal/103(a)209.151.253.234 SOFIA ROUTING 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:117 sofia/internal/103(a)209.151.253.234 Standard ROUTING 2013-11-11 09:44:09.132913 [INFO] mod_dialplan_xml.c:558 Processing 103 <103>->3101 in context public Dialplan: sofia/internal/103(a)209.151.253.234 parsing [public->unloop] continue=false Dialplan: sofia/internal/103(a)209.151.253.234 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/103(a)209.151.253.234 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/103(a)209.151.253.234 parsing [public->outside_call] continue=true Dialplan: sofia/internal/103(a)209.151.253.234 Absolute Condition [outside_call] Dialplan: sofia/internal/103(a)209.151.253.234 Action set(outside_call=true) Dialplan: sofia/internal/103(a)209.151.253.234 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/103(a)209.151.253.234 parsing [public->call_debug] continue=true Dialplan: sofia/internal/103(a)209.151.253.234 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/103(a)209.151.253.234 parsing [public->public_extensions] continue=false Dialplan: sofia/internal/103(a)209.151.253.234 Regex (FAIL) [public_extensions] destination_number(3101) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/103(a)209.151.253.234 parsing [public->vbox] continue=false Dialplan: sofia/internal/103(a)209.151.253.234 Regex (FAIL) [vbox] destination_number(3101) =~ /^vb-(1[0-9][0-9])$/ break=on-false Dialplan: sofia/internal/103(a)209.151.253.234 parsing [public->vmenu] continue=false Dialplan: sofia/internal/103(a)209.151.253.234 Regex (FAIL) [vmenu] destination_number(3101) =~ /^vm-(1[0-9][0-9])$/ break=on-false Dialplan: sofia/internal/103(a)209.151.253.234 parsing [public->public_did] continue=false Dialplan: sofia/internal/103(a)209.151.253.234 Regex (FAIL) [public_did] destination_number(3101) =~ /^(5551212)$/ break=on-false 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:167 (sofia/internal/103(a)209.151.253.234) State Change CS_ROUTING -> CS_EXECUTE 2013-11-11 09:44:09.132913 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/103(a)209.151.253.234 [BREAK] 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/103(a)209.151.253.234) State ROUTING going to sleep 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/103(a)209.151.253.234) Running State Change CS_EXECUTE 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:477 (sofia/internal/103(a)209.151.253.234) State EXECUTE 2013-11-11 09:44:09.132913 [DEBUG] mod_sofia.c:243 sofia/internal/103(a)209.151.253.234 SOFIA EXECUTE 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:209 sofia/internal/103(a)209.151.253.234 Standard EXECUTE EXECUTE sofia/internal/103(a)209.151.253.234 set(outside_call=true) 2013-11-11 09:44:09.132913 [DEBUG] mod_dptools.c:1402 sofia/internal/103(a)209.151.253.234 SET [outside_call]=[true] EXECUTE sofia/internal/103(a)209.151.253.234 export(RFC2822_DATE=Mon, 11 Nov 2013 09:44:09 -0800) 2013-11-11 09:44:09.132913 [DEBUG] switch_channel.c:1226 EXPORT (export_vars) [RFC2822_DATE]=[Mon, 11 Nov 2013 09:44:09 -0800] 2013-11-11 09:44:09.132913 [NOTICE] switch_core_state_machine.c:262 sofia/internal/103(a)209.151.253.234 has executed the last dialplan instruction, hanging up. 2013-11-11 09:44:09.132913 [NOTICE] switch_core_state_machine.c:264 Hangup sofia/internal/103(a)209.151.253.234 [CS_EXECUTE] [NORMAL_CLEARING] 2013-11-11 09:44:09.132913 [DEBUG] switch_channel.c:3134 Send signal sofia/internal/103(a)209.151.253.234 [KILL] 2013-11-11 09:44:09.132913 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/103(a)209.151.253.234 [BREAK] 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:477 (sofia/internal/103(a)209.151.253.234) State EXECUTE going to sleep 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/103(a)209.151.253.234) Running State Change CS_HANGUP 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:678 (sofia/internal/103(a)209.151.253.234) State HANGUP 2013-11-11 09:44:09.132913 [DEBUG] mod_sofia.c:506 Channel sofia/internal/103(a)209.151.253.234 hanging up, cause: NORMAL_CLEARING 2013-11-11 09:44:09.132913 [DEBUG] mod_sofia.c:640 Responding to INVITE with: 480 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:48 sofia/internal/103(a)209.151.253.234 Standard HANGUP, cause: NORMAL_CLEARING 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:678 (sofia/internal/103(a)209.151.253.234) State HANGUP going to sleep 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:689 (sofia/internal/103(a)209.151.253.234) Callstate Change RINGING -> HANGUP 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:446 (sofia/internal/103(a)209.151.253.234) State Change CS_HANGUP -> CS_REPORTING 2013-11-11 09:44:09.132913 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/103(a)209.151.253.234 [BREAK] 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/103(a)209.151.253.234) Running State Change CS_REPORTING 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:761 (sofia/internal/103(a)209.151.253.234) State REPORTING 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:92 sofia/internal/103(a)209.151.253.234 Standard REPORTING, cause: NORMAL_CLEARING 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:761 (sofia/internal/103(a)209.151.253.234) State REPORTING going to sleep 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/103(a)209.151.253.234) State Change CS_REPORTING -> CS_DESTROY 2013-11-11 09:44:09.132913 [DEBUG] switch_core_session.c:1338 Send signal sofia/internal/103(a)209.151.253.234 [BREAK] 2013-11-11 09:44:09.132913 [DEBUG] switch_core_session.c:1546 Session 13 (sofia/internal/103(a)209.151.253.234) Locked, Waiting on external entities 2013-11-11 09:44:09.132913 [NOTICE] switch_core_session.c:1564 Session 13 (sofia/internal/103(a)209.151.253.234) Ended 2013-11-11 09:44:09.132913 [NOTICE] switch_core_session.c:1568 Close Channel sofia/internal/103(a)209.151.253.234 [CS_DESTROY] 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:565 (sofia/internal/103(a)209.151.253.234) Callstate Change HANGUP -> DOWN 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:568 (sofia/internal/103(a)209.151.253.234) Running State Change CS_DESTROY 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/103(a)209.151.253.234) State DESTROY 2013-11-11 09:44:09.132913 [DEBUG] mod_sofia.c:399 sofia/internal/103(a)209.151.253.234 SOFIA DESTROY 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:99 sofia/internal/103(a)209.151.253.234 Standard DESTROY 2013-11-11 09:44:09.132913 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/103(a)209.151.253.234) State DESTROY going to sleep [/code] thanks,

2 1

Best codec for VOIP over VSAT
by Jan Sverre Andreassen 13 Nov '13

13 Nov '13

Guys, We have some vessels with around 512kbs VSAT links. The latency is around 650ms. I heard the people have had success with g.729 on similar systems. Does anyone know if Opus or some other built-in codecs are comparable to g.729, and what parameters I can set in order to gain more control over the bandwidth usage? I have currently standard Opus running, but I'm not in control over how much bandwidth Opus is using. Best Regards, Jan Sverre Andreassen ________________________________ This email and any files contained therein is confidential and may contain privileged information. If you are not the named addressee(s) or you have otherwise received this in error, you should not distribute or copy this e-mail or use any of its content for any purpose. Please notify the sender immediately by e-mail if you have received this e-mail in error and delete it from your system.

1 0

Dialer Switch with LCR Database
by Andre 13 Nov '13

13 Nov '13

I'm building a dialer deck that using a custom LCR. I look up LERG and LNR in my database and I look at 30 + rate decks to find the LCR. I want to know is it realistic to be doing the LCR in a database? I expect 1000 to 2000 CPS so that means I hit the database that many times per second. My query is a stored procedure and takes about 1 to 2 milliseconds to run. I know SQL Server 2014 will have in memory tables and I do plan on using it. What are others thoughts for a high capacity dialer FreeSWITCH switch?

2 1

Can't receive fax via Linksys SPA3000
by Ruan Chunping 13 Nov '13

13 Nov '13

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(a)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(a)192.168.1.77 [BREAK] 2013-11-13 22:14:38.985423 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/88086822(a)192.168.1.77 [BREAK] 2013-11-13 22:14:39.005424 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/88086822(a)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(a)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(a)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(a)192.168.1.77 [BREAK] 2013-11-13 22:14:39.044329 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/88086822(a)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(a)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(a)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(a)192.168.1.77 [BREAK] 2013-11-13 22:14:39.044329 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/88086822(a)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(a)192.168.1.77) State INIT 2013-11-13 22:14:39.044329 [DEBUG] mod_sofia.c:87 sofia/internal/88086822(a)192.168.1.77 SOFIA INIT 2013-11-13 22:14:39.044329 [DEBUG] mod_sofia.c:127 (sofia/internal/88086822(a)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(a)192.168.1.77 [BREAK] 2013-11-13 22:14:39.044329 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/88086822(a)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(a)192.168.1.77) Running State Change CS_ROUTING 2013-11-13 22:14:39.044329 [DEBUG] switch_channel.c:2164 (sofia/internal/88086822(a)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(a)192.168.1.77) State ROUTING 2013-11-13 22:14:39.044329 [DEBUG] mod_sofia.c:150 sofia/internal/88086822(a)192.168.1.77 SOFIA ROUTING 2013-11-13 22:14:39.044329 [DEBUG] switch_core_state_machine.c:117 sofia/internal/88086822(a)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(a)192.168.1.77 parsing [default->unloop] continue=false Dialplan: sofia/internal/88086822(a)192.168.1.77 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/88086822(a)192.168.1.77 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/88086822(a)192.168.1.77 parsing [default->tod_example] continue=true Dialplan: sofia/internal/88086822(a)192.168.1.77 Date/TimeMatch (FAIL) [tod_example] break=on-false Dialplan: sofia/internal/88086822(a)192.168.1.77 parsing [default->holiday_example] continue=true Dialplan: sofia/internal/88086822(a)192.168.1.77 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: sofia/internal/88086822(a)192.168.1.77 parsing [default->global-intercept] continue=false Dialplan: sofia/internal/88086822(a)192.168.1.77 Regex (FAIL) [global-intercept] destination_number(1013) =~ /^886$/ break=on-false Dialplan: sofia/internal/88086822(a)192.168.1.77 parsing [default->group-intercept] continue=false Dialplan: sofia/internal/88086822(a)192.168.1.77 Regex (FAIL) [group-intercept] destination_number(1013) =~ /^\*8$/ break=on-false Dialplan: sofia/internal/88086822(a)192.168.1.77 parsing [default->intercept-ext] continue=false Dialplan: sofia/internal/88086822(a)192.168.1.77 Regex (FAIL) [intercept-ext] destination_number(1013) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/internal/88086822(a)192.168.1.77 parsing [default->redial] continue=false Dialplan: sofia/internal/88086822(a)192.168.1.77 Regex (FAIL) [redial] destination_number(1013) =~ /^(redial|870)$/ break=on-false Dialplan: sofia/internal/88086822(a)192.168.1.77 parsing [default->global] continue=true Dialplan: sofia/internal/88086822(a)192.168.1.77 Regex (PASS) [global] ${call_debug}(true) =~ /^true$/ break=never Dialplan: sofia/internal/88086822(a)192.168.1.77 Action info() Dialplan: sofia/internal/88086822(a)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(a)192.168.1.77 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false Dialplan: sofia/internal/88086822(a)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(a)192.168.1.77 Absolute Condition [global] Dialplan: sofia/internal/88086822(a)192.168.1.77 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) Dialplan: sofia/internal/88086822(a)192.168.1.77 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/internal/88086822(a)192.168.1.77 Action hash(insert/${domain_name}-last_dial/global/${uuid}) Dialplan: sofia/internal/88086822(a)192.168.1.77 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/88086822(a)192.168.1.77 parsing [default->snom-demo-2] continue=false Dialplan: sofia/internal/88086822(a)192.168.1.77 Regex (FAIL) [snom-demo-2] destination_number(1013) =~ /^9001$/ break=on-false Dialplan: sofia/internal/88086822(a)192.168.1.77 parsing [default->snom-demo-1] continue=false Dialplan: sofia/internal/88086822(a)192.168.1.77 Regex (FAIL) [snom-demo-1] destination_number(1013) =~ /^9000$/ break=on-false Dialplan: sofia/internal/88086822(a)192.168.1.77 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/88086822(a)192.168.1.77 Regex (FAIL) [eavesdrop] destination_number(1013) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false Dialplan: sofia/internal/88086822(a)192.168.1.77 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/88086822(a)192.168.1.77 Regex (FAIL) [eavesdrop] destination_number(1013) =~ /^779$/ break=on-false Dialplan: sofia/internal/88086822(a)192.168.1.77 parsing [default->call_return] continue=false Dialplan: sofia/internal/88086822(a)192.168.1.77 Regex (FAIL) [call_return] destination_number(1013) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/internal/88086822(a)192.168.1.77 parsing [default->del-group] continue=false Dialplan: sofia/internal/88086822(a)192.168.1.77 Regex (FAIL) [del-group] destination_number(1013) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/internal/88086822(a)192.168.1.77 parsing [default->add-group] continue=false Dialplan: sofia/internal/88086822(a)192.168.1.77 Regex (FAIL) [add-group] destination_number(1013) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/internal/88086822(a)192.168.1.77 parsing [default->call-group-simo] continue=false Dialplan: sofia/internal/88086822(a)192.168.1.77 Regex (FAIL) [call-group-simo] destination_number(1013) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/internal/88086822(a)192.168.1.77 parsing [default->call-group-order] continue=false Dialplan: sofia/internal/88086822(a)192.168.1.77 Regex (FAIL) [call-group-order] destination_number(1013) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/internal/88086822(a)192.168.1.77 parsing [default->extension-intercom] continue=false Dialplan: sofia/internal/88086822(a)192.168.1.77 Regex (FAIL) [extension-intercom] destination_number(1013) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/88086822(a)192.168.1.77 parsing [default->fax_receive] continue=false Dialplan: sofia/internal/88086822(a)192.168.1.77 Regex (PASS) [fax_receive] destination_number(1013) =~ /^1013$/ break=on-false Dialplan: sofia/internal/88086822(a)192.168.1.77 Action answer() Dialplan: sofia/internal/88086822(a)192.168.1.77 Action playback(silence_stream://2000) Dialplan: sofia/internal/88086822(a)192.168.1.77 Action rxfax(/tmp/FAX-${uuid}.tif) Dialplan: sofia/internal/88086822(a)192.168.1.77 Action hangup() 2013-11-13 22:14:39.044329 [DEBUG] switch_core_state_machine.c:167 (sofia/internal/88086822(a)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(a)192.168.1.77 [BREAK] 2013-11-13 22:14:39.044329 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/88086822(a)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(a)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(a)192.168.1.77) State EXECUTE 2013-11-13 22:14:39.044329 [DEBUG] mod_sofia.c:243 sofia/internal/88086822(a)192.168.1.77 SOFIA EXECUTE 2013-11-13 22:14:39.044329 [DEBUG] switch_core_state_machine.c:209 sofia/internal/88086822(a)192.168.1.77 Standard EXECUTE EXECUTE sofia/internal/88086822(a)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(a)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(a)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(a)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(a)192.168.1.77] variable_sip_from_host: [192.168.1.77] variable_channel_name: [sofia/internal/88086822(a)192.168.1.77] variable_sip_call_id: [564e359b-4112c85a(a)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(a)192.168.1.77] variable_sip_req_host: [192.168.1.77] variable_sip_to_user: [1013] variable_sip_to_uri: [1013(a)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(a)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(a)192.168.1.77 hash(insert/192.168.1.77-spymap/88086822/f1e3a2ee-6d4c-e311-a706-0013722e92ac) EXECUTE sofia/internal/88086822(a)192.168.1.77 hash(insert/192.168.1.77-last_dial/88086822/1013) EXECUTE sofia/internal/88086822(a)192.168.1.77 hash(insert/192.168.1.77-last_dial/global/f1e3a2ee-6d4c-e311-a706-0013722e92ac) EXECUTE sofia/internal/88086822(a)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(a)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(a)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(a)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(a)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(a)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(a)192.168.1.77! 2013-11-13 22:14:39.083147 [DEBUG] switch_channel.c:3364 (sofia/internal/88086822(a)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(a)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(a)192.168.1.77 [BREAK] 2013-11-13 22:14:39.083147 [NOTICE] mod_dptools.c:1225 Channel [sofia/internal/88086822(a)192.168.1.77] has been answered 2013-11-13 22:14:39.083147 [DEBUG] switch_channel.c:3643 (sofia/internal/88086822(a)192.168.1.77) Callstate Change EARLY -> ACTIVE EXECUTE sofia/internal/88086822(a)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(a)192.168.1.77 [BREAK] 2013-11-13 22:14:39.108189 [DEBUG] sofia.c:5752 Channel sofia/internal/88086822(a)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(a)192.168.1.77 [BREAK] 2013-11-13 22:14:39.108189 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/88086822(a)192.168.1.77 [BREAK] 2013-11-13 22:14:39.108189 [DEBUG] switch_core_session.c:1006 Send signal sofia/internal/88086822(a)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(a)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(a)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(a)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(a)192.168.1.77 Restore previous codec PCMU:0. EXECUTE sofia/internal/88086822(a)192.168.1.77 hangup() 2013-11-13 22:15:21.905284 [NOTICE] mod_dptools.c:1199 Hangup sofia/internal/88086822(a)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(a)192.168.1.77 [KILL] 2013-11-13 22:15:21.905284 [DEBUG] switch_core_session.c:1341 Send signal sofia/internal/88086822(a)192.168.1.77 [BREAK] 2013-11-13 22:15:21.905284 [DEBUG] switch_core_session.c:2800 sofia/internal/88086822(a)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(a)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(a)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(a)192.168.1.77) State HANGUP 2013-11-13 22:15:21.905284 [DEBUG] mod_sofia.c:506 Channel sofia/internal/88086822(a)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(a)192.168.1.77 2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:48 sofia/internal/88086822(a)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(a)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(a)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(a)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(a)192.168.1.77 [BREAK] 2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/88086822(a)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(a)192.168.1.77) State REPORTING 2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:92 sofia/internal/88086822(a)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(a)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(a)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(a)192.168.1.77 [BREAK] 2013-11-13 22:15:21.905284 [DEBUG] switch_core_session.c:1549 Session 1 (sofia/internal/88086822(a)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(a)192.168.1.77) Ended 2013-11-13 22:15:21.905284 [NOTICE] switch_core_session.c:1571 Close Channel sofia/internal/88086822(a)192.168.1.77 [CS_DESTROY] 2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:565 (sofia/internal/88086822(a)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(a)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(a)192.168.1.77) State DESTROY 2013-11-13 22:15:21.905284 [DEBUG] mod_sofia.c:399 sofia/internal/88086822(a)192.168.1.77 SOFIA DESTROY 2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:99 sofia/internal/88086822(a)192.168.1.77 Standard DESTROY 2013-11-13 22:15:21.905284 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/88086822(a)192.168.1.77) State DESTROY going to sleep

1 0