[hylafax-users] HylaFAX 4.4.2 - IAXmodem 0.3.2 - NO CARRIER after AT+FRH=3

[Philipp Bauer <p.bauer@xxxxxxxxxxxxxx>]

Hi everybody,

i am an experienced Asterisk user/developer
but totally new to HylaFAX/IAXmodem - i spent the last 2 days
to get it to work - unfortunately without
success! I already googled the web and scanned every available FAQ / forum.

My problem:

Everytime i receive a fax the communication
aborts with the message "NO CARRIER" after sending an AT+FRH=3

My environment:

CentOS 5        
 (kernel 2.6.18-8.1.15)
Asterisk 1.4.13
HylaFAX 4.4.2     (hylafax-4.4.2-1rhel5.i386.rpm)
IAXmodem 0.3.2    (iaxmodem-0.3.2.tar.gz)

- iaxmodem compiled
- copied to /usr/bin
- included iaxmodem in /etc/inittab
(im00:23:respawn:/usr/bin/iaxmodem ttyIAX0)
- started via "init q"

- hylafax-rpm installed
- faxsetup performed with almost all
default parameters (except my faxnumber, prefixes & trace level)
- included faxgetty in /etc/inittab
(fg00:23:respawn:/usr/sbin/faxgetty ttyIAX0)
- startetd via "init q"

- all relevant processes running? (ps
aux)
  uucp      5347
 0.0  0.2   6712  1208 ?        Ss
  14:12   0:00 /usr/sbin/faxq
  uucp      5350
 0.0  0.1   4312   864 ?        Ss
  14:12   0:00 /usr/sbin/hfaxd -i hylafax
  uucp      5356
 0.0  0.3   4772  1800 ?        Ss
  14:12   0:00 /usr/sbin/faxgetty ttyIAX0
  uucp      4846
 0.0  0.1   2952   976 pts/2    Ss+  14:04
  0:00 /usr/bin/iaxmodem ttyIAX0

- my first try to receive a fax from
our ISPs fax server ended as follows
  Nov 11 14:23:44.58: [ 5398]:
SESSION BEGIN 000000001 43720007703
  Nov 11 14:23:44.58: [ 5398]:
HylaFAX (tm) Version 4.4.2
  Nov 11 14:23:44.58: [ 5398]:
CallID: "07208900001" "" "<NONE>" "s"
  Nov 11 14:23:44.58: [ 5398]:
MODEM set XON/XOFF/FLUSH: input ignored, output disabled
  Nov 11 14:23:44.58: [ 5398]:
<-- [4:ATA\r]
  Nov 11 14:23:48.30: [ 5398]:
--> [7:CONNECT]
  Nov 11 14:23:48.30: [ 5398]:
ANSWER: FAX CONNECTION  DEVICE '/dev/ttyIAX0'
  Nov 11 14:23:48.30: [ 5398]:
RECV FAX: begin
  Nov 11 14:23:48.30: [ 5398]:
<-- data [32]
  Nov 11 14:23:48.30: [ 5398]:
<-- data [2]
  Nov 11 14:23:49.22: [ 5398]:
--> [7:CONNECT]
  Nov 11 14:23:49.22: [ 5398]:
<-- data [23]
  Nov 11 14:23:49.22: [ 5398]:
<-- data [2]
  Nov 11 14:23:49.98: [ 5398]:
--> [7:CONNECT]
  Nov 11 14:23:49.98: [ 5398]:
<-- data [13]
  Nov 11 14:23:49.98: [ 5398]:
<-- data [2]
  Nov 11 14:23:50.56: [ 5398]:
--> [2:OK]
  Nov 11 14:23:50.56: [ 5398]:
<-- [9:AT+FRH=3\r]
  Nov 11 14:23:57.56: [ 5398]:
--> [0:]
  Nov 11 14:23:57.56: [ 5398]:
MODEM <Empty line>
  Nov 11 14:23:57.56: [ 5398]:
MODEM TIMEOUT: waiting for v.21 carrier
  Nov 11 14:23:57.56: [ 5398]:
<-- data [1]
  Nov 11 14:23:57.56: [ 5398]:
--> [2:OK]
  Nov 11 14:23:57.56: [ 5398]:
<-- [9:AT+FRS=7\r]
  Nov 11 14:24:13.23: [ 5398]:
--> [10:NO CARRIER]
  Nov 11 14:24:13.23: [ 5398]:
MODEM No carrier
  Nov 11 14:24:13.23: [ 5398]:
Failure to receive silence (synchronization failure).
  Nov 11 14:24:13.23: [ 5398]:
RECV FAX: Failure to receive silence (synchronization failure).
  Nov 11 14:24:13.23: [ 5398]:
RECV FAX: end
  Nov 11 14:24:13.23: [ 5398]:
Failure to receive silence (synchronization failure).
  Nov 11 14:24:13.23: [ 5398]:
SESSION END

- so i searched the web, found an adequate
fix for my config.ttyIAX0...
  Class1PPMWaitCmd:   "<delay:7>"
  Class1TCFWaitCmd:   "<delay:7>"
  Class1EOPWaitCmd:   "<delay:9>"
  Class1SwitchingCmd: "<delay:7>"

- ...and retried
  Nov 11 14:36:09.83: [ 5464]:
SESSION BEGIN 000000004 43720007703
  Nov 11 14:36:09.83: [ 5464]:
HylaFAX (tm) Version 4.4.2
  Nov 11 14:36:09.83: [ 5464]:
CallID: "07208900001" "" "<NONE>" "s"
  Nov 11 14:36:09.83: [ 5464]:
MODEM set XON/XOFF/FLUSH: input ignored, output disabled
  Nov 11 14:36:09.83: [ 5464]:
<-- [4:ATA\r]
  Nov 11 14:36:13.56: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:36:13.56: [ 5464]:
ANSWER: FAX CONNECTION  DEVICE '/dev/ttyIAX0'
  Nov 11 14:36:13.56: [ 5464]:
RECV FAX: begin
  Nov 11 14:36:13.56: [ 5464]:
<-- data [32]
  Nov 11 14:36:13.56: [ 5464]:
<-- data [2]
  Nov 11 14:36:14.52: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:36:14.52: [ 5464]:
<-- data [23]
  Nov 11 14:36:14.52: [ 5464]:
<-- data [2]
  Nov 11 14:36:15.26: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:36:15.26: [ 5464]:
<-- data [13]
  Nov 11 14:36:15.26: [ 5464]:
<-- data [2]
  Nov 11 14:36:15.84: [ 5464]:
--> [2:OK]
  Nov 11 14:36:15.84: [ 5464]:
<-- [9:AT+FRH=3\r]
  Nov 11 14:36:22.84: [ 5464]:
--> [0:]
  Nov 11 14:36:22.84: [ 5464]:
MODEM <Empty line>
  Nov 11 14:36:22.84: [ 5464]:
MODEM TIMEOUT: waiting for v.21 carrier
  Nov 11 14:36:22.84: [ 5464]:
<-- data [1]
  Nov 11 14:36:22.84: [ 5464]:
--> [2:OK]
  Nov 11 14:36:22.84: [ 5464]:
DELAY 70 ms
  Nov 11 14:36:22.91: [ 5464]:
<-- [9:AT+FTH=3\r]
  Nov 11 14:36:22.92: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:36:22.92: [ 5464]:
<-- data [32]
  Nov 11 14:36:22.92: [ 5464]:
<-- data [2]
  Nov 11 14:36:24.70: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:36:24.70: [ 5464]:
<-- data [23]
  Nov 11 14:36:24.70: [ 5464]:
<-- data [2]
  Nov 11 14:36:25.44: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:36:25.44: [ 5464]:
<-- data [13]
  Nov 11 14:36:25.44: [ 5464]:
<-- data [2]
  Nov 11 14:36:26.02: [ 5464]:
--> [2:OK]
  Nov 11 14:36:26.02: [ 5464]:
<-- [9:AT+FRH=3\r]
  Nov 11 14:36:33.02: [ 5464]:
--> [0:]
  Nov 11 14:36:33.02: [ 5464]:
MODEM <Empty line>
  Nov 11 14:36:33.02: [ 5464]:
MODEM TIMEOUT: waiting for v.21 carrier
  Nov 11 14:36:33.02: [ 5464]:
<-- data [1]
  Nov 11 14:36:33.02: [ 5464]:
--> [2:OK]
  Nov 11 14:36:33.02: [ 5464]:
DELAY 70 ms
  Nov 11 14:36:33.09: [ 5464]:
<-- [9:AT+FTH=3\r]
  Nov 11 14:36:33.10: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:36:33.10: [ 5464]:
<-- data [32]
  Nov 11 14:36:33.10: [ 5464]:
<-- data [2]
  Nov 11 14:36:34.88: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:36:34.88: [ 5464]:
<-- data [23]
  Nov 11 14:36:34.88: [ 5464]:
<-- data [2]
  Nov 11 14:36:35.62: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:36:35.62: [ 5464]:
<-- data [13]
  Nov 11 14:36:35.63: [ 5464]:
<-- data [2]
  Nov 11 14:36:36.20: [ 5464]:
--> [2:OK]
  Nov 11 14:36:36.20: [ 5464]:
<-- [9:AT+FRH=3\r]
  Nov 11 14:36:38.59: [ 5464]:
--> [10:NO CARRIER]
  Nov 11 14:36:38.59: [ 5464]:
MODEM No carrier
  Nov 11 14:36:38.59: [ 5464]:
DELAY 70 ms
  Nov 11 14:36:38.66: [ 5464]:
<-- [9:AT+FTH=3\r]
  Nov 11 14:36:38.66: [ 5464]:
--> [5:ERROR]
  Nov 11 14:36:38.66: [ 5464]:
RECV FAX: RSPREC error/got EOT
  Nov 11 14:36:38.66: [ 5464]:
RECV FAX: end
  Nov 11 14:36:38.66: [ 5464]:
RSPREC error/got EOT
  Nov 11 14:36:38.66: [ 5464]:
SESSION END

- i changed NOTHING, the remote fax
retried 1 minute later and produced the following log

  Nov 11 14:37:53.42: [ 5464]:
SESSION BEGIN 000000005 43720007703
  Nov 11 14:37:53.42: [ 5464]:
HylaFAX (tm) Version 4.4.2
  Nov 11 14:37:53.42: [ 5464]:
CallID: "07208900001" "" "<NONE>" "s"
  Nov 11 14:37:53.42: [ 5464]:
MODEM set XON/XOFF/FLUSH: input ignored, output disabled
  Nov 11 14:37:53.42: [ 5464]:
<-- [4:ATA\r]
  Nov 11 14:37:57.14: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:37:57.14: [ 5464]:
ANSWER: FAX CONNECTION  DEVICE '/dev/ttyIAX0'
  Nov 11 14:37:57.14: [ 5464]:
RECV FAX: begin
  Nov 11 14:37:57.14: [ 5464]:
<-- data [32]
  Nov 11 14:37:57.14: [ 5464]:
<-- data [2]
  Nov 11 14:37:58.06: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:37:58.06: [ 5464]:
<-- data [23]
  Nov 11 14:37:58.06: [ 5464]:
<-- data [2]
  Nov 11 14:37:58.82: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:37:58.82: [ 5464]:
<-- data [13]
  Nov 11 14:37:58.82: [ 5464]:
<-- data [2]
  Nov 11 14:37:59.40: [ 5464]:
--> [2:OK]
  Nov 11 14:37:59.40: [ 5464]:
<-- [9:AT+FRH=3\r]
  Nov 11 14:38:06.40: [ 5464]:
--> [0:]
  Nov 11 14:38:06.40: [ 5464]:
MODEM <Empty line>
  Nov 11 14:38:06.40: [ 5464]:
MODEM TIMEOUT: waiting for v.21 carrier
  Nov 11 14:38:06.40: [ 5464]:
<-- data [1]
  Nov 11 14:38:06.41: [ 5464]:
--> [2:OK]
  Nov 11 14:38:06.41: [ 5464]:
DELAY 70 ms
  Nov 11 14:38:06.48: [ 5464]:
<-- [9:AT+FTH=3\r]
  Nov 11 14:38:06.49: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:38:06.49: [ 5464]:
<-- data [32]
  Nov 11 14:38:06.49: [ 5464]:
<-- data [2]
  Nov 11 14:38:08.27: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:38:08.27: [ 5464]:
<-- data [23]
  Nov 11 14:38:08.27: [ 5464]:
<-- data [2]
  Nov 11 14:38:09.01: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:38:09.01: [ 5464]:
<-- data [13]
  Nov 11 14:38:09.01: [ 5464]:
<-- data [2]
  Nov 11 14:38:09.59: [ 5464]:
--> [2:OK]
  Nov 11 14:38:09.59: [ 5464]:
<-- [9:AT+FRH=3\r]
  Nov 11 14:38:16.59: [ 5464]:
--> [0:]
  Nov 11 14:38:16.59: [ 5464]:
MODEM <Empty line>
  Nov 11 14:38:16.59: [ 5464]:
MODEM TIMEOUT: waiting for v.21 carrier
  Nov 11 14:38:16.59: [ 5464]:
<-- data [1]
  Nov 11 14:38:16.59: [ 5464]:
--> [2:OK]
  Nov 11 14:38:16.59: [ 5464]:
DELAY 70 ms
  Nov 11 14:38:16.66: [ 5464]:
<-- [9:AT+FTH=3\r]
  Nov 11 14:38:16.67: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:38:16.67: [ 5464]:
<-- data [32]
  Nov 11 14:38:16.67: [ 5464]:
<-- data [2]
  Nov 11 14:38:18.45: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:38:18.45: [ 5464]:
<-- data [23]
  Nov 11 14:38:18.45: [ 5464]:
<-- data [2]
  Nov 11 14:38:19.19: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:38:19.19: [ 5464]:
<-- data [13]
  Nov 11 14:38:19.19: [ 5464]:
<-- data [2]
  Nov 11 14:38:19.77: [ 5464]:
--> [2:OK]
  Nov 11 14:38:19.77: [ 5464]:
<-- [9:AT+FRH=3\r]
  Nov 11 14:38:26.77: [ 5464]:
--> [0:]
  Nov 11 14:38:26.77: [ 5464]:
MODEM <Empty line>
  Nov 11 14:38:26.77: [ 5464]:
MODEM TIMEOUT: waiting for v.21 carrier
  Nov 11 14:38:26.77: [ 5464]:
<-- data [1]
  Nov 11 14:38:26.77: [ 5464]:
--> [2:OK]
  Nov 11 14:38:26.77: [ 5464]:
DELAY 70 ms
  Nov 11 14:38:26.84: [ 5464]:
<-- [9:AT+FTH=3\r]
  Nov 11 14:38:26.85: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:38:26.85: [ 5464]:
<-- data [32]
  Nov 11 14:38:26.85: [ 5464]:
<-- data [2]
  Nov 11 14:38:28.64: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:38:28.64: [ 5464]:
<-- data [23]
  Nov 11 14:38:28.64: [ 5464]:
<-- data [2]
  Nov 11 14:38:29.37: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:38:29.38: [ 5464]:
<-- data [13]
  Nov 11 14:38:29.38: [ 5464]:
<-- data [2]
  Nov 11 14:38:29.96: [ 5464]:
--> [2:OK]
  Nov 11 14:38:29.96: [ 5464]:
<-- [9:AT+FRH=3\r]
  Nov 11 14:38:36.96: [ 5464]:
--> [0:]
  Nov 11 14:38:36.96: [ 5464]:
MODEM <Empty line>
  Nov 11 14:38:36.96: [ 5464]:
MODEM TIMEOUT: waiting for v.21 carrier
  Nov 11 14:38:36.96: [ 5464]:
<-- data [1]
  Nov 11 14:38:36.96: [ 5464]:
--> [2:OK]
  Nov 11 14:38:36.96: [ 5464]:
DELAY 70 ms
  Nov 11 14:38:37.03: [ 5464]:
<-- [9:AT+FTH=3\r]
  Nov 11 14:38:37.04: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:38:37.04: [ 5464]:
<-- data [32]
  Nov 11 14:38:37.04: [ 5464]:
<-- data [2]
  Nov 11 14:38:38.82: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:38:38.82: [ 5464]:
<-- data [23]
  Nov 11 14:38:38.82: [ 5464]:
<-- data [2]
  Nov 11 14:38:39.56: [ 5464]:
--> [7:CONNECT]
  Nov 11 14:38:39.56: [ 5464]:
<-- data [13]
  Nov 11 14:38:39.56: [ 5464]:
<-- data [2]
  Nov 11 14:38:40.14: [ 5464]:
--> [2:OK]
  Nov 11 14:38:40.14: [ 5464]:
<-- [9:AT+FRH=3\r]
  Nov 11 14:38:43.20: [ 5464]:
--> [10:NO CARRIER]
  Nov 11 14:38:43.20: [ 5464]:
MODEM No carrier
  Nov 11 14:38:43.20: [ 5464]:
RECV FAX: No sender protocol (T.30 T1 timeout)
  Nov 11 14:38:43.21: [ 5464]:
RECV FAX: end
  Nov 11 14:38:43.21: [ 5464]:
No sender protocol (T.30 T1 timeout)
  Nov 11 14:38:43.21: [ 5464]:
SESSION END

I tried it many, many times - the result
is always the same:

  RECV FAX: RSPREC error/got EOT
(log1 above)   OR

  T.30 T1 timeout (log2 above)

I found nothing in the web that may
help - any help would be appreciated!!!

Thanks a lot,
Philipp from Vienna


-------------------------------------------------------------------------------------------------------------------------------------

- the config file for IAXmodem (/etc/hylafax/etc/config.ttyIAX0)

  # $Id: iaxmodem,v 1.1 2006/04/02
23:18:30 darren Exp $

  #
  # prototype config for the IAXmodem
softmodem which uses
  # the spandsp soft-DSP library
  #

  #
  CountryCode:      
     43
  AreaCode:      
        720
  FAXNumber:      
       +43.720.007703
  LongDistancePrefix:    
0
  InternationalPrefix:    00
  DialStringRules:    
   etc/dialrules
  ServerTracing:    
     527
  SessionTracing:    
    527
  RecvFileMode:      
    0600
  LogFileMode:      
     0600
  DeviceMode:      
      0600
  RingsBeforeAnswer:    
 1
  SpeakerVolume:    
     off
  GettyArgs:      
       "-h %l dx_%s"
  LocalIdentifier:    
   TestFax
  TagLineFont:      
     etc/lutRS18.pcf
  TagLineFormat:    
     "From %%l|%c|Page %%P of %%T"
  MaxRecvPages:      
    25
  #

  #
  #
  # Modem-related stuff: should
reflect modem command interface
  # and hardware connection/cabling
(e.g. flow control).
  #
  ModemType:      
       Class1          # use
this to supply a hint

  #
  # The modem is taken off-hook
during initialization, and then
  # placed back on-hook when done
to prevent glare.
  #
  ModemResetCmds:    
    "ATH1\nAT+VCID=1"       # enables
CallID display
  ModemReadyCmds:    
    ATH0

  Class1AdaptRecvCmd:    
AT+FAR=1
  Class1TMConnectDelay:  
400             # counteract quick CONNECT
response
  Class1RMQueryCmd:    
  "!24,48,72,96"  # V.17 fast-train recv doesn't work
well

  CallIDPattern:    
     "NMBR="
  CallIDPattern:    
     "NAME="
  CallIDPattern:    
     "ANID="
  CallIDPattern:    
     "NDID="
  # Uncomment these if you really
want them, but you probably don't.
  #CallIDPattern:    
     "DATE="
  #CallIDPattern:    
     "TIME="

  Class1PPMWaitCmd:   "<delay:7>"
  Class1TCFWaitCmd:   "<delay:7>"
  Class1EOPWaitCmd:   "<delay:9>"
  Class1SwitchingCmd: "<delay:7>"