channel_open_session not returning

[netthier]

I have the following code for a Client:

pub struct Client {
    handle: Handle<Handler>,
}

pub struct Channel {
    inner: russh::Channel<Msg>,
}

impl Client {
    pub async fn init(remote: &str, user: &str, key: impl AsRef<Path>) -> eyre::Result<Self> {
        let config = Arc::new(ClientConfig {
            connection_timeout: Some(Duration::from_secs(5)),
            ..Default::default()
        });
        let mut handle = client::connect(config, remote, Handler).await?;
        let key = Arc::new(load_secret_key(key, None)?);
        let res = handle.authenticate_publickey(user, key).await?;
        if !res {
            return Err(eyre::eyre!("Server rejected our SSH publickey"));
        }
        Ok(Self { handle })
    }

    pub async fn new_channel(&mut self) -> eyre::Result<Channel> {
        dbg!("a");
        let inner = self.handle.channel_open_session().await?;
        dbg!("b");
        Ok(Channel { inner })
    }
}

When running

    let mut ssh_client = ssh::Client::init(
        &env::var("REMOTE_ADDR")?,
        &env::var("SSH_USER")?,
        &env::var("SSH_KEY")?,
    )
    .await?;
    let mut channel = ssh_client.new_channel().await?;

the "a" gets printed, but the "b" does not.
I have implemented the method in the Handler for printing out the channel open confirmation, with the logs containing this:

[snip]
2022-12-19T11:02:19.625093Z DEBUG russh::client::encrypted: userauth_success    
[src/ssh.rs:75] "a" = "a"
2022-12-19T11:02:19.625233Z DEBUG russh::cipher: writing, seqn = 6    
2022-12-19T11:02:19.625251Z DEBUG russh::cipher: padding length 7    
2022-12-19T11:02:19.625259Z DEBUG russh::cipher: packet_length 32    
2022-12-19T11:02:19.649032Z DEBUG russh::cipher: reading, len = [191, 235, 165, 118]    
2022-12-19T11:02:19.649065Z DEBUG russh::cipher: reading, seqn = 7    
2022-12-19T11:02:19.649152Z DEBUG russh::cipher: reading, clear len = 624    
2022-12-19T11:02:19.649164Z DEBUG russh::cipher: read_exact 628    
2022-12-19T11:02:19.649178Z DEBUG russh::cipher: read_exact done    
2022-12-19T11:02:19.649533Z DEBUG russh::cipher: reading, padding_length 4    
2022-12-19T11:02:19.649616Z  WARN russh::client::encrypted: Unhandled global request: Ok("hostkeys-00@openssh.com") 0    
2022-12-19T11:02:19.649634Z DEBUG russh::cipher: writing, seqn = 7    
2022-12-19T11:02:19.649642Z DEBUG russh::cipher: padding length 14    
2022-12-19T11:02:19.649649Z DEBUG russh::cipher: packet_length 16    
2022-12-19T11:02:19.649841Z DEBUG russh::cipher: reading, len = [131, 217, 96, 50]    
2022-12-19T11:02:19.649864Z DEBUG russh::cipher: reading, seqn = 8    
2022-12-19T11:02:19.649921Z DEBUG russh::cipher: reading, clear len = 136    
2022-12-19T11:02:19.649929Z DEBUG russh::cipher: read_exact 140    
2022-12-19T11:02:19.649938Z DEBUG russh::cipher: read_exact done    
2022-12-19T11:02:19.650096Z DEBUG russh::cipher: reading, padding_length 7    
2022-12-19T11:02:19.650120Z DEBUG russh::cipher: reading, len = [219, 50, 139, 30]    
2022-12-19T11:02:19.650129Z DEBUG russh::cipher: reading, seqn = 9    
2022-12-19T11:02:19.650200Z DEBUG russh::cipher: reading, clear len = 136    
2022-12-19T11:02:19.650211Z DEBUG russh::cipher: read_exact 140    
2022-12-19T11:02:19.650225Z DEBUG russh::cipher: read_exact done    
2022-12-19T11:02:19.650451Z DEBUG russh::cipher: reading, padding_length 7    
2022-12-19T11:02:19.672871Z DEBUG russh::cipher: reading, len = [89, 113, 103, 91]    
2022-12-19T11:02:19.672897Z DEBUG russh::cipher: reading, seqn = 10    
2022-12-19T11:02:19.672984Z DEBUG russh::cipher: reading, clear len = 40    
2022-12-19T11:02:19.672995Z DEBUG russh::cipher: read_exact 44    
2022-12-19T11:02:19.673010Z DEBUG russh::cipher: read_exact done    
2022-12-19T11:02:19.673173Z DEBUG russh::cipher: reading, padding_length 6    
2022-12-19T11:02:19.673207Z DEBUG russh::client::encrypted: channel_open_confirmation    
2022-12-19T11:02:19.673251Z DEBUG ssh_worker::ssh: Got channel open confirmation for channel ChannelId(2)

After this the program seems to freeze.
I tried connecting to both a remote Debian server as well as a local linuxserver/openssh-server docker container.
Anyone know what might be going wrong here?

[Eugeny]

Could you please show your Handler implementation?

[netthier]

pub struct Handler;
#[async_trait]
impl client::Handler for Handler {
    type Error = eyre::Error;

    async fn check_server_key(
        self,
        server_public_key: &key::PublicKey,
    ) -> Result<(Self, bool), Self::Error> {
        info!(
            "Got public key from server: {}",
            server_public_key.fingerprint()
        );
        Ok((self, true))
    }
    async fn channel_open_confirmation(
        self,
        channel: ChannelId,
        _max_packet_size: u32,
        _window_size: u32,
        session: client::Session,
    ) -> Result<(Self, client::Session), Self::Error> {
        debug!("Got channel open confirmation for channel {channel:?}");
        Ok((self, session))
    }
    async fn data(
        self,
        channel: ChannelId,
        data: &[u8],
        session: client::Session,
    ) -> Result<(Self, client::Session), Self::Error> {
        debug!(
            "Received data on channel {channel:?}: {:?}",
            std::str::from_utf8(data)
        );
        Ok((self, session))
    }
}

[Eugeny]

Make sure to call the original implementation (let (self, session) = Handler::channel_open_confirmation(self, channel, max_packet_size, window_size, session).await?;)

[netthier]

Not quite sure what you mean, where would I call that?
But thanks for the tip, deleting my custom implementation of channel_open_confirmation fixed the issue.
However, the way I did it is also more or less the way described in the docs, isn't it? https://docs.rs/russh/0.35.0-beta.8/russh/client/index.html

[netthier]

Copy-pasting exactly the implementation from the docs leads to the same issue.

[Eugeny]

You can keep your custom implementation and add a call to the original like this:

    async fn channel_open_confirmation(
        self,
        channel: ChannelId,
        max_packet_size: u32,
        window_size: u32,
        session: client::Session,
    ) -> Result<(Self, client::Session), Self::Error> {
        let (self, session) = Handler::channel_open_confirmation(self, channel, max_packet_size, window_size, session).await?;
        debug!("Got channel open confirmation for channel {channel:?}");
        Ok((self, session))
    }

Thanks for pointing out the docs! A lot of these are inherited from thrussh and some are outdated - I'll update them.

[netthier]

Even if explicitly specifying russh::client::Handler there I get an infinite recursion, probably because the trait call is implicitly coerced to my own version of Handler here.

[simao]

I am also getting an infinite recursion on something like this. Is there a way to call the overridden method in russh::server::Handler ?

[yorkz1994]

@Eugeny

async fn channel_open_confirmation(
        self,
        channel: ChannelId,
        max_packet_size: u32,
        window_size: u32,
        session: client::Session,
    ) -> Result<(Self, client::Session), Self::Error> {
        let (self, session) = Handler::channel_open_confirmation(self, channel, max_packet_size, window_size, session).await?;
        debug!("Got channel open confirmation for channel {channel:?}");
        Ok((self, session))
    }

This will cause recursion and stackoverflow in runtime because this line: let (self, session) = Handler::channel_open_confirmation(self, channel, max_packet_size, window_size, session).await?;
This will call itself again and again. It is not possible to call the method in trait. I don't know if rust can do it.
Does that mean we cannot impl channel open/close related method?
How do we expect callback then. For example if we want to do something after a channel close?

[Eugeny]

In v0.38.0-beta.1, the default Handler behaviours now get executed independently of whether you've overridden a method or not.