Here you go (attached). Cheers Till
May 23, 2025 9:50 AM, "Jakub Jelen" <[email protected] (mailto:[email protected]?to=%22Jakub%20Jelen%22%20<[email protected]>)> wrote: That should not be the case. The server should be sending this message from the `session->ssh_connection_callback` so unless you override that one, it should be executed (and that one is not designed to be overridden). Can you get the debug logs from the server for one connection to see what is going on there? Jakub On Thu, May 22, 2025 at 11:34 PM <[email protected] (mailto:[email protected])> wrote: On 5/22/25 12:38, Jakub Jelen wrote:On Wed, May 21, 2025 at 4:26 PM <[email protected] (mailto:[email protected])> wrote: On 5/21/25 15:53, Jakub Jelen wrote: On Wed, May 21, 2025 at 1:43 PM <[email protected] (mailto:[email protected])> wrote: Hi On 5/21/25 09:44, Jakub Jelen wrote: Hi, the strace does not show much what libssh does. It just confirms the check is failing locally, without sending the public key to server. But the signature algorithm depends on the extensions negotiated during key exchange, which should be logged in verbose log. I meant setting the log level using something like this: int verbosity = SSH_LOG_TRACE; ssh_options_set(session, SSH_OPTIONS_LOG_VERBOSITY, &verbosity); Ah sure, but you don't need strace to read the log ;) I disabled it on purpose so you see the essential filehandling... Here you go again (attached). I think this was still log level 3, while to get all of the tracing information and packet numbers, log level 4 is required. I'm confused about how ssh_options_set(session, SSH_OPTIONS_LOG_VERBOSITY, ...) and ssh_set_log_level() is connected. I used ssh_set_log_level(SSH_LOG_PACKET) - this is not equal to ssh_options_set() with SSH_LOG_TRACE? Sorry, the names are a bit confusing. The SSH_LOG_PACKET = SSH_LOG_DEBUG is 3, while SSH_LOG_TRACE = SSH_LOG_FUNCTIONS is 4. These aliased names have quite conflicting descriptions (and I am not even sure why we have them twice). It would be good to make it a bit more systematic ... My bad, for some reason I put SSH_LOG_PACKET instead of SSH_LOG_FUNCTIONS. Yes I was always wondering why there are these two different naming schemes... Maybe there were plans to have some kind of scopes besides the levels. Ah wait I see the issue: I called ssh_set_log_level() after ssh_new(). I guess that makes the difference. New log attached. I am still trying to figure out if the extensions are negotiated and sent correctly to see if it is server or client issue. This is still not visible from this log. I think the code to handle this is already in 0.9.7, but it might be also affected by some configuration/options on the server side. It is also possible that the global configuration from cryptographic policies overrides the `SSH_OPTIONS_PUBLICKEY_ACCEPTED_TYPES`. The strace log shows that the OpenSSH configuration is read before connecting: openat(AT_FDCWD, "/etc/crypto-policies/back-ends/openssh.config", O_RDONLY) = 5 This file does not have the ssh-rsa (SHA1) mechanisms in accepted types: $ cat /etc/crypto-policies/back-ends/openssh.config | grep ssh-rsa If this is the case, is there a option to keep libssh from reading systemwide configs? In my case that would be neater than enabling SHA for the whole system... There is SSH_OPTIONS_PROCESS_CONFIG in ssh_options_set(), which if set to false, will not process any system configuration. https://api.libssh.org/master/group__libssh__session.html#ga7a801b85800baa3f4e16f5b47db0a73d (https://api.libssh.org/master/group__libssh__session.html#ga7a801b85800baa3f4e16f5b47db0a73d) Yes! That did the trick: [2025/05/21 16:16:49.030307, 3] ssh_packet_need_rekey: rekey: [data_rekey_needed=0, out_blocks=61, in_blocks=45] [2025/05/21 16:16:49.030405, 2] ssh_userauth_publickey_auto: Successfully authenticated using /home/useruser/id_rsa Connected and authenticated with key! Cheers Till Good to hear it worked. Looking at the log, I see the client correctly advertises the support for the extensions: [2025/05/21 16:12:17.052133, 4] ssh_list_kex: kex algos: curve25519-sha256,[email protected] (mailto:[email protected]),ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,ext-info-c But I do not see the server sending the SSH_MSG_EXT_INFO packet (RFC 8308) so its likely the server to blame for this issue. Updating to newer libssh would be good to get the newer functionality and bugfixes. I wrote the server 6 (?) years ago... But looking at the sources of libbssh 0.9.7 I can find the handling of SSH_MSG_EXT_INFO in ssh_server_connection_callback() (server.c:431). Maybe I overwrote the callback? I set the server callbacks here: struct ssh_server_callbacks_struct cb = { .userdata = &info, #ifdef WITH_PASSWORD .auth_password_function = auth_password, #endif #ifdef WITH_GSSAPI .auth_gssapi_mic_function = auth_gssapi_mic, #endif #ifdef WITH_PUBKEY .auth_pubkey_function = auth_publickey, #endif .channel_open_request_session_function = new_session_channel, .service_request_function = service_request }; All other custom callback functions are on channel level... Wait, there's also a custom message_callback(). But this only handles ssh_message_type(message) == SSH_REQUEST_CHANNEL_OPEN. In any other case it returns 1 (hence the lib should handle all other messages). Cheers, Till
[2025/05/23 14:02:12.077604, 4] 10.10.10.133 - === per_conn_thread: Thread 0x5 started. [2025/05/23 14:02:12.077604, 4] 10.10.10.133 - === connect_thread_worker: Thread 0x6 started. [2025/05/23 14:02:12.077604, 4] 10.10.10.133 - ssh_socket_pollcallback: Poll callback on socket 616 (POLLIN POLLOUT ), out buffer 22 [2025/05/23 14:02:12.077604, 3] 10.10.10.133 - ssh_socket_pollcallback: Received POLLOUT in connecting state [2025/05/23 14:02:12.077604, 4] 10.10.10.133 - ssh_socket_pollcallback: Poll callback on socket 616 (POLLIN POLLOUT ), out buffer 22 [2025/05/23 14:02:12.077604, 3] 10.10.10.133 - callback_receive_banner: Received banner: SSH-2.0-libssh_0.10.4 [2025/05/23 14:02:12.077604, 2] 10.10.10.133 - ssh_server_connection_callback: SSH client banner: SSH-2.0-libssh_0.10.4 [2025/05/23 14:02:12.077604, 2] 10.10.10.133 - ssh_analyze_banner: Analyzing banner: SSH-2.0-libssh_0.10.4 [2025/05/23 14:02:12.077604, 4] 10.10.10.133 - ssh_send_kex: Sending KEXINIT packet, first_kex_packet_follows = 0 [2025/05/23 14:02:12.077604, 4] 10.10.10.133 - ssh_list_kex: kex algos: curve25519-sha256,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group18-sha512,diffie-hellman-group16-sha512,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1 [2025/05/23 14:02:12.077604, 4] 10.10.10.133 - ssh_list_kex: server host key algo: rsa-sha2-512,rsa-sha2-256,ssh-rsa [2025/05/23 14:02:12.077604, 4] 10.10.10.133 - ssh_list_kex: encryption client->server: [email protected],[email protected],aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,3des-cbc [2025/05/23 14:02:12.077604, 4] 10.10.10.133 - ssh_list_kex: encryption server->client: [email protected],[email protected],aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,3des-cbc [2025/05/23 14:02:12.077604, 4] 10.10.10.133 - ssh_list_kex: mac algo client->server: [email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [2025/05/23 14:02:12.077604, 4] 10.10.10.133 - ssh_list_kex: mac algo server->client: [email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [2025/05/23 14:02:12.077604, 4] 10.10.10.133 - ssh_list_kex: compression algo client->server: none [2025/05/23 14:02:12.077604, 4] 10.10.10.133 - ssh_list_kex: compression algo server->client: none [2025/05/23 14:02:12.077604, 4] 10.10.10.133 - ssh_list_kex: languages client->server: [2025/05/23 14:02:12.077604, 4] 10.10.10.133 - ssh_list_kex: languages server->client: [2025/05/23 14:02:12.077604, 3] 10.10.10.133 - packet_send2: packet: wrote [type=20, len=884, padding_size=9, comp=874, payload=874] [2025/05/23 14:02:12.077604, 3] 10.10.10.133 - ssh_send_kex: SSH_MSG_KEXINIT sent [2025/05/23 14:02:12.077604, 3] 10.10.10.133 - ssh_socket_unbuffered_write: Enabling POLLOUT for socket [2025/05/23 14:02:12.077604, 4] 10.10.10.133 - ssh_socket_pollcallback: Poll callback on socket 616 (POLLOUT ), out buffer 0 [2025/05/23 14:02:12.077604, 4] 10.10.10.133 - ssh_socket_pollcallback: sending control flow event [2025/05/23 14:02:12.077604, 4] 10.10.10.133 - ssh_packet_socket_controlflow_callback: sending channel_write_wontblock callback [2025/05/23 14:02:12.093877, 4] 10.10.10.133 - ssh_socket_pollcallback: Poll callback on socket 616 (POLLIN ), out buffer 0 [2025/05/23 14:02:12.093877, 3] 10.10.10.133 - ssh_packet_socket_callback: packet: read type 20 [len=900,padding=7,comp=892,payload=892] [2025/05/23 14:02:12.093877, 3] 10.10.10.133 - ssh_packet_process: Dispatching handler for packet type 20 [2025/05/23 14:02:12.093877, 4] 10.10.10.133 - ssh_packet_kexinit: KEXINIT received [2025/05/23 14:02:12.093877, 3] 10.10.10.133 - ssh_packet_kexinit: The client supports extension negotiation. Enabled signature algorithms: SHA512 [2025/05/23 14:02:12.093877, 4] 10.10.10.133 - ssh_list_kex: kex algos: curve25519-sha256,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,ext-info-c [2025/05/23 14:02:12.093877, 4] 10.10.10.133 - ssh_list_kex: server host key algo: ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256 [2025/05/23 14:02:12.093877, 4] 10.10.10.133 - ssh_list_kex: encryption client->server: [email protected],[email protected],aes256-ctr,[email protected],aes128-ctr [2025/05/23 14:02:12.093877, 4] 10.10.10.133 - ssh_list_kex: encryption server->client: [email protected],[email protected],aes256-ctr,[email protected],aes128-ctr [2025/05/23 14:02:12.093877, 4] 10.10.10.133 - ssh_list_kex: mac algo client->server: [email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha1,hmac-sha2-512 [2025/05/23 14:02:12.093877, 4] 10.10.10.133 - ssh_list_kex: mac algo server->client: [email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha1,hmac-sha2-512 [2025/05/23 14:02:12.093877, 4] 10.10.10.133 - ssh_list_kex: compression algo client->server: none,[email protected],zlib [2025/05/23 14:02:12.093877, 4] 10.10.10.133 - ssh_list_kex: compression algo server->client: none,[email protected],zlib [2025/05/23 14:02:12.093877, 4] 10.10.10.133 - ssh_list_kex: languages client->server: [2025/05/23 14:02:12.093877, 4] 10.10.10.133 - ssh_list_kex: languages server->client: [2025/05/23 14:02:12.093877, 2] 10.10.10.133 - ssh_kex_select_methods: Negotiated curve25519-sha256,rsa-sha2-512,[email protected],[email protected],aead-gcm,aead-gcm,none,none,, [2025/05/23 14:02:12.093877, 3] 10.10.10.133 - crypt_set_algorithms_server: Set output algorithm [email protected] [2025/05/23 14:02:12.093877, 3] 10.10.10.133 - crypt_set_algorithms_server: Set HMAC output algorithm to aead-gcm [2025/05/23 14:02:12.093877, 3] 10.10.10.133 - crypt_set_algorithms_server: Set input algorithm [email protected] [2025/05/23 14:02:12.093877, 3] 10.10.10.133 - crypt_set_algorithms_server: Set HMAC input algorithm to aead-gcm [2025/05/23 14:02:12.140109, 4] 10.10.10.133 - ssh_socket_pollcallback: Poll callback on socket 616 (POLLIN ), out buffer 0 [2025/05/23 14:02:12.140109, 3] 10.10.10.133 - ssh_packet_socket_callback: packet: read type 30 [len=44,padding=6,comp=37,payload=37] [2025/05/23 14:02:12.140109, 3] 10.10.10.133 - ssh_packet_process: Dispatching handler for packet type 30 [2025/05/23 14:02:12.140109, 3] 10.10.10.133 - ssh_packet_kexdh_init: Received SSH_MSG_KEXDH_INIT [2025/05/23 14:02:12.140109, 3] 10.10.10.133 - ssh_packet_kexdh_init: Calling next KEXDH handler [2025/05/23 14:02:12.155371, 2] 10.10.10.133 - ssh_packet_server_curve25519_init: SSH_MSG_KEX_ECDH_REPLY sent [2025/05/23 14:02:12.155371, 3] 10.10.10.133 - ssh_socket_unbuffered_write: Enabling POLLOUT for socket [2025/05/23 14:02:12.155371, 3] 10.10.10.133 - packet_send2: packet: wrote [type=31, len=612, padding_size=11, comp=600, payload=600] [2025/05/23 14:02:12.155371, 3] 10.10.10.133 - packet_send2: packet: wrote [type=21, len=12, padding_size=10, comp=1, payload=1] [2025/05/23 14:02:12.155371, 4] 10.10.10.133 - ssh_packet_set_newkeys: called, direction = OUT [2025/05/23 14:02:12.155371, 2] 10.10.10.133 - ssh_init_rekey_state: Set rekey after 4294967296 blocks [2025/05/23 14:02:12.155371, 2] 10.10.10.133 - ssh_init_rekey_state: Set rekey after 4294967296 blocks [2025/05/23 14:02:12.155371, 2] 10.10.10.133 - ssh_packet_server_curve25519_init: SSH_MSG_NEWKEYS sent [2025/05/23 14:02:12.155371, 4] 10.10.10.133 - ssh_socket_pollcallback: Poll callback on socket 616 (POLLOUT ), out buffer 16 [2025/05/23 14:02:12.155371, 3] 10.10.10.133 - ssh_socket_unbuffered_write: Enabling POLLOUT for socket [2025/05/23 14:02:12.155371, 4] 10.10.10.133 - ssh_socket_pollcallback: Poll callback on socket 616 (POLLOUT ), out buffer 0 [2025/05/23 14:02:12.155371, 4] 10.10.10.133 - ssh_socket_pollcallback: sending control flow event [2025/05/23 14:02:12.155371, 4] 10.10.10.133 - ssh_packet_socket_controlflow_callback: sending channel_write_wontblock callback [2025/05/23 14:02:12.155371, 4] 10.10.10.133 - ssh_socket_pollcallback: Poll callback on socket 616 (POLLIN ), out buffer 0 [2025/05/23 14:02:12.155371, 3] 10.10.10.133 - ssh_packet_socket_callback: packet: read type 21 [len=12,padding=10,comp=1,payload=1] [2025/05/23 14:02:12.155371, 3] 10.10.10.133 - ssh_packet_process: Dispatching handler for packet type 21 [2025/05/23 14:02:12.155371, 2] 10.10.10.133 - ssh_packet_newkeys: Received SSH_MSG_NEWKEYS [2025/05/23 14:02:12.155371, 4] 10.10.10.133 - ssh_packet_set_newkeys: called, direction = IN [2025/05/23 14:02:12.155371, 3] 10.10.10.133 - ssh_server_send_extensions: Sending SSH_MSG_EXT_INFO [2025/05/23 14:02:12.155371, 3] 10.10.10.133 - ssh_socket_unbuffered_write: Enabling POLLOUT for socket [2025/05/23 14:02:12.155371, 3] 10.10.10.133 - packet_send2: packet: wrote [type=7, len=432, padding_size=8, comp=423, payload=423] [2025/05/23 14:02:12.155371, 3] 10.10.10.133 - ssh_handle_key_exchange: ssh_handle_key_exchange: current state : 7 [2025/05/23 14:02:12.155371, 4] 10.10.10.133 - ssh_socket_pollcallback: Poll callback on socket 616 (POLLOUT ), out buffer 0 [2025/05/23 14:02:12.155371, 4] 10.10.10.133 - ssh_socket_pollcallback: sending control flow event [2025/05/23 14:02:12.155371, 4] 10.10.10.133 - ssh_packet_socket_controlflow_callback: sending channel_write_wontblock callback [2025/05/23 14:02:12.155371, 4] 10.10.10.133 - ssh_socket_pollcallback: Poll callback on socket 616 (POLLIN ), out buffer 0 [2025/05/23 14:02:12.155371, 3] 10.10.10.133 - ssh_packet_socket_callback: packet: read type 1 [len=32,padding=11,comp=20,payload=20] [2025/05/23 14:02:12.155371, 3] 10.10.10.133 - ssh_packet_process: Dispatching handler for packet type 1 [2025/05/23 14:02:12.155371, 3] 10.10.10.133 - ssh_packet_disconnect_callback: Received SSH_MSG_DISCONNECT 11:Bye Bye [2025/05/23 14:02:12.155371, 1] 10.10.10.133 - ssh_packet_disconnect_callback: Received SSH_MSG_DISCONNECT: 11:Bye Bye [2025/05/23 14:02:12.155371, 1] 10.10.10.133 - === per_conn_thread: ssh_event_dopoll (before authentication) failed: Received SSH_MSG_DISCONNECT: 11:Bye Bye [2025/05/23 14:02:12.155371, 2] 10.10.10.133 - === per_conn_thread: Closing session. [2025/05/23 14:02:12.202603, 4] 10.10.10.133 - === connect_thread_worker: Thread 0x6 (connect loop) ended. sockets_cnt = 0 [2025/05/23 14:02:12.202603, 4] 10.10.10.133 - === per_conn_thread: Thread 0x5 (session event loop) ended.
