Hello Niklas,
I was trying with SSL connections on the 579071 Revision of Apache FTP
Server code.
Looks like the SSL authentication handshake goes fine, however, the actual
file transfer ( i tried a STOR command) does not go fine. I am providing the
debug trace log in attached file ApacheTraceLog-8Oct.txt.
The logs show the last statement as Opening Data Connection, and later on
nothing happens.
Am also attaching the ftpKeystore.jks file and ftpd.properties files that am
using. The pswd for jks is password.
Can you please suggest any fix for this ASAP.
Thanks and Regards,
Atul Gohad.
[DEBUG] [/127.0.0.1:1097] encrypted buf: DirectBuffer[pos=0 lim=45 cap=64: 17
03 01 00 28 3B 80 2A 91 81 03 3B 0A C2 56 9E DF 01 AF DA AD DA 33 2A BA B3 27
37 57 60 21 2E 30 F7 53 20 80 12 8F 64 92 9C 3B 94 33]
[DEBUG] [/127.0.0.1:1097] Filtered Write: [EMAIL PROTECTED]
[DEBUG] [/127.0.0.1:1097] encrypt: HeapBuffer[pos=0 lim=0 cap=0: empty]
[DEBUG] [/127.0.0.1:1097] encrypted buf: DirectBuffer[pos=0 lim=0 cap=1: empty]
[DEBUG] Exiting since queue is empty for /127.0.0.1:1097
[INFO] [/127.0.0.1:1097] SENT: 200 Command TYPE okay.
[DEBUG] Launching thread for /127.0.0.1:1097
[DEBUG] [/127.0.0.1:1097] Data Read: [EMAIL PROTECTED] (DirectBuffer[pos=0
lim=45 cap=512: 17 03 01 00 28 83 63 DA C5 96 44 46 1A 8D D2 DA 3C 90 E3 08 3D
64 0E 03 55 5D 11 3C C4 A9 F9 B1 6B 56 1D 23 A2 DD 87 C3 33 BA 67 6F 8D])
[DEBUG] [/127.0.0.1:1097] unwrap()
[DEBUG] [/127.0.0.1:1097] inNetBuffer: java.nio.DirectByteBuffer[pos=0
lim=45 cap=16665]
[DEBUG] [/127.0.0.1:1097] appBuffer: java.nio.DirectByteBuffer[pos=0
lim=33330 cap=33330]
[DEBUG] [/127.0.0.1:1097] Unwrap res:Status = OK HandshakeStatus =
NOT_HANDSHAKING
bytesConsumed = 45 bytesProduced = 24
[DEBUG] [/127.0.0.1:1097] inNetBuffer: java.nio.DirectByteBuffer[pos=45
lim=45 cap=16665]
[DEBUG] [/127.0.0.1:1097] appBuffer: java.nio.DirectByteBuffer[pos=24
lim=33330 cap=33330]
[DEBUG] [/127.0.0.1:1097] Unwrap res:Status = BUFFER_UNDERFLOW HandshakeStatus
= NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
[DEBUG] [/127.0.0.1:1097] appBuffer: java.nio.DirectByteBuffer[pos=0 lim=24
cap=33330]
[DEBUG] [/127.0.0.1:1097] app data read: DirectBuffer[pos=0 lim=24 cap=32: 53
54 4F 52 20 7A 39 61 64 32 66 30 39 65 5F 33 39 31 2E 65 64 69 0D 0A] (53 54 4F
52 20 7A 39 61 64 32 66 30 39 65 5F 33 39 31 2E 65 64 69 0D 0A)
[INFO] [/127.0.0.1:1097] RECEIVED: STOR z9ad2f09e_391.edi
[INFO] [/127.0.0.1:1097] WRITE: 150 File status okay; about to open data
connection.
[DEBUG] [/127.0.0.1:1097] Filtered Write: [EMAIL PROTECTED]
[DEBUG] [/127.0.0.1:1097] encrypt: DirectBuffer[pos=0 lim=54 cap=64: 31 35 30
20 46 69 6C 65 20 73 74 61 74 75 73 20 6F 6B 61 79 3B 20 61 62 6F 75 74 20 74
6F 20 6F 70 65 6E 20 64 61 74 61 20 63 6F 6E 6E 65 63 74 69 6F 6E 2E 0D 0A]
[DEBUG] [/127.0.0.1:1097] Wrap res:Status = OK HandshakeStatus =
NOT_HANDSHAKING
bytesConsumed = 54 bytesProduced = 75
[DEBUG] [/127.0.0.1:1097] encrypted buf: DirectBuffer[pos=0 lim=75 cap=128: 17
03 01 00 46 57 41 1E FE B8 54 19 6E 39 D7 33 0C DE F5 BD 37 CB 35 21 06 8B 02
6B 18 DE 64 80 59 37 B5 B3 73 00 D0 BC 0B E9 80 29 C7 13 76 E3 83 AC 6E 78 5A
59 CF 49 71 3A AA DF FE 69 76 2B 55 37 CF 2A 3B E5 3C E6 CA 34 B9]
[DEBUG] [/127.0.0.1:1097] Filtered Write: [EMAIL PROTECTED]
[DEBUG] [/127.0.0.1:1097] encrypt: HeapBuffer[pos=0 lim=0 cap=0: empty]
[DEBUG] [/127.0.0.1:1097] encrypted buf: DirectBuffer[pos=0 lim=0 cap=1: empty]
[INFO] [/127.0.0.1:1097] SENT: 150 File status okay; about to open data
connection.
[INFO] File upload : narayan - /z9ad2f09e_391.edi
[INFO] [/127.0.0.1:1097] WRITE: 226 Transfer complete.
[DEBUG] [/127.0.0.1:1097] Filtered Write: [EMAIL PROTECTED]
[DEBUG] [/127.0.0.1:1097] encrypt: DirectBuffer[pos=0 lim=24 cap=32: 32 32 36
20 54 72 61 6E 73 66 65 72 20 63 6F 6D 70 6C 65 74 65 2E 0D 0A]
[DEBUG] [/127.0.0.1:1097] Wrap res:Status = OK HandshakeStatus =
NOT_HANDSHAKING
bytesConsumed = 24 bytesProduced = 45
[DEBUG] [/127.0.0.1:1097] encrypted buf: DirectBuffer[pos=0 lim=45 cap=64: 17
03 01 00 28 18 36 3D 2F 6C 16 65 F9 1F 5D CE 32 10 FD 90 61 27 D8 CA CD 34 76
82 AB 0C 96 6B 11 62 AE CE 3C E0 94 35 AE 93 E8 D5 48]
[DEBUG] [/127.0.0.1:1097] Filtered Write: [EMAIL PROTECTED]
[DEBUG] [/127.0.0.1:1097] encrypt: HeapBuffer[pos=0 lim=0 cap=0: empty]
[DEBUG] [/127.0.0.1:1097] encrypted buf: DirectBuffer[pos=0 lim=0 cap=1: empty]
[DEBUG] Exiting since queue is empty for /127.0.0.1:1097
[INFO] [/127.0.0.1:1097] SENT: 226 Transfer complete.
[DEBUG] Launching thread for /127.0.0.1:1097
[DEBUG] Exiting since queue is empty for /127.0.0.1:1097
[INFO] [/127.0.0.1:1097] EXCEPTION:
java.io.IOException: An existing connection was forcibly closed by the remote
host.
at sun.nio.ch.SocketDispatcher.read0(Native Method)
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:43)
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:267)
at sun.nio.ch.IOUtil.read(IOUtil.java:234)
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:234)
at
org.apache.mina.transport.socket.nio.SocketIoProcessor.read(SocketIoProcessor.java:267)
at
org.apache.mina.transport.socket.nio.SocketIoProcessor.process(SocketIoProcessor.java:241)
at
org.apache.mina.transport.socket.nio.SocketIoProcessor.access$500(SocketIoProcessor.java:44)
at
org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run(SocketIoProcessor.java:559)
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:43)
at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:665)
at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:690)
at java.lang.Thread.run(Thread.java:799)
[DEBUG] Launching thread for /127.0.0.1:1097
[DEBUG] [/127.0.0.1:1097] Closed: [EMAIL PROTECTED]
[DEBUG] [/127.0.0.1:1097] Unexpected exception from SSLEngine.closeInbound().
javax.net.ssl.SSLException: Inbound closed before receiving peer's
close_notify: possible truncation attack?
at com.ibm.jsse2.n.a(n.java)
at com.ibm.jsse2.gc.a(gc.java:291)
at com.ibm.jsse2.gc.a(gc.java:169)
at com.ibm.jsse2.gc.closeInbound(gc.java:132)
at
org.apache.mina.filter.support.SSLHandler.destroy(SSLHandler.java:165)
at org.apache.mina.filter.SSLFilter.sessionClosed(SSLFilter.java:359)
at
org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionClosed(AbstractIoFilterChain.java:321)
at
org.apache.mina.common.support.AbstractIoFilterChain.access$900(AbstractIoFilterChain.java:54)
at
org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.sessionClosed(AbstractIoFilterChain.java:781)
at
org.apache.mina.common.support.AbstractIoFilterChain$HeadFilter.sessionClosed(AbstractIoFilterChain.java:599)
at
org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionClosed(AbstractIoFilterChain.java:321)
at
org.apache.mina.common.support.AbstractIoFilterChain.fireSessionClosed(AbstractIoFilterChain.java:313)
at
org.apache.mina.common.support.IoServiceListenerSupport.fireSessionDestroyed(IoServiceListenerSupport.java:271)
at
org.apache.mina.transport.socket.nio.SocketIoProcessor.doRemove(SocketIoProcessor.java:225)
at
org.apache.mina.transport.socket.nio.SocketIoProcessor.access$700(SocketIoProcessor.java:44)
at
org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run(SocketIoProcessor.java:563)
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:43)
at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:665)
at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:690)
at java.lang.Thread.run(Thread.java:799)
