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.
