Re: ssh_channel_request_exec is Failing, returning -1.

[Anderson Sasaki <ansasaki@xxxxxxxxxx>]

Hello,

----- Original Message -----
> From: "V Sidnal, Nagraju" <nagraju.sidnal@xxxxxxxxxxx>
> To: libssh@xxxxxxxxxx
> Sent: Friday, June 19, 2020 11:22:24 AM
> Subject: ssh_channel_request_exec is Failing, returning -1.
> 
> Hello All,
> 
> We have written ssh client using lissh to connect to Device(Having SSH Server
> )
> Our Sample application works with OpenSSH Server in Our Machine(Windows OS).
> *****************************************************
> However it is not working with Device. Below is sample code.
> ***************************************************
> 
> channel = ssh_channel_new(my_ssh_session);
> rc = ssh_channel_open_session(channel);
> rc = ssh_channel_request_exec(channel, command.c_str());
> 
> so here ssh_channel_request_exe() is failing , it is returning -1.
> ****************************************************
> Below is application log.(detailed log attached:
> LibSSH_SampleApplication_failedwithDevice.txt)
> *****************************************************
> [2020/06/18 09:46:16.881442, 3] ssh_packet_userauth_success:  Authentication
> successful
> [2020/06/18 09:46:16.884442, 4] ssh_packet_userauth_success:  Received
> SSH_USERAUTH_SUCCESS
> [2020/06/18 09:46:16.886442, 3] ssh_packet_need_rekey:  packet:
> [data_rekey_needed=0, out_blocks=13, in_blocks=11
> [2020/06/18 09:46:16.889442, 3] ssh_packet_need_rekey:  packet:
> [data_rekey_needed=0, out_blocks=13, in_blocks=11
> ssh_userauth_publickey
> ssh_is_connected
> [2020/06/18 09:46:16.900442, 2] channel_open:  Creating a channel 43 with
> 64000 window and 32768 max packet
> [2020/06/18 09:46:16.903442, 3] ssh_packet_need_rekey:  packet:
> [data_rekey_needed=0, out_blocks=14, in_blocks=12
> [2020/06/18 09:46:16.907442, 3] ssh_socket_unbuffered_write:  Enabling
> POLLOUT for socket
> [2020/06/18 09:46:16.914442, 3] packet_send2:  packet: wrote [type=90,
> len=44, padding_size=19, comp=24, payload=24]
> [2020/06/18 09:46:16.917442, 3] channel_open:  Sent a SSH_MSG_CHANNEL_OPEN
> type session for channel 43
> [2020/06/18 09:46:16.924442, 4] ssh_socket_pollcallback:  Poll callback on
> socket 212 (POLLIN POLLOUT ), out buffer 0
> [2020/06/18 09:46:16.926442, 3] ssh_packet_socket_callback:  packet: read
> type 91 [len=28,padding=10,comp=17,payload=17]
> [2020/06/18 09:46:16.930442, 3] ssh_packet_process:  Dispatching handler for
> packet type 91
> [2020/06/18 09:46:16.933442, 3] ssh_packet_channel_open_conf:  Received
> SSH2_MSG_CHANNEL_OPEN_CONFIRMATION
> [2020/06/18 09:46:16.936442, 2] ssh_packet_channel_open_conf:  Received a
> CHANNEL_OPEN_CONFIRMATION for channel 43:0
> [2020/06/18 09:46:16.939442, 2] ssh_packet_channel_open_conf:  Remote window
> : 0, maxpacket : 32768
> [2020/06/18 09:46:16.942442, 3] ssh_packet_need_rekey:  packet:
> [data_rekey_needed=0, out_blocks=14, in_blocks=12
> [2020/06/18 09:46:16.945442, 4] ssh_socket_pollcallback:  sending control
> flow event
> [2020/06/18 09:46:16.953442, 4] ssh_packet_socket_controlflow_callback:
> sending channel_write_wontblock callback
> ssh_channel_open_session:: returned Code= 0
> ssh_is_connected
> [2020/06/18 09:46:16.968442, 3] ssh_packet_need_rekey:  packet:
> [data_rekey_needed=0, out_blocks=16, in_blocks=14
> [2020/06/18 09:46:16.971442, 3] ssh_socket_unbuffered_write:  Enabling
> POLLOUT for socket
> [2020/06/18 09:46:16.973442, 3] packet_send2:  packet: wrote [type=98,
> len=44, padding_size=8, comp=35, payload=35]
> [2020/06/18 09:46:16.977442, 3] channel_request:  Sent a
> SSH_MSG_CHANNEL_REQUEST exec
> [2020/06/18 09:46:16.980442, 4] ssh_socket_pollcallback:  Poll callback on
> socket 212 (POLLIN POLLOUT ), out buffer 0
> [2020/06/18 09:46:16.984442, 3] ssh_packet_socket_callback:  packet: read
> type 100 [len=12,padding=6,comp=5,payload=5]
> [2020/06/18 09:46:16.992442, 3] ssh_packet_process:  Dispatching handler for
> packet type 100
> [2020/06/18 09:46:16.995442, 3] ssh_packet_channel_failure:  Received
> SSH_CHANNEL_FAILURE on channel (43:0)
> [2020/06/18 09:46:16.999442, 3] ssh_packet_need_rekey:  packet:
> [data_rekey_needed=0, out_blocks=16, in_blocks=12
> [2020/06/18 09:46:17.004442, 4] ssh_socket_pollcallback:  sending control
> flow event
> [2020/06/18 09:46:17.007442, 4] ssh_packet_socket_controlflow_callback:
> sending channel_write_wontblock callback
> [2020/06/18 09:46:17.010442, 1] channel_request:  Channel request exec failed
> ssh_channel_request_exec:: returned Code= -1
> 
> *********************************************************************************************************
> Then we check with Openssh Client to Device (session parameter & command
> together : ssh hostname privatekey command)
> It failed , below is the log (detailed log attached:
> OpenSSH_Client__ConnectionParamterAndCommandTogether_Fails.txt)
> 
> debug1: Authentication succeeded (publickey).
> Authenticated to xxx.xx.x.xx ([xxx.xx.x.xx]:22).
> debug1: channel 0: new [client-session]
> debug3: ssh_session2_open: channel_new: 0
> debug2: channel 0: send open
> debug3: send packet: type 90
> debug1: Requesting no-more-sessions@xxxxxxxxxxx
> debug3: send packet: type 80
> debug1: Entering interactive session.
> debug1: pledge: network
> debug3: receive packet: type 91
> debug2: channel_input_open_confirmation: channel 0: callback start
> debug2: fd 3 setting TCP_NODELAY
> debug3: ssh_packet_set_tos: set IP_TOS 0x08
> debug2: client_session2_setup: id 0
> debug1: Sending command: StartDevice
> debug2: channel 0: request exec confirm 1
> debug3: send packet: type 98
> debug2: channel_input_open_confirmation: channel 0: callback done
> debug2: channel 0: open confirm rwindow 0 rmax 32768
> debug3: receive packet: type 100
> debug2: channel_input_status_confirm: type 100 id 0
> exec request failed on channel 0
> *****************************************************************************************************************
> Then we check with Openssh Client to device (First SESSION ESTABLISHED & THEN
> COMMAND EXECUTION) :: Success Scenario
> After creating session we can execute the command
> its connecting and below is debug log of openssh(detailed log is attached :
> OpenSSh_Client_FirstSession_then_cmd_exe_Success_reqpty.txt)
> 
> debug1: Authentication succeeded (publickey).
> Authenticated to XXX.XXX.X.XX ([XXX.XXX.X.XX]:22).
> debug1: channel 0: new [client-session]
> debug3: ssh_session2_open: channel_new: 0
> debug2: channel 0: send open
> debug3: send packet: type 90
> debug1: Requesting no-more-sessions@xxxxxxxxxxx
> debug3: send packet: type 80
> debug1: Entering interactive session.
> debug1: pledge: network
> debug3: receive packet: type 91
> debug2: channel_input_open_confirmation: channel 0: callback start
> debug2: fd 3 setting TCP_NODELAY
> debug3: ssh_packet_set_tos: set IP_TOS 0x10
> debug2: client_session2_setup: id 0
> debug2: channel 0: request pty-req confirm 1
> debug3: send packet: type 98
> debug2: channel 0: request shell confirm 1
> debug3: send packet: type 98
> debug2: channel_input_open_confirmation: channel 0: callback done
> debug2: channel 0: open confirm rwindow 0 rmax 32768
> debug3: receive packet: type 99
> debug2: channel_input_status_confirm: type 99 id 0
> debug2: PTY allocation request accepted on channel 0
> debug2: channel 0: rcvd adjust 2097152
> debug3: receive packet: type 99
> debug2: channel_input_status_confirm: type 99 id 0
> debug2: shell request accepted on channel 0
> 
> *************************************************************************************************************
> In ABOVE log we found that it is making pty req. so we thought
> ssh_channel_request_pty is requiured
> we did below code
> 
> channel = ssh_channel_new(my_ssh_session);
> rc = ssh_channel_open_session(channel);
> rc = ssh_channel_request_pty(channel);
> rc = ssh_channel_request_shell(channel);
> rc = ssh_channel_request_exec(channel, command.c_str());
> 
> However it is still failing , Please find below log (detailed log attached :
> LibSSH_SampleApplication_failedwithdevicewith_PTY.txt)
> [2020/06/18 12:36:55.038442, 2] channel_open:  Creating a channel 43 with
> 64000 window and 32768 max packet
> [2020/06/18 12:36:55.044442, 2] ssh_packet_channel_open_conf:  Received a
> CHANNEL_OPEN_CONFIRMATION for channel 43:0
> [2020/06/18 12:36:55.046442, 2] ssh_packet_channel_open_conf:  Remote window
> : 0, maxpacket : 32768
> ssh_channel_open_session:: returned Code= 0
> [2020/06/18 12:36:55.061442, 2] channel_request:  Channel request pty-req
> success
> [2020/06/18 12:36:55.159442, 2] channel_rcv_change_window:  Adding 2097152
> bytes to channel (43:0) (from 0 bytes)
> [2020/06/18 12:36:55.161442, 2] channel_request:  Channel request shell
> success
> ssh_is_connected
> [2020/06/18 12:36:55.176442, 2] grow_window:  growing window (channel 43:0)
> to 1280000 bytes
> [2020/06/18 12:36:55.182442, 1] channel_request:  Channel request exec failed
> ssh_channel_request_exec:: returned Code= -1
> 
> Please provide your valuable suggestion/inputs to address the described
> problem.

Thank you for reporting, there is a fix I proposed in https://gitlab.com/libssh/libssh-mirror/-/merge_requests/122

Could you please check if it fixes the issue for you?

Thank you,
Anderson