Unexpected server response

Question

I am using a licensed version of edtftpj-pro-1.3.2 in a production system. Things were working just fine until yesterday afternoon when we started getting the following exception when trying to do a put. The only thing that happens is a blank file gets put into the destination server.

This is a high priority problem and I need help.

java.io.IOException: Unexpected server response
com.enterprisedt.net.j2ssh.sftp.SftpSubsystemClient.A(Unknown Source)
com.enterprisedt.net.j2ssh.sftp.SftpSubsystemClient.writeFile(Unknown Source)
com.enterprisedt.net.j2ssh.sftp.SftpFileOutputStream.write(Unknown Source)
com.enterprisedt.net.j2ssh.SftpClient.A(Unknown Source)
com.enterprisedt.net.j2ssh.SftpClient.put(Unknown Source)
com.enterprisedt.net.j2ssh.SftpClient.put(Unknown Source)
com.enterprisedt.net.ftp.ssh.SSHFTPClient.put(Unknown Source)
d4232.fhwa.FHWATransfer.sendFile(FHWATransfer.java:187)
d4232.fhwa.upload.UploadSession.uploadFile(UploadSession.java:85)
d4232.fhwa.upload.UploadSession.run(UploadSession.java:55)
java.lang.Thread.run(Thread.java:513)

I do not have log4j so I don't believe I can do any logging. Plus additional coding is not possible since this is a production application. As I said before this was working fine. Something happened either with the network or the servers that should be talking to each other. I need to identify what it is.

Answer 1

I have additional information.

According to the technicians supporting the FTP server we are uploading our file to, the logs seem to indicate that there is a packet length issue.

I took out some of the projects to upload in our application to make the file smaller and it worked. Could it be that there is a bug that causes this Unexpected Server Response error when a file is transferred that is too big? The file was only 3730 bytes.

Could this be a network problem, firewall problem, McAffee problem?

Answer 2

[quote="cdaniel"]
Could this be a network problem, firewall problem, McAffee problem?[/quote]

Actually, I don't believe it is any of these since I can transfer this same file through SSH Secure File Transfer Client without a problem. Unless the issue is a problem with java only.

Answer 3

If it is a packet length issue, you can try this:

SSHFTPClient.setMaxPacketSize(xxx)

where xxx could be say 8192.

Logging can be enabled by:

import com.enterprisedt.util.debug.*;

Logger.setLevel(Level.ALL); // Level.DEBUG for production systems, ALL is too high
Logger.addAppender(new FileAppender("file.log"));

Either of these options do require additional coding :(

Answer 4

[quote="support2"]If it is a packet length issue, you can try this:

SSHFTPClient.setMaxPacketSize(xxx)

where xxx could be say 8192.

Logging can be enabled by:

import com.enterprisedt.util.debug.*;

Logger.setLevel(Level.ALL); // Level.DEBUG for production systems, ALL is too high
Logger.addAppender(new FileAppender("file.log"));

Either of these options do require additional coding :([/quote]

Thanks. I figured out how to turn the log on (just logging to system.out) and have arranged to move that new code as an emergency production migration. I

Answer 5

The log when the error occurs.

DEBUG [com.enterprisedt.net.j2ssh.SftpClient] 7 Feb 2007 12:49.281 : put(e:\mpmsftp\PA_20070207_121339.DAT,PA_20070207_121339.DAT)
DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] 7 Feb 2007 12:49.281 : Sending SSH_FXP_STAT subsystem message
DEBUG [com.enterprisedt.net.j2ssh.connection.ConnectionProtocol] 7 Feb 2007 12:49.281 : Sending 4 bytes for channel id 0
ALL [TransportProtocolCommon] 7 Feb 2007 12:49.281 : Name=SSH_MSG_CHANNEL_DATA,MessageId=94
DEBUG [com.enterprisedt.net.j2ssh.connection.ConnectionProtocol] 7 Feb 2007 12:49.281 : Sending 59 bytes for channel id 0
ALL [TransportProtocolCommon] 7 Feb 2007 12:49.281 : Name=SSH_MSG_CHANNEL_DATA,MessageId=94
ALL [TransportProtocolCommon] 7 Feb 2007 12:49.328 : Received unregistered message: Name=SSH_MSG_IGNORE,MessageId=2
ALL [TransportProtocolCommon] 7 Feb 2007 12:49.328 : Received registered message: Name=SSH_MSG_CHANNEL_DATA,MessageId=94
DEBUG [AsyncService] 7 Feb 2007 12:49.328 : Routing SSH_MSG_CHANNEL_DATA
DEBUG [com.enterprisedt.net.j2ssh.connection.ConnectionProtocol] 7 Feb 2007 12:49.328 : Received 141 bytes of data for channel id 0
DEBUG [SubsystemMessageStore] 7 Feb 2007 12:49.328 : Received SSH_FXP_STATUS subsystem message
DEBUG [AsyncService] 7 Feb 2007 12:49.328 : Finished processing SSH_MSG_CHANNEL_DATA
DEBUG [com.enterprisedt.net.j2ssh.SftpClient] 7 Feb 2007 12:49.328 : remote path=/HOME/EDS_from_states/input/PA_20070207_121339.DAT
DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] 7 Feb 2007 12:49.328 : Sending SSH_FXP_STAT subsystem message
DEBUG [com.enterprisedt.net.j2ssh.connection.ConnectionProtocol] 7 Feb 2007 12:49.328 : Sending 4 bytes for channel id 0
ALL [TransportProtocolCommon] 7 Feb 2007 12:49.344 : Name=SSH_MSG_CHANNEL_DATA,MessageId=94
DEBUG [com.enterprisedt.net.j2ssh.connection.ConnectionProtocol] 7 Feb 2007 12:49.344 : Sending 59 bytes for channel id 0
ALL [TransportProtocolCommon] 7 Feb 2007 12:49.344 : Name=SSH_MSG_CHANNEL_DATA,MessageId=94
ALL [TransportProtocolCommon] 7 Feb 2007 12:49.938 : Received unregistered message: Name=SSH_MSG_IGNORE,MessageId=2
ALL [TransportProtocolCommon] 7 Feb 2007 12:49.938 : Received registered message: Name=SSH_MSG_CHANNEL_DATA,MessageId=94
DEBUG [AsyncService] 7 Feb 2007 12:49.938 : Routing SSH_MSG_CHANNEL_DATA
DEBUG [com.enterprisedt.net.j2ssh.connection.ConnectionProtocol] 7 Feb 2007 12:49.938 : Received 141 bytes of data for channel id 0
DEBUG [SubsystemMessageStore] 7 Feb 2007 12:49.938 : Received SSH_FXP_STATUS subsystem message
DEBUG [AsyncService] 7 Feb 2007 12:49.938 : Finished processing SSH_MSG_CHANNEL_DATA
DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] 7 Feb 2007 12:49.938 : Sending SSH_FXP_OPEN subsystem message
DEBUG [com.enterprisedt.net.j2ssh.connection.ConnectionProtocol] 7 Feb 2007 12:49.938 : Sending 4 bytes for channel id 0
ALL [TransportProtocolCommon] 7 Feb 2007 12:49.938 : Name=SSH_MSG_CHANNEL_DATA,MessageId=94
DEBUG [com.enterprisedt.net.j2ssh.connection.ConnectionProtocol] 7 Feb 2007 12:49.938 : Sending 75 bytes for channel id 0
ALL [TransportProtocolCommon] 7 Feb 2007 12:49.938 : Name=SSH_MSG_CHANNEL_DATA,MessageId=94
ALL [TransportProtocolCommon] 7 Feb 2007 12:49.984 : Received unregistered message: Name=SSH_MSG_IGNORE,MessageId=2
ALL [TransportProtocolCommon] 7 Feb 2007 12:49.984 : Received registered message: Name=SSH_MSG_CHANNEL_DATA,MessageId=94
DEBUG [AsyncService] 7 Feb 2007 12:49.984 : Routing SSH_MSG_CHANNEL_DATA
DEBUG [com.enterprisedt.net.j2ssh.connection.ConnectionProtocol] 7 Feb 2007 12:49.984 : Received 21 bytes of data for channel id 0
DEBUG [SubsystemMessageStore] 7 Feb 2007 12:49.984 : Received SSH_FXP_HANDLE subsystem message
DEBUG [AsyncService] 7 Feb 2007 12:49.984 : Finished processing SSH_MSG_CHANNEL_DATA
DEBUG [com.enterprisedt.net.j2ssh.SftpClient] 7 Feb 2007 12:49.984 : ENTRY - transferASCIIFile
DEBUG [SftpFileOutputStream] 7 Feb 2007 12:50.62 : Writing buffer of size 65535 (max packet size=65535)
DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] 7 Feb 2007 12:50.62 : Sending SSH_FXP_WRITE subsystem message
DEBUG [com.enterprisedt.net.j2ssh.connection.ConnectionProtocol] 7 Feb 2007 12:50.62 : Sending 4 bytes for channel id 0
ALL [TransportProtocolCommon] 7 Feb 2007 12:50.62 : Name=SSH_MSG_CHANNEL_DATA,MessageId=94
DEBUG [com.enterprisedt.net.j2ssh.connection.ConnectionProtocol] 7 Feb 2007 12:50.62 : Sending 65564 bytes for channel id 0
ALL [TransportProtocolCommon] 7 Feb 2007 12:50.62 : Name=SSH_MSG_CHANNEL_DATA,MessageId=94
ALL [TransportProtocolCommon] 7 Feb 2007 12:50.266 : Name=SSH_MSG_CHANNEL_DATA,MessageId=94
ALL [TransportProtocolCommon] 7 Feb 2007 12:50.297 : Received unregistered message: Name=SSH_MSG_IGNORE,MessageId=2
ALL [TransportProtocolCommon] 7 Feb 2007 12:50.297 : Received unregistered message: Name=SSH_MSG_DISCONNECT,MessageId=1
DEBUG [TransportProtocolCommon] 7 Feb 2007 12:50.297 : The remote computer disconnected: Protocol error: packet too long: 65580.
DEBUG [TransportProtocolCommon] 7 Feb 2007 12:50.297 : stop() called
DEBUG [com.enterprisedt.net.j2ssh.connection.Channel] 7 Feb 2007 12:50.297 : Remote side is closing channel
ERROR [TransportProtocolOutputStream] 7 Feb 2007 12:50.469 : sendMessage() failed: Connection aborted by peer: socket write error (state=5)
DEBUG [SftpSubsystemClient] 7 Feb 2007 12:50.469 : Waiting for response
DEBUG [com.enterprisedt.net.j2ssh.connection.Channel] 7 Feb 2007 12:50.469 : Connection is not connected
DEBUG [com.enterprisedt.net.j2ssh.connection.Channel] 7 Feb 2007 12:50.469 : Finalizing channel close
DEBUG [SftpSubsystemClient] 7 Feb 2007 12:50.469 : Received response
DEBUG [com.enterprisedt.net.j2ssh.connection.ConnectionProtocol] 7 Feb 2007 12:50.469 : Freeing channel 0 [sftp]
DEBUG [SftpSubsystemClient] 7 Feb 2007 12:50.469 : Closing file /HOME/EDS_from_states/input/PA_20070207_121339.DAT
DEBUG [TransportProtocolCommon] 7 Feb 2007 12:50.469 : The Transport Protocol has been stopped
DEBUG [com.enterprisedt.net.j2ssh.connection.ConnectionProtocol] 7 Feb 2007 12:50.469 : Closing all active channels
DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] 7 Feb 2007 12:50.469 : Sending SSH_FXP_CLOSE subsystem message
ERROR [com.enterprisedt.net.j2ssh.SftpClient] 7 Feb 2007 12:50.469 : Failed to close output stream in put() : The connection has been closed [Unnamed Channel]
java.io.IOException: The connection has been closed [Unnamed Channel]
at com.enterprisedt.net.j2ssh.connection.Channel.sendChannelData(Unknown Source)
at com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel.sendMessage(Unknown Source)
at com.enterprisedt.net.j2ssh.sftp.SftpSubsystemClient.closeHandle(Unknown Source)
at com.enterprisedt.net.j2ssh.sftp.SftpSubsystemClient.closeFile(Unknown Source)
at com.enterprisedt.net.j2ssh.sftp.SftpFile.close(Unknown Source)
at com.enterprisedt.net.j2ssh.sftp.SftpFileOutputStream.close(Unknown Source)
at com.enterprisedt.net.j2ssh.SftpClient.put(Unknown Source)
at com.enterprisedt.net.j2ssh.SftpClient.put(Unknown Source)
at com.enterprisedt.net.ftp.ssh.SSHFTPClient.put(Unknown Source)
at d4232.fhwa.FHWATransfer.sendFile(FHWATransfer.java:188)
at d4232.fhwa.upload.UploadSession.uploadFile(UploadSession.java:85)
at d4232.fhwa.upload.UploadSession.run(UploadSession.java:55)
at java.lang.Thread.run(Thread.java:513)
DEBUG [AsyncService] 7 Feb 2007 12:50.484 : ssh-connection thread is exiting
java.io.IOException: Unexpected server response
at com.enterprisedt.net.j2ssh

Answer 6

[quote]The packet size is worked out dynamically, but occasionally some SFTP servers have trouble with larger packets - we don't know why, and we've never found a good explanation via google for it either.

This code puts a limit on the packet size - we normally recommend setMaxPacketSize(32767) which generally works. The symptoms are something like "Protocol error: packet too long: 46780" returned as an error message.

I don't know what your error message is which is why i suggested 8192, but this is actually a bit small - hopefully 32767 will work for you.[/quote]

I used 32767. This worked.

Based on what you see from the logs will this be the permanent solution?

By the way thanks a ton.

Answer 7

In our experience this should deal with the problem permanently - it has for other customers. We can't guarantee it though as no-one seems to know why servers occasionally generate this error!