asterisk users - Feb 2010 - Asterisk 1.6.1.13 and T.38 faxing

Hello everyone.

I'm struggling to get T.38 faxing to work in Asterisk 1.6.1.13 with a SIP
DID provider here in Brazil (GVT - Vox IP service). Here's my scenario:

When faxes arrive by a specific DID, they are routed thru this simple macro:

[macro-recebefax]

exten => s,1,Set(DB(fax/count)=$[${DB(fax/count)} + 1])
exten => s,n,Set(FAXCOUNT=${DB(fax/count)})
exten => s,n,Set(FAXFILE=fax-${DB(fax/count)}-rx)
exten => s,n,Answer()
exten => s,n,Wait(3)
exten => s,n,ReceiveFAX(/var/spool/asterisk/fax/${FAXFILE}.tif)
exten => s,n,NoOp(FAXSTATUS = ${FAXSTATUS})
exten => s,n,NoOp(FAXERROR = ${FAXERROR})
exten => s,n,NoOp(CALLID = ${CALLERID(name)} ${CALLERID(num)}
${REMOTESTATIONID})
exten => s,n,NoOp(FAXPAGES = ${FAXPAGES})
exten => s,n,NoOp(FAXBITRATE = ${FAXBITRATE})
exten => s,n,NoOp(FAXRESOLUTION = ${FAXRESOLUTION})
exten => s,n,NoOp(FAXMODE = ${FAXMODE})

exten => h,1,System(tiff2pdf -o /var/spool/asterisk/fax/${FAXFILE}.pdf -p A4
/var/spool/asterisk/fax/${FAXFILE}.tif)
exten => h,n,System(rm /var/spool/asterisk/fax/${FAXFILE}.tif)
exten => h,n,System(echo "Fax recebido." > /tmp/${FAXFILE}.txt)
exten => h,n,System(echo "Remetente: ${CALLID}" >>
/tmp/${FAXFILE}.txt)
exten => h,n,System(echo "Paginas: ${FAXPAGES}" >>
/tmp/${FAXFILE}.txt)
exten => h,n,System(echo "Velocidade de transmissao: ${FAXBITRATE}
bps" >> /tmp/${FAXFILE}.txt)
exten => h,n,System(echo "Resolucao: ${FAXRESOLUTION}" >>
/tmp/${FAXFILE}.txt)
exten => h,n,System(mutt -s "Allvo FAX" -a
/var/spool/asterisk/fax/${FAXFILE}.pdf vinicius at canall.com.br <
/tmp/${FAXFILE}.txt)
exten => h,n,System(rm /tmp/${FAXFILE}.txt)


I'm using here app_fax that comes with Asterisk, not the res_fax and
res_fax_digium that comes with FFA.

What happens is sometimes the T.38 negotiation goes well and others it fails
completely. That's what I got from the debug info on two different calls,
without changing any configs:

[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP v=0... UNSUPPORTED.
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP o=PVG 1265107050040 1265107050040 IN IP4 10.152.0.164...
UNSUPPORTED.
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP s=-... UNSUPPORTED.
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP p=+1 6135555555... UNSUPPORTED.
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP c=IN IP4 10.152.0.164... OK.
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP t=0 0... UNSUPPORTED.
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:7753 process_sdp: Processing
media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:7753 process_sdp: Processing
media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED.
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:7753 process_sdp: Processing
media-level (audio) SDP a=ptime:20... OK.
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:7753 process_sdp: Processing
media-level (audio) SDP a=fmtp:18 annexb=no... UNSUPPORTED.
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:8289 process_sdp_a_image: FaxVersion:
0
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:7753 process_sdp: Processing
media-level (image) SDP a=T38FaxVersion:0... OK.
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:8263 process_sdp_a_image:
MaxBufferSize:1100
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:7753 process_sdp: Processing
media-level (image) SDP a=T38FaxMaxBuffer:1100... OK.
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:8298 process_sdp_a_image:
FaxMaxDatagram: 612
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:7753 process_sdp: Processing
media-level (image) SDP a=T38FaxMaxDatagram:612... OK.
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:8266 process_sdp_a_image:
T38MaxBitRate: 14400
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:7753 process_sdp: Processing
media-level (image) SDP a=T38MaxBitRate:14400... OK.
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:8335 process_sdp_a_image:
RateManagement: transferredTCF
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:7753 process_sdp: Processing
media-level (image) SDP a=T38FaxRateManagement:transferredTCF... OK.
[Feb  2 08:38:56] DEBUG[21032]: chan_sip.c:8342 process_sdp_a_image: UDP EC:
t38UDPRedundancy



[Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP v=0... UNSUPPORTED.
[Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP o=PVG 1265107000170 1265107000170 IN IP4 10.152.0.164...
UNSUPPORTED.
[Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP s=-... UNSUPPORTED.
[Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP p=+1 6135555555... UNSUPPORTED.
[Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP c=IN IP4 10.152.0.164... OK.
[Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP t=0 0... UNSUPPORTED.
[Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP a=sqn: 0... UNSUPPORTED.
[Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP a=cdsc: 1 image udptl t38... UNSUPPORTED.
[Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP a=cpar: a=T38FaxVersion:0... UNSUPPORTED.
[Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP a=cpar: a=T38FaxUdpEC:t38UDPRedundancy... UNSUPPORTED.
[Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7753 process_sdp: Processing
media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7753 process_sdp: Processing
media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED.
[Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7753 process_sdp: Processing
media-level (audio) SDP a=ptime:20... OK.
[Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:4653 change_t38_state: T38 state
changed to 0 on channel SIP/voxip-00000000
[Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7932 process_sdp: We're settling
with these formats: 0x8 (alaw)
[Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7937 process_sdp: We have an owner,
now see if we need to change this call
[Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:5231 update_call_counter: Updating
call counter for incoming call
[Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:3172 __sip_xmit: Trying to put
'ACK sip:10.' onto UDP socket destined for 10.150.65.16:5060
[Feb  2 08:38:06] DEBUG[21064]: app_fax.c:699 transmit_t38: Shut down T.38 on
SIP/voxip-00000000


Note how items like T38FaxUdpEC are listed as OK on one call and unsupported on
another one. Could that be a bug? I can show the entire SIP conversations if
that's necessary for debugging this.



Atenciosamente,

Vin?cius Fontes
Gerente de Seguran?a da Informa??o
Canall Tecnologia em Comunica??es
Passo Fundo - RS - Brasil
+55 54 2104-7000

Information Security Manager
Canall Tecnologia em Comunica??es
Passo Fundo - RS - Brazil
+55 54 2104-7000

Vin?cius Fontes wrote:
> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP v=0... UNSUPPORTED.
> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP o=PVG 1265107000170 1265107000170 IN IP4 10.152.0.164...
UNSUPPORTED.
> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP s=-... UNSUPPORTED.
> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP p=+1 6135555555... UNSUPPORTED.
> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP c=IN IP4 10.152.0.164... OK.
> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP t=0 0... UNSUPPORTED.
> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP a=sqn: 0... UNSUPPORTED.
> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP a=cdsc: 1 image udptl t38... UNSUPPORTED.
> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP a=cpar: a=T38FaxVersion:0... UNSUPPORTED.
> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589 process_sdp: Processing
session-level SDP a=cpar: a=T38FaxUdpEC:t38UDPRedundancy... UNSUPPORTED.
> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7753 process_sdp: Processing
media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7753 process_sdp: Processing
media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED.
> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7753 process_sdp: Processing
media-level (audio) SDP a=ptime:20... OK.
> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:4653 change_t38_state: T38 state
changed to 0 on channel SIP/voxip-00000000
> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7932 process_sdp: We're
settling with these formats: 0x8 (alaw)
> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7937 process_sdp: We have an
owner, now see if we need to change this call
> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:5231 update_call_counter:
Updating call counter for incoming call
> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:3172 __sip_xmit: Trying to put
'ACK sip:10.' onto UDP socket destined for 10.150.65.16:5060
> [Feb  2 08:38:06] DEBUG[21064]: app_fax.c:699 transmit_t38: Shut down T.38
on SIP/voxip-00000000
> 
> 
> Note how items like T38FaxUdpEC are listed as OK on one call and
unsupported on another one. Could that be a bug? I can show the entire SIP
conversations if that's necessary for debugging this.
That's not quite correct; in the second example, the T38 parameters are
being sent as 'capabilities' (a=cdsc and a=cpar) which Asterisk does not
support. The second example does not provide backwards compatibility for
SIP endpoints that do not support capability-based negotiation, whereas
the first one does.

-- 
Kevin P. Fleming
Digium, Inc. | Director of Software Technologies
445 Jan Davis Drive NW - Huntsville, AL 35806 - USA
skype: kpfleming | jabber: kpfleming at digium.com
Check us out at www.digium.com & www.asterisk.org

----- "Steve Underwood" <steveu at coppice.org> escreveu:
> On 02/02/2010 10:11 PM, Kevin P. Fleming wrote:
> > Steve Underwood wrote:
> >    
> >> Hi Kevin,
> >>
> >> On 02/02/2010 09:12 PM, Kevin P. Fleming wrote:
> >>      
> >>> Vin?cius Fontes wrote:
> >>>
> >>>
> >>>        
> >>>> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589
process_sdp:
> Processing session-level SDP v=0... UNSUPPORTED.
> >>>> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589
process_sdp:
> Processing session-level SDP o=PVG 1265107000170 1265107000170 IN IP4
> 10.152.0.164... UNSUPPORTED.
> >>>> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589
process_sdp:
> Processing session-level SDP s=-... UNSUPPORTED.
> >>>> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589
process_sdp:
> Processing session-level SDP p=+1 6135555555... UNSUPPORTED.
> >>>> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589
process_sdp:
> Processing session-level SDP c=IN IP4 10.152.0.164... OK.
> >>>> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589
process_sdp:
> Processing session-level SDP t=0 0... UNSUPPORTED.
> >>>> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589
process_sdp:
> Processing session-level SDP a=sqn: 0... UNSUPPORTED.
> >>>> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589
process_sdp:
> Processing session-level SDP a=cdsc: 1 image udptl t38...
> UNSUPPORTED.
> >>>> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589
process_sdp:
> Processing session-level SDP a=cpar: a=T38FaxVersion:0...
> UNSUPPORTED.
> >>>> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7589
process_sdp:
> Processing session-level SDP a=cpar: a=T38FaxUdpEC:t38UDPRedundancy...
> UNSUPPORTED.
> >>>> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7753
process_sdp:
> Processing media-level (audio) SDP a=rtpmap:101
> telephone-event/8000... OK.
> >>>> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7753
process_sdp:
> Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED.
> >>>> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7753
process_sdp:
> Processing media-level (audio) SDP a=ptime:20... OK.
> >>>> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:4653
change_t38_state:
> T38 state changed to 0 on channel SIP/voxip-00000000
> >>>> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7932
process_sdp:
> We're settling with these formats: 0x8 (alaw)
> >>>> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:7937
process_sdp: We
> have an owner, now see if we need to change this call
> >>>> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:5231
> update_call_counter: Updating call counter for incoming call
> >>>> [Feb  2 08:38:06] DEBUG[21032]: chan_sip.c:3172
__sip_xmit:
> Trying to put 'ACK sip:10.' onto UDP socket destined for
> 10.150.65.16:5060
> >>>> [Feb  2 08:38:06] DEBUG[21064]: app_fax.c:699
transmit_t38: Shut
> down T.38 on SIP/voxip-00000000
> >>>>
> >>>>
> >>>> Note how items like T38FaxUdpEC are listed as OK on one
call and
> unsupported on another one. Could that be a bug? I can show the entire
> SIP conversations if that's necessary for debugging this.
> >>>>
> >>>>          
> >>> That's not quite correct; in the second example, the T38
> parameters are
> >>> being sent as 'capabilities' (a=cdsc and a=cpar) which
Asterisk
> does not
> >>> support. The second example does not provide backwards
> compatibility for
> >>> SIP endpoints that do not support capability-based
negotiation,
> whereas
> >>> the first one does.
> >>>
> >>>        
> >> What do you mean by that? Surely if you don't understand the
cdsc
> and
> >> cpar lines you are supposed to simply ignore them, and carry on.
> >>
> >> If it were harmless, that capability information seems enormously
> >> useful, especially in the context of the current discussions on
> sorting
> >> out the mess that T.38 has become. Sadly, it does cause some
> systems to
> >> choke, which is probably why it is rarely included.
> >>      
> > In this case, the re-INVITE did *not* include a
> non-capabilities-based
> > offer for T.38. The SDP parser listed the cdsc and cpar lines as
> > unsupported, but it did not see any media stream offer for T.38
> (unlike
> > the OP's first example), so it set the internal T.38 state on the
> > channel to 'not in use'.
> >    
> That's how T.38 calls normally start. They mostly start as audio, and
> 
> switch into T.38 mode later. We have only seen an initial fragment in
> 
> the log. We haven't seen anything that's actually wrong. We see an
> offer 
> to do telephony events, and from there things might progress to T.38
> or 
> something else. I can't see anything invalid in that, even if the 
> cdsc/cpar stuff is not understood.
> 
> Steve
I couldn't agree more Steve.

Is there any other info I could provide in order to help you find out what's
wrong? I could even open an issue on Mantis if the Digium staff think it's
worth it.

----- "Kevin P. Fleming" <kpfleming at digium.com> escreveu:
> Vin?cius Fontes wrote:
> 
> > I couldn't agree more Steve.
> > 
> > Is there any other info I could provide in order to help you find
> out what's wrong? I could even open an issue on Mantis if the Digium
> staff think it's worth it.
> 
> Post a 'sip set debug' capture of the failing call in this thread;
> that
> will make it much more obvious what is happening.
> 
> -- 
> Kevin P. Fleming
> Digium, Inc. | Director of Software Technologies
> 445 Jan Davis Drive NW - Huntsville, AL 35806 - USA
> skype: kpfleming | jabber: kpfleming at digium.com
> Check us out at www.digium.com & www.asterisk.org
> 
> -- 
> _____________________________________________________________________
> -- Bandwidth and Colocation Provided by http://www.api-digital.com --
> 
> asterisk-users mailing list
> To UNSUBSCRIBE or update options visit:
>    http://lists.digium.com/mailman/listinfo/asterisk-users

I've put it on pastebin because is was a lot of text. Here's the link:
http://pastebin.com/m7467cea1. That's all the information on the CLI with
verbose=3 and "sip set debug peer voxip".

----- "Steve Underwood" <steveu at coppice.org> escreveu:
> On 02/03/2010 12:45 AM, Vin?cius Fontes wrote:
> > ----- "Kevin P. Fleming"<kpfleming at digium.com> 
escreveu:
> >
> >    
> >> Vin?cius Fontes wrote:
> >>
> >>      
> >>> I couldn't agree more Steve.
> >>>
> >>> Is there any other info I could provide in order to help you
find
> >>>        
> >> out what's wrong? I could even open an issue on Mantis if the
> Digium
> >> staff think it's worth it.
> >>
> >> Post a 'sip set debug' capture of the failing call in this
thread;
> >> that
> >> will make it much more obvious what is happening.
> >>
> >> -- 
> >> Kevin P. Fleming
> >> Digium, Inc. | Director of Software Technologies
> >> 445 Jan Davis Drive NW - Huntsville, AL 35806 - USA
> >> skype: kpfleming | jabber: kpfleming at digium.com
> >> Check us out at www.digium.com&  www.asterisk.org
> >>
> >> -- 
> >>
> _____________________________________________________________________
> >> -- Bandwidth and Colocation Provided by http://www.api-digital.com
> --
> >>
> >> asterisk-users mailing list
> >> To UNSUBSCRIBE or update options visit:
> >>     http://lists.digium.com/mailman/listinfo/asterisk-users
> >>      
> >
> > I've put it on pastebin because is was a lot of text. Here's
the
> link: http://pastebin.com/m7467cea1. That's all the information on the
> CLI with verbose=3 and "sip set debug peer voxip".
> >
> >    
> I wonder why Asterisk would say:
> 
> X-asterisk-Info: SIP re-invite (External RTP bridge)
> Content-Type: application/sdp
> Content-Length: 344
> 
> v=0
> o=root 44350963 44350964 IN IP4 10.153.66.146
> s=Asterisk PBX 1.6.1.13
> c=IN IP4 10.153.66.146
> t=0 0
> m=image 4819 udptl t38
> a=T38FaxVersion:0
> a=T38MaxBitRate:14400
> a=T38FaxFillBitRemoval
> a=T38FaxTranscodingMMR
> a=T38FaxTranscodingJBIG
> a=T38FaxRateManagement:transferredTCF
> a=T38FaxMaxDatagram:1400
> a=T38FaxUdpEC:t38UDPRedundancy
> 
> I'm pretty sure it doesn't support T38FaxTranscodingMMR or 
> T38FaxTranscodingJBIG, so they should not be there. Perhaps more 
> relevant to you, though, is why is * saying "(External RTP
bridge)".
> Does it really mean it?
> 
> Steve
I'm not really sure. What I know is that this telco has separate boxes for
SIP signalling and RTP media. Not even sure if that's related to your
question which, to be honest, I didn't fully understand. :)