Open kucharskim opened 1 month ago
When I enable logging via ssh.set_log_level(logging.DEBUG)
(as commented out above in test1.py
), I see this:
...
[2024/09/21 07:09:35.914803, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[2024/09/21 07:09:35.914841, 3] packet_send2: packet: wrote [type=50, len=1136, padding_size=5, comp=1130, payload=1130]
[2024/09/21 07:09:35.965620, 3] ssh_packet_socket_callback: packet: read type 52 [len=8,padding=6,comp=1,payload=1]
[2024/09/21 07:09:35.965631, 3] ssh_packet_process: Dispatching handler for packet type 52
[2024/09/21 07:09:35.965635, 3] ssh_packet_userauth_success: Authentication successful
[2024/09/21 07:09:35.965639, 3] ssh_packet_need_rekey: rekey: [data_rekey_needed=0, out_blocks=221, in_blocks=107]
ssh.is_connected=1
[2024/09/21 07:09:35.966108, 2] channel_open: Creating a channel 43 with 64000 window and 32768 max packet
[2024/09/21 07:09:35.966114, 3] ssh_packet_need_rekey: rekey: [data_rekey_needed=0, out_blocks=224, in_blocks=110]
[2024/09/21 07:09:35.966133, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[2024/09/21 07:09:35.966142, 3] packet_send2: packet: wrote [type=90, len=32, padding_size=7, comp=24, payload=24]
[2024/09/21 07:09:35.966146, 3] channel_open: Sent a SSH_MSG_CHANNEL_OPEN type session for channel 43
[2024/09/21 07:09:36.000845, 3] ssh_packet_socket_callback: packet: read type 80 [len=480,padding=4,comp=475,payload=475]
[2024/09/21 07:09:36.000860, 3] ssh_packet_process: Dispatching handler for packet type 80
[2024/09/21 07:09:36.000864, 2] ssh_packet_global_request: Received SSH_MSG_GLOBAL_REQUEST packet
[2024/09/21 07:09:36.000871, 2] ssh_packet_global_request: UNKNOWN SSH_MSG_GLOBAL_REQUEST hostkeys-00@openssh.com, want_reply = 0
[2024/09/21 07:09:36.000874, 3] ssh_packet_global_request: The requester doesn't want to know the request failed!
[2024/09/21 07:09:36.000879, 1] ssh_packet_global_request: Invalid SSH_MSG_GLOBAL_REQUEST packet
[2024/09/21 07:09:36.000882, 3] ssh_packet_socket_callback: Processing 280 bytes left in socket buffer
[2024/09/21 07:09:36.000889, 3] ssh_packet_socket_callback: packet: read type 4 [len=120,padding=7,comp=112,payload=112]
[2024/09/21 07:09:36.000892, 3] ssh_packet_process: Dispatching handler for packet type 4
[2024/09/21 07:09:36.000895, 2] ssh_packet_ignore_callback: Received SSH_MSG_DEBUG packet
[2024/09/21 07:09:36.000898, 3] ssh_packet_socket_callback: Processing 140 bytes left in socket buffer
[2024/09/21 07:09:36.000902, 3] ssh_packet_socket_callback: packet: read type 4 [len=120,padding=7,comp=112,payload=112]
[2024/09/21 07:09:36.000905, 3] ssh_packet_process: Dispatching handler for packet type 4
[2024/09/21 07:09:36.000908, 2] ssh_packet_ignore_callback: Received SSH_MSG_DEBUG packet
[2024/09/21 07:09:36.000911, 3] ssh_packet_need_rekey: rekey: [data_rekey_needed=0, out_blocks=224, in_blocks=194]
[2024/09/21 07:09:36.000914, 3] ssh_packet_need_rekey: rekey: [data_rekey_needed=0, out_blocks=224, in_blocks=194]
[2024/09/21 07:09:36.000917, 3] ssh_packet_need_rekey: rekey: [data_rekey_needed=0, out_blocks=224, in_blocks=194]
[2024/09/21 07:09:36.228678, 3] ssh_packet_socket_callback: packet: read type 91 [len=24,padding=6,comp=17,payload=17]
[2024/09/21 07:09:36.228691, 3] ssh_packet_process: Dispatching handler for packet type 91
[2024/09/21 07:09:36.228695, 3] ssh_packet_channel_open_conf: Received SSH2_MSG_CHANNEL_OPEN_CONFIRMATION
[2024/09/21 07:09:36.228699, 2] ssh_packet_channel_open_conf: Received a CHANNEL_OPEN_CONFIRMATION for channel 43:0
[2024/09/21 07:09:36.228702, 2] ssh_packet_channel_open_conf: Remote window : 0, maxpacket : 32768
[2024/09/21 07:09:36.228706, 3] ssh_packet_need_rekey: rekey: [data_rekey_needed=0, out_blocks=224, in_blocks=196]
Running uptime...
Executing exec_command()...
[2024/09/21 07:09:36.228773, 2] channel_open: Creating a channel 44 with 64000 window and 32768 max packet
[2024/09/21 07:09:36.228777, 3] ssh_packet_need_rekey: rekey: [data_rekey_needed=0, out_blocks=227, in_blocks=199]
[2024/09/21 07:09:36.228793, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[2024/09/21 07:09:36.228797, 3] packet_send2: packet: wrote [type=90, len=32, padding_size=7, comp=24, payload=24]
[2024/09/21 07:09:36.228800, 3] channel_open: Sent a SSH_MSG_CHANNEL_OPEN type session for channel 44
[2024/09/21 07:09:36.263447, 3] ssh_packet_socket_callback: packet: read type 91 [len=24,padding=6,comp=17,payload=17]
[2024/09/21 07:09:36.263460, 3] ssh_packet_process: Dispatching handler for packet type 91
[2024/09/21 07:09:36.263464, 3] ssh_packet_channel_open_conf: Received SSH2_MSG_CHANNEL_OPEN_CONFIRMATION
[2024/09/21 07:09:36.263467, 2] ssh_packet_channel_open_conf: Received a CHANNEL_OPEN_CONFIRMATION for channel 44:1
[2024/09/21 07:09:36.263470, 2] ssh_packet_channel_open_conf: Remote window : 0, maxpacket : 32768
[2024/09/21 07:09:36.263476, 3] ssh_packet_need_rekey: rekey: [data_rekey_needed=0, out_blocks=227, in_blocks=198]
[2024/09/21 07:09:36.263494, 3] ssh_packet_need_rekey: rekey: [data_rekey_needed=0, out_blocks=230, in_blocks=201]
[2024/09/21 07:09:36.263514, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[2024/09/21 07:09:36.263518, 3] packet_send2: packet: wrote [type=98, len=32, padding_size=7, comp=24, payload=24]
[2024/09/21 07:09:36.263522, 3] channel_request: Sent a SSH_MSG_CHANNEL_REQUEST exec
[2024/09/21 07:09:36.298556, 3] ssh_packet_socket_callback: packet: read type 93 [len=16,padding=6,comp=9,payload=9]
[2024/09/21 07:09:36.298568, 3] ssh_packet_process: Dispatching handler for packet type 93
[2024/09/21 07:09:36.298573, 2] channel_rcv_change_window: Adding 2097152 bytes to channel (44:1) (from 0 bytes)
[2024/09/21 07:09:36.298576, 3] ssh_packet_socket_callback: Processing 36 bytes left in socket buffer
[2024/09/21 07:09:36.298581, 3] ssh_packet_socket_callback: packet: read type 99 [len=16,padding=10,comp=5,payload=5]
[2024/09/21 07:09:36.298583, 3] ssh_packet_process: Dispatching handler for packet type 99
[2024/09/21 07:09:36.298587, 3] ssh_packet_channel_success: Received SSH_CHANNEL_SUCCESS on channel (44:1)
[2024/09/21 07:09:36.298590, 3] ssh_packet_need_rekey: rekey: [data_rekey_needed=0, out_blocks=230, in_blocks=199]
[2024/09/21 07:09:36.298593, 3] ssh_packet_need_rekey: rekey: [data_rekey_needed=0, out_blocks=230, in_blocks=199]
[2024/09/21 07:09:36.298597, 2] channel_request: Channel request exec success
[2024/09/21 07:09:36.298629, 3] ssh_packet_need_rekey: rekey: [data_rekey_needed=0, out_blocks=230, in_blocks=199]
[2024/09/21 07:09:36.298647, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[2024/09/21 07:09:36.298651, 3] packet_send2: packet: wrote [type=96, len=16, padding_size=10, comp=5, payload=5]
[2024/09/21 07:09:36.298654, 3] ssh_channel_send_eof: Sent a EOF on client channel (44:1)
[2024/09/21 07:09:36.303498, 3] ssh_packet_socket_callback: packet: read type 94 [len=88,padding=11,comp=76,payload=76]
[2024/09/21 07:09:36.303512, 3] ssh_packet_process: Dispatching handler for packet type 94
[2024/09/21 07:09:36.303517, 3] channel_rcv_data: Channel receiving 67 bytes data in 0 (local win=64000 remote win=2097152)
[2024/09/21 07:09:36.303521, 3] channel_default_bufferize: placing 67 bytes into channel buffer (stdout)
[2024/09/21 07:09:36.303527, 3] channel_rcv_data: Channel windows are now (local win=63933 remote win=2097152)
[2024/09/21 07:09:36.303538, 3] ssh_packet_need_rekey: rekey: [data_rekey_needed=0, out_blocks=231, in_blocks=209]
[2024/09/21 07:09:36.303548, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[2024/09/21 07:09:36.303552, 3] packet_send2: packet: wrote [type=93, len=16, padding_size=6, comp=9, payload=9]
[2024/09/21 07:09:36.303556, 2] grow_window: growing window (channel 44:1) to 1280000 bytes
[2024/09/21 07:09:36.303559, 3] ssh_packet_need_rekey: rekey: [data_rekey_needed=0, out_blocks=231, in_blocks=208]
[2024/09/21 07:09:36.303694, 3] ssh_packet_socket_callback: packet: read type 98 [len=32,padding=6,comp=25,payload=25]
[2024/09/21 07:09:36.303702, 3] ssh_packet_process: Dispatching handler for packet type 98
[2024/09/21 07:09:36.303708, 3] channel_rcv_request: received exit-status 0
[2024/09/21 07:09:36.303711, 3] ssh_packet_need_rekey: rekey: [data_rekey_needed=0, out_blocks=231, in_blocks=211]
[2024/09/21 07:09:36.303717, 3] ssh_packet_need_rekey: rekey: [data_rekey_needed=0, out_blocks=231, in_blocks=211]
[2024/09/21 07:09:36.303724, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[2024/09/21 07:09:36.303727, 3] packet_send2: packet: wrote [type=97, len=16, padding_size=10, comp=5, payload=5]
[2024/09/21 07:09:36.303731, 3] ssh_channel_close: Sent a close on client channel (44:1)
Executing exec_command()... done
stdout type: <class 'bytes'>
stdout:
7:09AM up 2 days, 3:50, 1 user, load averages: 0.06, 0.03, 0.00
stderr type: <class 'bytes'>
stderr:
return code: 0
Running ls...
Executing exec_command()...
[2024/09/21 07:09:36.303797, 2] channel_open: Creating a channel 45 with 64000 window and 32768 max packet
[2024/09/21 07:09:36.303802, 3] ssh_packet_need_rekey: rekey: [data_rekey_needed=0, out_blocks=234, in_blocks=214]
[2024/09/21 07:09:36.303808, 3] packet_send2: packet: wrote [type=90, len=32, padding_size=7, comp=24, payload=24]
[2024/09/21 07:09:36.303811, 3] channel_open: Sent a SSH_MSG_CHANNEL_OPEN type session for channel 45
[2024/09/21 07:09:36.303819, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
Segmentation fault (core dumped)
Version of remote SSH daemon (if that makes any difference):
$ nc -w5 -4 -v examplemachine1 22
Connection to examplemachine1 (xxx.xxx.xxx.xxx) 22 port [tcp/ssh] succeeded!
SSH-2.0-OpenSSH_9.7
@Jakuje ideas?
Having log level trace output (see #597) would help to investigate the issue. From the current debug log it is not clear what is going on. I can just guess from the backtrace, that after the first channel got closed, either the callback or something is probing the structure that might have been freed. Is there way to install debuginfo on openbsd to see some more information through gdb about variables that make it crash or does it look like crashing inside the cpython?
SUMMARY
On OpenBSD -current as of 2024-09-04 I have following backtrace from a core dump:
ISSUE TYPE
PYLISSH and LIBSSH VERSION
OS / ENVIRONMENT
STEPS TO REPRODUCE
EXPECTED RESULTS
Execution of below script should work all the time, but it code dumps intermittently.
ACTUAL RESULTS
Core dumps every now and then. Always on second command. First command always works.