SSH ping timeout

[awesomenode]

Hi!

Since updating from libnetconf2 2.1.40 version to the latest, I've noticed a change of behavior in one of the SSH client functionality.

I've attached the example, the client is in Java, and it's based on trilead-ssh2. I only use the SSH ping functionality to check if the server is still alive.

Ping sends a SSH_MSG_GLOBAL_REQUEST request ('trilead-ping') to the server and waits for the SSH_MSG_REQUEST_FAILURE reply packet from the server. According to RFC4254, the server should return SSH_MSG_REQUEST_FAILURE, instead it times out.

I could reproduce this using the latest netopeer2, and these are the verbose logs:

[INF]: LN: Accepted a connection on 0.0.0.0:830 from 127.0.0.1:60368. [INF]: LN: Received an SSH message "request-service" of subtype "ssh-userauth". [INF]: LN: Received an SSH message "request-auth" of subtype "none". [INF]: LN: Received an SSH message "request-auth" of subtype "password". [INF]: LN: User "admin" authenticated. [INF]: LN: Received an SSH message "request-channel-open" of subtype "session". [INF]: LN: Received an SSH message "request-channel" of subtype "subsystem". [2024/07/10 16:38:19.723316, 1] ssh_socket_exception_callback: Socket exception callback: 1 (0) [2024/07/10 16:38:19.723461, 1] ssh_socket_exception_callback: Socket error: disconnected [ERR]: LN: Session 8: SSH channel poll error (Socket error: disconnected).

It worked when I was using 2.1.40, and I used libssh 0.10.6 in both cases. Maybe something changed in libnetconf2 behavior that could've impacted this?

sshclient.zip

Thanks!

[michalvasko]

I am not aware of any intentional changes to this functionality, so I am not sure what can be wrong. There is nothing in the output about a global-request being received so my first suggestion would be to run the server with -c SSH to see information about all the SSH messages, which should provide clues as to what is happening.

[awesomenode]

Sure, here is the output with -c SSH:

[INF]: SR: Connection 4 created. [INF]: SR: Session 11 (user "root", CID 4) created. [INF]: SR: Triggering "ietf-netconf-server" "done" event on enabled data. [INF]: LN: Listening on 0.0.0.0:830 for SSH connections. [INF]: SR: Triggering "ietf-keystore" "done" event on enabled data. [INF]: SR: Triggering "ietf-truststore" "done" event on enabled data. [INF]: SR: Triggering "ietf-netconf-acm" "done" event on enabled data. [INF]: SR: Triggering "ietf-netconf-acm" "done" event on enabled data. [INF]: SR: Triggering "ietf-netconf-acm" "done" event on enabled data. [INF]: SR: Triggering "ietf-netconf-acm" "done" event on enabled data. [INF]: LN: Accepted a connection on 0.0.0.0:830 from 127.0.0.1:52770. [2024/07/22 09:52:51.410454, 2] ssh_pki_import_privkey_base64: Trying to decode privkey passphrase=false [2024/07/22 09:52:51.418878, 2] ssh_server_connection_callback: SSH client banner: SSH-2.0-TrileadSSH2Java_213 [2024/07/22 09:52:51.418920, 2] ssh_analyze_banner: Analyzing banner: SSH-2.0-TrileadSSH2Java_213 [2024/07/22 09:52:51.433571, 2] ssh_kex_select_methods: Negotiated diffie-hellman-group-exchange-sha256,rsa-sha2-256,aes256-ctr,aes256-ctr,hmac-sha2-512-etm@openssh.com,hmac-sha2-512-etm@openssh.com,none,none,, [2024/07/22 09:52:51.452253, 2] ssh_packet_server_dhgex_request: dh-gex: DHGEX_REQUEST[1024:2048:4096] [2024/07/22 09:52:51.453389, 2] ssh_retrieve_dhgroup_file: Selected 2048 bits modulus out of 63 candidates in 383 lines [2024/07/22 09:52:51.489085, 2] ssh_init_rekey_state: Set rekey after 4294967296 blocks [2024/07/22 09:52:51.489115, 2] ssh_init_rekey_state: Set rekey after 4294967296 blocks [2024/07/22 09:52:51.509887, 2] ssh_packet_newkeys: Received SSH_MSG_NEWKEYS [INF]: LN: Received an SSH message "request-service" of subtype "ssh-userauth". [INF]: LN: Received an SSH message "request-auth" of subtype "none". [INF]: LN: Received an SSH message "request-auth" of subtype "password". [INF]: LN: User "admin" authenticated. [INF]: LN: Received an SSH message "request-channel-open" of subtype "session". [INF]: LN: Received an SSH message "request-channel" of subtype "subsystem". [2024/07/22 09:53:21.592022, 1] ssh_socket_exception_callback: Socket exception callback: 1 (0) [2024/07/22 09:53:21.592105, 1] ssh_socket_exception_callback: Socket error: disconnected [ERR]: LN: Session 1: SSH channel poll error (Socket error: disconnected).

[michalvasko]

That does not say much, please update netopeer2 in the devel branch and try again, it should print more messages.

[awesomenode]

[INF]: SR: Connection 5 created. [INF]: SR: Session 19 (user "root", CID 5) created. [INF]: SR: Triggering "ietf-netconf-server" "done" event on enabled data. [INF]: LN: Listening on 0.0.0.0:830 for SSH connections. [INF]: SR: Triggering "ietf-keystore" "done" event on enabled data. [INF]: SR: Triggering "ietf-truststore" "done" event on enabled data. [INF]: SR: Triggering "ietf-netconf-acm" "done" event on enabled data. [INF]: SR: Triggering "ietf-netconf-acm" "done" event on enabled data. [INF]: SR: Triggering "ietf-netconf-acm" "done" event on enabled data. [INF]: SR: Triggering "ietf-netconf-acm" "done" event on enabled data. [INF]: LN: Accepted a connection on 0.0.0.0:830 from 127.0.0.1:48980. [2024/07/22 13:41:34.945141, 2] ssh_pki_import_privkey_base64: Trying to decode privkey passphrase=false [2024/07/22 13:41:34.946646, 3] ssh_socket_pollcallback: Received POLLOUT in connecting state [2024/07/22 13:41:34.946658, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 2 [2024/07/22 13:41:34.948766, 3] callback_receive_banner: Received banner: SSH-2.0-TrileadSSH2Java_213 [2024/07/22 13:41:34.948770, 2] ssh_server_connection_callback: SSH client banner: SSH-2.0-TrileadSSH2Java_213 [2024/07/22 13:41:34.948774, 2] ssh_analyze_banner: Analyzing banner: SSH-2.0-TrileadSSH2Java_213 [2024/07/22 13:41:34.948785, 3] packet_send2: packet: wrote [type=20, len=908, padding_size=4, comp=903, payload=903] [2024/07/22 13:41:34.948788, 3] ssh_send_kex: SSH_MSG_KEXINIT sent [2024/07/22 13:41:34.948843, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket [2024/07/22 13:41:34.948847, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 4 [2024/07/22 13:41:34.950919, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 4 [2024/07/22 13:41:34.953019, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 4 [2024/07/22 13:41:34.955126, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 4 [2024/07/22 13:41:34.957239, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 4 [2024/07/22 13:41:34.959351, 3] ssh_packet_socket_callback: packet: read type 20 [len=900,padding=6,comp=893,payload=893] [2024/07/22 13:41:34.959385, 3] ssh_packet_process: Dispatching handler for packet type 20 [2024/07/22 13:41:34.959419, 2] ssh_kex_select_methods: Negotiated diffie-hellman-group-exchange-sha256,rsa-sha2-256,aes256-ctr,aes256-ctr,hmac-sha2-512-etm@openssh.com,hmac-sha2-512-etm@openssh.com,none,none,, [2024/07/22 13:41:34.959435, 3] crypt_set_algorithms_server: Set output algorithm aes256-ctr [2024/07/22 13:41:34.959440, 3] crypt_set_algorithms_server: Set HMAC output algorithm to hmac-sha2-512-etm@openssh.com [2024/07/22 13:41:34.959445, 3] crypt_set_algorithms_server: Set input algorithm aes256-ctr [2024/07/22 13:41:34.959451, 3] crypt_set_algorithms_server: Set HMAC input algorithm to hmac-sha2-512-etm@openssh.com [2024/07/22 13:41:34.959457, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:34.961533, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:34.963630, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:34.965728, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:34.967829, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:34.969942, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:34.972063, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:34.974186, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:34.976308, 3] ssh_packet_socket_callback: packet: read type 34 [len=20,padding=6,comp=13,payload=13] [2024/07/22 13:41:34.976350, 3] ssh_packet_process: Dispatching handler for packet type 34 [2024/07/22 13:41:34.976364, 2] ssh_packet_server_dhgex_request: dh-gex: DHGEX_REQUEST[1024:2048:4096] [2024/07/22 13:41:34.977564, 2] ssh_retrieve_dhgroup_file: Selected 2048 bits modulus out of 63 candidates in 383 lines [2024/07/22 13:41:34.977672, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket [2024/07/22 13:41:34.977681, 3] packet_send2: packet: wrote [type=31, len=276, padding_size=8, comp=267, payload=267] [2024/07/22 13:41:34.977687, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:34.979762, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:34.981860, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:34.983973, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:34.986087, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:34.988193, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:34.990303, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:34.992404, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:34.994505, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:34.996604, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:34.998701, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:35.000785, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:35.002873, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:35.004976, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:35.007081, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:35.009198, 3] ssh_packet_socket_callback: packet: read type 32 [len=268,padding=5,comp=262,payload=262] [2024/07/22 13:41:35.009231, 3] ssh_packet_process: Dispatching handler for packet type 32 [2024/07/22 13:41:35.009239, 3] ssh_packet_server_dhgex_init: Received SSH_MSG_KEX_DHGEX_INIT [2024/07/22 13:41:35.018874, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket [2024/07/22 13:41:35.018909, 3] packet_send2: packet: wrote [type=33, len=836, padding_size=10, comp=825, payload=825] [2024/07/22 13:41:35.018916, 3] ssh_server_dh_process_init: Sent KEXDH[GEX]_REPLY [2024/07/22 13:41:35.018922, 3] packet_send2: packet: wrote [type=21, len=12, padding_size=10, comp=1, payload=1] [2024/07/22 13:41:35.018939, 2] ssh_init_rekey_state: Set rekey after 4294967296 blocks [2024/07/22 13:41:35.018944, 2] ssh_init_rekey_state: Set rekey after 4294967296 blocks [2024/07/22 13:41:35.019001, 3] ssh_packet_send_newkeys: SSH_MSG_NEWKEYS sent [2024/07/22 13:41:35.019022, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:35.021189, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket [2024/07/22 13:41:35.021217, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:35.023283, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:35.025355, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:35.027433, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:35.029555, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:35.031735, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:35.033903, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:35.035984, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:35.038085, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:35.040222, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 6 [2024/07/22 13:41:35.042336, 3] ssh_packet_socket_callback: packet: read type 21 [len=12,padding=10,comp=1,payload=1] [2024/07/22 13:41:35.042367, 3] ssh_packet_process: Dispatching handler for packet type 21 [2024/07/22 13:41:35.042376, 2] ssh_packet_newkeys: Received SSH_MSG_NEWKEYS [2024/07/22 13:41:35.042384, 3] ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 7 [2024/07/22 13:41:35.083279, 3] ssh_packet_socket_callback: packet: read type 5 [len=32,padding=14,comp=17,payload=17] [2024/07/22 13:41:35.083305, 3] ssh_packet_process: Dispatching handler for packet type 5 [2024/07/22 13:41:35.083311, 3] ssh_packet_service_request: Received a SERVICE_REQUEST for service ssh-userauth [2024/07/22 13:41:35.083317, 3] ssh_packet_socket_callback: Processing 116 bytes left in socket buffer [2024/07/22 13:41:35.083326, 3] ssh_packet_socket_callback: packet: read type 50 [len=48,padding=11,comp=36,payload=36] [2024/07/22 13:41:35.083332, 3] ssh_packet_process: Dispatching handler for packet type 50 [2024/07/22 13:41:35.083337, 3] ssh_packet_userauth_request: Auth request for service ssh-connection, method none for user 'admin' [INF]: LN: Received an SSH message "request-service" of subtype "ssh-userauth". [2024/07/22 13:41:35.083380, 3] ssh_message_service_reply_success: Sending a SERVICE_ACCEPT for service ssh-userauth [2024/07/22 13:41:35.083426, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket [2024/07/22 13:41:35.083435, 3] packet_send2: packet: wrote [type=6, len=28, padding_size=14, comp=17, payload=17] [INF]: LN: Received an SSH message "request-auth" of subtype "none". [2024/07/22 13:41:35.083622, 3] ssh_auth_reply_default: Sending a auth failure. methods that can continue: password [2024/07/22 13:41:35.083641, 3] packet_send2: packet: wrote [type=51, len=28, padding_size=17, comp=14, payload=14] [2024/07/22 13:41:35.083817, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket [2024/07/22 13:41:35.085417, 3] ssh_packet_socket_callback: packet: read type 50 [len=64,padding=13,comp=50,payload=50] [2024/07/22 13:41:35.085441, 3] ssh_packet_process: Dispatching handler for packet type 50 [2024/07/22 13:41:35.085450, 3] ssh_packet_userauth_request: Auth request for service ssh-connection, method password for user 'admin' [INF]: LN: Received an SSH message "request-auth" of subtype "password". [2024/07/22 13:41:35.085530, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket [2024/07/22 13:41:35.085540, 3] packet_send2: packet: wrote [type=52, len=12, padding_size=14, comp=1, payload=1] [INF]: LN: User "admin" authenticated. [2024/07/22 13:41:35.090581, 3] ssh_packet_socket_callback: packet: read type 90 [len=32,padding=7,comp=24,payload=24] [2024/07/22 13:41:35.090605, 3] ssh_packet_process: Dispatching handler for packet type 90 [2024/07/22 13:41:35.090613, 3] ssh_packet_channel_open: Clients wants to open a session channel [2024/07/22 13:41:35.090620, 3] ssh_packet_need_rekey: packet: [data_rekey_needed=0, out_blocks=1, in_blocks=7 [INF]: LN: Received an SSH message "request-channel-open" of subtype "session". [2024/07/22 13:41:35.090653, 3] ssh_message_channel_request_open_reply_accept_channel: Accepting a channel request_open for chan 100 [2024/07/22 13:41:35.090660, 3] ssh_packet_need_rekey: packet: [data_rekey_needed=0, out_blocks=2, in_blocks=8 [2024/07/22 13:41:35.090703, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket [2024/07/22 13:41:35.090711, 3] packet_send2: packet: wrote [type=91, len=28, padding_size=14, comp=17, payload=17] [2024/07/22 13:41:35.091969, 3] ssh_packet_socket_callback: packet: read type 98 [len=48,padding=17,comp=30,payload=30] [2024/07/22 13:41:35.091982, 3] ssh_packet_process: Dispatching handler for packet type 98 [2024/07/22 13:41:35.091990, 3] ssh_message_handle_channel_request: Received a subsystem channel_request for channel (43:100) (want_reply=1) [2024/07/22 13:41:35.091997, 3] ssh_packet_need_rekey: packet: [data_rekey_needed=0, out_blocks=2, in_blocks=8 [INF]: LN: Received an SSH message "request-channel" of subtype "subsystem". [2024/07/22 13:41:35.092026, 3] ssh_message_channel_request_reply_success: Sending a channel_request success to channel 100 [2024/07/22 13:41:35.092036, 3] ssh_packet_need_rekey: packet: [data_rekey_needed=0, out_blocks=2, in_blocks=8 [2024/07/22 13:41:35.092076, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket [2024/07/22 13:41:35.092085, 3] packet_send2: packet: wrote [type=99, len=12, padding_size=10, comp=5, payload=5] [2024/07/22 13:41:35.092168, 3] ssh_packet_need_rekey: packet: [data_rekey_needed=0, out_blocks=66, in_blocks=72 [2024/07/22 13:41:35.092189, 3] packet_send2: packet: wrote [type=94, len=1036, padding_size=12, comp=1027, payload=1027] [2024/07/22 13:41:35.092195, 3] channel_write_common: channel_write wrote 1018 bytes [2024/07/22 13:41:35.092214, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket [2024/07/22 13:41:35.092226, 3] ssh_packet_need_rekey: packet: [data_rekey_needed=0, out_blocks=129, in_blocks=71 [2024/07/22 13:41:35.092241, 3] packet_send2: packet: wrote [type=94, len=1020, padding_size=8, comp=1015, payload=1015] [2024/07/22 13:41:35.092248, 3] channel_write_common: channel_write wrote 1006 bytes [2024/07/22 13:41:35.092265, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket [2024/07/22 13:41:35.092277, 3] ssh_packet_need_rekey: packet: [data_rekey_needed=0, out_blocks=191, in_blocks=70 [2024/07/22 13:41:35.092291, 3] packet_send2: packet: wrote [type=94, len=1004, padding_size=14, comp=993, payload=993] [2024/07/22 13:41:35.092297, 3] channel_write_common: channel_write wrote 984 bytes [2024/07/22 13:41:35.092312, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket [2024/07/22 13:41:35.092319, 3] ssh_packet_need_rekey: packet: [data_rekey_needed=0, out_blocks=191, in_blocks=8 [2024/07/22 13:41:35.092332, 3] packet_send2: packet: wrote [type=94, len=28, padding_size=16, comp=15, payload=15] [2024/07/22 13:41:35.092338, 3] channel_write_common: channel_write wrote 6 bytes [2024/07/22 13:41:35.092351, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket [2024/07/22 13:41:35.093810, 3] ssh_packet_socket_callback: packet: read type 98 [len=32,padding=9,comp=22,payload=22] [2024/07/22 13:41:35.093826, 3] ssh_packet_process: Dispatching handler for packet type 98 [2024/07/22 13:41:35.093834, 3] ssh_message_handle_channel_request: Received a trilead-ping channel_request for channel (43:100) (want_reply=1) [2024/07/22 13:41:35.093840, 3] ssh_packet_need_rekey: packet: [data_rekey_needed=0, out_blocks=191, in_blocks=9 [2024/07/22 13:42:05.126065, 1] ssh_socket_exception_callback: Socket exception callback: 1 (0) [2024/07/22 13:42:05.126170, 1] ssh_socket_exception_callback: Socket error: disconnected [ERR]: LN: Session 1: SSH channel poll error (Socket error: disconnected).

[michalvasko]

[2024/07/22 13:41:35.093810, 3] ssh_packet_socket_callback: packet: read type 98 [len=32,padding=9,comp=22,payload=22] [2024/07/22 13:41:35.093826, 3] ssh_packet_process: Dispatching handler for packet type 98 [2024/07/22 13:41:35.093834, 3] ssh_message_handle_channel_request: Received a trilead-ping channel_request for channel (43:100) (want_reply=1) [2024/07/22 13:41:35.093840, 3] ssh_packet_need_rekey: packet: [data_rekey_needed=0, out_blocks=191, in_blocks=9

Seems to be the relevant log. Why no answer is sent I do not know and to fix this I would need to reproduce it. And since libssh does not support sending this message type on the client side, it would require using some other client, which all-in-all is a lot of effort that I do not currently have the time for.

So you can either take a look at this yourself or wait until we have enough spare time for this, sorry.

[michalvasko]

So I have taken a closer look at this and to reproduce I have used ssh(1). When enabling keep-alives, this was the server log:

[2024/07/30 12:01:16.909626, 3] ssh_packet_socket_callback:  packet: read type 80 [len=32,padding=4,comp=27,payload=27]
[2024/07/30 12:01:16.909686, 3] ssh_packet_process:  Dispatching handler for packet type 80
[2024/07/30 12:01:16.909702, 2] ssh_packet_global_request:  Received SSH_MSG_GLOBAL_REQUEST packet
[2024/07/30 12:01:16.909718, 2] ssh_packet_global_request:  Received keepalive@openssh.com 1
[2024/07/30 12:01:16.909732, 3] ssh_packet_need_rekey:  rekey: [data_rekey_needed=0, out_blocks=239, in_blocks=76]
[2024/07/30 12:01:16.909857, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2024/07/30 12:01:16.909883, 3] packet_send2:  packet: wrote [type=81, len=16, padding_size=14, comp=1, payload=1]
[2024/07/30 12:01:16.909899, 3] ssh_packet_need_rekey:  rekey: [data_rekey_needed=0, out_blocks=239, in_blocks=76]

Meaning replies were normally sent. The difference is that these were global-request messages, your client is sending special channel-request messages. Those seems to not be known and this code is being executed and the likely reason no reply is sent.

So, my guess is that you actually have updated your NETCONF client, which is now sending a different keep-alive messages, which are proprietary and not supported by libssh. If it was sending the global-request messages (as you say it was), it would work I believe.

[awesomenode]

The client version is the same, it is a channel-request though. Shouldn't the server still return SSH_MSG_REQUEST_FAILURE either way, according to RFC4254?

[michalvasko]

Well, I cannot say, it is fully handled by libssh. Please ask them.

[awesomenode]

In nc_ps_poll_session_io() if nc_session_ssh_msg() hasn't recognized the message, it doesn't return with anything. At least, that's what I've found so far. Maybe returning with ssh_message_reply_default() in that case would solve the issue.

[mpet]

@awesomenode could you share how you built to get the ssh traces?

[michalvasko]

I saw you have written to libssh mailing list but I think you can follow up with the output you posted here (and maybe add mine, too) and stress that it is not a global request being sent but a channel request. But whether a reply should be sent in both cases I cannot say. libssh people should know, though.

[mpet]

@michalvasko I will do. I noticed there are two ping classes but only one is used in ping()-method for trilead ssh2.

https://github.com/jenkinsci/trilead-ssh2/blob/main/src/com/trilead/ssh2/packets/PacketChannelTrileadPing.java

I checked https://www.rfc-editor.org/rfc/rfc4254.html#section-5

If 'want reply' is FALSE, no response will be sent to the request.
   Otherwise, the recipient responds with either
   SSH_MSG_CHANNEL_SUCCESS, SSH_MSG_CHANNEL_FAILURE, or request-specific
   continuation messages.  If the request is not recognized or is not
   supported for the channel, SSH_MSG_CHANNEL_FAILURE is returned.

So I would say at least a SSH_MSG_CHANNEL_FAILURE.

[michalvasko]

Seems reasonable, reply with all this information in the libssh mail thread. It is the feature (bug) of the library that it ignores channel requests but replies to global requests.

[awesomenode]

@awesomenode could you share how you built to get the ssh traces?

I just started netopeer2-server with the -c SSH flag.

[mpet]

@michalvasko there is no reply yet so maybe I should submit a bug?

[michalvasko]

There has been just now, they will fix it.

[mpet]

@michalvasko is TRACE included in -c SSH option?

"Correct, this is part of libssh and looks like the message type was not correctly set. Can you provide the server TRACE (log level 4) logs processing this message -- there should be much more than this one? There should be more messages when the packet is received and processed which should give us an idea about the code path that is being taken and why."

//mike

[michalvasko]

Saw the email and no, libssh trace level is not supported because you do not want it normally, it prints an unreasonable amount of messages. Use this netopeer2 patch to enable it in this specific case.

[mpet]

@michalvasko should I still use this one suggested here: https://github.com/CESNET/netopeer2/issues/1635#issuecomment-2317547130

[mpet]

@michalvasko it seems to fail to apply netopeer2 patch

I tried patch in https://github.com/CESNET/netopeer2/issues/1635#issuecomment-2317547130 and it works to apply.

[michalvasko]

Okay, you are probably using the master branch so please just open the patch and apply it yourself (change the code), it is trivial. Then run the server with -c SSH and you should see trace output as well. What you posted to libssh mailing list is without it.

[mpet]

I use development branch since @Roytak recommended me to use it. I do everything by commands to build a dockerfile to run netopeer2 so I cannot apply it manually. I will have to check if I can find another way around this.

[michalvasko]

Then I do not understand why does it not apply, I have used the clean devel branch of netopeer2 to create it.

[mpet]

I am trying to apply to devel branch on netopeer2

This what I see in the file:

Then I apply to the docker image ( adding unix LF).

RUN echo $ 'diff --git a/src/main.c b/src/main.c\n\
index 9a161af..9d056bd 100644\n\
--- a/src/main.c\n\
+++ b/src/main.c\n\
@@ -1372,7 +1372,7 @@ main(int argc, char *argv[])\n\
                     np2_verbose_level = NC_VERB_DEBUG_LOWLVL;\n\
 # ifdef NC_ENABLED_SSH_TLS\n\
                 } else if (!strcmp(ptr, "SSH")) {\n\
-                    np2_libssh_verbose_level = 3;\n\
+                    np2_libssh_verbose_level = 4;\n\
 # endif\n\
                 } else if (!strcmp(ptr, "SYSREPO")) {\n\
                     np2_sr_verbose_level = SR_LL_DBG;\n' > /home/netconf/libssh_trace.patch

# netopeer2
RUN \
      cd /opt/dev && \
      git clone https://github.com/CESNET/Netopeer2.git && cd Netopeer2 && \
      #git checkout tags/v2.2.28 && \
      git checkout devel && \
      git apply /home/netconf/libssh_trace.patch && \
      mkdir build && cd build && \
      #cmake -DNACM_RECOVERY_UID=102 -DCMAKE_INSTALL_PREFIX:PATH=/usr -DCMAKE_BUILD_TYPE:String="Debug" .. && \
      cmake -DNACM_RECOVERY_UID=102 -DCMAKE_INSTALL_PREFIX:PATH=/usr .. && \
      make -j2 && \
      make install

Building docker image gives:

2024-09-04 13:51:36,917 (BuildImageResultCallback.java:34) DEBUG : BuildResponseItem()
2024-09-04 13:51:36,917 (ImageFromDockerfile.java:106) DEBUG : Branch 'devel' set up to track remote branch 'devel' from 'origin'.
2024-09-04 13:51:36,917 (Wire.java:92) DEBUG : http-outgoing-0 << "43[\r][\n]"
2024-09-04 13:51:36,917 (Wire.java:92) DEBUG : http-outgoing-0 << "{"stream":"\u001b[91merror: corrupt patch at line 12\n\u001b[0m"}[\r][\n]"
2024-09-04 13:51:36,918 (Wire.java:92) DEBUG : http-outgoing-0 << "[\r][\n]"
2024-09-04 13:51:36,918 (BuildImageResultCallback.java:34) DEBUG : BuildResponseItem()
2024-09-04 13:51:36,918 (ImageFromDockerfile.java:106) DEBUG : error: corrupt patch at line 12

I am not expecting you to know how to build docker image. Could you share pic so I can see LF in your git ps.

//mike

[michalvasko]

The patch I posted I have created on Linux. Do not modify it, just apply it.

[mpet]

I found the issue. I used single quotes around the "echoed" string that was "redirected" to file. I should use double quotes since # would not be treated correct. I will re-run with correct trace level and post to libssh mailing-list.

[mpet]

@michalvasko there was a post in libssh mailing-list but I am guessing you will check and answer.

[mpet]

@michalvasko main.c devel has been changed. Can you send a new patch?

[michalvasko]

Fine, but it should not be a problem to write your own. libssh_trace.patch.txt

[mpet]

no sure which command you used to create it. I tried git apply /home/netconf/libssh_trace.patch with the content of above file and it failed.

Anyway I solved it with a simple sed to replace the string and set it to 4 so now I have the trace. I posted in mailing-list for libssh.org and attached the file to my post.

I will add it here as well.

log-issue-libneconf2-494-2.txt

[mpet]

@michalvasko what is happening now?

[michalvasko]

I would wait for a reply on the libssh mailing list, we will see afterwards.

[mpet]

I am trying to build we the patch Jakub suggested.

RUN \
      cd /opt/dev && \
      git clone https://github.com/CESNET/libnetconf2.git && \
      #cd libnetconf2 && git checkout tags/v3.3.3 && mkdir build && cd build && \
      cd libnetconf2 && git checkout devel && \
      git apply /home/netconf/session_server.patch && \
      mkdir build && cd build && \
      #cmake  -DCMAKE_BUILD_TYPE:String="Debug" -DCMAKE_INSTALL_PREFIX:PATH=/usr -DENABLE_TESTS=ON .. && \
      cmake -DENABLE_TESTS=OFF .. &&\
      make -j2 && \
      make install && \
      ldconfig

but I get this message:

2024-09-06 09:52:27,642 (Wire.java:92) DEBUG : http-outgoing-0 << "{"stream":"\u001b[91mCMake Error at /usr/share/cmake-3.22/Modules/FindPackageHandleStandardArgs.cmake:230 (message):\n Could NOT find LibNETCONF2: Found unsuitable version \"4.3.6\", but required\n is at least \"4.4.0\" (found /usr/local/lib/libnetconf2.so)\nCall Stack (most recent call first):\n /usr/share/cmake-3.22/Modules/FindPackageHandleStandardArgs.cmake:592 (_FPHSA_FAILURE_MESSAGE)\n CMakeModules/FindLibNETCONF2.cmake:89 (find_package_handle_standard_args)\n CMakeLists.txt:228 (find_package)\n\n\u001b[0m"}[\r][\n]" 2024-09-06 09:52:27,643 (Wire.java:92) DEBUG : http-outgoing-0 << "[\r][\n]" 2024-09-06 09:52:27,643 (BuildImageResultCallback.java:34) DEBUG : BuildResponseItem() 2024-09-06 09:52:27,643 (ImageFromDockerfile.java:106) DEBUG : CMake Error at /usr/share/cmake-3.22/Modules/FindPackageHandleStandardArgs.cmake:230 (message): Could NOT find LibNETCONF2: Found unsuitable version "4.3.6", but required is at least "4.4.0" (found /usr/local/lib/libnetconf2.so) Call Stack (most recent call first): /usr/share/cmake-3.22/Modules/FindPackageHandleStandardArgs.cmake:592 (_FPHSA_FAILURE_MESSAGE) CMakeModules/FindLibNETCONF2.cmake:89 (find_package_handle_standard_args) CMakeLists.txt:228 (find_package)

Has cmake been upgraded? Or is there any other reason I cannot build?

//mike

[michalvasko]

The devel version of libnetconf2 is 4.4.0 so I cannot help you. I do not have a good experience with docker and I am not using it so I cannot help. Seems that for some reason an older version is still installed.

[mpet]

@michalvasko managed to deliver a new log with the required patch applied.

[mpet]

Yes it works. So there will be a new release of libnetconf2? No changes in Netopeer2?

[michalvasko]

Yes, there will be a new release of libnetconf2 at some point, just like of all the other projects. Should be quite soon.

[mpet]

ok sounds great since we use neetopeer2/libnetconf2 in our CI machinery and needs to use fixed versions.