bug#58290: guile ssh error on guix deploy

["Artyom V. Poptsov" <poptsov.artyom@gmail.com>]

[-- Attachment #1: Type: text/plain, Size: 8151 bytes --]

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

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 519 bytes --]