[Freeswitch-users] Unable to TXFAX, but receiving is OK. Always result (49)

19 Mar 2012

      Hi All,

I can receive faxes and email them to their recipients now with rxfax!!!!

I cannot send anything though.

My test command is: (with number changed) 

                /usr/local/freeswitch/bin/fs_cli -x "originate
{ignore_early_media=true}sofia/gateway/voipinnovations/11234567890
&txfax(/usr/sean/output/txfax.tiff)"

I have also tried it without the ignore_early_media. 

I do not have any V.38 enabled.  When I did no incoming faxes would work.
The receiving fax never sent tone, so sender never connected.

Any help would be greatly appreciated.

Thanks.

Here is the FS log:

freeswitch@internal> 2012-03-19 12:58:06.511937 [DEBUG]
switch_ivr_originate.c:1884 Parsing global variables

2012-03-19 12:58:06.511937 [DEBUG] switch_event.c:1521 Parsing variable
[ignore_early_media]=[true]

2012-03-19 12:58:06.511937 [NOTICE] switch_channel.c:924 New Channel
sofia/external_noauth/14108038876 [bc6cadc8-761b-42cb-8873-889320fc2658]

2012-03-19 12:58:06.511937 [DEBUG] mod_sofia.c:4674
(sofia/external_noauth/14108038876) State Change CS_NEW -> CS_INIT

2012-03-19 12:58:06.511937 [DEBUG] switch_core_session.c:1180 Send signal
sofia/external_noauth/14108038876 [BREAK]

2012-03-19 12:58:06.511937 [DEBUG] switch_core_state_machine.c:362
(sofia/external_noauth/14108038876) Running State Change CS_INIT

2012-03-19 12:58:06.511937 [DEBUG] switch_core_state_machine.c:401
(sofia/external_noauth/14108038876) State INIT

2012-03-19 12:58:06.511937 [DEBUG] mod_sofia.c:85
sofia/external_noauth/14108038876 SOFIA INIT

2012-03-19 12:58:07.117896 [DEBUG] switch_nat.c:511 mapped public port 17322
protocol UDP to localport 17322

2012-03-19 12:58:07.602876 [DEBUG] switch_nat.c:511 mapped public port 17323
protocol UDP to localport 17323

2012-03-19 12:58:07.602876 [DEBUG] mod_sofia.c:125
(sofia/external_noauth/14108038876) State Change CS_INIT -> CS_ROUTING

2012-03-19 12:58:07.602876 [DEBUG] switch_core_session.c:1180 Send signal
sofia/external_noauth/14108038876 [BREAK]

2012-03-19 12:58:07.602876 [DEBUG] switch_core_state_machine.c:401
(sofia/external_noauth/14108038876) State INIT going to sleep

2012-03-19 12:58:07.602876 [DEBUG] switch_core_state_machine.c:362
(sofia/external_noauth/14108038876) Running State Change CS_ROUTING

2012-03-19 12:58:07.602876 [DEBUG] switch_channel.c:1884
(sofia/external_noauth/14108038876) Callstate Change DOWN -> RINGING

2012-03-19 12:58:07.602876 [DEBUG] switch_core_state_machine.c:410
(sofia/external_noauth/14108038876) State ROUTING

2012-03-19 12:58:07.602876 [DEBUG] mod_sofia.c:148
sofia/external_noauth/14108038876 SOFIA ROUTING

2012-03-19 12:58:07.602876 [DEBUG] switch_ivr_originate.c:66
(sofia/external_noauth/14108038876) State Change CS_ROUTING ->
CS_CONSUME_MEDIA

2012-03-19 12:58:07.602876 [DEBUG] switch_core_session.c:1180 Send signal
sofia/external_noauth/14108038876 [BREAK]

2012-03-19 12:58:07.602876 [DEBUG] switch_core_state_machine.c:410
(sofia/external_noauth/14108038876) State ROUTING going to sleep

2012-03-19 12:58:07.602876 [DEBUG] switch_core_state_machine.c:362
(sofia/external_noauth/14108038876) Running State Change CS_CONSUME_MEDIA

2012-03-19 12:58:07.602876 [DEBUG] switch_core_state_machine.c:429
(sofia/external_noauth/14108038876) State CONSUME_MEDIA

2012-03-19 12:58:07.602876 [DEBUG] switch_core_state_machine.c:429
(sofia/external_noauth/14108038876) State CONSUME_MEDIA going to sleep

2012-03-19 12:58:07.602876 [DEBUG] switch_core_session.c:875 Send signal
sofia/external_noauth/14108038876 [BREAK]

2012-03-19 12:58:07.602876 [DEBUG] sofia.c:5494 Channel
sofia/external_noauth/14108038876 entering state [calling][0]

2012-03-19 12:58:10.613725 [DEBUG] switch_core_session.c:875 Send signal
sofia/external_noauth/14108038876 [BREAK]

2012-03-19 12:58:10.613725 [DEBUG] switch_core_session.c:875 Send signal
sofia/external_noauth/14108038876 [BREAK]

2012-03-19 12:58:10.623715 [DEBUG] sofia.c:5494 Channel
sofia/external_noauth/14108038876 entering state [proceeding][183]

2012-03-19 12:58:10.623715 [DEBUG] sofia.c:5505 Remote SDP:

v=0

o=Sansay-VSXi 188 1 IN IP4 64.136.174.30

s=Session Controller

c=IN IP4 69.85.185.142

t=0 0

m=audio 26144 RTP/AVP 0 8 101

a=rtpmap:0 PCMU/8000

a=rtpmap:8 PCMA/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-15

a=ptime:20

2012-03-19 12:58:10.623715 [DEBUG] sofia_glue.c:4798 Audio Codec Compare
[PCMU:0:8000:20:64000]/[G7221:115:32000:20:48000]

2012-03-19 12:58:10.623715 [DEBUG] sofia_glue.c:4798 Audio Codec Compare
[PCMU:0:8000:20:64000]/[G7221:107:16000:20:32000]

2012-03-19 12:58:10.623715 [DEBUG] sofia_glue.c:4798 Audio Codec Compare
[PCMU:0:8000:20:64000]/[G722:9:8000:20:64000]

2012-03-19 12:58:10.623715 [DEBUG] sofia_glue.c:4798 Audio Codec Compare
[PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]

2012-03-19 12:58:10.623715 [DEBUG] sofia_glue.c:2919 Set Codec
sofia/external_noauth/14108038876 PCMU/8000 20 ms 160 samples 64000 bits

2012-03-19 12:58:10.623715 [DEBUG] sofia_glue.c:4912 Set 2833 dtmf send
payload to 101

2012-03-19 12:58:10.623715 [DEBUG] sofia_glue.c:3171 AUDIO RTP
[sofia/external_noauth/14108038876] 10.10.40.185 port 17322 -> 69.85.185.142
port 26144 codec: 0 ms: 20

2012-03-19 12:58:10.623715 [DEBUG] switch_rtp.c:1659 Starting timer [soft]
160 bytes per 20ms

2012-03-19 12:58:10.623715 [DEBUG] sofia_glue.c:3435 Set 2833 dtmf send
payload to 101

2012-03-19 12:58:10.623715 [DEBUG] sofia_glue.c:3441 Set 2833 dtmf receive
payload to 101

2012-03-19 12:58:10.623715 [NOTICE] sofia_glue.c:3945 Pre-Answer
sofia/external_noauth/14108038876!

2012-03-19 12:58:10.623715 [DEBUG] switch_channel.c:2930
(sofia/external_noauth/14108038876) Callstate Change RINGING -> EARLY

2012-03-19 12:58:23.010042 [DEBUG] switch_core_session.c:875 Send signal
sofia/external_noauth/14108038876 [BREAK]

2012-03-19 12:58:23.010042 [DEBUG] switch_core_session.c:875 Send signal
sofia/external_noauth/14108038876 [BREAK]

2012-03-19 12:58:23.010042 [DEBUG] sofia.c:5494 Channel
sofia/external_noauth/14108038876 entering state [completing][200]

2012-03-19 12:58:23.010042 [DEBUG] sofia.c:5502 Duplicate SDP

v=0

o=Sansay-VSXi 188 1 IN IP4 64.136.174.30

s=Session Controller

c=IN IP4 69.85.185.142

t=0 0

m=audio 26144 RTP/AVP 0 8 101

a=rtpmap:0 PCMU/8000

a=rtpmap:8 PCMA/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-15

a=ptime:20

2012-03-19 12:58:23.010042 [DEBUG] switch_core_session.c:875 Send signal
sofia/external_noauth/14108038876 [BREAK]

2012-03-19 12:58:23.010042 [DEBUG] switch_core_session.c:875 Send signal
sofia/external_noauth/14108038876 [BREAK]

2012-03-19 12:58:23.010042 [DEBUG] sofia.c:5494 Channel
sofia/external_noauth/14108038876 entering state [ready][200]

2012-03-19 12:58:23.010042 [DEBUG] switch_channel.c:3188
(sofia/external_noauth/14108038876) Callstate Change EARLY -> ACTIVE

2012-03-19 12:58:23.010042 [NOTICE] sofia.c:6142 Channel
[sofia/external_noauth/14108038876] has been answered

2012-03-19 12:58:23.010042 [DEBUG] switch_ivr_originate.c:3266 Originate
Resulted in Success: [sofia/external_noauth/14108038876]

2012-03-19 12:58:23.010042 [INFO] switch_channel.c:2708
sofia/external_noauth/14108038876 Flipping CID from "" <0000000000> to
"Outbound Call" <14108038876>

2012-03-19 12:58:23.010042 [DEBUG] mod_commands.c:3574
(sofia/external_noauth/14108038876) State Change CS_CONSUME_MEDIA ->
CS_EXECUTE

2012-03-19 12:58:23.010042 [DEBUG] switch_core_session.c:1180 Send signal
sofia/external_noauth/14108038876 [BREAK]

2012-03-19 12:58:23.010042 [DEBUG] switch_core_state_machine.c:362
(sofia/external_noauth/14108038876) Running State Change CS_EXECUTE

2012-03-19 12:58:23.010042 [DEBUG] switch_core_state_machine.c:417
(sofia/external_noauth/14108038876) State EXECUTE

2012-03-19 12:58:23.010042 [DEBUG] mod_sofia.c:241
sofia/external_noauth/14108038876 SOFIA EXECUTE

2012-03-19 12:58:23.010042 [DEBUG] switch_core_state_machine.c:192
sofia/external_noauth/14108038876 Standard EXECUTE

EXECUTE sofia/external_noauth/14108038876 txfax(/usr/sean/output/txfax.tiff)

2012-03-19 12:58:23.010042 [DEBUG] mod_spandsp_fax.c:1355 Raw read codec
activation Success L16 20000

2012-03-19 12:58:23.010042 [DEBUG] switch_core_codec.c:116
sofia/external_noauth/14108038876 Push codec L16:70

2012-03-19 12:58:23.010042 [DEBUG] mod_spandsp_fax.c:1371 Raw write codec
activation Success L16

2012-03-19 12:58:23.070036 [DEBUG] switch_rtp.c:3204 Correct ip/port
confirmed.

2012-03-19 12:58:25.539903 [DEBUG] switch_core_session.c:875 Send signal
sofia/external_noauth/14108038876 [BREAK]

2012-03-19 12:58:25.549903 [DEBUG] switch_channel.c:2846
(sofia/external_noauth/14108038876) Callstate Change ACTIVE -> HANGUP

2012-03-19 12:58:25.549903 [NOTICE] sofia.c:623 Hangup
sofia/external_noauth/14108038876 [CS_EXECUTE] [NORMAL_CLEARING]

2012-03-19 12:58:25.549903 [DEBUG] switch_channel.c:2869 Send signal
sofia/external_noauth/14108038876 [KILL]

2012-03-19 12:58:25.549903 [DEBUG] switch_core_session.c:1180 Send signal
sofia/external_noauth/14108038876 [BREAK]

2012-03-19 12:58:25.549903 [DEBUG] mod_spandsp_fax.c:489
============================================================================
==

2012-03-19 12:58:25.549903 [DEBUG] mod_spandsp_fax.c:502 Fax processing not
successful - result (49) The call dropped prematurely.

2012-03-19 12:58:25.549903 [DEBUG] mod_spandsp_fax.c:507 Remote station id: 

2012-03-19 12:58:25.549903 [DEBUG] mod_spandsp_fax.c:508 Local station id:
SpanDSP Fax Ident

2012-03-19 12:58:25.549903 [DEBUG] mod_spandsp_fax.c:509 Pages transferred:
0

2012-03-19 12:58:25.549903 [DEBUG] mod_spandsp_fax.c:511 Total fax pages:
0

2012-03-19 12:58:25.549903 [DEBUG] mod_spandsp_fax.c:512 Image resolution:
0x0

2012-03-19 12:58:25.549903 [DEBUG] mod_spandsp_fax.c:513 Transfer Rate:
14400

2012-03-19 12:58:25.549903 [DEBUG] mod_spandsp_fax.c:515 ECM status
off

2012-03-19 12:58:25.549903 [DEBUG] mod_spandsp_fax.c:516 remote country:   

2012-03-19 12:58:25.549903 [DEBUG] mod_spandsp_fax.c:517 remote vendor:    

2012-03-19 12:58:25.549903 [DEBUG] mod_spandsp_fax.c:518 remote model:     

2012-03-19 12:58:25.549903 [DEBUG] mod_spandsp_fax.c:520
============================================================================
==

2012-03-19 12:58:25.549903 [DEBUG] switch_core_codec.c:141
sofia/external_noauth/14108038876 Restore previous codec PCMU:0.

2012-03-19 12:58:25.549903 [DEBUG] switch_core_session.c:2285
sofia/external_noauth/14108038876 skip receive message
[APPLICATION_EXEC_COMPLETE] (channel is hungup already)

2012-03-19 12:58:25.549903 [DEBUG] switch_core_state_machine.c:417
(sofia/external_noauth/14108038876) State EXECUTE going to sleep

2012-03-19 12:58:25.549903 [DEBUG] switch_core_state_machine.c:362
(sofia/external_noauth/14108038876) Running State Change CS_HANGUP

2012-03-19 12:58:25.549903 [DEBUG] switch_core_state_machine.c:602
(sofia/external_noauth/14108038876) State HANGUP

2012-03-19 12:58:25.549903 [DEBUG] mod_sofia.c:463
sofia/external_noauth/14108038876 Overriding SIP cause 480 with 200 from the
other leg

2012-03-19 12:58:25.549903 [DEBUG] mod_sofia.c:469 Channel
sofia/external_noauth/14108038876 hanging up, cause: NORMAL_CLEARING

2012-03-19 12:58:25.549903 [DEBUG] switch_core_state_machine.c:47
sofia/external_noauth/14108038876 Standard HANGUP, cause: NORMAL_CLEARING

2012-03-19 12:58:25.549903 [DEBUG] switch_core_state_machine.c:602
(sofia/external_noauth/14108038876) State HANGUP going to sleep

2012-03-19 12:58:25.549903 [DEBUG] switch_core_state_machine.c:393
(sofia/external_noauth/14108038876) State Change CS_HANGUP -> CS_REPORTING

2012-03-19 12:58:25.549903 [DEBUG] switch_core_session.c:1180 Send signal
sofia/external_noauth/14108038876 [BREAK]

2012-03-19 12:58:25.549903 [DEBUG] switch_core_state_machine.c:362
(sofia/external_noauth/14108038876) Running State Change CS_REPORTING

2012-03-19 12:58:25.549903 [DEBUG] switch_core_state_machine.c:662
(sofia/external_noauth/14108038876) State REPORTING

2012-03-19 12:58:25.549903 [DEBUG] switch_core_state_machine.c:79
sofia/external_noauth/14108038876 Standard REPORTING, cause: NORMAL_CLEARING

2012-03-19 12:58:25.549903 [DEBUG] switch_core_state_machine.c:662
(sofia/external_noauth/14108038876) State REPORTING going to sleep

2012-03-19 12:58:25.549903 [DEBUG] switch_core_state_machine.c:387
(sofia/external_noauth/14108038876) State Change CS_REPORTING -> CS_DESTROY

2012-03-19 12:58:25.549903 [DEBUG] switch_core_session.c:1180 Send signal
sofia/external_noauth/14108038876 [BREAK]

2012-03-19 12:58:25.549903 [DEBUG] switch_core_session.c:1380 Session 184
(sofia/external_noauth/14108038876) Locked, Waiting on external entities

2012-03-19 12:58:25.549903 [NOTICE] switch_core_session.c:1398 Session 184
(sofia/external_noauth/14108038876) Ended

2012-03-19 12:58:25.549903 [NOTICE] switch_core_session.c:1400 Close Channel
sofia/external_noauth/14108038876 [CS_DESTROY]

2012-03-19 12:58:25.549903 [DEBUG] switch_core_state_machine.c:491
(sofia/external_noauth/14108038876) Callstate Change HANGUP -> DOWN

2012-03-19 12:58:25.549903 [DEBUG] switch_core_state_machine.c:494
(sofia/external_noauth/14108038876) Running State Change CS_DESTROY

2012-03-19 12:58:25.549903 [DEBUG] switch_core_state_machine.c:504
(sofia/external_noauth/14108038876) State DESTROY

2012-03-19 12:58:25.549903 [DEBUG] mod_sofia.c:374
sofia/external_noauth/14108038876 SOFIA DESTROY

2012-03-19 12:58:25.559907 [DEBUG] switch_nat.c:571 unmapped public port
17322 protocol UDP to localport 17322

2012-03-19 12:58:25.579904 [DEBUG] switch_nat.c:571 unmapped public port
17323 protocol UDP to localport 17323

2012-03-19 12:58:25.579904 [DEBUG] switch_core_state_machine.c:86
sofia/external_noauth/14108038876 Standard DESTROY

2012-03-19 12:58:25.579904 [DEBUG] switch_core_state_machine.c:504
(sofia/external_noauth/14108038876) State DESTROY going to sleep

[Freeswitch-users] Unable to TXFAX, but receiving is OK. Always result (49)

Sean Devoy