RE: ssh_channel_request_exec is Failing, returning -1.

["V Sidnal, Nagraju" <nagraju.sidnal@xxxxxxxxxxx>]

Hi Jakub,

I tried  same with Default SSH server running on Debain 9.  However it still failed.. 
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());

Please find below ServerLogs(Running on Debian 9) Log:
Jun 22 10:30:43 debian sshd[1880]: debug1: session_by_channel: session 0 channel 0
Jun 22 10:30:43 debian sshd[1880]: debug1: session_input_channel_req: session 0 req pty-req
Jun 22 10:30:43 debian sshd[1880]: debug1: Allocating pty.
Jun 22 10:30:43 debian sshd[1880]: debug3: mm_request_send entering: type 28
Jun 22 10:30:43 debian sshd[1880]: debug3: mm_pty_allocate: waiting for MONITOR_ANS_PTY
Jun 22 10:30:43 debian sshd[1880]: debug3: mm_request_receive_expect entering: type 29
Jun 22 10:30:43 debian sshd[1880]: debug3: mm_request_receive entering
Jun 22 10:30:43 debian sshd[1874]: debug3: mm_request_receive entering
Jun 22 10:30:43 debian sshd[1874]: debug3: monitor_read: checking request 28
Jun 22 10:30:43 debian sshd[1874]: debug3: mm_answer_pty entering
Jun 22 10:30:43 debian sshd[1874]: debug2: session_new: allocate (allocated 0 max 10)
Jun 22 10:30:43 debian sshd[1874]: debug3: session_unused: session id 0 unused
Jun 22 10:30:43 debian sshd[1874]: debug1: session_new: session 0
Jun 22 10:30:43 debian sshd[1874]: debug1: SELinux support disabled
Jun 22 10:30:43 debian sshd[1874]: debug3: mm_request_send entering: type 29
Jun 22 10:30:43 debian sshd[1874]: debug3: mm_answer_pty: tty /dev/pts/1 ptyfd 4
Jun 22 10:30:43 debian sshd[1880]: debug1: session_pty_req: session 0 alloc /dev/pts/1
Jun 22 10:30:43 debian sshd[1880]: debug3: send packet: type 99
Jun 22 10:30:43 debian sshd[1880]: debug3: receive packet: type 98
Jun 22 10:30:43 debian sshd[1880]: debug1: server_input_channel_req: channel 0 request shell reply 1
Jun 22 10:30:43 debian sshd[1880]: debug1: session_by_channel: session 0 channel 0
Jun 22 10:30:43 debian sshd[1880]: debug1: session_input_channel_req: session 0 req shell
Jun 22 10:30:43 debian sshd[1880]: Starting session: shell on pts/1 for abhijeet from 172.20.10.6 port 61619 id 0
Jun 22 10:30:43 debian sshd[1880]: debug2: fd 3 setting TCP_NODELAY
Jun 22 10:30:43 debian sshd[1880]: debug3: ssh_packet_set_tos: set IP_TOS 0x10
Jun 22 10:30:43 debian sshd[1880]: debug2: channel 0: rfd 10 isatty
Jun 22 10:30:43 debian sshd[1880]: debug2: fd 10 setting O_NONBLOCK
Jun 22 10:30:43 debian sshd[1880]: debug3: fd 8 is O_NONBLOCK
Jun 22 10:30:43 debian sshd[1880]: debug3: send packet: type 99
Jun 22 10:30:43 debian sshd[1881]: debug1: Setting controlling tty using TIOCSCTTY.
Jun 22 10:30:43 debian sshd[1881]: debug3: Copy environment: XDG_SESSION_ID=8
Jun 22 10:30:43 debian sshd[1881]: debug3: Copy environment: XDG_RUNTIME_DIR=/run/user/1000
Jun 22 10:30:43 debian sshd[1881]: debug3: Copy environment: DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
Jun 22 10:30:43 debian sshd[1881]: debug3: Copy environment: no_proxy=127.0.0.1, localhost, *.cnn.com, 192.168.1.10, domain.com:8080
Jun 22 10:30:43 debian sshd[1881]: debug3: Copy environment: PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/usr/lib/jvm/jdk-11.0.2/bin:/usr/lib/jvm/jdk-10.0.2/bin
Jun 22 10:30:43 debian sshd[1881]: debug3: Copy environment: JAVA_HOME=/usr/lib/jvm/jdk-10.0.2/bin
Jun 22 10:30:43 debian sshd[1881]: debug3: Copy environment: LANG=en_US.UTF-8
Jun 22 10:30:43 debian sshd[1880]: debug3: receive packet: type 98
Jun 22 10:30:43 debian sshd[1880]: debug1: server_input_channel_req: channel 0 request exec reply 1
Jun 22 10:30:43 debian sshd[1880]: debug1: session_by_channel: session 0 channel 0
Jun 22 10:30:43 debian sshd[1880]: debug1: session_input_channel_req: session 0 req exec
Jun 22 10:30:43 debian sshd[1880]: debug3: send packet: type 100
Jun 22 10:30:44 debian sshd[1880]: Read error from remote host 172.20.10.6 port 61619: Connection reset by peer

I think there is some bug with ssh_channel_request_exec, it does not work with ssh_channel_request_shell. Even you can reproduce this issue at your end.
Please guide me.

Regards,
Nagraju

-----Original Message-----
From: Jakub Jelen <jjelen@xxxxxxxxxx> 
Sent: Friday, June 19, 2020 5:11 PM
To: libssh@xxxxxxxxxx
Subject: Re: ssh_channel_request_exec is Failing, returning -1.

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.