RE: ssh_channel_read , throwing exception when SSH_OPTIONS_LOG_VERBOSITY is set to SSH_LOG_PACKET or SSH_LOG_FUNCTIONS

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

Hi Jakub,

Please find below log of LibsshClient, which raises exception once it goes inside any kind of channel read, ssh_channel_read(), I m using dll's.
I want to thank you for addressing & responding to my all queries, I'm happy to use & contribute towards libssh , This kind of good support for libssh,  Will definitely make it a go to library for ssh communications. Thanks a lot.

[2020/06/24 13:56:36.272826, 2] ssh_connect:  libssh 0.9.3 (c) 2003-2019 Aris Adamantiadis, Andreas Schneider and libssh contributors. Distributed under the LGPL, please refer to COPYING file for information about your rights, using threading threads_pthread
[2020/06/24 13:56:36.460330, 2] ssh_socket_connect:  Nonblocking connection socket: 700
[2020/06/24 13:56:36.460330, 2] ssh_connect:  Socket connecting, now waiting for the callbacks to work
[2020/06/24 13:56:36.460330, 3] ssh_connect:  Actual timeout : 5000
[2020/06/24 13:56:36.460330, 3] ssh_socket_pollcallback:  Received POLLOUT in connecting state
[2020/06/24 13:56:36.460330, 1] socket_callback_connected:  Socket connection callback: 1 (0)
[2020/06/24 13:56:36.460330, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2020/06/24 13:56:36.491611, 3] callback_receive_banner:  Received banner: SSH-2.0-OpenSSH_for_Windows_8.1
[2020/06/24 13:56:36.507189, 2] ssh_client_connection_callback:  SSH server banner: SSH-2.0-OpenSSH_for_Windows_8.1
[2020/06/24 13:56:36.507189, 2] ssh_analyze_banner:  Analyzing banner: SSH-2.0-OpenSSH_for_Windows_8.1
[2020/06/24 13:56:36.585325, 3] ssh_client_select_hostkeys:  Order of wanted host keys: "ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss"
[2020/06/24 13:56:36.585325, 1] ssh_key_cmp:  key types don't match!
[2020/06/24 13:56:36.585325, 1] ssh_key_cmp:  key types don't match!
[2020/06/24 13:56:36.585325, 1] ssh_key_cmp:  key types don't match!
[2020/06/24 13:56:36.585325, 1] ssh_key_cmp:  key types don't match!
[2020/06/24 13:56:36.600939, 1] ssh_key_cmp:  key types don't match!
[2020/06/24 13:56:36.600939, 1] ssh_key_cmp:  key types don't match!
[2020/06/24 13:56:36.600939, 1] ssh_known_hosts_read_entries:  Failed to open the known_hosts file '/etc/ssh/ssh_known_hosts': No such file or directory
[2020/06/24 13:56:36.600939, 3] ssh_client_select_hostkeys:  Algorithms found in known_hosts files: "ssh-ed25519,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss,ecdsa-sha2-nistp256"
[2020/06/24 13:56:36.600939, 3] ssh_client_select_hostkeys:  Changing host key method to "ssh-ed25519,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384"
[2020/06/24 13:56:36.600939, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2020/06/24 13:56:36.600939, 3] packet_send2:  packet: wrote [type=20, len=724, padding_size=7, comp=716, payload=716]
[2020/06/24 13:56:36.600939, 3] ssh_send_kex:  SSH_MSG_KEXINIT sent
[2020/06/24 13:56:36.600939, 3] ssh_packet_socket_callback:  packet: read type 20 [len=1076,padding=6,comp=1069,payload=1069]
[2020/06/24 13:56:36.600939, 3] ssh_packet_process:  Dispatching handler for packet type 20
[2020/06/24 13:56:36.600939, 2] ssh_kex_select_methods:  Negotiated diffie-hellman-group-exchange-sha256,ssh-ed25519,aes256-gcm@xxxxxxxxxxx,aes256-gcm@xxxxxxxxxxx,hmac-sha2-256-etm@xxxxxxxxxxx,hmac-sha2-256-etm@xxxxxxxxxxx,none,none,,
[2020/06/24 13:56:36.600939, 3] packet_send2:  packet: wrote [type=34, len=20, padding_size=6, comp=13, payload=13]
[2020/06/24 13:56:36.600939, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2020/06/24 13:56:36.679057, 3] ssh_packet_socket_callback:  packet: read type 31 [len=1044,padding=8,comp=1035,payload=1035]
[2020/06/24 13:56:36.694693, 3] ssh_packet_process:  Dispatching handler for packet type 31
[2020/06/24 13:56:36.694693, 2] ssh_packet_client_dhgex_group:  SSH_MSG_KEX_DH_GEX_GROUP received
[2020/06/24 13:56:38.241584, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2020/06/24 13:56:38.241584, 3] packet_send2:  packet: wrote [type=32, len=1036, padding_size=6, comp=1029, payload=1029]
[2020/06/24 13:56:38.319690, 3] ssh_packet_socket_callback:  packet: read type 33 [len=1180,padding=7,comp=1172,payload=1172]
[2020/06/24 13:56:38.319690, 3] ssh_packet_process:  Dispatching handler for packet type 33
[2020/06/24 13:56:38.319690, 2] ssh_packet_client_dhgex_reply:  SSH_MSG_KEX_DH_GEX_REPLY received
[2020/06/24 13:56:39.866581, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2020/06/24 13:56:39.866581, 3] packet_send2:  packet: wrote [type=21, len=12, padding_size=10, comp=1, payload=1]
[2020/06/24 13:56:39.866581, 3] crypt_set_algorithms2:  Set output algorithm to aes256-gcm@xxxxxxxxxxx
[2020/06/24 13:56:39.866581, 3] crypt_set_algorithms2:  Set HMAC output algorithm to aead-gcm
[2020/06/24 13:56:39.866581, 3] crypt_set_algorithms2:  Set input algorithm to aes256-gcm@xxxxxxxxxxx
[2020/06/24 13:56:39.866581, 3] crypt_set_algorithms2:  Set HMAC input algorithm to aead-gcm
[2020/06/24 13:56:39.866581, 2] ssh_init_rekey_state:  Set rekey after 4294967296 blocks
[2020/06/24 13:56:39.866581, 2] ssh_init_rekey_state:  Set rekey after 4294967296 blocks
[2020/06/24 13:56:39.866581, 2] ssh_packet_client_dhgex_reply:  SSH_MSG_NEWKEYS sent
[2020/06/24 13:56:39.866581, 3] ssh_packet_socket_callback:  Processing 196 bytes left in socket buffer
[2020/06/24 13:56:39.866581, 3] ssh_packet_socket_callback:  packet: read type 21 [len=12,padding=10,comp=1,payload=1]
[2020/06/24 13:56:39.866581, 3] ssh_packet_process:  Dispatching handler for packet type 21
[2020/06/24 13:56:39.882204, 2] ssh_packet_newkeys:  Received SSH_MSG_NEWKEYS
[2020/06/24 13:56:39.897825, 2] ssh_packet_newkeys:  Signature verified and valid
[2020/06/24 13:56:39.897825, 3] ssh_packet_socket_callback:  Processing 180 bytes left in socket buffer
[2020/06/24 13:56:39.897825, 3] ssh_packet_socket_callback:  packet: read type 7 [len=160,padding=18,comp=141,payload=141]
[2020/06/24 13:56:39.897825, 3] ssh_packet_process:  Dispatching handler for packet type 7
[2020/06/24 13:56:39.897825, 3] ssh_packet_ext_info:  Received SSH_MSG_EXT_INFO
[2020/06/24 13:56:39.897825, 3] ssh_packet_ext_info:  Follows 1 extensions
[2020/06/24 13:56:39.897825, 3] ssh_packet_ext_info:  Extension: server-sig-algs=<ssh-ed25519,ssh-rsa,rsa-sha2-256,rsa-sha2-512,ssh-dss,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521>
[2020/06/24 13:56:39.897825, 3] ssh_connect:  current state : 7
[2020/06/24 13:56:39.913441, 1] ssh_key_cmp:  key types don't match!
[2020/06/24 13:56:39.913441, 1] ssh_key_cmp:  key types don't match!
[2020/06/24 13:56:39.913441, 1] ssh_key_cmp:  key types don't match!
[2020/06/24 13:56:39.913441, 1] ssh_key_cmp:  key types don't match!
[2020/06/24 13:56:39.913441, 1] ssh_key_cmp:  key types don't match!
[2020/06/24 13:56:39.913441, 1] ssh_key_cmp:  key types don't match!
 [2020/06/24 13:56:39.929059, 2] ssh_pki_import_privkey_base64:  Trying to decode privkey passphrase=false
[2020/06/24 13:56:39.944681, 2] ssh_pki_openssh_import:  Opening OpenSSH private key: ciphername: none, kdf: none, nkeys: 1
 [2020/06/24 13:56:39.944681, 3] ssh_key_algorithm_allowed:  Checking ssh-ed25519 with list <ssh-ed25519-cert-v01@xxxxxxxxxxx,ecdsa-sha2-nistp521-cert-v01@xxxxxxxxxxx,ecdsa-sha2-nistp384-cert-v01@xxxxxxxxxxx,ecdsa-sha2-nistp256-cert-v01@xxxxxxxxxxx,rsa-sha2-512-cert-v01@xxxxxxxxxxx,rsa-sha2-256-cert-v01@xxxxxxxxxxx,ssh-rsa-cert-v01@xxxxxxxxxxx,ssh-dss-cert-v01@xxxxxxxxxxx,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss>
[2020/06/24 13:56:39.944681, 3] packet_send2:  packet: wrote [type=5, len=32, padding_size=14, comp=17, payload=17]
[2020/06/24 13:56:39.944681, 3] ssh_service_request:  Sent SSH_MSG_SERVICE_REQUEST (service ssh-userauth)
[2020/06/24 13:56:39.944681, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2020/06/24 13:56:39.944681, 3] ssh_packet_socket_callback:  packet: read type 6 [len=32,padding=14,comp=17,payload=17]
[2020/06/24 13:56:39.944681, 3] ssh_packet_process:  Dispatching handler for packet type 6
[2020/06/24 13:56:39.944681, 3] ssh_packet_service_accept:  Received SSH_MSG_SERVICE_ACCEPT
[2020/06/24 13:56:39.960313, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2020/06/24 13:56:39.960313, 3] packet_send2:  packet: wrote [type=50, len=208, padding_size=5, comp=202, payload=202]
[2020/06/24 13:56:40.241587, 3] ssh_packet_socket_callback:  packet: read type 52 [len=16,padding=14,comp=1,payload=1]
[2020/06/24 13:56:40.241587, 3] ssh_packet_process:  Dispatching handler for packet type 52
[2020/06/24 13:56:40.241587, 3] ssh_packet_userauth_success:  Authentication successful
[2020/06/24 13:56:40.241587, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=13, in_blocks=9
 [2020/06/24 13:56:40.241587, 2] channel_open:  Creating a channel 43 with 64000 window and 32768 max packet
[2020/06/24 13:56:40.241587, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=14, in_blocks=10
[2020/06/24 13:56:40.241587, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2020/06/24 13:56:40.241587, 3] packet_send2:  packet: wrote [type=90, len=32, padding_size=7, comp=24, payload=24]
[2020/06/24 13:56:40.241587, 3] channel_open:  Sent a SSH_MSG_CHANNEL_OPEN type session for channel 43
[2020/06/24 13:56:40.382188, 3] ssh_packet_socket_callback:  packet: read type 80 [len=608,padding=4,comp=603,payload=603]
[2020/06/24 13:56:40.382188, 3] ssh_packet_process:  Dispatching handler for packet type 80
[2020/06/24 13:56:40.382188, 2] ssh_packet_global_request:  Received SSH_MSG_GLOBAL_REQUEST packet
[2020/06/24 13:56:40.382188, 2] ssh_packet_global_request:  UNKNOWN SSH_MSG_GLOBAL_REQUEST hostkeys-00@xxxxxxxxxxx, want_reply = 0
[2020/06/24 13:56:40.397809, 3] ssh_packet_global_request:  The requester doesn't want to know the request failed!
[2020/06/24 13:56:40.397809, 1] ssh_packet_global_request:  Invalid SSH_MSG_GLOBAL_REQUEST packet
[2020/06/24 13:56:40.397809, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=14, in_blocks=46
[2020/06/24 13:56:40.397809, 3] ssh_packet_socket_callback:  packet: read type 91 [len=32,padding=14,comp=17,payload=17]
[2020/06/24 13:56:40.397809, 3] ssh_packet_process:  Dispatching handler for packet type 91
[2020/06/24 13:56:40.397809, 3] ssh_packet_channel_open_conf:  Received SSH2_MSG_CHANNEL_OPEN_CONFIRMATION
[2020/06/24 13:56:40.397809, 2] ssh_packet_channel_open_conf:  Received a CHANNEL_OPEN_CONFIRMATION for channel 43:0
[2020/06/24 13:56:40.397809, 2] ssh_packet_channel_open_conf:  Remote window : 0, maxpacket : 32768
[2020/06/24 13:56:40.397809, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=14, in_blocks=47
 [2020/06/24 13:56:40.413437, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=16, in_blocks=49
[2020/06/24 13:56:40.413437, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2020/06/24 13:56:40.413437, 3] packet_send2:  packet: wrote [type=98, len=64, padding_size=16, comp=47, payload=47]
[2020/06/24 13:56:40.413437, 3] channel_request:  Sent a SSH_MSG_CHANNEL_REQUEST pty-req
[2020/06/24 13:56:40.413437, 3] ssh_packet_socket_callback:  packet: read type 99 [len=16,padding=10,comp=5,payload=5]
[2020/06/24 13:56:40.413437, 3] ssh_packet_process:  Dispatching handler for packet type 99
[2020/06/24 13:56:40.413437, 3] ssh_packet_channel_success:  Received SSH_CHANNEL_SUCCESS on channel (43:0)
[2020/06/24 13:56:40.429060, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=16, in_blocks=47
[2020/06/24 13:56:40.429060, 2] channel_request:  Channel request pty-req success
[2020/06/24 13:56:40.429060, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=18, in_blocks=49
[2020/06/24 13:56:40.429060, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2020/06/24 13:56:40.429060, 3] packet_send2:  packet: wrote [type=98, len=48, padding_size=8, comp=39, payload=39]
[2020/06/24 13:56:40.429060, 3] channel_request:  Sent a SSH_MSG_CHANNEL_REQUEST window-change
[2020/06/24 13:56:40.429060, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=18, in_blocks=47
[2020/06/24 13:56:40.429060, 3] packet_send2:  packet: wrote [type=98, len=32, padding_size=16, comp=15, payload=15]
[2020/06/24 13:56:40.429060, 3] channel_request:  Sent a SSH_MSG_CHANNEL_REQUEST shell
[2020/06/24 13:56:40.429060, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2020/06/24 13:56:40.429060, 3] ssh_packet_socket_callback:  packet: read type 93 [len=16,padding=6,comp=9,payload=9]
[2020/06/24 13:56:40.429060, 3] ssh_packet_process:  Dispatching handler for packet type 93
[2020/06/24 13:56:40.444682, 2] channel_rcv_change_window:  Adding 2097152 bytes to channel (43:0) (from 0 bytes)
[2020/06/24 13:56:40.444682, 3] ssh_packet_socket_callback:  Processing 36 bytes left in socket buffer
[2020/06/24 13:56:40.444682, 3] ssh_packet_socket_callback:  packet: read type 99 [len=16,padding=10,comp=5,payload=5]
[2020/06/24 13:56:40.444682, 3] ssh_packet_process:  Dispatching handler for packet type 99
[2020/06/24 13:56:40.444682, 3] ssh_packet_channel_success:  Received SSH_CHANNEL_SUCCESS on channel (43:0)
[2020/06/24 13:56:40.444682, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=18, in_blocks=47
[2020/06/24 13:56:40.444682, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=18, in_blocks=47
[2020/06/24 13:56:40.444682, 2] channel_request:  Channel request shell success
 [2020/06/24 13:56:40.460325, 3] ssh_channel_read_timeout:  Read (1000) buffered : 0 bytes. Window: 64000
[2020/06/24 13:56:40.460325, 3] ssh_packet_socket_callback:  packet: read type 94 [len=32,padding=18,comp=13,payload=13]
[2020/06/24 13:56:40.460325, 3] ssh_packet_process:  Dispatching handler for packet type 94
[2020/06/24 13:56:40.460325, 3] channel_rcv_data:  Channel receiving 4 bytes data in 0 (local win=64000 remote win=2097152)

Exception which I ' getting while debugging is ""Unhandled exception at 0x7798a7e1 in LibsshTestClient.exe: 0xC0000005: Access violation reading location 0x00000004.""

Below is the line where this exception is getting raised. Call stack does not give much information. Exception dll lists.
nbytes = ssh_channel_read(channel, sshbuffer, sizeof(sshbuffer), 0);

Regards,
Nagraju
-----Original Message-----
From: Jakub Jelen <jjelen@xxxxxxxxxx>
Sent: Wednesday, June 24, 2020 1:00 AM
To: libssh@xxxxxxxxxx
Subject: Re: ssh_channel_read , throwing exception when SSH_OPTIONS_LOG_VERBOSITY is set to SSH_LOG_PACKET or SSH_LOG_FUNCTIONS

On Tue, 2020-06-23 at 16:09 +0000, V Sidnal, Nagraju wrote:
> Hi All,
> 
> If we are setting SSH_OPTIONS_LOG_VERBOSITY to SSH_LOG_PACKET or 
> SSH_LOG_FUNCTIONS. However it works fine for other log level.
> ssh_options_set(my_ssh_session, SSH_OPTIONS_LOG_VERBOSITY, 
> &verbosity);
> 
> ssh_channel_read() is throwing unhandled exception . Is this existing 
> bug or I m doing something wrong here.
> [cid:image001.png@01D649A6.C4548300]
> 
> 
> Please share your valuable inputs.

Can you run your code in debugger to get some more verbose information, backtrace or crash location?

Regards,
--
Jakub Jelen
Senior Software Engineer
Security Technologies
Red Hat, Inc.