Unexpected +FHNG:2 response after successful page transmit

[Mike Crooks <mc@mmpowered.com.au>]

Hi folks,

I've searched through the Hylafax documentation and FAQ and searchable
mailing list and read my modem documentation as well as downloaded 
Rockwell's AT command reference manual for Fax Class 2 commands

but I'm still stymied ...

9 out of 10 times when transmitting a fax to a normal fax machine
(Sharp UX-222) from a NetComm SmartModem 288 the fax (1 or 2 pages)
goes through ok, but the fax machine gets a COM-3 line error at the
end.  The other 1 out of 10 times it works with no complaints.

A sample session log is:
--
Jan 03 17:37:50.13: [14439]: SESSION BEGIN 00000057 61396969455
Jan 03 17:37:50.13: [14439]: DELAY 2600 ms
Jan 03 17:37:53.73: [14439]: <-- [14:ATE0V1Q0S0=0H\r]
Jan 03 17:37:53.83: [14439]: --> [2:OK]
Jan 03 17:37:53.83: [14439]: <-- [21:ATS8=2S7=60&K3&D2&C1\r]
Jan 03 17:37:53.94: [14439]: --> [2:OK]
Jan 03 17:37:53.94: [14439]: <-- [12:AT+FCLASS=2\r]
Jan 03 17:37:54.03: [14439]: --> [2:OK]
Jan 03 17:37:54.03: [14439]: <-- [10:AT+FTBC=0\r]
Jan 03 17:37:54.12: [14439]: --> [2:OK]
Jan 03 17:37:54.12: [14439]: <-- [10:AT+FBOR=0\r]
Jan 03 17:37:54.21: [14439]: --> [2:OK]
Jan 03 17:37:54.21: [14439]: <-- [13:AT+FPHCTO=30\r]
Jan 03 17:37:54.30: [14439]: --> [2:OK]
Jan 03 17:37:54.30: [14439]: <-- [24:AT+FDCC=1,5,0,2,1,0,0,0\r]
Jan 03 17:37:54.39: [14439]: --> [2:OK]
Jan 03 17:37:54.39: [14439]: <-- [5:ATM0\r]
Jan 03 17:37:54.48: [14439]: --> [2:OK]
Jan 03 17:37:54.51: [14439]: <-- [12:AT+FCLASS=2\r]
Jan 03 17:37:54.70: [14439]: --> [2:OK]
Jan 03 17:37:54.70: [14439]: <-- [10:AT+FTBC=0\r]
Jan 03 17:37:54.89: [14439]: --> [2:OK]
Jan 03 17:37:54.89: [14439]: <-- [10:AT+FBOR=0\r]
Jan 03 17:37:55.08: [14439]: --> [2:OK]
Jan 03 17:37:55.08: [14439]: <-- [13:AT+FPHCTO=30\r]
Jan 03 17:37:55.27: [14439]: --> [2:OK]
Jan 03 17:37:55.27: [14439]: <-- [24:AT+FDCC=1,5,0,2,1,0,0,0\r]
Jan 03 17:37:55.46: [14439]: --> [2:OK]
Jan 03 17:37:55.46: [14439]: <-- [23:AT+FLID="+61396969455"\r]
Jan 03 17:37:55.65: [14439]: --> [2:OK]
Jan 03 17:37:55.65: [14439]: DIAL 96969455
Jan 03 17:37:55.65: [14439]: <-- [13:ATDT96969455\r]
Jan 03 17:38:06.56: [14439]: --> [7:RINGING]
Jan 03 17:38:13.02: [14439]: --> [5:+FCON]
Jan 03 17:38:13.02: [14439]: --> [108:+FNSF:00 00 31 00 4E B8 00 84 0D
DD 00 00 DD DD 00 00 DD DD DD DD DD 97 01 03 05 17 34 40 ED 22 90 00 00
10 ]
Jan 03 17:38:13.02: [14439]: REMOTE NSF "00 00 31 00 4E B8 00 84 0D DD
00 00 DD DD 00 00 DD DD DD DD DD 97 01 03 05 17 34 40 ED 22 90 00 00 10"
Jan 03 17:38:13.14: [14439]: --> [28:+FCSI:"      +61 3 96969455"]
Jan 03 17:38:13.14: [14439]: REMOTE CSI "+61 3 96969455"
Jan 03 17:38:13.14: [14439]: --> [21:+FDIS:1,3,0,2,0,0,0,4]
Jan 03 17:38:13.14: [14439]: --> [2:OK]
Jan 03 17:38:13.14: [14439]: REMOTE best rate 9600 bit/s
Jan 03 17:38:13.14: [14439]: REMOTE max page width 1728 pixels in 215 mm
Jan 03 17:38:13.14: [14439]: REMOTE max unlimited page length 
Jan 03 17:38:13.14: [14439]: REMOTE best vres 7.7 line/mm
Jan 03 17:38:13.14: [14439]: REMOTE best format 1-D MR
Jan 03 17:38:13.14: [14439]: REMOTE best 20 ms, 10 ms/scanline
Jan 03 17:38:13.15: [14439]: USE 9600 bit/s
Jan 03 17:38:13.15: [14439]: USE 20 ms, 10 ms/scanline
Jan 03 17:38:13.15: [14439]: SEND file "docq/doc23.ps;30"
Jan 03 17:38:13.15: [14439]: USE page width 1728 pixels in 215 mm
Jan 03 17:38:13.15: [14439]: USE unlimited page length 
Jan 03 17:38:13.15: [14439]: USE 3.85 line/mm
Jan 03 17:38:13.16: [14439]: USE 1-D MR
Jan 03 17:38:13.16: [14439]: <-- [24:AT+FDIS=0,3,0,2,0,0,0,4\r]
Jan 03 17:38:13.32: [14439]: --> [2:OK]
Jan 03 17:38:13.32: [14439]: <-- [7:AT+FDT\r]
Jan 03 17:38:19.31: [14439]: --> [21:+FDCS:0,3,0,2,0,0,0,4]
Jan 03 17:38:21.03: [14439]: --> [7:CONNECT]
Jan 03 17:38:21.03: [14439]: SEND wait for XON
Jan 03 17:38:21.03: [14439]: --> [1:]
Jan 03 17:38:21.03: [14439]: SEND begin page
Jan 03 17:38:21.04: [14439]: <-- data [1031]
[stuff deleted]
Jan 03 17:38:32.46: [14439]: SENT 16026 bytes of data
Jan 03 17:38:32.46: [14439]: <-- data [2]
Jan 03 17:38:33.00: [14439]: SEND end page
Jan 03 17:38:49.49: [14439]: --> [2:OK]
Jan 03 17:38:49.49: [14439]: SEND send EOP (no more pages or documents)
Jan 03 17:38:49.49: [14439]: <-- [9:AT+FET=2\r]
Jan 03 17:38:53.75: [14439]: --> [7:+FPTS:1]
Jan 03 17:38:53.75: [14439]: SEND recv MCF (message confirmation)
Jan 03 17:38:53.75: [14439]: SEND FAX (00000057): FROM melbwest TO
96969455 (page 1 of 1 sent in 0:40)
Jan 03 17:38:53.75: [14439]: SEND FAX (00000057): FROM melbwest TO
96969455 (docq/doc23.ps;30 sent in 0:40)
Jan 03 17:38:53.83: [14439]: <-- [4:ATH\r]
Jan 03 17:38:53.95: [14439]: --> [7:+FHNG:2]
Jan 03 17:38:53.95: [14439]: REMOTE HANGUP: Call aborted,  from +FK or
<CAN> (code 2)
Jan 03 17:38:53.95: [14439]: --> [2:OK]
Jan 03 17:38:53.95: [14439]: SESSION END
--

Note that the tail differs from the description in the Rockwell manual
which indicates that 
  <-- [9:AT+FET=2\r]
should get a reply of:
  --> [7:+FPTS:1]
  --> [7:+FHNG:0]
  --> [2:OK]

I'm beginning to suspect a timing issue.  Is it possible that
Hylafax is forcing a ATH while the modem is still waiting for the
line to drop before returning the +FHNG:0
Is it possible to delay Hylafax sending the ATH without hacking the
source?

I'm running Hylafax 4.0 beta 15 binary distibution for Solaris 2.5
I tried turning off the PageChop on the final page because I thought
it might be related, but it made no difference.

Regards, Mike.  

--
Mike Crooks                 Email: mc@mmpowered.com.au
mmpowered communications    ACN: 007 093 343   Phone:+61 3 96969499 
177 Clarendon St South Melbourne, Vic. 3205    Fax:  +61 3 96969455