[Home]

Summary:ASTERISK-14261: ReceiveFAX does not produce CED tones, fax reception times out on DAHDI channels
Reporter:Vladimir Mikhelson (vmikhelson)Labels:
Date Opened:2009-06-03 14:52:07Date Closed:2011-06-07 14:00:45
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Applications/app_fax
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Asterisk takes a fax call on a DAHDI channel, properly switches to a "fax" dialplan. Sending end continues sending tones, never receives anything back from Asterisk, eventually times out.


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

Environment:

Asterisk 1.6.0.9, FreePBX 2.5.1.5, AsteriskNOW 1.5, DAHDI 2.1.0.4

Digium Fax T.38 Driver: 1.6.0_1.0.8 (optimized for pentium3m_32)
Digium Fax G.711 Driver: 1.6.0_1.0.8 (optimized for pentium3m_32)

CentOS Release 5.3

/var/log/asterisk/full fragment:

[Jun 3 12:27:27] VERBOSE[29849] logger.c: -- Channel 'DAHDI/1-1' receiving fax '/var/spool/asterisk/fax/1244050041.45-rx.tif'
[Jun 3 12:27:27] VERBOSE[29849] logger.c: -- Channel 'DAHDI/1-1' fax session '4' started
[Jun 3 12:27:27] WARNING[29849] frame.c: Smoother was working on 4 format frames, now trying to feed 64?
[Jun 3 12:27:27] ERROR[29849] res_fax.c: channel 'DAHDI/1-1' fax session '4' failure, reason: 'Failed to feed the smoother'
[Jun 3 12:28:10] VERBOSE[29850] logger.c: -- Channel 'DAHDI/1-1' fax session '4' is complete, result: 'FAILED' (FAX_NO_FAX), error: 'T1_TIMEOUT', pages: 0, resolution: 'unknown', transfer rate: '2400', remoteSID: ''
Comments:By: Vladimir Mikhelson (vmikhelson) 2009-06-17 19:34:35

Upgraded to Asterisk 1.6.0.10, still no luck.

-Vladimir

Sample CLI output:
   -- Starting simple switch on 'DAHDI/1-1'
   -- Executing [s@from-pstn:1] Set("DAHDI/1-1", "__FROM_DID=s") in new stack
   -- Executing [s@from-pstn:2] Gosub("DAHDI/1-1", "app-blacklist-check,s,1") in new stack
   -- Executing [s@app-blacklist-check:1] GotoIf("DAHDI/1-1", "0?blacklisted") in new stack
   -- Executing [s@app-blacklist-check:2] Return("DAHDI/1-1", "") in new stack
   -- Executing [s@from-pstn:3] ExecIf("DAHDI/1-1", "0 ?Set(CALLERID(name)=8475551212)") in new stack
   -- Executing [s@from-pstn:4] Ringing("DAHDI/1-1", "") in new stack
   -- Executing [s@from-pstn:5] Answer("DAHDI/1-1", "") in new stack
   -- Executing [s@from-pstn:6] Wait("DAHDI/1-1", "0") in new stack
   -- Executing [s@from-pstn:7] Set("DAHDI/1-1", "__CALLINGPRES_SV=allowed_not_screened") in new stack
   -- Executing [s@from-pstn:8] Set("DAHDI/1-1", "CALLERPRES()=allowed_not_screened") in new stack
   -- Executing [s@from-pstn:9] Goto("DAHDI/1-1", "timeconditions,1,1") in new stack
   -- Goto (timeconditions,1,1)
   -- Executing [1@timeconditions:1] GotoIfTime("DAHDI/1-1", "07:00-22:15|*|*|*?ivr-2,s,1") in new stack
   -- Goto (ivr-2,s,1)
   -- Executing [s@ivr-2:1] Set("DAHDI/1-1", "MSG=custom/you-have-reached") in new stack
   -- Executing [s@ivr-2:2] Set("DAHDI/1-1", "LOOPCOUNT=0") in new stack
   -- Executing [s@ivr-2:3] Set("DAHDI/1-1", "__DIR-CONTEXT=default") in new stack
   -- Executing [s@ivr-2:4] Set("DAHDI/1-1", "_IVR_CONTEXT_ivr-2=") in new stack
   -- Executing [s@ivr-2:5] Set("DAHDI/1-1", "_IVR_CONTEXT=ivr-2") in new stack
   -- Executing [s@ivr-2:6] GotoIf("DAHDI/1-1", "1?begin") in new stack
   -- Goto (ivr-2,s,9)
   -- Executing [s@ivr-2:9] Set("DAHDI/1-1", "TIMEOUT(digit)=3") in new stack
   -- Digit timeout set to 3
   -- Executing [s@ivr-2:10] Set("DAHDI/1-1", "TIMEOUT(response)=10") in new stack
   -- Response timeout set to 10
   -- Executing [s@ivr-2:11] Set("DAHDI/1-1", "__IVR_RETVM=") in new stack
   -- Executing [s@ivr-2:12] ExecIf("DAHDI/1-1", "1?Background(custom/you-have-reached)") in new stack
   -- <DAHDI/1-1> Playing 'custom/you-have-reached.slin' (language 'en')
   -- Executing [s@ivr-2:13] WaitExten("DAHDI/1-1", ",") in new stack
   -- Redirecting DAHDI/1-1 to fax extension
 == Spawn extension (ivr-2, fax, 1) exited non-zero on 'DAHDI/1-1'
   -- Executing [fax@ivr-2:1] Goto("DAHDI/1-1", "ext-fax,in_fax,1") in new stack
   -- Goto (ext-fax,in_fax,1)
   -- Executing [in_fax@ext-fax:1] StopPlayTones("DAHDI/1-1", "") in new stack
   -- Executing [in_fax@ext-fax:2] GotoIf("DAHDI/1-1", "1?3:analog_fax,1") in new stack
   -- Goto (ext-fax,in_fax,3)
   -- Executing [in_fax@ext-fax:3] Macro("DAHDI/1-1", "faxreceive") in new stack
   -- Executing [s@macro-faxreceive:1] NoOp("DAHDI/1-1", "**** FAX RECEIVE ****") in new stack
   -- Executing [s@macro-faxreceive:2] Set("DAHDI/1-1", "FAXFILE=/var/spool/asterisk/fax/1245283050.9-rx.tif") in new stack
   -- Executing [s@macro-faxreceive:3] Set("DAHDI/1-1", "EMAILADDR=xxxx@yyyyyyy.com") in new stack
   -- Executing [s@macro-faxreceive:4] Set("DAHDI/1-1", "GLOBAL(LASTFAXCALLERNUM)=8475551212") in new stack
 == Setting global variable 'LASTFAXCALLERNUM' to '8475551212'
   -- Executing [s@macro-faxreceive:5] Set("DAHDI/1-1", "GLOBAL(LASTFAXCALLERNAME)=ACME Co.") in new stack
 == Setting global variable 'LASTFAXCALLERNAME' to 'ACME Co.'
   -- Executing [s@macro-faxreceive:6] NoOp("DAHDI/1-1", "**** SETTING FAXOPT ****") in new stack
   -- Executing [s@macro-faxreceive:7] Set("DAHDI/1-1", "FAXOPT(ecm)=yes") in new stack
   -- Executing [s@macro-faxreceive:8] Set("DAHDI/1-1", "FAXOPT(headerinfo)=Asterisk FAX RX") in new stack
   -- Executing [s@macro-faxreceive:9] Set("DAHDI/1-1", "FAXOPT(localstationid)=1-847-555-9898") in new stack
   -- Executing [s@macro-faxreceive:10] Set("DAHDI/1-1", "FAXOPT(maxrate)=14400") in new stack
   -- Executing [s@macro-faxreceive:11] Set("DAHDI/1-1", "FAXOPT(minrate)=2400") in new stack
   -- Executing [s@macro-faxreceive:12] NoOp("DAHDI/1-1", "FAXOPT(ecm)  :  yes") in new stack
   -- Executing [s@macro-faxreceive:13] NoOp("DAHDI/1-1", "FAXOPT(headerinfo)  :  Asterisk FAX RX") in new stack
   -- Executing [s@macro-faxreceive:14] NoOp("DAHDI/1-1", "FAXOPT(localstationid)  :  1-847-555-9898") in new stack
   -- Executing [s@macro-faxreceive:15] NoOp("DAHDI/1-1", "FAXOPT(maxrate)  :  14400") in new stack
   -- Executing [s@macro-faxreceive:16] NoOp("DAHDI/1-1", "FAXOPT(minrate)  :  2400") in new stack
   -- Executing [s@macro-faxreceive:17] NoOp("DAHDI/1-1", "**** RECEIVING FAX ****") in new stack
   -- Executing [s@macro-faxreceive:18] ReceiveFAX("DAHDI/1-1", "/var/spool/asterisk/fax/1245283050.9-rx.tif") in new stack
   -- Executing [s@macro-faxreceive:19] NoOp("DAHDI/1-1", "FAXOPT(ecm)  :  no") in new stack
   -- Executing [s@macro-faxreceive:20] NoOp("DAHDI/1-1", "FAXOPT(filename)  :  /var/spool/asterisk/fax/1245283050.9-rx.tif") in new stack
   -- Executing [s@macro-faxreceive:21] NoOp("DAHDI/1-1", "FAXOPT(headerinfo)  :  Asterisk FAX RX") in new stack
   -- Executing [s@macro-faxreceive:22] NoOp("DAHDI/1-1", "FAXOPT(localstationid)  :  1-847-555-9898") in new stack
   -- Executing [s@macro-faxreceive:23] NoOp("DAHDI/1-1", "FAXOPT(maxrate)  :  14400") in new stack
   -- Executing [s@macro-faxreceive:24] NoOp("DAHDI/1-1", "FAXOPT(minrate)  :  2400") in new stack
   -- Executing [s@macro-faxreceive:25] NoOp("DAHDI/1-1", "FAXOPT(pages)  :  0") in new stack
   -- Executing [s@macro-faxreceive:26] NoOp("DAHDI/1-1", "FAXOPT(rate)  :  2400") in new stack
   -- Executing [s@macro-faxreceive:27] NoOp("DAHDI/1-1", "FAXOPT(remotestationid)  :  ") in new stack
   -- Executing [s@macro-faxreceive:28] NoOp("DAHDI/1-1", "FAXOPT(resolution)  :  unknown") in new stack
   -- Executing [s@macro-faxreceive:29] NoOp("DAHDI/1-1", "FAXOPT(status)  :  FAILED") in new stack
   -- Executing [s@macro-faxreceive:30] NoOp("DAHDI/1-1", "FAXOPT(statusstr)  :  FAX_NO_FAX") in new stack
   -- Executing [s@macro-faxreceive:31] NoOp("DAHDI/1-1", "FAXOPT(error)  :  T1_TIMEOUT") in new stack
   -- Executing [in_fax@ext-fax:4] Hangup("DAHDI/1-1", "") in new stack


By: Vladimir Mikhelson (vmikhelson) 2009-06-30 23:36:40

Upgraded res_fax and res_fax_digium.  No change in behavior.

-Vladimir



Fax For Asterisk Components:
       Applications: 1.6.0_1.0.9
       Digium Fax T.38 Driver: 1.6.0_1.0.9 (optimized for pentium3m_32)
       Digium Fax G.711 Driver: 1.6.0_1.0.9 (optimized for pentium3m_32)
By: Vladimir Mikhelson (vmikhelson) 2009-07-01 17:03:18

Here is a little bit more debugging information.

What looks strange that channel.c first switches codec to ulaw as it recognizes a fax transmission. Then down the road it switches back to slin.

-Vladimir


[Jul 1 15:11:49] DEBUG[9322] dsp.c: 1100 Hz done detected
[Jul 1 15:11:49] DEBUG[9322] chan_dahdi.c: DTMF digit: f on DAHDI/1-1
[Jul 1 15:11:49] VERBOSE[9322] logger.c: -- Redirecting DAHDI/1-1 to fax extension
[Jul 1 15:11:49] DEBUG[9322] channel.c: Soft-Hanging up channel 'DAHDI/1-1'
[Jul 1 15:11:49] DEBUG[9322] channel.c: Scheduling timer at 0 sample intervals
[Jul 1 15:11:49] DEBUG[9322] channel.c: Set channel DAHDI/1-1 to write format ulaw

<skipped>

[Jul 1 15:11:49] DEBUG[9322] pbx.c: Launching 'ReceiveFAX'
[Jul 1 15:11:49] VERBOSE[9322] logger.c: -- Executing [s@macro-faxreceive:18] ReceiveFAX("DAHDI/1-1", "/var/spool/asterisk/fax/1246479104.26-rx.tif") in new stack
[Jul 1 15:11:49] DEBUG[9322] res_fax.c: Requesting a new fax session from 'Digium Fax G.711 Driver'.
[Jul 1 15:11:49] DEBUG[9322] res_fax_digium.c: checking channel limits
[Jul 1 15:11:49] DEBUG[9322] res_fax_digium.c: Fax session '2' opened completion pipes (fd0: 30, fd1: 31)
[Jul 1 15:11:49] DEBUG[9322] res_fax_digium.c: AST_FAX_TECH_RECEIVE
[Jul 1 15:11:49] DEBUG[9322] res_fax_digium.c: returning fax session '2' to channel 'DAHDI/1-1'
[Jul 1 15:11:49] DEBUG[9322] res_fax.c: channel 'DAHDI/1-1' using fax session '2'
[Jul 1 15:11:49] DEBUG[9322] channel.c: Set channel DAHDI/1-1 to write format slin
[Jul 1 15:11:49] DEBUG[9322] channel.c: Set channel DAHDI/1-1 to read format slin
[Jul 1 15:11:49] DEBUG[9322] chan_dahdi.c: Requested indication 19 on channel DAHDI/1-1
[Jul 1 15:11:49] DEBUG[9322] res_fax_digium.c: session '2' opened fax handle: 0
[Jul 1 15:11:49] DEBUG[9322] res_fax_digium.c: session '2' created document queue for fax handle: 0
[Jul 1 15:11:49] DEBUG[9322] res_fax_digium.c: session '2' obtained default document parameters for fax handle: 0
[Jul 1 15:11:49] DEBUG[9322] res_fax_digium.c: fax resource: 0 queued '/var/spool/asterisk/fax/1246479104.26-rx.tif' to document queue as document number: 1
[Jul 1 15:11:49] DEBUG[9322] res_fax_digium.c: session '2' obtained default parameters for fax handle: 0
[Jul 1 15:11:49] DEBUG[9322] res_fax_digium.c: channel 'DAHDI/1-1' fax session '2' rates { Tx Min: 2400 -> Tx Max: 14400, Rx Min: 2400 }
[Jul 1 15:11:49] DEBUG[9322] res_fax_digium.c: fax handle: 0 is receiving fax into document queue: 0x9506938
[Jul 1 15:11:49] WARNING[9322] frame.c: Smoother was working on 4 format frames, now trying to feed 64?
[Jul 1 15:11:49] ERROR[9322] res_fax.c: channel 'DAHDI/1-1' fax session '2' failure, reason: 'Failed to feed the smoother'
[Jul 1 15:11:49] DEBUG[9322] res_fax.c: channel 'DAHDI/1-1' - event loop stopped { timeout: 10000, ms: -1, res: -1 }
[Jul 1 15:11:49] DEBUG[9322] res_fax_digium.c: destroying session '0' thread
[Jul 1 15:11:49] DEBUG[9323] res_fax_digium.c: fax channel: 0, resource: 0x9500090, event: EVN_RECEIVE_STARTED (0x3F3), event data: 0x0
By: Kevin P. Fleming (kpfleming) 2009-07-14 18:29:39

You are not using app_fax, you are using Fax For Asterisk. FFA issues must be reported to Digium technical support, not in the open source issue tracker, since it is not part of open source Asterisk.