Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.debian.bugs.dist > #1197770 > unrolled thread
| Started by | Sven-Haegar Koch <haegar@sdinet.de> |
|---|---|
| First post | 2024-05-17 21:50 +0200 |
| Last post | 2024-05-23 22:20 +0200 |
| Articles | 3 — 2 participants |
Back to article view | Back to linux.debian.bugs.dist
Bug#1071292: openssh-server: sshd fails to restart at package upgrade, future logins to server impossible Sven-Haegar Koch <haegar@sdinet.de> - 2024-05-17 21:50 +0200
Bug#1071292: openssh-server: sshd fails to restart at package upgrade, future logins to server impossible Colin Watson <cjwatson@debian.org> - 2024-05-23 21:10 +0200
Bug#1071292: openssh-server: sshd fails to restart at package upgrade, future logins to server impossible Sven-Haegar Koch <haegar@sdinet.de> - 2024-05-23 22:20 +0200
| From | Sven-Haegar Koch <haegar@sdinet.de> |
|---|---|
| Date | 2024-05-17 21:50 +0200 |
| Subject | Bug#1071292: openssh-server: sshd fails to restart at package upgrade, future logins to server impossible |
| Message-ID | <IFbKx-e1ur-1@gated-at.bofh.it> |
Package: openssh-server
Version: 1:9.7p1-5
Severity: important
Dear Maintainer,
I just upgraded openssh as part of my normal "apt dist-upgrade" every
few days, from 1:9.7p1-4 to 1:9.7p1-5.
The whole apt went through without any errors - but afterwards sshd
was no longer running / listening on its network ports.
Most likely related messages from syslog:
May 17 21:19:31 aurora64 systemd[1]: Reloading finished in 370 ms.
May 17 21:19:31 aurora64 sshd[1910600]: Received signal 15; terminating.
May 17 21:19:31 aurora64 systemd[1]: Stopping ssh.service - OpenBSD Secure Shell server...
May 17 21:19:31 aurora64 systemd[1]: ssh.service: Deactivated successfully.
May 17 21:19:31 aurora64 systemd[1]: Stopped ssh.service - OpenBSD Secure Shell server.
May 17 21:19:31 aurora64 systemd[1]: Starting ssh.service - OpenBSD Secure Shell server...
May 17 21:19:31 aurora64 systemd[1]: ssh.service: Control process exited, code=exited, status=127/n/a
May 17 21:19:31 aurora64 systemd[1]: ssh.service: Failed with result 'exit-code'.
May 17 21:19:31 aurora64 systemd[1]: Failed to start ssh.service - OpenBSD Secure Shell server.
May 17 21:19:31 aurora64 systemd[1]: ssh.service: Scheduled restart job, restart counter is at 1.
May 17 21:19:32 aurora64 systemd[1]: Starting ssh.service - OpenBSD Secure Shell server...
May 17 21:19:32 aurora64 systemd[1]: ssh.service: Control process exited, code=exited, status=127/n/a
May 17 21:19:32 aurora64 systemd[1]: ssh.service: Failed with result 'exit-code'.
May 17 21:19:32 aurora64 systemd[1]: Failed to start ssh.service - OpenBSD Secure Shell server.
May 17 21:19:32 aurora64 systemd[1]: Reloading requested from client PID 2653532 ('systemctl') (unit session-4.scope)...
May 17 21:19:32 aurora64 systemd[1]: Reloading...
May 17 21:19:32 aurora64 systemd[1]: systemd-fsckd.socket: Socket unit configuration has changed while unit has been running, no open socket file descriptor left. The socket unit is not functional until restarted.
May 17 21:19:32 aurora64 systemd[1]: Reloading finished in 384 ms.
May 17 21:19:32 aurora64 systemd[1]: ssh.service: Scheduled restart job, restart counter is at 2.
May 17 21:19:32 aurora64 systemd[1]: Starting ssh.service - OpenBSD Secure Shell server...
May 17 21:19:32 aurora64 systemd[1]: ssh.service: Control process exited, code=exited, status=127/n/a
May 17 21:19:32 aurora64 systemd[1]: ssh.service: Failed with result 'exit-code'.
May 17 21:19:32 aurora64 systemd[1]: Failed to start ssh.service - OpenBSD Secure Shell server.
May 17 21:19:32 aurora64 systemd[1]: ssh.service: Scheduled restart job, restart counter is at 3.
May 17 21:19:32 aurora64 systemd[1]: Starting ssh.service - OpenBSD Secure Shell server...
May 17 21:19:32 aurora64 systemd[1]: ssh.service: Control process exited, code=exited, status=127/n/a
May 17 21:19:32 aurora64 systemd[1]: ssh.service: Failed with result 'exit-code'.
May 17 21:19:32 aurora64 systemd[1]: Failed to start ssh.service - OpenBSD Secure Shell server.
May 17 21:19:33 aurora64 systemd[1]: ssh.service: Scheduled restart job, restart counter is at 4.
May 17 21:19:33 aurora64 systemd[1]: Starting ssh.service - OpenBSD Secure Shell server...
May 17 21:19:33 aurora64 systemd[1]: ssh.service: Control process exited, code=exited, status=127/n/a
May 17 21:19:33 aurora64 systemd[1]: ssh.service: Failed with result 'exit-code'.
May 17 21:19:33 aurora64 systemd[1]: Failed to start ssh.service - OpenBSD Secure Shell server.
May 17 21:19:33 aurora64 systemd[1]: ssh.service: Scheduled restart job, restart counter is at 5.
May 17 21:19:33 aurora64 systemd[1]: ssh.service: Start request repeated too quickly.
May 17 21:19:33 aurora64 systemd[1]: ssh.service: Failed with result 'exit-code'.
May 17 21:19:33 aurora64 systemd[1]: Failed to start ssh.service - OpenBSD Secure Shell server.
Did not find anything real in the logs why it would not restart,
just that it died.
A manual "systemctl restart ssh" afterwards just made ssh work again.
May 17 21:35:29 aurora64 systemd[1]: Starting ssh.service - OpenBSD Secure Shell server...
May 17 21:35:29 aurora64 sshd[2674496]: Server listening on 0.0.0.0 port 42666.
May 17 21:35:29 aurora64 sshd[2674496]: Server listening on :: port 42666.
May 17 21:35:29 aurora64 systemd[1]: Started ssh.service - OpenBSD Secure Shell server.
May 17 21:35:29 aurora64 sshd[2674496]: Server listening on 0.0.0.0 port 22.
May 17 21:35:29 aurora64 sshd[2674496]: Server listening on :: port 22.
Sadly I saw this problem too late, and had already looged out of one
machine again, and now can't login again until I am the next time
in the office and able to use the console to restart sshd :/
Greetings,
Haegar
PS:
Systemd was updated from 255.5-1 to 256~rc2-3 in the same apt
run, so could perhaps also be some ugly interaction between the
two updates.
-- System Information:
Debian Release: trixie/sid
APT prefers stable-security
APT policy: (500, 'stable-security'), (500, 'unstable'), (500, 'stable'), (500, 'oldstable'), (101, 'experimental')
Architecture: amd64 (x86_64)
Foreign Architectures: i386
Kernel: Linux 6.7.9-amd64 (SMP w/8 CPU threads; PREEMPT)
Kernel taint flags: TAINT_OOT_MODULE, TAINT_UNSIGNED_MODULE
Locale: LANG=en_US.UTF-8, LC_CTYPE=de_DE.UTF-8 (charmap=UTF-8), LANGUAGE=en_US
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled
Versions of packages openssh-server depends on:
ii adduser 3.137
ii debconf [debconf-2.0] 1.5.86
ii init-system-helpers 1.66
ii libaudit1 1:3.1.2-2.1
ii libc6 2.38-11
ii libcom-err2 1.47.1~rc2-1
ii libcrypt1 1:4.4.36-4
ii libgssapi-krb5-2 1.20.1-6+b1
ii libkrb5-3 1.20.1-6+b1
ii libpam-modules 1.5.3-7
ii libpam-runtime 1.5.3-7
ii libpam0g 1.5.3-7
ii libselinux1 3.5-2+b2
ii libssl3t64 3.2.1-3
ii libwrap0 7.6.q-33
ii openssh-client 1:9.7p1-5
ii openssh-sftp-server 1:9.7p1-5
ii procps 2:4.0.4-4
ii runit-helper 2.16.2
ii sysvinit-utils [lsb-base] 3.09-1
ii ucf 3.0043+nmu1
ii zlib1g 1:1.3.dfsg+really1.3.1-1
Versions of packages openssh-server recommends:
ii libpam-systemd [logind] 256~rc2-3
ii ncurses-term 6.5-2
ii xauth 1:1.1.2-1
Versions of packages openssh-server suggests:
pn molly-guard <none>
pn monkeysphere <none>
ii ssh-askpass 1:1.2.4.1-16+b1
pn ufw <none>
-- debconf-show failed
[toc] | [next] | [standalone]
| From | Colin Watson <cjwatson@debian.org> |
|---|---|
| Date | 2024-05-23 21:10 +0200 |
| Message-ID | <IHlZ8-fli2-1@gated-at.bofh.it> |
| In reply to | #1197770 |
On Fri, May 17, 2024 at 09:42:05PM +0200, Sven-Haegar Koch wrote: > I just upgraded openssh as part of my normal "apt dist-upgrade" every > few days, from 1:9.7p1-4 to 1:9.7p1-5. > > The whole apt went through without any errors - but afterwards sshd > was no longer running / listening on its network ports. Hm, I haven't seen this elsewhere either in my own upgrades or from anyone else, and as you say the ssh.service logs don't give much to go on. Is there anything informative in /var/log/auth.log, perhaps? -- Colin Watson (he/him) [cjwatson@debian.org]
[toc] | [prev] | [next] | [standalone]
| From | Sven-Haegar Koch <haegar@sdinet.de> |
|---|---|
| Date | 2024-05-23 22:20 +0200 |
| Message-ID | <IHn4R-flTd-3@gated-at.bofh.it> |
| In reply to | #1198372 |
On Thu, 23 May 2024, Colin Watson wrote:
> On Fri, May 17, 2024 at 09:42:05PM +0200, Sven-Haegar Koch wrote:
> > I just upgraded openssh as part of my normal "apt dist-upgrade" every
> > few days, from 1:9.7p1-4 to 1:9.7p1-5.
> >
> > The whole apt went through without any errors - but afterwards sshd
> > was no longer running / listening on its network ports.
>
> Hm, I haven't seen this elsewhere either in my own upgrades or from
> anyone else, and as you say the ssh.service logs don't give much to go
> on. Is there anything informative in /var/log/auth.log, perhaps?
Nothing really definitive.
For while doing the upgrade (as user aptdater):
May 17 20:06:12 vpnhub1 sshd[1102927]: Accepted publickey for aptdater
from 193.103.159.64 port 59666 ssh2: RSA SHA256:0FPN
60iZ3XPPFMs5PwTyRxGp8irW/g8w7x/MEveVwtY
May 17 20:06:12 vpnhub1 sshd[1102927]: pam_unix(sshd:session): session
opened for user aptdater(uid=110) by aptdater(uid=0)
May 17 20:06:17 vpnhub1 systemd-logind[332]: New session 28741 of user
aptdater.
May 17 20:06:20 vpnhub1 (systemd): pam_unix(systemd-user:session):
session opened for user aptdater(uid=110) by aptdater(ui
d=0)
May 17 20:06:24 vpnhub1 sshd[1102927]: pam_env(sshd:session): deprecated
reading of user environment enabled
May 17 20:06:27 vpnhub1 sudo: aptdater : TTY=pts/0 ;
PWD=/var/lib/apt-dater ; USER=root ; COMMAND=/usr/bin/apt update
May 17 20:06:27 vpnhub1 sudo: pam_unix(sudo:session): session opened for
user root(uid=0) by aptdater(uid=110)
May 17 20:06:47 vpnhub1 sudo: pam_unix(sudo:session): session closed for
user root
May 17 20:06:47 vpnhub1 sudo: aptdater : TTY=pts/0 ;
PWD=/var/lib/apt-dater ; USER=root ; COMMAND=/usr/bin/apt dist-upgrade
May 17 20:06:47 vpnhub1 sudo: pam_unix(sudo:session): session opened for
user root(uid=0) by aptdater(uid=110)
May 17 20:09:25 vpnhub1 sshd[382556]: Received signal 15; terminating.
May 17 20:11:30 vpnhub1 sudo: pam_unix(sudo:session): session closed for
user root
May 17 20:11:30 vpnhub1 sudo: aptdater : TTY=pts/0 ;
PWD=/var/lib/apt-dater ; USER=root ; COMMAND=/usr/bin/apt-get autoremove
May 17 20:11:30 vpnhub1 sudo: pam_unix(sudo:session): session opened for
user root(uid=0) by aptdater(uid=110)
May 17 20:11:44 vpnhub1 sudo: pam_unix(sudo:session): session closed for
user root
May 17 20:11:44 vpnhub1 sudo: aptdater : TTY=pts/0 ;
PWD=/var/lib/apt-dater ; USER=root ; COMMAND=/usr/bin/apt-get clean
May 17 20:11:44 vpnhub1 sudo: pam_unix(sudo:session): session opened for
user root(uid=0) by aptdater(uid=110)
May 17 20:11:44 vpnhub1 sudo: pam_unix(sudo:session): session closed for
user root
May 17 20:11:44 vpnhub1 sshd[1102968]: Received disconnect from
193.103.159.64 port 59666:11: disconnected by user
May 17 20:11:44 vpnhub1 sshd[1102968]: Disconnected from user aptdater
193.103.159.64 port 59666
May 17 20:11:44 vpnhub1 sshd[1102927]: pam_unix(sshd:session): session
closed for user aptdater
May 17 20:11:45 vpnhub1 systemd-logind[332]: Session 28741 logged out.
Waiting for processes to exit.
May 17 20:11:45 vpnhub1 systemd-logind[332]: Removed session 28741.
Just a single
May 17 20:09:25 vpnhub1 sshd[382556]: Received signal 15; terminating.
in the middle, what I assume was when sshd was killed, and supposed to
be restarted.
The regular
sshd[1102452]: Connection closed by 193.103.159.70 port 42808 [preauth]
from my monitoring which normally happens every 5 minutes did not occur
between 20:05 and 21:50, after I had restarted sshd.
When I was logging in after finding it through virt-manager / remote
console it shows some errors, but nothing that blocked the console
login, where I was able to restart sshd:
May 17 21:45:50 vpnhub1 login[2153297]: PAM unable to
dlopen(pam_lastlog.so): /usr/lib/security/pam_lastlog.so: cannot open
shared object file: No such file or directory
May 17 21:45:50 vpnhub1 login[2153297]: PAM adding faulty module:
pam_lastlog.so
May 17 21:45:52 vpnhub1 login[2153297]: pam_unix(login:session): session
opened for user haegar(uid=1000) by haegar(uid=0)
May 17 21:45:52 vpnhub1 login[2153297]: pam_systemd(login:session): New
sd-bus connection (system-bus-pam-systemd-2153297) opened.
May 17 21:45:53 vpnhub1 systemd-logind[332]: New session 28815 of user
haegar.
May 17 21:45:53 vpnhub1 (systemd): pam_unix(systemd-user:session):
session opened for user haegar(uid=1000) by haegar(uid=0)
May 17 21:45:53 vpnhub1 (systemd): pam_systemd(systemd-user:session):
Failed to create session: Invalid session class manager
May 17 21:45:53 vpnhub1 (sd-pam): pam_unix(systemd-user:session):
session closed for user haegar
May 17 21:46:00 vpnhub1 sudo: haegar : TTY=tty1 ; PWD=/root ;
USER=root ; COMMAND=/bin/bash
May 17 21:46:00 vpnhub1 sudo: pam_unix(sudo-i:session): session opened
for user root(uid=0) by haegar(uid=1000)
May 17 21:46:00 vpnhub1 sudo: pam_systemd(sudo-i:session): New sd-bus
connection (system-bus-pam-systemd-1129441) opened.
May 17 21:46:00 vpnhub1 sudo: pam_systemd(sudo-i:session): Failed to
create session: Invalid session class user-early
May 17 21:46:10 vpnhub1 sshd[1129457]: Server listening on 0.0.0.0 port
42666.
May 17 21:46:10 vpnhub1 sshd[1129457]: Server listening on :: port
42666.
May 17 21:46:10 vpnhub1 sshd[1129457]: Server listening on 0.0.0.0 port
22.
May 17 21:46:10 vpnhub1 sshd[1129457]: Server listening on :: port 22.
May 17 21:46:17 vpnhub1 sudo: pam_unix(sudo-i:session): session closed
for user root
May 17 21:46:18 vpnhub1 login[2153297]: pam_unix(login:session): session
closed for user haegar
May 17 21:46:18 vpnhub1 login[2153297]: pam_systemd(login:session): New
sd-bus connection (system-bus-pam-systemd-2153297) opened.
May 17 21:46:18 vpnhub1 systemd-logind[332]: Session 28815 logged out.
Waiting for processes to exit.
May 17 21:46:18 vpnhub1 systemd-logind[332]: Removed session 28815.
But what I now see in syslog (not auth.log) is that at around the same
time that the sshd restart failed the apt-daily.service also failed,
with similar logs:
May 17 20:09:24 vpnhub1 systemd[1]: Reloading finished in 1546 ms.
May 17 20:09:24 vpnhub1 systemd[1]: Reloading requested from client PID
1111388 ('systemctl') (unit session-28741.scope)...
May 17 20:09:24 vpnhub1 systemd[1]: Reloading...
May 17 20:09:24 vpnhub1 systemd[1]: Reloading finished in 208 ms.
May 17 20:09:24 vpnhub1 systemd[1]: Starting apt-daily.service - Daily
apt download activities...
May 17 20:09:24 vpnhub1 systemd[1]: apt-daily.service: Main process
exited, code=exited, status=127/n/a
May 17 20:09:24 vpnhub1 systemd[1]: apt-daily.service: Failed with
result 'exit-code'.
May 17 20:09:24 vpnhub1 systemd[1]: Failed to start apt-daily.service -
Daily apt download activities.
May 17 20:09:24 vpnhub1 systemd[1]: Stopping ssh.service - OpenBSD
Secure Shell server...
May 17 20:09:25 vpnhub1 sshd[382556]: Received signal 15; terminating.
May 17 20:09:25 vpnhub1 systemd[1]: ssh.service: Deactivated
successfully.
May 17 20:09:25 vpnhub1 systemd[1]: Stopped ssh.service - OpenBSD Secure
Shell server.
May 17 20:09:25 vpnhub1 systemd[1]: ssh.service: Consumed 16.618s CPU
time, 6.3M memory peak, 1.0M memory swap peak.
May 17 20:09:25 vpnhub1 systemd[1]: Starting ssh.service - OpenBSD
Secure Shell server...
May 17 20:09:25 vpnhub1 systemd[1]: ssh.service: Control process exited,
code=exited, status=127/n/a
May 17 20:09:25 vpnhub1 systemd[1]: ssh.service: Failed with result
'exit-code'.
May 17 20:09:25 vpnhub1 systemd[1]: Failed to start ssh.service -
OpenBSD Secure Shell server.
That the apt-daily timer was running at exactly this time was pure luck,
but I think it points more to a half-done systemd update in parallel
than to a fault of sshd.
From the dpkg.log I see that most systemd lib packages were
unpacked or fully upgraded before openssh-server package, but systemd
itself unpacked before, and fully installed only afterwards.
I think this bug can thus be closed, don't think we will get much more
until it maybe happens the next time or to someone else with better
logs.
Thanks for your attention,
c'ya
sven-haegar
--
Three may keep a secret, if two of them are dead.
- Ben F.
[toc] | [prev] | [standalone]
Back to top | Article view | linux.debian.bugs.dist
csiph-web