ASTERISK-15566: app_fax doesn't receive fax with T.38

[Home]

Summary: ASTERISK-15566: app_fax doesn't receive fax with T.38

Reporter: viniciusfontes (viniciusfontes) Labels:

Date Opened: 2010-02-02 13:56:25.000-0600 Date Closed: 2011-06-07 14:01:07

Priority: Major Regression? No

Status: Closed/Complete Components: Applications/app_fax

Versions: Frequency of
Occurrence

Related
Issues:

Environment: Attachments: ( 0) app_fax_debug_analog_landline.txt.gz
( 1) app_fax_debug.txt.gz
( 2) capture.wshark.zip
( 3) cli-debug-maxdatagramsize.txt
( 4) segfault-gdb.txt
( 5) segfault-gdb-notoptimized.txt

Description: When I try to receive a fax from a provider that supports T.38 using ReceiveFAX() provided by app_fax.so, the fax transmission ends prematurely with an error.

What happens (according to Kevin Fleming) is this:

"In this call, Asterisk sent a re-INVITE to T.38 mode
from audio mode, the provider accepted it, and then Asterisk
acknowledged it. Immediately afterwards, Asterisk sent a re-INVITE
*back* to audio mode, which the provider accepted (and included T.38
capabilities in their response). Because of this, the FAX reception
process failed since the T.38 session was destroyed."

For reference, here is a link to the original mailing list thread: http://lists.digium.com/pipermail/asterisk-users/2010-February/244136.html

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

Here's the entire call trace, and if this is too hard to read, here's the pastebin link: http://pastebin.com/m7467cea1

[Feb 2 14:42:13]
<--- SIP read from UDP://10.150.65.16:5060 --->
INVITE sip:5421047008@10.153.66.146:5060;transport=UDP;user=phone SIP/2.0
f: <sip:5433142499@10.150.65.16:5060;user=phone>;tag=c4-45026-46a0e9-51b1091a-46a0e9
t: <sip:5421047008@10.153.66.146:5060;user=phone>
i: a703afa81041960a13c446a0e913e48e6094541f8fbd08698-0322-4807
CSeq: 1 INVITE
User-agent: CS2000_NGSS/9.0
P-Asserted-Identity: <sip:5433142499@10.150.65.16;user=phone>
Allow: ACK,BYE,CANCEL,INVITE,OPTIONS,INFO,SUBSCRIBE,REFER,NOTIFY,PRACK
v: SIP/2.0/UDP PAE1CS2K:5060;maddr=10.150.65.16;branch=z9hG4bK-46a0e9-13e48f8a-7e260b64
Max-Forwards: 70
m: <sip:10.150.65.16:5060;transport=UDP>
k: 100rel
c: application/sdp
l: 416

v=0
o=PVG 1265128846300 1265128846300 IN IP4 10.152.0.164
s=-
p=+1 6135555555
c=IN IP4 10.152.0.164
t=0 0
m=audio 57198 RTP/AVP 18 8 101
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=fmtp:18 annexb=no
m=image 65390 udptl t38
a=T38FaxVersion:0
a=T38FaxMaxBuffer:1100
a=T38FaxMaxDatagram:612
a=T38MaxBitRate:14400
a=T38FaxRateManagement:transferredTCF
a=T38FaxUdpEC:t38UDPRedundancy

<------------->
[Feb 2 14:42:13] --- (14 headers 18 lines) ---
[Feb 2 14:42:13] == Using SIP RTP TOS bits 184
[Feb 2 14:42:13] == Using SIP RTP CoS mark 5
[Feb 2 14:42:13] == Using SIP VRTP TOS bits 136
[Feb 2 14:42:13] == Using SIP VRTP CoS mark 6
[Feb 2 14:42:13] == Using UDPTL TOS bits 184
[Feb 2 14:42:13] == Using UDPTL CoS mark 5
[Feb 2 14:42:13] Sending to 10.150.65.16 : 5060 (NAT)
[Feb 2 14:42:13] Using INVITE request as basis request - a703afa81041960a13c446a0e913e48e6094541f8fbd08698-0322-4807
[Feb 2 14:42:13] Found peer 'voxip' for '5433142499' from 10.150.65.16:5060
[Feb 2 14:42:13] Found RTP audio format 18
[Feb 2 14:42:13] Found RTP audio format 8
[Feb 2 14:42:13] Found RTP audio format 101
[Feb 2 14:42:13] Found audio description format telephone-event for ID 101
[Feb 2 14:42:13] Got T.38 offer in SDP in dialog a703afa81041960a13c446a0e913e48e6094541f8fbd08698-0322-4807
[Feb 2 14:42:13] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x108 (alaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x8 (alaw)
[Feb 2 14:42:13] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Feb 2 14:42:13] Peer audio RTP is at port 10.152.0.164:57198
[Feb 2 14:42:13] Looking for 5421047008 in entrada-e1 (domain 10.153.66.146)
[Feb 2 14:42:13] list_route: hop: <sip:10.150.65.16:5060;transport=UDP>
[Feb 2 14:42:13]
<--- Transmitting (no NAT) to 10.150.65.16:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP PAE1CS2K:5060;maddr=10.150.65.16;branch=z9hG4bK-46a0e9-13e48f8a-7e260b64;received=10.150.65.16
From: <sip:5433142499@10.150.65.16:5060;user=phone>;tag=c4-45026-46a0e9-51b1091a-46a0e9
To: <sip:5421047008@10.153.66.146:5060;user=phone>
Call-ID: a703afa81041960a13c446a0e913e48e6094541f8fbd08698-0322-4807
CSeq: 1 INVITE
Server: Asterisk PBX 1.6.1.13
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Contact: <sip:5421047008@10.153.66.146>
Content-Length: 0

<------------>
[Feb 2 14:42:13] -- Executing [5421047008@entrada-e1:1] Goto("SIP/voxip-00000109", "interno,7008,1") in new stack
[Feb 2 14:42:13] -- Goto (interno,7008,1)
[Feb 2 14:42:13] -- Executing [7008@interno:1] Goto("SIP/voxip-00000109", "macro-recebefax,s,1") in new stack
[Feb 2 14:42:13] -- Goto (macro-recebefax,s,1)
[Feb 2 14:42:13] -- Executing [s@macro-recebefax:1] Set("SIP/voxip-00000109", "DB(fax/count)=48") in new stack
[Feb 2 14:42:13] -- Executing [s@macro-recebefax:2] Set("SIP/voxip-00000109", "FAXCOUNT=48") in new stack
[Feb 2 14:42:13] -- Executing [s@macro-recebefax:3] Set("SIP/voxip-00000109", "FAXFILE=fax-48-rx") in new stack
[Feb 2 14:42:13] -- Executing [s@macro-recebefax:4] Answer("SIP/voxip-00000109", "") in new stack
[Feb 2 14:42:13] Audio is at 10.153.66.146 port 17336
[Feb 2 14:42:13] Adding codec 0x8 (alaw) to SDP
[Feb 2 14:42:13] Adding non-codec 0x1 (telephone-event) to SDP
[Feb 2 14:42:13]
<--- Reliably Transmitting (no NAT) to 10.150.65.16:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP PAE1CS2K:5060;maddr=10.150.65.16;branch=z9hG4bK-46a0e9-13e48f8a-7e260b64;received=10.150.65.16
From: <sip:5433142499@10.150.65.16:5060;user=phone>;tag=c4-45026-46a0e9-51b1091a-46a0e9
To: <sip:5421047008@10.153.66.146:5060;user=phone>;tag=as53a14c9a
Call-ID: a703afa81041960a13c446a0e913e48e6094541f8fbd08698-0322-4807
CSeq: 1 INVITE
Server: Asterisk PBX 1.6.1.13
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Contact: <sip:5421047008@10.153.66.146>
Content-Type: application/sdp
Content-Length: 235

v=0
o=root 44350963 44350963 IN IP4 10.153.66.146
s=Asterisk PBX 1.6.1.13
c=IN IP4 10.153.66.146
t=0 0
m=audio 17336 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
m=image 0 udptl t38

<------------>
[Feb 2 14:42:13]
<--- SIP read from UDP://10.150.65.16:5060 --->
ACK sip:5421047008@10.153.66.146 SIP/2.0
f: <sip:5433142499@10.150.65.16:5060;user=phone>;tag=c4-45026-46a0e9-51b1091a-46a0e9
To: <sip:5421047008@10.153.66.146:5060;user=phone>;tag=as53a14c9a
i: a703afa81041960a13c446a0e913e48e6094541f8fbd08698-0322-4807
CSeq: 1 ACK
User-agent: CS2000_NGSS/9.0
Max-Forwards: 70
Allow: ACK,BYE,CANCEL,INVITE,OPTIONS,INFO,SUBSCRIBE,REFER,NOTIFY,PRACK
v: SIP/2.0/UDP PAE1CS2K:5060;maddr=10.150.65.16;branch=z9hG4bK-46a0e9-13e48fb5-6319e822
m: <sip:10.150.65.16:5060;transport=UDP>
k: 100rel
l: 0

<------------->
[Feb 2 14:42:13] --- (12 headers 0 lines) ---
[Feb 2 14:42:13] -- Executing [s@macro-recebefax:5] Wait("SIP/voxip-00000109", "3") in new stack
[Feb 2 14:42:15] NOTICE[3980]: chan_sip.c:20366 handle_request_subscribe: Received SIP subscribe for peer without mailbox: 7017
[Feb 2 14:42:16] -- Executing [s@macro-recebefax:6] ReceiveFAX("SIP/voxip-00000109", "/var/spool/asterisk/fax/fax-48-rx.tif,d") in new stack
[Feb 2 14:42:16] set_destination: Parsing <sip:10.150.65.16:5060;transport=UDP> for address/port to send to
[Feb 2 14:42:16] set_destination: set destination to 10.150.65.16, port 5060
[Feb 2 14:42:16] Reliably Transmitting (no NAT) to 10.150.65.16:5060:
INVITE sip:10.150.65.16:5060;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.153.66.146:5060;branch=z9hG4bK0ee41ce2;rport
Max-Forwards: 70
From: <sip:5421047008@10.153.66.146:5060;user=phone>;tag=as53a14c9a
To: <sip:5433142499@10.150.65.16:5060;user=phone>;tag=c4-45026-46a0e9-51b1091a-46a0e9
Contact: <sip:5421047008@10.153.66.146>
Call-ID: a703afa81041960a13c446a0e913e48e6094541f8fbd08698-0322-4807
CSeq: 102 INVITE
User-Agent: Asterisk PBX 1.6.1.13
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
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

---
[Feb 2 14:42:16]
<--- SIP read from UDP://10.150.65.16:5060 --->
SIP/2.0 100 Trying
From: <sip:5421047008@10.153.66.146:5060;user=phone>;tag=as53a14c9a
t: <sip:5433142499@10.150.65.16:5060;user=phone>;tag=c4-45026-46a0e9-51b1091a-46a0e9
Call-ID: a703afa81041960a13c446a0e913e48e6094541f8fbd08698-0322-4807
CSeq: 102 INVITE
Server: CS2000_NGSS/9.0
k: 100rel
Allow: ACK,BYE,CANCEL,INVITE,OPTIONS,INFO,SUBSCRIBE,REFER,NOTIFY,PRACK
Via: SIP/2.0/UDP 10.153.66.146:5060;rport=5060;branch=z9hG4bK0ee41ce2
ontact: <sip:10.150.65.16:5060;transport=UDP>
Content-Length: 0

<------------->
[Feb 2 14:42:16] --- (11 headers 0 lines) ---
[Feb 2 14:42:16]
<--- SIP read from UDP://10.150.65.16:5060 --->
SIP/2.0 200 OK
From: <sip:5421047008@10.153.66.146:5060;user=phone>;tag=as53a14c9a
t: <sip:5433142499@10.150.65.16:5060;user=phone>;tag=c4-45026-46a0e9-51b1091a-46a0e9
Call-ID: a703afa81041960a13c446a0e913e48e6094541f8fbd08698-0322-4807
CSeq: 102 INVITE
Server: CS2000_NGSS/9.0
k: 100rel
Allow: ACK,BYE,CANCEL,INVITE,OPTIONS,INFO,SUBSCRIBE,REFER,NOTIFY,PRACK
Via: SIP/2.0/UDP 10.153.66.146:5060;rport=5060;branch=z9hG4bK0ee41ce2
Contact: <sip:10.150.65.16:5060;transport=UDP>
c: application/sdp
Content-Length: 299

v=0
o=PVG 1265128849830 1265128849830 IN IP4 10.152.0.164
s=-
p=+1 6135555555
c=IN IP4 10.152.0.164
t=0 0
m=image 65390 udptl t38
a=T38FaxVersion:0
a=T38FaxMaxBuffer:1100
a=T38FaxMaxDatagram:612
a=T38MaxBitRate:14400
a=T38FaxRateManagement:transferredTCF
a=T38FaxUdpEC:t38UDPRedundancy

<------------->
[Feb 2 14:42:16] --- (12 headers 13 lines) ---
[Feb 2 14:42:16] Got T.38 offer in SDP in dialog a703afa81041960a13c446a0e913e48e6094541f8fbd08698-0322-4807
[Feb 2 14:42:16] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x0 (nothing)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x0 (nothing)
[Feb 2 14:42:16] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing)
[Feb 2 14:42:16] Got T.38 Re-invite without audio. Keeping RTP active during T.38 session.
[Feb 2 14:42:16] set_destination: Parsing <sip:10.150.65.16:5060;transport=UDP> for address/port to send to
[Feb 2 14:42:16] set_destination: set destination to 10.150.65.16, port 5060
[Feb 2 14:42:16] Transmitting (no NAT) to 10.150.65.16:5060:
ACK sip:10.150.65.16:5060;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.153.66.146:5060;branch=z9hG4bK7d576e01;rport
Max-Forwards: 70
From: <sip:5421047008@10.153.66.146:5060;user=phone>;tag=as53a14c9a
To: <sip:5433142499@10.150.65.16:5060;user=phone>;tag=c4-45026-46a0e9-51b1091a-46a0e9
Contact: <sip:5421047008@10.153.66.146>
Call-ID: a703afa81041960a13c446a0e913e48e6094541f8fbd08698-0322-4807
CSeq: 102 ACK
User-Agent: Asterisk PBX 1.6.1.13
Content-Length: 0

---
[Feb 2 14:42:24] NOTICE[3980]: chan_sip.c:11888 check_auth: Correct auth, but based on stale nonce received from '<sip:7019@pabx.canall.com.br;transport=UDP>'
[Feb 2 14:42:25] NOTICE[3980]: chan_sip.c:11888 check_auth: Correct auth, but based on stale nonce received from '<sip:7019@pabx.canall.com.br;transport=UDP>'
[Feb 2 14:42:27] NOTICE[3980]: chan_sip.c:11888 check_auth: Correct auth, but based on stale nonce received from '<sip:7019@pabx.canall.com.br;transport=UDP>'
[Feb 2 14:42:31] NOTICE[3980]: chan_sip.c:11888 check_auth: Correct auth, but based on stale nonce received from '<sip:7019@pabx.canall.com.br;transport=UDP>'
[Feb 2 14:42:35] NOTICE[3980]: chan_sip.c:11888 check_auth: Correct auth, but based on stale nonce received from '<sip:7019@pabx.canall.com.br;transport=UDP>'
[Feb 2 14:42:36] WARNING[7880]: app_fax.c:178 phase_e_handler: Error transmitting fax. result=13: Unexpected message received.
[Feb 2 14:42:36] set_destination: Parsing <sip:10.150.65.16:5060;transport=UDP> for address/port to send to
[Feb 2 14:42:36] set_destination: set destination to 10.150.65.16, port 5060
[Feb 2 14:42:36] Audio is at 10.153.66.146 port 17336
[Feb 2 14:42:36] Adding codec 0x8 (alaw) to SDP
[Feb 2 14:42:36] Adding non-codec 0x1 (telephone-event) to SDP
[Feb 2 14:42:36] Reliably Transmitting (no NAT) to 10.150.65.16:5060:
INVITE sip:10.150.65.16:5060;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.153.66.146:5060;branch=z9hG4bK690f821b;rport
Max-Forwards: 70
From: <sip:5421047008@10.153.66.146:5060;user=phone>;tag=as53a14c9a
To: <sip:5433142499@10.150.65.16:5060;user=phone>;tag=c4-45026-46a0e9-51b1091a-46a0e9
Contact: <sip:5421047008@10.153.66.146>
Call-ID: a703afa81041960a13c446a0e913e48e6094541f8fbd08698-0322-4807
CSeq: 103 INVITE
User-Agent: Asterisk PBX 1.6.1.13
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
X-asterisk-Info: SIP re-invite (External RTP bridge)
Content-Type: application/sdp
Content-Length: 235

v=0
o=root 44350963 44350965 IN IP4 10.153.66.146
s=Asterisk PBX 1.6.1.13
c=IN IP4 10.153.66.146
t=0 0
m=audio 17336 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

---
[Feb 2 14:42:36]
<--- SIP read from UDP://10.150.65.16:5060 --->
SIP/2.0 100 Trying
From: <sip:5421047008@10.153.66.146:5060;user=phone>;tag=as53a14c9a
t: <sip:5433142499@10.150.65.16:5060;user=phone>;tag=c4-45026-46a0e9-51b1091a-46a0e9
Call-ID: a703afa81041960a13c446a0e913e48e6094541f8fbd08698-0322-4807
CSeq: 103 INVITE
Server: CS2000_NGSS/9.0
k: 100rel
Allow: ACK,BYE,CANCEL,INVITE,OPTIONS,INFO,SUBSCRIBE,REFER,NOTIFY,PRACK
Via: SIP/2.0/UDP 10.153.66.146:5060;rport=5060;branch=z9hG4bK690f821b
ontact: <sip:10.150.65.16:5060;transport=UDP>
Content-Length: 0

<------------->
[Feb 2 14:42:36] --- (11 headers 0 lines) ---
[Feb 2 14:42:36]
<--- SIP read from UDP://10.150.65.16:5060 --->
SIP/2.0 200 OK
From: <sip:5421047008@10.153.66.146:5060;user=phone>;tag=as53a14c9a
t: <sip:5433142499@10.150.65.16:5060;user=phone>;tag=c4-45026-46a0e9-51b1091a-46a0e9
Call-ID: a703afa81041960a13c446a0e913e48e6094541f8fbd08698-0322-4807
CSeq: 103 INVITE
Server: CS2000_NGSS/9.0
k: 100rel
Allow: ACK,BYE,CANCEL,INVITE,OPTIONS,INFO,SUBSCRIBE,REFER,NOTIFY,PRACK
Via: SIP/2.0/UDP 10.153.66.146:5060;rport=5060;branch=z9hG4bK690f821b
Contact: <sip:10.150.65.16:5060;transport=UDP>
c: application/sdp
Content-Length: 309

v=0
o=PVG 1265128870330 1265128870330 IN IP4 10.152.0.164
s=-
p=+1 6135555555
c=IN IP4 10.152.0.164
t=0 0
a=sqn: 0
a=cdsc: 1 image udptl t38
a=cpar: a=T38FaxVersion:0
a=cpar: a=T38FaxUdpEC:t38UDPRedundancy
m=audio 57198 RTP/AVP 8 101
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

<------------->
[Feb 2 14:42:36] --- (12 headers 14 lines) ---
[Feb 2 14:42:36] Found RTP audio format 8
[Feb 2 14:42:36] Found RTP audio format 101
[Feb 2 14:42:36] Found audio description format telephone-event for ID 101
[Feb 2 14:42:36] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x8 (alaw)
[Feb 2 14:42:36] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Feb 2 14:42:36] Peer audio RTP is at port 10.152.0.164:57198
[Feb 2 14:42:36] set_destination: Parsing <sip:10.150.65.16:5060;transport=UDP> for address/port to send to
[Feb 2 14:42:36] set_destination: set destination to 10.150.65.16, port 5060
[Feb 2 14:42:36] Transmitting (no NAT) to 10.150.65.16:5060:
ACK sip:10.150.65.16:5060;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.153.66.146:5060;branch=z9hG4bK2338b747;rport
Max-Forwards: 70
From: <sip:5421047008@10.153.66.146:5060;user=phone>;tag=as53a14c9a
To: <sip:5433142499@10.150.65.16:5060;user=phone>;tag=c4-45026-46a0e9-51b1091a-46a0e9
Contact: <sip:5421047008@10.153.66.146>
Call-ID: a703afa81041960a13c446a0e913e48e6094541f8fbd08698-0322-4807
CSeq: 103 ACK
User-Agent: Asterisk PBX 1.6.1.13
Content-Length: 0

---
[Feb 2 14:42:36] WARNING[7880]: app_fax.c:767 transmit: Transmission failed
[Feb 2 14:42:36] -- Executing [s@macro-recebefax:7] NoOp("SIP/voxip-00000109", "FAXSTATUS = FAILED") in new stack
[Feb 2 14:42:36] -- Executing [s@macro-recebefax:8] NoOp("SIP/voxip-00000109", "FAXERROR = Unexpected message received") in new stack
[Feb 2 14:42:36] -- Executing [s@macro-recebefax:9] NoOp("SIP/voxip-00000109", "CALLID = 5433142499 ") in new stack
[Feb 2 14:42:36] -- Executing [s@macro-recebefax:10] NoOp("SIP/voxip-00000109", "FAXPAGES = ") in new stack
[Feb 2 14:42:36] -- Executing [s@macro-recebefax:11] NoOp("SIP/voxip-00000109", "FAXBITRATE = ") in new stack
[Feb 2 14:42:36] -- Executing [s@macro-recebefax:12] NoOp("SIP/voxip-00000109", "FAXRESOLUTION = ") in new stack
[Feb 2 14:42:36] -- Executing [s@macro-recebefax:13] NoOp("SIP/voxip-00000109", "FAXMODE = T38") in new stack
[Feb 2 14:42:36] -- Auto fallthrough, channel 'SIP/voxip-00000109' status is 'UNKNOWN'
[Feb 2 14:42:36] -- Executing [h@macro-recebefax:1] System("SIP/voxip-00000109", "tiff2pdf -o /var/spool/asterisk/fax/fax-48-rx.pdf -p A4 /var/spool/asterisk/fax/fax-48-rx.tif") in new stack
[Feb 2 14:42:36] -- Executing [h@macro-recebefax:2] System("SIP/voxip-00000109", "rm /var/spool/asterisk/fax/fax-48-rx.tif") in new stack
[Feb 2 14:42:37] -- Executing [h@macro-recebefax:3] System("SIP/voxip-00000109", "echo "Fax recebido." > /tmp/fax-48-rx.txt") in new stack
[Feb 2 14:42:37] -- Executing [h@macro-recebefax:4] System("SIP/voxip-00000109", "echo "Remetente: " >> /tmp/fax-48-rx.txt") in new stack
[Feb 2 14:42:37] -- Executing [h@macro-recebefax:5] System("SIP/voxip-00000109", "echo "Paginas: " >> /tmp/fax-48-rx.txt") in new stack
[Feb 2 14:42:38] -- Executing [h@macro-recebefax:6] System("SIP/voxip-00000109", "echo "Velocidade de transmissao: bps" >> /tmp/fax-48-rx.txt") in new stack
[Feb 2 14:42:39] NOTICE[3980]: chan_sip.c:11888 check_auth: Correct auth, but based on stale nonce received from '<sip:7019@pabx.canall.com.br;transport=UDP>'
[Feb 2 14:42:39] -- Executing [h@macro-recebefax:7] System("SIP/voxip-00000109", "echo "Resolucao: " >> /tmp/fax-48-rx.txt") in new stack
[Feb 2 14:42:39] -- Executing [h@macro-recebefax:8] System("SIP/voxip-00000109", "mutt -s "Allvo FAX" -a /var/spool/asterisk/fax/fax-48-rx.pdf vinicius@canall.com.br < /tmp/fax-48-rx.txt") in new stack
[Feb 2 14:42:39] -- Executing [h@macro-recebefax:9] System("SIP/voxip-00000109", "rm /tmp/fax-48-rx.txt") in new stack
[Feb 2 14:42:39] Scheduling destruction of SIP dialog 'a703afa81041960a13c446a0e913e48e6094541f8fbd08698-0322-4807' in 6400 ms (Method: ACK)
[Feb 2 14:42:39] set_destination: Parsing <sip:10.150.65.16:5060;transport=UDP> for address/port to send to
[Feb 2 14:42:39] set_destination: set destination to 10.150.65.16, port 5060
[Feb 2 14:42:39] Reliably Transmitting (no NAT) to 10.150.65.16:5060:
BYE sip:10.150.65.16:5060;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.153.66.146:5060;branch=z9hG4bK568a6924;rport
Max-Forwards: 70
From: <sip:5421047008@10.153.66.146:5060;user=phone>;tag=as53a14c9a
To: <sip:5433142499@10.150.65.16:5060;user=phone>;tag=c4-45026-46a0e9-51b1091a-46a0e9
Call-ID: a703afa81041960a13c446a0e913e48e6094541f8fbd08698-0322-4807
CSeq: 104 BYE
User-Agent: Asterisk PBX 1.6.1.13
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0

---
[Feb 2 14:42:39]
<--- SIP read from UDP://10.150.65.16:5060 --->
SIP/2.0 200 OK
From: <sip:5421047008@10.153.66.146:5060;user=phone>;tag=as53a14c9a
t: <sip:5433142499@10.150.65.16:5060;user=phone>;tag=c4-45026-46a0e9-51b1091a-46a0e9
Call-ID: a703afa81041960a13c446a0e913e48e6094541f8fbd08698-0322-4807
CSeq: 104 BYE
Server: CS2000_NGSS/9.0
k: 100rel
Allow: ACK,BYE,CANCEL,INVITE,OPTIONS,INFO,SUBSCRIBE,REFER,NOTIFY,PRACK
Via: SIP/2.0/UDP 10.153.66.146:5060;rport=5060;branch=z9hG4bK568a6924
Content-Length: 0

<------------->
[Feb 2 14:42:39] --- (10 headers 0 lines) ---
[Feb 2 14:42:39] Really destroying SIP dialog 'a703afa81041960a13c446a0e913e48e6094541f8fbd08698-0322-4807' Method: ACK
[Feb 2 14:42:43] NOTICE[3980]: chan_sip.c:11888 check_auth: Correct auth, but based on stale nonce received from '<sip:7019@pabx.canall.com.br;transport=UDP>'
[Feb 2 14:42:45] NOTICE[3980]: chan_sip.c:20366 handle_request_subscribe: Received SIP subscribe for peer without mailbox: 7012
[Feb 2 14:42:47] NOTICE[3980]: chan_sip.c:11888 check_auth: Correct auth, but based on stale nonce received from '<sip:7019@pabx.canall.com.br;transport=UDP>'
[Feb 2 14:42:51] NOTICE[3980]: chan_sip.c:11888 check_auth: Correct auth, but based on stale nonce received from '<sip:7019@pabx.canall.com.br;transport=UDP>'
[Feb 2 14:42:55] NOTICE[3980]: chan_sip.c:11888 check_auth: Correct auth, but based on stale nonce received from '<sip:7019@pabx.canall.com.br;transport=UDP>'
[Feb 2 14:42:59] Reliably Transmitting (no NAT) to 10.150.65.16:5060:
OPTIONS sip:10.150.65.16 SIP/2.0
Via: SIP/2.0/UDP 10.153.66.146:5060;branch=z9hG4bK1ed2a4f0;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk@pabx.canall.com.br>;tag=as44a0b6c3
To: <sip:10.150.65.16>
Contact: <sip:asterisk@10.153.66.146>
Call-ID: 5ffc6f934e34d8a905bbbe8811e0a664@pabx.canall.com.br
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 1.6.1.13
Date: Tue, 02 Feb 2010 16:42:59 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Content-Length: 0

---
[Feb 2 14:42:59]
<--- SIP read from UDP://10.150.65.16:5060 --->
SIP/2.0 200 OK
From: "asterisk"<sip:asterisk@pabx.canall.com.br>;tag=as44a0b6c3
To: <sip:10.150.65.16>;tag=c4-45026-46a118-2db6566f-46a118
i: 5ffc6f934e34d8a905bbbe8811e0a664@pabx.canall.com.br
CSeq: 102 OPTIONS
Server: CS2000_NGSS/9.0
Accept: application/isup, application/sdp, application/dtmf-relay, audio/telephone-event, application/simple-message-summary
Allow: ACK,BYE,CANCEL,INVITE,OPTIONS,INFO,SUBSCRIBE,REFER,NOTIFY,PRACK
v: SIP/2.0/UDP 10.153.66.146:5060;rport=5060;branch=z9hG4bK1ed2a4f0
k: 100rel
l: 0

Comments: By: Leif Madsen (lmadsen) 2010-02-02 14:20:03.000-0600

In the future please attach long bits of text as a file attachment, and not inline.
By: Leif Madsen (lmadsen) 2010-02-02 15:26:08.000-0600

Could you reference the discussion you had with Kevin that you've quoted? Is that on the mailing list archives? (lists.digium.com)
By: viniciusfontes (viniciusfontes) 2010-02-02 17:55:01.000-0600

Kevin's message: http://lists.digium.com/pipermail/asterisk-users/2010-February/244151.html
By: Raivis Rengelis (raivisr) 2010-02-03 01:26:57.000-0600

WARNING[7880]: app_fax.c:178 phase_e_handler: Error transmitting fax. result=13: Unexpected message received.

this is returned by spandsp, so looking at packet capture of failing session might help to understand what went wrong and what is the unexpected message that was received. use tcpdump/wireshark to capture session and analyze it in wireshark telephony->voip calls
By: viniciusfontes (viniciusfontes) 2010-02-03 04:00:35.000-0600

As requested, I posted a capture of a failed fax session. There's two calls on the file (the system is in production so another call went in at the time), but should be easy to see that the failed fax is the only call that has the COMPLETED status.
By: Raivis Rengelis (raivisr) 2010-02-03 10:00:04.000-0600

If you look at the log you will see that reason was "Failure to train". Remote end was too slow to respond and app_fax just gave up. If you are trying to send fax from real fax machine, try a different one, if that does not help, work with your provider so that they fix their T.38 gateway.
By: viniciusfontes (viniciusfontes) 2010-02-03 10:22:38.000-0600

I tought of that too, but this provider works wonderfully well when I use a Linksys SPA-8000 instead of Asterisk, with the very same fax machine. Also, if I use Fax For Asterisk instead of app_fax, it works fine too.

Maybe the log I sent was an exception, but I really think the problem lies within app_fax and maybe some other parts of Asterisk.
By: Leif Madsen (lmadsen) 2010-02-03 10:51:25.000-0600

Hmmm, I wonder if this issue is really in spandsp then, and not in Asterisk itself?
By: viniciusfontes (viniciusfontes) 2010-02-03 10:55:43.000-0600

Could be. FFA doesn't use spandsp and is working fine. But according to Kevin, it might be an Asterisk issue due to the reinvites.
By: Raivis Rengelis (raivisr) 2010-02-03 11:52:33.000-0600

it is spandsp then, because udptl session is esatblished ok and spandsp is the one failing to receive fax. try different version maybe.
By: viniciusfontes (viniciusfontes) 2010-02-03 11:57:52.000-0600

Which spandsp version Digium used to test app_fax before the release?
By: Raivis Rengelis (raivisr) 2010-02-03 12:23:32.000-0600

I don't know about Digium, but it works ok for me with 0.0.6pre12
By: viniciusfontes (viniciusfontes) 2010-02-03 12:26:54.000-0600

I'm using 0.0.5pre-something. I couldn't compile app_fax.so using 0.0.5. What Asterisk version you're running?
By: Raivis Rengelis (raivisr) 2010-02-03 12:37:32.000-0600

1.6.trunk. looking at sources, 1.6.1.13 should support 0.0.6 series of spandsp as well. when installing new version of spandsp make sure to completely remove previous version, otherwise you will get a whole bunch of weird problems.
try following:
1) uninstall old version of spandsp
2) compile and install new version of spandsp
3) re-run configure for asterisk
4) confirm that all selections are there in menuselect (pay close attention to app_fax)
5) make && make install
6) restart your asterisk
By: viniciusfontes (viniciusfontes) 2010-02-03 13:18:38.000-0600

I Removed all previous versions of libspandsp. Installed spandsp-0.0.6pre17. Compiled Asterisk 1.6.1.14 from source. When ReceiveFAX() is called Asterisk segfaults.
By: Raivis Rengelis (raivisr) 2010-02-03 13:27:04.000-0600

for segfaults backtrace can sometimes help.
By: Leif Madsen (lmadsen) 2010-02-03 13:27:19.000-0600

1.6.trunk isn't a real version...

trunk is something entirely separate of the 1.4 and 1.6.x branches -- it will eventually have a branch made from it that will become 1.8 at some point in the future, and then will continue being the latest version of Asterisk in development.

There are 3 branches in the 1.6 series:

1.6.0
1.6.1
1.6.2

Each of these are separate branches with different feature sets (i.e. new features are added to the later versions). Bug fixes are done in all branches where the bug exists (i.e. 1.4, 1.6.0, 1.6.1, and 1.6.2).

Releases are done from the branches, such as 1.6.1.14, etc...

Please note that 'trunk' is always only a single thing -- there is no such thing as "1.6 trunk" or "1.4. trunk" etc... -- you should reference them as "the latest 1.6.0 branch", or "the latest 1.6.1 branch", etc...
By: Leif Madsen (lmadsen) 2010-02-03 13:28:10.000-0600

Add link to mailing list thread in Description: http://lists.digium.com/pipermail/asterisk-users/2010-February/244136.html
By: viniciusfontes (viniciusfontes) 2010-02-03 13:32:58.000-0600

As far as I can tell, 0.0.5 doesn't work and 0.0.6 segfaults Asterisk.

I would like to hear from someone at Digium if possible: what's the recommended libspandsp version for app_fax?
By: Raivis Rengelis (raivisr) 2010-02-03 13:35:06.000-0600

point taken :) I am using Asterisk SVN-trunk-r243346 i.e. something that eventually will become 1.8
By: viniciusfontes (viniciusfontes) 2010-02-03 13:39:55.000-0600

0.0.6 is making Asterisk segfault, but maybe when it doesn't it could work. :) How can I submit useful info on debugging the cause of that segfault?
By: Raivis Rengelis (raivisr) 2010-02-03 13:43:30.000-0600

cd /tmp
check if you see core file there (core.host-date
gdb /usr/sbin/asterisk corefile
at gdb prompt issue command "bt full"
By: viniciusfontes (viniciusfontes) 2010-02-03 13:48:20.000-0600

pabx:/tmp# gdb core.4036
GNU gdb 6.4.90-debian
Copyright (C) 2006 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for details.
This GDB was configured as "i486-linux-gnu"..."/tmp/core.4036": not in executable format: File format not recognized

(gdb) bt full
No stack.
(gdb)

Any suggestions?
By: Raivis Rengelis (raivisr) 2010-02-03 13:50:50.000-0600

second argument to gdb should be your asterisk executable that segfaulted and threw the core
By: viniciusfontes (viniciusfontes) 2010-02-03 13:51:58.000-0600

Yeah just noticed that. Cut me some slack, this bug is driving me crazy here. :)

Submitted the full output as textfile.
By: Raivis Rengelis (raivisr) 2010-02-03 13:57:00.000-0600

can you recompile asterisk with compiler optimization turned off and then try again?
By: viniciusfontes (viniciusfontes) 2010-02-03 13:58:46.000-0600

That would be the DONT_OPTIMIZE flag?
By: Leif Madsen (lmadsen) 2010-02-03 13:59:46.000-0600

Yeppers!
By: viniciusfontes (viniciusfontes) 2010-02-03 16:08:35.000-0600

Okay, recompiled it with DONT_OPTIMIZE and posted the full gdb session.

Is there any problem to keep running this not optimized version in production? My box has about 30 extensions and almost never goes past 10% CPU usage.
By: Kristijan Vrban (vrban) 2010-02-03 16:24:10.000-0600

it's ok to run your production asterisk with DONT_OPTIMIZE. I have three asterisk maschines with 500 user running with DONT_OPTIMIZE.

By: Raivis Rengelis (raivisr) 2010-02-03 16:26:32.000-0600

that is some huge max_datagram_size you have got there... try adding line t38pt_udptl=yes,maxdatagram=400 to your sip.conf (either ir general section or in your provider's config) and re-run test. If that helps, full debug log (core set debug 10, core set verbose 10) would prolly help to determine root cause of the problem.

no, it most likely is not a problem to run unoptimized version.
By: viniciusfontes (viniciusfontes) 2010-02-03 16:53:49.000-0600

Funny thing is, it is already set at 400! I'm pretty sure that's another bug on Asterisk.

Here's the relevant section on my sip.conf:

[voxip]
username=5421047000
nat=no
type=peer
secret=5421047000
port=5060
canreinvite=no
insecure=port,invite
host=10.150.65.16
fromuser=5421047000
fromdomain=gvt.com.br
dtmfmode=rfc2833
context=entrada-e1
disallow=all
allow=g729,alaw
qualify=no
;t38pt_udptl=yes
t38pt_udptl = yes,maxdatagram=400
By: Raivis Rengelis (raivisr) 2010-02-04 01:33:03.000-0600

something went wrong with T.38 negotiation. app_fax.c receives messed up t38parameters structure:
t38parameters = {
request_response = 2793090424, version = 135113997, max_ifp = 136490996, rate = AST_T38_RATE_2400, rate_management = 2793090472, fill_bit_removal = 0, transcoding_mmr = 0, transcoding_jbig = 1}

request_response can by no means be what it is, the same goes for version, max_ifp and rate_management. meanwhile rate, fill_bit_removal and both transcoding parameters are correct.

this all looks a bit weird to me, like memory corruption or something.. just to be on a safe side, have you tried to run memtest on that machine?
By: viniciusfontes (viniciusfontes) 2010-02-04 04:13:21.000-0600

No, but I really don't think there's a hardware issue, since the machine runs rock solid without crashing at all.
By: Raivis Rengelis (raivisr) 2010-02-04 04:17:13.000-0600

it could as well be memory allocation problem then, because there is no way asterisk could have put those values in there.
By: viniciusfontes (viniciusfontes) 2010-02-04 04:19:59.000-0600

Maybe a kernel bug? Because I'm still running Debian Sarge (don't laugh! :) and kernel 2.6.16 on that machine.

Could be worth trying a kernel update?
By: Raivis Rengelis (raivisr) 2010-02-04 04:26:52.000-0600

that IS a bit old :) (etch is going unsupported in 11 days, let alone sarge)
yes, maybe upgrading the whole system, inluding libc and gcc could help to solve your issue.
By: viniciusfontes (viniciusfontes) 2010-02-04 04:31:31.000-0600

I had plans on upgrading everything to Lenny... just not that soon. Well I'll try to update today after work hours and test again. I'll probably give some feedback tomorrow.

Thanks a lot for the help so far.
By: viniciusfontes (viniciusfontes) 2010-02-04 09:35:45.000-0600

Upgraded to Debian Lenny 5.0.4 (Kernel 2.6.26). Running Asterisk 1.6.1.14 compiled from source, spandsp 0.0.6pre17 (current release).

Now app_fax doesn't crash anymore, but fax reception is damn slow. I transmitted a fax from an analog landline and the bitrate negotiated was just 2400 bps. One page took about 5 minutes to be transmitted. Good news is I got no errors at all.

What info could I provide to help find out why the bitrate dropped so dramatically?
By: Raivis Rengelis (raivisr) 2010-02-04 09:45:15.000-0600

that question is beyond asterisk as on one end t.30 is converted to t.38 by your provider's gateway, on the other end (your) it is converted from t.38 to tiff by spandsp.
try faxing from supposedly good landline with supposedly good fax machine and see what results you get.
By: viniciusfontes (viniciusfontes) 2010-02-04 09:46:41.000-0600

That's exacly what I did.
I'll try FFA to check if I can get a better rate.
By: viniciusfontes (viniciusfontes) 2010-02-04 10:17:33.000-0600

Fax For Asterisk works perfectly, receiving at 9600bps from the very same landline that can only reach 2400bps on app_fax.

Should I save the frames to a file and post it?

By: Elazar Broad (ebroad) 2010-02-04 10:42:29.000-0600

Try spandsp 0.0.6pre12...
By: viniciusfontes (viniciusfontes) 2010-02-04 11:20:13.000-0600

Some improvement with spandsp-0.0.6pre12.

Got 7200 bps tops, but sometimes (I would say like 50-60% of the time) the transmission failed completely. When that happened, I got that on the CLI:

[Feb 4 15:13:07] WARNING[26408]: app_fax.c:178 phase_e_handler: Error transmitting fax. result=13: Unexpected message received.
[Feb 4 15:13:07] WARNING[26408]: app_fax.c:764 transmit: Transmission error

I would say that spandsp-0.0.6pre17 is much more reliable (never got a transmission error), but also much slower.

FFA continues to kick ass, tho. :) As usual, I'll provide any info needed to keep debugging this issue.
By: Elazar Broad (ebroad) 2010-02-04 12:57:35.000-0600

Are you using dahdi_dummy and is internal_timing set to yes in asterisk.conf?
By: viniciusfontes (viniciusfontes) 2010-02-04 13:01:35.000-0600

I have a TDM400P board, so I'm not using dahdi_dummy. And internal_timing is indeed set to yes in asterisk.conf.
By: Elazar Broad (ebroad) 2010-02-04 13:15:31.000-0600

I'm not familiar with the TDM400P, however, is it possible to use the timing on the board instead of internal_timing?
By: viniciusfontes (viniciusfontes) 2010-02-04 13:18:37.000-0600

Probably it's just setting internal_timing=no. :) I'll try that right now and will post the results in a few minutes.
By: viniciusfontes (viniciusfontes) 2010-02-04 13:29:17.000-0600

Seems a bit more reliable now (not getting transmission errors), but still slow. 4800bps at best.
By: Elazar Broad (ebroad) 2010-02-04 13:42:13.000-0600

I'm out of ideas. I usually get a 9600+ over a SIP trunk coming from a regular fax machine on a standard analog line. I have gotten 14.4 from a local fax machine attached to an SPA-2101. What kind of hardware are you running? I wonder if you will get better results on a machine that supports HPET using internal_timing...
By: viniciusfontes (viniciusfontes) 2010-02-04 13:46:51.000-0600

Yeah it's strange. Even more considering FFA works wonderfully well. Here's some info about my box:

pabx:~# cat /proc/cpuinfo
processor : 0
vendor_id : GenuineIntel
cpu family : 15
model : 4
model name : Intel(R) Pentium(R) 4 CPU 2.80GHz
stepping : 9
cpu MHz : 2793.390
cache size : 1024 KB
fdiv_bug : no
hlt_bug : no
f00f_bug : no
coma_bug : no
fpu : yes
fpu_exception : yes
cpuid level : 5
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe nx lm constant_tsc up pebs bts pni monitor ds_cpl tm2 cid cx16 xtpr
bogomips : 5593.02
clflush size : 64
power management:

pabx:~# free -m
total used free shared buffers cached
Mem: 504 495 8 0 57 338
-/+ buffers/cache: 99 405
Swap: 533 0 532

pabx:~# dahdi_test
Opened pseudo dahdi interface, measuring accuracy...
99.992% 99.987% 99.991% 99.991% 99.991% 99.991% 99.991% 99.991%
99.990% 99.989% 99.991% 99.991% 99.990% 99.989% 99.991% 99.992% ^C
--- Results after 16 passes ---
Best: 99.992 -- Worst: 99.987 -- Average: 99.990383, Difference: 99.990384

pabx*CLI> timing test
Attempting to test a timer with 50 ticks per second.
Using the 'DAHDI' timing module for this test.
It has been 1019 milliseconds, and we got 51 timer ticks

pabx:~# dahdi_cfg -tvv
DAHDI Tools Version - 2.2.1

DAHDI Version: 2.2.1
Echo Canceller(s): MG2
Configuration
======================

Dynamic span 1: driver eth, addr eth0/00:0B:3C:00:40:25, channels 32, timing 1

Channel map:

Channel 01: FXS Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 01)
Channel 02: FXS Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 02)
Channel 03: FXS Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 03)
Channel 05: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 05)
Channel 06: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 06)
Channel 07: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 07)
Channel 08: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 08)
Channel 09: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 09)
Channel 10: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 10)
Channel 11: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 11)
Channel 12: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 12)
Channel 13: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 13)
Channel 14: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 14)
Channel 15: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 15)
Channel 16: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 16)
Channel 17: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 17)
Channel 18: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 18)
Channel 19: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 19)
Channel 20: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 20)
Channel 21: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 21)
Channel 22: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 22)
Channel 23: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 23)
Channel 24: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 24)
Channel 25: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 25)
Channel 26: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 26)
Channel 27: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 27)
Channel 28: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 28)
Channel 29: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 29)
Channel 30: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 30)
Channel 31: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 31)
Channel 32: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 32)
Channel 33: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 33)
Channel 34: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 34)
Channel 35: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 35)
Channel 36: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 36)

35 channels to configure.

Any ideas are more than welcome.
By: Elazar Broad (ebroad) 2010-02-04 13:56:14.000-0600

Hmm, P4 620, should support HPET, though if you aren't using VMWare, older hardware RTC's were decently accurate for the most part. How is the fax coming in to your network? POTS-->TDM400P-->Asterisk?
By: viniciusfontes (viniciusfontes) 2010-02-04 13:58:36.000-0600

The fax is coming via a SIP provider, using T.38 (that's all about this issue is, T.38 faxing). So it's like this:

Fax machine -> POTS Landline -> SIP Provider -> Asterisk
By: Elazar Broad (ebroad) 2010-02-04 14:02:08.000-0600

So the TDM400P is not involved at all. What happens if you use ulaw(providing that your trunk provider supports it) as opposed to alaw,g729?
By: Raivis Rengelis (raivisr) 2010-02-04 14:12:12.000-0600

audio codecs have no impact on t.38 faxing as far as i am concerned
By: Elazar Broad (ebroad) 2010-02-04 14:42:04.000-0600

That is correct. I have seen some people resolve t.38 issues by reducing the maxdatagram size to around 180 or so...
By: viniciusfontes (viniciusfontes) 2010-02-05 04:31:02.000-0600

Still having very low bitrates even with maxdatagramsize=180. I attached a CLI session with "sip set debug peer voxip on". My relevant sip.conf section is as follows:

[voxip]
username=5421047000
nat=no
type=peer
secret=5421047000
port=5060
canreinvite=no
insecure=port,invite
host=10.150.65.16
fromuser=5421047000
fromdomain=gvt.com.br
dtmfmode=rfc2833
context=entrada-e1
disallow=all
allow=g729,alaw
qualify=no
;t38pt_udptl=yes
t38pt_udptl = yes,maxdatagram=180

I might be wrong, but I didn't see Asterisk trying to negotiate the maxdatagram size to 180 not even once. It just tries to negotiate it as 1400, which the provider doesn't accept and falls back to 612.

Anyway, I guess that's not the problem since FFA works perfectly under these very same conditions. If I had to bet my money on where the problem lies my bet would be on spandsp and/or app_fax.

By: Raivis Rengelis (raivisr) 2010-02-05 04:38:43.000-0600

according to itu-t t.38 recommendation remote end announces maximum datagram it is able to accept with T38FaxMaxDatagram attribute, that means, that your end announces to far end that it is able to receive datagrams as big as 1400 bytes and your provider announces that it is able to receive datagrams as big as 610 bytes. when using maxdatagram=180 you tell your end to forcibly use smaller datagram than far end announced when sending to it, which is ok. if you turned on full logs, you would see how chan_sip tells that it used overridden value.
By: viniciusfontes (viniciusfontes) 2010-02-05 05:18:11.000-0600

Good to know! I always tought the config on sip.conf would make the SDP negotiation use those values.

I got a full debug on app_fax and it seems to me that the transmission starts at 9600bps as expected but for some reason it falls back to 7200bps, 4800bps and finally to 2400bps where the transmission finally occurs.

Posted the log as app_fax_debug.txt.gz
By: viniciusfontes (viniciusfontes) 2010-02-05 05:28:36.000-0600

For comparison's sake, I sent a fax to an analog landline that is also connected to this same Asterisk box, via an FXO module on a TDM400P board. This time the transmission went smootly at 9600bps.

Seems that the problem only happens when one use app_fax to receive a fax via T.38.

Posted the log as app_fax_debug_analog_landline.txt.gz.
By: Raivis Rengelis (raivisr) 2010-02-05 05:30:55.000-0600

that actually is log of spandsp just relied to asterisk log by app_fax, author of spandsp Steve Underwood could maybe help you with this.
By: Leif Madsen (lmadsen) 2010-02-22 15:00:09.000-0600

So are we convinced yet that this appears to be an issue in SpanDSP?
By: viniciusfontes (viniciusfontes) 2010-02-24 09:58:01.000-0600

Actually it doesn't seem to be a problem on SpanDSP, Asterisk or FFA.

After a long email exchange with Steve Underwood we're convinced the problem lies on the provider itself, which has a completely broken T.38 implementation.
By: Leif Madsen (lmadsen) 2010-02-24 10:22:57.000-0600

Wow! Well good to know :)

Does this mean I should close the issue out?
By: viniciusfontes (viniciusfontes) 2010-02-24 10:28:30.000-0600

It's good for Asterisk, horrible for me! :( Yeah you can go ahead and close the issue. Sorry for all the hassle.