T.38 fax fails with no specific error

Asterisk Asterisk Fax
1

After fiddling around with sending any faxes, it now works for G.711. However, T.38 fails completely now. I am using Asterisk with pjsip, spandsp and res_fax.

> core show version
Asterisk 15.4.0 built by root @ fax3.mydomain.loc on a x86_64 running Linux on 2018-07-13 06:50:21 UTC

This is the error. Note that there is a long delay before the execution start and the error is thrown.

    -- Executing [faxout@fax_outgoing:6] SendFAX("PJSIP/sip-00000000", "/var/spool/asterisk/fax/loremipsum.tif,dfsz") in new stack
    -- Channel 'PJSIP/sip-00000000' sending FAX:
    --    /var/spool/asterisk/fax/loremipsum.tif
  == Spawn extension (fax_outgoing, faxout, 6) exited non-zero on 'PJSIP/sip_atms-00000000'
    -- Executing [h@fax_outgoing:1] NoOp("PJSIP/sip-00000000", "** Hung up **") in new stack

Searching the Internet reveals that this is a widespread problem obviously hardly one knows the answer to. Can someone please help me?

2

You haven’t provided the PJSIP configuration or a SIP trace for it (pjsip set logger on), those would be needed to see if anything is going on there.

As for “widespread” if it is then noone has reported such a thing. I only know of one PJSIP T.38 problem right now, which is the result of a remote SIP server and a very particular scenario.

3

Sure. That’s my pjsip config:

[simpletrans]
type=transport
protocol=udp
bind=0.0.0.0

[sip]
type=registration
outbound_auth=sip
transport=simpletrans
server_uri=sip:<myphonenr>@my.sipprovider.org:5060
client_uri=sip:<myphonenr>@my.sipprovider.org:5060

[sip]
type=auth
auth_type=userpass
password=MySecret
username=<myphonenr>

[sip]
type=aor
contact=sip:my.sipprovider.org:5060
 
[sip]
type=endpoint
context=from-external
disallow=all
allow=gsm
allow=alaw
allow=g722
outbound_auth=sip
aors=sip
rtp_symmetric=yes
force_rport=no
rewrite_contact=no
from_user=<myphonenr>
from_domain=my.sipprovider.org
t38_udptl=yes
t38_udptl_ec=redundancy
t38_udptl_maxdatagram=300
fax_detect=yes
direct_media=yes

[sip]
type=identify
endpoint=sip
match=my.sipprovider.org

and that’s the trace beginning from INVITE until hangup interleaved with the log- which IMHO is pretty empty.

<--- Transmitting SIP request (1317 bytes) to UDP:PROVIDER_IP_ADDR:5060 --->
INVITE sip:+DESTPHONENR@my.sipprovider.org SIP/2.0
Via: SIP/2.0/UDP 194.yyy.yyy.yyy:5060;rport;branch=z9hG4bKPj79d71a02-e452-4dda-ae16-9080537be481
From: <sip:MYPHONENR@my.sipprovider.org>;tag=518bf086-3d55-4445-a602-d571d43a5ad0
To: <sip:+DESTPHONENR@my.sipprovider.org>
Contact: <sip:MYPHONENR@194.yyy.yyy.yyy:5060>
Call-ID: 4d0c2054-b017-48ab-8033-2184c0ebc179
CSeq: 4084 INVITE
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Session-Expires: 1800
Min-SE: 90
Max-Forwards: 70
User-Agent: Asterisk PBX 15.4.0
Proxy-Authorization: Digest username="MYPHONENR", realm="my.sipprovider.org", nonce="346d0d1b0e55b0e23fb6f0feb7b58a9b", uri="sip:+DESTPHONENR@my.sipprovider.org", response="2078f0522ae97ebd0d13da17973784f2", algorithm=MD5, cnonce="3b255053-bb76-4909-83c1-361d00155ecd", opaque="b242c90595f30b81f69505e5bcd704b6", qop=auth, nc=00000001
Content-Type: application/sdp
Content-Length:   288

v=0
o=- 1262307033 1262307033 IN IP4 194.yyy.yyy.yyy
s=Asterisk
c=IN IP4 194.yyy.yyy.yyy
t=0 0
m=audio 15656 RTP/AVP 3 8 9 101
a=rtpmap:3 GSM/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

<--- Received SIP response (392 bytes) from UDP:PROVIDER_IP_ADDR:5060 --->
SIP/2.0 100 trying -- your call is important to us
Via: SIP/2.0/UDP 194.yyy.yyy.yyy:5060;rport=5060;branch=z9hG4bKPj79d71a02-e452-4dda-ae16-9080537be481;received=194.yyy.yyy.yyy
From: <sip:MYPHONENR@my.sipprovider.org>;tag=518bf086-3d55-4445-a602-d571d43a5ad0
To: <sip:+DESTPHONENR@my.sipprovider.org>
Call-ID: 4d0c2054-b017-48ab-8033-2184c0ebc179
CSeq: 4084 INVITE
Content-Length: 0


<--- Received SIP response (868 bytes) from UDP:PROVIDER_IP_ADDR:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 194.yyy.yyy.yyy:5060;received=194.yyy.yyy.yyy;branch=z9hG4bKPj79d71a02-e452-4dda-ae16-9080537be481;rport=5060
From: <sip:MYPHONENR@my.sipprovider.org>;tag=518bf086-3d55-4445-a602-d571d43a5ad0
To: <sip:+DESTPHONENR@my.sipprovider.org>;tag=YO!GWs34A-
Call-ID: 4d0c2054-b017-48ab-8033-2184c0ebc179
CSeq: 4084 INVITE
Supported: timer,x-diversion
Allow: INVITE,ACK,CANCEL,BYE,INFO,REGISTER,NOTIFY
Contact: <sip:192.168.46.66:5083>
Content-Length: 140
Content-Type: application/sdp
Record-Route: <sip:PROVIDER_IP_ADDR;lr;ftag=518bf086-3d55-4445-a602-d571d43a5ad0;x-rtpp=0>
User-Agent: TELES.C5/6.0.1.9
Allow-Events: talk
X-Call-ID: 4d0c2054-b017-48ab-8033-2184c0ebc179-UASession-0jpkNNaufV

v=0
o=- 199 2 IN IP4 PROVIDER_IP_ADDR
s=TELES-SBC
c=IN IP4 PROVIDER_IP_ADDR
t=0 0
m=audio 50490 RTP/AVP 8
a=rtpmap:8 PCMA/8000
a=ptime:20

       > 0x7f62bc0482f0 -- Strict RTP learning after remote address set to: PROVIDER_IP_ADDR:50490
<--- Transmitting SIP request (492 bytes) to UDP:PROVIDER_IP_ADDR:5060 --->
ACK sip:192.168.46.66:5083 SIP/2.0
Via: SIP/2.0/UDP 194.yyy.yyy.yyy:5060;rport;branch=z9hG4bKPj6f1591c4-4150-4aaf-b2bb-e68ddadf4b91
From: <sip:MYPHONENR@my.sipprovider.org>;tag=518bf086-3d55-4445-a602-d571d43a5ad0
To: <sip:+DESTPHONENR@my.sipprovider.org>;tag=YO!GWs34A-
Call-ID: 4d0c2054-b017-48ab-8033-2184c0ebc179
CSeq: 4084 ACK
Route: <sip:PROVIDER_IP_ADDR;lr;ftag=518bf086-3d55-4445-a602-d571d43a5ad0;x-rtpp=0>
Max-Forwards: 70
User-Agent: Asterisk PBX 15.4.0
Content-Length:  0


    -- PJSIP/sip-00000001 answered
    -- Executing [faxout@fax_outgoing:1] NoOp("PJSIP/sip-00000001", "**** SENDING FAX ****") in new stack
    -- Executing [faxout@fax_outgoing:2] Set("PJSIP/sip-00000001", "FAXFILE=loremipsum.tif") in new stack
    -- Executing [faxout@fax_outgoing:5] SendFAX("PJSIP/sip-00000001", "/var/spool/asterisk/fax/loremipsum.tif,dfsz") in new stack
    -- Channel 'PJSIP/sip-00000001' sending FAX:
    --    /var/spool/asterisk/fax/loremipsum.tif
<--- Received SIP request (899 bytes) from UDP:PROVIDER_IP_ADDR:5060 --->
INVITE sip:MYPHONENR@194.yyy.yyy.yyy:5060 SIP/2.0
Record-Route: <sip:PROVIDER_IP_ADDR;lr;ftag=518bf086-3d55-4445-a602-d571d43a5ad0;x-rtpp=0>
Via: SIP/2.0/UDP PROVIDER_IP_ADDR;branch=z9hG4bKf952.41a694637eb4bc40d3adfaaa1ac26d07.0
Via: SIP/2.0/UDP 192.168.46.66:5083;branch=z9hG4bKdt9QEd2wq!
From: <sip:+DESTPHONENR@my.sipprovider.org>;tag=YO!GWs34A-
To: "MYPHONENR" <sip:MYPHONENR@my.sipprovider.org>;tag=518bf086-3d55-4445-a602-d571d43a5ad0
Call-ID: 4d0c2054-b017-48ab-8033-2184c0ebc179
CSeq: 1 INVITE
Max-Forwards: 68
Supported: timer
Contact: <sip:192.168.46.66:5083>
Content-Length: 268
Content-Type: application/sdp

v=0
o=- 199 3 IN IP4 PROVIDER_IP_ADDR
s=TELES-SBC
c=IN IP4 PROVIDER_IP_ADDR
t=0 0
m=image 50492 udptl t38
a=T38FaxVersion:0
a=T38FaxUdpEC:t38UDPRedundancy
a=T38FaxRateManagement:transferredTCF
a=T38MaxBitRate:14400
a=T38FaxMaxBuffer:4000
a=T38FaxMaxDatagram:948

<--- Received SIP request (899 bytes) from UDP:PROVIDER_IP_ADDR:5060 --->
INVITE sip:MYPHONENR@194.yyy.yyy.yyy:5060 SIP/2.0
Record-Route: <sip:PROVIDER_IP_ADDR;lr;ftag=518bf086-3d55-4445-a602-d571d43a5ad0;x-rtpp=0>
Via: SIP/2.0/UDP PROVIDER_IP_ADDR;branch=z9hG4bKf952.41a694637eb4bc40d3adfaaa1ac26d07.0
Via: SIP/2.0/UDP 192.168.46.66:5083;branch=z9hG4bKdt9QEd2wq!
From: <sip:+DESTPHONENR@my.sipprovider.org>;tag=YO!GWs34A-
To: "MYPHONENR" <sip:MYPHONENR@my.sipprovider.org>;tag=518bf086-3d55-4445-a602-d571d43a5ad0
Call-ID: 4d0c2054-b017-48ab-8033-2184c0ebc179
CSeq: 1 INVITE
Max-Forwards: 68
Supported: timer
Contact: <sip:192.168.46.66:5083>
Content-Length: 268
Content-Type: application/sdp

v=0
o=- 199 3 IN IP4 PROVIDER_IP_ADDR
s=TELES-SBC
c=IN IP4 PROVIDER_IP_ADDR
t=0 0
m=image 50492 udptl t38
a=T38FaxVersion:0
a=T38FaxUdpEC:t38UDPRedundancy
a=T38FaxRateManagement:transferredTCF
a=T38MaxBitRate:14400
a=T38FaxMaxBuffer:4000
a=T38FaxMaxDatagram:948

<--- Transmitting SIP response (1045 bytes) to UDP:PROVIDER_IP_ADDR:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP PROVIDER_IP_ADDR;received=PROVIDER_IP_ADDR;branch=z9hG4bKf952.41a694637eb4bc40d3adfaaa1ac26d07.0
Via: SIP/2.0/UDP 192.168.46.66:5083;branch=z9hG4bKdt9QEd2wq!
Record-Route: <sip:PROVIDER_IP_ADDR;lr;ftag=518bf086-3d55-4445-a602-d571d43a5ad0;x-rtpp=0>
Call-ID: 4d0c2054-b017-48ab-8033-2184c0ebc179
From: <sip:+DESTPHONENR@my.sipprovider.org>;tag=YO!GWs34A-
To: "MYPHONENR" <sip:MYPHONENR@my.sipprovider.org>;tag=518bf086-3d55-4445-a602-d571d43a5ad0
CSeq: 1 INVITE
Contact: <sip:MYPHONENR@194.yyy.yyy.yyy:5060>
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Server: Asterisk PBX 15.4.0
Content-Type: application/sdp
Content-Length:   261

v=0
o=- 1262307033 1262307034 IN IP4 194.yyy.yyy.yyy
s=Asterisk
c=IN IP4 194.yyy.yyy.yyy
t=0 0
m=image 4559 udptl t38
a=T38FaxVersion:0
a=T38MaxBitRate:14400
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxDatagram:1400
a=T38FaxUdpEC:t38UDPRedundancy

<--- Received SIP request (473 bytes) from UDP:PROVIDER_IP_ADDR:5060 --->
ACK sip:MYPHONENR@194.yyy.yyy.yyy:5060 SIP/2.0
Via: SIP/2.0/UDP PROVIDER_IP_ADDR;branch=z9hG4bKf952.39486e358b1810765137030eb98a4d03.0
Via: SIP/2.0/UDP 192.168.46.66:5083;branch=z9hG4bKcrbKYYmU9E
From: <sip:+DESTPHONENR@my.sipprovider.org>;tag=YO!GWs34A-
To:  <sip:MYPHONENR@my.sipprovider.org>;tag=518bf086-3d55-4445-a602-d571d43a5ad0
Call-ID: 4d0c2054-b017-48ab-8033-2184c0ebc179
CSeq: 1 ACK
Max-Forwards: 68
Contact: <sip:192.168.46.66:5083>
Content-Length: 0


<--- Received SIP request (303 bytes) from UDP:PROVIDER_IP_ADDR:5060 --->
OPTIONS sip:s@194.yyy.yyy.yyy:5060 SIP/2.0
Via: SIP/2.0/UDP PROVIDER_IP_ADDR:5060;branch=z9hG4bK8587287
From: sip:hello@nat.refresh.local;tag=uloc-51-5b4d3c11-219e-4b41-38a4efc3-a7ee5634
To: sip:s@194.yyy.yyy.yyy:5060
Call-ID: 179ce531-477c85f2-b9de932@PROVIDER_IP_ADDR
CSeq: 1 OPTIONS
Content-Length: 0


<--- Transmitting SIP response (840 bytes) to UDP:PROVIDER_IP_ADDR:5060 --->
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP PROVIDER_IP_ADDR:5060;received=PROVIDER_IP_ADDR;branch=z9hG4bK8587287
Call-ID: 179ce531-477c85f2-b9de932@PROVIDER_IP_ADDR
From: <sip:hello@nat.refresh.local>;tag=uloc-51-5b4d3c11-219e-4b41-38a4efc3-a7ee5634
To: <sip:s@194.yyy.yyy.yyy>;tag=z9hG4bK8587287
CSeq: 1 OPTIONS
Accept: application/sdp, application/dialog-info+xml, application/pidf+xml, application/simple-message-summary, application/xpidf+xml, application/cpim-pidf+xml, application/pidf+xml, application/dialog-info+xml, application/simple-message-summary, message/sipfrag;version=2.0
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Accept-Encoding: text/plain
Accept-Language: en
Server: Asterisk PBX 15.4.0
Content-Length:  0


<--- Received SIP request (303 bytes) from UDP:PROVIDER_IP_ADDR:5060 --->
OPTIONS sip:s@194.yyy.yyy.yyy:5060 SIP/2.0
Via: SIP/2.0/UDP PROVIDER_IP_ADDR:5060;branch=z9hG4bK1139965
From: sip:hello@nat.refresh.local;tag=uloc-51-5b4d3c11-219e-4b41-38a4efc3-edfe5634
To: sip:s@194.yyy.yyy.yyy:5060
Call-ID: 179ce531-8d8c85f2-fade932@PROVIDER_IP_ADDR
CSeq: 1 OPTIONS
Content-Length: 0


<--- Transmitting SIP response (840 bytes) to UDP:PROVIDER_IP_ADDR:5060 --->
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP PROVIDER_IP_ADDR:5060;received=PROVIDER_IP_ADDR;branch=z9hG4bK1139965
Call-ID: 179ce531-8d8c85f2-fade932@PROVIDER_IP_ADDR
From: <sip:hello@nat.refresh.local>;tag=uloc-51-5b4d3c11-219e-4b41-38a4efc3-edfe5634
To: <sip:s@194.yyy.yyy.yyy>;tag=z9hG4bK1139965
CSeq: 1 OPTIONS
Accept: application/sdp, application/dialog-info+xml, application/pidf+xml, application/simple-message-summary, application/xpidf+xml, application/cpim-pidf+xml, application/pidf+xml, application/dialog-info+xml, application/simple-message-summary, message/sipfrag;version=2.0
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Accept-Encoding: text/plain
Accept-Language: en
Server: Asterisk PBX 15.4.0
Content-Length:  0


<--- Received SIP request (303 bytes) from UDP:PROVIDER_IP_ADDR:5060 --->
OPTIONS sip:s@194.yyy.yyy.yyy:5060 SIP/2.0
Via: SIP/2.0/UDP PROVIDER_IP_ADDR:5060;branch=z9hG4bK4581742
From: sip:hello@nat.refresh.local;tag=uloc-51-5b4d3c11-219e-4b41-38a4efc3-241f5634
To: sip:s@194.yyy.yyy.yyy:5060
Call-ID: 179ce531-c3ac85f2-3cde932@PROVIDER_IP_ADDR
CSeq: 1 OPTIONS
Content-Length: 0


<--- Transmitting SIP response (840 bytes) to UDP:PROVIDER_IP_ADDR:5060 --->
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP PROVIDER_IP_ADDR:5060;received=PROVIDER_IP_ADDR;branch=z9hG4bK4581742
Call-ID: 179ce531-c3ac85f2-3cde932@PROVIDER_IP_ADDR
From: <sip:hello@nat.refresh.local>;tag=uloc-51-5b4d3c11-219e-4b41-38a4efc3-241f5634
To: <sip:s@194.yyy.yyy.yyy>;tag=z9hG4bK4581742
CSeq: 1 OPTIONS
Accept: application/sdp, application/dialog-info+xml, application/pidf+xml, application/simple-message-summary, application/xpidf+xml, application/cpim-pidf+xml, application/pidf+xml, application/dialog-info+xml, application/simple-message-summary, message/sipfrag;version=2.0
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Accept-Encoding: text/plain
Accept-Language: en
Server: Asterisk PBX 15.4.0
Content-Length:  0


<--- Received SIP request (523 bytes) from UDP:PROVIDER_IP_ADDR:5060 --->
BYE sip:MYPHONENR@194.yyy.yyy.yyy:5060 SIP/2.0
Via: SIP/2.0/UDP PROVIDER_IP_ADDR;branch=z9hG4bKc952.397ba1de87274080b0e8dc7ed3bf28fc.0
Via: SIP/2.0/UDP 192.168.46.66:5083;branch=z9hG4bKVrBDuXezEk
From: <sip:+DESTPHONENR@my.sipprovider.org>;tag=YO!GWs34A-
To:  <sip:MYPHONENR@my.sipprovider.org>;tag=518bf086-3d55-4445-a602-d571d43a5ad0
Call-ID: 4d0c2054-b017-48ab-8033-2184c0ebc179
CSeq: 2 BYE
Max-Forwards: 69
Contact: <sip:192.168.46.66:5083>
Content-Length: 0
Reason: Q.850;cause=18;text="No user responding"


<--- Transmitting SIP response (438 bytes) to UDP:PROVIDER_IP_ADDR:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP PROVIDER_IP_ADDR;received=PROVIDER_IP_ADDR;branch=z9hG4bKc952.397ba1de87274080b0e8dc7ed3bf28fc.0
Via: SIP/2.0/UDP 192.168.46.66:5083;branch=z9hG4bKVrBDuXezEk
Call-ID: 4d0c2054-b017-48ab-8033-2184c0ebc179
From: <sip:+DESTPHONENR@my.sipprovider.org>;tag=YO!GWs34A-
To: <sip:MYPHONENR@my.sipprovider.org>;tag=518bf086-3d55-4445-a602-d571d43a5ad0
CSeq: 2 BYE
Server: Asterisk PBX 15.4.0
Content-Length:  0


  == Spawn extension (fax_outgoing, faxout, 5) exited non-zero on 'PJSIP/sip-00000001'
    -- Executing [h@fax_outgoing:1] NoOp("PJSIP/sip-00000001", "** Hung up **") in new stack
4

It looks as though T.38 was negotiated, but the remote side ended up terminating the call due to “Reason: Q.850;cause=18;text=“No user responding””. You’ll need to provide “udptl set debug on” or a packet capture to see if the traffic is flowing.

5

With UDPTL debugging on, it becomes obvious that no packets flow.

6

I’m not familiar with the lower levels of spandsp (it is what generates the T.38 traffic) so I’m not sure where to dig into there.

7

Thanks so far. Are there any other configuration files I have to watch out for? I do not find any for spandsp as such. Also note that this fax call is initiated by a callfile which runs the dialplan, so Asterisk is in the role of an endpoint, not in passthrough mode.

8

There’s no other configuration as far as I’m aware.