IAX2 Fax . Receive fax tones from fax but fails to receive

FreePBX Installation / Upgrade
1

Hi,

I have setup an IAX2 extension and then setup a fax using that extension. I have an analogue trunk pointing at the extension in inbound routes.

If I dial the extension internally or from outside via the analogue trunk I can hear the fax tones.

If I send a fax to the extension from outside the fax appears to handshake but then fails to send. I have tried 2 different fax machines to send on 2 different sites so it can not be my sending fax.

I have tailed the log and am geting NOTICE[25815] chan_dahdi.c: Fax detected, but no fax extension

Does anyone have an ideas?

Thanks

Steve

[Nov 10 16:51:24] DEBUG[3219] dsp.c: dsp busy pattern set to 0,0
[Nov 10 16:51:24] VERBOSE[25815] logger.c: – Starting simple switch on ‘Zap/5-1’
[Nov 10 16:51:26] NOTICE[25815] chan_dahdi.c: Got event 18 (Ring Begin)…
[Nov 10 16:51:27] NOTICE[25815] chan_dahdi.c: Got event 2 (Ring/Answered)…
[Nov 10 16:51:29] NOTICE[25815] chan_dahdi.c: Got event 18 (Ring Begin)…
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@from-zaptel:1] NoOp(“Zap/5-1”, "Entering from-zaptel with DID == ") in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@from-zaptel:2] Ringing(“Zap/5-1”, “”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@from-zaptel:3] Set(“Zap/5-1”, “DID=s”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@from-zaptel:4] NoOp(“Zap/5-1”, “DID is now s”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@from-zaptel:5] GotoIf(“Zap/5-1”, “1?zapok:notzap”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Goto (from-zaptel,s,8)
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@from-zaptel:8] NoOp(“Zap/5-1”, “Is a Zaptel Channel”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@from-zaptel:9] Set(“Zap/5-1”, “CHAN=5-1”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@from-zaptel:10] Set(“Zap/5-1”, “CHAN=5”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@from-zaptel:11] Macro(“Zap/5-1”, “from-zaptel-5|s|1”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-from-zaptel-5:1] NoOp(“Zap/5-1”, “Entering macro-from-zaptel-5 with DID = s and setting to: 502836”) in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Noop
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-from-zaptel-5:2] Set(“Zap/5-1”, “__FROM_DID=502836”) in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Set
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-from-zaptel-5:3] Goto(“Zap/5-1”, “from-trunk|502836|1”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Goto (from-trunk,502836,1)
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Goto
[Nov 10 16:51:29] VERBOSE[25815] logger.c: == Channel ‘Zap/5-1’ jumping out of macro ‘from-zaptel-5’
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [502836@from-trunk:1] Set(“Zap/5-1”, “__FROM_DID=502836”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [502836@from-trunk:2] GotoIf(“Zap/5-1”, “0 ?cidok”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [502836@from-trunk:3] Set(“Zap/5-1”, “CALLERID(name)=”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [502836@from-trunk:4] NoOp(“Zap/5-1”, “CallerID is “” <>”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [502836@from-trunk:5] Set(“Zap/5-1”, “__ALERT_INFO=”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [502836@from-trunk:6] Goto(“Zap/5-1”, “from-did-direct|300|1”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Goto (from-did-direct,300,1)
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [300@from-did-direct:1] Macro(“Zap/5-1”, “exten-vm|novm|300”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-exten-vm:1] Macro(“Zap/5-1”, “user-callerid”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-user-callerid:1] NoOp(“Zap/5-1”, "user-callerid: ") in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Noop
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-user-callerid:2] Set(“Zap/5-1”, “AMPUSER=”) in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Set
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-user-callerid:3] GotoIf(“Zap/5-1”, “0?report”) in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: GotoIf
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-user-callerid:4] ExecIf(“Zap/5-1”, “1|Set|REALCALLERIDNUM=”) in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: ExecIf
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Last app: Set|REALCALLERIDNUM=
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-user-callerid:5] NoOp(“Zap/5-1”, “REALCALLERIDNUM is “) in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Noop
[Nov 10 16:51:29] DEBUG[25815] func_db.c: DB: DEVICE//user not found in database.
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-user-callerid:6] Set(“Zap/5-1”, “AMPUSER=”) in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Set
[Nov 10 16:51:29] DEBUG[25815] func_db.c: DB: AMPUSER//cidname not found in database.
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-user-callerid:7] Set(“Zap/5-1”, “AMPUSERCIDNAME=”) in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Set
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-user-callerid:8] GotoIf(“Zap/5-1”, “1?report”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Goto (macro-user-callerid,s,13)
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: GotoIf
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-user-callerid:13] NoOp(“Zap/5-1”, “TTL: ARG1: novm”) in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Noop
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-user-callerid:14] GotoIf(“Zap/5-1”, “0?continue”) in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: GotoIf
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-user-callerid:15] Set(“Zap/5-1”, “__TTL=64”) in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Set
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-user-callerid:16] GotoIf(“Zap/5-1”, “1?continue”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Goto (macro-user-callerid,s,23)
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: GotoIf
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-user-callerid:23] NoOp(“Zap/5-1”, “Using CallerID “” <>”) in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Noop
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Macro
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-exten-vm:2] Set(“Zap/5-1”, “FROMCONTEXT=exten-vm”) in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Set
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-exten-vm:3] Set(“Zap/5-1”, “VMBOX=novm”) in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Set
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-exten-vm:4] Set(“Zap/5-1”, “EXTTOCALL=300”) in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Set
[Nov 10 16:51:29] DEBUG[25815] func_db.c: DB: CFU/300 not found in database.
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-exten-vm:5] Set(“Zap/5-1”, “CFUEXT=”) in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Set
[Nov 10 16:51:29] DEBUG[25815] func_db.c: DB: CFB/300 not found in database.
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-exten-vm:6] Set(“Zap/5-1”, “CFBEXT=”) in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Set
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-exten-vm:7] Set(“Zap/5-1”, “RT=”””) in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Set
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-exten-vm:8] Macro(“Zap/5-1”, “record-enable|300|IN”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-record-enable:1] GotoIf(“Zap/5-1”, “0?2:4”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Goto (macro-record-enable,s,4)
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: GotoIf
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-record-enable:4] AGI(“Zap/5-1”, “recordingcheck|20081110-165129|1226335884.3467”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Nov 10 16:51:29] VERBOSE[25815] logger.c: recordingcheck|20081110-165129|1226335884.3467: Inbound recording not enabled
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – AGI Script recordingcheck completed, returning 0
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: AGI
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-record-enable:5] NoOp(“Zap/5-1”, “No recording needed”) in new stack
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Noop
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: Macro
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-exten-vm:9] Macro(“Zap/5-1”, “dial||tr|300”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-dial:1] GotoIf(“Zap/5-1”, “1?dial”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Goto (macro-dial,s,3)
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: GotoIf
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-dial:3] AGI(“Zap/5-1”, “dialparties.agi”) in new stack
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Nov 10 16:51:29] VERBOSE[25815] logger.c: dialparties.agi: Starting New Dialparties.agi
[Nov 10 16:51:29] VERBOSE[25851] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Nov 10 16:51:29] VERBOSE[25851] logger.c: Found
[Nov 10 16:51:29] VERBOSE[25851] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Nov 10 16:51:29] VERBOSE[25851] logger.c: Found
[Nov 10 16:51:29] VERBOSE[25851] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Nov 10 16:51:29] VERBOSE[25851] logger.c: Found
[Nov 10 16:51:29] WARNING[25851] config.c: Unknown directive ‘#permit=192.168.1.0/255.255.255.0’ at line 18 of /etc/asterisk/manager_custom.conf
[Nov 10 16:51:29] VERBOSE[25851] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Nov 10 16:51:29] VERBOSE[25815] logger.c: dialparties.agi: Caller ID name is ‘unknown’ number is ‘unknown’
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – AGI Script Executing Application: (SIPAddHeader) Options: (Alert-Info:)
[Nov 10 16:51:29] VERBOSE[25815] logger.c: dialparties.agi: Methodology of ring is ‘none’
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – dialparties.agi: Added extension 300 to extension map
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – dialparties.agi: Extension 300 cf is disabled
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – dialparties.agi: Extension 300 do not disturb is disabled
[Nov 10 16:51:29] VERBOSE[25815] logger.c: dialparties.agi: Extension 300 has ExtensionState: 0
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – dialparties.agi: Checking CW and CFB status for extension 300
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – dialparties.agi: DbDel CALLTRACE/300 - Caller ID is not defined
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – dialparties.agi: Filtered ARG3: 300
[Nov 10 16:51:29] VERBOSE[25851] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – AGI Script dialparties.agi completed, returning 0
[Nov 10 16:51:29] DEBUG[25815] app_macro.c: Executed application: AGI
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Executing [s@macro-dial:7] Dial(“Zap/5-1”, “IAX2/300||tr”) in new stack
[Nov 10 16:51:29] DEBUG[25815] chan_iax2.c: prepending 4 to prefs
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – Called 300
[Nov 10 16:51:29] VERBOSE[3204] logger.c: – Call accepted by 127.0.0.1 (format ulaw)
[Nov 10 16:51:29] VERBOSE[3204] logger.c: – Format for call is ulaw
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – IAX2/300-16062 is ringing
[Nov 10 16:51:29] VERBOSE[25815] logger.c: – IAX2/300-16062 answered Zap/5-1
[Nov 10 16:51:29] DEBUG[25815] chan_dahdi.c: Took Zap/5-1 off hook
[Nov 10 16:51:29] WARNING[25815] chan_dahdi.c: Unable to request echo training on channel 5: Invalid argument
[Nov 10 16:51:30] DEBUG[25815] chan_dahdi.c: Ignore switch to REVERSED Polarity on channel 5, state 6
[Nov 10 16:51:30] DEBUG[25815] chan_dahdi.c: Ignoring Polarity switch to IDLE on channel 5, state 6
[Nov 10 16:51:30] DEBUG[25815] chan_dahdi.c: Polarity Reversal event occured - DEBUG 2: channel 5, state 6, pol= 0, aonp= 0, honp= 0, pdelay= 600, tv= -2024756647
[Nov 10 16:51:36] NOTICE[25815] chan_dahdi.c: Fax detected, but no fax extension
[Nov 10 16:51:45] NOTICE[3208] chan_iax2.c: Restricting registration for peer ‘300’ to 60 seconds (requested 300)

2

Update: I am using a sangoma A200 card, have now tried it with echocancel=no and echocancelwhenbridged=no and also echocancel=yes and echocancelwhenbridged=yes and this appears to make no difference.

I have now tried 4 different fax machines on 3 different lines (inc ISDN) and I am still getting the issue.

Any imput will be very gratefully appreciated.

Kindest Regards

Steve

3

Hi there…
i’m sailing through the exact same issues… did you figure out where the source of the problem was and how to fix this?

As far as I’ve been troubleshooting this (debug/logs/etc.) I always got to the same point : handshaking is there but for some reason it seems that no data seems to go from source to destination. I tried no enable/disable echo canceler, etc. without luck so far.

I just wanted to note one thing, if that may help to get closer to a solution : FAX1=external fax machine (neighbor fax)
FAX2=connected on asterisk (analog)
when sending from FAX1 to FAX2, FAX1 is making a very very loud sound which it never does when sending to another fax in the area. Is FAX2 completely deaf?

Steve, if you have any information to share, I’ll be very glad to read you.

Thanks for your help, you and the community…

Frederic

4

I’m wondering if IAX2 has too much compression for fax to work properly.

Bill/W5WAF

5

ANY audio compression at all will screw up faxing.

Faxing really only works with with no compression. So check that all connection are only using ulaw or alaw (g.711u or g711a) depending on where in the world you are located.

6

GSM=Highly Compressed.

BF

7

Not according to what I can find (or remember)… IAX2 can use one of many codecs. http://www.voip-info.org/wiki/index.php?page=Asterisk+bandwidth+iax2

8

The Default CODEC in the IAXy is GSM, and I think most implementations of IAX2 default to GSM.

BF

9

so Frederic,

Change the codec on the IAX tunnel to uLaw or aLaw based on where you are. uLaw is North America for the most part, aLaw is everyplace else.