ASTERISK-07861: T38 relay doesn't work between Audiocodes Tulip AC494 ATAs

[Home]

Summary: ASTERISK-07861: T38 relay doesn't work between Audiocodes Tulip AC494 ATAs

Reporter: Brian Candler (candlerb) Labels:

Date Opened: 2006-10-03 07:32:22 Date Closed: 2011-06-07 14:03:01

Priority: Major Regression? No

Status: Closed/Complete Components: Channels/chan_sip/T.38

Versions: Frequency of
Occurrence

Related
Issues:

Environment: Attachments: ( 0) 20070926_debug.txt
( 1) t38bug.txt
( 2) t38bug2.txt
( 3) t38debug3.txt
( 4) t38direct-tcpdump.txt
( 5) t38log3c.txt.gz

Description: When trying to use T38 fax relay between a pair of Audiocodes AC494's, when fax is detected and one ATA sends a reinvite with

m=image 5004 UDPTL t38
a=T38FaxVersion:0
...

Asterisk rejects it with "488 Not acceptable here" and logs "Unsupported SDP media type in offer: image 5004 UDPTL t38". As a result, fax relay fails completely.

****** ADDITIONAL INFORMATION ******

Platform: CentOS 4.4. Built from source using

make clean
./configure
make
sudo make install

Test network is as follows:
- 10.69.255.251 Asterisk SVN r44249 under CentOS 4.4
- 10.69.255.246 AC494 (originating fax, Windows XP laptop; username tulip2; ext 402 in dialplan)
- 10.69.255.242 AC494 (accepting fax, USR Courier modem with mgetty on CentOS; username tulip4; ext 404)

Debugging trace attached. Note: I followed bug report instructions at http://www.voip-info.org/tiki-index.php?page=Asterisk%20T.38
however "set debug 4" and "set verbose 4" commands are rejected.

I have purposely disabled the G711u and G711a codecs on the Audiocodes; the remaining ones they support are G729, G723, G726-16 and G726-32.

Audio G729 calls are established successfully. However when the fax detection is triggered, then the re-invite is rejected with 488.

Relevant parts of sip.conf:

[general]
context=default ; Default context for incoming calls
realm=inspiredbroadcast.net
allowoverlap=no ; Disable overlap dialing support. (Default is yes)
bindport=5060 ; UDP Port to bind to (SIP standard port is 5060)
bindaddr=0.0.0.0 ; IP address to bind to (0.0.0.0 binds to all)
srvlookup=yes ; Enable DNS SRV lookups on outbound calls
dtmfmode=auto
disallow=all
allow=gsm
allow=g729 ; needs licence except for pass-thru
allow=g726
allow=g723.1 ; pass-thru only
allow=ilbc
allow=lpc10
allow=speex
allow=adpcm

[authentication]

[tulip2]
type=friend
secret=xyzzy
context=from-sip ; Where to start in the dialplan when this phone calls
callerid=Tulip ATA port 2 <402> ; Full caller ID, to override the phones config
; on incoming calls to Asterisk
nat=no ; there is not NAT between phone and Asterisk
canreinvite=yes ; allow RTP voice traffic to bypass Asterisk
host=dynamic ; needed to allow registration
t38pt_udptl=yes

[tulip4]
type=friend
secret=xyzzy
context=from-sip ; Where to start in the dialplan when this phone calls
callerid=Tulip ATA port 4 <404> ; Full caller ID, to override the phones config
; on incoming calls to Asterisk
nat=no ; there is not NAT between phone and Asterisk
canreinvite=yes ; allow RTP voice traffic to bypass Asterisk
host=dynamic ; needed to allow registration
t38pt_udptl=yes

========= update ==========

Just in case the problem was to do with using g729, I commented out both g729 and g723.1 in sip.conf. That forced everything to use G726-32/8000. However the problem is unchanged:
...
Sending to 10.69.255.242 : 5060 (NAT)
[Oct 3 13:24:58] WARNING[15966]: chan_sip.c:4637 process_sdp: Unsupported SDP media type in offer: image 5004 UDPTL t38
Transmitting (NAT) to 10.69.255.242:5060:
SIP/2.0 488 Not acceptable here
...

Comments: By: dea (dea) 2006-10-03 12:17:09

I may be off my rocker, but the code appears to be looking for this in the
SDP:
m=image 5004 udptl t38

Note the case difference in UDPTL vs. udptl

If your endpoint is sending UDPTL, perhaps a quick hack near line 4627 to
the sscanf that looks for:
image %d udptl t38%n
can be changed to:
image %d UDPTL t38%n

If that fixes it for that endpoint, then a proper solution can be
identified.
By: Brian Candler (candlerb) 2006-10-04 03:48:59

That gets me a bit further, so that case-sensitivity issue certainly needs fixing.

However it now fails as follows:

Sending to 10.69.255.242 : 5060 (NAT)
Got T.38 offer in SDP in dialog 7435a75d15c3198367167da32ac6cb2f@10.69.255.251
Peer doesn't provide audio
[Oct 4 09:45:07] DEBUG[25996]: chan_sip.c:4699 process_sdp: Peer T.38 UDPTL is at port 10.69.255.242:5004
[Oct 4 09:45:07] DEBUG[25996]: chan_sip.c:4907 process_sdp: Our T38 capability = (3840), peer T38 capability (16160), joint T38 capability (3872)
Capabilities: us - 0xea2 (gsm|g726|adpcm|lpc10|speex|ilbc), peer - audio=0x0 (nothing)/video=0x0 (nothing), combined - 0x0 (nothing)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing)
[Oct 4 09:45:07] NOTICE[25996]: chan_sip.c:4942 process_sdp: No compatible codecs, not accepting this offer!
Transmitting (NAT) to 10.69.255.242:5060:
SIP/2.0 488 Not acceptable here
By: dea (dea) 2006-10-04 14:07:50

I'm not sure the best way to handle the case issue. A quick google
tour around the various SIP RFCs shows that some elements of the SDP
are case sensitive, but the media attribute is not one of them.

I see a couple ugly ways to deal with it, but at least we've identified
the issue and maybe a chan_sip guru will be able to identify the best fix.

I would suggest that the endpoint manufacturer 'fix' their code in the
invite, but that might be an option.

The second issue has been reported a number of times, and is related to the
fact that chan_sip requires a common audio codec even if it is not going to
use it. If the Audiocodes endpoint can be configured with a fall-back codec
(ulaw), you might get a little further.
By: Brian Candler (candlerb) 2006-10-05 02:49:29

There is a compatible codec already - G726. However to eliminate this as a source of problems I've re-enabled G711a/u on both the ATAs and on Asterisk:

> sip show peer tulip1
...
T38 pt UDPTL : Yes
T38 pt RTP : No
T38 pt TCP : No
CanReinvite : Yes
...
Codecs : 0xeae (gsm|ulaw|alaw|g726|adpcm|lpc10|speex|ilbc)
Codec Order : (ulaw:20,alaw:20,gsm:20,g726:20,ilbc:30,lpc10:20,speex:20,adpcm:20)

The same problem occurs - the audio channel is set up as ulaw, but then it all fails when the ATA tries to switch to T38, giving "no compatible codec". I will upload a new log "t38bug2.txt" which shows this.

Note that the SDP offer from the ATA only includes m=image 5004 UDPTL t38 and no audio codecs at all.
By: Serge Vecher (serge-v) 2006-10-05 09:13:15

does this change help any http://lists.digium.com/pipermail/svn-commits/2006-October/017504.html ?
By: Brian Candler (candlerb) 2006-10-06 03:57:13

Thanks. I did an svn update to r44544, and I still had to make the "UDPTL" case change to line 4626

It's different now. The INVITEs are forwarded, but something goes wrong. Asterisk keeps retransmitting INVITEs, and eventually gives up.

Attachment t38log3c.txt.gz gives the details. I haven't been able to get any logs out of the Tulip more than "on hook" and "off hook" :-(

By: Brian Candler (candlerb) 2006-10-06 04:09:38

To analyse this a bit more: the attempt to switch to T38 starts at 09:47:46

ATA Astx ATA
.246 .251 .242
<----- INVITE t38
<----- INVITE T38
-----> 200 OK
------> 200 OK
<----- ACK

At this point Asterisk logs the following:

[Oct 6 09:47:46] DEBUG[5379]: rtp.c:2752 bridge_native_loop: Oooh, 'SIP/tulip4-
09ba6af8' changed end address to 0.0.0.0:0 (format 4)
[Oct 6 09:47:46] DEBUG[5379]: rtp.c:2754 bridge_native_loop: Oooh, 'SIP/tulip4-
09ba6af8' changed end vaddress to 0.0.0.0:0 (format 4)
[Oct 6 09:47:46] DEBUG[5379]: rtp.c:2756 bridge_native_loop: Oooh, 'SIP/tulip4-
09ba6af8' was 10.69.255.242:5004/(format 4)
[Oct 6 09:47:46] DEBUG[5379]: rtp.c:2758 bridge_native_loop: Oooh, 'SIP/tulip4-
09ba6af8' was 0.0.0.0:0/(format 4)
[Oct 6 09:47:46] DEBUG[5379]: chan_sip.c:16377 sip_set_rtp_peer: Sending reinvi
te on SIP '100f83c8-f6ff450a-13c4-4526182a-2270ea99-4526182a@10.69.255.246' - It
's audio soon redirected to IP 10.69.255.251

That is, I think Astx is putting the channel back to audio, with SDP pointing to itself - presumably to play a failure tone?

Aside: after this test I changed "udptl" to "UDPTL" in line 5774, so that the outbound INVITE has it in caps, but this doesn't seem to make a difference (and in any case, you can see the ATA is happy with the INVITE anyway in the above exchange)
By: Brian Candler (candlerb) 2006-10-06 04:27:48

One more note: I set one Tulip to make a direct SIP call to the other, bypassing Asterisk entirely, using the "speed dial" feature:

Speed Dial: 8404
Destination: Direct Call
User ID: tulip4
IP Address or Host Name: 10.69.255.242

T38 fax transmission works successfully. tcpdump shows some rather small UDP packets, rather than the 200 byte packets for G711 :-)

A tcpdump of the SIP exchange is attached as t38direct-tcpdump.txt
By: Brian Candler (candlerb) 2006-10-06 05:01:01

Minor observation: I believe there is a bug in line 5683 onwards, which prints "T38MaxFaxRate" instead of "T38MaxBitRate" in each case - but that only affects debugging output.

Now, one other thing I noticed from t38log3c.txt.gz; if you compare the t38 INVITE SDP as sent by the ATA:

v=0
o=rtp 1160124458839569000 160124458839569000 IN IP4 10.69.255.242
s=-
c=IN IP4 10.69.255.242
t=0 0
m=image 5004 UDPTL t38
a=T38FaxVersion:0
a=T38MaxBitRate:14400
a=T38FaxMaxBuffer:1024
a=T38FaxMaxDatagram:238
a=T38FaxRateManagement:transferredTCF
a=T38FaxUdpEC:t38UDPRedundancy

with the one proxied by Asterisk:

v=0
o=root 5371 5372 IN IP4 10.69.255.242
s=session
c=IN IP4 10.69.255.242
t=0 0
m=image 5004 udptl t38
a=T38FaxVersion:0
a=T38MaxBitRate:9600
a=T38FaxFillBitRemoval:0
a=T38FaxTranscodingMMR:0
a=T38FaxTranscodingJBIG:0
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:238
a=T38FaxMaxDatagram:238
a=T38FaxUdpEC:t38UDPRedundancy

you can see some differences. In particular T38MaxBitRate has changed from 14400 to 9600, and T38FaxMaxBuffer has changed from 1024 to 238

The logs say:
Our T38 capability (3840), peer T38 capability (3872), joint capability (3872)

(This would be much easier in hex, as 0xF00 and 0xF20 :-) which includes 9600 but not 12000 or 14400. I notice that global_t38_capability doesn't include speeds above 9600; not sure if that's related.

The T38FaxMaxBuffer generated by Asterisk looks to be nailed to the same as T38FaxMaxDatagram (i.e. both come from ast_udptl_get_local_max_datagram). I guess that's intentional?

But this is a minor aside. I don't think it explains the fundamental problem described above in notes (0052633) and (0052634) which is that the T.38 connection is dropped like a hot potato.

By: jmls (jmls) 2006-11-05 12:46:03.000-0600

is there anyone familiar with T38 who can shed some light on this and perhaps move it forward ? Thanks.
By: dea (dea) 2006-11-08 22:56:11.000-0600

The repeating invite issue is likely related to bugid 7501, which has
had a fix committed. A retest may be worthwhile.

The case issue is still present in SVN.

candlerb's post 0052634 might hold a clue. It looks like the
bridge_native_loop in rtp.c fails, as well it should since we
are trying to establish T38, but that failure triggers an immediate
re-invite, knocking us out of T38 setup.

Should sip_set_rtp_peer() be checking to see if we are in the middle
of setting up T38 and not re-invite if that is the case?

By: dea (dea) 2006-11-10 20:15:27.000-0600

Shameless bump. I attached a small patch to bug 7844 that I
think will solve this.

There has been one report of semi-success, where Asterisk
permitted the call to complete, but the fax was corrupted.
Since we are talking pass-through, I'm not ready to blame
Asterisk.

Candlerb, can you test that patch with the Sipuras?
By: Olle Johansson (oej) 2006-11-12 09:35:55.000-0600

I added support for UDPTL with upper case to 1.4 and trunk as well as some other T.38 changes. Please re-test as soon as possible - thank you!
By: Olle Johansson (oej) 2006-11-15 15:39:03.000-0600

Any feedback to me?
By: Brian Candler (candlerb) 2006-11-16 05:39:17.000-0600

Sorry my T38 test rig is currently dismantled, so I can't provide feedback right now.

(It was two Unix PCs + sendfax/mgetty + two faxmodems + two Tulip ATAs)
By: Joshua C. Colp (jcolp) 2006-11-21 13:20:35.000-0600

I'm going to suspend this for now since your test rig is dismantled and not available. If when you retest the problem still occurs then feel free to reopen this, or post to the other T.38 bugs that have developed. Peace and long live faxing! (please... no... just use PDFs...)
By: Tilghman Lesher (tilghman) 2007-09-26 14:34:37

Reopened, by request of De_Mon (via #asterisk-bugs)
By: Jon Webster (jon) 2007-09-26 15:26:44

Just ran into this bug myself, uploaded 20070926_debug.txt -- the debug 10, verbose 10 log of the call.
By: Jon Webster (jon) 2007-09-26 16:28:44

Ahh, apparently the packet I really wanted wasn't within the scope of the command: sip debug peer testphone

You can delete 20070926_debug.txt, look at this instead

pbx*CLI> sip debug ip 216.82.224.202
SIP Debugging Enabled for IP: 216.82.224.202
-- Executing [dial-15552937963@local:5] Set("SIP/testphone-0844ae70", "CALLERID(all)="Elephant Outlook" <+18638774177>") in new stack
-- Executing [dial-15552937963@local:6] Dial("SIP/testphone-0844ae70",
"SIP/bandwidth/+15552937963") in new stack Video is at 192.168.10.225 port 18900 Audio is at 192.168.10.225 port 12894 Adding codec 0x4 (ulaw) to SDP Adding codec 0x2 (gsm) to SDP Adding codec 0x80000 (h263) to SDP Adding non-codec 0x1 (telephone-event) to SDP Reliably Transmitting (no NAT) to 216.82.224.202:5060:
INVITE sip:+15552937963@216.82.224.202 SIP/2.0
Via: SIP/2.0/UDP 192.168.10.225:5060;branch=z9hG4bK7e490e03;rport
From: "Elephant Outlook" <sip:+18638774177@4.68.250.148>;tag=as0bcd3341
To: <sip:+15552937963@216.82.224.202>
Contact: <sip:+18638774177@192.168.10.225>
Call-ID: 047caabf60378e05225c67c25441df80@4.68.250.148
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Wed, 26 Sep 2007 21:43:02 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Type: application/sdp
Content-Length: 339

v=0
o=root 16400 16400 IN IP4 192.168.10.225 s=session c=IN IP4 192.168.10.225
b=CT:384
t=0 0
m=audio 12894 RTP/AVP 0 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
m=video 18900 RTP/AVP 34
a=rtpmap:34 H263/90000
a=sendrecv

---
-- Called bandwidth/+15552937963
<--- SIP read from 216.82.224.202:5060 ---> SIP/2.0 100 bandwidth.com has received your request
Via: SIP/2.0/UDP 192.168.10.225:5060;branch=z9hG4bK7e490e03;rport=5060
From: "Elephant Outlook" <sip:+18638774177@4.68.250.148>;tag=as0bcd3341
To: <sip:+15552937963@216.82.224.202>
Call-ID: 047caabf60378e05225c67c25441df80@4.68.250.148
CSeq: 102 INVITE
Server: Bandwidth.com TRM (bw7.gold.13)
Content-Length: 0

<------------->
--- (8 headers 0 lines) ---
pbx*CLI>
<--- SIP read from 216.82.224.202:5060 ---> SIP/2.0 183 Session Progress
v: SIP/2.0/UDP 192.168.10.225:5060;branch=z9hG4bK7e490e03;rport=5060
Record-Route:
<sip:216.82.224.202;lr;ftag=as0bcd3341;vsf=AAAAABMHCw4EDwMGAwZ3A24CFhgKGwIbARoJNDg->
P-Charging-Vector:icid-value=default~a187189b7133a7da19724dd436a55426;icid-generated-at=204.13.236.129;orig-ioi=default~;term-ioi=default~;Charge=sip%3A8638774177%404.68.250.148
From: "Elephant Outlook" <sip:+18638774177@4.68.250.148>;tag=as0bcd3341
t:
<sip:+15552937963@216.82.224.202>;tag=61bd0a692dcabf2a933b95ffd8f47375
i: 047caabf60378e05225c67c25441df80@4.68.250.148
CSeq: 102 INVITE
Server: DC-SIP/1.2
k: timer
m: <sip:5552937963@204.13.236.129:5060;transport=udp>
c: application/sdp
l: 290

v=0
o=- 194901 19490100 IN IP4 204.13.236.130
s=-
t=0 0
m=image 44742 udptl t38
c=IN IP4 204.13.236.130
a=T38FaxVersion:0
a=T38MaxBitRate:14400
a=T38FaxFillBitRemoval:0
a=T38FaxTranscodingMMR:0
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:200
=T38FaxMaxDatagram:72

<------------->
--- (13 headers 13 lines) ---
[Sep 26 17:43:04] WARNING[25857]: chan_sip.c:5017 process_sdp:
Unsupported SDP media type in offer: image 44742 udptl t38
-- SIP/bandwidth-084fecf8 is making progress passing it to SIP/testphone-0844ae70 Scheduling destruction of SIP dialog '047caabf60378e05225c67c25441df80@4.68.250.148' in 32000 ms (Method:
INVITE)
Reliably Transmitting (no NAT) to 216.82.224.202:5060:
CANCEL sip:+15552937963@216.82.224.202 SIP/2.0
Via: SIP/2.0/UDP 192.168.10.225:5060;branch=z9hG4bK7e490e03;rport
From: "Elephant Outlook" <sip:+18638774177@4.68.250.148>;tag=as0bcd3341
To: <sip:+15552937963@216.82.224.202>
Call-ID: 047caabf60378e05225c67c25441df80@4.68.250.148
CSeq: 102 CANCEL
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0

---
Scheduling destruction of SIP dialog
'047caabf60378e05225c67c25441df80@4.68.250.148' in 32000 ms (Method:
INVITE)
== Spawn extension (local, dial-15552937963, 6) exited non-zero on 'SIP/testphone-0844ae70'
Really destroying SIP dialog 'b01d298b-7082aaba-dd93fa81@192.168.2.21'
Method: ACK
pbx*CLI>
<--- SIP read from 216.82.224.202:5060 ---> SIP/2.0 200 canceling
Via: SIP/2.0/UDP 192.168.10.225:5060;branch=z9hG4bK7e490e03;rport=5060
From: "Elephant Outlook" <sip:+18638774177@4.68.250.148>;tag=as0bcd3341
To:
<sip:+15552937963@216.82.224.202>;tag=6c8d6b8eaf3981f68fb5449c71ab6dfd-392d
Call-ID: 047caabf60378e05225c67c25441df80@4.68.250.148
CSeq: 102 CANCEL
Server: Bandwidth.com TRM (bw7.gold.13)
Content-Length: 0

<------------->
--- (8 headers 0 lines) ---
pbx*CLI>
<--- SIP read from 216.82.224.202:5060 ---> SIP/2.0 487 Request Terminated
v: SIP/2.0/UDP 192.168.10.225:5060;branch=z9hG4bK7e490e03;rport=5060
Record-Route:
<sip:216.82.224.202;lr;ftag=as0bcd3341;vsf=AAAAABMHCw4EDwMGAwZ3A24CFhgKGwIbARoJNDg->
P-Charging-Vector:icid-value=default~a187189b7133a7da19724dd436a55426;icid-generated-at=204.13.236.129;orig-ioi=default~;term-ioi=default~;Charge=sip%3A8638774177%404.68.250.148
From: "Elephant Outlook" <sip:+18638774177@4.68.250.148>;tag=as0bcd3341
t:
<sip:+15552937963@216.82.224.202>;tag=61bd0a692dcabf2a933b95ffd8f47375
i: 047caabf60378e05225c67c25441df80@4.68.250.148
CSeq: 102 INVITE
Server: DC-SIP/1.2
k: timer
m: <sip:5552937963@204.13.236.129:5060;transport=udp>
l: 0

<------------->
--- (12 headers 0 lines) ---
Transmitting (no NAT) to 216.82.224.202:5060:
ACK sip:+15552937963@216.82.224.202 SIP/2.0
Via: SIP/2.0/UDP 192.168.10.225:5060;branch=z9hG4bK7e490e03;rport
From: "Elephant Outlook" <sip:+18638774177@4.68.250.148>;tag=as0bcd3341
To:
<sip:+15552937963@216.82.224.202>;tag=61bd0a692dcabf2a933b95ffd8f47375
Contact: <sip:+18638774177@192.168.10.225>
Call-ID: 047caabf60378e05225c67c25441df80@4.68.250.148
CSeq: 102 ACK
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0

---
Really destroying SIP dialog
'047caabf60378e05225c67c25441df80@4.68.250.148' Method: INVITE
pbx*CLI>

By: Jon Webster (jon) 2007-10-01 10:27:21

Here's some more info...

I'm trying to place a SIP call and expect the other end to answer with an audio stream (not fax).

sip.conf entries

[jon]
regexten=3149
callerid="Jon Webster" <3149>
secret=********
type=friend
host=dynamic
nat=yes
canreinvite=no
context=local
qualify=yes
call-limit=100
busy-limit=99

[bandwidth]
type=friend
host=216.82.224.202
fromdomain=4.68.250.148
insecure=port,invite
videosupport=yes
canreinvite=yes
qualify=no

call with core debug on didn't fit in note, find it in the attachment, t38debug3.txt

By: Tilghman Lesher (tilghman) 2007-10-26 13:00:07

jon: have you enabled t38pt_udptl in the general section of sip.conf?
By: Jon Webster (jon) 2007-10-26 13:07:03

t38pt_udptl is not set in my config.

For better or worse, I created ASTERISK-10602 for my issue. Unlike the current T38 bugs, my scenario is with t38 not set at all, and it broke the existing non-t38 config.

By: Tilghman Lesher (tilghman) 2007-10-28 08:31:34

jon: since you have another bug open on this, I'm going to re-suspend this one.