#83 Output Truncated (Race Conditions?)

[Dave Thrall]

1) I used the code from the tutorial to read the server output (java inputstream). I did this in the single command mode, not a pseudo-terminal.

2) I found that a high rate of the commands that I was executing appeared to be failing in an unknown manner when examining the client-side output.

3) I wrote a simple loop to essentially "echo i > /test/i && cat i;" where i was my counter from 1 to 1000. I found that a relatively high percentage (>20%) of the time the commands were executed, the output would be empty.

4) I was able to verify that on the server side, all commands were executing successfully, as I had 1000 files containing the proper contents.

5) The *really* funky thing happened at this point. I went from my Linux box (using the official sun jdk) and ran it on a Windows XP Pro box. 100% of the commands I ran successfully produced output on the client side.

6) I executed a lot of commands in the form "command1 && command 2; echo Exit $?" and found that my output fell into a few categories:

a) blank output
b) output for command 1
c) output for command 1 and command 2
d) output for all commands invoked

Most frequently results were a) and d)

--------

Ugly Quick Fix & Theory:

Once the session channel's state is closed, one can no longer read the associated InputStream. This was verified by waiting for the channel to close and then attempting to process the output, which failed 100% of the time.

Adding "; sleep .250" to the end of each command before it is executed resulted in me getting 100% accurate output, "; sleep .100" led to success > 95%, and as I decreased the length of the sleep command, my failure rate increased.

It is my hypothesis that the session channel was getting closed before the full output had been read from the streams. Adding an extra command which produced no output, but increased the time between my last real command and the closing of the session channel is what gave adequate time to finish processing the stream before being severed.

The following is a snippet of what I am now using:

SessionChannelClient session = null;
InputStream in = null;

String line = "";
String output = "";

try
{
// The connection is authenticated we can now do some real work!
session = ssh.openSessionChannel();
in = session.getInputStream();

// Pause for a fraction of a second to prevent connection from
// being closed prematurely, before we've finished reading out
command = command + "; sleep .250;";
if (session.executeCommand(command))
{
BufferedReader br = new BufferedReader(new InputStreamReader(in));
StringBuffer buffer = new StringBuffer();
while ((line = br.readLine()) != null || session.getState().equals(ChannelState.CHANNEL_OPEN))
{
buffer.append(line + "\n");
}
output = buffer.toString();
}
}

[Joel]

We have encountered this issue as well.
Multi-line output is being truncated and adding a "; sleep .500" to the command has fixed the problem 99.9% of the time but once and a while it is still truncated. We're testing with "sleep 1" to see if that works more reliably but it would still be nice if the root cause was fixed in code. :)
Awesome find Dave!

[Pepijn Schmitz]

I just posted about this on the forum. I think I know what causes this bug. Here is what I said:

"There is a large race condition in J2SSH; in the ChannelInputStream class to be precise. When the channel is closed before all data is read from the ChannelInputStream, it will report that it is EOF, even if there is still incoming data in the message store!

This causes the output of commands to be lost either completely or partially on a random basis.

The cause is this while loop on line 267 of ChannelnputStream (the same bug is repeated a few lines further on for stdout):

while ((msg == null) && !isClosed()) {
// ... read msg ...
}

isClosed() returns true if the underlying message store is closed, regardless of whether there are still message waiting in the message store. Since the channel is closed automatically when the command is finished, and the channel closes the message stores when it is closed, this while loop will always be skipped after the command has finished and if any of the command's output is still buffered in the message store it will be lost.

One possible short term solution is to simply remove the !isClosed() from the conditions of the two while loops. This will allow the getMessage() method of the message store to throw a MessageStoreEOFException when the message store is closed and there are no more messages buffered.

Really all this code should be refactored though. Relying on exceptions for flow control is very ugly."

[Sascha Hunold]

Pepijn is totally right.
I changed the code according to what he pointed out. I haven't tried it though, so I won't say the bug has been fixed now.