sshj-ssh giving "Failed: Unknown: Null" in Rundeck 4.11

[Russ Robinson]

After upgrading from 4.7 to 4.11 Rundeck opensource; our jobs running remote commands to Linux target nodes returns "Failed: Unknown: null" .  Our test job is just issuing remote command "date" to the target nodes in the workflow.

Our Rundeck server is running on Oracle Linux 7.  The project settings are:

project.always-set-pty=true

project.keep-alive-interval=5

project.plugin.FileCopier.ssh-copier.authentication=password

project.plugin.NodeExecutor.ssh-exec.authentication=password

project.ssh-authentication=password
project.ssh-command-timeout=0
project.ssh-connect-timeout=0
project.ssh-keypath=/var/lib/rundeck/.ssh/id_rsa
project.ssh.user=${option.username}
project.sudo-command-enabled=true

service.FileCopier.default.provider=sshj-scp
service.NodeExecutor.default.provider=sshj-ssh

Node entry in inventory contains:

  {
    "nodename": "node1.mytest.com",
    "type": "Node",
    "hostname": "node1.mytest.com",
    "tags": [

    ],
    "os": "Linux",
    "os_name": "Linux",
    "osFamily": "unix",
    "sudo-command-enabled": "true",
    "sudo-password-option": "option.sshPassword",
    "username": "${option.username}",
    "password-option": "option.sshPassword",
  },

Here is the job log in debug mode:

[workflow] beginExecuteNodeStep(node1.mytest.com): NodeDispatch: CommandItem{label='Issue Date Command', command=[1 words]}

[sshj-ssh] hostname: node1.mytest.com

[sshj-ssh] port: null

[sshj-ssh] username: rurobin

[sshj-ssh] init SSHJDefaultConfig

[sshj-ssh] setting timeouts

[sshj-ssh] getConnectTimeout timeout: 0

[sshj-ssh] getTimeout timeout: 0

[sshj-ssh] keepAliveInterval: 5

[sshj-ssh] retry: true

[sshj-ssh] retryCount: 3

[sshj-ssh] adding loadKnownHosts

[sshj-ssh] open connection

[net.schmizz.sshj.transport.TransportImpl] Client identity string: SSH-2.0-SSHJ_0.35.0

[net.schmizz.sshj.transport.TransportImpl] Server identity string: SSH-2.0-OpenSSH_7.4

[net.schmizz.sshj.SSHClient] Initiating Key Exchange for new connection

[net.schmizz.concurrent.Promise] Setting <<kex done>> to `null`

[net.schmizz.sshj.transport.KeyExchanger] Sending SSH_MSG_KEXINIT

[net.schmizz.concurrent.Promise] Setting <<kexinit sent>> to `SOME`

[net.schmizz.sshj.transport.KeyExchanger] Received SSH_MSG_KEXINIT

[net.schmizz.concurrent.Promise] Awaiting <<kex done>>

[net.schmizz.sshj.transport.KeyExchanger] Negotiated algorithms: [ kex=curve25519-sha256; sig=rsa-sha2-512; c2sCipher=aes128-ctr; s2cCipher=aes128-ctr; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1; c2sComp=none; s2cComp=none; ]

[net.schmizz.sshj.transport.KeyExchanger] Received kex followup data

[net.schmizz.sshj.transport.KeyExchanger] Trying to verify host key with net.schmizz.sshj.transport.verification.PromiscuousVerifier@5f57b7ff

[net.schmizz.sshj.transport.KeyExchanger] Sending SSH_MSG_NEWKEYS

[net.schmizz.sshj.transport.KeyExchanger] Received SSH_MSG_NEWKEYS

[net.schmizz.concurrent.Promise] Setting <<kexinit sent>> to `null`

[net.schmizz.concurrent.Promise] Setting <<kex done>> to `SOME`

[net.schmizz.sshj.transport.TransportImpl] Received SSH_MSG_EXT_INFO

[net.schmizz.sshj.SSHClient] Key exchange took 0.016 seconds

[sshj-ssh] connection done

[net.schmizz.concurrent.Promise] Setting <<service accept>> to `null`

[net.schmizz.sshj.transport.TransportImpl] Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth

[net.schmizz.concurrent.Promise] Awaiting <<service accept>>

[net.schmizz.sshj.transport.TransportImpl] Setting active service to ssh-userauth

[net.schmizz.concurrent.Promise] Setting <<service accept>> to `SOME`

[net.schmizz.concurrent.Promise] Setting <<authenticated>> to `null`

[net.schmizz.sshj.userauth.UserAuthImpl] Trying `password` auth...

[net.schmizz.sshj.userauth.method.AuthPassword] Requesting password for [AccountResource] rur...@node1.mytest.com

[net.schmizz.concurrent.Promise] Awaiting <<authenticated>>

[net.schmizz.sshj.transport.TransportImpl] Setting active service to ssh-connection

[net.schmizz.concurrent.Promise] Setting <<authenticated>> to `true`

[net.schmizz.sshj.userauth.UserAuthImpl] `password` auth successful

[sshj-ssh] authentication set

[sshj-ssh] connection done

[sshj-ssh] open connection

[net.schmizz.sshj.transport.TransportImpl] Client identity string: SSH-2.0-SSHJ_0.35.0

[net.schmizz.sshj.transport.TransportImpl] Server identity string: SSH-2.0-OpenSSH_7.4

SSH command execution error: Unknown: null

[net.schmizz.sshj.transport.TransportImpl] Disconnected - BY_APPLICATION

[net.schmizz.sshj.connection.ConnectionImpl] Notified of net.schmizz.sshj.transport.TransportException: [BY_APPLICATION] Disconnected

[net.schmizz.sshj.transport.TransportImpl] Sending SSH_MSG_DISCONNECT: reason=[BY_APPLICATION], msg=[]

[net.schmizz.concurrent.Promise] Setting <<transport close>> to `SOME`

Failed: Unknown: null

[workflow] finishExecuteNodeStep(node1.mytest.com): NodeDispatch: Unknown: null

[net.schmizz.sshj.transport.Reader] Stopping

[rac...@rundeck.com]

Hi Russ,

Could you check the SSHJ plugin version? The latest version is 0.1.6.

Regards.

[Russ Robinson]

Yes - In /var/lib/rundeck/libext is: sshj-plugin-v0.1.6.jar

[rac...@rundeck.com]

Hi Russ,

Could you check the project model source and check that SSHJ is selected?

Checking your config, those lines:

project.ssh-command-timeout=0
project.ssh-connect-timeout=0

Corresponds to SSH default node executor.

I created from scratch a SSHJ Job Level authentication project and contains this config:

#Thu Mar 30 13:50:54 CLST 2023
#edit below
project.disable.executions=false
project.disable.schedule=false
project.execution.history.cleanup.batch=500
project.execution.history.cleanup.enabled=false
project.execution.history.cleanup.retention.days=60
project.execution.history.cleanup.retention.minimum=50
project.execution.history.cleanup.schedule=0 0 0 1/1 * ? *
project.jobs.gui.groupExpandLevel=1
project.later.executions.disable.value=0
project.later.executions.disable=false
project.later.executions.enable.value=
project.later.executions.enable=false
project.later.schedule.disable.value=
project.later.schedule.disable=false
project.later.schedule.enable.value=
project.later.schedule.enable=false
project.name=ProjectSSH
project.nodeCache.enabled=true
project.nodeCache.firstLoadSynch=true
project.output.allowUnsanitized=false
project.retry-counter=3
project.ssh-authentication=privateKey
project.ssh-keypath=/home/reideianto/.ssh/id_rsa
resources.source.1.type=local
resources.source.2.config.file=/home/reideianto/Programs/rundeck/resources_node00.xml
resources.source.2.config.format=resourcexml
resources.source.2.config.requireFileExists=true
resources.source.2.config.writeable=true
resources.source.2.type=file
service.FileCopier.default.provider=sshj-scp
service.NodeExecutor.default.provider=sshj-ssh

I used the following model source file (XML):

<?xml version="1.0" encoding="UTF-8"?>
<project>
  <node name="node00" description="NODE 00" tags="" hostname="192.168.56.20" osArch="amd64" osFamily="unix" osName="Linux" osVersion="3.10.0-514.el7.x86_64" username="username" ssh-authentication="password" ssh-password-option="option.sshPassword"/>
</project>

And the following Job definition to test (YAML):

- defaultTab: nodes
  description: ''
  executionEnabled: true
  id: aae9815d-c76f-4a66-9012-61695f956204
  loglevel: INFO
  name: DateToRemoteNode
  nodeFilterEditable: false
  nodefilters:
    dispatch:
      excludePrecedence: true
      keepgoing: false
      rankOrder: ascending
      successOnEmptyNodeFilter: false
      threadcount: '2'
    filter: 'name: node00 '
  nodesSelectedByDefault: true
  options:
  - name: sshPassword
    secure: true
    storagePath: keys/node00passwd
  plugins:
    ExecutionLifecycle: null
  scheduleEnabled: true
  sequence:
    commands:
    - exec: date
    keepgoing: false
    strategy: node-first
  uuid: aae9815d-c76f-4a66-9012-61695f956204

So, I'm suspecting that your config contains SSH default node executor elements. Could you try with a new SSHJ project / Job against your remote node and compare the results?

Best regards!

[Russ Robinson]

So I went through all of my project settings related to ssh.  The plugin works fine after I remove the line:

project.retry-enable=true

Interesting....

[Russ Robinson]

Also fyi.....all of the project settings work fine with:

• Rundeck release 4.9 (sshj plugin version 0.1.3)
• Rundeck release 4.10.2 (sshj plugin version 0.1.4)

So it only seems to be with sshj plugin 0.1.6 with Rundeck release 4.11.

[Russ Robinson]

Any idea why project setting "project.retry-enable=true" would cause issues in 0.1.6 release of ssj plugin?

[rac...@rundeck.com]

Hi Russ,

I can't find that property in the Rundeck docs. What is the objective of that property? Maybe I'm missing something.

Regards.

[Russ Robinson]

If I go into "Installed Plugins" and select the SSHJ-SSH plugin's information, it contains:

• Enable retry on fail?

  Enable a connection retry when the connection fails

  Configure Project:project.retry-enable=false

  Configure Framework:framework.retry-enable=false

  Default value:false

[rac...@rundeck.com]

Hi Russ,

I reproduced your issue, could you open a new issue here please?

Good catch.

Thanks!

[Russ Robinson]

Opened: https://github.com/rundeck-plugins/sshj-plugin/issues/14