On Thu, 25 May 2006, Darren Reed wrote:
To collect information about the ftp proxy activity for bug reports,
do "ipf -T ippr_ftp_debug=10", do exercise to produce the problem and
then "ipf -T ippr_ftp_debug=0".
Thank you for that suggestion. The resulting debug output ends (with the
preceding, almost 2800) lines omitted with
May 24 22:11:38 [hostname] ipf: [ID 197032 kern.notice]
ippr_ftp_process:seq[0](d76b0bb4) + (ffffffe2) != (d76b0bb2)
May 24 22:12:25 [hostname] ipf: [ID 120314 kern.notice] ippr_ftp_process: mlen
29
May 24 22:12:25 [hostname] ipf: [ID 145773 kern.notice] seqoff -31 thseq
d76b0bb4 ackmin d76b0b94
May 24 22:12:25 [hostname] ipf: [ID 414890 kern.notice] ackoff 0 thack b2057e87
seqmin 0
May 24 22:12:25 [hostname] ipf: [ID 117454 kern.notice] IN: 18 seq d76b0bb4/-31
ack b2057e87/0 len 29/69 off 40
May 24 22:12:25 [hostname] ipf: [ID 186263 kern.notice] sel 1 seqmin 0/0 offset
0/0
May 24 22:12:25 [hostname] ipf: [ID 392369 kern.notice] sel 0 ackmin
d76b0b94/d76b0af5 offset -31/-30
May 24 22:12:25 [hostname] ipf: [ID 730772 kern.notice] rv 1 t:seq[0] b2057e87
seq[1] b2057e87 -31/0
May 24 22:12:25 [hostname] ipf: [ID 599374 kern.notice] ippr_ftp_process:len
29/0 off 69 wptr 3006e3fff31 junk 0 [.*s]
May 24 22:12:25 [hostname] ipf: [ID 261411 kern.notice] ippr_ftp_valid=0 len 29 rv 1 ptr 3006e3fff14/3006e3fff31
May 24 22:12:25 [hostname] ipf: [ID 364674 kern.notice] buf [.*s]
May 24 22:12:25 [hostname] ipf: [ID 498613 kern.notice] ftps_seq[1] = d76b0bd1
inc 0 len 0
May 24 22:12:25 [hostname] ipf: [ID 120314 kern.notice] ippr_ftp_process: mlen 0
May 24 22:12:25 [hostname] ipf: [ID 117454 kern.notice] OUT: 10 seq b2057e87/0
ack d76b0bb2/-30 len 0/40 off 54
May 24 22:12:25 [hostname] ipf: [ID 186263 kern.notice] sel 0 seqmin 0/0 offset
0/0
May 24 22:12:25 [hostname] ipf: [ID 392369 kern.notice] sel 1 ackmin
d76b0af5/d76b0b94 offset -30/-31
May 24 22:12:25 [hostname] ipf: [ID 730772 kern.notice] rv 0 t:seq[0] d76b0bb4
seq[1] d76b0bd1 0/-30
May 24 22:12:25 [hostname] ipf: [ID 154247 kern.notice] not ok
May 24 22:12:25 [hostname] ipf: [ID 197032 kern.notice]
ippr_ftp_process:seq[0](d76b0bb4) + (ffffffe2) != (d76b0bb2)
[NB long pause here corresponding to client timeout]
May 24 22:15:51 [hostname] ipf: [ID 120314 kern.notice] ippr_ftp_process: mlen 8
May 24 22:15:51 [hostname] ipf: [ID 117454 kern.notice] OUT: 18 seq b2057e87/0
ack d76b0bb2/-30 len 8/48 off 40
May 24 22:15:51 [hostname] ipf: [ID 186263 kern.notice] sel 0 seqmin 0/0 offset
0/0
May 24 22:15:51 [hostname] ipf: [ID 392369 kern.notice] sel 1 ackmin
d76b0af5/d76b0b94 offset -30/-31
May 24 22:15:51 [hostname] ipf: [ID 730772 kern.notice] rv 0 t:seq[0] d76b0bb4
seq[1] d76b0bd1 0/-30
May 24 22:15:51 [hostname] ipf: [ID 154247 kern.notice] not ok
May 24 22:15:51 [hostname] ipf: [ID 599374 kern.notice] ippr_ftp_process:len
8/0 off 48 wptr 3006e3ffe74 junk 0 [.*s]
May 24 22:15:51 [hostname] ipf: [ID 261411 kern.notice] ippr_ftp_valid=0 len 8 rv 0 ptr 3006e3ffe6c/3006e3ffe74
May 24 22:15:51 [hostname] ipf: [ID 364674 kern.notice] buf [.*s]
May 24 22:15:51 [hostname] ipf: [ID 498613 kern.notice] ftps_seq[1] = b2057e8f
inc 0 len 0
May 24 22:15:51 [hostname] ipf: [ID 120314 kern.notice] ippr_ftp_process: mlen 6
May 24 22:15:51 [hostname] ipf: [ID 145773 kern.notice] seqoff -31 thseq
d76b0bd1 ackmin d76b0b94
May 24 22:15:51 [hostname] ipf: [ID 414890 kern.notice] ackoff 0 thack 0 seqmin 0
May 24 22:15:51 [hostname] ipf: [ID 117454 kern.notice] IN: 4 seq d76b0bd1/-31
ack 0/0 len 6/46 off 40
May 24 22:15:51 [hostname] ipf: [ID 186263 kern.notice] sel 1 seqmin 0/0 offset
0/0
May 24 22:15:51 [hostname] ipf: [ID 392369 kern.notice] sel 0 ackmin
d76b0b94/d76b0af5 offset -31/-30
May 24 22:15:51 [hostname] ipf: [ID 730772 kern.notice] rv 1 t:seq[0] b2057e87
seq[1] b2057e8f -31/0
May 24 22:15:51 [hostname] ipf: [ID 154247 kern.notice] not ok
May 24 22:15:51 [hostname] ipf: [ID 599374 kern.notice] ippr_ftp_process:len
6/0 off 46 wptr 3006e3fff1a junk 0 [.*s]
May 24 22:15:51 [hostname] ipf: [ID 860473 kern.notice]
ippr_ftp_server_valid:bad:junk 0 len 6/5 c 0x4e buf [.*s]
May 24 22:15:51 [hostname] ipf: [ID 261411 kern.notice] ippr_ftp_valid=1 len 6 rv 1 ptr 3006e3fff14/3006e3fff1a
May 24 22:15:51 [hostname] ipf: [ID 364674 kern.notice] buf [.*s]
May 24 22:15:51 [hostname] ipf: [ID 498613 kern.notice] ftps_seq[1] = d76b0bd7
inc 0 len 0
The client (mirror script) reported failure at the end of a remote
directory listing, noting that it was aborting because "Cannot get remote
directory details" (i.e. the same as usual, in passive mode).
As noted previously, the system acting as FTP client is the one running IP
Filter, the far end is a Mac running the NetPresenz FTP server.
Does that provide any meaningful clues to the problem? The line before the
pause, reporting inequality of two values that were presumably expected to
be equal "looks hopeful", but even if relevant may not offer any clues as
to the cause.
I'm also curious about the "not ok" remarks, which started at the 196th
log entry out of around 2800 and appeared 44 times in the debug
output.
John
--
John Line - web & news development, University of Cambridge Computing Service
