GnuTLS error -9: A TLS packet with unexpected length was received

[Dan Olsen]

I am trying to FTP from a mainframe running z/OS 1.11 using TLS. Cannot seem to get a data connection. I support EPSV on the mainframe as well.

Log:
Status: Connecting to 66.180.4.6:21...
Status: Connection established, waiting for welcome message...
Trace: CFtpControlSocket::OnReceive()
Response: 220-FTPD1 IBM FTP CS V1R11 at LOOPBACK, 20:41:29 on 2010-09-09.
Trace: CFtpControlSocket::OnReceive()
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::ContinueHandshake()
Trace: CTlsSocket::ContinueHandshake()
Trace: CTlsSocket::ContinueHandshake()
Trace: CTlsSocket::ContinueHandshake()
Trace: CTlsSocket::ContinueHandshake()
Trace: Handshake successful
Trace: Cipher: ARCFOUR-128, MAC: MD5
Status: Verifying certificate...
Trace: CFtpControlSocket::SendNextCommand()
Command: USER dolsen
Status: TLS/SSL connection established.
Trace: CFtpControlSocket::OnReceive()
Response: 331 Send password please.
Trace: CFtpControlSocket::SendNextCommand()
Command: PASS
Trace: CFtpControlSocket::OnReceive()
Response: 230 DOLSEN is logged on. Working directory is "DOLSEN.".
Trace: CFtpControlSocket::SendNextCommand()
Command: SYST
Trace: CFtpControlSocket::OnReceive()
Response: 215 MVS is the operating system of this server. FTP Server is running on z/OS.
Trace: CFtpControlSocket::SendNextCommand()
Command: PBSZ 0
Trace: CFtpControlSocket::OnReceive()
Response: 200 Protection buffer size accepted
Trace: CFtpControlSocket::SendNextCommand()
Command: PROT P
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: PWD
Trace: CFtpControlSocket::OnReceive()
Response: 257 "'DOLSEN.'" is working directory.
Trace: CFtpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CFtpControlSocket::ParseSubcommandResult(0)
Trace: CFtpControlSocket::ListSubcommandResult()
Trace: CFtpControlSocket::SendNextCommand()
Trace: CFtpControlSocket::TransferSend()
Command: TYPE I
Trace: CFtpControlSocket::OnReceive()
Response: 200 Representation type is Image
Trace: CFtpControlSocket::TransferParseResponse()
Trace: CFtpControlSocket::SendNextCommand()
Trace: CFtpControlSocket::TransferSend()
Command: PASV
Trace: CFtpControlSocket::OnReceive()
Response: 227 Entering Passive Mode (10,200,32,254,234,121)
Trace: CFtpControlSocket::TransferParseResponse()
Status: Server sent passive reply with unroutable address. Using server address instead.
Trace: Reply: 10.200.32.254, peer: 66.180.4.6
Trace: CFtpControlSocket::SendNextCommand()
Trace: CFtpControlSocket::TransferSend()
Command: LIST
Trace: CTransferSocket::OnConnect
Trace: CTlsSocket::Handshake()
Trace: CTlsSocket::ContinueHandshake()
Trace: CTlsSocket::ContinueHandshake()
Trace: CFtpControlSocket::OnReceive()
Response: 125 List started OK
Trace: CFtpControlSocket::TransferParseResponse()
Trace: CFtpControlSocket::SendNextCommand()
Trace: CFtpControlSocket::TransferSend()
Trace: CTlsSocket::ContinueHandshake()
Trace: Handshake successful
Trace: Session resumed
Trace: Cipher: ARCFOUR-128, MAC: MD5
Trace: CTransferSocket::OnConnect
Trace: CTlsSocket::OnSocketEvent(): close event received
Error: GnuTLS error -9: A TLS packet with unexpected length was received.
Status: Server did not properly shut down TLS connection
Error: Could not read from transfer socket: ECONNABORTED - Connection aborted
Trace: CTransferSocket::TransferEnd(3)
Trace: CFtpControlSocket::TransferEnd()
Trace: CFtpControlSocket::OnReceive()
Response: 250 List completed successfully.
Trace: CFtpControlSocket::TransferParseResponse()
Trace: CFtpControlSocket::ResetOperation(2)
Trace: CControlSocket::ResetOperation(2)
Trace: CFtpControlSocket::ParseSubcommandResult(2)
Trace: CFtpControlSocket::ListSubcommandResult()
Trace: CFtpControlSocket::ResetOperation(2)
Trace: CControlSocket::ResetOperation(2)
Error: Failed to retrieve directory listing
Trace: CTlsSocket::OnSocketEvent(): close event received
Trace: CRealControlSocket::OnClose(0)
Error: Connection closed by server
Trace: CFtpControlSocket::ResetOperation(66)
Trace: CControlSocket::ResetOperation(66)

System type:
FileZilla Client

---

Version: 3.3.4.1

Build information:

Compiled for: i586-pc-mingw32msvc
Compiled on: x86_64-unknown-linux-gnu
Build date: 2010-08-16
Compiled with: i586-mingw32msvc-gcc (GCC) 4.2.1-sjlj (mingw32-2)
Compiler flags: -g -O2 -Wall -g -fexceptions

Linked against:

wxWidgets: 2.8.11
GnuTLS: 2.8.3

Operating system:

Name: Windows XP (build 2600, Service Pack 3)
Version: 5.1
Platform: 32 bit system

[Dan Olsen]

Mainfram side detail trace beginning with 125 message:

Sep 9 21:20:42 FTSPJN4 ftps[384]: SR3397 reply: --> 125 List started OK
Sep 9 21:20:42 FTSPJN4 ftps[384]: SR4256 usingUTF8: entered
Sep 9 21:20:42 FTSPJN4 ftps[384]: FU0533 secureWrite: entered
Sep 9 21:20:42 FTSPJN4 ftps[384]: FU0285 protDataConn: entered
Sep 9 21:20:42 FTSPJN4 ftps[384]: FU0297 protDataConn: secure_socket_open()
Sep 9 21:20:42 FTSPJN4 ftps[384]: SR4312 getFNDELAY: entered
Sep 9 21:20:42 FTSPJN4 ftps[384]: FU0381 protDataConn: secure_socket_init()
Sep 9 21:20:42 FTSPJN4 ftps[384]: FU0433 secureRead: entered
Sep 9 21:20:42 FTSPJN4 ftps[384]: FU0433 secureRead: entered
Sep 9 21:20:42 FTSPJN4 ftps[384]: FU0533 secureWrite: entered
Sep 9 21:20:42 FTSPJN4 FSUM1221 syslogd: last message repeated 2 times
Sep 9 21:20:42 FTSPJN4 ftps[384]: FU0433 secureRead: entered
Sep 9 21:20:42 FTSPJN4 FSUM1221 syslogd: last message repeated 3 times
Sep 9 21:20:42 FTSPJN4 ftps[384]: FU0394 protDataConn: secure_socket_init complete
Sep 9 21:20:42 FTSPJN4 ftps[384]: FU0396 protDataConn: ... handshake exchanged 269 bytes
Sep 9 21:20:42 FTSPJN4 ftps[384]: SR4347 setFNDELAY: entered
Sep 9 21:20:42 FTSPJN4 ftps[384]: SR4628 update_data_appldata: entered
Sep 9 21:20:42 FTSPJN4 ftps[384]: FU1411 getNegotiatedTLSvalues: entered
Sep 9 21:20:42 FTSPJN4 ftps[384]: GU4887 ftpSetApplData: entered
Sep 9 21:20:42 FTSPJN4 ftps[384]: GU1391 get_recfm_values: entered
Sep 9 21:20:43 FTSPJN4 FSUM1221 syslogd: last message repeated 11 times
Sep 9 21:20:43 FTSPJN4 ftps[384]: MR5544 psListD: DSSTAT(1) rc for DOLSEN is -5.
Sep 9 21:20:43 FTSPJN4 ftps[384]: MR6722 fill_send: entered
Sep 9 21:20:43 FTSPJN4 ftps[384]: FU0693 tls_send_data: entered
Sep 9 21:20:43 FTSPJN4 ftps[384]: FU0533 secureWrite: entered
Sep 9 21:20:43 FTSPJN4 ftps[384]: SR3591 send_data: entered
Sep 9 21:20:43 FTSPJN4 ftps[384]: MR5481 psListD: routine entered with command LIST
Sep 9 21:20:43 FTSPJN4 ftps[384]: SR0384 data_close: entered (ps=10, ds=-1)
Sep 9 21:20:43 FTSPJN4 ftps[384]: FR1202 endSecureConn: entered
Sep 9 21:20:43 FTSPJN4 ftps[384]: SR3360 reply: entered
Sep 9 21:20:43 FTSPJN4 ftps[384]: SR3397 reply: --> 250 List completed successfully.
Sep 9 21:20:43 FTSPJN4 ftps[384]: SR4256 usingUTF8: entered
Sep 9 21:20:43 FTSPJN4 ftps[384]: FU0533 secureWrite: entered
Sep 9 21:20:43 FTSPJN4 ftps[384]: PR1179 onearg_cmd: returning
Sep 9 21:20:43 FTSPJN4 ftps[384]: SR0360 clear_reply_sent: entered
Sep 9 21:20:43 FTSPJN4 ftps[384]: SR1214 get_command: entered
Sep 9 21:20:56 FTSPJN4 ftps[16777598]: SR0987 data_connect: connect() failed on socket 9, retry_conn = 0 - EDC8127I Connection timed out. (errno2=76630291)

[Tim Kosse]

Error: GnuTLS error -9: A TLS packet with unexpected length was received.
Status: Server did not properly shut down TLS connection

That's a bug in your server. Read ​http://forum.filezilla-project.org/viewtopic.php?f=2&t=7688 for details.

[Dan Olsen]

Opened a problem ticket with IBM. Their response is as follows:

In the packet trace I see only control connection but no data connection
open between these pair of IP address.

Local Ip Address: 10.200.32.254
Remote Ip Address: 66.180.1.228

.

Host: Local, Remote

Client or Server: SERVER, CLIENT
Port: 21, 46287
Application: ftp,
Link speed (parm): 10, 10 Megabits/s

.
I reviewed your previous update and I ntoice you are using NAT firewall
in this configuration.
The server's public IP address is 66.180.4.6 as per trace below
Status: Connecting to 66.180.4.6:21...
.
When client issue PASV, I see server return a private IP address
10,200,32,254, see trace below.
.
Command: PASV
Trace: CFtpControlSocket::OnReceive()
Response: 227 Entering Passive Mode (10,200,32,254,234,121)
.
Since the control connection is encrypted, so NAT will not be able to
translate the 10,200,32,254 back to 66.180.4.6, thus client fail to
open a data connection with z/OS host.
.
If you are running only one NAT then you can try ACTIVE transfer,
instead of PASV, however if you are running two NAT (one NAT on
each end) then you must have client issue EPSV command to fix this
issue, EPSV command will force server not to send IP address on
control connection, EPSV reply contains only the port number so
we will continue use the public IP address to communicate.
RFC 2428 defines EPSV and EPRT commands for NATs and IPv6 sessions
.
In summary, please change Filezilla to use ACTIVE transfer first,
if that still not working, please open a ticket to filezilla vendo
of how to implement EPSV command in the client end.
.
========================================================================
Active will not work due to firewalls on the client side so EPSV which is RFC2428 should be supported. This will support encrypted connections through NATted firewalls.

Dan Olsen

[Tim Kosse]

According to both the client as well as the server logs, the data connection was in fact established successfully and the TLS handshake as well was successful:

Command: PASV
Response: 227 Entering Passive Mode (10,200,32,254,234,121)
Status: Server sent passive reply with unroutable address. Using server address instead.

Trace: Handshake successful
Trace: Session resumed
Trace: Cipher: ARCFOUR-128, MAC: MD5

Sep 9 21:20:42 FTSPJN4 ftps[384]: FU0394 protDataConn: secure_socket_init complete
Sep 9 21:20:42 FTSPJN4 ftps[384]: FU0396 protDataConn: ... handshake exchanged 269 bytes

Since the only difference between PORT, PASV and EPSV is the negotiation of the initial data connection parameters, the subsequent behavior is exactly the same once the TCP connection has been established.

The problem is that the server does not properly shut down the secure channel but instead drops the underlaying TCP connection. That's incorrect behavior since it is indistinguishable from an attacker sending a forged FIN (or RST) packet.
Please have a look at the TLS specifications. It is explained in detail in section 7.2.1 in RFC 2246.

[Thomas Arthur Seidel]

I would like to add the information that indeed this mentioned problem appears like a FileZilla problem rather than a FTPES Server problem. I have tested FileZilla on various machines, mostly Win2008Server R2 with the operating systems FTPES Server, and it works fine, but it fails with the above mentioned error on any attempt to connect to an UBUNTU VSFTPD or QNAP FTPES Server. With any of these (VSFTPD, QNAP, WinFTPES) I have no difficulties with other programs, including our own applications. I can help you with any kind of experiments, because I can choose from a big collection of customers machines in remote maintenance.

TASKI

[Tim Kosse]

As I have explained before, this is a bug in the server. I am not going to add a workaround as this server bug has security implications.