Nixpkgs: sshd.socket fails after some disconnections.

Created on 30 Sep 2020  路  12Comments  路  Source: NixOS/nixpkgs

Describe the bug

After some NixOS updates Sometimes SSH is unreachable.

To Reproduce

{
    services.openssh = {
        enable = true;
        startWhenNeeded = true;
        permitRootLogin = "without-password";

        extraConfig = ''
            AllowGroups ssh
            MaxAuthTries 3
            LogLevel ERROR
            TCPKeepAlive no
            ClientAliveCountMax 24
            ClientAliveInterval 3600
        '';
    };

    systemd.services."sshd@" = {
        serviceConfig = {
            OOMScoreAdjust = "-1000";
        };
        unitConfig = {
            IgnoreOnIsolate = true;
        };
    };
}

Expected behavior

SSH always works.

Additional context

The logs show the following:

Sep 29 20:14:14 t6 systemd[1]: sshd.socket: Failed to queue service startup job (Maybe the service file is missing or not a template unit?): Transport endpoint is not connected
Sep 29 20:14:14 t6 systemd[1]: sshd.socket: Failed with result 'resources'.
Sep 29 20:14:14 t6 systemd[1]: sshd.socket: Consumed 1ms CPU time, received 216B IP traffic, sent 60B IP traffic.

The "Maybe the service file is missing or not a template unit?" is what led me to correlate updates.

Notify maintainers Unclear who these are.

Metadata

  • system: "x86_64-linux"
  • host os: Linux 5.4.66, NixOS, 21.03pre244416.daaa0e33505 (Okapi)
  • multi-user?: yes
  • sandbox: yes
  • version: nix-env (Nix) 2.3.7
  • channels(kevincox): ""
  • channels(root): "nixos-21.03pre244416.daaa0e33505, nixpkgs-21.03pre244458.3eb1f8a446d"
  • nixpkgs: /nix/var/nix/profiles/per-user/root/channels/nixos

Maintainer information:

module:
- openssh
bug regression nixos
Source
picture kevincox
👍1

All 12 comments

Actually thinking back I rebooted after the update so it probably isn't that.

kevincox picture kevincox on 30 Sep 2020

I realize that there is very little to go on here. I'm hoping that I can find someone else who is seeing this or just log what I find for now.

kevincox picture kevincox on 30 Sep 2020

It might be related to connection overload. However I didn't see log lines about that in the past so it isn't clear that was the reason. However in artificial scenarios it does mimic the behaviour.

Otherwise it may be some amount of failed auth attempts. I've increased the log level of sshd itself to monitor this.

kevincox picture kevincox on 30 Sep 2020

my server is also running unstable, and I haven't had any closures...

jonringer picture jonringer on 30 Sep 2020 
Oct 05 06:40:48 t6 systemd[1]: Starting SSH Daemon (120.201.250.44:44340)...
Oct 05 06:40:48 t6 systemd[1]: Started SSH Daemon (120.201.250.44:44340).
Oct 05 06:40:48 t6 sshd[10665]: Connection from 120.201.250.44 port 44340 on 192.168.0.250 port 22 rdomain ""
Oct 05 06:40:48 t6 sshd[10665]: Connection closed by 120.201.250.44 port 44340 [preauth]
Oct 05 06:40:48 t6 systemd[1]: [email protected]:22-120.201.250.44:44340.service: Succeeded.
Oct 05 06:42:11 t6 systemd[1]: Starting SSH Daemon (62.234.182.174:38128)...
Oct 05 06:42:11 t6 systemd[1]: Started SSH Daemon (62.234.182.174:38128).
Oct 05 06:42:11 t6 sshd[10760]: Connection from 62.234.182.174 port 38128 on 192.168.0.250 port 22 rdomain ""
Oct 05 06:42:13 t6 sshd[10760]: Connection closed by 62.234.182.174 port 38128 [preauth]
Oct 05 06:42:13 t6 systemd[1]: [email protected]:22-62.234.182.174:38128.service: Succeeded.
Oct 05 06:43:31 t6 systemd[1]: Starting SSH Daemon (112.85.42.69:47192)...
Oct 05 06:43:31 t6 systemd[1]: Started SSH Daemon (112.85.42.69:47192).
Oct 05 06:43:31 t6 sshd[10848]: Connection from 112.85.42.69 port 47192 on 192.168.0.250 port 22 rdomain ""
Oct 05 06:43:31 t6 sshd[10848]: Unable to negotiate with 112.85.42.69 port 47192: no matching key exchange method found. Their offer: diffie-hellman-group1-sha1,diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1 [preauth]
Oct 05 06:43:31 t6 systemd[1]: [email protected]:22-112.85.42.69:47192.service: Succeeded.
Oct 05 06:47:12 t6 systemd[1]: Starting SSH Daemon (112.85.42.47:60484)...
Oct 05 06:47:12 t6 systemd[1]: Started SSH Daemon (112.85.42.47:60484).
Oct 05 06:47:12 t6 sshd[11034]: Connection from 112.85.42.47 port 60484 on 192.168.0.250 port 22 rdomain ""
Oct 05 06:47:12 t6 sshd[11034]: Unable to negotiate with 112.85.42.47 port 60484: no matching key exchange method found. Their offer: diffie-hellman-group1-sha1,diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1 [preauth]
Oct 05 06:47:12 t6 systemd[1]: [email protected]:22-112.85.42.47:60484.service: Succeeded.
Oct 05 06:51:25 t6 systemd[1]: Starting SSH Daemon (218.92.0.212:52624)...
Oct 05 06:51:25 t6 systemd[1]: Started SSH Daemon (218.92.0.212:52624).
Oct 05 06:51:25 t6 sshd[11243]: Connection from 218.92.0.212 port 52624 on 192.168.0.250 port 22 rdomain ""
Oct 05 06:51:25 t6 sshd[11243]: Unable to negotiate with 218.92.0.212 port 52624: no matching key exchange method found. Their offer: diffie-hellman-group1-sha1,diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1 [preauth]
Oct 05 06:51:25 t6 systemd[1]: [email protected]:22-218.92.0.212:52624.service: Succeeded.
Oct 05 06:52:23 t6 systemd[1]: Starting SSH Daemon (49.233.135.204:41402)...
Oct 05 06:52:23 t6 sshd[11321]: Connection from 49.233.135.204 port 41402 on 192.168.0.250 port 22 rdomain ""
Oct 05 06:52:23 t6 systemd[1]: Started SSH Daemon (49.233.135.204:41402).
Oct 05 06:52:24 t6 sshd[11321]: Connection closed by 49.233.135.204 port 41402 [preauth]
Oct 05 06:52:24 t6 systemd[1]: [email protected]:22-49.233.135.204:41402.service: Succeeded.
Oct 05 06:54:53 t6 systemd[1]: Starting SSH Daemon (112.85.42.69:20556)...
Oct 05 06:54:53 t6 systemd[1]: Started SSH Daemon (112.85.42.69:20556).
Oct 05 06:54:53 t6 sshd[11449]: Connection from 112.85.42.69 port 20556 on 192.168.0.250 port 22 rdomain ""
Oct 05 06:54:53 t6 sshd[11449]: Unable to negotiate with 112.85.42.69 port 20556: no matching key exchange method found. Their offer: diffie-hellman-group1-sha1,diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1 [preauth]
Oct 05 06:54:53 t6 systemd[1]: [email protected]:22-112.85.42.69:20556.service: Succeeded.
Oct 05 07:02:17 t6 systemd[1]: Starting SSH Daemon (218.92.0.248:7611)...
Oct 05 07:02:17 t6 systemd[1]: Started SSH Daemon (218.92.0.248:7611).
Oct 05 07:02:17 t6 sshd[11759]: Connection from 218.92.0.248 port 7611 on 192.168.0.250 port 22 rdomain ""
Oct 05 07:02:17 t6 sshd[11759]: Unable to negotiate with 218.92.0.248 port 7611: no matching key exchange method found. Their offer: diffie-hellman-group1-sha1,diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1 [preauth]
Oct 05 07:02:17 t6 systemd[1]: [email protected]:22-218.92.0.248:7611.service: Succeeded.
Oct 05 07:05:13 t6 systemd[1]: sshd.socket: Failed to queue service startup job (Maybe the service file is missing or not a template unit?): Transport endpoint is not connected
Oct 05 07:05:13 t6 systemd[1]: sshd.socket: Failed with result 'resources'.
Oct 05 07:05:13 t6 systemd[1]: sshd.socket: Consumed 4.031s CPU time, received 86.5M IP traffic, sent 141.1M IP traffic.
kevincox picture kevincox on 5 Oct 2020

Sounds similar to https://bugzilla.redhat.com/show_bug.cgi?id=783344 which was fixed in 2012 馃槙

kevincox picture kevincox on 5 Oct 2020

apparently this was fixed again recently https://github.com/systemd/systemd/commit/86e045ecefc404d4fccbeb78aa212ec4714a5763

kevincox picture kevincox on 5 Oct 2020

Should be fixed by https://github.com/NixOS/nixpkgs/pull/97989

kevincox picture kevincox on 5 Oct 2020

I'm seeing this as well although very soon after booting. Setting services.openssh.startWhenNeeded = false; works around the issue for now.

peterhoeg picture peterhoeg on 12 Nov 2020
❤1

We might want to backport #97989

peterhoeg picture peterhoeg on 12 Nov 2020
👍1

I have no idea what the policy for backporting systemd is. Is it preferable to backport the whole version or just a relevant patch?

Either way I haven't seen this in a while so I think it is closed for me. Is it best to track any backports in this issue or open a new one?

kevincox picture kevincox on 12 Nov 2020

@kevincox see https://github.com/NixOS/nixpkgs/pull/97989#issuecomment-731771488

flokli picture flokli on 22 Nov 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

copumpkin picture copumpkin  路  3Comments
matthiasbeyer picture matthiasbeyer  路  3Comments
grahamc picture grahamc  路  3Comments
spacekitteh picture spacekitteh  路  3Comments
edolstra picture edolstra  路  3Comments