Re: voice calls to faxmodem (slow recovery)

[Tim Tsai <tim@futuresouth.com>]

>     Feb  1 00:12:46 mail FaxGetty[23826]: STATE CHANGE: RUNNING -> LISTENING
> 
> This isn't a session(!) trace, it's a server trace; the log of
> a session is in spool/log/c0000.... and please send one of such
> a voice call.

  I feel really really really stupid.  :-(  Sorry about that.  Here it
is:

Feb 01 00:12:46.70: [23826]: SESSION BEGIN 00000013 16018404056
Feb 01 00:12:46.70: [23826]: <-- [22:AT+FCLASS=1&H1&I0&R2A\r]
Feb 01 00:12:52.23: [23826]: --> [7:CONNECT]
Feb 01 00:12:52.23: [23826]: ANSWER: FAX CONNECTION
Feb 01 00:12:52.23: [23826]: STATE CHANGE: ANSWERING -> RECEIVING
Feb 01 00:12:52.23: [23826]: MODEM input buffering enabled
Feb 01 00:12:52.24: [23826]: RECV FAX: begin
Feb 01 00:12:52.25: [23826]: MODEM input buffering disabled
Feb 01 00:12:52.25: [23826]: <-- HDLC<23:FF C0 02 92 C2 CA 62 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04>
Feb 01 00:12:52.25: [23826]: <-- data [23]
Feb 01 00:12:52.25: [23826]: <-- data [2]
Feb 01 00:12:53.87: [23826]: --> [7:CONNECT]
Feb 01 00:12:53.87: [23826]: <-- HDLC<10:FF C8 01 00 77 5F 01 79 03 C0>
Feb 01 00:12:53.87: [23826]: <-- data [10]
Feb 01 00:12:53.87: [23826]: <-- data [2]
Feb 01 00:12:54.68: [23826]: --> [2:OK]
Feb 01 00:12:54.68: [23826]: <-- [9:AT+FRH=3\r]
Feb 01 00:12:56.15: [23826]: --> [7:CONNECT]
Feb 01 00:12:57.79: [23826]: MODEM TIMEOUT: waiting for HDLC flags
Feb 01 00:12:57.79: [23826]: <-- data [1]
Feb 01 00:12:58.00: [23826]: MODEM TIMEOUT: reading line from modem
Feb 01 00:12:58.00: [23826]: MODEM <Timeout>
Feb 01 00:12:58.00: [23826]: DELAY 1500 ms
Feb 01 00:12:59.51: [23826]: <-- [9:AT+FTH=3\r]
Feb 01 00:12:59.60: [23826]: --> [7:CONNECT]
Feb 01 00:12:59.60: [23826]: <-- HDLC<23:FF C0 02 92 C2 CA 62 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04>
Feb 01 00:12:59.60: [23826]: <-- data [23]
Feb 01 00:12:59.60: [23826]: <-- data [2]
Feb 01 00:13:01.34: [23826]: --> [7:CONNECT]
Feb 01 00:13:01.34: [23826]: <-- HDLC<10:FF C8 01 00 77 5F 01 79 03 C0>
Feb 01 00:13:01.34: [23826]: <-- data [10]
Feb 01 00:13:01.34: [23826]: <-- data [2]
Feb 01 00:13:02.15: [23826]: --> [2:OK]
Feb 01 00:13:02.15: [23826]: <-- [9:AT+FRH=3\r]
Feb 01 00:13:05.26: [23826]: --> [0:]
Feb 01 00:13:05.26: [23826]: MODEM <Empty line>
Feb 01 00:13:05.26: [23826]: MODEM TIMEOUT: waiting for v.21 carrier
Feb 01 00:13:05.26: [23826]: <-- data [1]
Feb 01 00:13:05.27: [23826]: --> [2:OK]
Feb 01 00:13:05.27: [23826]: DELAY 1500 ms
Feb 01 00:13:06.78: [23826]: <-- [9:AT+FTH=3\r]
Feb 01 00:13:06.87: [23826]: --> [7:CONNECT]
Feb 01 00:13:06.87: [23826]: <-- HDLC<23:FF C0 02 92 C2 CA 62 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04>
Feb 01 00:13:06.87: [23826]: <-- data [23]
Feb 01 00:13:06.87: [23826]: <-- data [2]
Feb 01 00:13:08.61: [23826]: --> [7:CONNECT]
Feb 01 00:13:08.61: [23826]: <-- HDLC<10:FF C8 01 00 77 5F 01 79 03 C0>
Feb 01 00:13:08.61: [23826]: <-- data [10]
Feb 01 00:13:08.61: [23826]: <-- data [2]
Feb 01 00:13:09.42: [23826]: --> [2:OK]
Feb 01 00:13:09.42: [23826]: <-- [9:AT+FRH=3\r]
Feb 01 00:13:10.04: [23826]: --> [7:CONNECT]
Feb 01 00:13:12.53: [23826]: MODEM TIMEOUT: waiting for HDLC flags
Feb 01 00:13:12.53: [23826]: <-- data [1]
Feb 01 00:13:12.74: [23826]: MODEM TIMEOUT: reading line from modem
Feb 01 00:13:12.74: [23826]: MODEM <Timeout>
Feb 01 00:13:12.74: [23826]: DELAY 1500 ms
Feb 01 00:13:14.25: [23826]: <-- [9:AT+FTH=3\r]
Feb 01 00:13:14.34: [23826]: --> [7:CONNECT]
Feb 01 00:13:14.34: [23826]: <-- HDLC<23:FF C0 02 92 C2 CA 62 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04>
Feb 01 00:13:14.34: [23826]: <-- data [23]
Feb 01 00:13:14.34: [23826]: <-- data [2]
Feb 01 00:13:16.08: [23826]: --> [7:CONNECT]
Feb 01 00:13:16.08: [23826]: <-- HDLC<10:FF C8 01 00 77 5F 01 79 03 C0>
Feb 01 00:13:16.08: [23826]: <-- data [10]
Feb 01 00:13:16.08: [23826]: <-- data [2]
Feb 01 00:13:16.89: [23826]: --> [2:OK]
Feb 01 00:13:16.89: [23826]: <-- [9:AT+FRH=3\r]
Feb 01 00:13:20.00: [23826]: --> [0:]
Feb 01 00:13:20.00: [23826]: MODEM <Empty line>
Feb 01 00:13:20.00: [23826]: MODEM TIMEOUT: waiting for v.21 carrier
Feb 01 00:13:20.00: [23826]: <-- data [1]
Feb 01 00:13:20.01: [23826]: --> [2:OK]
Feb 01 00:13:20.01: [23826]: DELAY 1500 ms
Feb 01 00:13:21.52: [23826]: <-- [9:AT+FTH=3\r]
Feb 01 00:13:21.61: [23826]: --> [7:CONNECT]
Feb 01 00:13:21.61: [23826]: <-- HDLC<23:FF C0 02 92 C2 CA 62 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04>
Feb 01 00:13:21.61: [23826]: <-- data [23]
Feb 01 00:13:21.61: [23826]: <-- data [2]
Feb 01 00:13:23.35: [23826]: --> [7:CONNECT]
Feb 01 00:13:23.35: [23826]: <-- HDLC<10:FF C8 01 00 77 5F 01 79 03 C0>
Feb 01 00:13:23.35: [23826]: <-- data [10]
Feb 01 00:13:23.35: [23826]: <-- data [2]
Feb 01 00:13:24.16: [23826]: --> [2:OK]
Feb 01 00:13:24.16: [23826]: <-- [9:AT+FRH=3\r]
Feb 01 00:13:27.27: [23826]: --> [0:]
Feb 01 00:13:27.27: [23826]: MODEM <Empty line>
Feb 01 00:13:27.27: [23826]: MODEM TIMEOUT: waiting for v.21 carrier
Feb 01 00:13:27.27: [23826]: <-- data [1]
Feb 01 00:13:27.28: [23826]: --> [2:OK]
Feb 01 00:13:27.28: [23826]: DELAY 1500 ms
Feb 01 00:13:28.79: [23826]: <-- [9:AT+FTH=3\r]
Feb 01 00:13:28.88: [23826]: --> [7:CONNECT]
Feb 01 00:13:28.88: [23826]: <-- HDLC<23:FF C0 02 92 C2 CA 62 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04>
Feb 01 00:13:28.88: [23826]: <-- data [23]
Feb 01 00:13:28.88: [23826]: <-- data [2]
Feb 01 00:13:30.62: [23826]: --> [7:CONNECT]
Feb 01 00:13:30.62: [23826]: <-- HDLC<10:FF C8 01 00 77 5F 01 79 03 C0>
Feb 01 00:13:30.62: [23826]: <-- data [10]
Feb 01 00:13:30.62: [23826]: <-- data [2]
Feb 01 00:13:31.43: [23826]: --> [2:OK]
Feb 01 00:13:31.43: [23826]: <-- [9:AT+FRH=3\r]
Feb 01 00:13:34.54: [23826]: --> [0:]
Feb 01 00:13:34.54: [23826]: MODEM <Empty line>
Feb 01 00:13:34.54: [23826]: MODEM TIMEOUT: waiting for v.21 carrier
Feb 01 00:13:34.54: [23826]: <-- data [1]
Feb 01 00:13:34.55: [23826]: --> [2:OK]
Feb 01 00:13:34.55: [23826]: RECV FAX: No answer (T.30 T1 timeout)
Feb 01 00:13:34.56: [23826]: RECV FAX: end
Feb 01 00:13:34.56: [23826]: SESSION END