HylaFAX The world's most advanced open source fax server |
Fabio -
I don't see a problem here. This looks like the log of a successful fax receipt. In fact, the lines you are showing now from xferfaxlog are all looking normal. Unless the faxes you received were not as you expected, I do not see the issue.
-Siri Vias
-----Original Message-----
From: hylafax-users-bounce@xxxxxxxxxxx on behalf of Fabio Nigi
Sent: Tue 2/10/2009 12:13 AM
To: hylafax-users@xxxxxxxxxxx
Subject: Re: [hylafax-users] problem "waiting for modem to came ready"
Siri Vias Khalsa wrote:
> Fabio -
>
> Please send the log of one of the failed calls. From what I can see
> here, it looks like you are getting incoming calls that do not complete,
> every 3-4 minutes during one period there. The call lengths are all very
> similar, so I would guess that it is timing out, not getting the
> response it expected.
>
this is the error message that i found until modem become waiting
hope is it usefully
Feb 10 08:49:32.83: [ 4017]: <-- [9:AT+FTH=3\r]
Feb 10 08:49:32.86: [ 4017]: --> [7:CONNECT]
Feb 10 08:49:32.86: [ 4017]: <-- data [3]
Feb 10 08:49:32.86: [ 4017]: <-- data [2]
Feb 10 08:49:34.16: [ 4017]: --> [2:OK]
Feb 10 08:49:34.16: [ 4017]: <-- [11:AT+FRM=146\r]
Feb 10 08:49:34.61: [ 4017]: --> [7:CONNECT]
Feb 10 08:49:34.61: [ 4017]: RECV: begin page
Feb 10 08:50:09.91: [ 4017]: RECV: 2394 total lines, 0 bad lines, 0
consecutive bad lines
Feb 10 08:50:09.91: [ 4017]: RECV: end page
Feb 10 08:50:09.91: [ 4017]: --> [10:NO CARRIER]
Feb 10 08:50:09.91: [ 4017]: <-- [9:AT+FRH=3\r]
Feb 10 08:50:10.37: [ 4017]: --> [7:CONNECT]
Feb 10 08:50:11.26: [ 4017]: --> [2:OK]
Feb 10 08:50:11.26: [ 4017]: RECV recv EOP (no more pages or documents)
Feb 10 08:50:11.26: [ 4017]: DELAY 70 ms
Feb 10 08:50:11.33: [ 4017]: <-- [9:AT+FTH=3\r]
Feb 10 08:50:11.47: [ 4017]: --> [7:CONNECT]
Feb 10 08:50:11.47: [ 4017]: <-- data [3]
Feb 10 08:50:11.47: [ 4017]: <-- data [2]
Feb 10 08:50:12.77: [ 4017]: --> [2:OK]
Feb 10 08:50:12.77: [ 4017]: RECV send MCF (message confirmation)
Feb 10 08:50:12.77: [ 4017]: RECV FAX (000000290): from Fax, page 1 in
0:47, A4, 7.7 line/mm, 2-D MR, 14400 bit/s
Feb 10 08:50:12.77: [ 4017]: RECV FAX (000000290):
recvq/fax000000188.tif from Fax, route to <unspecified>, 1 pages in 0:50
Feb 10 08:50:12.77: [ 4017]: <-- [9:AT+FRH=3\r]
Feb 10 08:50:13.48: [ 4017]: --> [7:CONNECT]
Feb 10 08:50:14.53: [ 4017]: --> [2:OK]
Feb 10 08:50:14.53: [ 4017]: RECV recv DCN (disconnect)
Feb 10 08:50:14.53: [ 4017]: RECV FAX: bin/faxrcvd
"recvq/fax000000188.tif" "ttyS0" "000000290" ""
Feb 10 08:50:14.53: [ 4017]: RECV FAX: end
Feb 10 08:50:14.53: [ 4017]: SESSION END
02/09/09 09:54 RECV 000000286 ttyS0 "" fax "7364726" "050877040"
2220073 2 7:46 7:46 "T.30 T2 timeout, expected signal not
received" "" "" "" "" "00 46 1F 23 01 01 01 01 01 00"
02/09/09 09:53 CALL 000000286 ttyS0 "" fax "7364726" "" 0 0 8:00 8:00
"T.30 T2 timeout, expected signal not received" "" "" "" "" ""
02/09/09 11:57 RECV 000000287 ttyS0 "" fax "7364726" "050877040"
2220073 2 2:55 2:55 "" "" "" "" "" "00 46 1F 23 01 01 01 01 01 00"
02/09/09 11:57 CALL 000000287 ttyS0 "" fax "7364726" "" 0 0 3:02
3:02 "" "" "" "" "" ""
02/09/09 15:53 RECV 000000288 ttyS0 "" fax "7364726" "" 2105384 1
0:54 0:54 "" "" "" "" "" "00 44 1E"
02/09/09 15:53 CALL 000000288 ttyS0 "" fax "7364726" "" 0 0 1:01
1:01 "" "" "" "" "" ""
02/09/09 17:03 RECV 000000289 ttyS0 "" fax "7364726" "055219397"
2220072 4 1:29 1:29 "" "" "" "" "" "00 44 1F 23 01 00"
02/09/09 17:03 CALL 000000289 ttyS0 "" fax "7364726" "" 0 0 1:36
1:36 "" "" "" "" "" ""
02/10/09 08:49 RECV 000000290 ttyS0 "" fax "7364726" "Fax"
2375721 1 0:50 0:50 "" "" "" "" "" "00 47 08"
02/10/09 08:49 CALL 000000290 ttyS0 "" fax "7364726" "" 0 0 0:58
0:58 "" "" "" "" "" ""
fanfaniserver:/var/spool/hylafax/log#
thanks
> On Mon, 2009-02-09 at 12:39 -0600, Fabio Nigi wrote:
>> hi all,
>> i have changed my modem, with one of the supported list on the site,
>> the problem persist, debian installation i follow the howto on hylafax
>> web site:
>>
>> 02/06/09 17:38 CALL 000000274 ttyS0 "" fax "7364726" "" 0 0 0:28 0:28
>> "COMREC invalid response received" "" "" "" "" ""
>> 02/06/09 17:41 CALL 000000275 ttyS0 "" fax "7364726" "" 0 0 0:48 0:48
>> "RSPREC error/got DCN (sender abort)" "" "" "" "" ""
>> 02/06/09 17:45 CALL 000000276 ttyS0 "" fax "7364726" "" 0 0 0:47 0:47
>> "RSPREC error/got DCN (sender abort)" "" "" "" "" ""
>> 02/06/09 17:49 CALL 000000277 ttyS0 "" fax "7364726" "" 0 0 0:48 0:48
>> "RSPREC error/got DCN (sender abort)" "" "" "" "" ""
>> 02/06/09 17:53 CALL 000000278 ttyS0 "" fax "7364726" "" 0 0 0:47 0:47
>> "RSPREC error/got DCN (sender abort)" "" "" "" "" ""
>> 02/06/09 17:56 CALL 000000279 ttyS0 "" fax "7364726" "" 0 0 0:52 0:52
>> "RSPREC error/got DCN (sender abort)" "" "" "" "" ""
>> 02/06/09 18:00 CALL 000000280 ttyS0 "" fax "7364726" "" 0 0 0:47 0:47
>> "RSPREC error/got DCN (sender abort)" "" "" "" "" ""
>> 02/06/09 18:04 CALL 000000281 ttyS0 "" fax "7364726" "" 0 0 0:47 0:47
>> "RSPREC error/got DCN (sender abort)" "" "" "" "" ""
>> 02/06/09 18:08 CALL 000000282 ttyS0 "" fax "7364726" "" 0 0 0:47 0:47
>> "RSPREC error/got DCN (sender abort)" "" "" "" "" ""
>> 02/09/09 09:19 RECV 000000283 ttyS0 "" fax "7364726" "Fax"
>> 2375721 1 0:49 0:49 "" "" "" "" "" "00 47 08"
>> 02/09/09 09:19 CALL 000000283 ttyS0 "" fax "7364726" "" 0 0 0:57
>> 0:57 "" "" "" "" "" ""
>>
>> i found lot's of this error message on the log,
>>
>> after same received fax (can be 10 or 100)modem stop working, until i
>> restart hylafax, or reboot the server.
>>
>> faxstat said: "waiting for modem to came ready"
>>
>> a log of a received fax:
>>
>> Feb 09 17:04:27.71: [ 4031]: --> [10:NO CARRIER]
>> Feb 09 17:04:27.71: [ 4031]: <-- [9:AT+FRH=3\r]
>> Feb 09 17:04:28.10: [ 4031]: --> [7:CONNECT]
>> Feb 09 17:04:29.13: [ 4031]: --> [2:OK]
>> Feb 09 17:04:29.13: [ 4031]: RECV recv PPS (partial page signal)
>> Feb 09 17:04:29.13: [ 4031]: RECV recv MPS (more pages, same document)
>> Feb 09 17:04:29.13: [ 4031]: RECV received 119 frames of block 1 of page 3
>> Feb 09 17:04:29.15: [ 4031]: RECV: 29925 bytes of data, 1146 total lines
>> Feb 09 17:04:29.16: [ 4031]: DELAY 70 ms
>> Feb 09 17:04:29.23: [ 4031]: <-- [9:AT+FTH=3\r]
>> Feb 09 17:04:29.26: [ 4031]: --> [7:CONNECT]
>> Feb 09 17:04:29.26: [ 4031]: RECV send MCF (message confirmation)
>> Feb 09 17:04:29.26: [ 4031]: <-- data [3]
>> Feb 09 17:04:29.26: [ 4031]: <-- data [2]
>> Feb 09 17:04:29.27: [ 4031]: RECV FAX (000000289): from 055219397, page
>> 3 in 0:23, INF, 3.85 line/mm, 2-D MMR, 14400 bit/s
>> Feb 09 17:04:30.56: [ 4031]: --> [2:OK]
>> Feb 09 17:04:30.56: [ 4031]: <-- [11:AT+FRM=146\r]
>> Feb 09 17:04:31.54: [ 4031]: --> [7:CONNECT]
>> Feb 09 17:04:32.03: [ 4031]: RECV received frame number 0
>> Feb 09 17:04:32.24: [ 4031]: RECV received frame number 1
>> Feb 09 17:04:32.38: [ 4031]: RECV received frame number 2
>> Feb 09 17:04:32.52: [ 4031]: RECV received frame number 3
>> Feb 09 17:04:32.66: [ 4031]: RECV received frame number 4
>> Feb 09 17:04:32.80: [ 4031]: RECV received frame number 5
>> Feb 09 17:04:32.94: [ 4031]: RECV received frame number 6
>> Feb 09 17:04:33.08: [ 4031]: RECV received frame number 7
>> Feb 09 17:04:33.23: [ 4031]: RECV received frame number 8
>> Feb 09 17:04:33.37: [ 4031]: RECV received frame number 9
>> Feb 09 17:04:33.58: [ 4031]: RECV received frame number 10
>> Feb 09 17:04:33.72: [ 4031]: RECV received frame number 11
>> Feb 09 17:04:33.86: [ 4031]: RECV received frame number 12
>> Feb 09 17:04:34.00: [ 4031]: RECV received frame number 13
>> Feb 09 17:04:34.14: [ 4031]: RECV received frame number 14
>> Feb 09 17:04:34.28: [ 4031]: RECV received frame number 15
>> Feb 09 17:04:34.43: [ 4031]: RECV received frame number 16
>> Feb 09 17:04:34.57: [ 4031]: RECV received frame number 17
>> Feb 09 17:04:34.78: [ 4031]: RECV received frame number 18
>> Feb 09 17:04:34.92: [ 4031]: RECV received frame number 19
>> Feb 09 17:04:35.06: [ 4031]: RECV received frame number 20
>> Feb 09 17:04:35.20: [ 4031]: RECV received frame number 21
>> Feb 09 17:04:35.34: [ 4031]: RECV received frame number 22
>> Feb 09 17:04:35.48: [ 4031]: RECV received frame number 23
>> Feb 09 17:04:35.62: [ 4031]: RECV received frame number 24
>> Feb 09 17:04:35.83: [ 4031]: RECV received frame number 25
>> Feb 09 17:04:35.97: [ 4031]: RECV received frame number 26
>> Feb 09 17:04:36.12: [ 4031]: RECV received frame number 27
>> Feb 09 17:04:36.26: [ 4031]: RECV received frame number 28
>> Feb 09 17:04:36.40: [ 4031]: RECV received frame number 29
>> Feb 09 17:04:36.54: [ 4031]: RECV received frame number 30
>> Feb 09 17:04:36.68: [ 4031]: RECV received frame number 31
>> Feb 09 17:04:36.82: [ 4031]: RECV received frame number 32
>> Feb 09 17:04:37.04: [ 4031]: RECV received frame number 33
>> Feb 09 17:04:37.18: [ 4031]: RECV received frame number 34
>> Feb 09 17:04:37.32: [ 4031]: RECV received frame number 35
>> Feb 09 17:04:37.46: [ 4031]: RECV received frame number 36
>> Feb 09 17:04:37.60: [ 4031]: RECV received frame number 37
>> Feb 09 17:04:37.74: [ 4031]: RECV received frame number 38
>> Feb 09 17:04:37.88: [ 4031]: RECV received frame number 39
>> Feb 09 17:04:38.02: [ 4031]: RECV received frame number 40
>> Feb 09 17:04:38.23: [ 4031]: RECV received frame number 41
>> Feb 09 17:04:38.37: [ 4031]: RECV received frame number 42
>> Feb 09 17:04:38.51: [ 4031]: RECV received frame number 43
>> Feb 09 17:04:38.65: [ 4031]: RECV received frame number 44
>> Feb 09 17:04:38.79: [ 4031]: RECV received frame number 45
>> Feb 09 17:04:38.93: [ 4031]: RECV received frame number 46
>> Feb 09 17:04:39.07: [ 4031]: RECV received frame number 47
>> Feb 09 17:04:39.28: [ 4031]: RECV received frame number 48
>> Feb 09 17:04:39.42: [ 4031]: RECV received frame number 49
>> Feb 09 17:04:39.56: [ 4031]: RECV received frame number 50
>> Feb 09 17:04:39.70: [ 4031]: RECV received frame number 51
>> Feb 09 17:04:39.84: [ 4031]: RECV received frame number 52
>> Feb 09 17:04:39.98: [ 4031]: RECV received frame number 53
>> Feb 09 17:04:40.12: [ 4031]: RECV received frame number 54
>> Feb 09 17:04:40.34: [ 4031]: RECV received frame number 55
>> Feb 09 17:04:40.48: [ 4031]: RECV received frame number 56
>> Feb 09 17:04:40.62: [ 4031]: RECV received frame number 57
>> Feb 09 17:04:40.76: [ 4031]: RECV received frame number 58
>> Feb 09 17:04:40.90: [ 4031]: RECV received frame number 59
>> Feb 09 17:04:41.04: [ 4031]: RECV received frame number 60
>> Feb 09 17:04:41.18: [ 4031]: RECV received frame number 61
>> Feb 09 17:04:41.32: [ 4031]: RECV received frame number 62
>> Feb 09 17:04:41.53: [ 4031]: RECV received frame number 63
>> Feb 09 17:04:41.67: [ 4031]: RECV received frame number 64
>> Feb 09 17:04:41.81: [ 4031]: RECV received frame number 65
>> Feb 09 17:04:41.95: [ 4031]: RECV received frame number 66
>> Feb 09 17:04:42.09: [ 4031]: RECV received frame number 67
>> Feb 09 17:04:42.23: [ 4031]: RECV received frame number 68
>> Feb 09 17:04:42.37: [ 4031]: RECV received frame number 69
>> Feb 09 17:04:42.51: [ 4031]: RECV received frame number 70
>> Feb 09 17:04:42.72: [ 4031]: RECV received frame number 71
>> Feb 09 17:04:42.86: [ 4031]: RECV received frame number 72
>> Feb 09 17:04:43.00: [ 4031]: RECV received frame number 73
>> Feb 09 17:04:43.15: [ 4031]: RECV received frame number 74
>> Feb 09 17:04:43.28: [ 4031]: RECV received frame number 75
>> Feb 09 17:04:43.42: [ 4031]: RECV received frame number 76
>> Feb 09 17:04:43.57: [ 4031]: RECV received frame number 77
>> Feb 09 17:04:43.78: [ 4031]: RECV received frame number 78
>> Feb 09 17:04:43.92: [ 4031]: RECV received frame number 79
>> Feb 09 17:04:44.06: [ 4031]: RECV received frame number 80
>> Feb 09 17:04:44.06: [ 4031]: RECV received RCP frame
>> Feb 09 17:04:44.20: [ 4031]: --> [10:NO CARRIER]
>> Feb 09 17:04:44.20: [ 4031]: <-- [9:AT+FRH=3\r]
>> Feb 09 17:04:44.60: [ 4031]: --> [7:CONNECT]
>> Feb 09 17:04:45.63: [ 4031]: --> [2:OK]
>> Feb 09 17:04:45.63: [ 4031]: RECV recv PPS (partial page signal)
>> Feb 09 17:04:45.63: [ 4031]: RECV recv EOP (no more pages or documents)
>> Feb 09 17:04:45.63: [ 4031]: RECV received 81 frames of block 1 of page 4
>> Feb 09 17:04:45.65: [ 4031]: RECV: 20495 bytes of data, 1165 total lines
>> Feb 09 17:04:45.65: [ 4031]: DELAY 70 ms
>> Feb 09 17:04:45.72: [ 4031]: <-- [9:AT+FTH=3\r]
>> Feb 09 17:04:45.76: [ 4031]: --> [7:CONNECT]
>> Feb 09 17:04:45.76: [ 4031]: <-- data [3]
>> Feb 09 17:04:45.76: [ 4031]: <-- data [2]
>> Feb 09 17:04:47.05: [ 4031]: --> [2:OK]
>> Feb 09 17:04:47.05: [ 4031]: RECV send MCF (message confirmation)
>> Feb 09 17:04:47.05: [ 4031]: RECV FAX (000000289): from 055219397, page
>> 4 in 0:16, INF, 3.85 line/mm, 2-D MMR, 14400 bit/s
>> Feb 09 17:04:47.05: [ 4031]: RECV FAX (000000289):
>> recvq/fax000000187.tif from 055219397, route to <unspecified>, 4 pages
>> in 1:29
>> Feb 09 17:04:47.05: [ 4031]: <-- [9:AT+FRH=3\r]
>> Feb 09 17:04:47.48: [ 4031]: --> [7:CONNECT]
>> Feb 09 17:04:48.37: [ 4031]: --> [2:OK]
>> Feb 09 17:04:48.37: [ 4031]: RECV recv DCN (disconnect)
>> Feb 09 17:04:48.37: [ 4031]: RECV FAX: bin/faxrcvd
>> "recvq/fax000000187.tif" "ttyS0" "000000289" ""
>> Feb 09 17:04:48.37: [ 4031]: RECV FAX: end
>> Feb 09 17:04:48.37: [ 4031]: SESSION END
>>
>>
>> no strange conf, only pdf mail.
>>
>> the server only receive fax i don't understand where is the problem
>>
>> sameone can help me??
>>
>> there is a way when we understand the problem to restart hylafax every
>> received fax??
>>
>>
>> thanks,
>>
>> Fabio
>>