Section 5.3 of the RFC indicates that when the client receives the CHANNEL_CLOSE message from the server it must also send the same message back:

When either party wishes to terminate the channel, it sends SSH_MSG_CHANNEL_CLOSE. Upon receiving this message, a party MUST send back an SSH_MSG_CHANNEL_CLOSE unless it has already sent this message for the channel. The channel is considered closed for a party when it has both sent and received SSH_MSG_CHANNEL_CLOSE, and the party may then reuse the channel number. A party MAY send SSH_MSG_CHANNEL_CLOSE without having sent or received SSH_MSG_CHANNEL_EOF.

We do currently receive the message from the server but we do not return the message:

thrussh/src/client/encrypted.rs:315

msg::CHANNEL_CLOSE => {
    debug!("channel_close");
    let mut r = buf.reader(1);
    let channel_num = ChannelId(r.read_u32().map_err(crate::Error::from)?);
    if let Some(ref mut enc) = self.common.encrypted {
        enc.channels.remove(&channel_num);
    }
     let c = client.take().unwrap();
     let (c, s) = c.channel_close(channel_num, self).await?;
     *client = Some(c);
     Ok(s)
}

The end result of this is that sessions do not get closed on the ssh server (such as when connected to openssh). To test this, you can set MaxSessions to a small number, such as 4. Next, using a simple test, such as one of the examples in the project, connect to the host and exec an “echo” command 5 times in a row, using the same session. This will attempt to use a channel each time, but because these channels are never closed, they will continue to increment until sshd indicates that the max number of sessions has been exhausted. At this point the session will be disconnected.

Example:

impl Session {
...
    async fn call(&mut self, command: &str) -> Result {
            let mut channel = self.session.channel_open_session().await?;
            channel.exec(true, command).await?;
            let mut output = Vec::new();
            let mut code = None;
            while let Some(msg) = channel.wait().await {
                match msg {
                    thrussh::ChannelMsg::Data { ref data } => {
                        output.write_all(&data).unwrap();
                    }
                    thrussh::ChannelMsg::ExitStatus { exit_status } => {
                        code = Some(exit_status);
                    }
                    thrussh::ChannelMsg::Eof => {
                        println!("Channel received EOF.");
                    }
                    _ => {}
                }
            }

            Ok(CommandResult { output, code })
        }
}
...
let mut ssh = Session::connect("root", "password", "192.168.1.14:22").await?;
for i in 1..10 {
    let r = ssh.call("echo 'sending some text.'").await?;
    println!("success: {}, output: {}", r.success(), r.output());
}

In addition to this issue, we should also include the ability to send the CLOSE_CHANNEL message from the channel. Section 5.3 of the spec indicates that sending EOF is not enough to close the channel:

However, the application may send EOF to whatever is at the other end of the channel. Note that the channel remains open after this message, and more data may still be sent in the other direction. - Section 5.3

I have a patch that fixes the issue and has been tested against OpenSSH 7.4p1. I will be committing shortly.

I noticed several “File Undeletion” entries in my patch. Is this expected? All I did was clone the repo, make my changes to each file, add each file, and record the files. Is this normal?

Thanks for the patch!

I noticed several “File Undeletion” entries in my patch. Is this expected? All I did was clone the repo, make my changes to each file, add each file, and record the files. Is this normal?

This isn’t normal, but isn’t your fault. This repository was edited a long time ago with a buggy version of Pijul, and some remnants of that still remain today (I haven’t fixed it yet).

One thing you can do with interactive records is to delete the portions of a patch you don’t want.

Also, you don’t need to add the files, “add” means “start tracking these files”, there’s no staging area in Pijul (nor is there a strong need for that).

Thanks for the feedback @pmeunier. I wanted to provide some more context for this patch. I put together the following test and ran it against my version of OpenSSH running on CentOS 7.9.2009:

#[tokio::test]
async fn test_multiple_commands_from_same_handle() -> Result<(), Box<dyn std::error::Error>> {
    struct Client {}

    impl client::Handler for Client {
        type Error = thrussh::Error;
        type FutureUnit = futures::future::Ready<Result<(Self, client::Session), Self::Error>>;
        type FutureBool = futures::future::Ready<Result<(Self, bool), Self::Error>>;

        fn finished_bool(self, b: bool) -> Self::FutureBool {
            futures::future::ready(Ok((self, b)))
        }
        fn finished(self, session: client::Session) -> Self::FutureUnit {
            futures::future::ready(Ok((self, session)))
        }
        fn check_server_key(self, _server_public_key: &key::PublicKey) -> Self::FutureBool {
            self.finished_bool(true)
        }
    }

    pub struct Session {
        session: client::Handle<Client>,
    }

    impl Session {
        async fn connect(
            user: impl Into<String>,
            password: impl Into<String>,
            addr: impl std::net::ToSocketAddrs,
        ) -> Result<Self, anyhow::Error> {
            let config = client::Config::default();
            let config = Arc::new(config);
            let sh = Client {};

            let addr = (addr)
                .to_socket_addrs()?
                .find(|x| x.is_ipv4())
                .expect("Connected");

            let mut session: Handle<Client> = client::connect(config, addr, sh).await?;

            session.authenticate_password(user, password).await?;
            Ok(Self { session })
        }

        async fn call(&mut self, command: &str) -> Result<CommandResult, anyhow::Error> {
            let mut channel = self.session.channel_open_session().await?;
            channel.exec(true, command).await?;
            let mut output = Vec::new();
            let mut code = None;
            while let Some(msg) = channel.wait().await {
                match msg {
                    thrussh::ChannelMsg::Data { ref data } => {
                        output.write_all(&data).unwrap();
                    }
                    thrussh::ChannelMsg::ExitStatus { exit_status } => {
                        code = Some(exit_status);
                    }
                    thrussh::ChannelMsg::Eof => {
                        println!("Channel received EOF.");
                    }
                    _ => {}
                }
            }

            channel.eof().await?;

            Ok(CommandResult { output, code })
        }
    }

    struct CommandResult {
        output: Vec<u8>,
        code: Option<u32>,
    }

    impl CommandResult {
        fn output(&self) -> String {
            String::from_utf8_lossy(&self.output).into()
        }

        fn success(&self) -> bool {
            self.code == Some(0)
        }
    }

    let mut ssh = Session::connect("root", "password", "192.168.1.14:22").await?;
    for i in 1..10 {
        let r = ssh.call("echo 'some message.'").await?;
        println!("success: {}, output: {}", r.success(), r.output());
    }

    Ok(())
}

This is just a simple test that will establish a connection and use channel_open_session to get a channel and run a simple command over ssh. I wanted to run the same command 10 times but before running, I set the MaxSessions variable to 4 in /etc/ssh/sshd_config and restarted sshd. When I ran my test before the change, my connection was disconnected and the test failed. The logs under /var/log/secure indicate that the ssh server ran out of sessions:

test output:

running 1 test
Channel received EOF.
success: true, output: some message

Channel received EOF.
success: true, output: some message

Channel received EOF.
success: true, output: some message

Channel received EOF.
success: true, output: some message

Error: Disconnected

/var/log/secure output:

...
Aug 29 15:50:05 node1 sshd[27956]: debug3: channel 0: will not send data after close
Aug 29 15:50:05 node1 sshd[27956]: debug3: channel 1: will not send data after close
Aug 29 15:50:05 node1 sshd[27956]: debug3: channel 2: will not send data after close
Aug 29 15:50:05 node1 sshd[27956]: debug3: channel 3: will not send data after close
Aug 29 15:50:05 node1 sshd[27956]: debug1: channel 4: new [server-session]
Aug 29 15:50:05 node1 sshd[27956]: debug1: session_open: channel 4
Aug 29 15:50:05 node1 sshd[27956]: error: no more sessions
Aug 29 15:50:05 node1 sshd[27956]: debug1: session open failed, free channel 4
Aug 29 15:50:05 node1 sshd[27956]: debug1: channel 4: free: server-session, nchannels 5
Aug 29 15:50:05 node1 sshd[27956]: debug3: channel 4: status: The following connections are open:\r\n  #0 server-session (t4 r2 i3/0 o3/0 fd -1/-1 cc -1)\r\n  #1 server-session (t4 r3 i3/0 o3/0 fd -1/-1 cc -1)\r\n  #2 server-session (t4 r4 i3/0 o3/0 fd -1/-1 cc -1)\r\n  #3 server-session (t4 r5 i3/0 o3/0 fd -1/-1 cc -1)\r\n  #4 server-session (t10 r-1 i0/0 o0/0 fd -1/-1 cc -1)\r\n
Aug 29 15:50:05 node1 sshd[27956]: debug1: server_input_channel_open: failure session
Aug 29 15:50:05 node1 sshd[27956]: debug3: send packet: type 92
Aug 29 15:50:05 node1 sshd[27956]: Connection closed by 10.73.10.1 port 47068
Aug 29 15:50:05 node1 sshd[27956]: debug1: channel 0: free: server-session, nchannels 4
Aug 29 15:50:05 node1 sshd[27956]: debug3: channel 0: status: The following connections are open:\r\n  #0 server-session (t4 r2 i3/0 o3/0 fd -1/-1 cc -1)\r\n  #1 server-session (t4 r3 i3/0 o3/0 fd -1/-1 cc -1)\r\n  #2 server-session (t4 r4 i3/0 o3/0 fd -1/-1 cc -1)\r\n  #3 server-session (t4 r5 i3/0 o3/0 fd -1/-1 cc -1)\r\n
Aug 29 15:50:05 node1 sshd[27956]: debug1: channel 1: free: server-session, nchannels 3
Aug 29 15:50:05 node1 sshd[27956]: debug3: channel 1: status: The following connections are open:\r\n  #1 server-session (t4 r3 i3/0 o3/0 fd -1/-1 cc -1)\r\n  #2 server-session (t4 r4 i3/0 o3/0 fd -1/-1 cc -1)\r\n  #3 server-session (t4 r5 i3/0 o3/0 fd -1/-1 cc -1)\r\n
Aug 29 15:50:05 node1 sshd[27956]: debug1: channel 2: free: server-session, nchannels 2
Aug 29 15:50:05 node1 sshd[27956]: debug3: channel 2: status: The following connections are open:\r\n  #2 server-session (t4 r4 i3/0 o3/0 fd -1/-1 cc -1)\r\n  #3 server-session (t4 r5 i3/0 o3/0 fd -1/-1 cc -1)\r\n
Aug 29 15:50:05 node1 sshd[27956]: debug1: channel 3: free: server-session, nchannels 1
Aug 29 15:50:05 node1 sshd[27956]: debug3: channel 3: status: The following connections are open:\r\n  #3 server-session (t4 r5 i3/0 o3/0 fd -1/-1 cc -1)\r\n
Aug 29 15:50:05 node1 sshd[27956]: Close session: user root from 10.73.10.1 port 47068 id 0
Aug 29 15:50:05 node1 sshd[27956]: debug3: session_unused: session id 0 unused
Aug 29 15:50:05 node1 sshd[27956]: Close session: user root from 10.73.10.1 port 47068 id 1
Aug 29 15:50:05 node1 sshd[27956]: debug3: session_unused: session id 1 unused
Aug 29 15:50:05 node1 sshd[27956]: Close session: user root from 10.73.10.1 port 47068 id 2
Aug 29 15:50:05 node1 sshd[27956]: debug3: session_unused: session id 2 unused
Aug 29 15:50:05 node1 sshd[27956]: Close session: user root from 10.73.10.1 port 47068 id 3
Aug 29 15:50:05 node1 sshd[27956]: debug3: session_unused: session id 3 unused
Aug 29 15:50:05 node1 sshd[27956]: debug1: do_cleanup

From the logs you can see that every time we call channel_open_session the server opens a new session and increments the id until there are no more sessions available, at which time we are disconnected from the server. The server then closes each of the sessions once we’ve been disconnected.

With this patch you can see that the same code executes and the session is released after the completion of each call and thus the id does not increment as it did before:

test output:

running 1 test
Channel received EOF.
success: true, output: some message

Channel received EOF.
success: true, output: some message

Channel received EOF.
success: true, output: some message

Channel received EOF.
success: true, output: some message

Channel received EOF.
success: true, output: some message

Channel received EOF.
success: true, output: some message

Channel received EOF.
success: true, output: some message

Channel received EOF.
success: true, output: some message

Channel received EOF.
success: true, output: some message

test test_multiple_commands_from_same_handle2 ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 5 filtered out; finished in 0.61s

/var/log/secure logs:

Aug 29 15:56:59 node1 sshd[28993]: Starting session: command for root from 10.73.10.1 port 47216 id 0
Aug 29 15:56:59 node1 sshd[28993]: debug2: fd 11 setting O_NONBLOCK
Aug 29 15:56:59 node1 sshd[28993]: debug2: fd 10 setting O_NONBLOCK
Aug 29 15:56:59 node1 sshd[28993]: debug2: fd 13 setting O_NONBLOCK
Aug 29 15:56:59 node1 sshd[28993]: debug3: send packet: type 99
Aug 29 15:56:59 node1 sshd[29053]: debug1: PAM: reinitializing credentials
Aug 29 15:56:59 node1 sshd[29053]: debug1: permanently_set_uid: 0/0
Aug 29 15:56:59 node1 sshd[29053]: debug3: Copy environment: XDG_SESSION_ID=1848
Aug 29 15:56:59 node1 sshd[29053]: debug3: Copy environment: XDG_RUNTIME_DIR=/run/user/0
Aug 29 15:56:59 node1 sshd[28993]: debug1: Received SIGCHLD.
Aug 29 15:56:59 node1 sshd[28993]: debug1: session_by_pid: pid 29053
Aug 29 15:56:59 node1 sshd[28993]: debug1: session_exit_message: session 0 channel 0 pid 29053
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: request exit-status confirm 0
Aug 29 15:56:59 node1 sshd[28993]: debug3: send packet: type 98
Aug 29 15:56:59 node1 sshd[28993]: debug1: session_exit_message: release channel 0
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: write failed
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: close_write
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: send eow
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: output open -> closed
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: read 0 from efd 13
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: closing read-efd 13
Aug 29 15:56:59 node1 sshd[28993]: debug2: notify_done: reading
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: read<=0 rfd 11 len 0
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: read failed
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: close_read
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: input open -> drain
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: ibuf empty
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: send eof
Aug 29 15:56:59 node1 sshd[28993]: debug3: send packet: type 96
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: input drain -> closed
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: send close
Aug 29 15:56:59 node1 sshd[28993]: debug3: send packet: type 97
Aug 29 15:56:59 node1 sshd[28993]: debug3: channel 0: will not send data after close
Aug 29 15:56:59 node1 sshd[28993]: debug3: receive packet: type 97
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: rcvd close
Aug 29 15:56:59 node1 sshd[28993]: debug3: channel 0: will not send data after close
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: is dead
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: gc: notify user
Aug 29 15:56:59 node1 sshd[28993]: debug1: session_by_channel: session 0 channel 0
Aug 29 15:56:59 node1 sshd[28993]: debug1: session_close_by_channel: channel 0 child 0
Aug 29 15:56:59 node1 sshd[28993]: Close session: user root from 10.73.10.1 port 47216 id 0
Aug 29 15:56:59 node1 sshd[28993]: debug3: session_unused: session id 0 unused
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: gc: user detached
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: is dead
Aug 29 15:56:59 node1 sshd[28993]: debug2: channel 0: garbage collecting
Aug 29 15:56:59 node1 sshd[28993]: debug1: channel 0: free: server-session, nchannels 1
Aug 29 15:56:59 node1 sshd[28993]: debug3: channel 0: status: The following connections are open:\r\n  #0 server-session (t4 r10 i3/0 o3/0 fd -1/-1 cc -1)\r\n
Aug 29 15:56:59 node1 sshd[28993]: Connection closed by 10.73.10.1 port 47216
Aug 29 15:56:59 node1 sshd[28993]: debug1: do_cleanup
Aug 29 15:56:59 node1 sshd[28993]: debug1: PAM: cleanup
Aug 29 15:56:59 node1 sshd[28993]: debug1: PAM: closing session
Aug 29 15:56:59 node1 sshd[28993]: pam_unix(sshd:session): session closed for user root
Aug 29 15:56:59 node1 sshd[28993]: debug1: PAM: deleting credentials
Aug 29 15:56:59 node1 sshd[28993]: debug3: PAM: sshpam_thread_cleanup entering
Aug 29 15:56:59 node1 sshd[28993]: Transferred: sent 3632, received 1408 bytes
Aug 29 15:56:59 node1 sshd[28993]: Closing connection to 10.73.10.1 port 47216

As you can see that at the end of the logs the connection count never goes above 1 since the sessions are closed after each call. I hope this provided some more context. I will update my patch to remove the unnecessary entries.

I was able to remove the unnecessary hunks from the commit so it should be good to go now. Note that I ran cargo fmt so it looks like it updated a couple of other things as well. Let me know if there is anything else that needs to be addressed in the patch. Thanks.

Hi @pmeunier, does everything look ok with the patch?

Hi @pmeunier, is there any chance this can be merged?

I’ll merge and republish very soon. I’m in the middle of moving to a new place at the moment, so I need to review your patch carefully. From what I’ve seen it looks good, I promise I’ll find time soon.

Hi @pmeunier. Is there any progress on this? I’m trying to use thrussh to continuously poll the state of a service by using an open ssh connection, open a channel using channel_open_session and then doing an exec on that channel. It works great a few times, but then it halts on the exec.

To give some more context here, what I see is the following:

Dec 27 08:59:35.247 TRACE myapp::ssh: open_session
Dec 27 08:59:35.247 DEBUG thrussh::cipher: writing, seqn = 23    
Dec 27 08:59:35.247 DEBUG thrussh::cipher: padding length 7    
Dec 27 08:59:35.248 DEBUG thrussh::cipher: packet_length 32    
Dec 27 08:59:35.248 DEBUG thrussh::client: writing to stream: 52 bytes    
Dec 27 08:59:35.249 DEBUG thrussh::cipher: reading, len = [96, 162, 182, 125]    
Dec 27 08:59:35.249 DEBUG thrussh::cipher: reading, seqn = 69    
Dec 27 08:59:35.250 DEBUG thrussh::cipher: reading, clear len = 40    
Dec 27 08:59:35.250 DEBUG thrussh::cipher: read_exact 44    
Dec 27 08:59:35.250 DEBUG thrussh::cipher: read_exact done    
Dec 27 08:59:35.250 DEBUG thrussh::cipher: reading, padding_length 6    
Dec 27 08:59:35.250 DEBUG thrussh::client::encrypted: client_read_encrypted, buf = [91, 0, 0, 0, 11, 0, 0, 0, 9, 0, 0, 0, 0, 0, 0, 128, 0]    
Dec 27 08:59:35.251 DEBUG thrussh::client::encrypted: buf = 17 bytes    
Dec 27 08:59:35.251 TRACE thrussh::client::encrypted: buf = [91, 0, 0, 0, 11, 0, 0, 0, 9, 0, 0, 0, 0, 0, 0, 128, 0]    
Dec 27 08:59:35.251 DEBUG thrussh::client::encrypted: channel_open_confirmation    
Dec 27 08:59:35.251 TRACE myapp::ssh: channel_exec
Dec 27 08:59:35.251 TRACE myapp::ssh: channel.wait
Dec 27 08:59:35.252 DEBUG thrussh::cipher: writing, seqn = 24    
Dec 27 08:59:35.252 DEBUG thrussh::cipher: padding length 6    
Dec 27 08:59:35.252 DEBUG thrussh::cipher: packet_length 40

[ ... ]

Dec 27 08:59:35.333 DEBUG thrussh::client::encrypted: client_read_encrypted, buf = [97, 0, 0, 0, 11]    
Dec 27 08:59:35.333 DEBUG thrussh::client::encrypted: buf = 5 bytes    
Dec 27 08:59:35.333 TRACE thrussh::client::encrypted: buf = [97, 0, 0, 0, 11]    
Dec 27 08:59:35.333 DEBUG thrussh::client::encrypted: channel_close    
Dec 27 08:59:35.448 TRACE myapp::ssh: open_session
Dec 27 08:59:35.449 DEBUG thrussh::cipher: writing, seqn = 25    
Dec 27 08:59:35.449 DEBUG thrussh::cipher: padding length 7    
Dec 27 08:59:35.449 DEBUG thrussh::cipher: packet_length 32    
Dec 27 08:59:35.450 DEBUG thrussh::client: writing to stream: 52 bytes    
Dec 27 08:59:35.451 DEBUG thrussh::cipher: reading, len = [200, 43, 139, 76]    
Dec 27 08:59:35.452 DEBUG thrussh::cipher: reading, seqn = 76    
Dec 27 08:59:35.452 DEBUG thrussh::cipher: reading, clear len = 56    
Dec 27 08:59:35.452 DEBUG thrussh::cipher: read_exact 60    
Dec 27 08:59:35.452 DEBUG thrussh::cipher: read_exact done    
Dec 27 08:59:35.453 DEBUG thrussh::cipher: reading, padding_length 11    
Dec 27 08:59:35.453 DEBUG thrussh::client::encrypted: client_read_encrypted, buf = [92, 0, 0, 0, 12, 0, 0, 0, 1, 0, 0, 0, 11, 111, 112, 101, 110, 32, 102, 97]    
Dec 27 08:59:35.453 DEBUG thrussh::client::encrypted: buf = 28 bytes    
Dec 27 08:59:35.453 TRACE thrussh::client::encrypted: buf = [92, 0, 0, 0, 12, 0, 0, 0, 1, 0, 0, 0, 11, 111, 112, 101, 110, 32, 102, 97, 105, 108, 101, 100, 0, 0, 0, 0]    
Dec 27 08:59:35.453 DEBUG thrussh::client::encrypted: channel_open_failure    

@pmeunier Can we integrate this change?