Potential SSH session exhaustion

  • Done
  • quality assurance status badge
Details
2 participants
  • Ludovic Courtès
  • Jakob L. Kreuze
Owner
unassigned
Submitted by
Jakob L. Kreuze
Severity
normal
J
J
Jakob L. Kreuze wrote on 24 Jun 2019 19:23
(address . bug-guix@gnu.org)
87pnn2x5gs.fsf@sdf.lonestar.org
Hello, Guix

In developing a test suite for the internals of 'guix deploy', the
virtual machine I spun up spat out an OpenSSH error that I've never
encountered before.

Jun 24 16:59:26 localhost sshd[235]: error: no more sessions

This is, initially, quite curious. Creating the SSH session with
#:log-verbosity set to 'protocol gives some insight.

;;; [2019/06/24 13:08:36.711847, 2] channel_open: Creating a channel 43 with 64000 window and 32768 max packet
;;; [2019/06/24 13:08:36.711959, 2] ssh_packet_global_request: Received SSH_MSG_GLOBAL_REQUEST packet
;;; [2019/06/24 13:08:36.711987, 2] ssh_packet_global_request: UNKNOWN SSH_MSG_GLOBAL_REQUEST hostkeys-00@openssh.com 0
;;; [2019/06/24 13:08:36.712010, 1] ssh_packet_process: Couldn't do anything with packet type 80
;;; [2019/06/24 13:08:36.712197, 2] ssh_packet_channel_open_conf: Received a CHANNEL_OPEN_CONFIRMATION for channel 43:0
;;; [2019/06/24 13:08:36.712219, 2] ssh_packet_channel_open_conf: Remote window : 0, maxpacket : 32768
;;; [2019/06/24 13:08:36.712618, 2] channel_rcv_change_window: Adding 2097152 bytes to channel (43:0) (from 0 bytes)
;;; [2019/06/24 13:08:36.712651, 2] channel_request: Channel request exec success
...
;;; [2019/06/24 12:59:26.296022, 2] channel_open: Creating a channel 74 with 64000 window and 32768 max packet
;;; [2019/06/24 12:59:26.296262, 2] ssh_packet_channel_open_conf: Received a CHANNEL_OPEN_CONFIRMATION for channel 74:8
;;; [2019/06/24 12:59:26.296308, 2] ssh_packet_channel_open_conf: Remote window : 0, maxpacket : 32768
;;; [2019/06/24 12:59:26.296667, 2] channel_rcv_change_window: Adding 2097152 bytes to channel (74:8) (from 0 bytes)
;;; [2019/06/24 12:59:26.296721, 2] channel_request: Channel request exec success
;;; [2019/06/24 12:59:26.487339, 2] grow_window: growing window (channel 74:8) to 1280000 bytes
;;; [2019/06/24 12:59:26.489031, 2] channel_open: Creating a channel 75 with 64000 window and 32768 max packet
;;; [2019/06/24 12:59:26.489376, 2] ssh_packet_channel_open_conf: Received a CHANNEL_OPEN_CONFIRMATION for channel 75:8
;;; [2019/06/24 12:59:26.489402, 2] ssh_packet_channel_open_conf: Remote window : 0, maxpacket : 32768
;;; [2019/06/24 12:59:26.489858, 2] channel_rcv_change_window: Adding 2097152 bytes to channel (75:8) (from 0 bytes)
;;; [2019/06/24 12:59:26.489906, 2] channel_request: Channel request exec success
;;; [2019/06/24 12:59:26.542586, 2] grow_window: growing window (channel 75:8) to 1280000 bytes
;;; [2019/06/24 12:59:26.546104, 2] channel_open: Creating a channel 76 with 64000 window and 32768 max packet
;;; [2019/06/24 12:59:26.546407, 2] ssh_packet_channel_open_conf: Received a CHANNEL_OPEN_CONFIRMATION for channel 76:9
;;; [2019/06/24 12:59:26.546438, 2] ssh_packet_channel_open_conf: Remote window : 0, maxpacket : 32768
;;; [2019/06/24 12:59:26.546839, 2] channel_rcv_change_window: Adding 2097152 bytes to channel (76:9) (from 0 bytes)
;;; [2019/06/24 12:59:26.546865, 2] channel_request: Channel request exec success
;;; [2019/06/24 12:59:26.630055, 2] grow_window: growing window (channel 76:9) to 1280000 bytes
;;; [2019/06/24 12:59:27.272139, 2] channel_open: Creating a channel 77 with 64000 window and 32768 max packet
;;; [2019/06/24 12:59:27.272846, 1] ssh_packet_channel_open_fail: Channel opening failure: channel 77 error (2) open failed

I will admit that my knowledge of the SSH protocol is limited, but the
rising channel number gives me the impression that channels are going
out of scope and aren't being cleaned up. For reference, this occurs
when 'remote-eval' is invoked multiple times -- which, in turn, invokes
'send-files'.

building path(s) `/gnu/store/3rfkwdbayg7m3wdrydmcljnfqhvrady5-remote-exp.scm'
sending 1 store item (0 MiB) to 'localhost'...
exporting path `/gnu/store/3rfkwdbayg7m3wdrydmcljnfqhvrady5-remote-exp.scm'
building path(s) `/gnu/store/ib59b0pnypsw4vf59f2gwpwhn343xnzb-remote-exp.scm'
sending 1 store item (0 MiB) to 'localhost'...
exporting path `/gnu/store/ib59b0pnypsw4vf59f2gwpwhn343xnzb-remote-exp.scm'
[this is where the "no more sessions" error occurs]

Currently, my code performs all of these 'remote-eval' calls with the
same session. I suppose it would be possible to create a new session for
each call, but I feel I should raise this as it may cause issues down
the line: do we need to do something about cleaning up SSH channels?

If a reproducible example is necessary, you can look to the temporary
'tests/machine.scm' in 64ffe453b0c71f417927737fa808dffe858359cd on my
personal branch.[1]

Regards,
Jakob

-----BEGIN PGP SIGNATURE-----

iQIzBAEBCAAdFiEEa1VJLOiXAjQ2BGSm9Qb9Fp2P2VoFAl0RBxMACgkQ9Qb9Fp2P
2VrvcxAApJkJljMn9BObHClrw8V+oOnNn2xO8qrcqRZQEPxBiJYVRWj3fLg18ozE
S9ePPsmWe+UvVSg8wszOydt4RVejJVKaGg1OZYY5tLznMiVQU6k65lQN1jpzkOr1
pgenJZNE0SqgL9rkV/4kHiBf/S97T3kBKYn9VU+1Sh2KPOLqOtCisiqICY5sfTBY
/R+ZHn9Ijo2tMX1XoDWSpsA4VxdwhS0Y8Oqab/7MjiqoCr3TgY05tzYEZ88JCfQ/
V9ljl3FKMXhFd8tLKDKoM0q+FNfF18G6+HtPHPnlLn4Anh3hKBry/Y4WycPBziNz
wp3iydtLQrDMYMKBjD9fQ0nH7NQGBbGpyY02IZLwF+LL+Fjschl9VXRYIZMz15iG
HcX9lFy660bLEbyvXnnaL5bJGhAVHiejeu6F069L3s4t9U4NiKXs8tNpRDrHKmRm
K2wgm55hWZDGM0LCyjRXl++iPY8lVlIo/NOQqEF4GH3+DxnSF+LXYYUJka9lz5Cn
8qrmiQzHjQBuvfmA2L+3MOe1tmphe++bKiewZKS/EcDwx02W5wWq+yXrngM+JE+R
5ajkHe+HvewLDj55RQyMu5byPWR72m1Bdyd4yb3732Qmm+C/0R7ggsQrhObakAJT
Ojg8G9VRg2xMLYbZ7ukzm+bfYEDjsyqpUtRQm4bwAKvqrB++cH4=
=Ldje
-----END PGP SIGNATURE-----

L
L
Ludovic Courtès wrote on 24 Jun 2019 22:45
(name . Jakob L. Kreuze)(address . zerodaysfordays@sdf.lonestar.org)(address . 36364@debbugs.gnu.org)
87ftny3e6q.fsf@gnu.org
Hello Jakob,

zerodaysfordays@sdf.lonestar.org (Jakob L. Kreuze) skribis:

Toggle quote (9 lines)
> In developing a test suite for the internals of 'guix deploy', the
> virtual machine I spun up spat out an OpenSSH error that I've never
> encountered before.
>
> Jun 24 16:59:26 localhost sshd[235]: error: no more sessions
>
> This is, initially, quite curious. Creating the SSH session with
> #:log-verbosity set to 'protocol gives some insight.

[...]

Toggle quote (13 lines)
> ;;; [2019/06/24 12:59:26.546104, 2] channel_open: Creating a channel 76 with 64000 window and 32768 max packet
> ;;; [2019/06/24 12:59:26.546407, 2] ssh_packet_channel_open_conf: Received a CHANNEL_OPEN_CONFIRMATION for channel 76:9
> ;;; [2019/06/24 12:59:26.546438, 2] ssh_packet_channel_open_conf: Remote window : 0, maxpacket : 32768
> ;;; [2019/06/24 12:59:26.546839, 2] channel_rcv_change_window: Adding 2097152 bytes to channel (76:9) (from 0 bytes)
> ;;; [2019/06/24 12:59:26.546865, 2] channel_request: Channel request exec success
> ;;; [2019/06/24 12:59:26.630055, 2] grow_window: growing window (channel 76:9) to 1280000 bytes
> ;;; [2019/06/24 12:59:27.272139, 2] channel_open: Creating a channel 77 with 64000 window and 32768 max packet
> ;;; [2019/06/24 12:59:27.272846, 1] ssh_packet_channel_open_fail: Channel opening failure: channel 77 error (2) open failed
>
> I will admit that my knowledge of the SSH protocol is limited, but the
> rising channel number gives me the impression that channels are going
> out of scope and aren't being cleaned up.

Procedures like ‘send-files’ call ‘channel-get-exit-status’ and
‘close-port’ on ports that represent SSH channels.

AFAICS, ‘close-port’ triggers a call of ‘ptob_close’ in Guile-SSH, which
in turn calls ‘ssh_channel_close’.

sshd_config(5) says:

Toggle snippet (11 lines)
MaxSessions
Specifies the maximum number of open shell, login or
subsystem (e.g. sftp) sessions permitted per network
connection. Multiple sessions may be established by clients
that support connection multiplexing. Setting MaxSessions to
1 will effectively disable session multiplexing, whereas
setting it to 0 will prevent all shell, login and subsystem
sessions while still permitting forwarding. The default is
10.

So you must be hitting this limit.

I see that ‘remote-eval’ does not close ‘remote’ though, so this channel
port remains open until it’s GC’d, which happens too late. Could you
try the attached patch? It allows me to do more than 10 ‘remote-eval’
calls in a row.

Thanks,
Ludo’.
Toggle diff (18 lines)
diff --git a/guix/remote.scm b/guix/remote.scm
index cc051dee8a..fa19ece112 100644
--- a/guix/remote.scm
+++ b/guix/remote.scm
@@ -116,6 +116,7 @@ remote store."
(mbegin %store-monad
(built-derivations to-build)
((store-lift send-files) to-send remote #:recursive? #t)
+ (return (close-connection remote))
(return (%remote-eval lowered session))))
(let ((to-send (map (lambda (input)
(match (gexp-input-thing input)
@@ -127,4 +128,5 @@ remote store."
(mbegin %store-monad
((store-lift send-files) to-send remote #:recursive? #t)
(return (build-derivations remote to-build))
+ (return (close-connection remote))
(return (%remote-eval lowered session)))))))
J
J
Jakob L. Kreuze wrote on 25 Jun 2019 01:28
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 36364@debbugs.gnu.org)
877e9awokj.fsf@sdf.lonestar.org
Hi,

Ludovic Courtès <ludo@gnu.org> writes:

Toggle quote (17 lines)
> Procedures like ‘send-files’ call ‘channel-get-exit-status’ and
> ‘close-port’ on ports that represent SSH channels.
>
> AFAICS, ‘close-port’ triggers a call of ‘ptob_close’ in Guile-SSH,
> which in turn calls ‘ssh_channel_close’.
>
> sshd_config(5) says:
>
> MaxSessions Specifies the maximum number of open shell, login or subsystem
> (e.g. sftp) sessions permitted per network connection. Multiple sessions may be
> established by clients that support connection multiplexing. Setting MaxSessions
> to 1 will effectively disable session multiplexing, whereas setting it to 0 will
> prevent all shell, login and subsystem sessions while still permitting
> forwarding. The default is 10.
>
> So you must be hitting this limit.

Ah, thank you for the corrections :)

Toggle quote (5 lines)
> I see that ‘remote-eval’ does not close ‘remote’ though, so this
> channel port remains open until it’s GC’d, which happens too late.
> Could you try the attached patch? It allows me to do more than 10
> ‘remote-eval’ calls in a row.

Wow, that was quick. The patch works like a charm, thanks!

Regards,
Jakob
-----BEGIN PGP SIGNATURE-----

iQIzBAEBCAAdFiEEa1VJLOiXAjQ2BGSm9Qb9Fp2P2VoFAl0RXJ0ACgkQ9Qb9Fp2P
2Vpwfw/6Awi/sdKYTZLbLwfydvRUMXMK68YpdFxAzNCf7spd0Ayv5nGblKqXRWOz
ATDXea+fNpFmgbKF1KVztCrWqxCS8ySyujlQlC+ETGbyygvjlhFpJg6HmYyW/S+R
4v78zxWUHgVNT/rVdpKToJQd2037PlvHGJBAYFuT9YOAeJ61NcCL6MMP/2eHO3fi
JhgkFEJiv51Cu06zLXzpKFHh1zUXYXjs9hpVBD+HwYU9pM5GKB73+crx9Np0qF/w
975l1QqIA5hJgDfZQLXilQ1a9YBuL2ev28N6WoUnMeWQ3/zyEGQc4a6gAWoxYXtY
DVOMs3iiSU85FKcHFJKowkWP6n7qNSwJWWg3oLJojeUApOc/TdnOWKGcc/1dP8bF
HxV8Rysp2YPVS7kw/G9uctHjqz620j09oX8fhA5afc6EKUAQydHv2MjsfwoQYWPB
obt9xOCVd93xB962d7CrXIeIWBue8EKc9qwkladCwsu9ik+dm36Ltm2MWUa5Zd+Z
N+A0ScIv17G50wMn3IVacCrupPwF3r0rE5FOHxC35sChb8NjjG9/R4n9cIWEzAUu
1x7ACDPQK6vrmkNFSSWiuK4PnLl2yC23SzAvmmDLBF2caqRM6Cx2ft45o6SNzxJC
M2Dlqc+rTWYOw7FUhTQY69fiQOl/gPDRI8rCTxzJQYqMV7rCY0I=
=mzRr
-----END PGP SIGNATURE-----

L
L
Ludovic Courtès wrote on 25 Jun 2019 18:14
(name . Jakob L. Kreuze)(address . zerodaysfordays@sdf.lonestar.org)(address . 36364-done@debbugs.gnu.org)
87y31pk5gn.fsf@gnu.org
Hi,

zerodaysfordays@sdf.lonestar.org (Jakob L. Kreuze) skribis:

Toggle quote (2 lines)
> Ludovic Courtès <ludo@gnu.org> writes:

[...]

Toggle quote (7 lines)
>> I see that ‘remote-eval’ does not close ‘remote’ though, so this
>> channel port remains open until it’s GC’d, which happens too late.
>> Could you try the attached patch? It allows me to do more than 10
>> ‘remote-eval’ calls in a row.
>
> Wow, that was quick. The patch works like a charm, thanks!

Cool, thanks for testing!

(I plan to merge the ‘remove-eval’ patches soonish…)

Ludo’.
Closed
?