sshj icon indicating copy to clipboard operation
sshj copied to clipboard

Published 20 hours ago • verified publisher icon hierynomus

"Opening `session` channel failed: open failed" exception when running multiple commands in succession

Open Estraysian opened this issue 3 years ago • 6 comments
trafficstars

Found this bug while trying out 0.32.0 - 0.31.0 still works. Assuming reusing sshClient for multiple commands is a legitimate use case. Distilled it to the following code snippet that reliably reproduces the above exception:

            Session sshSession;
            Session.Command sshCommand;
            logger.log(Level.INFO,"calling exec in quick succession 1");
            // sshClient intialized further back.
            sshSession=sshClient.startSession();
            logger.log(Level.INFO,"started session 1, echoing");
            sshCommand = sshSession.exec("echo hello");
            logger.log(Level.INFO,"echoed, reading");
            // Intended for result logging and error handling.
            // Using net.schmizz.sshj.common.IOUtils.readFully behaves the same
            org.apache.commons.io.IOUtils.toString(sshCommand.getInputStream());
            logger.log(Level.INFO,"read, closing");
            sshSession.close();
            //Thread.sleep(1000); // Workaround.
            logger.log(Level.INFO,"calling exec in quick succession 2");
            sshSession=sshClient.startSession(); // failure
            logger.log(Level.INFO,"started session 2, echoing");
            sshSession.exec("echo hello");
            logger.log(Level.INFO,"echoed, closing");
            sshSession.close();

Short version:

            sshSession=sshClient.startSession();
            sshCommand = sshSession.exec("echo hello");
            org.apache.commons.io.IOUtils.toString(sshCommand.getInputStream());
            sshSession.close();
            
            sshSession=sshClient.startSession();
            sshSession.exec("echo hello");
            sshSession.close();

The log output (sanitized) will show the following:

calling exec in quick succession 1
started session 1, echoing
echoed, reading
read, closing
calling exec in quick succession 2
Exception: open failed
...
Caused by: Opening `session` channel failed: open failed 
	at net.schmizz.sshj.connection.channel.direct.AbstractDirectChannel.gotOpenFailure(AbstractDirectChannel.java:74)
	at net.schmizz.sshj.connection.channel.direct.AbstractDirectChannel.gotUnknown(AbstractDirectChannel.java:99)
	at net.schmizz.sshj.connection.channel.AbstractChannel.handle(AbstractChannel.java:204)
	at net.schmizz.sshj.connection.ConnectionImpl.handle(ConnectionImpl.java:130)
	at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:472)
	at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:113)
	at net.schmizz.sshj.transport.Decoder.received(Decoder.java:200)
	at net.schmizz.sshj.transport.Reader.run(Reader.java:60)

So the program will fail at starting session right after the previous one closed. I've confirmed that commenting out org.apache.commons.io.IOUtils.toString(sshCommand.getInputStream()); will fix the issue. I've also found that inserting a Thread.sleep(1000) after the session close fixes the issue.

I've checked the recent SSHJ changes and found commit eb09a16 (Send EOF on channel Close). I've reverted that commit, rebuilt SSHJ and re-run the test and it worked.

I don't understand the code well enough to tell you why the revert worked (it really shouldn't) or why the sleep worked (it really, REALLY shouldn't) or to suggest an actual solution, but the above should be reproducible. This one is going on the shelf with the "weird damn bugs".

Estraysian avatar Dec 08 '21 12:12 Estraysian

That is indeed a weird bug... Thanks for reporting this. We re-added the send EOF recently indeed, because I couldn't remember what was wrong with it. Now we seem to have a somewhat more reliable testcase, we should be able to debug it. What kind of server are you connecting to, and which version?

hierynomus avatar Dec 22 '21 16:12 hierynomus

The server is a host that is a part of a virtualization cluster based on CentOS Linux release 7.9.2009 (Core), using SSH2 - /etc/ssh/sshd_config states

# The default requires explicit activation of protocol 1
#Protocol 2

And this is what SSHD is telling me: OpenSSH_7.4p1, OpenSSL 1.0.2k-fips 26 Jan 2017

Sorry for being vague, I'm not sure my company would like it if I gave you too many specifics about our internal servers. Basically, it's a CentOS linux, I suspect other distros would behave the same, unless the bug is triggered by some RHEL specific.

Estraysian avatar Dec 23 '21 09:12 Estraysian

Thanks, I hope that's enough :) I'll try to build a test case to figure out what's going wrong.

hierynomus avatar Dec 23 '21 09:12 hierynomus

Excuse me, is there any solution for this fault? I also encountered it in the 0.32.0 version, but it does not always occur.

BadTrasher avatar Aug 25 '22 01:08 BadTrasher

Those "OpenFailed" errors are difficult to debug on the client side. Could you show us the server logs?

  • Add this option to /etc/ssh/sshd_config: 
    LogLevel DEBUG2
  • Restart the server, reproduce the bug.
  • Find the server logs. I don't know where they should appear in RH-based distros, but in Ubuntu the debugging logs would appear in /var/log/auth.log

vladimirlagunov avatar Aug 25 '22 08:08 vladimirlagunov

I encounter a failure like above, the code logic in my project is like this:

                final SSHClient ssh = new SSHClient();
                ssh.loadKnownHosts();
                ssh.connect("x.x.x.x");
                ssh.authPassword("ma_user", "ma_user");
                for (int i = 0; i < 100; i++) {
                    Session session = ssh.startSession();
                    Session.Command command = session.exec("echo hello");
                    IOUtils.readFully(command.getInputStream());
                    session.close();
                }

And the server logs:


Aug 26 09:53:54 szvp000207944 sshd[690]: debug1: Forked child 19648.
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: Set /proc/self/oom_score_adj to 0
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: inetd sockets after dupping: 3, 3
Aug 26 09:53:54 szvp000207944 sshd[19648]: Connection from x.x.x.x port 39382 on 100.109.227.77 port 22
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: Client protocol version 2.0; client software version SSHJ_0.32.0
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: no match: SSHJ_0.32.0
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: Local version string SSH-2.0-OpenSSH_7.6p1 Ubuntu-4ubuntu0.5
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: fd 3 setting O_NONBLOCK
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: Network child is on pid 19649
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: permanently_set_uid: 106/65534 [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: list_hostkey_types: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: SSH2_MSG_KEXINIT received [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: local server KEXINIT proposal [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: KEX algorithms: curve25519-sha256,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1 [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: host key algorithms: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: ciphers ctos: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: ciphers stoc: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: MACs ctos: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: MACs stoc: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: compression ctos: none,[email protected] [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: compression stoc: none,[email protected] [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: languages ctos:  [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: languages stoc:  [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: first_kex_follows 0  [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: reserved 0  [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: peer client KEXINIT proposal [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: KEX algorithms: curve25519-sha256,[email protected],diffie-hellman-group-exchange-sha256,ecdh-sha2-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1,diffie-hellman-group14-sha1,diffie-hellman-group14-sha256,diffie-hellman-group15-sha512,diffie-hellman-group16-sha512,diffie-hellman-group17-sha512,diffie-hellman-group18-sha512,[email protected],diffie-hellman-group15-sha256,diffie-hellman-group15-sha2
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: host key algorithms: ecdsa-sha2-nistp256,[email protected],ssh-ed25519,[email protected],ecdsa-sha2-nistp521,[email protected],ecdsa-sha2-nistp384,[email protected],rsa-sha2-512,rsa-sha2-256,[email protected],[email protected],ssh-rsa,ssh-dss [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: ciphers ctos: [email protected],aes128-cbc,aes128-ctr,aes192-cbc,aes192-ctr,aes256-cbc,aes256-ctr,[email protected],[email protected],blowfish-cbc,blowfish-ctr,cast128-cbc,cast128-ctr,idea-cbc,idea-ctr,serpent128-cbc,serpent128-ctr,serpent192-cbc,serpent192-ctr,serpent256-cbc,serpent256-ctr,3des-cbc,3des-ctr,twofish128-cbc,twofish128-ctr,twofish192-cbc,twofish192-ctr,twofish256-cbc,twofish256-ctr,twofish-cbc,arcfour,arcfour128,arcfour256 [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: ciphers stoc: [email protected],aes128-cbc,aes128-ctr,aes192-cbc,aes192-ctr,aes256-cbc,aes256-ctr,[email protected],[email protected],blowfish-cbc,blowfish-ctr,cast128-cbc,cast128-ctr,idea-cbc,idea-ctr,serpent128-cbc,serpent128-ctr,serpent192-cbc,serpent192-ctr,serpent256-cbc,serpent256-ctr,3des-cbc,3des-ctr,twofish128-cbc,twofish128-ctr,twofish192-cbc,twofish192-ctr,twofish256-cbc,twofish256-ctr,twofish-cbc,arcfour,arcfour128,arcfour256 [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: MACs ctos: hmac-sha1,[email protected],hmac-sha1-96,[email protected],hmac-md5,[email protected],hmac-md5-96,[email protected],hmac-sha2-256,[email protected],hmac-sha2-512,[email protected],hmac-ripemd160,[email protected],hmac-ripemd160-96,[email protected] [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: MACs stoc: hmac-sha1,[email protected],hmac-sha1-96,[email protected],hmac-md5,[email protected],hmac-md5-96,[email protected],hmac-sha2-256,[email protected],hmac-sha2-512,[email protected],hmac-ripemd160,[email protected],hmac-ripemd160-96,[email protected] [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: compression ctos: none [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: compression stoc: none [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: languages ctos:  [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: languages stoc:  [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: first_kex_follows 0  [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: reserved 0  [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: kex: algorithm: curve25519-sha256 [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: kex: host key algorithm: ecdsa-sha2-nistp256 [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: kex: client->server cipher: [email protected] MAC: <implicit> compression: none [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: kex: server->client cipher: [email protected] MAC: <implicit> compression: none [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: monitor_read: 6 used once, disabling now
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: set_newkeys: mode 1 [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: rekey after 134217728 blocks [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: set_newkeys: mode 0 [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: rekey after 134217728 blocks [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: KEX done [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: userauth-request for user ma_user service ssh-connection method password [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: attempt 0 failures 0 [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: parse_server_config: config reprocess config len 308
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: monitor_read: 8 used once, disabling now
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: input_userauth_request: setting up authctxt for ma_user [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: input_userauth_request: try method password [preauth]
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: PAM: initializing for "ma_user"
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: PAM: setting PAM_RHOST to "x.x.x.x"
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: PAM: setting PAM_TTY to "ssh"
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: monitor_read: 100 used once, disabling now
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: monitor_read: 4 used once, disabling now
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: PAM: password authentication accepted for ma_user
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: do_pam_account: called
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: do_pam_account: auth information in SSH_AUTH_INFO_0
Aug 26 09:53:54 szvp000207944 sshd[19648]: Accepted password for ma_user from x.x.x.x port 39382 ssh2
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: monitor_child_preauth: ma_user has been authenticated by privileged process
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: monitor_read_log: child log fd closed
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: PAM: establishing credentials
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug2: do_pam_session: auth information in SSH_AUTH_INFO_0
Aug 26 09:53:54 szvp000207944 sshd[19648]: pam_unix(sshd:session): session opened for user ma_user by (uid=0)
Aug 26 09:53:54 szvp000207944 systemd-logind[650]: New session 79 of user ma_user.
Aug 26 09:53:54 szvp000207944 sshd[19648]: User child is on pid 19674
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: SELinux support disabled
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: PAM: establishing credentials
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: permanently_set_uid: 1001/1001
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: set_newkeys: mode 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: rekey after 134217728 blocks
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: set_newkeys: mode 1
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: rekey after 134217728 blocks
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: ssh_packet_set_postauth: called
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: Entering interactive session for SSH2.
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: fd 4 setting O_NONBLOCK
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: fd 6 setting O_NONBLOCK
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: server_init_dispatch
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: server_input_channel_open: ctype session rchan 0 win 2097152 max 32768
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: input_session_request
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: channel 0: new [server-session]
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: session_new: allocate (allocated 0 max 100)
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_new: session 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_open: channel 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_open: session 0: link with channel 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: server_input_channel_open: confirm session
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: server_input_channel_req: channel 0 request exec reply 1
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_by_channel: session 0 channel 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_input_channel_req: session 0 req exec
Aug 26 09:53:54 szvp000207944 sshd[19674]: Starting session: command for ma_user from x.x.x.x port 39382 id 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: fd 3 setting TCP_NODELAY
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: fd 10 setting O_NONBLOCK
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: fd 9 setting O_NONBLOCK
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: fd 12 setting O_NONBLOCK
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: read<=0 rfd 10 len 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: read failed
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: close_read
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: input open -> drain
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: read 0 from efd 12
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: closing read-efd 12
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: ibuf empty
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: send eof
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: input drain -> closed
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: notify_done: reading
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: Received SIGCHLD.
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_by_pid: pid 19675
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_exit_message: session 0 channel 0 pid 19675
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: request exit-status confirm 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_exit_message: release channel 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: write failed
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: close_write
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: send eow
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: output open -> closed
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: send close
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: rcvd eof
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: rcvd close
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: server_input_channel_open: ctype session rchan 1 win 2097152 max 32768
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: input_session_request
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: channel 1: new [server-session]
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: session_new: allocate (allocated 1 max 100)
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_new: session 1
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_open: channel 1
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_open: session 1: link with channel 1
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: server_input_channel_open: confirm session
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: is dead
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: gc: notify user
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_by_channel: session 0 channel 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_close_by_channel: channel 0 child 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: Close session: user ma_user from x.x.x.x port 39382 id 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: gc: user detached
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: is dead
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: garbage collecting
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: channel 0: free: server-session, nchannels 2
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: server_input_channel_req: channel 1 request exec reply 1
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_by_channel: session 1 channel 1
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_input_channel_req: session 1 req exec
Aug 26 09:53:54 szvp000207944 sshd[19674]: Starting session: command for ma_user from x.x.x.x port 39382 id 1
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: fd 10 setting O_NONBLOCK
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: fd 9 setting O_NONBLOCK
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: fd 12 setting O_NONBLOCK
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: read<=0 rfd 10 len 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: read failed
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: close_read
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: input open -> drain
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: read 0 from efd 12
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: closing read-efd 12
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: ibuf empty
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: send eof
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: input drain -> closed
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: notify_done: reading
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: Received SIGCHLD.
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_by_pid: pid 19676
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_exit_message: session 1 channel 1 pid 19676
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: request exit-status confirm 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_exit_message: release channel 1
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: write failed
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: close_write
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: send eow
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: output open -> closed
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: send close
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: rcvd eof
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: rcvd close
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: server_input_channel_open: ctype session rchan 2 win 2097152 max 32768
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: input_session_request
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: channel 0: new [server-session]
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_new: session 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_open: channel 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_open: session 0: link with channel 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: server_input_channel_open: confirm session
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: is dead
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: gc: notify user
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_by_channel: session 1 channel 1
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_close_by_channel: channel 1 child 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: Close session: user ma_user from x.x.x.x port 39382 id 1
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: gc: user detached
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: is dead
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 1: garbage collecting
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: channel 1: free: server-session, nchannels 2
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: server_input_channel_req: channel 0 request exec reply 1
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_by_channel: session 0 channel 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_input_channel_req: session 0 req exec
Aug 26 09:53:54 szvp000207944 sshd[19674]: Starting session: command for ma_user from x.x.x.x port 39382 id 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: fd 10 setting O_NONBLOCK
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: fd 9 setting O_NONBLOCK
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: fd 12 setting O_NONBLOCK
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: read<=0 rfd 10 len 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: read failed
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: close_read
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: input open -> drain
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: read 0 from efd 12
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: closing read-efd 12
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: ibuf empty
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: send eof
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: input drain -> closed
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: notify_done: reading
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: Received SIGCHLD.
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_by_pid: pid 19677
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_exit_message: session 0 channel 0 pid 19677
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: request exit-status confirm 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_exit_message: release channel 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: write failed
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: close_write
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: send eow
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: output open -> closed
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: send close
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: rcvd close
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: is dead
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: gc: notify user
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_by_channel: session 0 channel 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: session_close_by_channel: channel 0 child 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: Close session: user ma_user from x.x.x.x port 39382 id 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: gc: user detached
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: is dead
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug2: channel 0: garbage collecting
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: channel 0: free: server-session, nchannels 1
Aug 26 09:53:54 szvp000207944 sshd[19674]: channel_by_id: 0: bad id: channel free
Aug 26 09:53:54 szvp000207944 sshd[19674]: Disconnecting user ma_user x.x.x.x port 39382: ieof packet referred to nonexistent channel 0
Aug 26 09:53:54 szvp000207944 sshd[19674]: debug1: do_cleanup
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: do_cleanup
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: PAM: cleanup
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: PAM: closing session
Aug 26 09:53:54 szvp000207944 sshd[19648]: pam_unix(sshd:session): session closed for user ma_user
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: PAM: deleting credentials
Aug 26 09:53:54 szvp000207944 sshd[19648]: debug1: audit_event: unhandled event 12
Aug 26 09:53:54 szvp000207944 systemd-logind[650]: Removed session 79.
Aug 26 09:54:01 szvp000207944 CRON[19688]: pam_unix(cron:session): session opened for user root by (uid=0)
Aug 26 09:54:01 szvp000207944 CRON[19689]: pam_unix(cron:session): session opened for user root by (uid=0)
Aug 26 09:54:01 szvp000207944 CRON[19688]: pam_unix(cron:session): session closed for user root
Aug 26 09:54:01 szvp000207944 CRON[19689]: pam_unix(cron:session): session closed for user root

(IP and user name have been anonymized)

realliujiaxu avatar Aug 26 '22 02:08 realliujiaxu