TimeoutStalled with binary transfer

[OllyC]

hi Guys,

We're running proftpd 1.3.0 on AIX 5.2
We have the TimeoutStalled directive to kill off dead connections.  it works fine for ASCII transfers, but for binary transfers the connection is closed early.
For binary connections rather than wait for the connection to stall and then start the timer, the timer starts immediately the connection is made.

Code:

ftp> get /tmp/olly.txt
200 PORT command successful
150 Opening ASCII mode data connection for /tmp/olly.txt (37518690 bytes)
226 Transfer complete.
ftp: 37598517 bytes received in 69.85Seconds 538.29Kbytes/sec.
ftp> bin
200 Type set to I
ftp> get  /tmp/olly.txt
200 PORT command successful
150 Opening BINARY mode data connection for /tmp/olly.txt (37518690 bytes)
Connection closed by remote host.
ftp> ls
Not connected.

in the above example, TimeoutStalled was set to 10; the ASCII transfer worked fine (the connection never stalled), but the binary connection got closed after only 10s even though data was flowing ok.
(typically we have the TimeoutStalled set higher, but it was set to 10 for testing)

Has anyone got any ideas on a solution?
cheers

[castaglia]

Please provide the proftpd debug logging:

  http://www.castaglia.org/proftpd/doc/contrib/ProFTPD-mini-HOWTO-Debugging.html

Attempting to analyze a server issue using only the error messages you see in the client will only cause frustration.

[OllyC]

in the ftplog, when I use ASCII transfer I see loads of

Code:

FS: using system read()

but these are missing in the binary transfer (even in a successful binary transfer they are missing).

here's the first half of the log showing the successful ASCII transfer:

Code:

May 10 15:18:46 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): scrubbing scoreboard
May 10 15:18:46 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): ROOT PRIVS at mod_core.c:131
May 10 15:18:46 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): RELINQUISH PRIVS at mod_core.c:133
May 10 15:18:46 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): ROOT PRIVS at mod_core.c:161
May 10 15:18:46 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): RELINQUISH PRIVS at mod_core.c:192
May 10 15:18:46 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): ident lookup disabled
May 10 15:18:46 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): connected - local  : 10.106.13.8:21
May 10 15:18:46 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): connected - remote : 10.17.11.32:2693
May 10 15:18:46 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FTP session opened.
May 10 15:18:48 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'USER mercator' to mod_tls
May 10 15:18:48 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'USER mercator' to mod_core
May 10 15:18:48 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'USER mercator' to mod_core
May 10 15:18:48 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'USER mercator' to mod_delay
May 10 15:18:48 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'USER mercator' to mod_auth
May 10 15:18:48 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "endpwent" to module mod_auth_file
May 10 15:18:48 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "endpwent" to module mod_auth_unix
May 10 15:18:48 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "endgrent" to module mod_auth_file
May 10 15:18:48 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "endgrent" to module mod_auth_unix
May 10 15:18:48 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching CMD command 'USER mercator' to mod_auth
May 10 15:18:48 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "getgroups" to module mod_auth_file
May 10 15:18:48 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "getgroups" to module mod_auth_unix
May 10 15:18:48 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "requires_pass" to module mod_tls
May 10 15:18:48 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching POST_CMD command 'USER mercator' to mod_delay
May 10 15:18:48 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching LOG_CMD command 'USER mercator' to mod_log
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'PASS (hidden)' to mod_tls
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'PASS (hidden)' to mod_core
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'PASS (hidden)' to mod_core
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'PASS (hidden)' to mod_delay
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'PASS (hidden)' to mod_auth
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "endpwent" to module mod_auth_file
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "endpwent" to module mod_auth_unix
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "endgrent" to module mod_auth_file
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "endgrent" to module mod_auth_unix
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching CMD command 'PASS (hidden)' to mod_auth
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "getgroups" to module mod_auth_file
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "getgroups" to module mod_auth_unix
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "getpwnam" to module mod_auth_file
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "getpwnam" to module mod_auth_unix
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "gid2name" to module mod_auth_file
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "gid2name" to module mod_auth_unix
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "auth" to module mod_tls
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "auth" to module mod_auth_pam
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): ROOT PRIVS at mod_auth_pam.c:264
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): RELINQUISH PRIVS at mod_auth_pam.c:423
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): user mercator authenticated by mod_auth_pam.c
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "setgrent" to module mod_auth_file
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "setgrent" to module mod_auth_unix
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): ROOT PRIVS at mod_auth.c:463
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): RELINQUISH PRIVS at mod_auth.c:465
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): USER PRIVS 210 at mod_auth.c:1042
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): RELINQUISH PRIVS at mod_auth.c:1044
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]):
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): Config for EIH Test ftp server:
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): DefaultServer
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): IdentLookups
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): HiddenStores
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): RootLogin
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): TimeoutStalled
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): RootLogin
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): TimeoutStalled
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): TimeoutNoTransfer
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): TimeoutIdle
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): TimeoutLogin
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): SyslogLevel
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): DebugLevel
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): DelayEngine
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): DefaultRoot
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): Umask
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): UserID
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): UserName
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): GroupID
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): GroupName
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): /
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]):  Limit
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]):   DenyAll
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]):  AllowOverwrite
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]):  HiddenStores
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]):  RootLogin
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]):  Umask
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]):  TransferLog
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): TransferLog
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): ExtendedLog
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): CURRENT-CLIENTS
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): USER
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): USER mercator: Login successful.
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): ROOT PRIVS at mod_auth.c:1113
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): opening TransferLog '/var/adm/ftplog_pipe.xfer'
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): RELINQUISH PRIVS at mod_auth.c:1142
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): ROOT PRIVS at mod_auth.c:1185
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): SETUP PRIVS at mod_auth.c:1192
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system chdir()
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): in dir_check_full(): path = '/home/mercator', fullpath = '/home/merc
ator'.
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system stat()
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system stat()
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system stat()
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system stat()
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system stat()
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system stat()
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system stat()
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system stat()
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching POST_CMD command 'PASS (hidden)' to mod_tls
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching POST_CMD command 'PASS (hidden)' to mod_delay
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching POST_CMD command 'PASS (hidden)' to mod_log
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching POST_CMD command 'PASS (hidden)' to mod_ls
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching POST_CMD command 'PASS (hidden)' to mod_auth
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): RELINQUISH PRIVS at mod_auth.c:1552
May 10 15:18:49 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching LOG_CMD command 'PASS (hidden)' to mod_log
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'PORT 10,17,11,32,10,135' to mod_tls
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'PORT 10,17,11,32,10,135' to mod_core
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'PORT 10,17,11,32,10,135' to mod_core
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching CMD command 'PORT 10,17,11,32,10,135' to mod_core
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system stat()
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system stat()
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching LOG_CMD command 'PORT 10,17,11,32,10,135' to mod_log
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'RETR /tmp/olly.txt' to mod_tls
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching LOG_CMD command 'PORT 10,17,11,32,10,135' to mod_log
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'RETR /tmp/olly.txt' to mod_tls
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'RETR /tmp/olly.txt' to mod_core
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'RETR /tmp/olly.txt' to mod_core
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'RETR /tmp/olly.txt' to mod_xfer
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system stat()
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system lstat()
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching CMD command 'RETR /tmp/olly.txt' to mod_xfer
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system open()
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system stat()
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): ROOT PRIVS at inet.c:323
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): RELINQUISH PRIVS at inet.c:381
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): active data connection opened - local  : 10.106.13.8:20
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): active data connection opened - remote : 10.17.11.32:2695
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system read()
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system read()
May 10 15:18:53 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system read()
... loads more system reads ....
May 10 15:20:00 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system read()
May 10 15:20:00 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system close()

[OllyC]

heres the second half of the log showing a binary transfer timing out (the same connection was used as for the ASCII transfer):

Code:

May 10 15:20:00 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching LOG_CMD command 'RETR /tmp/olly.txt' to mod_log
May 10 15:20:00 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching LOG_CMD command 'RETR /tmp/olly.txt' to mod_xfer
May 10 15:20:00 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): Transfer completed: 37518690 bytes in 67.02 seconds
May 10 15:20:21 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'TYPE I' to mod_tls
May 10 15:20:21 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'TYPE I' to mod_core
May 10 15:20:21 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'TYPE I' to mod_core
May 10 15:20:21 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching CMD command 'TYPE I' to mod_xfer
May 10 15:20:21 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching LOG_CMD command 'TYPE I' to mod_log
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'PORT 10,17,11,32,10,145' to mod_tls
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'PORT 10,17,11,32,10,145' to mod_core
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'PORT 10,17,11,32,10,145' to mod_core
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching CMD command 'PORT 10,17,11,32,10,145' to mod_core
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system stat()
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system stat()
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching LOG_CMD command 'PORT 10,17,11,32,10,145' to mod_log
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'RETR /tmp/olly.txt' to mod_tls
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'RETR /tmp/olly.txt' to mod_core
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'RETR /tmp/olly.txt' to mod_core
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching PRE_CMD command 'RETR /tmp/olly.txt' to mod_xfer
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system stat()
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system lstat()
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching CMD command 'RETR /tmp/olly.txt' to mod_xfer
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system open()
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system stat()
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): ROOT PRIVS at inet.c:323
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): RELINQUISH PRIVS at inet.c:381
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): active data connection opened - local  : 10.106.13.8:20
May 10 15:20:22 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): active data connection opened - remote : 10.17.11.32:2705
May 10 15:20:32 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): Data transfer stall timeout: 10 seconds
May 10 15:20:32 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "endpwent" to module mod_auth_file
May 10 15:20:32 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "endpwent" to module mod_auth_unix
May 10 15:20:32 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "endgrent" to module mod_auth_file
May 10 15:20:32 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): dispatching auth request "endgrent" to module mod_auth_unix
May 10 15:20:32 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FS: using system close()
May 10 15:20:32 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): Transfer aborted after 0 bytes in 10.00 seconds
May 10 15:20:32 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): ROOT PRIVS at mod_auth_pam.c:148
May 10 15:20:32 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): RELINQUISH PRIVS at mod_auth_pam.c:179
May 10 15:20:32 europa_tst proftpd[64356] europa_tst.exel.com (10.17.11.32[10.17.11.32]): FTP session closed.

[castaglia]

What happens if you get your FTP client to use passive data transfers (i.e. the PASV command) rather than active data transfers (i.e. the PORT command)?  If passive transfers work, then I'd suspect some sort of firewall/NAT interference on the FTP client machine...

[OllyC]

the same problem occurs for passive as well as active FTP.  The problem also occurs when the FTP client session is started on the same box as the FTP server.

Note that if the binary transfer does not timeout, I get my file successfully - for binary transfers data is flowing between the client and the server successfully, its just getting timed out early.

So even though there is no "FS: using system read()" for binary transfers I'm still getting the data.

[OllyC]

I've found the cause of the problem - if I turn UseSendfile off then TimeoutStalled works fine.

Olly.