Hi,
I'm finding that uploads from FireFTP are failing frequently with
"java.io.EOFException: Unexpected end of ZLIB input stream".
FireFTP then stalls for about 30 seconds before disconnecting,
reconnecting, and retrying the upload (this time via 'APPE' rather
than 'STOR'), which then works.
I wondered if it could be related to http://issues.apache.org/jira/browse/FTPSERVER-316
(but this issue is supposed to be fixed in 1.0.2)?
Transmit and Interarchy clients for OS X seem to work fine, but they
do not appear to send 'MODE Z'.
Any suggestions as to how I can solve the problem, or do I need to
raise an issue?
Thanks
--
Roger
Server:
- OS X 10.5.7
- Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_19-
b02-304)
- Clean extract of Apache FtpServer 1.0.2 Release, started via 'bin/
ftpd.sh res/conf/ftpd-typical.xml'
Client:
- FireFTP 1.0.5 on Firefox 3.5.1 on OS X 10.4.11
- Connecting over LAN
Server Log:
[ INFO] 2009-07-28 18:03:52,251 [] [] Refreshing
org
.springframework
.context.support.filesystemxmlapplicationcont...@724a9d: display name
[org
.springframework
.context.support.filesystemxmlapplicationcont...@724a9d]; startup date
[Tue Jul 28 18:03:52 BST 2009]; root of context hierarchy
[ INFO] 2009-07-28 18:03:52,324 [] [] Loading XML bean definitions
from file [/Users/roger/Projects/apache-ftpserver-1.0.2/res/conf/ftpd-
typical.xml]
[ INFO] 2009-07-28 18:03:52,699 [] [] Bean factory for application
context
[org
.springframework
.context.support.filesystemxmlapplicationcont...@724a9d]:
org
.springframework.beans.factory.support.defaultlistablebeanfact...@b0d33c
[ INFO] 2009-07-28 18:03:52,719 [] [] Pre-instantiating singletons in
org
.springframework
.beans.factory.support.defaultlistablebeanfact...@b0d33c: defining
beans
[org
.apache
.ftpserver
.listener
.ListenerFactory
#0
,org
.apache
.ftpserver
.usermanager
.PropertiesUserManagerFactory
#0,org.apache.ftpserver.FtpServerFactory#0,myServer]; root of factory
hierarchy
[ INFO] 2009-07-28 18:03:52,996 [] [] FTP server started
[ INFO] 2009-07-28 18:04:03,449 [] [192.168.2.120] CREATED
[ INFO] 2009-07-28 18:04:03,458 [] [192.168.2.120] OPENED
[ INFO] 2009-07-28 18:04:03,479 [] [192.168.2.120] SENT: 220 Service
ready for new user.
[ INFO] 2009-07-28 18:04:03,484 [] [192.168.2.120] RECEIVED: USER admin
[ INFO] 2009-07-28 18:04:03,491 [admin] [192.168.2.120] SENT: 331 User
name okay, need password for admin.
[ INFO] 2009-07-28 18:04:03,581 [admin] [192.168.2.120] RECEIVED: PASS
*****
[ INFO] 2009-07-28 18:04:03,602 [admin] [192.168.2.120] Login success
- admin
[ INFO] 2009-07-28 18:04:03,603 [admin] [192.168.2.120] SENT: 230 User
logged in, proceed.
[ INFO] 2009-07-28 18:04:03,603 [admin] [192.168.2.120] RECEIVED: FEAT
[ INFO] 2009-07-28 18:04:03,605 [admin] [192.168.2.120] SENT: 211-
Extensions supported
SIZE
MDTM
REST STREAM
LANG en;zh-tw;ja;is
MLST Size;Modify;Type;Perm
AUTH SSL
AUTH TLS
MODE Z
UTF8
TVFS
MD5
MMD5
MFMT
211 End
[ INFO] 2009-07-28 18:04:03,606 [admin] [192.168.2.120] RECEIVED: PWD
[ INFO] 2009-07-28 18:04:03,607 [admin] [192.168.2.120] SENT: 257 "/"
is current directory.
[ INFO] 2009-07-28 18:04:08,593 [admin] [192.168.2.120] RECEIVED: TYPE I
[ INFO] 2009-07-28 18:04:08,596 [admin] [192.168.2.120] SENT: 200
Command TYPE okay.
[ INFO] 2009-07-28 18:04:08,674 [admin] [192.168.2.120] RECEIVED: MODE Z
[ INFO] 2009-07-28 18:04:08,680 [admin] [192.168.2.120] SENT: 200
Command MODE okay.
[ INFO] 2009-07-28 18:04:08,680 [admin] [192.168.2.120] RECEIVED: PASV
[ INFO] 2009-07-28 18:04:08,684 [admin] [192.168.2.120] SENT: 227
Entering Passive Mode (192,168,2,111,242,122)
[ INFO] 2009-07-28 18:04:08,687 [admin] [192.168.2.120] RECEIVED: STOR
some_file.flv
[ INFO] 2009-07-28 18:04:10,593 [admin] [192.168.2.120] File uploaded /
some_file.flv
[ INFO] 2009-07-28 18:04:10,594 [admin] [192.168.2.120] SENT: 150 File
status okay; about to open data connection.
[ INFO] 2009-07-28 18:04:10,594 [admin] [192.168.2.120] SENT: 226
Transfer complete.
.
.
.
[ INFO] 2009-07-28 18:05:14,886 [admin] [192.168.2.120] RECEIVED: TYPE I
[ INFO] 2009-07-28 18:05:14,887 [admin] [192.168.2.120] SENT: 200
Command TYPE okay.
[ INFO] 2009-07-28 18:05:14,888 [admin] [192.168.2.120] RECEIVED: PASV
[ INFO] 2009-07-28 18:05:14,889 [admin] [192.168.2.120] SENT: 227
Entering Passive Mode (192,168,2,111,242,132)
[ INFO] 2009-07-28 18:05:14,892 [admin] [192.168.2.120] RECEIVED: STOR
WM Components 2.2.2.3.dmg
[ WARN] 2009-07-28 18:06:14,893 [admin] [192.168.2.120] Exception
during data transfer, closing data connection socket
java.io.EOFException: Unexpected end of ZLIB input stream
at java.util.zip.InflaterInputStream.fill(InflaterInputStream.java:216)
at java.util.zip.InflaterInputStream.read(InflaterInputStream.java:134)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
at java.io.FilterInputStream.read(FilterInputStream.java:90)
at
org
.apache.ftpserver.impl.IODataConnection.transfer(IODataConnection.java:
243)
at
org
.apache
.ftpserver
.impl.IODataConnection.transferFromClient(IODataConnection.java:136)
at org.apache.ftpserver.command.impl.STOR.execute(STOR.java:146)
at
org
.apache
.ftpserver
.impl.DefaultFtpHandler.messageReceived(DefaultFtpHandler.java:210)
at
org
.apache
.ftpserver
.listener.nio.FtpHandlerAdapter.messageReceived(FtpHandlerAdapter.java:
61)
at org.apache.mina.core.filterchain.DefaultIoFilterChain
$TailFilter.messageReceived(DefaultIoFilterChain.java:721)
at
org
.apache
.mina
.core
.filterchain
.DefaultIoFilterChain
.callNextMessageReceived(DefaultIoFilterChain.java:433)
at org.apache.mina.core.filterchain.DefaultIoFilterChain.access
$1200(DefaultIoFilterChain.java:47)
at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl
$1.messageReceived(DefaultIoFilterChain.java:801)
at
org
.apache
.ftpserver
.listener.nio.FtpLoggingFilter.messageReceived(FtpLoggingFilter.java:85)
at
org
.apache
.mina
.core
.filterchain
.DefaultIoFilterChain
.callNextMessageReceived(DefaultIoFilterChain.java:433)
at org.apache.mina.core.filterchain.DefaultIoFilterChain.access
$1200(DefaultIoFilterChain.java:47)
at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl
$1.messageReceived(DefaultIoFilterChain.java:801)
at
org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:
71)
at
org
.apache
.mina.filter.logging.MdcInjectionFilter.filter(MdcInjectionFilter.java:
136)
at
org
.apache
.mina
.filter.util.CommonEventFilter.messageReceived(CommonEventFilter.java:
70)
at
org
.apache
.mina
.core
.filterchain
.DefaultIoFilterChain
.callNextMessageReceived(DefaultIoFilterChain.java:433)
at org.apache.mina.core.filterchain.DefaultIoFilterChain.access
$1200(DefaultIoFilterChain.java:47)
at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl
$1.messageReceived(DefaultIoFilterChain.java:801)
at org.apache.mina.filter.codec.ProtocolCodecFilter
$ProtocolDecoderOutputImpl.flush(ProtocolCodecFilter.java:375)
at
org
.apache
.mina
.filter
.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:229)
at
org
.apache
.mina
.core
.filterchain
.DefaultIoFilterChain
.callNextMessageReceived(DefaultIoFilterChain.java:433)
at org.apache.mina.core.filterchain.DefaultIoFilterChain.access
$1200(DefaultIoFilterChain.java:47)
at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl
$1.messageReceived(DefaultIoFilterChain.java:801)
at
org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:
71)
at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
at org.apache.mina.filter.executor.OrderedThreadPoolExecutor
$Worker.runTask(OrderedThreadPoolExecutor.java:801)
at org.apache.mina.filter.executor.OrderedThreadPoolExecutor
$Worker.runTasks(OrderedThreadPoolExecutor.java:793)
at org.apache.mina.filter.executor.OrderedThreadPoolExecutor
$Worker.run(OrderedThreadPoolExecutor.java:735)
at java.lang.Thread.run(Thread.java:613)
[ INFO] 2009-07-28 18:06:14,897 [admin] [192.168.2.120] SENT: 150 File
status okay; about to open data connection.
[ INFO] 2009-07-28 18:06:14,897 [admin] [192.168.2.120] RECEIVED: QUIT
[ INFO] 2009-07-28 18:06:14,898 [admin] [192.168.2.120] CLOSED
[ INFO] 2009-07-28 18:06:24,896 [] [192.168.2.120] CREATED
[ INFO] 2009-07-28 18:06:24,896 [admin] [192.168.2.120] OPENED
[ INFO] 2009-07-28 18:06:24,897 [admin] [192.168.2.120] SENT: 220
Service ready for new user.
[ INFO] 2009-07-28 18:06:24,901 [] [192.168.2.120] RECEIVED: USER admin
[ INFO] 2009-07-28 18:06:24,902 [admin] [192.168.2.120] SENT: 331 User
name okay, need password for admin.
[ INFO] 2009-07-28 18:06:24,935 [admin] [192.168.2.120] RECEIVED: PASS
*****
[ INFO] 2009-07-28 18:06:24,936 [admin] [192.168.2.120] Login success
- admin
[ INFO] 2009-07-28 18:06:24,944 [admin] [192.168.2.120] SENT: 230 User
logged in, proceed.
[ INFO] 2009-07-28 18:06:24,967 [admin] [192.168.2.120] RECEIVED: CWD /
[ INFO] 2009-07-28 18:06:24,968 [admin] [192.168.2.120] SENT: 250
Directory changed to /
[ INFO] 2009-07-28 18:06:25,067 [admin] [192.168.2.120] RECEIVED: TYPE I
[ INFO] 2009-07-28 18:06:25,068 [admin] [192.168.2.120] SENT: 200
Command TYPE okay.
[ INFO] 2009-07-28 18:06:25,072 [admin] [192.168.2.120] RECEIVED: SIZE
WM Components 2.2.2.3.dmg
[ INFO] 2009-07-28 18:06:25,073 [admin] [192.168.2.120] SENT: 213
10104832
[ INFO] 2009-07-28 18:06:25,087 [admin] [192.168.2.120] RECEIVED: MODE Z
[ INFO] 2009-07-28 18:06:25,088 [admin] [192.168.2.120] SENT: 200
Command MODE okay.
[ INFO] 2009-07-28 18:06:25,091 [admin] [192.168.2.120] RECEIVED: PASV
[ INFO] 2009-07-28 18:06:25,093 [admin] [192.168.2.120] SENT: 227
Entering Passive Mode (192,168,2,111,242,133)
[ INFO] 2009-07-28 18:06:25,095 [admin] [192.168.2.120] RECEIVED: APPE
WM Components 2.2.2.3.dmg
[ INFO] 2009-07-28 18:06:25,168 [admin] [192.168.2.120] File uploaded /
WM Components 2.2.2.3.dmg
[ INFO] 2009-07-28 18:06:25,168 [admin] [192.168.2.120] SENT: 150 File
status okay; about to open data connection.
[ INFO] 2009-07-28 18:06:25,169 [admin] [192.168.2.120] SENT: 226
Transfer complete.
[ INFO] 2009-07-28 18:06:25,171 [admin] [192.168.2.120] RECEIVED: TYPE A
[ INFO] 2009-07-28 18:06:25,171 [admin] [192.168.2.120] SENT: 200
Command TYPE okay.
[ INFO] 2009-07-28 18:06:25,173 [admin] [192.168.2.120] RECEIVED: PASV
[ INFO] 2009-07-28 18:06:25,174 [admin] [192.168.2.120] SENT: 227
Entering Passive Mode (192,168,2,111,242,134)
[ INFO] 2009-07-28 18:06:25,183 [admin] [192.168.2.120] RECEIVED: LIST
[ INFO] 2009-07-28 18:06:25,185 [admin] [192.168.2.120] SENT: 150 File
status okay; about to open data connection.
[ INFO] 2009-07-28 18:06:25,186 [admin] [192.168.2.120] SENT: 226
Closing data connection.
