Problem reading output from Session.exec

225 views

Skip to first unread message

bernd...@xaidat.com

unread,

Aug 11, 2017, 10:38:10 AM8/11/17

to sshj-users

sshj Dependency: compile 'com.hierynomus:sshj:0.21.1'

Platform: Koltin 1.1.3-2 (JRE 1.8.0_131-b11, Azul Zulu on Mac 10.12)

---

As part for a tool for developer onboarding, I’m trying to install ssh public keys on a gitblit server, patterned after https://github.com/hierynomus/sshj/blob/master/examples/src/main/java/net/schmizz/sshj/examples/Exec.java.

Unfortunately I can’t seem to read from or write to the streams.

I cut it down to this in the Repl:

```Kotlin

import org.slf4j.Logger
import org.slf4j.LoggerFactory
import java.util.logging.Level
import java.util.logging.LogManager

fun sshClientWithTrustingHostkeyVerifier(): SSHClient {
    return SSHClient(DefaultConfig()).also { client ->
        client.addHostKeyVerifier(object : OpenSSHKnownHosts(File(sshDir(), "known_hosts")) {
            override fun hostKeyUnverifiableAction(hostname: String?, key: PublicKey?): Boolean {
                super.write(SimpleEntry(null, hostname, KeyType.fromKey(key), key))
                return true
            }
        })
    }
}

LogManager.getLogManager().let {lm -> lm.loggerNames.asSequence().forEach { lm.getLogger(it).apply{
    level = Level.FINEST
    handlers.forEach { it.level = Level.FINEST }}}}

val log: Logger = LoggerFactory.getLogger("foo")

log.debug("a")
val client = sshClientWithTrustingHostkeyVerifier()
log.debug("b")
client.connect("the.gitblit.local", 29418)
log.debug("c")
client.authPassword("my_account", "my super password")
log.debug("d")
val session = client.startSession()
log.debug("e")
val cmd = session.exec("keys --help")
log.debug("f")
log.debug(cmd.inputStream.readBytes().toString())
log.debug("g")
log.debug(cmd.errorStream.readBytes().toString())
log.debug("h")
cmd.join()
log.debug("i")
log.debug("Exit status: {}", cmd.exitStatus)

```

This produces a *lot* of output, which includes a weird error "[PROTOCOL_ERROR] Received CHANNEL_SUCCESS" does not contain gitblit's output which, using the openssh client, is this:

Full log, minus identifying info, minus hex dumps (not sure if secrets could be derived from them - please advise if necessary and publishable):

Aug 11, 2017 2:05:18 PM Line_9 <init>
FINE: a
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.transport.random.BouncyCastleRandom <init>
INFO: Generating random seed from SecureRandom.
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.transport.random.BouncyCastleRandom <init>
FINE: Creating random seed took 0 ms
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.DefaultConfig initCipherFactories
WARNING: Illegal key size
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.DefaultConfig initCipherFactories
WARNING: Illegal key size
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.DefaultConfig initCipherFactories
WARNING: Illegal key size
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.DefaultConfig initCipherFactories
WARNING: Illegal key size
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.DefaultConfig initCipherFactories
WARNING: Illegal key size
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.DefaultConfig initCipherFactories
WARNING: Illegal key size
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.DefaultConfig initCipherFactories
WARNING: Illegal key size
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.DefaultConfig initCipherFactories
WARNING: Illegal key size
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.DefaultConfig initCipherFactories
WARNING: Illegal key size
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.DefaultConfig initCipherFactories
WARNING: Illegal key size
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.DefaultConfig initCipherFactories
WARNING: Illegal key size
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.DefaultConfig initCipherFactories
WARNING: Illegal key size
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.DefaultConfig initCipherFactories
WARNING: Illegal key size
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.DefaultConfig initCipherFactories
WARNING: Illegal key size
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.DefaultConfig initCipherFactories
WARNING: Illegal key size or default parameters
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.DefaultConfig initCipherFactories
WARNING: Disabling high-strength ciphers: cipher strengths apparently limited by JCE policy
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.DefaultConfig initCipherFactories
FINE: Available cipher factories: [net.schmizz.sshj.transport.cipher.AES128CTR$Factory@304542ec, net.schmizz.sshj.transport.cipher.AES128CBC$Factory@43687885, net.schmizz.sshj.transport.cipher.TripleDESCBC$Factory@5c609f47, net.schmizz.sshj.transport.cipher.BlowfishCBC$Factory@3004c204, cast128-cbc, cast128-ctr, idea-cbc, idea-ctr, serpent128-cbc, serpent128-ctr, 3des-ctr, twofish128-cbc, twofish128-ctr, arcfour, arcfour128]
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.common.KeyType$3 readPubKeyFromBuffer
FINE: Key algo: ecdsa-sha2-nistp256, Key curve: nistp256, Key Len: 65, 0x04: 4
x: […]
y: […]
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.common.KeyType$3 readPubKeyFromBuffer
FINE: Key algo: ecdsa-sha2-nistp256, Key curve: nistp256, Key Len: 65, 0x04: 4
x: […]
y: […]
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.common.KeyType$3 readPubKeyFromBuffer
FINE: Key algo: ecdsa-sha2-nistp256, Key curve: nistp256, Key Len: 65, 0x04: 4
x: […]
y: […]
Aug 11, 2017 2:05:18 PM Line_9 <init>
FINE: b
Aug 11, 2017 2:05:18 PM net.schmizz.sshj.transport.TransportImpl sendClientIdent
INFO: Client identity string: SSH-2.0-SSHJ_0.21.1
Aug 11, 2017 2:05:19 PM net.schmizz.sshj.transport.TransportImpl init
INFO: Server identity string: SSH-2.0-Gitblit_v1.8.0 (SSHD-CORE-1.0.0-NIO2)
Aug 11, 2017 2:05:19 PM net.schmizz.concurrent.Promise deliver
FINE: Setting <<kex done>> to `null`
Aug 11, 2017 2:05:19 PM net.schmizz.sshj.transport.KeyExchanger sendKexInit
FINE: Sending SSH_MSG_KEXINIT
Aug 11, 2017 2:05:19 PM net.schmizz.sshj.transport.Encoder encode
FINEST: Encoding packet #-1: …
Aug 11, 2017 2:05:19 PM net.schmizz.concurrent.Promise deliver
FINE: Setting <<kexinit sent>> to `SOME`
Aug 11, 2017 2:05:19 PM net.schmizz.concurrent.Promise tryRetrieve
FINE: Awaiting <<kex done>>
Aug 11, 2017 2:05:19 PM net.schmizz.sshj.transport.Decoder decode
FINEST: Received packet #0: …
Aug 11, 2017 2:05:19 PM net.schmizz.sshj.transport.TransportImpl handle
FINEST: Received packet KEXINIT
Aug 11, 2017 2:05:19 PM net.schmizz.sshj.transport.KeyExchanger handle
FINE: Received SSH_MSG_KEXINIT
Aug 11, 2017 2:05:19 PM net.schmizz.sshj.transport.KeyExchanger gotKexInit
FINE: Negotiated algorithms: [ kex=diffie-hellman-group-exchange-sha256; sig=ssh-rsa; c2sCipher=aes128-ctr; s2cCipher=aes128-ctr; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1; c2sComp=none; s2cComp=none ]
Aug 11, 2017 2:05:19 PM net.schmizz.sshj.transport.kex.AbstractDHGex init
FINE: Sending KEX_DH_GEX_REQUEST
Aug 11, 2017 2:05:19 PM net.schmizz.sshj.transport.Encoder encode
FINEST: Encoding packet #0: …
Aug 11, 2017 2:05:19 PM net.schmizz.sshj.transport.Decoder decode
FINEST: Received packet #1: …
Aug 11, 2017 2:05:19 PM net.schmizz.sshj.transport.TransportImpl handle
FINEST: Received packet KEXDH_31
Aug 11, 2017 2:05:19 PM net.schmizz.sshj.transport.KeyExchanger handle
FINE: Received kex followup data
Aug 11, 2017 2:05:19 PM net.schmizz.sshj.transport.kex.AbstractDHGex next
FINE: Got message KEXDH_31
Aug 11, 2017 2:05:19 PM net.schmizz.sshj.transport.kex.AbstractDHGex parseGexGroup
FINE: Received server p bitlength 2048
Aug 11, 2017 2:05:19 PM net.schmizz.sshj.transport.kex.AbstractDHGex parseGexGroup
FINE: Sending KEX_DH_GEX_INIT
Aug 11, 2017 2:05:19 PM net.schmizz.sshj.transport.Encoder encode
FINEST: Encoding packet #1: …
Aug 11, 2017 2:05:20 PM net.schmizz.sshj.transport.Decoder decode
FINEST: Received packet #2: …
Aug 11, 2017 2:05:20 PM net.schmizz.sshj.transport.TransportImpl handle
FINEST: Received packet KEX_DH_GEX_REPLY
Aug 11, 2017 2:05:20 PM net.schmizz.sshj.transport.KeyExchanger handle
FINE: Received kex followup data
Aug 11, 2017 2:05:20 PM net.schmizz.sshj.transport.kex.AbstractDHGex next
FINE: Got message KEX_DH_GEX_REPLY
Aug 11, 2017 2:05:20 PM net.schmizz.sshj.transport.KeyExchanger verifyHost
FINE: Trying to verify host key with at.merkur.pos.gitmigra.GitmigraKt$sshClientWithTrustingHostkeyVerifier$1$1@7f2b1057
Aug 11, 2017 2:05:20 PM net.schmizz.sshj.transport.KeyExchanger sendNewKeys
FINE: Sending SSH_MSG_NEWKEYS
Aug 11, 2017 2:05:20 PM net.schmizz.sshj.transport.Encoder encode
FINEST: Encoding packet #2: 15
Aug 11, 2017 2:05:20 PM net.schmizz.sshj.transport.Decoder decode
FINEST: Received packet #3: 15
Aug 11, 2017 2:05:20 PM net.schmizz.sshj.transport.TransportImpl handle
FINEST: Received packet NEWKEYS
Aug 11, 2017 2:05:20 PM net.schmizz.sshj.transport.KeyExchanger handle
FINE: Received SSH_MSG_NEWKEYS
Aug 11, 2017 2:05:20 PM net.schmizz.concurrent.Promise deliver
FINE: Setting <<kexinit sent>> to `null`
Aug 11, 2017 2:05:20 PM net.schmizz.concurrent.Promise deliver
FINE: Setting <<kex done>> to `SOME`
Aug 11, 2017 2:05:20 PM net.schmizz.sshj.SSHClient doKex
FINE: Key exchange took 1.371 seconds
Aug 11, 2017 2:05:20 PM Line_9 <init>
FINE: c
Aug 11, 2017 2:05:20 PM net.schmizz.concurrent.Promise deliver
FINE: Setting <<service accept>> to `null`
Aug 11, 2017 2:05:20 PM net.schmizz.sshj.transport.TransportImpl sendServiceRequest
FINE: Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth
Aug 11, 2017 2:05:20 PM net.schmizz.sshj.transport.Encoder encode
FINEST: Encoding packet #3: …
Aug 11, 2017 2:05:20 PM net.schmizz.concurrent.Promise tryRetrieve
FINE: Awaiting <<service accept>>
Aug 11, 2017 2:05:20 PM net.schmizz.sshj.transport.Decoder decode
FINEST: Received packet #4: …
Aug 11, 2017 2:05:20 PM net.schmizz.sshj.transport.TransportImpl handle
FINEST: Received packet SERVICE_ACCEPT
Aug 11, 2017 2:05:20 PM net.schmizz.concurrent.Promise deliver
FINE: Setting <<service accept>> to `SOME`
Aug 11, 2017 2:05:20 PM net.schmizz.sshj.transport.TransportImpl setService
FINE: Setting active service to ssh-userauth
Aug 11, 2017 2:05:20 PM net.schmizz.concurrent.Promise deliver
FINE: Setting <<authenticated>> to `null`
Aug 11, 2017 2:05:20 PM net.schmizz.sshj.userauth.UserAuthImpl authenticate
FINE: Trying `password` auth...
Aug 11, 2017 2:05:20 PM net.schmizz.sshj.userauth.method.AuthPassword buildReq
FINE: Requesting password for [AccountResource] my_ac...@the.gitblit.local
Aug 11, 2017 2:05:20 PM net.schmizz.sshj.transport.Encoder encode
FINEST: Encoding packet #4: …
Aug 11, 2017 2:05:20 PM net.schmizz.concurrent.Promise tryRetrieve
FINE: Awaiting <<authenticated>>
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.Decoder decode
FINEST: Received packet #5: 34
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.TransportImpl handle
FINEST: Received packet USERAUTH_SUCCESS
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.TransportImpl setService
FINE: Setting active service to ssh-connection
Aug 11, 2017 2:05:21 PM net.schmizz.concurrent.Promise deliver
FINE: Setting <<authenticated>> to `true`
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.userauth.UserAuthImpl authenticate
FINE: `password` auth successful
Aug 11, 2017 2:05:21 PM Line_9 <init>
FINE: d
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.connection.ConnectionImpl attach
FINE: Attaching `session` channel (#0)
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.Encoder encode
FINEST: Encoding packet #5: …
Aug 11, 2017 2:05:21 PM net.schmizz.concurrent.Promise tryRetrieve
FINE: Awaiting <<chan#0 / open>>
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.Decoder decode
FINEST: Received packet #6: …
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.TransportImpl handle
FINEST: Received packet CHANNEL_OPEN_CONFIRMATION
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.connection.channel.AbstractChannel init
FINE: Initialized - < session channel: id=0, recipient=0, localWin=[winSize=2097152], remoteWin=[winSize=2097152] >
Aug 11, 2017 2:05:21 PM net.schmizz.concurrent.Promise deliver
FINE: Setting <<chan#0 / open>> to `SOME`
Aug 11, 2017 2:05:21 PM Line_9 <init>
FINE: e
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.connection.channel.direct.SessionChannel exec
FINE: Will request to exec `keys --help`
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.connection.channel.AbstractChannel sendChannelRequest
FINE: Sending channel request for `exec`
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.Encoder encode
FINEST: Encoding packet #6: …
Aug 11, 2017 2:05:21 PM net.schmizz.concurrent.Promise tryRetrieve
FINE: Awaiting <<chan#0 / chanreq for exec>>
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.Decoder decode
FINEST: Received packet #7: …
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.TransportImpl handle
FINEST: Received packet CHANNEL_EXTENDED_DATA
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.connection.channel.AbstractChannel receiveInto
FINEST: IN #0: …
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.connection.channel.Window consume
FINE: Consuming by 1242 down to 2095910
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.Decoder decode
FINEST: Received packet #8: …
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.TransportImpl handle
FINEST: Received packet CHANNEL_EOF
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.connection.channel.AbstractChannel gotEOF
FINE: Got EOF
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.Decoder decode
FINEST: Received packet #9: …
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.TransportImpl handle
FINEST: Received packet CHANNEL_REQUEST
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.connection.channel.AbstractChannel gotChannelRequest
FINE: Got chan request for `exit-status`
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.Decoder decode
FINEST: Received packet #10: …
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.TransportImpl handle
FINEST: Received packet CHANNEL_CLOSE
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.connection.channel.AbstractChannel gotClose
FINE: Got close
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.connection.channel.AbstractChannel sendClose
FINE: Sending close
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.Encoder encode
FINEST: Encoding packet #7: …
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.connection.ConnectionImpl forget
FINE: Forgetting `session` channel (#0)
Aug 11, 2017 2:05:21 PM net.schmizz.concurrent.Promise deliver
FINE: Setting <<chan#0 / close>> to `SOME`
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.Decoder decode
FINEST: Received packet #11: …
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.TransportImpl handle
FINEST: Received packet CHANNEL_SUCCESS
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.TransportImpl die
SEVERE: Dying because - {}
net.schmizz.sshj.connection.ConnectionException: [PROTOCOL_ERROR] Received CHANNEL_SUCCESS on unknown channel #0
	at net.schmizz.sshj.connection.ConnectionImpl.getChannel(ConnectionImpl.java:119)
	at net.schmizz.sshj.connection.ConnectionImpl.handle(ConnectionImpl.java:130)
	at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:500)
	at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:102)
	at net.schmizz.sshj.transport.Decoder.received(Decoder.java:170)
	at net.schmizz.sshj.transport.Reader.run(Reader.java:59)

Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.TransportImpl notifyDisconnect
INFO: Disconnected - PROTOCOL_ERROR
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.KeyExchanger notifyError
FINE: Got notified of net.schmizz.sshj.connection.ConnectionException: [PROTOCOL_ERROR] Received CHANNEL_SUCCESS on unknown channel #0
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.AbstractService notifyError
FINE: Notified of net.schmizz.sshj.connection.ConnectionException: [PROTOCOL_ERROR] Received CHANNEL_SUCCESS on unknown channel #0
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.TransportImpl setService
FINE: Setting active service to null-service
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.TransportImpl sendDisconnect
FINE: Sending SSH_MSG_DISCONNECT: reason=[PROTOCOL_ERROR], msg=[Received CHANNEL_SUCCESS on unknown channel #0]
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.Encoder encode
FINEST: Encoding packet #8: …
Aug 11, 2017 2:05:21 PM net.schmizz.concurrent.Promise deliver
FINE: Setting <<transport close>> to `SOME`
Aug 11, 2017 2:05:21 PM net.schmizz.sshj.transport.Reader run

(and then, if I let it sit, it just dies of a timeout after a while)

Reply all

Reply to author

Forward

0 new messages