[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
bug#58290: guile ssh error on guix deploy
From: |
Artyom V. Poptsov |
Subject: |
bug#58290: guile ssh error on guix deploy |
Date: |
Sun, 22 Jan 2023 23:00:20 +0300 |
User-agent: |
Gnus/5.13 (Gnus v5.13) Emacs/28.2 (gnu/linux) |
Hello Ludovic, Andrew and all,
thank you for reporting the bug!
The code for reproducing the bug was very helpful indeed, I just
slightly modified the it:
--8<---------------cut here---------------start------------->8---
(use-modules (ssh session)
(ssh popen)
(ssh auth)
(ssh log)
(rnrs io ports))
(define session
(make-session #:host "localhost"))
(define (main args)
(session-parse-config! session)
(connect! session)
(userauth-public-key/auto! session)
(set-log-verbosity! 'functions)
(let loop ((i 0))
(format (current-error-port) "-- ~a --~%" i)
(let ((pipe (open-remote-pipe session "date" "r")))
(pk 'x (get-string-all pipe))
(close-port pipe)
(loop (+ 1 i)))))
--8<---------------cut here---------------end--------------->8---
It seems to me that the reason Guile-SSH fails at least partly lies in
changes that were introduced in OpenSSH 5.1.
I set "LogLevel" to "DEBUG3" and ran the test code. System logs have
shown the following error:
--8<---------------cut here---------------start------------->8---
янв 22 22:40:06 elephant sshd[131488]: debug3: channel 8: will not send data
after close
янв 22 22:40:06 elephant sshd[131488]: debug3: channel 9: will not send data
after close
янв 22 22:40:06 elephant sshd[131488]: debug2: channel 9: rcvd adjust 1216033
янв 22 22:40:06 elephant sshd[131488]: debug3: channel 0: will not send data
after close
янв 22 22:40:06 elephant sshd[131488]: debug3: channel 1: will not send data
after close
янв 22 22:40:06 elephant sshd[131488]: debug3: channel 2: will not send data
after close
янв 22 22:40:06 elephant sshd[131488]: debug3: channel 3: will not send data
after close
янв 22 22:40:06 elephant sshd[131488]: debug3: channel 4: will not send data
after close
янв 22 22:40:06 elephant sshd[131488]: debug3: channel 5: will not send data
after close
янв 22 22:40:06 elephant sshd[131488]: debug3: channel 6: will not send data
after close
янв 22 22:40:06 elephant sshd[131488]: debug3: channel 7: will not send data
after close
янв 22 22:40:06 elephant sshd[131488]: debug3: channel 8: will not send data
after close
янв 22 22:40:06 elephant sshd[131488]: debug3: channel 9: will not send data
after close
янв 22 22:40:06 elephant sshd[131488]: debug3: receive packet: type 90
янв 22 22:40:06 elephant sshd[131488]: debug1: server_input_channel_open: ctype
session rchan 53 win 64000 max 32768
янв 22 22:40:06 elephant sshd[131488]: debug1: input_session_request
янв 22 22:40:06 elephant sshd[131488]: debug2: channel: expanding 20
янв 22 22:40:06 elephant sshd[131488]: debug1: channel 10: new [server-session]
янв 22 22:40:06 elephant sshd[131488]: debug1: session_open: channel 10
янв 22 22:40:06 elephant sshd[131488]: error: no more sessions
--8<---------------cut here---------------end--------------->8---
This "no more sessions" error was the key to understanding the problem.
Here's an excerpt from OpenSSH 5.1 changelog [1]:
--8<---------------cut here---------------start------------->8---
Changes since OpenSSH 5.0
=========================
[...]
* Added a MaxSessions option to sshd_config(5) to allow control of the
number of multiplexed sessions supported over a single TCP connection.
This allows increasing the number of allowed sessions above the
previous default of 10, disabling connection multiplexing
(MaxSessions=1) or disallowing login/shell/subsystem sessions
entirely (MaxSessions=0).
--8<---------------cut here---------------end--------------->8---
When I set "MaxSessions" in "/etc/ssh/sshd_config" to 100 and restarted
the sshd daemon, the test code fails on the 100th iteration.
--8<---------------cut here---------------start------------->8---
[...]
;;; [2023/01/22 22:52:03.246549, 3] ssh_packet_need_rekey: rekey:
[data_rekey_needed=0, out_blocks=817, in_blocks=1309]
;;; [2023/01/22 22:52:03.246559, 3] ssh_packet_socket_callback: rcv packet cb
(len=0, state=INIT)
;;; [2023/01/22 22:52:03.246568, 3] ssh_packet_socket_callback: Waiting for
more data (0 < 4)
;;; [2023/01/22 22:52:03.246579, 4] ssh_socket_pollcallback: sending control
flow event
;;; [2023/01/22 22:52:03.246587, 4] ssh_packet_socket_controlflow_callback:
sending channel_write_wontblock callback
;;; [2023/01/22 22:52:03.246600, 4] [GSSH DEBUG] read result: 0: #<input:
channel (closed by the remote side) 7fba6349d240>
;;; (x "Вс 22 янв 2023 22:52:03 MSK\n")
;;; [2023/01/22 22:52:03.246636, 4] [GSSH DEBUG] the channel is already freed
by the closing request from the remote side.
-- 100 --
;;; [2023/01/22 22:52:03.246655, 2] channel_open: Creating a channel 143 with
64000 window and 32768 max packet
;;; [2023/01/22 22:52:03.246664, 3] ssh_packet_need_rekey: rekey:
[data_rekey_needed=0, out_blocks=820, in_blocks=1312]
;;; [2023/01/22 22:52:03.246693, 3] ssh_socket_unbuffered_write: Enabling
POLLOUT for socket
;;; [2023/01/22 22:52:03.246703, 3] packet_send2: packet: wrote [type=90,
len=32, padding_size=7, comp=24, payload=24]
;;; [2023/01/22 22:52:03.246712, 3] channel_open: Sent a SSH_MSG_CHANNEL_OPEN
type session for channel 143
;;; [2023/01/22 22:52:03.246721, 4] ssh_socket_pollcallback: Poll callback on
socket 10 (POLLOUT ), out buffer 0
;;; [2023/01/22 22:52:03.246732, 4] ssh_socket_pollcallback: sending control
flow event
;;; [2023/01/22 22:52:03.246741, 4] ssh_packet_socket_controlflow_callback:
sending channel_write_wontblock callback
;;; [2023/01/22 22:52:03.247437, 4] ssh_socket_pollcallback: Poll callback on
socket 10 (POLLIN ), out buffer 0
;;; [2023/01/22 22:52:03.247449, 3] ssh_packet_socket_callback: rcv packet cb
(len=60, state=INIT)
;;; [2023/01/22 22:52:03.247462, 3] ssh_packet_socket_callback: packet: read
type 92 [len=40,padding=11,comp=28,payload=28]
;;; [2023/01/22 22:52:03.247473, 3] ssh_packet_incoming_filter: Filtering
packet type 92
;;; [2023/01/22 22:52:03.247484, 3] ssh_packet_process: Dispatching handler for
packet type 92
;;; [2023/01/22 22:52:03.247496, 1] ssh_packet_channel_open_fail: Channel
opening failure: channel 143 error (2) open failed
;;; [2023/01/22 22:52:03.247506, 3] ssh_packet_need_rekey: rekey:
[data_rekey_needed=0, out_blocks=820, in_blocks=1312]
;;; [2023/01/22 22:52:03.247518, 3] ssh_packet_socket_callback: rcv packet cb
(len=0, state=INIT)
;;; [2023/01/22 22:52:03.247531, 3] ssh_packet_socket_callback: Waiting for
more data (0 < 4)
;;; [2023/01/22 22:52:03.247545, 4] [GSSH DEBUG] result: -1: #<input: channel
(closed) 7fba634e5560>
;;; [2023/01/22 22:52:03.247570, 0] [GSSH ERROR] Channel opening failure:
channel 143 error (2) open failed: #<input: channel (closed) 7fba634e5560>
Backtrace:
In ice-9/boot-9.scm:
1752:10 6 (with-exception-handler _ _ #:unwind? _ # _)
In unknown file:
5 (apply-smob/0 #<thunk 7fba634b82e0>)
In ice-9/boot-9.scm:
724:2 4 (call-with-prompt _ _ #<procedure default-prompt-handle…>)
In ice-9/eval.scm:
619:8 3 (_ #(#(#<directory (guile-user) 7fba634bdc80>)))
In /home/avp/src/projects/guile-ssh/./test.scm:
22:16 2 (main _)
In ssh/popen.scm:
64:4 1 (open-remote-pipe _ "date" "r")
In unknown file:
0 (channel-open-session #<input: channel (closed) 7fba634…>)
ERROR: In procedure channel-open-session:
Throw to key `guile-ssh-error' with args `("channel-open-session" "Channel
opening failure: channel 143 error (2) open failed" #<input: channel (closed)
7fba634e5560> #f)'.
--8<---------------cut here---------------end--------------->8---
I'm not sure if I should deal with this "MaxSessions" error in Guile-SSH
code; and if so, what the right thing to do on the Guile-SSH side?
I'd love to hear your opinions on that.
Thanks,
- avp
References:
1. https://www.openssh.com/txt/release-5.1
--
Artyom "avp" Poptsov <poptsov.artyom@gmail.com>
Home page: https://memory-heap.org/~avp/
CADR Hackerspace co-founder: https://cadrspace.ru/
GPG: D0C2 EAC1 3310 822D 98DE B57C E9C5 A2D9 0898 A02F
signature.asc
Description: PGP signature