[asterisk-users] rxfax() problem - fax signal seems to be ignored

[Pirlouwi]

Hello,
my configuration is the following:
a TDM400P board with an fxs and fxo daughter boards on it.

I thus connect a fax to my FXS port, after having verified that this port
was correctly functioning. For this, I had tried before with a simple phone,
and with some basic voicemail exten scripts.

Here is my simple dialplan for my fax reception:
exten => 300,1,Ringing()
exten => 300,n,Answer()
exten => 300,n,Set(FAXFILE=/tmp/test.tif)
exten => 300,n,rxfax(${FAXFILE}||debug)

I then dialed 300 on my fax machine, and expected to be lucky and to obtain
a /tmp/test.tif file after faxing completion.
But instead, I always got such error in the /var/log/asterisk/full log file:

[Sep  5 13:42:21] DEBUG[1272] chan_zap.c: Monitor doohicky got event
Ring/Answered on channel 1
[Sep  5 13:42:21] VERBOSE[1298] logger.c:     -- Starting simple switch on
'Zap/1-1'
[Sep  5 13:42:22] DEBUG[1298] chan_zap.c: DTMF digit: 3 on Zap/1-1
[Sep  5 13:42:23] DEBUG[1298] chan_zap.c: DTMF digit: 0 on Zap/1-1
[Sep  5 13:42:24] DEBUG[1298] chan_zap.c: DTMF digit: 0 on Zap/1-1
[Sep  5 13:42:24] DEBUG[1298] devicestate.c: Notification of state change to
be queued on device/channel Zap/1-1
[Sep  5 13:42:24] DEBUG[1298] chan_zap.c: Enabled echo cancellation on
channel 1
[Sep  5 13:42:24] DEBUG[1298] pbx.c: Launching 'Ringing'
[Sep  5 13:42:24] VERBOSE[1298] logger.c:     -- Executing [300 at Internal:1]
Ringing("Zap/1-1", "") in new stack
[Sep  5 13:42:24] DEBUG[1298] chan_zap.c: Requested indication 3 on channel
Zap/1-1
[Sep  5 13:42:24] DEBUG[1298] devicestate.c: Notification of state change to
be queued on device/channel Zap/1-1
[Sep  5 13:42:24] DEBUG[1298] pbx.c: Launching 'Answer'
[Sep  5 13:42:24] VERBOSE[1298] logger.c:     -- Executing [300 at Internal:2]
Answer("Zap/1-1", "") in new stack
[Sep  5 13:42:24] DEBUG[1298] devicestate.c: Notification of state change to
be queued on device/channel Zap/1-1
[Sep  5 13:42:24] DEBUG[1298] chan_zap.c: Took Zap/1-1 off hook
[Sep  5 13:42:24] DEBUG[1298] pbx.c: Launching 'Set'
[Sep  5 13:42:24] VERBOSE[1298] logger.c:     -- Executing [300 at Internal:3]
Set("Zap/1-1", "FAXFILE=/tmp/test.tif") in new stack
[Sep  5 13:42:24] DEBUG[1298] pbx.c: Launching 'RxFAX'
[Sep  5 13:42:24] VERBOSE[1298] logger.c:     -- Executing [ 300 at Internal:4]
RxFAX("Zap/1-1", "/tmp/test.tif||debug") in new stack
[Sep  5 13:42:24] DEBUG[1298] channel.c: Set channel Zap/1-1 to read format
slin
[Sep  5 13:42:24] DEBUG[1298] channel.c: Set channel Zap/1-1 to write format
slin
[Sep  5 13:42:24] DEBUG[1270] devicestate.c: No provider found, checking
channel drivers for Zap - 1
[Sep  5 13:42:24] DEBUG[1270] devicestate.c: Changing state for Zap/1 -
state 2 (In use)
[Sep  5 13:42:24] DEBUG[1270] devicestate.c: No provider found, checking
channel drivers for Zap - 1
[Sep  5 13:42:24] DEBUG[1270] devicestate.c: Changing state for Zap/1 -
state 2 (In use)
[Sep  5 13:42:24] DEBUG[1270] devicestate.c: No provider found, checking
channel drivers for Zap - 1
[Sep  5 13:42:24] DEBUG[1270] devicestate.c: Changing state for Zap/1 -
state 2 (In use)
[Sep  5 13:42:24] DEBUG[1299] app_queue.c: Device 'Zap/1' changed to state
'2' (In use) but we don't care because they're not a member of any queue.
[Sep  5 13:42:24] DEBUG[1300] app_queue.c: Device 'Zap/1' changed to state
'2' (In use) but we don't care because they're not a member of any queue.
[Sep  5 13:42:24] DEBUG[1301] app_queue.c: Device 'Zap/1' changed to state
'2' (In use) but we don't care because they're not a member of any queue.
[Sep  5 13:43:09] DEBUG[1298] chan_zap.c: Exception on 8, channel 1
[Sep  5 13:43:09] DEBUG[1298] chan_zap.c: Got event On hook(1) on channel 1
(index 0)
[Sep  5 13:43:09] DEBUG[1298] chan_zap.c: disabled echo cancellation on
channel 1
[Sep  5 13:43:09] DEBUG[1298] app_rxfax.c: Got hangup
[Sep  5 13:43:09] DEBUG[1298] channel.c: Set channel Zap/1-1 to read format
ulaw
[Sep  5 13:43:09] DEBUG[1298] channel.c: Set channel Zap/1-1 to write format
ulaw
[Sep  5 13:43:09] DEBUG[1298] app_rxfax.c:
==================================================
[Sep  5 13:43:09] DEBUG[1298] app_rxfax.c: Fax receive not successful -
result (51) The call dropped prematurely.
[Sep  5 13:43:09] DEBUG[1298] app_rxfax.c:
==================================================
[Sep  5 13:43:09] DEBUG[1298] app_rxfax.c: FLOW FAX Set rx type 13
[Sep  5 13:43:09] DEBUG[1298] app_rxfax.c: FLOW FAX FAX exchange complete
[Sep  5 13:43:09] DEBUG[1298] app_rxfax.c: FLOW FAX Set tx type 13
[Sep  5 13:43:09] DEBUG[1298] app_rxfax.c: FLOW FAX FAX exchange complete
[Sep  5 13:43:09] DEBUG[1298] pbx.c: Extension 300, priority 4 returned
normally even though call was hung up
[Sep  5 13:43:09] DEBUG[1298] channel.c: Soft-Hanging up channel 'Zap/1-1'
[Sep  5 13:43:09] DEBUG[1298] channel.c : Hanging up channel 'Zap/1-1'
[Sep  5 13:43:09] DEBUG[1298] chan_zap.c: zt_hangup(Zap/1-1)
[Sep  5 13:43:09] DEBUG[1298] chan_zap.c: Hangup: channel: 1 index = 0,
normal = 8, callwait = -1, thirdcall = -1
[Sep  5 13:43:09] DEBUG[1298] chan_zap.c: disabled echo cancellation on
channel 1
[Sep  5 13:43:09] DEBUG[1298] chan_zap.c: Set option TDD MODE, value: OFF(0)
on Zap/1-1
[Sep  5 13:43:09] DEBUG[1298] chan_zap.c: Updated conferencing on 1, with 0
conference users
[Sep  5 13:43:09] VERBOSE[1298] logger.c:     -- Hungup 'Zap/1-1'
[Sep  5 13:43:09] DEBUG[1298] devicestate.c: Notification of state change to
be queued on device/channel Zap/1-1
[Sep  5 13:43:09] DEBUG[1270] devicestate.c: No provider found, checking
channel drivers for Zap - 1
[Sep  5 13:43:09] DEBUG[1270] devicestate.c: Changing state for Zap/1 -
state 0 (Unknown)
[Sep  5 13:43:09] DEBUG[1303] app_queue.c: Device 'Zap/1' changed to state
'0' (Unknown) but we don't care because they're not a member of any queue.
[Sep  5 13:43:10] DEBUG[1272] chan_zap.c: Monitor doohicky got event Hook
Transition Complete on channel 1

I have enabled the #define LOG_FAX_AUDIO inside spandsp library, and two
audio files (fax-rx-audio-b7933500-070905134224 and
fax-tx-audio-b7933500-070905134224) appeared in /tmp.

I used Cool96 (an old Win98 free program) to import this audio data (8KHz
mono 16bit PCM-Intel), and it appears that there is currently no fax
synchronisation nor negotiation at all.
All I see in Cool96 is that the fax send its CNG (a 1100Hz tone during
0.5severy 3 seconds), and that Asterisk application app_rxfax() answer
with an
exactly identical tone.
I am not very specialist of T.30 protocol, but I thought that in this case
SPANDSP would have answered with a CED tone (a 2100Hz tone during 2.5s),
like explained here (http://www.eicon.com/support/helpweb/dssdk/i200.htm)

This is not the case in my setup. What did I wrong?
Thx for your help.
--Pirlouwi
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.digium.com/pipermail/asterisk-users/attachments/20070905/bfdc7833/attachment.htm