[Asterisk-Users] Asterisk spanDSP / Faxing problem

Juan Jose Comellas juanjo at comellas.com.ar
Sun Mar 26 06:20:25 MST 2006 

For us it takes about 6 seconds to detect fax tones, so you should change your 
dialplan to either play and audio while detecting fax tones 
(NVBackgroundDetect) or Wait for at least 6-7 seconds if using a Zaptel 
channel.

On Sat March 25 2006 08:56, Thys de Wet wrote:
> Hi There.
> I have the following setup :
> Asterisk 1.2.4 , freePBX 2.0.1, spandsp-0.0.2pre24
>
> My problem is as follows :
> If I set up a very simple extensions.conf. when I dial from a fax
> machine, it seems as if no fax is being recognised.
> If I answer the call, I can hear the fax machine beeping.
>
>
>
> extensions.conf :
> ---------------------------------------------------------------------------
>-------------------------------- [from-pstn]
>  ; Answer the line and listen
>  exten => s,1,Answer
>  ; Dial an extension, let asterisk give a ringtone
>  exten => s,2,Dial(SIP/3000,40,r)
>  ; Hangup if nobody picked up within 40 seconds
>  exten => s,3,Hangup
>
>  ; Did we get a fax?   <--------------------------Seems as if we never
> get this far :(((((
>  exten => fax,1,SetVar(FAXFILE=/var/spool/asterisk-fax/${UNIQUEID}.tif)
>  exten => fax,2,rxfax(${FAXFILE}|debug)
> ---------------------------------------------------------------------------
>---------------------------------- zapata.conf :
> ---------------------------------------------------------------------------
>---------------------------------- [trunkgroups]
> ; define any trunk groups
> [channels]
> ; hardware channels
> ; default
> usecallerid=yes
> hidecallerid=no
> callwaiting=no
> threewaycalling=yes
> transfer=yes
> echocancel=yes
> echotraining=yes
>
> faxdetect=both
> busydetect=yes
> busycount=4
> busypattern=500,500
> callprogress=no
>
>
> ; define channels
> context=from-pstn ;
> signalling=fxs_ls ;
> channel=>1-3 ;
>
> context=aa_1 ;
> signalling=fxs_ls ;
> channel=>4 ;
> ---------------------------------------------------------------------------
>-----------------------------------------------------------------------
> Output from asterisk log :
>
> Mar 25 13:45:16 VERBOSE[17282] logger.c:     -- Starting simple switch
> on 'Zap/1-1'
> Mar 25 13:45:18 NOTICE[17282] chan_zap.c: Got event 18 (Ring Begin)...
> Mar 25 13:45:19 NOTICE[17282] chan_zap.c: Got event 2 (Ring/Answered)...
> Mar 25 13:45:21 NOTICE[17282] chan_zap.c: Got event 18 (Ring Begin)...
> Mar 25 13:45:21 VERBOSE[17282] logger.c:     -- Executing
> Answer("Zap/1-1", "") in new stack
> Mar 25 13:45:21 DEBUG[17282] chan_zap.c: Took Zap/1-1 off hook
> Mar 25 13:45:21 DEBUG[17282] chan_zap.c: Enabled echo cancellation on
> channel 1
> Mar 25 13:45:21 DEBUG[17282] chan_zap.c: Engaged echo training on channel 1
> Mar 25 13:45:21 VERBOSE[17282] logger.c:     -- Executing
> Dial("Zap/1-1", "SIP/3000|40|r") in new stack
> Mar 25 13:45:21 DEBUG[17282] chan_sip.c: Setting NAT on RTP to 0
> Mar 25 13:45:21 DEBUG[17282] chan_sip.c: Outgoing Call for 3000
> Mar 25 13:45:21 VERBOSE[17282] logger.c:     -- Called 3000
> Mar 25 13:45:21 DEBUG[17282] chan_zap.c: Requested indication 3 on
> channel Zap/1-1
> Mar 25 13:45:21 DEBUG[17229] chan_sip.c: (Provisional) Stopping
> retransmission (but retaining packet) on
> '5f8bf93a4e7e14fa4b9c2319609192c6 at 192.168.1.76' Request 102: Found
> Mar 25 13:45:21 DEBUG[17229] chan_sip.c: (Provisional) Stopping
> retransmission (but retaining packet) on
> '5f8bf93a4e7e14fa4b9c2319609192c6 at 192.168.1.76' Request 102: Found
> Mar 25 13:45:21 VERBOSE[17282] logger.c:     -- SIP/3000-dbc4 is ringing
> Mar 25 13:45:21 DEBUG[17222] channel.c: Avoiding initial deadlock for
> 'SIP/3000-dbc4'
> Mar 25 13:45:29 DEBUG[17229] chan_sip.c: Acked pending invite 102
> Mar 25 13:45:29 DEBUG[17229] chan_sip.c: Stopping retransmission on
> '5f8bf93a4e7e14fa4b9c2319609192c6 at 192.168.1.76' of Request 102: Match Found
> Mar 25 13:45:29 DEBUG[17229] chan_sip.c: build_route: Contact hop:
> <sip:3000 at 192.168.1.74>
> Mar 25 13:45:29 VERBOSE[17282] logger.c:     -- SIP/3000-dbc4 answered
> Zap/1-1
> Mar 25 13:45:29 DEBUG[17282] chan_zap.c: Requested indication -1 on
> channel Zap/1-1
> Mar 25 13:45:50 DEBUG[17282] channel.c: Didn't get a frame from channel:
> SIP/3000-dbc4
> Mar 25 13:45:50 DEBUG[17282] channel.c: Bridge stops bridging channels
> Zap/1-1 and SIP/3000-dbc4
> Mar 25 13:45:50 DEBUG[17282] chan_sip.c: update_call_counter(3000) -
> decrement call limit counter
> Mar 25 13:45:50 DEBUG[17282] app_dial.c: Exiting with DIALSTATUS=ANSWER.
> Mar 25 13:45:50 VERBOSE[17282] logger.c:   == Spawn extension
> (from-pstn, s, 2) exited non-zero on 'Zap/1-1'
> Mar 25 13:45:50 DEBUG[17282] cdr_addon_mysql.c: cdr_mysql: inserting a
> CDR record.
> Mar 25 13:45:50 DEBUG[17282] cdr_addon_mysql.c: cdr_mysql: SQL command
> as follows: INSERT INTO cdr
> (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duratio
>n,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2006-03-25
> 13:45:21','','','s','from-pstn',
> 'Zap/1-1','SIP/3000-dbc4','Dial','SIP/3000|40|r',29,29,'ANSWERED',3,'','114
>3287116.0') Mar 25 13:45:50 DEBUG[17282] chan_zap.c: Hangup: channel: 1
> index = 0, normal = 10, callwait = -1, thirdcall = -1
> Mar 25 13:45:50 DEBUG[17282] chan_zap.c: disabled echo cancellation on
> channel 1
> Mar 25 13:45:50 DEBUG[17282] chan_zap.c: Set option TDD MODE, value:
> OFF(0) on Zap/1-1
> Mar 25 13:45:50 DEBUG[17282] chan_zap.c: Updated conferencing on 1, with
> 0 conference users
> Mar 25 13:45:50 VERBOSE[17282] logger.c:     -- Hungup 'Zap/1-1'
> ---------------------------------------------------------------------------
>----------------------------------------------------------------------------
>----------------------
>
>
> If I change extensions.conf to read as follows :
>
> exten => s,1,Answer
> exten => s,2,AbsoluteTimeout(35)
> exten => s,3,Set(FAXFILE=/var/spool/asterisk-fax/${UNIQUEID}.tif)
> exten => s,4,rxfax(${FAXFILE}|debug)
> exten => T,1,Hangup()
>
> The call gets answered, but I get the following in the log :
>
> Mar 25 13:53:42 DEBUG[17449] dsp.c: dsp busy pattern set to 500,500
> Mar 25 13:53:42 VERBOSE[17501] logger.c:     -- Starting simple switch
> on 'Zap/1-1'
> Mar 25 13:53:43 NOTICE[17501] chan_zap.c: Got event 18 (Ring Begin)...
> Mar 25 13:53:44 NOTICE[17501] chan_zap.c: Got event 2 (Ring/Answered)...
> Mar 25 13:53:44 NOTICE[17501] chan_zap.c: Got event 18 (Ring Begin)...
> Mar 25 13:53:45 NOTICE[17501] chan_zap.c: Got event 2 (Ring/Answered)...
> Mar 25 13:53:46 NOTICE[17501] chan_zap.c: Got event 18 (Ring Begin)...
> Mar 25 13:53:46 VERBOSE[17501] logger.c:     -- Executing
> Answer("Zap/1-1", "") in new stack
> Mar 25 13:53:46 DEBUG[17501] chan_zap.c: Took Zap/1-1 off hook
> Mar 25 13:53:46 DEBUG[17501] chan_zap.c: Enabled echo cancellation on
> channel 1
> Mar 25 13:53:46 DEBUG[17501] chan_zap.c: Engaged echo training on channel 1
> Mar 25 13:53:46 VERBOSE[17501] logger.c:     -- Executing
> AbsoluteTimeout("Zap/1-1", "35") in new stack
> Mar 25 13:53:46 WARNING[17501] pbx.c: AbsoluteTimeout is deprecated,
> please use Set(TIMEOUT(absolute)=timeout) instead.
> Mar 25 13:53:46 VERBOSE[17501] logger.c:     -- Set Absolute Timeout to 35
> Mar 25 13:53:46 VERBOSE[17501] logger.c:     -- Executing Set("Zap/1-1",
> "FAXFILE=/var/spool/asterisk-fax/1143287622.0.tif") in new stack
> Mar 25 13:53:46 VERBOSE[17501] logger.c:     -- Executing
> RxFAX("Zap/1-1", "/var/spool/asterisk-fax/1143287622.0.tif|debug") in
> new stack
> Mar 25 13:53:46 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier up
> Mar 25 13:53:46 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier down
> Mar 25 13:53:47 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier up
> Mar 25 13:53:47 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier down
> Mar 25 13:53:47 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier up
> Mar 25 13:53:47 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier down
> Mar 25 13:53:47 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier up
> Mar 25 13:53:47 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier down
> Mar 25 13:53:47 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier up
> Mar 25 13:53:47 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier down
> Mar 25 13:53:47 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier up
> Mar 25 13:53:47 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier down
> Mar 25 13:53:47 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier up
> Mar 25 13:53:47 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier down
> Mar 25 13:53:48 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier up
> Mar 25 13:53:48 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier down
> Mar 25 13:53:48 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier up
> Mar 25 13:53:48 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier down
> Mar 25 13:53:48 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier up
> Mar 25 13:53:48 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier down
> Mar 25 13:53:49 DEBUG[17501] app_rxfax.c: FLOW Changed from phase 1 to 4
> Mar 25 13:53:49 DEBUG[17501] app_rxfax.c: FLOW >>> DIS:Mar 25 13:53:49
> DEBUG[17501] app_rxfax.c:  80Mar 25 13:53:49 DEBUG[17501] app_rxfax.c:
> 00Mar 25 13:53:49 DEBUG[17501] app_rxfax.c:  ceMar 25 13:53:49
> DEBUG[17501] app_rxfax.c:  f4Mar 25 13:53:49 DEBUG[17501] app_rxfax.c:
> 80Mar 25 13:53:49 DEBUG[17501] app_rxfax.c:  80Mar 25 13:53:49
> DEBUG[17501] app_rxfax.c:  81Mar 25 13:53:49 DEBUG[17501] app_rxfax.c:
> 80Mar 25 13:53:49 DEBUG[17501] app_rxfax.c:  80Mar 25 13:53:49
> DEBUG[17501] app_rxfax.c:  80Mar 25 13:53:49 DEBUG[17501] app_rxfax.c:
> 18Mar 25 13:53:49 DEBUG[17501] app_rxfax.c:
> Mar 25 13:53:51 DEBUG[17501] app_rxfax.c: FLOW HDLC underflow in state 9
> Mar 25 13:53:51 DEBUG[17501] app_rxfax.c: FLOW Changed from phase 4 to 3
> Mar 25 13:53:51 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier up
> Mar 25 13:53:51 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier down
> Mar 25 13:53:51 DEBUG[17501] app_rxfax.c: FLOW HDLC carrier up
> Mar 25 13:53:51 DEBUG[17501] app_rxfax.c: FLOW HDLC framing OK
> Mar 25 13:53:53 DEBUG[17501] app_rxfax.c: FLOW <<< TSI:Mar 25 13:53:53
> DEBUG[17501] app_rxfax.c:  43Mar 25 13:53:53 DEBUG[17501] app_rxfax.c:
> 39Mar 25 13:53:53 DEBUG[17501] app_rxfax.c:  32Mar 25 13:53:53
> DEBUG[17501] app_rxfax.c:  32Mar 25 13:53:53 DEBUG[17501] app_rxfax.c:
> 32Mar 25 13:53:53 DEBUG[17501] app_rxfax.c:  36Mar 25 13:53:53
> DEBUG[17501] app_rxfax.c:  32Mar 25 13:53:53 DEBUG[17501] app_rxfax.c:
> 34Mar 25 13:53:53 DEBUG[17501] app_rxfax.c:  2bMar 25 13:53:53
> DEBUG[17501] app_rxfax.c:  31Mar 25 13:53:53 DEBUG[17501] app_rxfax.c:
> 32Mar 25 13:53:53 DEBUG[17501] app_rxfax.c:  30Mar 25 13:53:53
> DEBUG[17501] app_rxfax.c:  20Mar 25 13:53:53 DEBUG[17501] app_rxfax.c:
> 20Mar 25 13:53:53 DEBUG[17501] app_rxfax.c:  20Mar 25 13:53:53
> DEBUG[17501] app_rxfax.c:  20Mar 25 13:53:53 DEBUG[17501] app_rxfax.c:
> 20Mar 25 13:53:53 DEBUG[17501] app_rxfax.c:  20Mar 25 13:53:53
> DEBUG[17501] app_rxfax.c:  20Mar 25 13:53:53 DEBUG[17501] app_rxfax.c:
> 20Mar 25 13:53:53 DEBUG[17501] app_rxfax.c:  20Mar 25 13:53:53
> DEBUG[17501] app_rxfax.c:
> Mar 25 13:53:53 DEBUG[17501] app_rxfax.c: FLOW TSI without final frame tag
> Mar 25 13:53:53 DEBUG[17501] app_rxfax.c: FLOW Remote fax gave TSI as:
> "021+4262229"
> Mar 25 13:53:53 DEBUG[17501] app_rxfax.c: FLOW <<< DCS:Mar 25 13:53:53
> DEBUG[17501] app_rxfax.c:  83Mar 25 13:53:53 DEBUG[17501] app_rxfax.c:
> 00Mar 25 13:53:53 DEBUG[17501] app_rxfax.c:  86Mar 25 13:53:53
> DEBUG[17501] app_rxfax.c:  a4Mar 25 13:53:53 DEBUG[17501] app_rxfax.c:
> 00Mar 25 13:53:53 DEBUG[17501] app_rxfax.c:
> Mar 25 13:53:53 DEBUG[17501] app_rxfax.c: FLOW DCS with final frame tag
> Mar 25 13:53:53 DEBUG[17501] app_rxfax.c: FLOW In state 9
> Mar 25 13:53:53 DEBUG[17501] app_rxfax.c: FLOW Get at 9600bps, modem 1
> Mar 25 13:53:53 DEBUG[17501] app_rxfax.c: FLOW Changed from phase 3 to 5
> Mar 25 13:53:53 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier up
> Mar 25 13:53:53 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier training
> failed
> Mar 25 13:53:55 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier down
> Mar 25 13:53:58 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier up
> Mar 25 13:53:58 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier training
> failed
> Mar 25 13:54:00 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier down
> Mar 25 13:54:00 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier up
> Mar 25 13:54:00 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier training
> failed
> Mar 25 13:54:02 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier down
> Mar 25 13:54:04 DEBUG[17450] chan_sip.c: Stopping retransmission on
> '76a78ede698fa5e658232143526319d9 at 192.168.1.76' of Request 102: Match Found
> Mar 25 13:54:05 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier up
> Mar 25 13:54:05 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier training
> failed
> Mar 25 13:54:07 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier down
> Mar 25 13:54:07 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier up
> Mar 25 13:54:07 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier training
> failed
> Mar 25 13:54:09 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier down
> Mar 25 13:54:12 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier up
> Mar 25 13:54:12 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier training
> failed
> Mar 25 13:54:13 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier down
> Mar 25 13:54:13 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier up
> Mar 25 13:54:13 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier down
> Mar 25 13:54:14 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier up
> Mar 25 13:54:14 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier training
> failed
> Mar 25 13:54:14 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier down
> Mar 25 13:54:15 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier up
> Mar 25 13:54:15 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier training
> failed
> Mar 25 13:54:15 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier down
> Mar 25 13:54:16 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier up
> Mar 25 13:54:16 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier training
> failed
> Mar 25 13:54:16 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier down
> Mar 25 13:54:17 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier up
> Mar 25 13:54:17 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier training
> failed
> Mar 25 13:54:17 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier down
> Mar 25 13:54:18 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier up
> Mar 25 13:54:18 DEBUG[17501] app_rxfax.c: FLOW Non-ECM carrier training
> failed
> Mar 25 13:54:18 DEBUG[17501] dsp.c: ast_dsp_busydetect detected busy,
> avgtone: 500, avgsilence 500
> Mar 25 13:54:18 DEBUG[17501] dsp.c: Requesting Hangup because the busy
> tone was detected on channel Zap/1-1
> Mar 25 13:54:18 DEBUG[17501] app_rxfax.c: Got hangup
> Mar 25 13:54:18 DEBUG[17501] pbx.c: Extension s, priority 4 returned
> normally even though call was hung up
> Mar 25 13:54:18 DEBUG[17501] cdr_addon_mysql.c: cdr_mysql: inserting a
> CDR record.
> Mar 25 13:54:18 DEBUG[17501] cdr_addon_mysql.c: cdr_mysql: SQL command
> as follows: INSERT INTO cdr
> (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duratio
>n,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2006-03-25
> 13:53:46','','','s','from-pstn',
> 'Zap/1-1','','RxFAX','/var/spool/asterisk-fax/1143287622.0.tif|debug',32,32
>,'ANSWERED',3,'','1143287622.0') Mar 25 13:54:18 DEBUG[17501] chan_zap.c:
> Hangup: channel: 1 index = 0, normal = 10, callwait = -1, thirdcall = -1
> Mar 25 13:54:18 DEBUG[17501] chan_zap.c: disabled echo cancellation on
> channel 1
> Mar 25 13:54:18 DEBUG[17501] chan_zap.c: Set option TDD MODE, value:
> OFF(0) on Zap/1-1
> Mar 25 13:54:18 DEBUG[17501] chan_zap.c: Updated conferencing on 1, with
> 0 conference users
> Mar 25 13:54:18 VERBOSE[17501] logger.c:     -- Hungup 'Zap/1-1'
>
> I have received a fax from a different machine with this config, but I
> would like to be able to have the faxes pulled out from incoming calls
> and voice going to a digital receptionist .
>
> Thanx
> Thys de Wet
> Cape Town
> South Africa
>
>
>
> _______________________________________________
> --Bandwidth and Colocation provided by Easynews.com --
>
> Asterisk-Users mailing list
> To UNSUBSCRIBE or update options visit:
>    http://lists.digium.com/mailman/listinfo/asterisk-users

-- 
Juan Jose Comellas
(juanjo at comellas.com.ar)

More information about the asterisk-users mailing list