Re: ssh_channel_request_exec is Failing, returning -1.

[Jakub Jelen <jjelen@xxxxxxxxxx>]

Hello,
the execution of the command failed for some reason. I believe if you
will turn on debug log in the device sshd server, you will be able to
get more information why the exec request is failing.

Regards,
Jakub

On Fri, 2020-06-19 at 09:22 +0000, V Sidnal, Nagraju wrote:
> 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.
> 
> Regards,
> Nagraju
-- 
Jakub Jelen
Senior Software Engineer
Security Technologies
Red Hat, Inc.