Re: [hylafax-users] Hylafax Loopback failing (w/ IAXModem and asterisk)

[James Lamanna <jlamanna@xxxxxxxxx>]

Looking at the iaxmodem logs, I've also noticed a lot of:
Adjusting skew .... messages

Both asterisk and iaxmodem are running on the same box as well.
However this is running on "slow" hardware, a 500MHz ARM board (TS-8000)
Would that have something to do with it?

-- James

On Sat, Feb 7, 2009 at 3:15 AM, James Lamanna <jlamanna@xxxxxxxxx> wrote:
> Hi,
> I'm using sendfax to run a loopback test through my asterisk box back
> to Hylafax, however it seems as though I cannot receive the fax.
> The call never leaves the asterisk box, but just dials another
> IAXModem directly.
>
> Any ideas?
>
> Thanks.
>
> Here's the receive side Hylafax log:
>
> Feb 07 11:07:22.89: [ 1964]: HylaFAX (tm) Version 5.2.8
> Feb 07 11:07:23.07: [ 1964]: <-- [4:ATA\r]
> Feb 07 11:07:26.80: [ 1964]: --> [7:CONNECT]
> Feb 07 11:07:26.80: [ 1964]: ANSWER: FAX CONNECTION  DEVICE '/dev/ttyIAX1'
> Feb 07 11:07:26.80: [ 1964]: RECV FAX: begin
> Feb 07 11:07:26.80: [ 1964]: <-- data [32]
> Feb 07 11:07:26.80: [ 1964]: <-- data [2]
> Feb 07 11:07:27.76: [ 1964]: --> [7:CONNECT]
> Feb 07 11:07:27.76: [ 1964]: <-- data [23]
> Feb 07 11:07:27.76: [ 1964]: <-- data [2]
> Feb 07 11:07:28.49: [ 1964]: --> [7:CONNECT]
> Feb 07 11:07:28.49: [ 1964]: <-- data [13]
> Feb 07 11:07:28.49: [ 1964]: <-- data [2]
> Feb 07 11:07:29.07: [ 1964]: --> [2:OK]
> Feb 07 11:07:29.07: [ 1964]: <-- [9:AT+FRH=3\r]
> Feb 07 11:07:29.33: [ 1964]: --> [7:CONNECT]
> Feb 07 11:07:30.75: [ 1964]: --> [2:OK]
> Feb 07 11:07:30.75: [ 1964]: RECV recv TSI (sender id)
> Feb 07 11:07:30.76: [ 1964]: REMOTE TSI "NothingSetup"
> Feb 07 11:07:30.76: [ 1964]: <-- [9:AT+FRH=3\r]
> Feb 07 11:07:31.09: [ 1964]: --> [7:CONNECT]
> Feb 07 11:07:31.14: [ 1964]: --> [2:OK]
> Feb 07 11:07:31.14: [ 1964]: RECV recv DCS (command signal)
> Feb 07 11:07:31.14: [ 1964]: REMOTE wants 9600 bit/s
> Feb 07 11:07:31.14: [ 1964]: REMOTE wants A4 page width (215 mm)
> Feb 07 11:07:31.14: [ 1964]: REMOTE wants unlimited page length
> Feb 07 11:07:31.14: [ 1964]: REMOTE wants 3.85 line/mm
> Feb 07 11:07:31.14: [ 1964]: REMOTE wants 2-D MMR
> Feb 07 11:07:31.14: [ 1964]: REMOTE wants T.30 Annex A, 256-byte ECM
> Feb 07 11:07:31.14: [ 1964]: RECV training at v.29 9600 bit/s
> Feb 07 11:07:31.14: [ 1964]: <-- [10:AT+FRM=96\r]
> Feb 07 11:07:35.65: [ 1964]: --> [0:]
> Feb 07 11:07:35.65: [ 1964]: MODEM <Empty line>
> Feb 07 11:07:35.65: [ 1964]: <-- data [1]
> Feb 07 11:07:35.86: [ 1964]: --> [2:OK]
> Feb 07 11:07:35.86: [ 1964]: <-- [9:AT+FRS=7\r]
> Feb 07 11:07:35.86: [ 1964]: --> [2:OK]
> Feb 07 11:07:35.86: [ 1964]: <-- [9:AT+FRS=7\r]
> Feb 07 11:07:36.19: [ 1964]: --> [2:OK]
> Feb 07 11:07:36.19: [ 1964]: <-- [9:AT+FTH=3\r]
> Feb 07 11:07:36.31: [ 1964]: --> [7:CONNECT]
> Feb 07 11:07:36.31: [ 1964]: <-- data [3]
> Feb 07 11:07:36.32: [ 1964]: <-- data [2]
> Feb 07 11:07:37.25: [ 1964]: --> [2:OK]
> Feb 07 11:07:37.25: [ 1964]: TRAINING failed
> Feb 07 11:07:37.26: [ 1964]: <-- [9:AT+FRH=3\r]
> Feb 07 11:07:37.52: [ 1964]: --> [7:CONNECT]
> Feb 07 11:07:37.55: [ 1964]: --> [5:ERROR]
> Feb 07 11:07:37.55: [ 1964]: MODEM Command error
> Feb 07 11:07:37.55: [ 1964]: FCS error
> Feb 07 11:07:37.55: [ 1964]: <-- [10:AT+FRS=21\r]
> Feb 07 11:07:42.08: [ 1964]: --> [2:OK]
> Feb 07 11:07:42.08: [ 1964]: <-- [9:AT+FTH=3\r]
> Feb 07 11:07:42.10: [ 1964]: --> [7:CONNECT]
> Feb 07 11:07:42.10: [ 1964]: <-- data [3]
> Feb 07 11:07:42.10: [ 1964]: <-- data [2]
> Feb 07 11:07:43.17: [ 1964]: --> [2:OK]
> Feb 07 11:07:43.17: [ 1964]: RECV send CRP (command repeat)
> Feb 07 11:07:43.18: [ 1964]: <-- [9:AT+FRH=3\r]
> Feb 07 11:07:43.57: [ 1964]: --> [7:CONNECT]
> Feb 07 11:07:44.53: [ 1964]: --> [2:OK]
> Feb 07 11:07:44.53: [ 1964]: RECV recv CRP (command repeat)
> Feb 07 11:07:44.53: [ 1964]: <-- [9:AT+FTH=3\r]
> Feb 07 11:07:44.55: [ 1964]: --> [7:CONNECT]
> Feb 07 11:07:44.55: [ 1964]: <-- data [32]
> Feb 07 11:07:44.56: [ 1964]: <-- data [2]
> Feb 07 11:07:46.33: [ 1964]: --> [7:CONNECT]
> Feb 07 11:07:46.33: [ 1964]: <-- data [23]
> Feb 07 11:07:46.34: [ 1964]: <-- data [2]
> Feb 07 11:07:47.07: [ 1964]: --> [7:CONNECT]
> Feb 07 11:07:47.07: [ 1964]: <-- data [13]
> Feb 07 11:07:47.07: [ 1964]: <-- data [2]
> Feb 07 11:07:47.65: [ 1964]: --> [2:OK]
> Feb 07 11:07:47.65: [ 1964]: <-- [9:AT+FRH=3\r]
> Feb 07 11:07:47.91: [ 1964]: --> [7:CONNECT]
> Feb 07 11:07:47.65: [ 1964]: <-- [9:AT+FRH=3\r]
> Feb 07 11:07:47.91: [ 1964]: --> [7:CONNECT]
> Feb 07 11:07:49.33: [ 1964]: --> [2:OK]
> Feb 07 11:07:49.33: [ 1964]: RECV recv TSI (sender id)
> Feb 07 11:07:49.34: [ 1964]: REMOTE TSI "NothingSetup"
> Feb 07 11:07:49.34: [ 1964]: <-- [9:AT+FRH=3\r]
> Feb 07 11:07:49.67: [ 1964]: --> [7:CONNECT]
> Feb 07 11:07:49.71: [ 1964]: --> [2:OK]
> Feb 07 11:07:49.71: [ 1964]: RECV recv DCS (command signal)
> Feb 07 11:07:49.71: [ 1964]: REMOTE wants 7200 bit/s
> Feb 07 11:07:49.72: [ 1964]: REMOTE wants A4 page width (215 mm)
> Feb 07 11:07:49.72: [ 1964]: REMOTE wants unlimited page length
> Feb 07 11:07:49.72: [ 1964]: REMOTE wants 3.85 line/mm
> Feb 07 11:07:49.72: [ 1964]: REMOTE wants 2-D MMR
> Feb 07 11:07:49.72: [ 1964]: REMOTE wants T.30 Annex A, 256-byte ECM
> Feb 07 11:07:49.72: [ 1964]: RECV training at v.29 7200 bit/s
> Feb 07 11:07:49.72: [ 1964]: <-- [10:AT+FRM=72\r]
> Feb 07 11:07:54.22: [ 1964]: --> [0:]
> Feb 07 11:07:54.22: [ 1964]: MODEM <Empty line>
> Feb 07 11:07:54.22: [ 1964]: <-- data [1]
> Feb 07 11:07:54.43: [ 1964]: MODEM <Timeout>
> Feb 07 11:07:54.77: [ 1964]: <-- [9:AT+FRS=7\r]
> Feb 07 11:07:54.77: [ 1964]: --> [2:OK]
> Feb 07 11:07:54.78: [ 1964]: <-- [9:AT+FTH=3\r]
> Feb 07 11:07:54.78: [ 1964]: --> [7:CONNECT]
> Feb 07 11:07:54.78: [ 1964]: <-- data [3]
> Feb 07 11:07:54.78: [ 1964]: <-- data [2]
> Feb 07 11:07:54.86: [ 1964]: --> [2:OK]
> Feb 07 11:07:54.86: [ 1964]: TRAINING failed
> Feb 07 11:07:54.86: [ 1964]: <-- [9:AT+FRH=3\r]
> Feb 07 11:07:56.99: [ 1964]: --> [7:CONNECT]
> Feb 07 11:07:57.02: [ 1964]: --> [5:ERROR]
> Feb 07 11:07:57.02: [ 1964]: MODEM Command error
> Feb 07 11:07:57.02: [ 1964]: FCS error
> Feb 07 11:07:57.02: [ 1964]: <-- [10:AT+FRS=21\r]
> Feb 07 11:07:57.63: [ 1964]: --> [2:OK]
> Feb 07 11:07:57.63: [ 1964]: <-- [9:AT+FTH=3\r]
> Feb 07 11:07:57.65: [ 1964]: --> [7:CONNECT]
> Feb 07 11:07:57.66: [ 1964]: <-- data [3]
> Feb 07 11:07:57.65: [ 1964]: --> [7:CONNECT]
> Feb 07 11:07:57.66: [ 1964]: <-- data [3]
> Feb 07 11:07:57.66: [ 1964]: <-- data [2]
> Feb 07 11:07:58.73: [ 1964]: --> [2:OK]
> Feb 07 11:07:58.73: [ 1964]: RECV send CRP (command repeat)
> Feb 07 11:07:58.73: [ 1964]: <-- [9:AT+FRH=3\r]
> Feb 07 11:07:58.99: [ 1964]: --> [7:CONNECT]
> Feb 07 11:08:00.41: [ 1964]: --> [2:OK]
> Feb 07 11:08:00.41: [ 1964]: RECV recv TSI (sender id)
> Feb 07 11:08:00.42: [ 1964]: REMOTE TSI "NothingSetup"
> Feb 07 11:08:00.42: [ 1964]: <-- [9:AT+FRH=3\r]
> Feb 07 11:08:00.75: [ 1964]: --> [7:CONNECT]
> Feb 07 11:08:00.79: [ 1964]: --> [2:OK]
> Feb 07 11:08:00.79: [ 1964]: RECV recv DCS (command signal)
> Feb 07 11:08:00.79: [ 1964]: REMOTE wants 4800 bit/s
> Feb 07 11:08:00.80: [ 1964]: REMOTE wants A4 page width (215 mm)
> Feb 07 11:08:00.80: [ 1964]: REMOTE wants unlimited page length
> Feb 07 11:08:00.80: [ 1964]: REMOTE wants 3.85 line/mm
> Feb 07 11:08:00.80: [ 1964]: REMOTE wants 2-D MMR
> Feb 07 11:08:00.80: [ 1964]: REMOTE wants T.30 Annex A, 256-byte ECM
> Feb 07 11:08:00.80: [ 1964]: RECV training at v.27ter 4800 bit/s
> Feb 07 11:08:00.80: [ 1964]: <-- [10:AT+FRM=48\r]
> Feb 07 11:08:05.30: [ 1964]: --> [0:]
> Feb 07 11:08:05.30: [ 1964]: MODEM <Empty line>
> Feb 07 11:08:05.30: [ 1964]: <-- data [1]
> Feb 07 11:08:05.51: [ 1964]: MODEM <Timeout>
> Feb 07 11:08:07.01: [ 1964]: <-- [9:AT+FRS=7\r]
> Feb 07 11:08:07.01: [ 1964]: --> [2:OK]
> Feb 07 11:08:07.01: [ 1964]: <-- [9:AT+FTH=3\r]
> Feb 07 11:08:07.05: [ 1964]: --> [7:CONNECT]
> Feb 07 11:08:07.05: [ 1964]: <-- data [3]
> Feb 07 11:08:07.05: [ 1964]: <-- data [2]
> Feb 07 11:08:07.28: [ 1964]: --> [2:OK]
> Feb 07 11:08:07.28: [ 1964]: TRAINING failed
> Feb 07 11:08:07.28: [ 1964]: <-- [9:AT+FRH=3\r]
> Feb 07 11:08:10.49: [ 1964]: --> [7:CONNECT]
> Feb 07 11:08:10.52: [ 1964]: --> [10:NO CARRIER]
> Feb 07 11:08:10.52: [ 1964]: MODEM No carrier
> Feb 07 11:08:10.52: [ 1964]: <-- [10:AT+FRS=21\r]
> Feb 07 11:08:10.68: [ 1964]: --> [2:OK]
> Feb 07 11:08:10.68: [ 1964]: <-- [9:AT+FTH=3\r]
> Feb 07 11:08:10.70: [ 1964]: --> [7:CONNECT]
> Feb 07 11:08:10.70: [ 1964]: <-- data [3]
> Feb 07 11:08:10.70: [ 1964]: <-- data [2]
> Feb 07 11:08:11.76: [ 1964]: --> [2:OK]
> Feb 07 11:08:11.76: [ 1964]: RECV send CRP (command repeat)
> Feb 07 11:08:11.76: [ 1964]: <-- [9:AT+FRH=3\r]
> Feb 07 11:08:12.02: [ 1964]: --> [7:CONNECT]
> Feb 07 11:08:13.44: [ 1964]: --> [2:OK]
> Feb 07 11:08:13.44: [ 1964]: RECV recv TSI (sender id)
> Feb 07 11:08:13.44: [ 1964]: REMOTE TSI "NothingSetup"
> Feb 07 11:08:13.44: [ 1964]: <-- [9:AT+FRH=3\r]
> Feb 07 11:08:13.78: [ 1964]: --> [7:CONNECT]
> Feb 07 11:08:13.82: [ 1964]: --> [2:OK]
> Feb 07 11:08:13.82: [ 1964]: RECV recv DCS (command signal)
> Feb 07 11:08:13.82: [ 1964]: REMOTE wants 2400 bit/s
> Feb 07 11:08:13.82: [ 1964]: REMOTE wants A4 page width (215 mm)
> Feb 07 11:08:13.82: [ 1964]: REMOTE wants unlimited page length
> Feb 07 11:08:13.82: [ 1964]: REMOTE wants 3.85 line/mm
> Feb 07 11:08:13.82: [ 1964]: REMOTE wants 2-D MMR
> Feb 07 11:08:13.82: [ 1964]: REMOTE wants T.30 Annex A, 256-byte ECM
> Feb 07 11:08:13.82: [ 1964]: RECV training at v.27ter fallback mode 2400 bit/s
> Feb 07 11:08:13.82: [ 1964]: <-- [10:AT+FRM=24\r]
> Feb 07 11:08:18.32: [ 1964]: --> [0:]
> Feb 07 11:08:18.32: [ 1964]: MODEM <Empty line>
> Feb 07 11:08:18.32: [ 1964]: <-- data [1]
> Feb 07 11:08:18.53: [ 1964]: MODEM <Timeout>
> Feb 07 11:08:21.81: [ 1964]: <-- [9:AT+FRS=7\r]
> Feb 07 11:08:21.81: [ 1964]: --> [2:OK]
> Feb 07 11:08:21.81: [ 1964]: <-- [9:AT+FTH=3\r]
> Feb 07 11:08:21.82: [ 1964]: --> [7:CONNECT]
> Feb 07 11:08:21.82: [ 1964]: <-- data [3]
> Feb 07 11:08:21.82: [ 1964]: <-- data [2]
> Feb 07 11:08:22.19: [ 1964]: --> [2:OK]
> Feb 07 11:08:22.19: [ 1964]: TRAINING failed
> Feb 07 11:08:22.19: [ 1964]: <-- [9:AT+FRH=3\r]
> Feb 07 11:08:22.42: [ 1964]: --> [7:CONNECT]
> Feb 07 11:08:23.00: [ 1964]: --> [5:ERROR]
> Feb 07 11:08:23.00: [ 1964]: MODEM Command error
> Feb 07 11:08:23.00: [ 1964]: FCS error
> Feb 07 11:08:23.00: [ 1964]: <-- [10:AT+FRS=21\r]
> Feb 07 11:08:23.69: [ 1964]: --> [2:OK]
> Feb 07 11:08:23.69: [ 1964]: <-- [9:AT+FTH=3\r]
> Feb 07 11:08:23.71: [ 1964]: --> [7:CONNECT]
> Feb 07 11:08:23.71: [ 1964]: <-- data [3]
> Feb 07 11:08:23.71: [ 1964]: <-- data [2]
> Feb 07 11:08:23.91: [ 1964]: --> [2:OK]
> Feb 07 11:08:23.91: [ 1964]: RECV send CRP (command repeat)
> Feb 07 11:08:23.91: [ 1964]: <-- [9:AT+FRH=3\r]
> Feb 07 11:08:24.99: [ 1964]: --> [7:CONNECT]
> Feb 07 11:08:25.50: [ 1964]: --> [10:NO CARRIER]
> Feb 07 11:08:25.50: [ 1964]: MODEM No carrier
> Feb 07 11:08:25.50: [ 1964]: <-- [10:AT+FRS=21\r]
> Feb 07 11:08:25.75: [ 1964]: --> [2:OK]
> Feb 07 11:08:25.75: [ 1964]: <-- [9:AT+FTH=3\r]
> Feb 07 11:08:25.76: [ 1964]: --> [7:CONNECT]
> Feb 07 11:08:25.76: [ 1964]: <-- data [3]
> Feb 07 11:08:25.76: [ 1964]: <-- data [2]
> Feb 07 11:08:26.84: [ 1964]: --> [2:OK]
> Feb 07 11:08:26.84: [ 1964]: RECV send CRP (command repeat)
> Feb 07 11:08:26.84: [ 1964]: <-- [9:AT+FRH=3\r]
> Feb 07 11:08:27.10: [ 1964]: --> [7:CONNECT]
> Feb 07 11:08:28.06: [ 1964]: --> [2:OK]
> Feb 07 11:08:28.06: [ 1964]: RECV recv DCN (disconnect)
> Feb 07 11:08:28.06: [ 1964]: RECV FAX: RSPREC error/got DCN (sender
> abort) {E103}
> Feb 07 11:08:28.06: [ 1964]: RECV FAX: end
> Feb 07 11:08:28.06: [ 1964]: RSPREC error/got DCN (sender abort) {E103}
> Feb 07 11:08:28.06: [ 1964]: SESSION END
>


____________________ HylaFAX(tm) Users Mailing List _______________________
  To subscribe/unsubscribe, click http://lists.hylafax.org/cgi-bin/lsg2.cgi
 On UNIX: mail -s unsubscribe hylafax-users-request@xxxxxxxxxxx < /dev/null
  *To learn about commercial HylaFAX(tm) support, mail sales@xxxxxxxxx*