FTPES with z/OS server can't read transfer socket

[spitvalve]

( 1 ) SUMMARY
Using server type FTPES (FTP over explicit TLS/SSL), the server is z/OS, the client platform is Windows XP.

This problem occurs in v3.1.0 but IS NOT a problem in v3.0.11.1. After successfully connecting, you can't see any directory and you get the following error messages:

Error: Could not read from transfer socket: ECONNABORTED - Connection aborted
Response: 250 List completed successfully.
Error: Failed to retrieve directory listing

( 2 ) v3.1.0 SESSION LOG
Here is the whole problem session (name, server, etc. made generic) under 3.1.0:

Status: Connecting to xxx.xx.xx.xxx:21...
Status: Connection established, waiting for welcome message...
Response: 220-FTPD1 IBM FTP CS V1R7 at aaaa.state.xx.us, 21:31:59 on 2008-07-23.
Response: 220-*
Response: 220-* Unauthorized Use of computing resources is punishable by *
Response: 220-* xxxxxx criminal law xxxxxxxxx yyyyyyyyyyyyy zzzzzzzzzzzzzzzzzz *
Response: 220-*
Response: 220 Connection will close if idle for more than 5 minutes.
Command: AUTH TLS
Response: 234 Security environment established - ready for negotiation
Status: Initializing TLS...
Status: Verifying certificate...
Command: USER xxxxxxx
Status: TLS/SSL connection established.
Response: 331 Send password please.
Command: PASS
Response: 230 xxxxxxx is logged on. Working directory is "XXXXXXX.".
Command: SYST
Response: 215 MVS is the operating system of this server. FTP Server is running on z/OS.
Command: FEAT
Response: 211- Extensions supported
Response: AUTH TLS
Response: PBSZ
Response: PROT
Response: 211 End
Command: PBSZ 0
Response: 200 Protection buffer size accepted
Command: PROT P
Response: 200 Data connection protection set to private
Status: Connected
Status: Retrieving directory listing...
Command: PWD
Response: 257 "'XXXXXXX.'" is working directory.
Command: TYPE I
Response: 200 Representation type is Image
Command: PASV
Response: 227 Entering Passive Mode (111,22,33,444,15,109)
Command: LIST
Response: 125 List started OK
Error: Could not read from transfer socket: ECONNABORTED - Connection aborted
Response: 250 List completed successfully.
Error: Failed to retrieve directory listing

( 2 ) v3.0.11.1 SESSION LOG
Here is the whole successful session (name, server, etc. made generic) under 3.0.11.1:
Status: Connecting to xxx.xx.xx.xxx:21...
Status: Connection established, waiting for welcome message...
Response: 220-FTPD1 IBM FTP CS V1R7 at xxxx.state.xx.us, 21:37:16 on 2008-07-23.
Response: 220-*
Response: 220-* Unauthorized Use of computing resources is punishable by *
Response: 220-* criminal law xxxxxxxxxxxxxxxx yyyyyyyyyyyy zzzzzzzzzzzzzzzzzzz *
Response: 220-*
Response: 220 Connection will close if idle for more than 5 minutes.
Command: AUTH TLS
Response: 234 Security environment established - ready for negotiation
Status: Initializing TLS...
Command: USER xxxxxxx
Status: Verifying certificate...
Status: TLS/SSL connection established.
Response: 331 Send password please.
Command: PASS
Response: 230 xxxxxxx is logged on. Working directory is "XXXXXXX.".
Command: SYST
Response: 215 MVS is the operating system of this server. FTP Server is running on z/OS.
Command: FEAT
Response: 211- Extensions supported
Response: AUTH TLS
Response: PBSZ
Response: PROT
Response: 211 End
Command: PBSZ 0
Response: 200 Protection buffer size accepted
Command: PROT P
Response: 200 Data connection protection set to private
Status: Connected
Status: Retrieving directory listing...
Command: PWD
Response: 257 "'XXXXXXX.'" is working directory.
Command: TYPE I
Response: 200 Representation type is Image
Command: PASV
Response: 227 Entering Passive Mode (111,22,33,444,15,151)
Command: LIST
Response: 125 List started OK
Response: 250 List completed successfully.
Status: Directory listing successful

[Tim Kosse]

So far I have been unable to reproduce this problem, and a code review doesn't spot anything unusual.

Would it be possible to get a temporary guest account on your server?

[spitvalve]

Thanks for such a quick response! Unfortunately, you would not be able to get a guest account. I'm a "just a developer" working in a large state mainframe environment where there's no such thing as a guest account. It only took 30 sec. for me to back down to 3.0.11.1 so I'll just stay on that version. Maybe it's something about the state's z/OS server that reacts differently to the two versions of Filezilla for some reason.

BTW, I showed this problem to a colleague, so he upgraded to 3.1.0 and had the identical problem. Then he reverted to 3.0.11.1 it worked fine just like it did for me.

[Tim Kosse]

Does your server perform an orderly SSL shutdown? Or does it just close the socket without performing an SSL shutdown?

[spitvalve]

I can't get info from the server. Even the z/OS log does not show evidence of my session (I wonder if ftp is run on a virtual machine such as IFL). But I looked at another bug report and saw that I could give you more help by going through with a trace level of 4. So here is a sample session that culminates in the error.

Status: Resolving address of aaaa.state.bb.us
Status: Connecting to 111.11.11.111:21...
Status: Connection established, waiting for welcome message...
Trace: CFtpControlSocket::OnReceive()
Response: 220-FTPD1 IBM FTP CS V1R7 at aaaa.state.bb.us, 20:46:41 on 2008-07-24.
Trace: CFtpControlSocket::OnReceive()
Response: 220-*
Response: 220-* Unauthorized Use of computing resources is punishable by *
Response: 220-*
Response: 220 Connection will close if idle for more than 5 minutes.
Trace: CFtpControlSocket::SendNextCommand()
Command: AUTH TLS
Trace: CFtpControlSocket::OnReceive()
Response: 234 Security environment established - ready for negotiation
Status: Initializing TLS...
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::OnSend()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: Handshake successful
Trace: Cipher: ARCFOUR-128, MAC: MD5
Status: Verifying certificate...
Trace: CFtpControlSocket::SendNextCommand()
Command: USER XXXXXXX
Status: TLS/SSL connection established.
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 331 Send password please.
Trace: CFtpControlSocket::SendNextCommand()
Command: PASS
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 230 XXXXXXX is logged on. Working directory is "XXXXXXX.".
Trace: CFtpControlSocket::SendNextCommand()
Command: SYST
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 215 MVS is the operating system of this server. FTP Server is running on z/OS.
Trace: CFtpControlSocket::SendNextCommand()
Command: FEAT
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 211- Extensions supported
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: AUTH TLS
Response: PBSZ
Response: PROT
Response: 211 End
Trace: CFtpControlSocket::SendNextCommand()
Command: PBSZ 0
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 200 Protection buffer size accepted
Trace: CFtpControlSocket::SendNextCommand()
Command: PROT P
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 200 Data connection protection set to private
Status: Connected
Trace: CFtpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Status: Retrieving directory listing...
Trace: CFtpControlSocket::SendNextCommand()
Trace: CFtpControlSocket::ChangeDirSend()
Command: CWD 'xxxxxxx.yyy.print'
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 250 The working directory "XXXXXXX.YYY.PRINT" is a partitioned data set
Trace: CFtpControlSocket::SendNextCommand()
Trace: CFtpControlSocket::ChangeDirSend()
Command: PWD
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 257 "'XXXXXXX.YYY.PRINT'" partitioned data set is working directory.
Trace: CFtpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CFtpControlSocket::ParseSubcommandResult(0)
Trace: CFtpControlSocket::ListSubcommandResult()
Trace: state = 1
Trace: CFtpControlSocket::SendNextCommand()
Trace: CFtpControlSocket::TransferSend()
Trace: state = 1
Command: TYPE I
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 200 Representation type is Image
Trace: CFtpControlSocket::TransferParseResponse()
Trace: code = 2
Trace: state = 1
Trace: CFtpControlSocket::SendNextCommand()
Trace: CFtpControlSocket::TransferSend()
Trace: state = 2
Command: PASV
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 227 Entering Passive Mode (111,22,33,444,8,214)
Trace: CFtpControlSocket::TransferParseResponse()
Trace: code = 2
Trace: state = 2
Trace: CFtpControlSocket::SendNextCommand()
Trace: CFtpControlSocket::TransferSend()
Trace: state = 4
Command: LIST
Trace: CTransferSocket::OnConnect
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::OnSend()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 125 List started OK
Trace: CFtpControlSocket::TransferParseResponse()
Trace: code = 1
Trace: state = 4
Trace: CFtpControlSocket::SendNextCommand()
Trace: CFtpControlSocket::TransferSend()
Trace: state = 5
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: Handshake successful
Trace: Cipher: ARCFOUR-128, MAC: MD5
Trace: CTransferSocket::OnConnect
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::OnRead()
Trace: CTransferSocket::OnReceive(), m_transferMode=0
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::OnSocketEvent(): close event received
Trace: CTransferSocket::OnReceive(), m_transferMode=0
Trace: GnuTLS error -9: A TLS packet with unexpected length was received.
Error: Could not read from transfer socket: ECONNABORTED - Connection aborted
Trace: CTransferSocket::TransferEnd(3)
Trace: Skipping socket event 5, no socket or id mismatch.
Trace: Skipping socket event 5, no socket or id mismatch.
Trace: CFtpControlSocket::TransferEnd()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 250 List completed successfully.
Trace: CFtpControlSocket::TransferParseResponse()
Trace: code = 2
Trace: state = 7
Trace: CFtpControlSocket::ResetOperation(2)
Trace: CControlSocket::ResetOperation(2)
Trace: CFtpControlSocket::ParseSubcommandResult(2)
Trace: CFtpControlSocket::ListSubcommandResult()
Trace: state = 2
Trace: CFtpControlSocket::ResetOperation(2)
Trace: CControlSocket::ResetOperation(2)
Error: Failed to retrieve directory listing

[spitvalve]

...and, here is a successful session (under FZ 3.0.11.1) using debug level 4:

Status: Resolving IP-Address for aaaa.state.bb.us
Trace: ControlSocket.cpp(1056): CRealControlSocket::ContinueConnect(0p13b1b78) m_pEngine=0p13104a0 caller=0p13be170
Status: Connecting to 111.22.33.444:21...
Status: Connection established, waiting for welcome message...
Trace: CFtpControlSocket::OnReceive()
Response: 220-FTPD1 IBM FTP CS V1R7 at aaaa.state.bb.us, 20:58:33 on 2008-07-24.
Trace: CFtpControlSocket::OnReceive()
Response: 220-*
Response: 220-* Unauthorized Use of computing resources is punishable by *
Response: 220-*
Response: 220 Connection will close if idle for more than 5 minutes.
Trace: CFtpControlSocket::SendNextCommand()
Command: AUTH TLS
Trace: CFtpControlSocket::OnReceive()
Response: 234 Security environment established - ready for negotiation
Status: Initializing TLS...
Trace: CTlsSocket::Handshake()
Trace: CFtpControlSocket::SendNextCommand()
Command: USER XXXXXXX
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: Handshake successful
Trace: Cipher: ARCFOUR-128, MAC: MD5
Status: Verifying certificate...
Status: TLS/SSL connection established.
Trace: CFtpControlSocket::OnReceive()
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 331 Send password please.
Trace: CFtpControlSocket::SendNextCommand()
Command: PASS
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 230 XXXXXXX is logged on. Working directory is "XXXXXXX.".
Trace: CFtpControlSocket::SendNextCommand()
Command: SYST
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 215 MVS is the operating system of this server. FTP Server is running on z/OS.
Trace: CFtpControlSocket::SendNextCommand()
Command: FEAT
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 211- Extensions supported
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: AUTH TLS
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: PBSZ
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: PROT
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 211 End
Trace: CFtpControlSocket::SendNextCommand()
Command: PBSZ 0
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 200 Protection buffer size accepted
Trace: CFtpControlSocket::SendNextCommand()
Command: PROT P
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 200 Data connection protection set to private
Status: Connected
Trace: CFtpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Status: Retrieving directory listing...
Trace: CFtpControlSocket::SendNextCommand()
Trace: CFtpControlSocket::ChangeDirSend()
Command: CWD 'xxxxxxx.yyy.print'
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 250 The working directory "XXXXXXX.YYY.PRINT" is a partitioned data set
Trace: CFtpControlSocket::SendNextCommand()
Trace: CFtpControlSocket::ChangeDirSend()
Command: PWD
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 257 "'XXXXXXX.YYY.PRINT'" partitioned data set is working directory.
Trace: CFtpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CFtpControlSocket::ParseSubcommandResult(0)
Trace: CFtpControlSocket::ListSubcommandResult()
Trace: state = 1
Trace: CFtpControlSocket::SendNextCommand()
Trace: CFtpControlSocket::TransferSend()
Trace: state = 1
Command: TYPE I
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 200 Representation type is Image
Trace: CFtpControlSocket::TransferParseResponse()
Trace: code = 2
Trace: state = 1
Trace: CFtpControlSocket::SendNextCommand()
Trace: CFtpControlSocket::TransferSend()
Trace: state = 2
Command: PASV
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 227 Entering Passive Mode (111,22,33,444,9,133)
Trace: CFtpControlSocket::TransferParseResponse()
Trace: code = 2
Trace: state = 2
Trace: CFtpControlSocket::SendNextCommand()
Trace: CFtpControlSocket::TransferSend()
Trace: state = 4
Command: LIST
Trace: CFtpControlSocket::OnReceive()
Trace: CTransferSocket::OnConnect
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 125 List started OK
Trace: CFtpControlSocket::TransferParseResponse()
Trace: code = 1
Trace: state = 4
Trace: CFtpControlSocket::SendNextCommand()
Trace: CFtpControlSocket::TransferSend()
Trace: state = 5
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::Handshake()
Trace: Handshake successful
Trace: Cipher: ARCFOUR-128, MAC: MD5
Trace: CTransferSocket::OnConnect
Trace: CTransferSocket::OnReceive(), m_transferMode=0
Trace: CTransferSocket::OnConnect
Trace: CTlsSocket::OnRead()
Trace: CTransferSocket::OnReceive(), m_transferMode=0
Trace: CTlsSocket::OnRead()
Trace: CTransferSocket::OnReceive(), m_transferMode=0
Trace: CTransferSocket::OnReceive(), m_transferMode=0
Trace: CTransferSocket::OnReceive(), m_transferMode=0
Trace: CTlsSocket::OnRead()
Trace: CTlsSocket::OnSocketEvent(): pending data, postponing wxSOCKET_LOST
Trace: CTlsSocket::OnRead()
Trace: CTransferSocket::OnReceive(), m_transferMode=0
Trace: CTlsSocket::OnSocketEvent(): pending data, postponing wxSOCKET_LOST
Trace: CTlsSocket::OnRead()
Trace: CTransferSocket::OnReceive(), m_transferMode=0
Trace: CTlsSocket::OnSocketEvent(): pending data, postponing wxSOCKET_LOST
Trace: CTlsSocket::OnRead()
Trace: CTransferSocket::OnReceive(), m_transferMode=0
Trace: CTransferSocket::OnReceive(), m_transferMode=0
Trace: CTlsSocket::OnSocketEvent(): pending data, postponing wxSOCKET_LOST
Trace: CTlsSocket::OnRead()
Trace: CTransferSocket::OnReceive(), m_transferMode=0
Trace: CTlsSocket::OnSocketEvent(): wxSOCKET_LOST received
Trace: CTransferSocket::OnReceive(), m_transferMode=0
Trace: CTransferSocket::OnClose
Trace: CTransferSocket::TransferEnd(1)
Trace: CFtpControlSocket::TransferEnd()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Trace: CTlsSocket::OnRead()
Trace: CFtpControlSocket::OnReceive()
Response: 250 List completed successfully.
Trace: CFtpControlSocket::TransferParseResponse()
Trace: code = 2
Trace: state = 7
Trace: CFtpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CFtpControlSocket::ParseSubcommandResult(0)
Trace: CFtpControlSocket::ListSubcommandResult()
Trace: state = 2
Trace: CFtpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Status: Directory listing successful
Trace: CFtpControlSocket::OnReceive()

[Tim Kosse]

This is a bug in the server. It does not perform an orderly TLS/SSL shutdown like it is supposed to do.

[spitvalve]

I gather that I'm better served by Filezilla 3.0.11.1 which is forgiving of the server's disorderly shutdown, and keeps doing business with the server even after the server misbehaves.

[mvsdino]

z/OS 1.9 and FileZilla Client 3.2.6.1:

Applied Fix UK43295 (APAR PK77240) to z/OS 1.9 FTPD Server

Coded Parm in FTP.DATA of my z/OS-Server [in our case SYS1.TCPPARMS(FTPDATA)]:
TLSRFCLEVEL RFC4217

Message "Could not read from transfer socket: ECONNABORTED - Connection aborted"
while trying to list z/OS-Directory is gone.

In another system without PK77240, TLSRFCLEVEL RFC4217 does not correct the problem.