flexfax: PTS problems resulting in RTN

[Paul Stevens <paul@nfg.nl>]

Hi all,

Im having trouble with what looks like incorrect post page status
transmission. 

Many people who send faxes to my modems complain of retransmissions of
pages. I often receive the first page two or more times over while
following pages are never received at all.

Using two machines with identical Hylafax configs on identical modems
results in  typical traces reproduced below.

Hylafax: V4.0beta20
Systems: debian(1.3/2.0)-i386, gcc-2.7.2.3
Modems: Vaes I1400-V.34NL (a dutch class 1,2 faxmodem)
Firmware: RC288DPi  Rev 05BA
Modem capabilities: AT+FDCC=?	(0,1),(0-5),(0-2),(0-2),(0-1),0,0,(0-7)

If anyone would be so kind as to shed some light on this matter I
would be greatfull.

follows:
- brief excerpt from relevant parts of logs
- longer excerpts from logs
- config.modem
-----------------------------------------------------

brief logs:

Receiver:
Jun 16 16:17:48.37: [  435]: RECV: send trigger 022
Jun 16 16:17:48.37: [  435]: <-- data [1]
Jun 16 16:18:11.27: [  435]: RECV: 1153 total lines, 1 bad lines, 1 consecutive bad lines
Jun 16 16:18:11.27: [  435]: --> [17:+FPTS: 2,2219,0,0]	# major suspect ?
Jun 16 16:18:12.51: [  435]: --> [7:+FET: 2]
Jun 16 16:18:12.51: [  435]: RECV recv EOP (no more pages or documents)
Jun 16 16:18:12.62: [  435]: --> [2:OK]
Jun 16 16:18:12.62: [  435]: RECV send MCF (message confirmation)

Sender:
Jun 17 17:47:41.59: [  584]: SEND end page
Jun 17 17:47:44.34: [  584]: --> [2:OK]
Jun 17 17:47:44.34: [  584]: SEND send EOP (no more pages or documents)
Jun 17 17:47:44.34: [  584]: <-- [9:AT+FET=2\r]
Jun 17 17:47:47.39: [  584]: --> [8:+FPTS: 2]		# I think this should be +FPTS: 1
Jun 17 17:47:47.50: [  584]: --> [2:OK]
Jun 17 17:47:47.50: [  584]: SEND recv RTN (retrain negative)
Jun 17 17:47:47.50: [  584]: <-- [7:AT+FDT\r]
Jun 17 17:47:55.21: [  584]: --> [22:+FDCS: 0,5,0,2,1,0,0,0]
Jun 17 17:47:55.21: [  584]: --> [7:CONNECT]
Jun 17 17:47:55.21: [  584]: SEND wait for XON


-----------------------------------------------------
Long logs

Sender:

Jun 17 17:46:53.21: [  584]: SESSION BEGIN 00000659 31433560502
Jun 17 17:46:53.22: [  584]: SEND FAX: JOB 48 DEST 0433560502 COMMID 00000659
Jun 17 17:46:53.22: [  584]: MODEM set DTR OFF
Jun 17 17:46:53.22: [  584]: DELAY 2600 ms
Jun 17 17:46:55.83: [  584]: MODEM set DTR ON
Jun 17 17:46:55.83: [  584]: MODEM set baud rate: 115200 baud, input flow RTS/CTS, output flow RTS/CTS
Jun 17 17:46:55.83: [  584]: MODEM flush i/o
Jun 17 17:46:55.83: [  584]: <-- [15:ATE0V1Q0S0=0H0\r]
Jun 17 17:46:55.85: [  584]: --> [2:OK]
Jun 17 17:46:55.85: [  584]: <-- [21:ATS8=2S7=60&K3&D3&C1\r]
Jun 17 17:46:55.86: [  584]: --> [2:OK]
Jun 17 17:46:55.86: [  584]: <-- [12:AT+FCLASS=2\r]
Jun 17 17:46:55.87: [  584]: --> [2:OK]
Jun 17 17:46:55.87: [  584]: <-- [10:AT+FTBC=0\r]
Jun 17 17:46:55.88: [  584]: --> [2:OK]
Jun 17 17:46:55.88: [  584]: <-- [10:AT+FBOR=0\r]
Jun 17 17:46:55.89: [  584]: --> [2:OK]
Jun 17 17:46:55.89: [  584]: <-- [13:AT+FPHCTO=30\r]
Jun 17 17:46:55.90: [  584]: --> [2:OK]
Jun 17 17:46:55.90: [  584]: <-- [10:AT+FBUG=1\r]
Jun 17 17:46:55.91: [  584]: --> [5:ERROR]
Jun 17 17:46:55.91: [  584]: MODEM Command error
Jun 17 17:46:55.91: [  584]: <-- [24:AT+FDCC=1,5,2,2,1,0,0,0\r]
Jun 17 17:46:55.92: [  584]: --> [2:OK]
Jun 17 17:46:55.92: [  584]: <-- [5:ATM0\r]
Jun 17 17:46:55.93: [  584]: --> [2:OK]
Jun 17 17:46:55.93: [  584]: MODEM input buffering enabled
Jun 17 17:46:55.93: [  584]: <-- [12:AT+FCLASS=2\r]
Jun 17 17:46:56.04: [  584]: --> [2:OK]
Jun 17 17:46:56.04: [  584]: <-- [10:AT+FTBC=0\r]
Jun 17 17:46:56.15: [  584]: --> [2:OK]
Jun 17 17:46:56.15: [  584]: <-- [10:AT+FBOR=0\r]
Jun 17 17:46:56.26: [  584]: --> [2:OK]
Jun 17 17:46:56.26: [  584]: <-- [13:AT+FPHCTO=30\r]
Jun 17 17:46:56.37: [  584]: --> [2:OK]
Jun 17 17:46:56.37: [  584]: <-- [10:AT+FBUG=1\r]
Jun 17 17:46:56.48: [  584]: --> [5:ERROR]
Jun 17 17:46:56.48: [  584]: MODEM Command error
Jun 17 17:46:56.48: [  584]: <-- [24:AT+FDCC=1,5,2,2,1,0,0,0\r]
Jun 17 17:46:56.59: [  584]: --> [2:OK]
Jun 17 17:46:56.59: [  584]: <-- [25:AT+FLID="+31.30.2817227"\r]
Jun 17 17:46:56.70: [  584]: --> [2:OK]
Jun 17 17:46:56.73: [  584]: DIAL 0433560502
Jun 17 17:46:56.73: [  584]: <-- [15:ATDT0433560502\r]
Jun 17 17:47:11.64: [  584]: --> [5:+FCON]
Jun 17 17:47:13.23: [  584]: --> [29:+FCSI: "      +31.43.3560502"]
Jun 17 17:47:13.23: [  584]: REMOTE CSI "+31.43.3560502"
Jun 17 17:47:13.73: [  584]: --> [22:+FDIS: 1,5,2,2,1,0,0,0]
Jun 17 17:47:13.73: [  584]: --> [2:OK]
Jun 17 17:47:13.73: [  584]: REMOTE best rate 14400 bit/s
Jun 17 17:47:13.73: [  584]: REMOTE max page width 2432 pixels in 303 mm
Jun 17 17:47:13.73: [  584]: REMOTE max unlimited page length 
Jun 17 17:47:13.73: [  584]: REMOTE best vres 7.7 line/mm
Jun 17 17:47:13.73: [  584]: REMOTE best format 2-D MR
Jun 17 17:47:13.73: [  584]: REMOTE best 0 ms/scanline
Jun 17 17:47:13.74: [  584]: USE 14400 bit/s
Jun 17 17:47:13.74: [  584]: USE 0 ms/scanline
Jun 17 17:47:13.74: [  584]: SEND file "docq/doc52.tif;40"
Jun 17 17:47:13.75: [  584]: USE page width 1728 pixels in 215 mm
Jun 17 17:47:13.75: [  584]: USE unlimited page length 
Jun 17 17:47:13.75: [  584]: USE 3.85 line/mm
Jun 17 17:47:13.75: [  584]: USE 2-D MR
Jun 17 17:47:13.75: [  584]: <-- [24:AT+FDIS=0,5,0,2,1,0,0,0\r]
Jun 17 17:47:13.87: [  584]: --> [2:OK]
Jun 17 17:47:13.87: [  584]: <-- [7:AT+FDT\r]
Jun 17 17:47:21.57: [  584]: --> [22:+FDCS: 0,5,0,2,1,0,0,0]
Jun 17 17:47:21.57: [  584]: --> [7:CONNECT]
Jun 17 17:47:21.57: [  584]: SEND wait for XON
Jun 17 17:47:21.57: [  584]: --> [1:]
Jun 17 17:47:21.57: [  584]: SEND begin page
Jun 17 17:47:21.60: [  584]: <-- data [1034]

[ .. ]

Jun 17 17:47:41.05: [  584]: <-- data [945]
Jun 17 17:47:41.59: [  584]: SENT 39852 bytes of data
Jun 17 17:47:41.59: [  584]: <-- data [2]
Jun 17 17:47:41.59: [  584]: SEND end page
Jun 17 17:47:44.34: [  584]: --> [2:OK]
Jun 17 17:47:44.34: [  584]: SEND send EOP (no more pages or documents)
Jun 17 17:47:44.34: [  584]: <-- [9:AT+FET=2\r]
Jun 17 17:47:47.39: [  584]: --> [8:+FPTS: 2]
Jun 17 17:47:47.50: [  584]: --> [2:OK]
Jun 17 17:47:47.50: [  584]: SEND recv RTN (retrain negative)
Jun 17 17:47:47.50: [  584]: <-- [7:AT+FDT\r]
Jun 17 17:47:55.21: [  584]: --> [22:+FDCS: 0,5,0,2,1,0,0,0]
Jun 17 17:47:55.21: [  584]: --> [7:CONNECT]
Jun 17 17:47:55.21: [  584]: SEND wait for XON
Jun 17 17:47:55.21: [  584]: --> [1:]
Jun 17 17:47:55.21: [  584]: SEND begin page
Jun 17 17:47:55.23: [  584]: <-- data [1034]

[ .. ]

Jun 17 17:48:14.67: [  584]: <-- data [945]
Jun 17 17:48:15.23: [  584]: SENT 39852 bytes of data
Jun 17 17:48:15.23: [  584]: <-- data [2]
Jun 17 17:48:15.23: [  584]: SEND end page
Jun 17 17:48:17.96: [  584]: --> [2:OK]
Jun 17 17:48:17.96: [  584]: SEND send EOP (no more pages or documents)
Jun 17 17:48:17.96: [  584]: <-- [9:AT+FET=2\r]
Jun 17 17:48:31.73: [  584]: --> [9:+FHNG: 54]
Jun 17 17:48:31.73: [  584]: REMOTE HANGUP: No response to EOP repeated 3 times (code 54)
Jun 17 17:48:31.73: [  584]: <-- [5:ATH0\r]
Jun 17 17:48:32.32: [  584]: --> [2:OK]
Jun 17 17:48:32.32: [  584]: MODEM set DTR OFF
Jun 17 17:48:32.33: [  584]: SESSION END


Receiver:
Jun 16 16:17:31.83: [  435]: SESSION BEGIN 00000119 31433560502
Jun 16 16:17:31.84: [  435]: <-- [4:ATA\r]
Jun 16 16:17:34.91: [  435]: --> [3:FAX]
Jun 16 16:17:34.91: [  435]: ANSWER: FAX CONNECTION
Jun 16 16:17:34.91: [  435]: RECV FAX: begin
Jun 16 16:17:42.57: [  435]: --> [5:b'asę]
Jun 16 16:17:42.57: [  435]: --> [29:+FTSI: "      +31.30.2817227"]
Jun 16 16:17:42.57: [  435]: REMOTE TSI "+31.30.2817227"
Jun 16 16:17:43.03: [  435]: --> [22:+FDCS: 0,5,0,2,1,0,0,0]
Jun 16 16:17:43.03: [  435]: REMOTE wants 14400 bit/s
Jun 16 16:17:43.03: [  435]: REMOTE wants page width 1728 pixels in 215 mm
Jun 16 16:17:43.03: [  435]: REMOTE wants unlimited page length 
Jun 16 16:17:43.03: [  435]: REMOTE wants 3.85 line/mm
Jun 16 16:17:43.03: [  435]: REMOTE wants 2-D MR
Jun 16 16:17:43.14: [  435]: --> [2:OK]
Jun 16 16:17:43.14: [  435]: <-- [7:AT+FDR\r]
Jun 16 16:17:46.09: [  435]: --> [5:+FCFR]
Jun 16 16:17:48.37: [  435]: --> [22:+FDCS: 0,5,0,2,1,0,0,0]
Jun 16 16:17:48.37: [  435]: REMOTE wants 14400 bit/s
Jun 16 16:17:48.37: [  435]: REMOTE wants page width 1728 pixels in 215 mm
Jun 16 16:17:48.37: [  435]: REMOTE wants unlimited page length 
Jun 16 16:17:48.37: [  435]: REMOTE wants 3.85 line/mm
Jun 16 16:17:48.37: [  435]: REMOTE wants 2-D MR
Jun 16 16:17:48.37: [  435]: --> [7:CONNECT]
Jun 16 16:17:48.37: [  435]: RECV: begin page
Jun 16 16:17:48.37: [  435]: RECV: send trigger 022
Jun 16 16:17:48.37: [  435]: <-- data [1]
Jun 16 16:18:11.27: [  435]: RECV: 1153 total lines, 1 bad lines, 1 consecutive bad lines
Jun 16 16:18:11.27: [  435]: --> [17:+FPTS: 2,2219,0,0]
Jun 16 16:18:12.51: [  435]: --> [7:+FET: 2]
Jun 16 16:18:12.51: [  435]: RECV recv EOP (no more pages or documents)
Jun 16 16:18:12.62: [  435]: --> [2:OK]
Jun 16 16:18:12.62: [  435]: RECV send MCF (message confirmation)
Jun 16 16:18:12.62: [  435]: RECV FAX (00000119): from +31.30.2817227, page 1 in 0:29, INF, 3.85 line/mm, 2-D MR
Jun 16 16:18:12.62: [  435]: RECV FAX (00000119): recvq/fax00095.tif from +31.30.2817227, route to <unspecified>, 1 pages in 0:38
Jun 16 16:18:12.64: [  435]: <-- [7:AT+FDR\r]
Jun 16 16:18:16.13: [  435]: --> [29:+FTSI: "      +31.30.2817227"]
Jun 16 16:18:16.13: [  435]: RECV FAX: bin/faxrcvd "recvq/fax00095.tif" "modem" "00000119" ""
Jun 16 16:18:17.85: [  435]: RECV FAX: end
Jun 16 16:18:17.85: [  435]: SESSION END
-----------------------------------------------------


config.modem



CountryCode:		31
AreaCode:		30
FAXNumber:		+31.30.2817227
LongDistancePrefix:	0
InternationalPrefix:	00
DialStringRules:	etc/dialrules
ServerTracing:		1
#SessionTracing:		8467
SessionTracing:		46671
LogFacility:		local5
RecvFileMode:		0664
LogFileMode:		0664
DeviceMode:		0660
RingsBeforeAnswer:	1
SpeakerVolume:		off
GettyArgs:		"-h %l %s vt100"
#
LocalIdentifier:	+31.30.2817227
TagLineFont:		etc/lutRS18.pcf
TagLineFormat:		"From %%l|%c|Page %%p of %%t"
MaxRecvPages:		25


#
# Configuration for a Rockwell RC288DPi-based Class 2 modem
# (should also work for 144DPi-based modems).
#    Microcom DeskPorte 28.8S	firmware rev V1.100K-V34_DS
#    (and others)
#
# NB: DCD is toggled at page end during transmits; this can
#     cause problems on systems where it's not possible to
#     set CLOCAL and also enable RTS/CTS flow control.
#
# CONFIG: CLASS2: ROCKWELL-AC/V34-*
#
# BEGIN-SERVER
# END-SERVER
#
# Modem-related stuff: should reflect modem command interface
# and hardware connection/cabling (e.g. flow control).
#
ModemType:		Class2		# use class 1 interface
ModemRate:		115200		# locked for fax sending&receiving
ModemFlowControl:	rtscts		# default
#
ModemNoFlowCmd:		AT&K0		# disable flow control cmd
ModemSoftFlowCmd:	AT&K4		# software flow control cmd
ModemHardFlowCmd:	AT&K3		# hardware flow control cmd
ModemSetupDTRCmd:	AT&D3		# DTR off causes modem to reset
ModemSetupDCDCmd:	AT&C1		# DCD follows carrier
ModemSetupAACmd:        AT+FAA=1+FCLASS=0       # enable adaptive-answer in Class 2
ModemAnswerFaxCmd:      AT+FAA=1
#
ModemRecvFillOrder:	MSB2LSB		# bit order of received facsimile
ModemSendFillOrder:	LSB2MSB		# bit order modem expects for transmit
#
ModemDialCmd:		ATDT%s		# T for tone dialing
#
# Chip locks the line rate and switches to xon/xoff flow
# control when receiving facsimile--we must follow suit.
#
ModemAnswerFaxBeginCmd:	"<9600><xon>"	# lock line rate & switch flow control
#
Class2RecvDataTrigger:	"\022"		# character sent to modem to start recv
#
UUCPLockDir:            /var/lock
UUCPLockTimeout:        15
#
 

-- 
  ________________________________________________________________
  Paul Stevens                                  mailto:paul@nfg.nl
  NET FACILITIES GROUP                     PGP: finger paul@nfg.nl
  The Netherlands________________________________http://www.nfg.nl