Posted: Wed May 20, 2009 10:06 am Post subject: [asterisk-users] Problems receiving some faxes in T.38
Hello,
We have been working with the ReceiveFax application for some weeks now in order to receive faxes in T.38 and it works fairly well, but there are some faxes that for some reason we are not able to receive correctly.
The asterisk version we are using is 1.6.0.6 with spandsp-0.0.5pre4 and the asterisk machine is behind a CISCO mediaGW to be able to communicate with the PSTN.
The SIP call flows are different between the faxes we receive correctly and the ones that fail.
In the case of successfully received faxes, after establishing the audio session between de CISCO and Asterisk, CISCO sends a re-INVITE with the T.38 SDP. The T.38 setup succeeds.
On the other hand, with some faxes, the re-INVITE is sent by Asterisk and it looks that there is something wrong in the T.38 setup that makes the fax reception fail after the permitted retries. The FAXERROR variable is set to: "Disconnected after permitted retries".
What I can see from the traces is that it gets to a point that asterisk is sending T.38 data to the CISCO but the CISCO doesn't answer.
CISCO Asterisk
| |
| |
| |
|INVITE (SDP alaw)
|------------->|
|200 OK (SDP alaw)
|<-------------|
|ACK |
|------------->|
|Re-INVITE (SDP T.38)
|<-------------|
|200 OK (SDP T.38)
|------------->|
|ACK |
|<-------------|
| |
|..............|
|T.38 |
|..............|
|[t.38]no signal
|<-------------|
|[t.38]no signal
|------------->|
|[t.38]CED |
|<-------------|
|[t.38]no signal
|------------->|
|[t.38]V21-preamble
|<-------------|
|[t.38]hdlc |
|<-------------|
|[t.38]no signal
|<-------------|
|[t.38]V21-preamble
|<-------------|
|[t.38]hdlc |
|<-------------|
|[t.38]no signal
|<-------------|
|[t.38]V21-preamble
|<-------------|
|[t.38]hdlc |
|<-------------|
|[t.38]no signal
|<-------------|
|[t.38]V21-preamble
|<-------------|
|[t.38]hdlc |
|<-------------|
|[t.38]no signal
|<-------------|
|[t.38]V21-preamble
|<-------------|
|[t.38]DCN |
|<-------------|
|BYE |
|<-------------|
|200 OK |
|------------->|
Any idea of what might be happening?
Thanks in advance. Best regards,
Santiago Gimeno
The relevant information in the asterisk configuration files is:
Posted: Wed May 20, 2009 11:37 am Post subject: [asterisk-users] Problems receiving some faxes in T.38
Hi Santiago,
Santiago Gimeno wrote:
Quote:
Hello,
We have been working with the ReceiveFax application for some weeks
now in order to receive faxes in T.38 and it works fairly well, but
there are some faxes that for some reason we are not able to receive
correctly.
The asterisk version we are using is 1.6.0.6 with spandsp-0.0.5pre4
and the asterisk machine is behind a CISCO mediaGW to be able to
communicate with the PSTN.
The SIP call flows are different between the faxes we receive
correctly and the ones that fail.
In the case of successfully received faxes, after establishing the
audio session between de CISCO and Asterisk, CISCO sends a re-INVITE
with the T.38 SDP. The T.38 setup succeeds.
CISCO Asterisk
| |
| |
| |
|INVITE (SDP alaw)
|------------->|
|200 OK (SDP alaw)
|<-------------|
|ACK |
|------------->|
|Re-INVITE (SDP T.38)
|------------->|
|200 OK (SDP T.38)
|<-------------|
|ACK |
|------------->|
| |
|..............|
|T.38 |
|..............|
|[t.38]no signal
|<-------------|
|[t.38]no signal
|------------->|
|[t.38]CED |
|<-------------|
|[t.38]V21-preamble
|------------->|
Did you draw that arrow in the wrong direction? The side answering the
call should send the first V.21 signal.
Quote:
| |
| |
On the other hand, with some faxes, the re-INVITE is sent by Asterisk
and it looks that there is something wrong in the T.38 setup that
makes the fax reception fail after the permitted retries. The FAXERROR
variable is set to: "Disconnected after permitted retries".
What I can see from the traces is that it gets to a point that
asterisk is sending T.38 data to the CISCO but the CISCO doesn't answer.
CISCO Asterisk
| |
| |
| |
|INVITE (SDP alaw)
|------------->|
|200 OK (SDP alaw)
|<-------------|
|ACK |
|------------->|
|Re-INVITE (SDP T.38)
|<-------------|
|200 OK (SDP T.38)
|------------->|
|ACK |
|<-------------|
| |
|..............|
|T.38 |
|..............|
|[t.38]no signal
|<-------------|
|[t.38]no signal
|------------->|
|[t.38]CED |
|<-------------|
|[t.38]no signal
|------------->|
|[t.38]V21-preamble
|<-------------|
|[t.38]hdlc |
|<-------------|
|[t.38]no signal
|<-------------|
|[t.38]V21-preamble
|<-------------|
|[t.38]hdlc |
|<-------------|
|[t.38]no signal
|<-------------|
|[t.38]V21-preamble
|<-------------|
|[t.38]hdlc |
|<-------------|
|[t.38]no signal
|<-------------|
|[t.38]V21-preamble
|<-------------|
|[t.38]hdlc |
|<-------------|
|[t.38]no signal
|<-------------|
|[t.38]V21-preamble
|<-------------|
|[t.38]DCN |
|<-------------|
|BYE |
|<-------------|
|200 OK |
|------------->|
Any idea of what might be happening?
Thanks in advance. Best regards,
Santiago Gimeno
The relevant information in the asterisk configuration files is:
extensions.conf
[fax-in]
exten => 99999,1,Set(INCOMING_FAXFILE=/root/santi/fax/incoming.tif)
exten => 99999,n,Answer()
exten => 99999,n,Wait(3)
exten => 99999,n,ReceiveFax(${INCOMING_FAXFILE})
Try changing that Wait(3) to Wait(6). It seems some T.38 boxes act
strangely if the T.38 negotiation occurs too soon after the call starts.
I am not clear why, though I have tried to find suitable test cases to
pin this down.
Posted: Wed May 20, 2009 2:09 pm Post subject: [asterisk-users] Problems receiving some faxes in T.38
Hi Steve,
Thanks for the answers.
Comments inline.
2009/5/20 Steve Underwood <steveu@coppice.org>:
Quote:
Did you draw that arrow in the wrong direction? The side answering the
call should send the first V.21 signal.
No. That's what the wireshark trace shows.
Quote:
> The relevant information in the asterisk configuration files is:
>
> extensions.conf
>
> [fax-in]
> exten => 99999,1,Set(INCOMING_FAXFILE=/root/santi/fax/incoming.tif)
> exten => 99999,n,Answer()
> exten => 99999,n,Wait(3)
> exten => 99999,n,ReceiveFax(${INCOMING_FAXFILE})
Try changing that Wait(3) to Wait(6). It seems some T.38 boxes act
strangely if the T.38 negotiation occurs too soon after the call starts.
I am not clear why, though I have tried to find suitable test cases to
pin this down.
Changed that, but no luck, same problem.
What it is strange to me is that receiving faxes always work for me in
the case that the calling part (CISCO) sends the re-INVITE but it
doesn't if its the receiver of the fax (asterisk) that sends this
re-INVITE. I thought the standard said that the re-INVITE should be
sent by the receiver ot the fax.
This is part of the log file with debug level set to 4 showing the
start of the T.38 negotiation. The setup is tried 4 times before
dropping the call. I hope this helps to shed some light on the issue.
May 20 16:39:58 server asterisk[2456]: VERBOSE[25323]: --
Executing [99999@fax-in:5] ReceiveFAX("SIP/10.100.27.254-b7b27f60",
"/tmp/incoming1242830392.464.tif") in new stack
May 20 16:39:58 server asterisk[2456]: DEBUG[25323]: channel.c:3385 in
set_format: Set channel SIP/10.100.27.254-b7b27f60 to read format slin
May 20 16:39:58 server asterisk[2456]: DEBUG[25323]: channel.c:3385 in
set_format: Set channel SIP/10.100.27.254-b7b27f60 to write format
slin
May 20 16:39:58 server asterisk[2456]: DEBUG[25323]: app_fax.c:363 in
transmit_audio: Setting up CNG detection on SIP/10.100.27.254-b7b27f60
May 20 16:39:58 server asterisk[2456]: DEBUG[25323]: dsp.c:408 in
ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160,
hits_required=21
May 20 16:39:58 server asterisk[2456]: DEBUG[25323]: dsp.c:408 in
ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160,
hits_required=116
May 20 16:39:58 server asterisk[2456]: DEBUG[25323]: channel.c:2241 in
ast_settimeout: Scheduling timer at 160 sample intervals
May 20 16:39:58 server asterisk[2456]: DEBUG[25323]: channel.c:2352 in
ast_read_generator_actions: Generator got voice, switching to phase
locked mode
May 20 16:39:58 server asterisk[2456]: DEBUG[25323]: channel.c:2241 in
ast_settimeout: Scheduling timer at 0 sample intervals
May 20 16:39:58 server asterisk[2456]: DEBUG[25323]: rtp.c:3189 in
ast_rtp_write: Ooh, format changed from unknown to alaw
May 20 16:39:58 server asterisk[2456]: DEBUG[25323]: rtp.c:3205 in
ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 HDLC carrier up in state 1
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: dsp.c:526 in
tone_detect: 1100 Hz done detected
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: app_fax.c:398 in
transmit_audio: Fax tone detected. Requesting T38
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: chan_sip.c:3953
in change_t38_state: T38 state changed to 2 on channel
SIP/10.100.27.254-b7b27f60
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: chan_sip.c:8126
in t38_get_rate: T38MaxBitRate 9600 found
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: chan_sip.c:2360
in initialize_initreq: Initializing already initialized SIP dialog
E9C2BF4F-448211DE-B049F119-6B05D36C@10.100.27.254 (presumably
reinvite)
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: chan_sip.c:2598
in __sip_xmit: Trying to put 'INVITE sip' onto UDP socket destined for
10.100.27.254:5060
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: rtp.c:1100 in
ast_rtcp_read: Got RTCP report of 72 bytes
May 20 16:39:59 server asterisk[2456]: DEBUG[2577]: chan_sip.c:3115 in
__sip_semi_ack: (Provisional) Stopping retransmission (but retaining
packet) on 'E9C2BF4F-448211DE-B049F119-6B05D36C@10.100.27.254' Request
102: Found
May 20 16:39:59 server asterisk[2456]: DEBUG[2577]: chan_sip.c:14927
in handle_response_invite: SIP response 100 to RE-invite on outgoing
call E9C2BF4F-448211DE-B049F119-6B05D36C@10.100.27.254
May 20 16:39:59 server asterisk[2456]: DEBUG[2577]: chan_sip.c:3040 in
__sip_ack: Acked pending invite 102
May 20 16:39:59 server asterisk[2456]: DEBUG[2577]: chan_sip.c:3075 in
__sip_ack: Stopping retransmission on
'E9C2BF4F-448211DE-B049F119-6B05D36C@10.100.27.254' of Request 102:
Match Found
May 20 16:39:59 server asterisk[2456]: DEBUG[2577]: chan_sip.c:14927
in handle_response_invite: SIP response 200 to RE-invite on outgoing
call E9C2BF4F-448211DE-B049F119-6B05D36C@10.100.27.254
May 20 16:39:59 server asterisk[2456]: DEBUG[2577]: chan_sip.c:6990 in
process_sdp: FaxVersion: 0
May 20 16:39:59 server asterisk[2456]: DEBUG[2577]: chan_sip.c:6967 in
process_sdp: T38MaxBitRate: 9600
May 20 16:39:59 server asterisk[2456]: DEBUG[2577]: chan_sip.c:7032 in
process_sdp: RateManagement: transferredTCF
May 20 16:39:59 server asterisk[2456]: DEBUG[2577]: chan_sip.c:6964 in
process_sdp: MaxBufferSize:200
May 20 16:39:59 server asterisk[2456]: DEBUG[2577]: chan_sip.c:6997 in
process_sdp: FaxMaxDatagram: 72
May 20 16:39:59 server asterisk[2456]: DEBUG[2577]: chan_sip.c:3953 in
change_t38_state: T38 state changed to 5 on channel
SIP/10.100.27.254-b7b27f60
May 20 16:39:59 server asterisk[2456]: DEBUG[2577]: chan_sip.c:7112 in
process_sdp: Have T.38 but no audio codecs, accepting offer anyway
May 20 16:39:59 server asterisk[2456]: DEBUG[2577]: chan_sip.c:4524 in
update_call_counter: Updating call counter for incoming call
May 20 16:39:59 server asterisk[2456]: DEBUG[2577]: chan_sip.c:2598 in
__sip_xmit: Trying to put 'ACK sip:97' onto UDP socket destined for
10.100.27.254:5060
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: app_fax.c:430 in
transmit_audio: T38 negotiated, finishing audio loop
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: app_fax.c:448 in
transmit_audio: Loop finished, res=1
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: channel.c:2241 in
ast_settimeout: Scheduling timer at 0 sample intervals
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 Changing from state 1 to 32
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 Changing from phase T30_PHASE_A_CED to
T30_PHASE_CALL_FINISHED
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW FAX Set rx type 13
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW FAX FAX exchange complete
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW FAX Set tx type 13
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW FAX FAX exchange complete
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: channel.c:3385 in
set_format: Set channel SIP/10.100.27.254-b7b27f60 to write format
alaw
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: channel.c:3385 in
set_format: Set channel SIP/10.100.27.254-b7b27f60 to read format alaw
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 0: indicator no-signal
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Rx 0: IFP 00
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Rx 0: indicator no-signal
May 20 16:39:59 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 No signal is present
May 20 16:40:00 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 1: indicator ced
May 20 16:40:00 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Rx 1: IFP 00
May 20 16:40:00 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Rx 1: indicator no-signal
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 Send complete in phase T30_PHASE_A_CED, state
1
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 Starting answer mode
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 Changing from phase T30_PHASE_A_CED to
T30_PHASE_B_TX
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38T Set rx type 0
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38T Set tx type 4
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 Changing from state 1 to 17
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 DIS:
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... ...1= Store and forward Internet fax
(T.37): Set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... .1..= Real-time Internet fax (T.38):
Set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... 0...= 3G mobile network: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 ..0. ....= V.8 capabilities: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .0.. ....= Preferred octets: 256 octets
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... ...0= Ready to transmit a fax document
(polling): Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... ..1.= Can receive fax: Set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 ..10 11..= Supported data signalling rates:
V.27 ter, V.29, and V.17
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .1.. ....= R8x7.7lines/mm and/or
200x200pels/25.4mm: Set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 1... ....= 2-D coding: Set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... ..00= Recording width: 215mm +- 1%
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... 10..= Recording length: Unlimited
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .111 ....= Receiver's minimum scan line
time: 0ms at 3.85 l/mm; T7.7 = T3.85
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 1... ....= Extension indicator: Set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... ..0.= Compressed/uncompressed mode:
Compressed
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... .1..= Error correction mode (ECM): ECM
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .1.. ....= T.6 coding: Set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 1... ....= Extension indicator: Set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... ...0= "Field not valid" supported: Not
set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... ..0.= Multiple selective polling: Not
set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... .0..= Polled sub-address: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... 0...= T.43 coding: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 ...0 ....= Plane interleave: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 ..0. ....= Voice coding with 32kbit/s ADPCM
(Rec. G.726): Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .0.. ....= Reserved for the use of extended
voice coding set: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 1... ....= Extension indicator: Set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... ...1= R8x15.4lines/mm: Set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... ..0.= 300x300pels/25.4mm: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... .0..= R16x15.4lines/mm and/or
400x400pels/25.4mm: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... 0...= Inch-based resolution preferred:
Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 ...1 ....= Metric-based resolution
preferred: Set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 ..0. ....= Minimum scan line time for higher
resolutions: T15.4 = T7.7
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .0.. ....= Selective polling: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 1... ....= Extension indicator: Set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... ...0= Sub-addressing: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... ..0.= Password: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... .0..= Ready to transmit a data file
(polling): Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 ...0 ....= Binary file transfer (BFT): Not
set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 ..0. ....= Document transfer mode (DTM): Not
set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .0.. ....= Electronic data interchange
(EDI): Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 1... ....= Extension indicator: Set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... ...0= Basic transfer mode (BTM): Not
set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... .0..= Ready to transfer a character or
mixed mode document (polling): Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... 0...= Character mode: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 ..0. ....= Mixed mode (Annex E/T.4): Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 1... ....= Extension indicator: Set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... ...0= Processable mode 26 (Rec. T.505):
Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... ..0.= Digital network capability: Not
set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... .0..= Duplex capability: Half only
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... 0...= JPEG coding: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 ...0 ....= Full colour mode: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .0.. ....= 12bits/pel component: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 1... ....= Extension indicator: Set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... ...0= No subsampling (1:1:1): Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... ..0.= Custom illuminant: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... .0..= Custom gamut range: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .... 1...= North American Letter (215.9mm x
279.4mm): Set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 ...1 ....= North American Legal (215.9mm x
355.6mm): Set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 ..0. ....= Single-progression sequential
coding (Rec. T.85) basic: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 .0.. ....= Single-progression sequential
coding (Rec. T.85) optional L0: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 0... ....= Extension indicator: Not set
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 Tx: DIS with final frame tag
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 Tx: ff 13 80 05 ee f8 c4 80 91 80 80 80 18
May 20 16:40:03 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 2: indicator v21-preamble
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 3: (0) data v21/hdlc-data + 1 byte(s)
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 3: IFP c0 01 80 00 00 ff
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 4: (0) data v21/hdlc-data + 1 byte(s)
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 4: IFP c0 01 80 00 00 c8
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 5: (0) data v21/hdlc-data + 1 byte(s)
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 5: IFP c0 01 80 00 00 01
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 6: (0) data v21/hdlc-data + 1 byte(s)
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 6: IFP c0 01 80 00 00 a0
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 7: (0) data v21/hdlc-data + 1 byte(s)
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 7: IFP c0 01 80 00 00 77
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 8: (0) data v21/hdlc-data + 1 byte(s)
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 8: IFP c0 01 80 00 00 1f
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 9: (0) data v21/hdlc-data + 1 byte(s)
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 9: IFP c0 01 80 00 00 23
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 10: (0) data v21/hdlc-data + 1 byte(s)
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 10: IFP c0 01 80 00 00 01
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 11: (0) data v21/hdlc-data + 1 byte(s)
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 11: IFP c0 01 80 00 00 89
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 12: (0) data v21/hdlc-data + 1 byte(s)
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 12: IFP c0 01 80 00 00 01
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 13: (0) data v21/hdlc-data + 1 byte(s)
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 13: IFP c0 01 80 00 00 01
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 14: (0) data v21/hdlc-data + 1 byte(s)
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 14: IFP c0 01 80 00 00 01
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 15: (0) data v21/hdlc-data + 1 byte(s)
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 15: IFP c0 01 80 00 00 18
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 Send complete in phase T30_PHASE_B_TX, state
17
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 16: (0) data v21/hdlc-fcs-OK-sig-end + 0
byte(s)
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 16: IFP c0 01 40
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38 Tx 17: indicator no-signal
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 Send complete in phase T30_PHASE_B_TX, state
17
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 Changing from phase T30_PHASE_B_TX to
T30_PHASE_B_RX
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38T Set rx type 4
May 20 16:40:04 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38T Set tx type 0
May 20 16:40:08 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 T4 expired in phase T30_PHASE_B_RX, state 17
May 20 16:40:08 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.30 Changing from phase T30_PHASE_B_RX to
T30_PHASE_B_TX
May 20 16:40:08 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38T Set rx type 0
May 20 16:40:08 server asterisk[2456]: DEBUG[25323]: app_fax.c:129 in
span_message: FLOW T.38T Set tx type 4
Quote:
Why turn off ECM?
Turned it on.
Best regards,
Santiago Gimeno
_______________________________________________
-- Bandwidth and Colocation Provided by http://www.api-digital.com --
Posted: Wed May 20, 2009 3:39 pm Post subject: [asterisk-users] Problems receiving some faxes in T.38
Santiago Gimeno wrote:
Quote:
Hi Steve,
Thanks for the answers.
Comments inline.
2009/5/20 Steve Underwood <steveu@coppice.org>:
> Did you draw that arrow in the wrong direction? The side answering the
> call should send the first V.21 signal.
>
No. That's what the wireshark trace shows.
Strange.
Quote:
>> The relevant information in the asterisk configuration files is:
>>
>> extensions.conf
>>
>> [fax-in]
>> exten => 99999,1,Set(INCOMING_FAXFILE=/root/santi/fax/incoming.tif)
>> exten => 99999,n,Answer()
>> exten => 99999,n,Wait(3)
>> exten => 99999,n,ReceiveFax(${INCOMING_FAXFILE})
>>
> Try changing that Wait(3) to Wait(6). It seems some T.38 boxes act
> strangely if the T.38 negotiation occurs too soon after the call starts.
> I am not clear why, though I have tried to find suitable test cases to
> pin this down.
>
Changed that, but no luck, same problem.
What it is strange to me is that receiving faxes always work for me in
the case that the calling part (CISCO) sends the re-INVITE but it
doesn't if its the receiver of the fax (asterisk) that sends this
re-INVITE. I thought the standard said that the re-INVITE should be
sent by the receiver ot the fax.
The T.38 spec says the receiving side should initiate the re-invite, but
its really common for it to be a free-for-all with calls often falling
over when both ends re-invite at the same moment.
Quote:
This is part of the log file with debug level set to 4 showing the
start of the T.38 negotiation. The setup is tried 4 times before
dropping the call. I hope this helps to shed some light on the issue.
Not really. It just shows very little comming back from the Cisco. Can
you get a packet trace from a good call and a bad one, and e-mail them
to me? It doesn't look like this has anything to do with spandsp. It
looks likes its something in the call negotiation going wrong. I'm still
interested in taking a look, though.
Steve
_______________________________________________
-- Bandwidth and Colocation Provided by http://www.api-digital.com --
Posted: Thu May 21, 2009 10:24 am Post subject: [asterisk-users] Problems receiving some faxes in T.38
On Wed, May 20, 2009 at 6:58 AM, Santiago Gimeno
<santiago.gimeno@gmail.com> wrote:
Quote:
We have been working with the ReceiveFax application for some weeks now in
order to receive faxes in T.38 and it works fairly well, but there are some
faxes that for some reason we are not able to receive correctly.
The asterisk version we are using is 1.6.0.6 with spandsp-0.0.5pre4 and the
asterisk machine is behind a CISCO mediaGW to be able to communicate with
the PSTN.
That's very similar to a setup I made. And I was troubleshooting
similar problems. Let me ask you a question:
Are you quite confident that the inbound faxes that fail are going to
succeed on an ordinary fax machine?
In my case I was able to crank through my logs, and trace that the
failing calls were people who were calling a fax line by mistake, or
wardialers, or clients with lousy fax configurations where those faxes
also fail to our 'real' fax machines.
When we stopped counting the 'never going to work anyway' faxes in our
fax success calculations we had nearly perfect success rates.
And here's my debugging tip. Pick a number that always fails, change
the Cisco dialpeer to send those as ordinary audio fax passthrough, no
t.38, use asterisk with monitor to record them, and watch whether they
ever succeed. I'm willing to be my two cents that they don't.
_______________________________________________
-- Bandwidth and Colocation Provided by http://www.api-digital.com --
Posted: Thu May 21, 2009 2:11 pm Post subject: [asterisk-users] Problems receiving some faxes in T.38
Hi David,
Quote:
That's very similar to a setup I made. And I was troubleshooting
similar problems. Let me ask you a question:
Are you quite confident that the inbound faxes that fail are going to
succeed on an ordinary fax machine?
At least I'm sure of a couple of calling numbers that I know are real
faxes that work.
There are others, I suspect, are not really "good" faxes.
Quote:
In my case I was able to crank through my logs, and trace that the
failing calls were people who were calling a fax line by mistake, or
wardialers, or clients with lousy fax configurations where those faxes
also fail to our 'real' fax machines.
When we stopped counting the 'never going to work anyway' faxes in our
fax success calculations we had nearly perfect success rates.
And here's my debugging tip. Pick a number that always fails, change
the Cisco dialpeer to send those as ordinary audio fax passthrough, no
t.38, use asterisk with monitor to record them, and watch whether they
ever succeed. I'm willing to be my two cents that they don't.
Thanks for the tip, I'll try this in order to figure out which are
"real" and which are not.
Best regards,
Santiago Gimeno
_______________________________________________
-- Bandwidth and Colocation Provided by http://www.api-digital.com --
You cannot post new topics in this forum You cannot reply to topics in this forum You cannot edit your posts in this forum You cannot delete your posts in this forum You cannot vote in polls in this forum