[Freeswitch-users] Fax Problem

Wed Jul 28 04:07:23 PDT 2010

Hi, I'm trying send a document to fax machine.
It worked when under the private network.

but when it fax via the PSTN, everytime fax machine answer the call,
FreeSwitch immediately crash without any message or warning, I cant find the
problem.

FreeSwitch : 192.168.1.24
Voip Gateway (Wellgate 2644) : 192.168.1.200
Traditional Fax Machine ( Panasonic KX-F126 )

here is the command:
originate sofia/gateway/voipgw/12345678 &txfax(test.tif)

under private network it worked:
  FREESWITCH-----ip network-----VOIP GATEWAY--fxs----FAX MACHINE

But when it via the PSTN, it will crash:
  FREESWITCH-----ip network-----VOIP GATEWAY--fxo----PSTN----FAX MACHINE
(tel number: 12345678)

the log file:
2010-07-28 18:38:56.734375 [DEBUG] sofia.c:5999 IP 192.168.1.24 Rejected by
acl "domains". Falling back to Digest auth.
2010-07-28 18:38:56.843750 [DEBUG] sofia.c:5999 IP 192.168.1.24 Rejected by
acl "domains". Falling back to Digest auth.
2010-07-28 18:38:56.921875 [NOTICE] switch_channel.c:776 New Channel
sofia/internal/1001 at 192.168.1.24 [bbb8b3fd-73bd-461c-9558-23242c58bce7]
2010-07-28 18:38:56.921875 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/1001 at 192.168.1.24) Running State Change CS_NEW
2010-07-28 18:38:56.921875 [DEBUG] switch_core_state_machine.c:320
(sofia/internal/1001 at 192.168.1.24) State NEW
2010-07-28 18:38:57.031250 [DEBUG] sofia.c:4317 Channel sofia/internal/
1001 at 192.168.1.24 entering state [received][100]
2010-07-28 18:38:57.031250 [DEBUG] sofia.c:4328 Remote SDP:
v=0
o=- 6 2 IN IP4 192.168.1.24
s=CounterPath X-Lite 3.0
c=IN IP4 192.168.1.24
t=0 0
m=audio 23260 RTP/AVP 107 0 8 101
a=rtpmap:107 BV32/16000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=alt:1 2 : vyr71tjd uA0nYpAb 192.168.1.24 23260
a=alt:2 1 : MiwEZ8b+ c79RnVwq 192.168.56.1 23260

2010-07-28 18:38:57.031250 [DEBUG] sofia_glue.c:3845 Audio Codec Compare
[BV32:107:16000:20]/[G7221:115:32000:20]
2010-07-28 18:38:57.031250 [DEBUG] sofia_glue.c:3845 Audio Codec Compare
[BV32:107:16000:20]/[G7221:107:16000:20]
2010-07-28 18:38:57.031250 [DEBUG] sofia_glue.c:3845 Audio Codec Compare
[BV32:107:16000:20]/[G722:9:8000:20]
2010-07-28 18:38:57.031250 [DEBUG] sofia_glue.c:3845 Audio Codec Compare
[BV32:107:16000:20]/[PCMU:0:8000:20]
2010-07-28 18:38:57.031250 [DEBUG] sofia_glue.c:3845 Audio Codec Compare
[BV32:107:16000:20]/[PCMA:8:8000:20]
2010-07-28 18:38:57.031250 [DEBUG] sofia_glue.c:3845 Audio Codec Compare
[BV32:107:16000:20]/[GSM:3:8000:20]
2010-07-28 18:38:57.031250 [DEBUG] sofia_glue.c:3845 Audio Codec Compare
[PCMU:0:8000:20]/[G7221:115:32000:20]
2010-07-28 18:38:57.031250 [DEBUG] sofia_glue.c:3845 Audio Codec Compare
[PCMU:0:8000:20]/[G7221:107:16000:20]
2010-07-28 18:38:57.031250 [DEBUG] sofia_glue.c:3845 Audio Codec Compare
[PCMU:0:8000:20]/[G722:9:8000:20]
2010-07-28 18:38:57.031250 [DEBUG] sofia_glue.c:3845 Audio Codec Compare
[PCMU:0:8000:20]/[PCMU:0:8000:20]
2010-07-28 18:38:57.031250 [DEBUG] sofia_glue.c:2442 Set Codec
sofia/internal/1001 at 192.168.1.24 PCMU/8000 20 ms 160 samples
2010-07-28 18:38:57.031250 [DEBUG] sofia_glue.c:3941 Set 2833 dtmf send/recv
payload to 101
2010-07-28 18:38:57.031250 [DEBUG] sofia.c:4475 (sofia/internal/
1001 at 192.168.1.24) State Change CS_NEW -> CS_INIT
2010-07-28 18:38:57.031250 [DEBUG] switch_core_session.c:1027 Send signal
sofia/internal/1001 at 192.168.1.24 [BREAK]
2010-07-28 18:38:57.031250 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/1001 at 192.168.1.24) Running State Change CS_INIT
2010-07-28 18:38:57.031250 [DEBUG] switch_core_state_machine.c:338
(sofia/internal/1001 at 192.168.1.24) State INIT
2010-07-28 18:38:57.031250 [DEBUG] mod_sofia.c:83 sofia/internal/
1001 at 192.168.1.24 SOFIA INIT
2010-07-28 18:38:57.031250 [DEBUG] mod_sofia.c:119 (sofia/internal/
1001 at 192.168.1.24) State Change CS_INIT -> CS_ROUTING
2010-07-28 18:38:57.031250 [DEBUG] switch_core_session.c:1027 Send signal
sofia/internal/1001 at 192.168.1.24 [BREAK]
2010-07-28 18:38:57.031250 [DEBUG] switch_core_state_machine.c:338
(sofia/internal/1001 at 192.168.1.24) State INIT going to sleep
2010-07-28 18:38:57.031250 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/1001 at 192.168.1.24) Running State Change CS_ROUTING
2010-07-28 18:38:57.031250 [DEBUG] switch_channel.c:1471 (sofia/internal/
1001 at 192.168.1.24) Callstate Change DOWN -> RINGING
2010-07-28 18:38:57.031250 [DEBUG] switch_core_state_machine.c:341
(sofia/internal/1001 at 192.168.1.24) State ROUTING
2010-07-28 18:38:57.031250 [DEBUG] mod_sofia.c:142 sofia/internal/
1001 at 192.168.1.24 SOFIA ROUTING
2010-07-28 18:38:57.031250 [DEBUG] switch_core_state_machine.c:77
sofia/internal/1001 at 192.168.1.24 Standard ROUTING
2010-07-28 18:38:57.031250 [INFO] mod_dialplan_xml.c:331 Processing 1->0014
in context default
Dialplan: sofia/internal/1001 at 192.168.1.24 parsing
[default->test_txfax_stream] continue=false
Dialplan: sofia/internal/1001 at 192.168.1.24 Regex (PASS) [test_txfax_stream]
destination_number(0014) =~ /^0014$/ break=on-false
Dialplan: sofia/internal/1001 at 192.168.1.24 Action log(ALERT ${api_result})
Dialplan: sofia/internal/1001 at 192.168.1.24 Action lua(test.lua)
Dialplan: sofia/internal/1001 at 192.168.1.24 Action sleep(30000)
2010-07-28 18:38:57.046875 [DEBUG] switch_core_state_machine.c:119
(sofia/internal/1001 at 192.168.1.24) State Change CS_ROUTING -> CS_EXECUTE
2010-07-28 18:38:57.046875 [DEBUG] switch_core_session.c:1027 Send signal
sofia/internal/1001 at 192.168.1.24 [BREAK]
2010-07-28 18:38:57.046875 [DEBUG] switch_core_state_machine.c:341
(sofia/internal/1001 at 192.168.1.24) State ROUTING going to sleep
2010-07-28 18:38:57.046875 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/1001 at 192.168.1.24) Running State Change CS_EXECUTE
2010-07-28 18:38:57.046875 [DEBUG] switch_core_state_machine.c:348
(sofia/internal/1001 at 192.168.1.24) State EXECUTE
2010-07-28 18:38:57.046875 [DEBUG] mod_sofia.c:235 sofia/internal/
1001 at 192.168.1.24 SOFIA EXECUTE
2010-07-28 18:38:57.046875 [DEBUG] switch_core_state_machine.c:157
sofia/internal/1001 at 192.168.1.24 Standard EXECUTE
EXECUTE sofia/internal/1001 at 192.168.1.24 log(ALERT )
2010-07-28 18:38:57.046875 [ALERT] mod_dptools.c:984
EXECUTE sofia/internal/1001 at 192.168.1.24 lua(test.lua)
2010-07-28 18:38:57.093750 [NOTICE] switch_channel.c:776 New Channel
sofia/external/23649136 [69e9d03f-535b-483c-893a-a3bfebe427ad]
2010-07-28 18:38:57.093750 [DEBUG] mod_sofia.c:3892
(sofia/external/23649136) State Change CS_NEW -> CS_INIT
2010-07-28 18:38:57.093750 [DEBUG] switch_core_session.c:1027 Send signal
sofia/external/23649136 [BREAK]
2010-07-28 18:38:57.093750 [DEBUG] switch_core_state_machine.c:314
(sofia/external/23649136) Running State Change CS_INIT
2010-07-28 18:38:57.093750 [DEBUG] switch_core_state_machine.c:338
(sofia/external/23649136) State INIT
2010-07-28 18:38:57.093750 [DEBUG] mod_sofia.c:83 sofia/external/23649136
SOFIA INIT
2010-07-28 18:38:57.093750 [DEBUG] mod_sofia.c:119 (sofia/external/23649136)
State Change CS_INIT -> CS_ROUTING
2010-07-28 18:38:57.093750 [DEBUG] switch_core_session.c:1027 Send signal
sofia/external/23649136 [BREAK]
2010-07-28 18:38:57.093750 [DEBUG] switch_core_state_machine.c:338
(sofia/external/23649136) State INIT going to sleep
2010-07-28 18:38:57.093750 [DEBUG] switch_core_state_machine.c:314
(sofia/external/23649136) Running State Change CS_ROUTING
2010-07-28 18:38:57.093750 [DEBUG] switch_channel.c:1471
(sofia/external/23649136) Callstate Change DOWN -> RINGING
2010-07-28 18:38:57.093750 [DEBUG] sofia.c:4317 Channel
sofia/external/23649136 entering state [calling][0]
2010-07-28 18:38:57.093750 [DEBUG] switch_core_state_machine.c:341
(sofia/external/23649136) State ROUTING
2010-07-28 18:38:57.093750 [DEBUG] mod_sofia.c:142 sofia/external/23649136
SOFIA ROUTING
2010-07-28 18:38:57.109375 [DEBUG] switch_ivr_originate.c:64
(sofia/external/23649136) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2010-07-28 18:38:57.109375 [DEBUG] switch_core_session.c:1027 Send signal
sofia/external/23649136 [BREAK]
2010-07-28 18:38:57.109375 [DEBUG] switch_core_state_machine.c:341
(sofia/external/23649136) State ROUTING going to sleep
2010-07-28 18:38:57.109375 [DEBUG] switch_core_state_machine.c:314
(sofia/external/23649136) Running State Change CS_CONSUME_MEDIA
2010-07-28 18:38:57.109375 [DEBUG] switch_core_state_machine.c:360
(sofia/external/23649136) State CONSUME_MEDIA
2010-07-28 18:38:57.109375 [DEBUG] switch_core_state_machine.c:360
(sofia/external/23649136) State CONSUME_MEDIA going to sleep
2010-07-28 18:38:59.093750 [INFO] sofia.c:662 sofia/external/23649136 Update
Callee ID to "23649136" <23649136>
2010-07-28 18:38:59.093750 [DEBUG] sofia.c:4317 Channel
sofia/external/23649136 entering state [proceeding][183]
2010-07-28 18:38:59.093750 [DEBUG] sofia.c:4328 Remote SDP:
v=0
o=2dsp_4fxs_4fxo_108 16384 0 IN IP4 192.168.1.200
s=SIP CALL
i=Audio Session
c=IN IP4 192.168.1.200
t=0 0
m=audio 16384 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000/1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

2010-07-28 18:38:59.093750 [DEBUG] sofia_glue.c:3845 Audio Codec Compare
[PCMU:0:8000:20]/[PCMU:0:8000:20]
2010-07-28 18:38:59.093750 [DEBUG] sofia_glue.c:2442 Set Codec
sofia/external/23649136 PCMU/8000 20 ms 160 samples
2010-07-28 18:38:59.093750 [DEBUG] sofia_glue.c:3935 Set 2833 dtmf send
payload to 101
2010-07-28 18:38:59.093750 [DEBUG] sofia_glue.c:2682 AUDIO RTP
[sofia/external/23649136] 192.168.1.24 port 23668 -> 192.168.1.200 port
16384 codec: 0 ms: 20
2010-07-28 18:38:59.093750 [DEBUG] switch_rtp.c:1413 Starting timer [soft]
160 bytes per 20ms
2010-07-28 18:38:59.093750 [DEBUG] sofia_glue.c:2892 Set 2833 dtmf send
payload to 101
2010-07-28 18:38:59.093750 [DEBUG] sofia_glue.c:2897 Set 2833 dtmf receive
payload to 101
2010-07-28 18:38:59.093750 [NOTICE] sofia_glue.c:3290 Pre-Answer
sofia/external/23649136!
2010-07-28 18:38:59.093750 [DEBUG] switch_channel.c:2349
(sofia/external/23649136) Callstate Change RINGING -> EARLY
2010-07-28 18:38:59.093750 [DEBUG] switch_ivr_originate.c:3328 Originate
Resulted in Success: [sofia/external/23649136]
2010-07-28 18:38:59.093750 [DEBUG] mod_commands.c:2936
(sofia/external/23649136) State Change CS_CONSUME_MEDIA -> CS_EXECUTE
2010-07-28 18:38:59.093750 [DEBUG] switch_core_session.c:1027 Send signal
sofia/external/23649136 [BREAK]
2010-07-28 18:38:59.093750 [DEBUG] switch_core_state_machine.c:314
(sofia/external/23649136) Running State Change CS_EXECUTE
2010-07-28 18:38:59.093750 [DEBUG] switch_core_state_machine.c:348
(sofia/external/23649136) State EXECUTE
2010-07-28 18:38:59.093750 [DEBUG] mod_sofia.c:235 sofia/external/23649136
SOFIA EXECUTE
2010-07-28 18:38:59.093750 [DEBUG] switch_core_state_machine.c:157
sofia/external/23649136 Standard EXECUTE
EXECUTE sofia/external/23649136 txfax(zzz.tif)
2010-07-28 18:38:59.109375 [DEBUG] switch_cpp.cpp:968 sofia/internal/
1001 at 192.168.1.24 destroy/unlink session from object
EXECUTE sofia/internal/1001 at 192.168.1.24 sleep(30000)
2010-07-28 18:38:59.125000 [DEBUG] mod_spandsp_fax.c:1051 Raw read codec
activation Success L16 20000
2010-07-28 18:38:59.125000 [DEBUG] switch_core_codec.c:116
sofia/external/23649136 Push codec L16:10
2010-07-28 18:38:59.125000 [DEBUG] mod_spandsp_fax.c:1067 Raw write codec
activation Success L16
2010-07-28 18:38:59.156250 [DEBUG] switch_rtp.c:2517 Correct ip/port
confirmed.
2010-07-28 18:38:59.390625 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier up (-2) in state 18
2010-07-28 18:38:59.468750 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier down (-1) in state 18
2010-07-28 18:38:59.468750 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier up (-2) in state 18
2010-07-28 18:38:59.500000 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier down (-1) in state 18
2010-07-28 18:38:59.500000 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier up (-2) in state 18
2010-07-28 18:38:59.515625 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier down (-1) in state 18
2010-07-28 18:38:59.531250 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier up (-2) in state 18
2010-07-28 18:38:59.562500 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier down (-1) in state 18
2010-07-28 18:38:59.562500 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier up (-2) in state 18
2010-07-28 18:38:59.578125 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier down (-1) in state 18
2010-07-28 18:38:59.578125 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier up (-2) in state 18
2010-07-28 18:38:59.593750 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier down (-1) in state 18
2010-07-28 18:38:59.593750 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier up (-2) in state 18
2010-07-28 18:38:59.609375 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier down (-1) in state 18
2010-07-28 18:38:59.640625 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier up (-2) in state 18
2010-07-28 18:38:59.656250 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier down (-1) in state 18
2010-07-28 18:38:59.656250 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier up (-2) in state 18
2010-07-28 18:38:59.656250 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier down (-1) in state 18
2010-07-28 18:39:00.078125 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier up (-2) in state 18
2010-07-28 18:39:01.078125 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier down (-1) in state 18
2010-07-28 18:39:02.953125 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier up (-2) in state 18
2010-07-28 18:39:02.953125 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier down (-1) in state 18
2010-07-28 18:39:03.093750 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier up (-2) in state 18
2010-07-28 18:39:04.078125 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier down (-1) in state 18
2010-07-28 18:39:06.453125 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier up (-2) in state 18
2010-07-28 18:39:06.453125 [DEBUG] mod_spandsp_fax.c:271 FLOW T.30 HDLC
signal status is Carrier down (-1) in state 18
2010-07-28 18:39:07.062500 [DEBUG] sofia.c:4317 Channel
sofia/external/23649136 entering state [completing][200]
2010-07-28 18:39:07.062500 [DEBUG] sofia.c:4325 Duplicate SDP
v=0
o=2dsp_4fxs_4fxo_108 16384 0 IN IP4 192.168.1.200
s=SIP CALL
i=Audio Session
c=IN IP4 192.168.1.200
t=0 0
m=audio 16384 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000/1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

2010-07-28 18:39:07.062500 [DEBUG] sofia.c:4317 Channel
sofia/external/23649136 entering state [ready][200]
2010-07-28 18:39:07.062500 [DEBUG] switch_channel.c:2494
(sofia/external/23649136) Callstate Change EARLY -> ACTIVE
2010-07-28 18:39:07.062500 [NOTICE] sofia.c:4826 Channel
[sofia/external/23649136] has been answered

-- 
Best regards,
Ted
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20100728/06dfdc39/attachment-0001.html 