KS-Soft. Network Management Solutions
 FAQFAQ   SearchSearch   MemberlistMemberlist   UsergroupsUsergroups   RegisterRegister    ProfileProfile    Log inLog in 

SSH tests do not work on Ubuntu 16.04
Goto page 1, 2  Next
 
Post new topic   Reply to topic    KS-Soft Forum Index -> Configuration, Maintenance, Troubleshooting
View previous topic :: View next topic  
Author Message
v.yesakov



Joined: 29 Jun 2016
Posts: 13

PostPosted: Wed Jun 29, 2016 12:32 pm    Post subject: SSH tests do not work on Ubuntu 16.04 Reply with quote

Hi,

We use HM 9.84 now.
Recently we started testing on Ubuntu 16.04 and it seems to be a problem with SSH tests.

After we solved key exchange and incompatible cipher issues we've got weird error message on HM:

"Protocol error. server refuses open channel"
Please help us to resolve this issue.

This is server side log from SSHD.

[code]
Jun 29 14:27:38 mcloud-91-30 sshd[29365]: debug3: fd 4 is not O_NONBLOCK
Jun 29 14:27:38 mcloud-91-30 sshd[29365]: debug1: Forked child 29368.
Jun 29 14:27:38 mcloud-91-30 sshd[29365]: debug3: send_rexec_state: entering fd = 7 config len 852
Jun 29 14:27:38 mcloud-91-30 sshd[29365]: debug3: ssh_msg_send: type 0
Jun 29 14:27:38 mcloud-91-30 sshd[29365]: debug3: send_rexec_state: done
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: oom_adjust_restore
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: Set /proc/self/oom_score_adj to 0
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: rexec start in 4 out 4 newsock 4 pipe 6 sock 7
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: inetd sockets after dupping: 3, 3
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: Connection from *.*.*.2 port 1165 on *.*.*.30 port 22
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: Client protocol version 2.0; client software version KS_SSH
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: no match: KS_SSH
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: Enabling compatibility mode for protocol 2.0
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: Local version string SSH-2.0-OpenSSH_7.2p2 Ubuntu-4ubuntu1
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: fd 3 setting O_NONBLOCK
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: Network child is on pid 29369
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: preauth child monitor started
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: privsep user:group 110:65534 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: permanently_set_uid: 110/65534 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: list_hostkey_types: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ssh-dss,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: send packet: type 20 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: receive packet: type 20 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: SSH2_MSG_KEXINIT received [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: local server KEXINIT proposal [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: KEX algorithms: curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: host key algorithms: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ssh-dss,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: compression ctos: none,zlib@openssh.com [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: compression stoc: none,zlib@openssh.com [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: languages ctos: [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: languages stoc: [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: first_kex_follows 0 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: reserved 0 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: peer client KEXINIT proposal [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: KEX algorithms: diffie-hellman-group1-sha1 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: host key algorithms: ssh-dss [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: ciphers ctos: aes128-cbc [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: ciphers stoc: aes128-cbc [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: MACs ctos: hmac-sha1 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: MACs stoc: hmac-sha1 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: compression ctos: none [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: compression stoc: none [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: languages ctos: en [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: languages stoc: en [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: first_kex_follows 0 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: reserved 0 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: kex: algorithm: diffie-hellman-group1-sha1 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: kex: host key algorithm: ssh-dss [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: kex: client->server cipher: aes128-cbc MAC: hmac-sha1 compression: none [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: kex: server->client cipher: aes128-cbc MAC: hmac-sha1 compression: none [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: bits set: 505/1024 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: expecting SSH2_MSG_KEXDH_INIT [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: receive packet: type 30 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: bits set: 489/1024 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_key_sign entering [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_send entering: type 6 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_key_sign: waiting for MONITOR_ANS_SIGN [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_receive_expect entering: type 7 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_receive entering [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_receive entering
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: monitor_read: checking request 6
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_answer_sign
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_answer_sign: hostkey proof signature 0x55fe8266fae0(55)
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_send entering: type 7
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: monitor_read: 6 used once, disabling now
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: send packet: type 31 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: send packet: type 21 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: set_newkeys: mode 1 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: rekey after 4294967296 blocks [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: receive packet: type 21 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: set_newkeys: mode 0 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: rekey after 4294967296 blocks [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: KEX done [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: receive packet: type 5 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: send packet: type 6 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: receive packet: type 50 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: userauth-request for user alliance service ssh-connection method none [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: attempt 0 failures 0 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_getpwnamallow entering [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_send entering: type 8 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_receive_expect entering: type 9 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_receive entering [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_receive entering
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: monitor_read: checking request 8
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_answer_pwnamallow
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: parse_server_config: config reprocess config len 852
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_send entering: type 9
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: monitor_read: 8 used once, disabling now
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: input_userauth_request: setting up authctxt for alliance [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_start_pam entering [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_send entering: type 100 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_inform_authserv entering [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_send entering: type 4 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: input_userauth_request: try method none [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: userauth_finish: failure partial=0 next methods="publickey,password" [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: send packet: type 51 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_receive entering
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: monitor_read: checking request 100
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: PAM: initializing for "alliance"
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: PAM: setting PAM_RHOST to "*.*.*.2"
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: PAM: setting PAM_TTY to "ssh"
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: monitor_read: 100 used once, disabling now
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_receive entering
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: monitor_read: checking request 4
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_answer_authserv: service=ssh-connection, style=, role=
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: monitor_read: 4 used once, disabling now
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: receive packet: type 50 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: userauth-request for user alliance service ssh-connection method password [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: attempt 1 failures 0 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug2: input_userauth_request: try method password [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_auth_password entering [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_send entering: type 12 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_receive_expect entering: type 13 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_receive entering [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_receive entering
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: monitor_read: checking request 12
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: PAM: sshpam_passwd_conv called with 1 messages
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: PAM: password authentication accepted for alliance
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_answer_authpassword: sending result 1
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_send entering: type 13
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_receive_expect entering: type 102
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_receive entering
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: do_pam_account: called
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: PAM: do_pam_account pam_acct_mgmt = 0 (Success)
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_send entering: type 103
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: Accepted password for alliance from *.*.*.2 port 1165 ssh2
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: monitor_child_preauth: alliance has been authenticated by privileged process
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_get_keystate: Waiting for new keys
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_receive_expect entering: type 26
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_receive entering
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_get_keystate: GOT new keys
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_auth_password: user authenticated [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_do_pam_account entering [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_send entering: type 102 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_receive_expect entering: type 103 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_receive entering [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_do_pam_account returning 1 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: send packet: type 52 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_send entering: type 26 [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_send_keystate: Finished sending state [preauth]
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: monitor_read_log: child log fd closed
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_share_sync: Share sync
Jun 29 14:27:38 mcloud-91-30 systemd-logind[1043]: New session 185 of user alliance.
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_share_sync: Share sync end
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: PAM: establishing credentials
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: PAM: opening session
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: pam_unix(sshd:session): session opened for user alliance by (uid=0)
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: PAM: sshpam_store_conv called with 1 messages
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: User child is on pid 29398
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug1: SELinux support disabled
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug1: PAM: establishing credentials
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug1: permanently_set_uid: 1000/1000
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug3: monitor_apply_keystate: packet_set_state
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug2: set_newkeys: mode 0
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug1: rekey after 4294967296 blocks
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug2: set_newkeys: mode 1
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug1: rekey after 4294967296 blocks
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug1: ssh_packet_set_postauth: called
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug3: ssh_packet_set_state: done
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug3: notify_hostkeys: key 0: ssh-rsa SHA256:3sboIsNGjltcKlFFkL3G6TmS15wc55Fx44JxsOGeK9Y
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug3: notify_hostkeys: key 1: ssh-dss SHA256:rb5y9dvvm40fcj6AgHn3j3zkmBr8E9LQypM7ekQ/kkI
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug3: notify_hostkeys: key 2: ecdsa-sha2-nistp256 SHA256:bTesPfDUXQI20tDhcCzw/st2HdKFEv9Z1/BqNYaT1/o
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug3: notify_hostkeys: key 3: ssh-ed25519 SHA256:/5kVnTH4KvmkQQ7GdbRKni9J8YLb/OK262ccQpkRVVo
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug3: notify_hostkeys: sent 4 hostkeys
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug3: send packet: type 80
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug1: Entering interactive session for SSH2.
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug2: fd 5 setting O_NONBLOCK
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug2: fd 6 setting O_NONBLOCK
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug1: server_init_dispatch_20
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug3: receive packet: type 90
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug1: server_input_channel_open: ctype session rchan 0 win 16384 max 16384
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug1: input_session_request
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug1: channel 0: new [server-session]
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug2: session_new: allocate (allocated 0 max 10)
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug3: session_unused: session id 0 unused
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug1: session_new: session 0
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug1: session_open: channel 0
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug1: session_open: session 0: link with channel 0
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug1: server_input_channel_open: confirm session
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug3: send packet: type 91
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug3: receive packet: type 1
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: Received disconnect from *.*.*.2 port 1165:11: end
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: Disconnected from *.*.*.2 port 1165
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug1: do_cleanup
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug3: PAM: sshpam_thread_cleanup entering
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: mm_request_receive entering
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: do_cleanup
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: PAM: cleanup
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: PAM: closing session
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: pam_unix(sshd:session): session closed for user alliance
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: PAM: deleting credentials
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug3: PAM: sshpam_thread_cleanup entering
Jun 29 14:27:38 mcloud-91-30 sshd[29368]: debug1: audit_event: unhandled event 12
Jun 29 14:27:38 mcloud-91-30 systemd-logind[1043]: Removed session 185.
[/code]
Back to top
View user's profile Send private message
KS-Soft



Joined: 03 Apr 2002
Posts: 11761
Location: USA

PostPosted: Wed Jun 29, 2016 2:37 pm    Post subject: Reply with quote

I think you need HostMonitor version 10.14 or higher.
Please check your license before update using menu Help->Update check

Regards
Alex
Back to top
View user's profile Send private message Send e-mail Visit poster's website
v.yesakov



Joined: 29 Jun 2016
Posts: 13

PostPosted: Wed Jun 29, 2016 3:10 pm    Post subject: Reply with quote

KS-Soft wrote:
I think you need HostMonitor version 10.14 or higher.
Please check your license before update using menu Help->Update check

Regards
Alex


Is there "debug log" in host monitor ? Is there a way to troubleshoot what exact problem there is with connection to new SSHD ?

PS: I did "update check" and it does not allow upgrade to new version. I'll bring this issue up to management, but right now we need some sort of a solution or a workaround.
Back to top
View user's profile Send private message
KS-Soft



Joined: 03 Apr 2002
Posts: 11761
Location: USA

PostPosted: Wed Jun 29, 2016 3:30 pm    Post subject: Reply with quote

I think this is the problem
Quote:
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug3: notify_hostkeys: sent 4 hostkeys
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug3: send packet: type 80
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug1: Entering interactive session for SSH2.

if you can disable this option (do not send all host keys after authentication), this may help

Regards
Alex
Back to top
View user's profile Send private message Send e-mail Visit poster's website
v.yesakov



Joined: 29 Jun 2016
Posts: 13

PostPosted: Wed Jun 29, 2016 4:41 pm    Post subject: Reply with quote

KS-Soft wrote:
I think this is the problem
Quote:
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug3: notify_hostkeys: sent 4 hostkeys
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug3: send packet: type 80
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug1: Entering interactive session for SSH2.

if you can disable this option (do not send all host keys after authentication), this may help
Regards
Alex


Thank you, Alex. I will see tomorrow if this can be disabled.

Just for the record: this is normal session with Ubuntu 12.04.5 server with the same level of debug output.

Code:

Jun 29 18:33:42 host-name-30 sshd[4765]: Connection from 888.888.888.2 port 2877
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: Client protocol version 2.0; client software version KS_SSH
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: no match: KS_SSH
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: Enabling compatibility mode for protocol 2.0
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: Local version string SSH-2.0-OpenSSH_5.9p1 Debian-5ubuntu1.9
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: fd 3 setting O_NONBLOCK
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: Network child is on pid 4766
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: preauth child monitor started
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: privsep user:group 105:65534 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: permanently_set_uid: 105/65534 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: list_hostkey_types: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: SSH2_MSG_KEXINIT received [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-256-96,hmac-sha2-512,hmac-sha2-512-96,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-256-96,hmac-sha2-512,hmac-sha2-512-96,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: none,zlib@openssh.com [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: none,zlib@openssh.com [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit:  [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit:  [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: first_kex_follows 0  [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: reserved 0  [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: diffie-hellman-group1-sha1 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: ssh-dss [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: aes128-cbc [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: aes128-cbc [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: hmac-sha1 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: hmac-sha1 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: none [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: none [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: en [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: en [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: first_kex_follows 0  [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_parse_kexinit: reserved 0  [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: mac_setup: found hmac-sha1 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: kex: client->server aes128-cbc hmac-sha1 none [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: mac_setup: found hmac-sha1 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: kex: server->client aes128-cbc hmac-sha1 none [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: dh_gen_key: priv key bits set: 159/320 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: bits set: 526/1024 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: expecting SSH2_MSG_KEXDH_INIT [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: bits set: 517/1024 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_key_sign entering [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_send entering: type 5 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_key_sign: waiting for MONITOR_ANS_SIGN [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_receive_expect entering: type 6 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_receive entering [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_receive entering
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: monitor_read: checking request 5
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_answer_sign
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_answer_sign: signature 0x7f26070d3790(55)
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_send entering: type 6
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: monitor_read: 5 used once, disabling now
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: kex_derive_keys [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: set_newkeys: mode 1 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: set_newkeys: mode 0 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: KEX done [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: userauth-request for user alliance service ssh-connection method none [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: attempt 0 failures 0 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_getpwnamallow entering [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_send entering: type 7 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_receive_expect entering: type 8 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_receive entering [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_receive entering
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: monitor_read: checking request 7
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_answer_pwnamallow
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: Trying to reverse map address 888.888.888.2.
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: parse_server_config: config reprocess config len 686
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_send entering: type 8
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: monitor_read: 7 used once, disabling now
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: input_userauth_request: setting up authctxt for alliance [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_start_pam entering [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_send entering: type 50 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_inform_authserv entering [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_send entering: type 3 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: input_userauth_request: try method none [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_receive entering
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: monitor_read: checking request 50
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: PAM: initializing for "alliance"
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: PAM: setting PAM_RHOST to "hm1.connectionnetworks.net"
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: PAM: setting PAM_TTY to "ssh"
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: monitor_read: 50 used once, disabling now
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_receive entering
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: monitor_read: checking request 3
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_answer_authserv: service=ssh-connection, style=, role=
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: monitor_read: 3 used once, disabling now
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: userauth-request for user alliance service ssh-connection method password [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: attempt 1 failures 0 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: input_userauth_request: try method password [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_auth_password entering [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_send entering: type 11 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_receive_expect entering: type 12 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_receive entering [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_receive entering
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: monitor_read: checking request 11
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: PAM: sshpam_passwd_conv called with 1 messages
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: PAM: password authentication accepted for alliance
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_answer_authpassword: sending result 1
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_send entering: type 12
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_receive_expect entering: type 51
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_receive entering
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: do_pam_account: called
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: PAM: do_pam_account pam_acct_mgmt = 0 (Success)
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_send entering: type 52
Jun 29 18:33:42 host-name-30 sshd[4765]: Accepted password for alliance from 888.888.888.2 port 2877 ssh2
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_auth_password: user authenticated [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_do_pam_account entering [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_send entering: type 51 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_receive_expect entering: type 52 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_receive entering [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_do_pam_account returning 1 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_send_keystate: Sending new keys: 0x7f26070df480 0x7f26070df2e0 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_newkeys_to_blob: converting 0x7f26070df480 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_newkeys_to_blob: converting 0x7f26070df2e0 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_send_keystate: New keys have been sent [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_send_keystate: Sending compression state [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_send entering: type 25 [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_send_keystate: Finished sending state [preauth]
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: monitor_read_log: child log fd closed
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: monitor_child_preauth: alliance has been authenticated by privileged process
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_get_keystate: Waiting for new keys
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_receive_expect entering: type 25
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_receive entering
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_newkeys_from_blob: 0x7f26070e5450(127)
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: mac_setup: found hmac-sha1
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_get_keystate: Waiting for second key
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_newkeys_from_blob: 0x7f26070e5450(127)
Jun 29 18:33:42 host-name-30 sshd[4765]: debug2: mac_setup: found hmac-sha1
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_get_keystate: Getting compression state
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_get_keystate: Getting Network I/O buffers
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_share_sync: Share sync
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_share_sync: Share sync end
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: PAM: establishing credentials
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: PAM: opening session
Jun 29 18:33:42 host-name-30 sshd[4765]: pam_unix(sshd:session): session opened for user alliance by (uid=0)
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: PAM: sshpam_store_conv called with 1 messages
Jun 29 18:33:42 host-name-30 sshd[4765]: User child is on pid 4904
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: SELinux support disabled
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: PAM: establishing credentials
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: permanently_set_uid: 1000/1000
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: set_newkeys: mode 0
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: set_newkeys: mode 1
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: Entering interactive session for SSH2.
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: fd 5 setting O_NONBLOCK
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: fd 6 setting O_NONBLOCK
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: server_init_dispatch_20
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: server_input_channel_open: ctype session rchan 0 win 16384 max 16384
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: input_session_request
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: channel 0: new [server-session]
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: session_new: allocate (allocated 0 max 10)
Jun 29 18:33:42 host-name-30 sshd[4904]: debug3: session_unused: session id 0 unused
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: session_new: session 0
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: session_open: channel 0
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: session_open: session 0: link with channel 0
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: server_input_channel_open: confirm session
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: server_input_channel_req: channel 0 request exec reply 1
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: session_by_channel: session 0 channel 0
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: session_input_channel_req: session 0 req exec
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: fd 3 setting TCP_NODELAY
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: fd 9 setting O_NONBLOCK
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: fd 8 setting O_NONBLOCK
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: fd 11 setting O_NONBLOCK
Jun 29 18:33:42 host-name-30 sshd[4905]: debug3: Copy environment: PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games
Jun 29 18:33:42 host-name-30 sshd[4905]: debug3: Copy environment: LANG=en_US.UTF-8
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: notify_done: reading
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: Received SIGCHLD.
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: session_by_pid: pid 4905
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: session_exit_message: session 0 channel 0 pid 4905
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: channel 0: request exit-status confirm 0
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: session_exit_message: release channel 0
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: channel 0: write failed
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: channel 0: close_write
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: channel 0: send eow
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: channel 0: output open -> closed
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: channel 0: read<=0 rfd 9 len 0
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: channel 0: read failed
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: channel 0: close_read
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: channel 0: input open -> drain
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: channel 0: read 0 from efd 11
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: channel 0: closing read-efd 11
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: channel 0: ibuf empty
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: channel 0: send eof
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: channel 0: input drain -> closed
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: channel 0: send close
Jun 29 18:33:42 host-name-30 sshd[4904]: debug3: channel 0: will not send data after close
Jun 29 18:33:42 host-name-30 sshd[4904]: debug2: channel 0: rcvd adjust 34
Jun 29 18:33:42 host-name-30 sshd[4904]: debug3: channel 0: will not send data after close
Jun 29 18:33:42 host-name-30 sshd[4904]: Received disconnect from 888.888.888.2: 11: session close
Jun 29 18:33:42 host-name-30 sshd[4904]: debug1: do_cleanup
Jun 29 18:33:42 host-name-30 sshd[4904]: debug3: PAM: sshpam_thread_cleanup entering
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: mm_request_receive entering
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: do_cleanup
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: PAM: cleanup
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: PAM: closing session
Jun 29 18:33:42 host-name-30 sshd[4765]: pam_unix(sshd:session): session closed for user alliance
Jun 29 18:33:42 host-name-30 sshd[4765]: debug1: PAM: deleting credentials
Jun 29 18:33:42 host-name-30 sshd[4765]: debug3: PAM: sshpam_thread_cleanup entering
Back to top
View user's profile Send private message
v.yesakov



Joined: 29 Jun 2016
Posts: 13

PostPosted: Thu Jun 30, 2016 10:41 am    Post subject: Reply with quote

KS-Soft wrote:
I think this is the problem
Quote:
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug3: notify_hostkeys: sent 4 hostkeys
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug3: send packet: type 80
Jun 29 14:27:38 mcloud-91-30 sshd[29398]: debug1: Entering interactive session for SSH2.

if you can disable this option (do not send all host keys after authentication), this may help
Regards
Alex


It did not help. I've got exactly same error "server refuses open channel"

Somewhere on the forum I've seen people used KSSSHCMD utility. Can this be used to troubleshoot this issue ? Does it have debug log output of some sort ?

http://www.ks-soft.net/cgi-bin/phpBB/viewtopic.php?p=34189#34189

Code:

Jun 30 12:33:14 888.888.888.25 sshd[19358]: User child is on pid 19389
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug1: SELinux support disabled
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug1: PAM: establishing credentials
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug1: permanently_set_uid: 1000/1000
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug3: monitor_apply_keystate: packet_set_state
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug2: set_newkeys: mode 0
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug1: rekey after 4294967296 blocks
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug2: set_newkeys: mode 1
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug1: rekey after 4294967296 blocks
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug1: ssh_packet_set_postauth: called
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug3: ssh_packet_set_state: done
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug3: notify_hostkeys: key 0: ssh-dss SHA256:1bYipixgUwysTy9gBiXDRIuffa/jS6tbmuuYHPHeUiY
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug3: notify_hostkeys: sent 1 hostkeys
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug3: send packet: type 80
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug1: Entering interactive session for SSH2.
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug2: fd 5 setting O_NONBLOCK
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug2: fd 6 setting O_NONBLOCK
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug1: server_init_dispatch_20
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug3: receive packet: type 90
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug1: server_input_channel_open: ctype session rchan 0 win 16384 max 16384
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug1: input_session_request
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug1: channel 0: new [server-session]
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug2: session_new: allocate (allocated 0 max 10)
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug3: session_unused: session id 0 unused
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug1: session_new: session 0
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug1: session_open: channel 0
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug1: session_open: session 0: link with channel 0
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug1: server_input_channel_open: confirm session
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug3: send packet: type 91
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug3: receive packet: type 1
Jun 30 12:33:14 888.888.888.25 sshd[19389]: Received disconnect from 888.888.888.55 port 1237:11: end
Jun 30 12:33:14 888.888.888.25 sshd[19389]: Disconnected from 888.888.888.55 port 1237
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug1: do_cleanup
Jun 30 12:33:14 888.888.888.25 sshd[19389]: debug3: PAM: sshpam_thread_cleanup entering
Jun 30 12:33:14 888.888.888.25 sshd[19358]: debug3: mm_request_receive entering
Jun 30 12:33:14 888.888.888.25 sshd[19358]: debug1: do_cleanup
Jun 30 12:33:14 888.888.888.25 sshd[19358]: debug1: PAM: cleanup
Jun 30 12:33:14 888.888.888.25 sshd[19358]: debug1: PAM: closing session
Jun 30 12:33:14 888.888.888.25 sshd[19358]: pam_unix(sshd:session): session closed for user administrator
Jun 30 12:33:14 888.888.888.25 sshd[19358]: debug1: PAM: deleting credentials
Jun 30 12:33:14 888.888.888.25 sshd[19358]: debug3: PAM: sshpam_thread_cleanup entering
Jun 30 12:33:14 888.888.888.25 sshd[19358]: debug1: audit_event: unhandled event 12
Jun 30 12:33:14 888.888.888.25 systemd-logind[1227]: Removed session 816.
Back to top
View user's profile Send private message
KS-Soft



Joined: 03 Apr 2002
Posts: 11761
Location: USA

PostPosted: Thu Jun 30, 2016 11:04 am    Post subject: Reply with quote

No, it will not provide log that can help.
Have you tried latest HostMonitor?
(please install it on different system or backup your config files - new version may convert your HML and LST files)

Regards
Alex
Back to top
View user's profile Send private message Send e-mail Visit poster's website
v.yesakov



Joined: 29 Jun 2016
Posts: 13

PostPosted: Thu Jun 30, 2016 11:57 am    Post subject: Reply with quote

KS-Soft wrote:
No, it will not provide log that can help.
Have you tried latest HostMonitor?
(please install it on different system or backup your config files - new version may convert your HML and LST files)

Regards
Alex


Version 10.20 worked with minimal SSHD configuration change.
At first I've got error: "cannot agree hostkey"

Code:

sshd[24351]: debug3: list_hostkey_types: ssh-dss key not permitted by HostkeyAlgorithms [preauth]
sshd[24351]: debug1: list_hostkey_types: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]


I had to add this to server config and then it worked:

Code:

HostkeyAlgorithms=+ssh-dss


Can you add support for one of the default methods to the next version, so there will be no changes to server config ?

Thank you.
Back to top
View user's profile Send private message
KS-Soft



Joined: 03 Apr 2002
Posts: 11761
Location: USA

PostPosted: Thu Jun 30, 2016 12:59 pm    Post subject: Reply with quote

Yes, we plan to add ssh-rsa

Regards
Alex
Back to top
View user's profile Send private message Send e-mail Visit poster's website
menno



Joined: 21 May 2010
Posts: 137

PostPosted: Thu Jul 28, 2016 1:59 pm    Post subject: Reply with quote

Quote:
PostPosted: Thu Jun 30, 2016 6:59 pm Post subject: Reply with quote
Yes, we plan to add ssh-rsa

Regards
Alex


Hi Alex
can you please tell us when ?
we also have issues with the ssh test methods

can you also tell me where to find the tool : KSSSHCMD.EXE

many thanks in advance
Menno
Back to top
View user's profile Send private message
KS-Soft



Joined: 03 Apr 2002
Posts: 11761
Location: USA

PostPosted: Thu Jul 28, 2016 2:26 pm    Post subject: Reply with quote

>can you please tell us when ?
in version 10.30

>KSSSHCMD.EXE
www.ks-soft.net/download/utils/kssshcmd.zip

Regards
Alex
Back to top
View user's profile Send private message Send e-mail Visit poster's website
menno



Joined: 21 May 2010
Posts: 137

PostPosted: Fri Jul 29, 2016 1:13 am    Post subject: Reply with quote

Quote:
PostPosted: Thu Jul 28, 2016 8:26 pm Post subject:
>can you please tell us when ?
in version 10.30


Can you tell me the ETA of version 10.30 ???
Back to top
View user's profile Send private message
KS-Soft



Joined: 03 Apr 2002
Posts: 11761
Location: USA

PostPosted: Fri Jul 29, 2016 8:04 am    Post subject: Reply with quote

I hope August 2016

Regards
Alex
Back to top
View user's profile Send private message Send e-mail Visit poster's website
KS-Soft



Joined: 03 Apr 2002
Posts: 11761
Location: USA

PostPosted: Mon Aug 08, 2016 3:00 pm    Post subject: Reply with quote

New version available
http://www.ks-soft.net/hostmon.eng/news.htm

SSH test supports RSA keys (ssh-rsa). New code considered as experimental and disabled by default. You may enable it individually for HostMonitor or some RMA agents - add SSHMode=1 line into [Misc] section of hostmon.ini file and restart HostMonitor (modify rma.ini file instead of hostmon.ini if you want to enable this option for Remote Monitoring Agent)

Regards
Alex
Back to top
View user's profile Send private message Send e-mail Visit poster's website
v.yesakov



Joined: 29 Jun 2016
Posts: 13

PostPosted: Thu May 04, 2017 4:07 pm    Post subject: Reply with quote

KS-Soft wrote:
New version available

SSH test supports RSA keys (ssh-rsa).
add SSHMode=1 line into [Misc] section


Finally I've got my hands on new version and have done some tests.

What's working:
SSH tests now able to login and run commands on Ubuntu 16.04 just fine.

What's not working:
Background processes do not survive. Basically HM logs into system, checks if certain process is running and if not starts new instance using
Code:

nohup /path/to/binary -parameters &

than logs out. This was working perfectly with "old" HM and Ubuntu 12.04.

For some reason when I go with new Ubuntu and new HM/RMA in "SSHMode=1", backgroung process gets killed when HM logs out of system. Exactly same process stays up when I use putty, login manually and then logout.

What is the actual difference in SSHMode=1 compared to "old" style ? How can I run background processes with new version ?

V.
Back to top
View user's profile Send private message
Display posts from previous:   
Post new topic   Reply to topic    KS-Soft Forum Index -> Configuration, Maintenance, Troubleshooting All times are GMT - 6 Hours
Goto page 1, 2  Next
Page 1 of 2

 
Jump to:  
You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum


Powered by phpBB © 2001, 2005 phpBB Group

KS-Soft Forum Index