unofficial mirror of bug-guix@gnu.org 
 help / color / mirror / code / Atom feed
* bug#58290: guile ssh error on guix deploy
@ 2022-10-04 11:09 Andrew Tropin
  2022-10-08 12:39 ` Ludovic Courtès
  0 siblings, 1 reply; 8+ messages in thread
From: Andrew Tropin @ 2022-10-04 11:09 UTC (permalink / raw)
  To: 58290

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

From time to time I get the following error, the only thing I change is
IPv6 config in static-networking service.  Sometimes it fails, but after
a few more attempts with the same config it deploys sucessfully.

--8<---------------cut here---------------start------------->8---
-*- mode: compilation; default-directory: "~/work/abcdw/trop.in/" -*-
Compilation started at Tue Oct  4 14:19:46

make -k deploy-pinky
guix deploy ./guix/pinky.scm
The following 1 machine will be deployed:
  pinky

guix deploy: deploying to pinky...
guix deploy: sending 0 store items (0 MiB) to '23.137.249.202'...
guix deploy: sending 0 store items (0 MiB) to '23.137.249.202'...
substitute: updating substitutes from 'https://substitutes.nonguix.org'... 100.0%
substitute: updating substitutes from 'https://bordeaux.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'http://ci.guix.trop.in'... 100.0%
The following derivations will be built:
  /gnu/store/yzilvx4jr4s7174f6azxxbb5c24311xc-remote-exp.scm.drv
  /gnu/store/sqlbbg5z19h2ww86p8nzhfbnidsm5sag-switch-to-system.scm.drv
  /gnu/store/ayssizgz8i4mnk6p2yhilqgzwim4ql7j-system.drv
  /gnu/store/9fxf3gcgi07hg5nmhjvnvlhk6829h304-provenance.drv
  /gnu/store/djs7vabv5wr3inz3pva87wfw7ya10ajq-boot.drv
  /gnu/store/smmzsd1b9v4qmncvl0pl6f0nrasp39ks-activate.scm.drv
  /gnu/store/5hpm7v0xnqqilhj7qdg66cjkf8dvkimx-activate-service.scm.drv
  /gnu/store/g62yd6a8wd081w0y4jji83dbcxhiks3i-etc.drv

building /gnu/store/9fxf3gcgi07hg5nmhjvnvlhk6829h304-provenance.drv...
building /gnu/store/g62yd6a8wd081w0y4jji83dbcxhiks3i-etc.drv...
building /gnu/store/5hpm7v0xnqqilhj7qdg66cjkf8dvkimx-activate-service.scm.drv...
building /gnu/store/smmzsd1b9v4qmncvl0pl6f0nrasp39ks-activate.scm.drv...
building /gnu/store/djs7vabv5wr3inz3pva87wfw7ya10ajq-boot.drv...
building /gnu/store/ayssizgz8i4mnk6p2yhilqgzwim4ql7j-system.drv...
building /gnu/store/sqlbbg5z19h2ww86p8nzhfbnidsm5sag-switch-to-system.scm.drv...
building /gnu/store/yzilvx4jr4s7174f6azxxbb5c24311xc-remote-exp.scm.drv...
guix deploy: sending 10 store items (0 MiB) to '23.137.249.202'...
guix deploy: sending 0 store items (0 MiB) to '23.137.249.202'...
guix deploy: sending 0 store items (0 MiB) to '23.137.249.202'...
The following derivations will be built:
  /gnu/store/36rmj2xp0sd7lx0ndv8imkyxrh2lmmdy-remote-exp.scm.drv
  /gnu/store/823hs0g4wxdmfwmj6nn8smcnrp45a1g7-install-bootloader.scm.drv
  /gnu/store/0m7f6gg0d0iq6r99p40rw3m65z52fjiy-grub.cfg.drv

building /gnu/store/0m7f6gg0d0iq6r99p40rw3m65z52fjiy-grub.cfg.drv...
building /gnu/store/823hs0g4wxdmfwmj6nn8smcnrp45a1g7-install-bootloader.scm.drv...
building /gnu/store/36rmj2xp0sd7lx0ndv8imkyxrh2lmmdy-remote-exp.scm.drv...
;;; [2022/10/04 14:20:23.191118, 0] [GSSH ERROR] Channel opening failure: channel 67 error (2) open failed: #<input-output: channel (closed) 7f7d1af9e140>
Backtrace:
In guix/store.scm:
  1402:13 19 (map/accumulate-builds #<store-connection 256.99 7f7d1…> …)
  1377:11 18 (map/accumulate-builds #<store-connection 256.99 7f7d1…> …)
   1295:8 17 (call-with-build-handler #<procedure 7f7d15629ea0 at g…> …)
In ice-9/boot-9.scm:
  1752:10 16 (with-exception-handler _ _ #:unwind? _ # _)
In guix/scripts/deploy.scm:
    168:6 15 (_)
In guix/store.scm:
  2165:25 14 (run-with-store #<store-connection 256.99 7f7d143b0690> …)
In gnu/machine/ssh.scm:
   506:32 13 (_ _)
In ice-9/boot-9.scm:
  1752:10 12 (with-exception-handler _ _ #:unwind? _ # _)
In gnu/machine/ssh.scm:
   506:32 11 (_)
In guix/store.scm:
  2165:25 10 (run-with-store #<store-connection 256.99 7f7d1207b3c0> …)
In guix/remote.scm:
   138:10  9 (_ _)
In guix/store.scm:
  2037:38  8 (_ #<store-connection 256.99 7f7d1207b3c0>)
In guix/ssh.scm:
    376:2  7 (send-files #<store-connection 256.99 7f7d1207b3c0> _ # …)
    222:5  6 (remote-run (begin (use-modules (guix) (srfi #) # #) …) #)
In ssh/popen.scm:
     64:4  5 (open-remote-pipe* _ "r+" _ . _)
In unknown file:
           4 (channel-open-session #<input-output: channel (closed) …>)
In ice-9/boot-9.scm:
  1685:16  3 (raise-exception _ #:continuable? _)
  1683:16  2 (raise-exception _ #:continuable? _)
  1685:16  1 (raise-exception _ #:continuable? _)
  1685:16  0 (raise-exception _ #:continuable? _)

ice-9/boot-9.scm:1685:16: In procedure raise-exception:
Throw to key `guile-ssh-error' with args `("channel-open-session" "Channel opening failure: channel 67 error (2) open failed" #<input-output: channel (closed) 7f7d1af9e140> #f)'.
make: *** [Makefile:28: deploy-pinky] Error 1

Compilation exited abnormally with code 2 at Tue Oct  4 14:20:23
--8<---------------cut here---------------end--------------->8---

-- 
Best regards,
Andrew Tropin

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

^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#58290: guile ssh error on guix deploy
  2022-10-04 11:09 bug#58290: guile ssh error on guix deploy Andrew Tropin
@ 2022-10-08 12:39 ` Ludovic Courtès
  2022-10-14  6:45   ` Andrew Tropin
  0 siblings, 1 reply; 8+ messages in thread
From: Ludovic Courtès @ 2022-10-08 12:39 UTC (permalink / raw)
  To: Andrew Tropin; +Cc: 58290

Hi!

Andrew Tropin <andrew@trop.in> skribis:

> From time to time I get the following error, the only thing I change is
> IPv6 config in static-networking service.  Sometimes it fails, but after
> a few more attempts with the same config it deploys sucessfully.
>
> -*- mode: compilation; default-directory: "~/work/abcdw/trop.in/" -*-
> Compilation started at Tue Oct  4 14:19:46
>
> make -k deploy-pinky
> guix deploy ./guix/pinky.scm

[...]

> In guix/ssh.scm:
>     376:2  7 (send-files #<store-connection 256.99 7f7d1207b3c0> _ # …)
>     222:5  6 (remote-run (begin (use-modules (guix) (srfi #) # #) …) #)
> In ssh/popen.scm:
>      64:4  5 (open-remote-pipe* _ "r+" _ . _)
> In unknown file:
>            4 (channel-open-session #<input-output: channel (closed) …>)
> In ice-9/boot-9.scm:
>   1685:16  3 (raise-exception _ #:continuable? _)
>   1683:16  2 (raise-exception _ #:continuable? _)
>   1685:16  1 (raise-exception _ #:continuable? _)
>   1685:16  0 (raise-exception _ #:continuable? _)
>
> ice-9/boot-9.scm:1685:16: In procedure raise-exception:
> Throw to key `guile-ssh-error' with args `("channel-open-session" "Channel opening failure: channel 67 error (2) open failed" #<input-output: channel (closed) 7f7d1af9e140> #f)'.

Are there any hints from sshd in the /var/log/messages of that machine
as to why the connection was closed?

Thanks,
Ludo’.




^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#58290: guile ssh error on guix deploy
  2022-10-08 12:39 ` Ludovic Courtès
@ 2022-10-14  6:45   ` Andrew Tropin
  2022-10-17 14:39     ` Ludovic Courtès
  0 siblings, 1 reply; 8+ messages in thread
From: Andrew Tropin @ 2022-10-14  6:45 UTC (permalink / raw)
  To: Ludovic Courtès; +Cc: 58290

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

On 2022-10-08 14:39, Ludovic Courtès wrote:

> Hi!
>
> Andrew Tropin <andrew@trop.in> skribis:
>
>> From time to time I get the following error, the only thing I change is
>> IPv6 config in static-networking service.  Sometimes it fails, but after
>> a few more attempts with the same config it deploys sucessfully.
>>
>> -*- mode: compilation; default-directory: "~/work/abcdw/trop.in/" -*-
>> Compilation started at Tue Oct  4 14:19:46
>>
>> make -k deploy-pinky
>> guix deploy ./guix/pinky.scm
>
> [...]
>
>> In guix/ssh.scm:
>>     376:2  7 (send-files #<store-connection 256.99 7f7d1207b3c0> _ # …)
>>     222:5  6 (remote-run (begin (use-modules (guix) (srfi #) # #) …) #)
>> In ssh/popen.scm:
>>      64:4  5 (open-remote-pipe* _ "r+" _ . _)
>> In unknown file:
>>            4 (channel-open-session #<input-output: channel (closed) …>)
>> In ice-9/boot-9.scm:
>>   1685:16  3 (raise-exception _ #:continuable? _)
>>   1683:16  2 (raise-exception _ #:continuable? _)
>>   1685:16  1 (raise-exception _ #:continuable? _)
>>   1685:16  0 (raise-exception _ #:continuable? _)
>>
>> ice-9/boot-9.scm:1685:16: In procedure raise-exception:
>> Throw to key `guile-ssh-error' with args `("channel-open-session" "Channel opening failure: channel 67 error (2) open failed" #<input-output: channel (closed) 7f7d1af9e140> #f)'.
>
> Are there any hints from sshd in the /var/log/messages of that machine
> as to why the connection was closed?

--8<---------------cut here---------------start------------->8---
bob@pinky /var/log$ zcat messages.1.gz | grep "Oct  4" | grep ssh
Oct  4 05:57:09 localhost shepherd[1]: Service sshd-380 has been started. 
Oct  4 05:57:11 localhost sshd[15950]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 54710 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 06:34:17 localhost shepherd[1]: Service sshd-381 has been started. 
Oct  4 06:34:19 localhost sshd[15958]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 57064 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 06:36:55 localhost shepherd[1]: Service sshd-382 has been started. 
Oct  4 06:36:57 localhost sshd[15991]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 41088 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 06:37:30 localhost shepherd[1]: Service sshd-383 has been started. 
Oct  4 06:37:33 localhost sshd[16031]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 56148 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 06:43:39 localhost shepherd[1]: 3 connections still in use after sshd-382 termination. 
Oct  4 06:43:39 localhost shepherd[1]: Service sshd-382 (PID 15991) exited with 255. 
Oct  4 06:43:39 localhost shepherd[1]: Service sshd-382 has been disabled. 
Oct  4 06:43:39 localhost shepherd[1]: Transient service sshd-382 terminated, now unregistered. 
Oct  4 06:43:41 localhost shepherd[1]: Service sshd-384 has been started. 
Oct  4 06:43:42 localhost sshd[16166]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 36040 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 06:43:49 localhost shepherd[1]: 3 connections still in use after sshd-384 termination. 
Oct  4 06:43:49 localhost shepherd[1]: Service sshd-384 has been disabled. 
Oct  4 06:43:49 localhost shepherd[1]: Transient service sshd-384 terminated, now unregistered. 
Oct  4 06:48:58 localhost shepherd[1]: Service sshd-385 has been started. 
Oct  4 06:49:00 localhost sshd[16205]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 34134 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 06:52:05 localhost shepherd[1]: Service sshd-386 has been started. 
Oct  4 06:52:06 localhost sshd[16212]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 55922 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 06:53:02 localhost shepherd[1]: 4 connections still in use after sshd-386 termination. 
Oct  4 06:53:02 localhost shepherd[1]: Service sshd-386 has been disabled. 
Oct  4 06:53:02 localhost shepherd[1]: Transient service sshd-386 terminated, now unregistered. 
Oct  4 06:53:03 localhost shepherd[1]: Service sshd-387 has been started. 
Oct  4 06:53:04 localhost sshd[16370]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 50604 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 06:53:11 localhost shepherd[1]: 4 connections still in use after sshd-387 termination. 
Oct  4 06:53:11 localhost shepherd[1]: Service sshd-387 has been disabled. 
Oct  4 06:53:11 localhost shepherd[1]: Transient service sshd-387 terminated, now unregistered. 
Oct  4 06:54:25 localhost shepherd[1]: Service ssh-daemon has been stopped. 
Oct  4 06:57:42 localhost shepherd[1]: Service ssh-daemon has been started. 
Oct  4 06:58:20 localhost shepherd[1]: Service sshd-1 has been started. 
Oct  4 06:58:22 localhost sshd[239]: Accepted publickey for bob from 185.115.7.223 port 10436 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:01:22 localhost shepherd[1]: Service sshd-2 has been started. 
Oct  4 07:01:24 localhost sshd[247]: Accepted publickey for bob from 185.115.7.223 port 29449 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:02:29 localhost shepherd[1]: Service sshd-3 has been started. 
Oct  4 07:02:31 localhost sshd[254]: Accepted publickey for bob from 185.115.7.223 port 29456 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:03:05 localhost sshd[256]: error: no more sessions
Oct  4 07:03:05 localhost shepherd[1]: 2 connections still in use after sshd-3 termination. 
Oct  4 07:03:05 localhost shepherd[1]: Service sshd-3 has been disabled. 
Oct  4 07:03:05 localhost shepherd[1]: Transient service sshd-3 terminated, now unregistered. 
Oct  4 07:04:21 localhost shepherd[1]: Service sshd-4 has been started. 
Oct  4 07:04:22 localhost sshd[385]: Accepted publickey for bob from 185.115.7.223 port 10409 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:04:36 localhost shepherd[1]: Service sshd-5 has been started. 
Oct  4 07:04:38 localhost sshd[435]: Accepted publickey for bob from 185.115.7.223 port 10426 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:04:50 localhost sshd[387]: error: no more sessions
Oct  4 07:04:50 localhost shepherd[1]: 3 connections still in use after sshd-4 termination. 
Oct  4 07:04:50 localhost shepherd[1]: Service sshd-4 has been disabled. 
Oct  4 07:04:50 localhost shepherd[1]: Transient service sshd-4 terminated, now unregistered. 
Oct  4 07:05:10 localhost shepherd[1]: Service sshd-6 has been started. 
Oct  4 07:05:12 localhost sshd[508]: Accepted publickey for bob from 185.115.7.223 port 29519 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:05:57 localhost shepherd[1]: 3 connections still in use after sshd-6 termination. 
Oct  4 07:05:57 localhost shepherd[1]: Service sshd-6 has been disabled. 
Oct  4 07:05:57 localhost shepherd[1]: Transient service sshd-6 terminated, now unregistered. 
Oct  4 07:05:57 localhost shepherd[1]: Service sshd-7 has been started. 
Oct  4 07:05:59 localhost sshd[666]: Accepted publickey for bob from 185.115.7.223 port 29495 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:06:03 localhost shepherd[1]: 3 connections still in use after sshd-7 termination. 
Oct  4 07:06:03 localhost shepherd[1]: Service sshd-7 has been disabled. 
Oct  4 07:06:03 localhost shepherd[1]: Transient service sshd-7 terminated, now unregistered. 
Oct  4 07:07:13 localhost shepherd[1]: Service sshd-8 has been started. 
Oct  4 07:07:14 localhost sshd[699]: Accepted publickey for bob from 185.115.7.223 port 29463 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:07:51 localhost shepherd[1]: 3 connections still in use after sshd-8 termination. 
Oct  4 07:07:51 localhost shepherd[1]: Service sshd-8 has been disabled. 
Oct  4 07:07:51 localhost shepherd[1]: Transient service sshd-8 terminated, now unregistered. 
Oct  4 07:07:52 localhost shepherd[1]: Service sshd-9 has been started. 
Oct  4 07:07:54 localhost sshd[857]: Accepted publickey for bob from 185.115.7.223 port 10407 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:07:58 localhost shepherd[1]: 3 connections still in use after sshd-9 termination. 
Oct  4 07:07:58 localhost shepherd[1]: Service sshd-9 (PID 857) exited with 255. 
Oct  4 07:07:58 localhost shepherd[1]: Service sshd-9 has been disabled. 
Oct  4 07:07:58 localhost shepherd[1]: Transient service sshd-9 terminated, now unregistered. 
Oct  4 07:08:22 localhost shepherd[1]: Service sshd-10 has been started. 
Oct  4 07:08:24 localhost sshd[889]: Accepted publickey for bob from 185.115.7.223 port 10478 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:08:55 localhost sshd[891]: error: no more sessions
Oct  4 07:08:55 localhost shepherd[1]: 3 connections still in use after sshd-10 termination. 
Oct  4 07:08:55 localhost shepherd[1]: Service sshd-10 has been disabled. 
Oct  4 07:08:55 localhost shepherd[1]: Transient service sshd-10 terminated, now unregistered. 
Oct  4 07:09:24 localhost shepherd[1]: Service sshd-11 has been started. 
Oct  4 07:09:25 localhost sshd[1010]: Accepted publickey for bob from 185.115.7.223 port 10489 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:10:01 localhost shepherd[1]: 3 connections still in use after sshd-11 termination. 
Oct  4 07:10:01 localhost shepherd[1]: Service sshd-11 (PID 1010) exited with 255. 
Oct  4 07:10:01 localhost shepherd[1]: Service sshd-11 has been disabled. 
Oct  4 07:10:01 localhost shepherd[1]: Transient service sshd-11 terminated, now unregistered. 
Oct  4 07:10:01 localhost shepherd[1]: Service sshd-12 has been started. 
Oct  4 07:10:03 localhost sshd[1164]: Accepted publickey for bob from 185.115.7.223 port 29458 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:10:08 localhost shepherd[1]: 3 connections still in use after sshd-12 termination. 
Oct  4 07:10:08 localhost shepherd[1]: Service sshd-12 (PID 1164) exited with 255. 
Oct  4 07:10:08 localhost shepherd[1]: Service sshd-12 has been disabled. 
Oct  4 07:10:08 localhost shepherd[1]: Transient service sshd-12 terminated, now unregistered. 
Oct  4 07:11:09 localhost shepherd[1]: Service sshd-1 has been stopped. 
Oct  4 07:11:09 localhost shepherd[1]: Transient service sshd-1 unregistered. 
Oct  4 07:11:09 localhost shepherd[1]: Service ssh-daemon has been stopped. 
Oct  4 07:11:59 localhost shepherd[1]: Service ssh-daemon has been started. 
Oct  4 07:12:02 localhost shepherd[1]: Service sshd-1 has been started. 
Oct  4 07:12:04 localhost sshd[241]: Accepted publickey for bob from 185.115.7.223 port 10202 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:15:09 localhost shepherd[1]: Service sshd-2 has been started. 
Oct  4 07:15:11 localhost sshd[269]: Accepted publickey for bob from 185.115.7.223 port 29443 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:16:08 localhost sshd[271]: error: no more sessions
Oct  4 07:16:08 localhost shepherd[1]: 1 connection still in use after sshd-2 termination. 
Oct  4 07:16:08 localhost shepherd[1]: Service sshd-2 has been disabled. 
Oct  4 07:16:08 localhost shepherd[1]: Transient service sshd-2 terminated, now unregistered. 
Oct  4 07:16:31 localhost shepherd[1]: Service sshd-3 has been started. 
Oct  4 07:16:33 localhost sshd[404]: Accepted publickey for bob from 185.115.7.223 port 10413 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:17:13 localhost shepherd[1]: 1 connection still in use after sshd-3 termination. 
Oct  4 07:17:13 localhost shepherd[1]: Service sshd-3 (PID 404) exited with 255. 
Oct  4 07:17:13 localhost shepherd[1]: Service sshd-3 has been disabled. 
Oct  4 07:17:13 localhost shepherd[1]: Transient service sshd-3 terminated, now unregistered. 
Oct  4 07:17:14 localhost shepherd[1]: Service sshd-4 has been started. 
Oct  4 07:17:15 localhost sshd[556]: Accepted publickey for bob from 185.115.7.223 port 10454 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:17:19 localhost shepherd[1]: 1 connection still in use after sshd-4 termination. 
Oct  4 07:17:19 localhost shepherd[1]: Service sshd-4 has been disabled. 
Oct  4 07:17:19 localhost shepherd[1]: Transient service sshd-4 terminated, now unregistered. 
Oct  4 07:27:39 localhost shepherd[1]: Service sshd-5 has been started. 
Oct  4 07:27:41 localhost sshd[602]: Accepted publickey for bob from 185.115.7.223 port 29522 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:28:13 localhost sshd[604]: error: no more sessions
Oct  4 07:28:13 localhost shepherd[1]: 1 connection still in use after sshd-5 termination. 
Oct  4 07:28:13 localhost shepherd[1]: Service sshd-5 has been disabled. 
Oct  4 07:28:13 localhost shepherd[1]: Transient service sshd-5 terminated, now unregistered. 
Oct  4 07:28:20 localhost shepherd[1]: Service sshd-6 has been started. 
Oct  4 07:28:21 localhost sshd[723]: Accepted publickey for bob from 185.115.7.223 port 29474 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:28:50 localhost sshd[725]: error: no more sessions
Oct  4 07:28:50 localhost shepherd[1]: 1 connection still in use after sshd-6 termination. 
Oct  4 07:28:50 localhost shepherd[1]: Service sshd-6 has been disabled. 
Oct  4 07:28:50 localhost shepherd[1]: Transient service sshd-6 terminated, now unregistered. 
Oct  4 07:30:39 localhost shepherd[1]: Service sshd-7 has been started. 
Oct  4 07:30:40 localhost sshd[840]: Accepted publickey for bob from 185.115.7.223 port 10445 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:31:44 localhost shepherd[1]: Service sshd-8 has been started. 
Oct  4 07:31:46 localhost sshd[857]: Accepted publickey for bob from 185.115.7.223 port 10393 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:32:13 localhost sshd[859]: error: no more sessions
Oct  4 07:32:13 localhost shepherd[1]: 2 connections still in use after sshd-8 termination. 
Oct  4 07:32:13 localhost shepherd[1]: Service sshd-8 has been disabled. 
Oct  4 07:32:13 localhost shepherd[1]: Transient service sshd-8 terminated, now unregistered. 
Oct  4 07:33:07 localhost shepherd[1]: Service ssh-daemon has been stopped. 
Oct  4 07:34:15 localhost shepherd[1]: Service ssh-daemon has been started. 
Oct  4 07:34:26 localhost shepherd[1]: Service sshd-1 has been started. 
Oct  4 07:34:28 localhost sshd[239]: Accepted publickey for bob from 185.115.7.223 port 29462 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:35:14 localhost shepherd[1]: Service sshd-2 has been started. 
Oct  4 07:35:16 localhost sshd[258]: Accepted publickey for bob from 185.115.7.223 port 29504 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:35:52 localhost shepherd[1]: 1 connection still in use after sshd-2 termination. 
Oct  4 07:35:52 localhost shepherd[1]: Service sshd-2 has been disabled. 
Oct  4 07:35:52 localhost shepherd[1]: Transient service sshd-2 terminated, now unregistered. 
Oct  4 07:36:13 localhost shepherd[1]: Service sshd-3 has been started. 
Oct  4 07:36:14 localhost sshd[418]: Accepted publickey for bob from 185.115.7.223 port 29463 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:36:52 localhost shepherd[1]: 1 connection still in use after sshd-3 termination. 
Oct  4 07:36:52 localhost shepherd[1]: Service sshd-3 (PID 418) exited with 255. 
Oct  4 07:36:52 localhost shepherd[1]: Service sshd-3 has been disabled. 
Oct  4 07:36:52 localhost shepherd[1]: Transient service sshd-3 terminated, now unregistered. 
Oct  4 07:38:51 localhost shepherd[1]: Service ssh-daemon has been started. 
Oct  4 07:38:58 localhost shepherd[1]: Service sshd-1 has been started. 
Oct  4 07:39:00 localhost sshd[257]: Accepted publickey for bob from 185.115.7.223 port 29563 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:40:14 localhost sshd[259]: Received disconnect from 185.115.7.223 port 29563:11: disconnected by user
Oct  4 07:40:14 localhost sshd[259]: Disconnected from user bob 185.115.7.223 port 29563
Oct  4 07:40:14 localhost shepherd[1]: 0 connections still in use after sshd-1 termination. 
Oct  4 07:40:14 localhost shepherd[1]: Service sshd-1 (PID 257) exited with 255. 
Oct  4 07:40:14 localhost shepherd[1]: Service sshd-1 has been disabled. 
Oct  4 07:40:14 localhost shepherd[1]: Transient service sshd-1 terminated, now unregistered. 
Oct  4 07:40:31 localhost shepherd[1]: Service sshd-2 has been started. 
Oct  4 07:40:33 localhost sshd[267]: Accepted publickey for bob from 185.115.7.223 port 10488 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:40:43 localhost sshd[269]: Received disconnect from 185.115.7.223 port 10488:11: disconnected by user
Oct  4 07:40:43 localhost sshd[269]: Disconnected from user bob 185.115.7.223 port 10488
Oct  4 07:40:43 localhost shepherd[1]: 0 connections still in use after sshd-2 termination. 
Oct  4 07:40:43 localhost shepherd[1]: Service sshd-2 (PID 267) exited with 255. 
Oct  4 07:40:43 localhost shepherd[1]: Service sshd-2 has been disabled. 
Oct  4 07:40:43 localhost shepherd[1]: Transient service sshd-2 terminated, now unregistered. 
Oct  4 07:41:03 localhost shepherd[1]: Service sshd-3 has been started. 
Oct  4 07:41:05 localhost sshd[271]: Accepted publickey for bob from 185.115.7.223 port 10368 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:41:10 localhost sshd[273]: Received disconnect from 185.115.7.223 port 10368:11: disconnected by user
Oct  4 07:41:10 localhost sshd[273]: Disconnected from user bob 185.115.7.223 port 10368
Oct  4 07:41:10 localhost shepherd[1]: 0 connections still in use after sshd-3 termination. 
Oct  4 07:41:10 localhost shepherd[1]: Service sshd-3 (PID 271) exited with 255. 
Oct  4 07:41:10 localhost shepherd[1]: Service sshd-3 has been disabled. 
Oct  4 07:41:10 localhost shepherd[1]: Transient service sshd-3 terminated, now unregistered. 
Oct  4 07:41:13 localhost shepherd[1]: Service sshd-4 has been started. 
Oct  4 07:41:16 localhost sshd[275]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 47302 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:41:19 localhost sshd[277]: Received disconnect from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 47302:11: disconnected by user
Oct  4 07:41:19 localhost sshd[277]: Disconnected from user bob 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 47302
Oct  4 07:41:19 localhost shepherd[1]: 0 connections still in use after sshd-4 termination. 
Oct  4 07:41:19 localhost shepherd[1]: Service sshd-4 (PID 275) exited with 255. 
Oct  4 07:41:19 localhost shepherd[1]: Service sshd-4 has been disabled. 
Oct  4 07:41:19 localhost shepherd[1]: Transient service sshd-4 terminated, now unregistered. 
Oct  4 07:41:24 localhost shepherd[1]: Service sshd-5 has been started. 
Oct  4 07:41:26 localhost sshd[280]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 33450 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:42:39 localhost shepherd[1]: 0 connections still in use after sshd-5 termination. 
Oct  4 07:42:39 localhost shepherd[1]: Service sshd-5 has been disabled. 
Oct  4 07:42:39 localhost shepherd[1]: Transient service sshd-5 terminated, now unregistered. 
Oct  4 07:43:20 localhost shepherd[1]: Service sshd-6 has been started. 
Oct  4 07:43:22 localhost sshd[436]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 60366 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:44:08 localhost shepherd[1]: 0 connections still in use after sshd-6 termination. 
Oct  4 07:44:08 localhost shepherd[1]: Service sshd-6 (PID 436) exited with 255. 
Oct  4 07:44:08 localhost shepherd[1]: Service sshd-6 has been disabled. 
Oct  4 07:44:08 localhost shepherd[1]: Transient service sshd-6 terminated, now unregistered. 
Oct  4 07:44:23 localhost shepherd[1]: Service sshd-7 has been started. 
Oct  4 07:44:25 localhost sshd[592]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 34526 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:44:56 localhost shepherd[1]: Service sshd-8 has been started. 
Oct  4 07:44:57 localhost sshd[598]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 59492 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:45:42 localhost shepherd[1]: 1 connection still in use after sshd-8 termination. 
Oct  4 07:45:42 localhost shepherd[1]: Service sshd-8 (PID 598) exited with 255. 
Oct  4 07:45:42 localhost shepherd[1]: Service sshd-8 has been disabled. 
Oct  4 07:45:42 localhost shepherd[1]: Transient service sshd-8 terminated, now unregistered. 
Oct  4 07:45:49 localhost shepherd[1]: Service sshd-9 has been started. 
Oct  4 07:45:51 localhost sshd[754]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 56454 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:46:35 localhost shepherd[1]: 1 connection still in use after sshd-9 termination. 
Oct  4 07:46:35 localhost shepherd[1]: Service sshd-9 has been disabled. 
Oct  4 07:46:35 localhost shepherd[1]: Transient service sshd-9 terminated, now unregistered. 
Oct  4 07:46:52 localhost shepherd[1]: Service ssh-daemon has been stopped. 
Oct  4 07:47:33 localhost shepherd[1]: Service ssh-daemon has been started. 
Oct  4 07:48:24 localhost shepherd[1]: Service sshd-1 has been started. 
Oct  4 07:48:26 localhost sshd[239]: Accepted publickey for bob from 185.115.7.223 port 29446 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:49:13 localhost shepherd[1]: Service sshd-2 has been started. 
Oct  4 07:49:15 localhost sshd[253]: Accepted publickey for bob from 185.115.7.223 port 29550 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:49:54 localhost shepherd[1]: 1 connection still in use after sshd-2 termination. 
Oct  4 07:49:54 localhost shepherd[1]: Service sshd-2 (PID 253) exited with 255. 
Oct  4 07:49:54 localhost shepherd[1]: Service sshd-2 has been disabled. 
Oct  4 07:49:54 localhost shepherd[1]: Transient service sshd-2 terminated, now unregistered. 
Oct  4 07:50:56 localhost shepherd[1]: Service sshd-3 has been started. 
Oct  4 07:50:58 localhost sshd[405]: Accepted publickey for bob from 185.115.7.223 port 10382 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:51:01 localhost shepherd[1]: Service sshd-1 has been stopped. 
Oct  4 07:51:01 localhost shepherd[1]: Transient service sshd-1 unregistered. 
Oct  4 07:52:54 localhost shepherd[1]: Service ssh-daemon has been started. 
Oct  4 07:52:56 localhost shepherd[1]: Service sshd-1 has been started. 
Oct  4 07:52:57 localhost sshd[238]: Accepted publickey for bob from 185.115.7.223 port 10479 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:53:22 localhost shepherd[1]: Service sshd-2 has been started. 
Oct  4 07:53:24 localhost sshd[246]: Accepted publickey for bob from 185.115.7.223 port 10482 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:53:59 localhost sshd[248]: error: no more sessions
Oct  4 07:53:59 localhost shepherd[1]: 1 connection still in use after sshd-2 termination. 
Oct  4 07:53:59 localhost shepherd[1]: Service sshd-2 has been disabled. 
Oct  4 07:53:59 localhost shepherd[1]: Transient service sshd-2 terminated, now unregistered. 
Oct  4 07:56:18 localhost shepherd[1]: Service sshd-3 has been started. 
Oct  4 07:56:20 localhost sshd[368]: Accepted publickey for bob from 185.115.7.223 port 25376 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:56:24 localhost shepherd[1]: Service ssh-daemon has been stopped. 
Oct  4 07:57:09 localhost shepherd[1]: Service ssh-daemon has been started. 
Oct  4 07:57:11 localhost shepherd[1]: Service sshd-1 has been started. 
Oct  4 07:57:12 localhost sshd[237]: Accepted publickey for bob from 185.115.7.223 port 25371 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:57:22 localhost shepherd[1]: Service sshd-2 has been started. 
Oct  4 07:57:23 localhost sshd[245]: Accepted publickey for bob from 185.115.7.223 port 29507 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:57:56 localhost sshd[247]: error: no more sessions
Oct  4 07:57:56 localhost shepherd[1]: 1 connection still in use after sshd-2 termination. 
Oct  4 07:57:56 localhost shepherd[1]: Service sshd-2 (PID 245) exited with 255. 
Oct  4 07:57:56 localhost shepherd[1]: Service sshd-2 has been disabled. 
Oct  4 07:57:56 localhost shepherd[1]: Transient service sshd-2 terminated, now unregistered. 
Oct  4 07:58:19 localhost shepherd[1]: Service sshd-3 has been started. 
Oct  4 07:58:20 localhost sshd[368]: Accepted publickey for bob from 185.115.7.223 port 29460 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 07:58:49 localhost sshd[370]: error: no more sessions
Oct  4 07:58:49 localhost shepherd[1]: 1 connection still in use after sshd-3 termination. 
Oct  4 07:58:49 localhost shepherd[1]: Service sshd-3 has been disabled. 
Oct  4 07:58:49 localhost shepherd[1]: Transient service sshd-3 terminated, now unregistered. 
Oct  4 08:00:15 localhost shepherd[1]: Service sshd-4 has been started. 
Oct  4 08:00:17 localhost sshd[485]: Accepted publickey for bob from 185.115.7.223 port 10372 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 08:00:26 localhost sshd[239]: Received disconnect from 185.115.7.223 port 25371:11: disconnected by user
Oct  4 08:00:26 localhost sshd[239]: Disconnected from user bob 185.115.7.223 port 25371
Oct  4 08:00:26 localhost shepherd[1]: 1 connection still in use after sshd-1 termination. 
Oct  4 08:00:26 localhost shepherd[1]: Service sshd-1 (PID 237) exited with 255. 
Oct  4 08:00:26 localhost shepherd[1]: Service sshd-1 has been disabled. 
Oct  4 08:00:26 localhost shepherd[1]: Transient service sshd-1 terminated, now unregistered. 
Oct  4 08:00:51 localhost sshd[487]: error: no more sessions
Oct  4 08:00:51 localhost shepherd[1]: 0 connections still in use after sshd-4 termination. 
Oct  4 08:00:51 localhost shepherd[1]: Service sshd-4 (PID 485) exited with 255. 
Oct  4 08:00:51 localhost shepherd[1]: Service sshd-4 has been disabled. 
Oct  4 08:00:51 localhost shepherd[1]: Transient service sshd-4 terminated, now unregistered. 
Oct  4 08:19:30 localhost shepherd[1]: Service sshd-5 has been started. 
Oct  4 08:19:32 localhost sshd[609]: Accepted publickey for bob from 176.221.231.220 port 43732 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 08:21:49 localhost shepherd[1]: Service sshd-6 has been started. 
Oct  4 08:21:53 localhost sshd[621]: Accepted publickey for bob from 176.221.231.220 port 51448 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 08:23:42 localhost shepherd[1]: Service sshd-7 has been started. 
Oct  4 08:23:43 localhost sshd[630]: Accepted publickey for bob from 185.70.53.164 port 29603 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 08:24:13 localhost sshd[632]: error: no more sessions
Oct  4 08:24:13 localhost shepherd[1]: 2 connections still in use after sshd-7 termination. 
Oct  4 08:24:13 localhost shepherd[1]: Service sshd-7 has been disabled. 
Oct  4 08:24:13 localhost shepherd[1]: Transient service sshd-7 terminated, now unregistered. 
Oct  4 08:24:36 localhost shepherd[1]: Service sshd-8 has been started. 
Oct  4 08:24:38 localhost sshd[752]: Accepted publickey for bob from 185.70.53.164 port 29677 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 08:25:05 localhost shepherd[1]: 2 connections still in use after sshd-8 termination. 
Oct  4 08:25:05 localhost shepherd[1]: Service sshd-8 has been disabled. 
Oct  4 08:25:05 localhost shepherd[1]: Transient service sshd-8 terminated, now unregistered. 
Oct  4 08:29:46 localhost shepherd[1]: Service sshd-9 has been started. 
Oct  4 08:29:47 localhost sshd[900]: Accepted publickey for bob from 185.70.53.164 port 29693 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 08:30:15 localhost shepherd[1]: 2 connections still in use after sshd-9 termination. 
Oct  4 08:30:15 localhost shepherd[1]: Service sshd-9 (PID 900) exited with 255. 
Oct  4 08:30:15 localhost shepherd[1]: Service sshd-9 has been disabled. 
Oct  4 08:30:15 localhost shepherd[1]: Transient service sshd-9 terminated, now unregistered. 
Oct  4 08:34:22 localhost shepherd[1]: Service sshd-10 has been started. 
Oct  4 08:34:23 localhost sshd[1049]: Accepted publickey for bob from 185.70.53.164 port 44181 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 08:34:24 localhost shepherd[1]: Service ssh-daemon has been stopped. 
Oct  4 08:35:14 localhost shepherd[1]: Service ssh-daemon has been started. 
Oct  4 08:35:46 localhost shepherd[1]: Service sshd-1 has been started. 
Oct  4 08:35:48 localhost sshd[259]: Accepted publickey for bob from 185.70.53.164 port 29608 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 08:35:51 localhost shepherd[1]: Service sshd-2 has been started. 
Oct  4 08:35:53 localhost sshd[264]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 54908 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 08:36:33 localhost shepherd[1]: Service sshd-3 has been started. 
Oct  4 08:36:34 localhost sshd[274]: Accepted publickey for bob from 185.70.53.164 port 44804 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 08:37:05 localhost shepherd[1]: 2 connections still in use after sshd-3 termination. 
Oct  4 08:37:05 localhost shepherd[1]: Service sshd-3 has been disabled. 
Oct  4 08:37:05 localhost shepherd[1]: Transient service sshd-3 terminated, now unregistered. 
Oct  4 08:37:18 localhost shepherd[1]: Service sshd-4 has been started. 
Oct  4 08:37:20 localhost sshd[424]: Accepted publickey for bob from 185.70.53.164 port 44907 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 08:38:09 localhost shepherd[1]: Service ssh-daemon has been started. 
Oct  4 08:38:28 localhost shepherd[1]: Service sshd-1 has been started. 
Oct  4 08:38:29 localhost sshd[239]: Accepted publickey for bob from 185.70.53.164 port 29582 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 08:39:05 localhost shepherd[1]: Service sshd-2 has been started. 
Oct  4 08:39:06 localhost sshd[248]: Accepted publickey for bob from 185.70.53.164 port 44208 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 08:39:21 localhost shepherd[1]: 1 connection still in use after sshd-2 termination. 
Oct  4 08:39:21 localhost shepherd[1]: Service sshd-2 has been disabled. 
Oct  4 08:39:21 localhost shepherd[1]: Transient service sshd-2 terminated, now unregistered. 
Oct  4 08:39:53 localhost shepherd[1]: Service sshd-3 has been started. 
Oct  4 08:39:54 localhost sshd[309]: Accepted publickey for bob from 185.70.53.164 port 44253 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 08:40:22 localhost shepherd[1]: 1 connection still in use after sshd-3 termination. 
Oct  4 08:40:22 localhost shepherd[1]: Service sshd-3 (PID 309) exited with 255. 
Oct  4 08:40:22 localhost shepherd[1]: Service sshd-3 has been disabled. 
Oct  4 08:40:22 localhost shepherd[1]: Transient service sshd-3 terminated, now unregistered. 
Oct  4 08:42:19 localhost shepherd[1]: Service ssh-daemon has been started. 
Oct  4 08:42:22 localhost shepherd[1]: Service sshd-1 has been started. 
Oct  4 08:42:24 localhost sshd[254]: Accepted publickey for bob from 185.70.53.164 port 29687 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 08:46:41 localhost shepherd[1]: Service sshd-2 has been started. 
Oct  4 08:46:44 localhost sshd[267]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 48908 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 08:48:49 localhost sshd[256]: Received disconnect from 185.70.53.164 port 29687:11: disconnected by user
Oct  4 08:48:49 localhost sshd[256]: Disconnected from user bob 185.70.53.164 port 29687
Oct  4 08:48:49 localhost shepherd[1]: 1 connection still in use after sshd-1 termination. 
Oct  4 08:48:49 localhost shepherd[1]: Service sshd-1 (PID 254) exited with 255. 
Oct  4 08:48:49 localhost shepherd[1]: Service sshd-1 has been disabled. 
Oct  4 08:48:49 localhost shepherd[1]: Transient service sshd-1 terminated, now unregistered. 
Oct  4 11:03:31 localhost shepherd[1]: 0 connections still in use after sshd-2 termination. 
Oct  4 11:03:31 localhost shepherd[1]: Service sshd-2 (PID 267) exited with 255. 
Oct  4 11:03:31 localhost shepherd[1]: Service sshd-2 has been disabled. 
Oct  4 11:03:31 localhost shepherd[1]: Transient service sshd-2 terminated, now unregistered. 
Oct  4 11:45:49 localhost shepherd[1]: Service sshd-3 has been started. 
Oct  4 11:45:51 localhost sshd[294]: Accepted publickey for bob from 185.70.53.164 port 29659 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 11:47:35 localhost shepherd[1]: Service sshd-4 has been started. 
Oct  4 11:47:37 localhost sshd[306]: Accepted publickey for bob from 185.70.53.164 port 1907 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 11:47:49 localhost shepherd[1]: Service sshd-5 has been started. 
Oct  4 11:47:52 localhost sshd[347]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 55988 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 11:48:15 localhost shepherd[1]: 2 connections still in use after sshd-4 termination. 
Oct  4 11:48:15 localhost shepherd[1]: Service sshd-4 has been disabled. 
Oct  4 11:48:15 localhost shepherd[1]: Transient service sshd-4 terminated, now unregistered. 
Oct  4 11:49:03 localhost shepherd[1]: Service sshd-5 has been stopped. 
Oct  4 11:49:03 localhost shepherd[1]: Transient service sshd-5 unregistered. 
Oct  4 11:50:46 localhost shepherd[1]: Service ssh-daemon has been started. 
Oct  4 11:50:53 localhost shepherd[1]: Service sshd-1 has been started. 
Oct  4 11:50:55 localhost sshd[238]: Accepted publickey for bob from 185.70.53.164 port 29589 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 11:51:49 localhost shepherd[1]: Service sshd-2 has been started. 
Oct  4 11:51:50 localhost sshd[250]: Accepted publickey for bob from 185.70.53.164 port 1915 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 11:52:28 localhost sshd[252]: error: no more sessions
Oct  4 11:52:28 localhost shepherd[1]: 1 connection still in use after sshd-2 termination. 
Oct  4 11:52:28 localhost shepherd[1]: Service sshd-2 has been disabled. 
Oct  4 11:52:28 localhost shepherd[1]: Transient service sshd-2 terminated, now unregistered. 
Oct  4 11:52:46 localhost shepherd[1]: Service sshd-3 has been started. 
Oct  4 11:52:48 localhost sshd[380]: Accepted publickey for bob from 185.70.53.164 port 3549 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 11:53:22 localhost shepherd[1]: 1 connection still in use after sshd-3 termination. 
Oct  4 11:53:22 localhost shepherd[1]: Service sshd-3 (PID 380) exited with 255. 
Oct  4 11:53:22 localhost shepherd[1]: Service sshd-3 has been disabled. 
Oct  4 11:53:22 localhost shepherd[1]: Transient service sshd-3 terminated, now unregistered. 
Oct  4 12:05:47 localhost shepherd[1]: Service sshd-4 has been started. 
Oct  4 12:05:48 localhost sshd[668]: Accepted publickey for bob from 185.70.53.164 port 1847 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 12:06:21 localhost shepherd[1]: 1 connection still in use after sshd-4 termination. 
Oct  4 12:06:21 localhost shepherd[1]: Service sshd-4 (PID 668) exited with 255. 
Oct  4 12:06:21 localhost shepherd[1]: Service sshd-4 has been disabled. 
Oct  4 12:06:21 localhost shepherd[1]: Transient service sshd-4 terminated, now unregistered. 
Oct  4 12:06:39 localhost shepherd[1]: Service ssh-daemon has been stopped. 
Oct  4 12:10:31 localhost shepherd[1]: Service ssh-daemon has been started. 
Oct  4 12:10:41 localhost shepherd[1]: Service sshd-1 has been started. 
Oct  4 12:10:43 localhost sshd[258]: Accepted publickey for bob from 185.70.53.164 port 1914 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 12:11:25 localhost shepherd[1]: Service sshd-2 has been started. 
Oct  4 12:11:27 localhost sshd[283]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 43872 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 12:11:54 localhost shepherd[1]: Service sshd-3 has been started. 
Oct  4 12:11:58 localhost sshd[286]: Accepted publickey for bob from 185.70.53.164 port 29596 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 12:12:54 localhost shepherd[1]: 2 connections still in use after sshd-3 termination. 
Oct  4 12:12:54 localhost shepherd[1]: Service sshd-3 (PID 286) exited with 255. 
Oct  4 12:12:54 localhost shepherd[1]: Service sshd-3 has been disabled. 
Oct  4 12:12:54 localhost shepherd[1]: Transient service sshd-3 terminated, now unregistered. 
Oct  4 12:14:10 localhost shepherd[1]: Service sshd-4 has been started. 
Oct  4 12:14:11 localhost sshd[461]: Accepted publickey for bob from 185.70.53.164 port 29693 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 12:14:49 localhost shepherd[1]: 2 connections still in use after sshd-4 termination. 
Oct  4 12:14:49 localhost shepherd[1]: Service sshd-4 (PID 461) exited with 255. 
Oct  4 12:14:49 localhost shepherd[1]: Service sshd-4 has been disabled. 
Oct  4 12:14:49 localhost shepherd[1]: Transient service sshd-4 terminated, now unregistered. 
Oct  4 12:15:25 localhost shepherd[1]: Service ssh-daemon has been stopped. 
Oct  4 12:17:34 localhost shepherd[1]: Service ssh-daemon has been started. 
Oct  4 12:17:56 localhost shepherd[1]: Service sshd-1 has been started. 
Oct  4 12:17:58 localhost sshd[256]: Accepted publickey for bob from 185.70.53.164 port 29656 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 12:19:46 localhost shepherd[1]: Service sshd-2 has been started. 
Oct  4 12:19:48 localhost sshd[262]: Accepted publickey for bob from 185.70.53.164 port 1871 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 12:20:23 localhost sshd[264]: error: no more sessions
Oct  4 12:20:23 localhost shepherd[1]: 1 connection still in use after sshd-2 termination. 
Oct  4 12:20:23 localhost shepherd[1]: Service sshd-2 has been disabled. 
Oct  4 12:20:23 localhost shepherd[1]: Transient service sshd-2 terminated, now unregistered. 
Oct  4 12:30:09 localhost shepherd[1]: Service sshd-3 has been started. 
Oct  4 12:30:11 localhost sshd[389]: Accepted publickey for bob from 185.70.53.164 port 29601 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 12:30:46 localhost shepherd[1]: 1 connection still in use after sshd-3 termination. 
Oct  4 12:30:46 localhost shepherd[1]: Service sshd-3 (PID 389) exited with 255. 
Oct  4 12:30:46 localhost shepherd[1]: Service sshd-3 has been disabled. 
Oct  4 12:30:46 localhost shepherd[1]: Transient service sshd-3 terminated, now unregistered. 
Oct  4 12:44:29 localhost shepherd[1]: Service sshd-4 has been started. 
Oct  4 12:44:31 localhost sshd[540]: Accepted publickey for bob from 185.70.53.164 port 1209 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 12:46:33 localhost shepherd[1]: Service sshd-5 has been started. 
Oct  4 12:46:34 localhost sshd[550]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 56270 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 12:47:17 localhost shepherd[1]: 2 connections still in use after sshd-5 termination. 
Oct  4 12:47:17 localhost shepherd[1]: Service sshd-5 (PID 550) exited with 255. 
Oct  4 12:47:17 localhost shepherd[1]: Service sshd-5 has been disabled. 
Oct  4 12:47:17 localhost shepherd[1]: Transient service sshd-5 terminated, now unregistered. 
Oct  4 13:28:20 localhost shepherd[1]: Service sshd-6 has been started. 
Oct  4 13:28:22 localhost sshd[713]: Accepted publickey for bob from 201:2a73:cac3:e128:cf3d:8dc:8afa:df66 port 42030 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
Oct  4 14:29:39 localhost shepherd[1]: 2 connections still in use after sshd-1 termination. 
Oct  4 14:29:39 localhost shepherd[1]: Service sshd-1 (PID 256) exited with 255. 
Oct  4 14:29:39 localhost shepherd[1]: Service sshd-1 has been disabled. 
Oct  4 14:29:39 localhost shepherd[1]: Transient service sshd-1 terminated, now unregistered. 
Oct  4 14:57:54 localhost shepherd[1]: 1 connection still in use after sshd-4 termination. 
Oct  4 14:57:54 localhost shepherd[1]: Service sshd-4 (PID 540) exited with 255. 
Oct  4 14:57:54 localhost shepherd[1]: Service sshd-4 has been disabled. 
Oct  4 14:57:54 localhost shepherd[1]: Transient service sshd-4 terminated, now unregistered. 
Oct  4 17:41:45 localhost shepherd[1]: 0 connections still in use after sshd-6 termination. 
Oct  4 17:41:45 localhost shepherd[1]: Service sshd-6 (PID 713) exited with 255. 
Oct  4 17:41:45 localhost shepherd[1]: Service sshd-6 has been disabled. 
Oct  4 17:41:45 localhost shepherd[1]: Transient service sshd-6 terminated, now unregistered. 
--8<---------------cut here---------------end--------------->8---

-- 
Best regards,
Andrew Tropin

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

^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#58290: guile ssh error on guix deploy
  2022-10-14  6:45   ` Andrew Tropin
@ 2022-10-17 14:39     ` Ludovic Courtès
  2022-10-17 17:27       ` Marius Bakke
  0 siblings, 1 reply; 8+ messages in thread
From: Ludovic Courtès @ 2022-10-17 14:39 UTC (permalink / raw)
  To: Andrew Tropin; +Cc: 58290

Hi,

Andrew Tropin <andrew@trop.in> skribis:

>>> ice-9/boot-9.scm:1685:16: In procedure raise-exception:
>>> Throw to key `guile-ssh-error' with args `("channel-open-session" "Channel opening failure: channel 67 error (2) open failed" #<input-output: channel (closed) 7f7d1af9e140> #f)'.
>>
>> Are there any hints from sshd in the /var/log/messages of that machine
>> as to why the connection was closed?
>
> bob@pinky /var/log$ zcat messages.1.gz | grep "Oct  4" | grep ssh

It’s hard (if not impossible) to see which lines correspond to the error
above.  :-)

Could try to reproduce the bug, and have ‘tail -f /var/log/messages’
running on the server side so you can capture just the right lines?
/var/log/debug might be interesting too.

Thanks,
Ludo’.




^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#58290: guile ssh error on guix deploy
  2022-10-17 14:39     ` Ludovic Courtès
@ 2022-10-17 17:27       ` Marius Bakke
  2022-10-18 15:31         ` Ludovic Courtès
  0 siblings, 1 reply; 8+ messages in thread
From: Marius Bakke @ 2022-10-17 17:27 UTC (permalink / raw)
  To: Ludovic Courtès, Andrew Tropin; +Cc: 58290

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

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

> Hi,
>
> Andrew Tropin <andrew@trop.in> skribis:
>
>>>> ice-9/boot-9.scm:1685:16: In procedure raise-exception:
>>>> Throw to key `guile-ssh-error' with args `("channel-open-session" "Channel opening failure: channel 67 error (2) open failed" #<input-output: channel (closed) 7f7d1af9e140> #f)'.
>>>
>>> Are there any hints from sshd in the /var/log/messages of that machine
>>> as to why the connection was closed?
>>
>> bob@pinky /var/log$ zcat messages.1.gz | grep "Oct  4" | grep ssh
>
> It’s hard (if not impossible) to see which lines correspond to the error
> above.  :-)
>
> Could try to reproduce the bug, and have ‘tail -f /var/log/messages’
> running on the server side so you can capture just the right lines?
> /var/log/debug might be interesting too.

I have the same problem.  Log messages around failure look something
like this (extracted from above message):

  Oct  4 11:51:49 localhost shepherd[1]: Service sshd-2 has been started. 
  Oct  4 11:51:50 localhost sshd[250]: Accepted publickey for bob from 185.70.53.164 port 1915 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
  Oct  4 11:52:28 localhost sshd[252]: error: no more sessions
  Oct  4 11:52:28 localhost shepherd[1]: 1 connection still in use after sshd-2 termination. 
  Oct  4 11:52:28 localhost shepherd[1]: Service sshd-2 has been disabled. 

Then deploy crashes with 'Channel opening failure'.

Due to the number of SSH connections made by deploy and frequent
occurence of this problem, I was not able to successfully deploy through
many attempts.

I found that removing the memoizing open-machine-ssh-session* in
(gnu machine ssh) works around it and can happily deploy again.

(that is, just use 'open-machine-ssh-session' instead)

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

^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#58290: guile ssh error on guix deploy
  2022-10-17 17:27       ` Marius Bakke
@ 2022-10-18 15:31         ` Ludovic Courtès
  2022-11-03 23:47           ` Marius Bakke
  0 siblings, 1 reply; 8+ messages in thread
From: Ludovic Courtès @ 2022-10-18 15:31 UTC (permalink / raw)
  To: Marius Bakke; +Cc: 58290, Andrew Tropin

Hi,

Marius Bakke <marius@gnu.org> skribis:

> I have the same problem.  Log messages around failure look something
> like this (extracted from above message):
>
>   Oct  4 11:51:49 localhost shepherd[1]: Service sshd-2 has been started. 
>   Oct  4 11:51:50 localhost sshd[250]: Accepted publickey for bob from 185.70.53.164 port 1915 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
>   Oct  4 11:52:28 localhost sshd[252]: error: no more sessions
>   Oct  4 11:52:28 localhost shepherd[1]: 1 connection still in use after sshd-2 termination. 
>   Oct  4 11:52:28 localhost shepherd[1]: Service sshd-2 has been disabled. 
>
> Then deploy crashes with 'Channel opening failure'.

“no more sessions” comes from this:

--8<---------------cut here---------------start------------->8---
int
session_open(Authctxt *authctxt, int chanid)
{
	Session *s = session_new();
	debug("session_open: channel %d", chanid);
	if (s == NULL) {
		error("no more sessions");
		return 0;
	}

[...]

}
--8<---------------cut here---------------end--------------->8---

Would be interesting to run sshd in verbose/debug mode and see why we
hit that; it could be because the maximum number of sessions has been
reached or something.

> Due to the number of SSH connections made by deploy and frequent
> occurence of this problem, I was not able to successfully deploy through
> many attempts.

Ouch.  Normally, thanks to memoization, ‘guix deploy’ opens only one
session per machine.  (I think it works well with the 25 local build
machines behind berlin; it’s also fine for a small set of machines I
take care of at work.)

> I found that removing the memoizing open-machine-ssh-session* in
> (gnu machine ssh) works around it and can happily deploy again.
>
> (that is, just use 'open-machine-ssh-session' instead)

Interesting.  That gives us a hint.  Could you add a ‘pk’ in
‘open-machine-ssh-session*’ to see how many connections it opens?

Thanks for your feedback!

Ludo’.




^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#58290: guile ssh error on guix deploy
  2022-10-18 15:31         ` Ludovic Courtès
@ 2022-11-03 23:47           ` Marius Bakke
  2022-11-10 10:06             ` Andrew Tropin
  0 siblings, 1 reply; 8+ messages in thread
From: Marius Bakke @ 2022-11-03 23:47 UTC (permalink / raw)
  To: Ludovic Courtès; +Cc: 58290, Andrew Tropin


[-- Attachment #1.1: Type: text/plain, Size: 9393 bytes --]

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

> Hi,
>
> Marius Bakke <marius@gnu.org> skribis:
>
>> I have the same problem.  Log messages around failure look something
>> like this (extracted from above message):
>>
>>   Oct  4 11:51:49 localhost shepherd[1]: Service sshd-2 has been started. 
>>   Oct  4 11:51:50 localhost sshd[250]: Accepted publickey for bob from 185.70.53.164 port 1915 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
>>   Oct  4 11:52:28 localhost sshd[252]: error: no more sessions
>>   Oct  4 11:52:28 localhost shepherd[1]: 1 connection still in use after sshd-2 termination. 
>>   Oct  4 11:52:28 localhost shepherd[1]: Service sshd-2 has been disabled. 
>>
>> Then deploy crashes with 'Channel opening failure'.
>
> “no more sessions” comes from this:
>
> --8<---------------cut here---------------start------------->8---
> int
> session_open(Authctxt *authctxt, int chanid)
> {
> 	Session *s = session_new();
> 	debug("session_open: channel %d", chanid);
> 	if (s == NULL) {
> 		error("no more sessions");
> 		return 0;
> 	}
>
> [...]
>
> }
> --8<---------------cut here---------------end--------------->8---
>
> Would be interesting to run sshd in verbose/debug mode and see why we
> hit that; it could be because the maximum number of sessions has been
> reached or something.

I enabled (log-level 'debug) and this is what happens server side:

Nov  3 21:48:25 capella sshd[26345]: debug1: permanently_set_uid: 0/0
Nov  3 21:50:27 capella sshd[26115]: debug1: Received SIGCHLD.
Nov  3 21:50:27 capella sshd[26115]: debug1: session_by_pid: pid 26345
Nov  3 21:50:27 capella sshd[26115]: debug1: session_exit_message: session 8 channel 8 pid 26345
Nov  3 21:50:27 capella sshd[26115]: debug1: session_exit_message: release channel 8
Nov  3 21:50:28 capella sshd[26115]: debug1: server_input_channel_open: ctype session rchan 65 win 64000 max 32768
Nov  3 21:50:28 capella sshd[26115]: debug1: input_session_request
Nov  3 21:50:28 capella sshd[26115]: debug1: channel 0: new [server-session]
Nov  3 21:50:28 capella sshd[26115]: debug1: session_new: session 0
Nov  3 21:50:28 capella sshd[26115]: debug1: session_open: channel 0
Nov  3 21:50:28 capella sshd[26115]: debug1: session_open: session 0: link with channel 0
Nov  3 21:50:28 capella sshd[26115]: debug1: server_input_channel_open: confirm session
Nov  3 21:50:28 capella sshd[26115]: debug1: server_input_channel_req: channel 0 request exec reply 1
Nov  3 21:50:28 capella sshd[26115]: debug1: session_by_channel: session 0 channel 0
Nov  3 21:50:28 capella sshd[26115]: debug1: session_input_channel_req: session 0 req exec
Nov  3 21:50:28 capella sshd[26535]: debug1: PAM: reinitializing credentials
Nov  3 21:50:28 capella sshd[26535]: debug1: permanently_set_uid: 0/0
Nov  3 21:50:28 capella sshd[26115]: debug1: server_input_channel_open: ctype session rchan 66 win 64000 max 32768
Nov  3 21:50:28 capella sshd[26115]: debug1: input_session_request
Nov  3 21:50:28 capella sshd[26115]: debug1: channel 10: new [server-session]
Nov  3 21:50:28 capella sshd[26115]: debug1: session_open: channel 10
["no more sessions" error occurs here, in a different log file]
Nov  3 21:50:28 capella sshd[26115]: debug1: session open failed, free channel 10
Nov  3 21:50:28 capella sshd[26115]: debug1: channel 10: free: server-session, nchannels 11
Nov  3 21:50:28 capella sshd[26115]: debug1: server_input_channel_open: failure session
Nov  3 21:50:28 capella sshd[26115]: debug1: channel 0: free: server-session, nchannels 10
Nov  3 21:50:28 capella sshd[26115]: debug1: channel 1: free: server-session, nchannels 9
Nov  3 21:50:28 capella sshd[26115]: debug1: channel 2: free: server-session, nchannels 8
Nov  3 21:50:28 capella sshd[26115]: debug1: channel 3: free: server-session, nchannels 7
Nov  3 21:50:28 capella sshd[26115]: debug1: channel 4: free: server-session, nchannels 6
Nov  3 21:50:28 capella sshd[26115]: debug1: channel 5: free: server-session, nchannels 5
Nov  3 21:50:28 capella sshd[26115]: debug1: channel 6: free: server-session, nchannels 4
Nov  3 21:50:28 capella sshd[26115]: debug1: channel 7: free: server-session, nchannels 3
Nov  3 21:50:28 capella sshd[26115]: debug1: channel 8: free: server-session, nchannels 2
Nov  3 21:50:28 capella sshd[26115]: debug1: channel 9: free: server-session, nchannels 1
Nov  3 21:50:28 capella sshd[26115]: debug1: do_cleanup

I compared this with a successful deploy:

Nov  3 21:44:22 capella sshd[25842]: debug1: permanently_set_uid: 0/0
Nov  3 21:46:25 capella sshd[25612]: debug1: Received SIGCHLD.
Nov  3 21:46:25 capella sshd[25612]: debug1: session_by_pid: pid 25842
Nov  3 21:46:25 capella sshd[25612]: debug1: session_exit_message: session 6 channel 6 pid 25842
Nov  3 21:46:25 capella sshd[25612]: debug1: session_exit_message: release channel 6
Nov  3 21:46:26 capella sshd[25612]: debug1: server_input_channel_open: ctype session rchan 65 win 64000 max 32768
Nov  3 21:46:26 capella sshd[25612]: debug1: input_session_request
Nov  3 21:46:26 capella sshd[25612]: debug1: channel 0: new [server-session]
Nov  3 21:46:26 capella sshd[25612]: debug1: session_new: session 0
Nov  3 21:46:26 capella sshd[25612]: debug1: session_open: channel 0
Nov  3 21:46:26 capella sshd[25612]: debug1: session_open: session 0: link with channel 0
Nov  3 21:46:26 capella sshd[25612]: debug1: server_input_channel_open: confirm session
Nov  3 21:46:26 capella sshd[25612]: debug1: server_input_channel_req: channel 0 request exec reply 1
Nov  3 21:46:26 capella sshd[25612]: debug1: session_by_channel: session 0 channel 0
Nov  3 21:46:26 capella sshd[25612]: debug1: session_input_channel_req: session 0 req exec
Nov  3 21:46:26 capella sshd[26032]: debug1: PAM: reinitializing credentials
Nov  3 21:46:26 capella sshd[26032]: debug1: permanently_set_uid: 0/0
Nov  3 21:46:26 capella sshd[25612]: debug1: server_input_channel_open: ctype session rchan 66 win 64000 max 32768
Nov  3 21:46:26 capella sshd[25612]: debug1: input_session_request
Nov  3 21:46:26 capella sshd[25612]: debug1: channel 8: new [server-session]
Nov  3 21:46:26 capella sshd[25612]: debug1: session_new: session 8
Nov  3 21:46:26 capella sshd[25612]: debug1: session_open: channel 8
Nov  3 21:46:26 capella sshd[25612]: debug1: session_open: session 8: link with channel 8
Nov  3 21:46:26 capella sshd[25612]: debug1: server_input_channel_open: confirm session
Nov  3 21:46:26 capella sshd[25612]: debug1: server_input_channel_req: channel 8 request exec reply 1
Nov  3 21:46:26 capella sshd[25612]: debug1: session_by_channel: session 8 channel 8
Nov  3 21:46:26 capella sshd[25612]: debug1: session_input_channel_req: session 8 req exec
Nov  3 21:46:26 capella sshd[26043]: debug1: PAM: reinitializing credentials
Nov  3 21:46:26 capella sshd[26043]: debug1: permanently_set_uid: 0/0
Nov  3 21:46:28 capella sshd[25612]: debug1: chan_shutdown_extended_read: channel 8: (i0 o3 sock -1 wfd -1 efd 13 [read])
Nov  3 21:46:28 capella sshd[25612]: debug1: server_input_channel_open: ctype session rchan 67 win 64000 max 32768
Nov  3 21:46:28 capella sshd[25612]: debug1: input_session_request
Nov  3 21:46:28 capella sshd[25612]: debug1: channel 9: new [server-session]
Nov  3 21:46:28 capella sshd[25612]: debug1: session_new: session 9
[... more channels and stuffs before graceful shutdown ...]

I believe the two-minute window before SIGCHLD is waiting for some
Shepherd services to time out (long story..!).

In my current tests the failure always occur at the
very end of deploy:

building /gnu/store/19yajyzw4jhnkkz9w0l9gm4az0jxihkc-install-bootloader.scm.drv...
building /gnu/store/m7ngq5gszyswm6sficinz7ghpra30dl4-remote-exp.scm.drv...
;;; [2022/11/03 21:50:28.892606, 0] [GSSH ERROR] Channel opening failure: channel 66 error (2) open failed: #<input-output: channel (closed) 7fdefb015e80>

What's interesting is that all of the failed deploys fail to open
"channel 10", whereas successful deploys never reach it.  All of these
are deploying the exact same configuration and commit, so the SSH
traffic should nearly identical.

I have attached the transcripts of each session (by grepping the PIDs
from /var/log/debug).  Grepping for session_open yields some
inconstencies, but haven't studied them in detail yet.

>> Due to the number of SSH connections made by deploy and frequent
>> occurence of this problem, I was not able to successfully deploy through
>> many attempts.
>
> Ouch.  Normally, thanks to memoization, ‘guix deploy’ opens only one
> session per machine.  (I think it works well with the 25 local build
> machines behind berlin; it’s also fine for a small set of machines I
> take care of at work.)

Have they been rebooted since the switch to inetd-style sshd?  It fails
more often than not for me.

>> I found that removing the memoizing open-machine-ssh-session* in
>> (gnu machine ssh) works around it and can happily deploy again.
>>
>> (that is, just use 'open-machine-ssh-session' instead)
>
> Interesting.  That gives us a hint.  Could you add a ‘pk’ in
> ‘open-machine-ssh-session*’ to see how many connections it opens?

Indeed it only opens a single connection.  The problem seems to be
with multiple "channels" and "sessions" over a single connection.


[-- Attachment #1.2: deploy-fail.log.gz --]
[-- Type: application/gzip, Size: 3684 bytes --]

[-- Attachment #1.3: deploy-success.log.gz --]
[-- Type: application/gzip, Size: 3943 bytes --]

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

^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#58290: guile ssh error on guix deploy
  2022-11-03 23:47           ` Marius Bakke
@ 2022-11-10 10:06             ` Andrew Tropin
  0 siblings, 0 replies; 8+ messages in thread
From: Andrew Tropin @ 2022-11-10 10:06 UTC (permalink / raw)
  To: Marius Bakke, Ludovic Courtès; +Cc: poptsov.artyom, 58290

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

On 2022-11-04 00:47, Marius Bakke wrote:

> Ludovic Courtès <ludo@gnu.org> skriver:
>
>> Hi,
>>
>> Marius Bakke <marius@gnu.org> skribis:
>>
>>> I have the same problem.  Log messages around failure look something
>>> like this (extracted from above message):
>>>
>>>   Oct  4 11:51:49 localhost shepherd[1]: Service sshd-2 has been started. 
>>>   Oct  4 11:51:50 localhost sshd[250]: Accepted publickey for bob from 185.70.53.164 port 1915 ssh2: RSA SHA256:/X3jyhyMizAOKOjCfXK5cLN3Pa0vmi7dbQG+fxK3d3Y
>>>   Oct  4 11:52:28 localhost sshd[252]: error: no more sessions
>>>   Oct  4 11:52:28 localhost shepherd[1]: 1 connection still in use after sshd-2 termination. 
>>>   Oct  4 11:52:28 localhost shepherd[1]: Service sshd-2 has been disabled. 
>>>
>>> Then deploy crashes with 'Channel opening failure'.
>>
>> “no more sessions” comes from this:
>>
>> --8<---------------cut here---------------start------------->8---
>> int
>> session_open(Authctxt *authctxt, int chanid)
>> {
>> 	Session *s = session_new();
>> 	debug("session_open: channel %d", chanid);
>> 	if (s == NULL) {
>> 		error("no more sessions");
>> 		return 0;
>> 	}
>>
>> [...]
>>
>> }
>> --8<---------------cut here---------------end--------------->8---
>>
>> Would be interesting to run sshd in verbose/debug mode and see why we
>> hit that; it could be because the maximum number of sessions has been
>> reached or something.
>
> I enabled (log-level 'debug) and this is what happens server side:
>
> Nov  3 21:48:25 capella sshd[26345]: debug1: permanently_set_uid: 0/0
> Nov  3 21:50:27 capella sshd[26115]: debug1: Received SIGCHLD.
> Nov  3 21:50:27 capella sshd[26115]: debug1: session_by_pid: pid 26345
> Nov  3 21:50:27 capella sshd[26115]: debug1: session_exit_message: session 8 channel 8 pid 26345
> Nov  3 21:50:27 capella sshd[26115]: debug1: session_exit_message: release channel 8
> Nov  3 21:50:28 capella sshd[26115]: debug1: server_input_channel_open: ctype session rchan 65 win 64000 max 32768
> Nov  3 21:50:28 capella sshd[26115]: debug1: input_session_request
> Nov  3 21:50:28 capella sshd[26115]: debug1: channel 0: new [server-session]
> Nov  3 21:50:28 capella sshd[26115]: debug1: session_new: session 0
> Nov  3 21:50:28 capella sshd[26115]: debug1: session_open: channel 0
> Nov  3 21:50:28 capella sshd[26115]: debug1: session_open: session 0: link with channel 0
> Nov  3 21:50:28 capella sshd[26115]: debug1: server_input_channel_open: confirm session
> Nov  3 21:50:28 capella sshd[26115]: debug1: server_input_channel_req: channel 0 request exec reply 1
> Nov  3 21:50:28 capella sshd[26115]: debug1: session_by_channel: session 0 channel 0
> Nov  3 21:50:28 capella sshd[26115]: debug1: session_input_channel_req: session 0 req exec
> Nov  3 21:50:28 capella sshd[26535]: debug1: PAM: reinitializing credentials
> Nov  3 21:50:28 capella sshd[26535]: debug1: permanently_set_uid: 0/0
> Nov  3 21:50:28 capella sshd[26115]: debug1: server_input_channel_open: ctype session rchan 66 win 64000 max 32768
> Nov  3 21:50:28 capella sshd[26115]: debug1: input_session_request
> Nov  3 21:50:28 capella sshd[26115]: debug1: channel 10: new [server-session]
> Nov  3 21:50:28 capella sshd[26115]: debug1: session_open: channel 10
> ["no more sessions" error occurs here, in a different log file]
> Nov  3 21:50:28 capella sshd[26115]: debug1: session open failed, free channel 10
> Nov  3 21:50:28 capella sshd[26115]: debug1: channel 10: free: server-session, nchannels 11
> Nov  3 21:50:28 capella sshd[26115]: debug1: server_input_channel_open: failure session
> Nov  3 21:50:28 capella sshd[26115]: debug1: channel 0: free: server-session, nchannels 10
> Nov  3 21:50:28 capella sshd[26115]: debug1: channel 1: free: server-session, nchannels 9
> Nov  3 21:50:28 capella sshd[26115]: debug1: channel 2: free: server-session, nchannels 8
> Nov  3 21:50:28 capella sshd[26115]: debug1: channel 3: free: server-session, nchannels 7
> Nov  3 21:50:28 capella sshd[26115]: debug1: channel 4: free: server-session, nchannels 6
> Nov  3 21:50:28 capella sshd[26115]: debug1: channel 5: free: server-session, nchannels 5
> Nov  3 21:50:28 capella sshd[26115]: debug1: channel 6: free: server-session, nchannels 4
> Nov  3 21:50:28 capella sshd[26115]: debug1: channel 7: free: server-session, nchannels 3
> Nov  3 21:50:28 capella sshd[26115]: debug1: channel 8: free: server-session, nchannels 2
> Nov  3 21:50:28 capella sshd[26115]: debug1: channel 9: free: server-session, nchannels 1
> Nov  3 21:50:28 capella sshd[26115]: debug1: do_cleanup
>
> I compared this with a successful deploy:
>
> Nov  3 21:44:22 capella sshd[25842]: debug1: permanently_set_uid: 0/0
> Nov  3 21:46:25 capella sshd[25612]: debug1: Received SIGCHLD.
> Nov  3 21:46:25 capella sshd[25612]: debug1: session_by_pid: pid 25842
> Nov  3 21:46:25 capella sshd[25612]: debug1: session_exit_message: session 6 channel 6 pid 25842
> Nov  3 21:46:25 capella sshd[25612]: debug1: session_exit_message: release channel 6
> Nov  3 21:46:26 capella sshd[25612]: debug1: server_input_channel_open: ctype session rchan 65 win 64000 max 32768
> Nov  3 21:46:26 capella sshd[25612]: debug1: input_session_request
> Nov  3 21:46:26 capella sshd[25612]: debug1: channel 0: new [server-session]
> Nov  3 21:46:26 capella sshd[25612]: debug1: session_new: session 0
> Nov  3 21:46:26 capella sshd[25612]: debug1: session_open: channel 0
> Nov  3 21:46:26 capella sshd[25612]: debug1: session_open: session 0: link with channel 0
> Nov  3 21:46:26 capella sshd[25612]: debug1: server_input_channel_open: confirm session
> Nov  3 21:46:26 capella sshd[25612]: debug1: server_input_channel_req: channel 0 request exec reply 1
> Nov  3 21:46:26 capella sshd[25612]: debug1: session_by_channel: session 0 channel 0
> Nov  3 21:46:26 capella sshd[25612]: debug1: session_input_channel_req: session 0 req exec
> Nov  3 21:46:26 capella sshd[26032]: debug1: PAM: reinitializing credentials
> Nov  3 21:46:26 capella sshd[26032]: debug1: permanently_set_uid: 0/0
> Nov  3 21:46:26 capella sshd[25612]: debug1: server_input_channel_open: ctype session rchan 66 win 64000 max 32768
> Nov  3 21:46:26 capella sshd[25612]: debug1: input_session_request
> Nov  3 21:46:26 capella sshd[25612]: debug1: channel 8: new [server-session]
> Nov  3 21:46:26 capella sshd[25612]: debug1: session_new: session 8
> Nov  3 21:46:26 capella sshd[25612]: debug1: session_open: channel 8
> Nov  3 21:46:26 capella sshd[25612]: debug1: session_open: session 8: link with channel 8
> Nov  3 21:46:26 capella sshd[25612]: debug1: server_input_channel_open: confirm session
> Nov  3 21:46:26 capella sshd[25612]: debug1: server_input_channel_req: channel 8 request exec reply 1
> Nov  3 21:46:26 capella sshd[25612]: debug1: session_by_channel: session 8 channel 8
> Nov  3 21:46:26 capella sshd[25612]: debug1: session_input_channel_req: session 8 req exec
> Nov  3 21:46:26 capella sshd[26043]: debug1: PAM: reinitializing credentials
> Nov  3 21:46:26 capella sshd[26043]: debug1: permanently_set_uid: 0/0
> Nov  3 21:46:28 capella sshd[25612]: debug1: chan_shutdown_extended_read: channel 8: (i0 o3 sock -1 wfd -1 efd 13 [read])
> Nov  3 21:46:28 capella sshd[25612]: debug1: server_input_channel_open: ctype session rchan 67 win 64000 max 32768
> Nov  3 21:46:28 capella sshd[25612]: debug1: input_session_request
> Nov  3 21:46:28 capella sshd[25612]: debug1: channel 9: new [server-session]
> Nov  3 21:46:28 capella sshd[25612]: debug1: session_new: session 9
> [... more channels and stuffs before graceful shutdown ...]
>
> I believe the two-minute window before SIGCHLD is waiting for some
> Shepherd services to time out (long story..!).
>
> In my current tests the failure always occur at the
> very end of deploy:
>
> building /gnu/store/19yajyzw4jhnkkz9w0l9gm4az0jxihkc-install-bootloader.scm.drv...
> building /gnu/store/m7ngq5gszyswm6sficinz7ghpra30dl4-remote-exp.scm.drv...
> ;;; [2022/11/03 21:50:28.892606, 0] [GSSH ERROR] Channel opening failure: channel 66 error (2) open failed: #<input-output: channel (closed) 7fdefb015e80>
>
> What's interesting is that all of the failed deploys fail to open
> "channel 10", whereas successful deploys never reach it.  All of these
> are deploying the exact same configuration and commit, so the SSH
> traffic should nearly identical.
>
> I have attached the transcripts of each session (by grepping the PIDs
> from /var/log/debug).  Grepping for session_open yields some
> inconstencies, but haven't studied them in detail yet.
>
>>> Due to the number of SSH connections made by deploy and frequent
>>> occurence of this problem, I was not able to successfully deploy through
>>> many attempts.
>>
>> Ouch.  Normally, thanks to memoization, ‘guix deploy’ opens only one
>> session per machine.  (I think it works well with the 25 local build
>> machines behind berlin; it’s also fine for a small set of machines I
>> take care of at work.)
>
> Have they been rebooted since the switch to inetd-style sshd?  It fails
> more often than not for me.
>
>>> I found that removing the memoizing open-machine-ssh-session* in
>>> (gnu machine ssh) works around it and can happily deploy again.
>>>
>>> (that is, just use 'open-machine-ssh-session' instead)
>>
>> Interesting.  That gives us a hint.  Could you add a ‘pk’ in
>> ‘open-machine-ssh-session*’ to see how many connections it opens?
>
> Indeed it only opens a single connection.  The problem seems to be
> with multiple "channels" and "sessions" over a single connection.
>

Very detailed report, thank you for digging in!

CCed Artyom Poptsov, author of Guile-SSH.

-- 
Best regards,
Andrew Tropin

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

^ permalink raw reply	[flat|nested] 8+ messages in thread

end of thread, other threads:[~2022-11-10 10:11 UTC | newest]

Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-10-04 11:09 bug#58290: guile ssh error on guix deploy Andrew Tropin
2022-10-08 12:39 ` Ludovic Courtès
2022-10-14  6:45   ` Andrew Tropin
2022-10-17 14:39     ` Ludovic Courtès
2022-10-17 17:27       ` Marius Bakke
2022-10-18 15:31         ` Ludovic Courtès
2022-11-03 23:47           ` Marius Bakke
2022-11-10 10:06             ` Andrew Tropin

Code repositories for project(s) associated with this public inbox

	https://git.savannah.gnu.org/cgit/guix.git

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).