From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mp11.migadu.com ([2001:41d0:8:6d80::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by ms5.migadu.com with LMTPS id uAZhKw+WzWNZVQAAbAwnHQ (envelope-from ) for ; Sun, 22 Jan 2023 21:01:19 +0100 Received: from aspmx1.migadu.com ([2001:41d0:8:6d80::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by mp11.migadu.com with LMTPS id kKdqKw+WzWN2KQAA9RJhRA (envelope-from ) for ; Sun, 22 Jan 2023 21:01:19 +0100 Received: from lists.gnu.org (lists.gnu.org [209.51.188.17]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by aspmx1.migadu.com (Postfix) with ESMTPS id 2432C1BA27 for ; Sun, 22 Jan 2023 21:01:19 +0100 (CET) Received: from localhost ([::1] helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1pJgWX-0003p6-US; Sun, 22 Jan 2023 15:01:06 -0500 Received: from eggs.gnu.org ([2001:470:142:3::10]) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1pJgWU-0003ol-VS for bug-guix@gnu.org; Sun, 22 Jan 2023 15:01:03 -0500 Received: from debbugs.gnu.org ([209.51.188.43]) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.90_1) (envelope-from ) id 1pJgWU-0003rx-Mv for bug-guix@gnu.org; Sun, 22 Jan 2023 15:01:02 -0500 Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1pJgWU-0005L1-4j for bug-guix@gnu.org; Sun, 22 Jan 2023 15:01:02 -0500 X-Loop: help-debbugs@gnu.org Subject: bug#58290: guile ssh error on guix deploy Resent-From: "Artyom V. Poptsov" Original-Sender: "Debbugs-submit" Resent-CC: bug-guix@gnu.org Resent-Date: Sun, 22 Jan 2023 20:01:02 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: followup 58290 X-GNU-PR-Package: guix X-GNU-PR-Keywords: To: Ludovic =?UTF-8?Q?Court=C3=A8s?= Cc: 58290@debbugs.gnu.org, Andrew Tropin , Marius Bakke Received: via spool by 58290-submit@debbugs.gnu.org id=B58290.167441763720476 (code B ref 58290); Sun, 22 Jan 2023 20:01:02 +0000 Received: (at 58290) by debbugs.gnu.org; 22 Jan 2023 20:00:37 +0000 Received: from localhost ([127.0.0.1]:52676 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1pJgW4-0005KB-Oo for submit@debbugs.gnu.org; Sun, 22 Jan 2023 15:00:37 -0500 Received: from mail-ej1-f48.google.com ([209.85.218.48]:41537) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1pJgW1-0005Jw-7E for 58290@debbugs.gnu.org; Sun, 22 Jan 2023 15:00:35 -0500 Received: by mail-ej1-f48.google.com with SMTP id u19so25719561ejm.8 for <58290@debbugs.gnu.org>; Sun, 22 Jan 2023 12:00:33 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20210112; h=mime-version:user-agent:message-id:in-reply-to:date:references :subject:cc:to:from:from:to:cc:subject:date:message-id:reply-to; bh=dQsADPl5Q+JLBft+ZothL1cfkmqZ2cQ4Ffj66BpVW64=; b=KYv/VXX38MqwHU/H/sbJhTnM8N4tmux7TRCzYtY4RlNlAub8iBTbW/TD95dKLC276+ cJkX6xxrU3FrMM29ES2zYvgHeg6vH2t56SHCz9bcX1GTsMPuY+dj+vmykjrohnaYhaJo 9zo1qnF3xax5Cg3UmFEBKXeJus7s8ULMb92pQPDKlo58eX95Y+KZiibKXrgVCt9y6uWM WdfTu7otC4JvxYn2R2m5lEeXz+LR5H+gkLz0D/7TVPiZPti8n5dlpXI4JsI6ExnAi461 yo2w3OXrEQob0wZYua9HmwR6LDlcgm7KBpyC/xItT6BF+wgdQJUU2etPSvdwDW6XvEd/ sX/g== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=mime-version:user-agent:message-id:in-reply-to:date:references :subject:cc:to:from:x-gm-message-state:from:to:cc:subject:date :message-id:reply-to; bh=dQsADPl5Q+JLBft+ZothL1cfkmqZ2cQ4Ffj66BpVW64=; b=ah3QD85jq83gI0GscEpFF8fQtDoEubNFxwFLXHONvjMFyMVxgnfmzo05fBEIGfvQLb v0AFSWFkAk7VnyIGkvdzUnb2e4H8hOGtH6mqugwAuizq8BqLUoMmw3Q0PeBcXoJrzt2P mW5hN/wC7UOYjFREoJPGTrAUId7xHuEBHiBrRYqsm7Wx7feCT3PbAmVcC9QxBrlrcC3H /vF0Qh3jl7yuZaL3eEu4qVeIbXSX/rwfDOLyMRpS4SVdl0zmuHJpo7wI+qcnoVIg6V/p 82TndOSQl6vz94jvEz+cQadZhrWlf/5dbKDUHtnNsmIgs4GqGncdLIIQt1nUgX2D1SE7 pwGQ== X-Gm-Message-State: AFqh2kruAqxkBgv5oNNFkV9cIZrFWHp+7UXZ+TrEy9+EyrJV8xNavTks sT4tyObdAk6e2cNFVZNKm1E= X-Google-Smtp-Source: AMrXdXuREUmyczBdgV7lbicScEawChne4z+BoOzrqPX6uxHiZTd3o10TiVtIwtPo0Nwll/Bg4BCc7w== X-Received: by 2002:a17:907:8b08:b0:860:c12c:14fd with SMTP id sz8-20020a1709078b0800b00860c12c14fdmr26130094ejc.76.1674417627026; Sun, 22 Jan 2023 12:00:27 -0800 (PST) Received: from elephant ([95.79.5.207]) by smtp.gmail.com with ESMTPSA id ky16-20020a170907779000b007bd0bb6423csm21087810ejc.199.2023.01.22.12.00.25 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Sun, 22 Jan 2023 12:00:26 -0800 (PST) From: "Artyom V. Poptsov" References: <87sfk34zhj.fsf@trop.in> <87bkqm8p5z.fsf@gnu.org> <87o7uec39j.fsf@trop.in> <8735bmsee9.fsf@gnu.org> <87h702uzrb.fsf@gnu.org> <87y1tdkv1d.fsf@gnu.org> <875yfv38jt.fsf@gnu.org> <87v8lcgdg3.fsf@gnu.org> <87o7r3hqgy.fsf@gnu.org> Date: Sun, 22 Jan 2023 23:00:20 +0300 In-Reply-To: <87o7r3hqgy.fsf@gnu.org> ("Ludovic =?UTF-8?Q?Court=C3=A8s?="'s message of "Thu, 12 Jan 2023 13:44:45 +0100") Message-ID: <87zgaaz6ej.fsf@gmail.com> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/28.2 (gnu/linux) MIME-Version: 1.0 Content-Type: multipart/signed; boundary="=-=-="; micalg=pgp-sha512; protocol="application/pgp-signature" X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.18 Precedence: list X-BeenThere: bug-guix@gnu.org List-Id: Bug reports for GNU Guix List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: bug-guix-bounces+larch=yhetil.org@gnu.org Sender: bug-guix-bounces+larch=yhetil.org@gnu.org X-Migadu-Country: US X-Migadu-Flow: FLOW_IN ARC-Seal: i=1; s=key1; d=yhetil.org; t=1674417679; a=rsa-sha256; cv=none; b=N72p0grO0TpY+xx77klmf4GHhZ73y+ZAuaY2E0EcGB+v9ur1jBTQn7VvHAM/XSFOVKQfrs 5La9ltG9YBNgCBaHttBONAxmlkDO+EiZS5zYX7RRuX68IT9EWPVrsXQ2XIMMF0fWVw8PWy pmJiTYe8DoODhKCs/ybbSKaFzwUOXvgD4V2/9xghw0MubR+aT2xWjYBNFtJjWUN+GKu0Ed jb03yQVLkCQTDjWcTfmXXx3heCMvhJWbLvtnKAZDgv/+h7uv+vmDWyUFzuJ8RVtlz2as21 Q8djxY0IBtFLbP9VKD+Gd67usUCjoOAhlDajdRuVEoDiHnhqZakawAkJWrz6CA== ARC-Authentication-Results: i=1; aspmx1.migadu.com; dkim=fail ("headers rsa verify failed") header.d=gmail.com header.s=20210112 header.b="KYv/VXX3"; dmarc=fail reason="SPF not aligned (relaxed)" header.from=gmail.com (policy=none); spf=pass (aspmx1.migadu.com: domain of "bug-guix-bounces+larch=yhetil.org@gnu.org" designates 209.51.188.17 as permitted sender) smtp.mailfrom="bug-guix-bounces+larch=yhetil.org@gnu.org" ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=yhetil.org; s=key1; t=1674417679; h=from:from:sender:sender:reply-to:subject:subject:date:date: message-id:message-id:to:to:cc:cc:mime-version:mime-version: content-type:content-type:resent-cc:resent-from:resent-sender: resent-message-id:in-reply-to:in-reply-to:references:references: list-id:list-help:list-unsubscribe:list-subscribe:list-post: dkim-signature; bh=dQsADPl5Q+JLBft+ZothL1cfkmqZ2cQ4Ffj66BpVW64=; b=h2QuTD/JJTCkgdubt2R2Y/wpETlzwtLQwcUaDTZaYmLR6KIdv6HZsdmXLM6mXFrzgJ9J6F tT37sJLiXp/wCPX5LqTP2k+4384ch2psetHowOpxk5TszI9WqtXtgapTNlwX29pEgdCQbv 1VgTYcWCh/tlQ2hPgDk3RGglnpoHex/HozdwdWD53hfZa6K2d8f3abfpG8DLztQ7K1uO8n tQCbc75y7C31UOJ16E34dG2AwGx8lmReMNOpWJVzlPa591Ld4pwdC+G376AHYA7tk3fMo2 n++iKICIaUP22h8TTwkq8sKdwkUKeeiwxDsfaJt5huPrHGO1soOdVWYF7cyWGw== X-Spam-Score: 3.71 X-Migadu-Queue-Id: 2432C1BA27 Authentication-Results: aspmx1.migadu.com; dkim=fail ("headers rsa verify failed") header.d=gmail.com header.s=20210112 header.b="KYv/VXX3"; dmarc=fail reason="SPF not aligned (relaxed)" header.from=gmail.com (policy=none); spf=pass (aspmx1.migadu.com: domain of "bug-guix-bounces+larch=yhetil.org@gnu.org" designates 209.51.188.17 as permitted sender) smtp.mailfrom="bug-guix-bounces+larch=yhetil.org@gnu.org" X-Migadu-Scanner: scn0.migadu.com X-Migadu-Spam-Score: 3.71 X-TUID: SGE9P8WToPij --=-=-= Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable 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: =2D-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))))) =2D-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: =2D-8<---------------cut here---------------start------------->8--- =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: debug3: channel 8: wi= ll not send data after close =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: debug3: channel 9: wi= ll not send data after close =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: debug2: channel 9: rc= vd adjust 1216033 =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: debug3: channel 0: wi= ll not send data after close =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: debug3: channel 1: wi= ll not send data after close =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: debug3: channel 2: wi= ll not send data after close =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: debug3: channel 3: wi= ll not send data after close =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: debug3: channel 4: wi= ll not send data after close =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: debug3: channel 5: wi= ll not send data after close =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: debug3: channel 6: wi= ll not send data after close =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: debug3: channel 7: wi= ll not send data after close =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: debug3: channel 8: wi= ll not send data after close =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: debug3: channel 9: wi= ll not send data after close =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: debug3: receive packe= t: type 90 =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: debug1: server_input_= channel_open: ctype session rchan 53 win 64000 max 32768 =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: debug1: input_session= _request =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: debug2: channel: expa= nding 20 =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: debug1: channel 10: n= ew [server-session] =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: debug1: session_open:= channel 10 =D1=8F=D0=BD=D0=B2 22 22:40:06 elephant sshd[131488]: error: no more sessio= ns =2D-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]: =2D-8<---------------cut here---------------start------------->8--- Changes since OpenSSH 5.0 =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D [...] * 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=20 (MaxSessions=3D1) or disallowing login/shell/subsystem sessions entirely (MaxSessions=3D0). =2D-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. =2D-8<---------------cut here---------------start------------->8--- [...] ;;; [2023/01/22 22:52:03.246549, 3] ssh_packet_need_rekey: rekey: [data_rek= ey_needed=3D0, out_blocks=3D817, in_blocks=3D1309] ;;; [2023/01/22 22:52:03.246559, 3] ssh_packet_socket_callback: rcv packet = cb (len=3D0, state=3DINIT) ;;; [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 contro= l 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: # ;;; (x "=D0=92=D1=81 22 =D1=8F=D0=BD=D0=B2 2023 22:52:03 MSK\n") ;;; [2023/01/22 22:52:03.246636, 4] [GSSH DEBUG] the channel is already fre= ed by the closing request from the remote side. =2D- 100 -- ;;; [2023/01/22 22:52:03.246655, 2] channel_open: Creating a channel 143 wi= th 64000 window and 32768 max packet ;;; [2023/01/22 22:52:03.246664, 3] ssh_packet_need_rekey: rekey: [data_rek= ey_needed=3D0, out_blocks=3D820, in_blocks=3D1312] ;;; [2023/01/22 22:52:03.246693, 3] ssh_socket_unbuffered_write: Enabling P= OLLOUT for socket ;;; [2023/01/22 22:52:03.246703, 3] packet_send2: packet: wrote [type=3D90,= len=3D32, padding_size=3D7, comp=3D24, payload=3D24] ;;; [2023/01/22 22:52:03.246712, 3] channel_open: Sent a SSH_MSG_CHANNEL_OP= EN 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 contro= l 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=3D60, state=3DINIT) ;;; [2023/01/22 22:52:03.247462, 3] ssh_packet_socket_callback: packet: rea= d type 92 [len=3D40,padding=3D11,comp=3D28,payload=3D28] ;;; [2023/01/22 22:52:03.247473, 3] ssh_packet_incoming_filter: Filtering p= acket 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 o= pening failure: channel 143 error (2) open failed ;;; [2023/01/22 22:52:03.247506, 3] ssh_packet_need_rekey: rekey: [data_rek= ey_needed=3D0, out_blocks=3D820, in_blocks=3D1312] ;;; [2023/01/22 22:52:03.247518, 3] ssh_packet_socket_callback: rcv packet = cb (len=3D0, state=3DINIT) ;;; [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: # ;;; [2023/01/22 22:52:03.247570, 0] [GSSH ERROR] Channel opening failure: c= hannel 143 error (2) open failed: # Backtrace: In ice-9/boot-9.scm: 1752:10 6 (with-exception-handler _ _ #:unwind? _ # _) In unknown file: 5 (apply-smob/0 #) In ice-9/boot-9.scm: 724:2 4 (call-with-prompt _ _ #) In ice-9/eval.scm: 619:8 3 (_ #(#(#))) 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 #) 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" # #f)'. =2D-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, =2D avp References: 1. https://www.openssh.com/txt/release-5.1 =2D-=20 Artyom "avp" Poptsov 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 --=-=-= Content-Type: application/pgp-signature; name="signature.asc" -----BEGIN PGP SIGNATURE----- iQFNBAEBCgA3FiEE0MLqwTMQgi2Y3rV86cWi2QiYoC8FAmPNldQZHHBvcHRzb3Yu YXJ0eW9tQGdtYWlsLmNvbQAKCRDpxaLZCJigLxVnB/45HlrG3M7wGz+x0XBvHmOr Tyy0U+fX7cAsLod5yvLrtDg92X+LW1qoeMEaVKuxhIBerMuR/fvimT9arOHs7TgH soCLEeyaY1YdtPwU5hSRMfgtK4IzW3wltAfJJSCCXXhh+uvuUMeVHIDgtCUT+wlB eWHlHhm2XViQWer2Shr0p2Wvt2QxGGPHteamzO4J8yCmoVa0qCWZWMp0kbHWfBFE /4s7NyxKcNjA5M0XBjSBQTiAL+gcQzPq5VVmiUuz1fNLbROSo8Pau7rafHJ9zrqF n4p3prHojGIL6Gzuju/JT52YfWzhbLksu2fbJXMX2TeKFvKXg22JOe3J0zrlT79b =RAfK -----END PGP SIGNATURE----- --=-=-=--