exit-status returns non-deterministic

[muzy]

Hi,

I just discovered that the exit-status is not always set (in net.schmizz.sshj.connection.channel.direct) , even though the according packets are send by the ssh host. A first evaluation of this points to the StreamCopier (net.schmizz.sshj.StreamCopier) because depending on the call of the copy() function, the exit-status is available or not (see attached logfiles).

Logfile when exit-status is fetched:

DEBUG ConnectionImpl:68 - Attaching `session` channel (#3)
TRACE Encoder:100 - Encoding packet #18: 5a 00 00 00 07 73 65 73 73 69 6f 6e 00 00 00 03 00 20 00 00 00 00 80 00
DEBUG Promise:164 - Awaiting <<chan#3 / open>>
TRACE Decoder:125 - Received packet #25: 5b 00 00 00 03 00 00 00 00 00 00 00 00 00 00 80 00
TRACE TransportImpl:471 - Received packet CHANNEL_OPEN_CONFIRMATION
DEBUG SessionChannel:125 - Initialized - < session channel: id=3, recipient=0, localWin=[winSize=2097152], remoteWin=[winSize=0] >
DEBUG Promise:78 - Setting <<chan#3 / open>> to `SOME`
INFO  SessionChannel:120 - Will request to exec `test -x /tmp/nmon`
DEBUG SessionChannel:374 - Sending channel request for `exec`
TRACE Encoder:100 - Encoding packet #19: 62 00 00 00 00 00 00 00 04 65 78 65 63 01 00 00 00 11 74 65 73 74 20 2d 78 20 2f 74 6d 70 2f 6e 6d 6f 6e
DEBUG Promise:164 - Awaiting <<chan#3 / chanreq for exec>>
TRACE Decoder:125 - Received packet #26: 5d 00 00 00 03 00 20 00 00
TRACE TransportImpl:471 - Received packet CHANNEL_WINDOW_ADJUST
DEBUG SessionChannel:328 - Received window adjustment for 2097152 bytes
DEBUG Window$Remote:41 - Increasing by 2097152 up to 2097152
TRACE Decoder:125 - Received packet #27: 63 00 00 00 03
TRACE TransportImpl:471 - Received packet CHANNEL_SUCCESS
DEBUG Promise:78 - Setting <<chan#3 / chanreq for exec>> to `SOME`
DEBUG SSHWrapper:241 - < session channel: id=3, recipient=0, localWin=[winSize=2097152], remoteWin=[winSize=2097152] >
TRACE Decoder:125 - Received packet #28: 60 00 00 00 03
TRACE TransportImpl:471 - Received packet CHANNEL_EOF
DEBUG SessionChannel:410 - Got EOF
DEBUG StreamCopier:139 - 0.0 KiB transferred  in 0.038 seconds (0.0 KiB/s)
TRACE Decoder:125 - Received packet #29: 62 00 00 00 03 00 00 00 0b 65 78 69 74 2d 73 74 61 74 75 73 00 00 00 00 01
TRACE TransportImpl:471 - Received packet CHANNEL_REQUEST
DEBUG SessionChannel:316 - Got chan request for `exit-status`
TRACE Decoder:125 - Received packet #30: 61 00 00 00 03
TRACE TransportImpl:471 - Received packet CHANNEL_CLOSE
DEBUG SessionChannel:223 - Got close
DEBUG SessionChannel:427 - Sending EOF
TRACE Encoder:100 - Encoding packet #20: 60 00 00 00 00
DEBUG StreamCopier:139 - 0.0 KiB transferred  in 0.0 seconds (NaN KiB/s)
DEBUG SessionChannel:289 - Sending close
TRACE Encoder:100 - Encoding packet #21: 61 00 00 00 00
DEBUG Promise:164 - Awaiting <<chan#3 / close>>
DEBUG ConnectionImpl:84 - Forgetting `session` channel (#3)
DEBUG Promise:78 - Setting <<chan#3 / close>> to `SOME`

Logfile when the exit-status remains "null":

DEBUG ConnectionImpl:68 - Attaching `session` channel (#4)
TRACE Encoder:100 - Encoding packet #22: 5a 00 00 00 07 73 65 73 73 69 6f 6e 00 00 00 04 00 20 00 00 00 00 80 00
DEBUG Promise:164 - Awaiting <<chan#4 / open>>
TRACE Decoder:125 - Received packet #31: 5b 00 00 00 04 00 00 00 00 00 00 00 00 00 00 80 00
TRACE TransportImpl:471 - Received packet CHANNEL_OPEN_CONFIRMATION
DEBUG SessionChannel:125 - Initialized - < session channel: id=4, recipient=0, localWin=[winSize=2097152], remoteWin=[winSize=0] >
DEBUG Promise:78 - Setting <<chan#4 / open>> to `SOME`
INFO  SessionChannel:120 - Will request to exec `test -x /tmp/nmon`
DEBUG SessionChannel:374 - Sending channel request for `exec`
TRACE Encoder:100 - Encoding packet #23: 62 00 00 00 00 00 00 00 04 65 78 65 63 01 00 00 00 11 74 65 73 74 20 2d 78 20 2f 74 6d 70 2f 6e 6d 6f 6e
DEBUG Promise:164 - Awaiting <<chan#4 / chanreq for exec>>
TRACE Decoder:125 - Received packet #32: 5d 00 00 00 04 00 20 00 00
TRACE TransportImpl:471 - Received packet CHANNEL_WINDOW_ADJUST
DEBUG SessionChannel:328 - Received window adjustment for 2097152 bytes
DEBUG Window$Remote:41 - Increasing by 2097152 up to 2097152
TRACE Decoder:125 - Received packet #33: 63 00 00 00 04
TRACE TransportImpl:471 - Received packet CHANNEL_SUCCESS
DEBUG Promise:78 - Setting <<chan#4 / chanreq for exec>> to `SOME`
DEBUG SSHWrapper:241 - < session channel: id=4, recipient=0, localWin=[winSize=2097152], remoteWin=[winSize=2097152] >
TRACE Decoder:125 - Received packet #34: 60 00 00 00 04
TRACE TransportImpl:471 - Received packet CHANNEL_EOF
DEBUG SessionChannel:410 - Got EOF
DEBUG StreamCopier:139 - 0.0 KiB transferred  in 0.039 seconds (0.0 KiB/s)
DEBUG StreamCopier:139 - 0.0 KiB transferred  in 0.0 seconds (NaN KiB/s)
TRACE Decoder:125 - Received packet #35: 62 00 00 00 04 00 00 00 0b 65 78 69 74 2d 73 74 61 74 75 73 00 00 00 00 01
TRACE TransportImpl:471 - Received packet CHANNEL_REQUEST
DEBUG SessionChannel:316 - Got chan request for `exit-status`
TRACE Decoder:125 - Received packet #36: 61 00 00 00 04
TRACE TransportImpl:471 - Received packet CHANNEL_CLOSE
DEBUG SessionChannel:223 - Got close
DEBUG SessionChannel:427 - Sending EOF
TRACE Encoder:100 - Encoding packet #24: 60 00 00 00 00
DEBUG SessionChannel:289 - Sending close
TRACE Encoder:100 - Encoding packet #25: 61 00 00 00 00
DEBUG Promise:164 - Awaiting <<chan#4 / close>>
DEBUG ConnectionImpl:84 - Forgetting `session` channel (#4)
DEBUG Promise:78 - Setting <<chan#4 / close>> to `SOME`

Even though the SSH related RFC (http://www.ietf.org/rfc/rfc4254.txt) only recommends to return the exit-status, an accurate exit-status would be great instead of an null value (when the host has send the packet).

[shikhar]

seems like a visibility issue - sounds like some of SessionChannel's fields (exitStatus, exitSignal, wasCoreDumped, exitErrMsg, canDoFlowControl) need to be volatile.

[muzy]

The issue still persist and is not fixed using the latest snapshot version.

[shikhar]

ok, reopening

[BioQwer]

Hello
have same problem
Methods return null in debuger see thats value is not null

Session.Command cmd = null;
Session session = ssh.startSession();
cmd = session.exec(shellCommand);
System.out.println("status = " + cmd.getExitStatus());
System.out.println("cmd.getExitSignal() = " + cmd.getExitSignal());
System.out.println("cmd = " + cmd);
LOGGER.debug("{}@{}:# {}", _login, _host, shellCommand);
return cmd.getInputStream();

[BioQwer]

If execute cmd.close(); method work.

Before getExitStatus (as i think) you must flush resources of command.

Session.Command cmd = null;
Session session = ssh.startSession();
cmd = session.exec(shellCommand);
cmd.close();
if (cmd.getExitStatus() != 0) {
    throw new ExecutionException("Shell command " +
            "'"+shellCommand+"' on host = "+_host+" exit w
            .getExitStatus());
}
LOGGER.debug("{}@{}:# {}", _login, _host, shellCommand);

stdout
exception.ExecutionException: Shell command 'asdasd' on host = hadoop08 exit with status 127