Hello Jörg, thanks for the reply.
Was the computer rebooted after the update?
It was not. Rebooting fixes the issue, as does manually kill(1)ing the
errant openvpn instances and restarting the systemd unit(s).
Sorry, "Upgrades break systemd supervision" was perhaps not the best
summary. It's more like "Upgrades restart openvpn outside of
systemd".
I have checked your bug report on every server I have access to.
Likewise, I have checked the problem in multiple VMs. The error was not
reproducible there either.
This worked for me on a fresh amd64 buster VM:
echo "deb http://snapshot.debian.org/archive/debian/20210601T022916Z/ buster
main" >/etc/apt/sources.list.d/snapshot.list
apt update
apt install openvpn=2.4.7-1 ssl-cert
# placeholder config
zcat /usr/share/doc/openvpn/examples/sample-config-files/server.conf.gz
>/etc/openvpn/server.conf
ln -s /etc/ssl/certs/ssl-cert-snakeoil.pem /etc/openvpn/server.crt
ln -s /etc/ssl/certs/ssl-cert-snakeoil.pem /etc/openvpn/ca.crt
ln -s /etc/ssl/private/ssl-cert-snakeoil.key /etc/openvpn/server.key
openssl dhparam -out /etc/openvpn/dh2048.pem 2048
openvpn --genkey --secret /etc/openvpn/ta.key
systemctl start openvpn@server
apt install unattended-upgrades
systemctl start apt-daily-upgrade
systemctl status
# Observe: openvpn process is now in apt-daily-upgrade.service
systemctl start apt-daily-upgrade # (a second time)
# systemd now warns about the lingering process
Alternatively, replace 'apt install unattended-upgrades' and everything
thereafter with:
apt upgrade
systemctl status
Which should show the openvpn daemon lingering in whatever scope unit
contains your shell.
Or, simpler still:
invoke-rc.d openvpn cond-restart
which is invoked by openvpn's postinst and has much the same effect.
Can you please provide the complete update logs?
Attached are extracts of of `journalctl --output=with-unit` and
/var/log/unattended-upgrades/unattended-upgrades-dpkg.log after having
done the above. HTH!
Thanks,
--
Daniel Gnoutcheff
Systems Administrator
Software Freedom Law Center
-- Logs begin at Tue 2021-08-03 17:57:06 EDT. --
Tue 2021-08-03 17:59:18 EDT bug4 session-4.scope[1238]: group added to /etc/group: name=ssl-cert, GID=112
Tue 2021-08-03 17:59:18 EDT bug4 session-4.scope[1238]: group added to /etc/gshadow: name=ssl-cert
Tue 2021-08-03 17:59:18 EDT bug4 session-4.scope[1238]: new group: name=ssl-cert, GID=112
Tue 2021-08-03 17:59:20 EDT bug4 init.scope[1]: Reloading.
Tue 2021-08-03 17:59:21 EDT bug4 init.scope[1]: Reloading.
Tue 2021-08-03 17:59:21 EDT bug4 init.scope[1]: Reloading.
Tue 2021-08-03 17:59:23 EDT bug4 init.scope[1]: Reloading.
Tue 2021-08-03 17:59:23 EDT bug4 init.scope[1]: Reloading.
Tue 2021-08-03 17:59:24 EDT bug4 init.scope[1]: Listening on PC/SC Smart Card Daemon Activation Socket.
Tue 2021-08-03 17:59:24 EDT bug4 init.scope[1]: Started PC/SC Smart Card Daemon.
Tue 2021-08-03 17:59:24 EDT bug4 init.scope[1]: Reloading.
Tue 2021-08-03 17:59:24 EDT bug4 init.scope[1]: Reloading.
Tue 2021-08-03 17:59:28 EDT bug4 init.scope[1]: Reloading.
-- Logs begin at Tue 2021-08-03 17:57:06 EDT. --
Tue 2021-08-03 18:02:47 EDT bug4 init.scope[1]: Created slice system-openvpn.slice.
Tue 2021-08-03 18:02:47 EDT bug4 init.scope[1]: Reached target Network is Online.
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: WARNING: file 'server.key' is group or others accessible
Tue 2021-08-03 18:02:47 EDT bug4 init.scope[1]: Starting OpenVPN connection to server...
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: OpenVPN 2.4.7 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Feb 20 2019
Tue 2021-08-03 18:02:47 EDT bug4 init.scope[1]: Started OpenVPN connection to server.
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: library versions: OpenSSL 1.1.1d 10 Sep 2019, LZO 2.10
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: Diffie-Hellman initialized with 2048 bit key
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: ROUTE_GATEWAY 10.179.201.1/255.255.255.0 IFACE=eth0 HWADDR=52:54:00:ec:b2:f5
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: TUN/TAP device tun0 opened
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: TUN/TAP TX queue length set to 100
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: /sbin/ip link set dev tun0 up mtu 1500
Tue 2021-08-03 18:02:47 EDT bug4 kernel: tun: Universal TUN/TAP device driver, 1.6
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: /sbin/ip addr add dev tun0 local 10.8.0.1 peer 10.8.0.2
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: /sbin/ip route add 10.8.0.0/24 via 10.8.0.2
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: Could not determine IPv4/IPv6 protocol. Using AF_INET
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: Socket Buffers: R=[212992->212992] S=[212992->212992]
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: UDPv4 link local (bound): [AF_INET][undef]:1194
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: UDPv4 link remote: [AF_UNSPEC]
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: MULTI: multi_init called, r=256 v=256
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: IFCONFIG POOL: base=10.8.0.4 size=62, ipv6=0
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: IFCONFIG POOL LIST
Tue 2021-08-03 18:02:47 EDT bug4 openvpn@server.service[1667]: Initialization Sequence Completed
Tue 2021-08-03 18:03:06 EDT bug4 init.scope[1]: Reloading.
Tue 2021-08-03 18:03:07 EDT bug4 init.scope[1]: Reloading.
Tue 2021-08-03 18:03:07 EDT bug4 init.scope[1]: Reloading.
Tue 2021-08-03 18:03:07 EDT bug4 init.scope[1]: Reloading.
Tue 2021-08-03 18:03:07 EDT bug4 init.scope[1]: Reloading.
Tue 2021-08-03 18:03:09 EDT bug4 init.scope[1]: Reloading.
Tue 2021-08-03 18:03:23 EDT bug4 init.scope[1]: Starting Daily apt upgrade and clean activities...
Tue 2021-08-03 18:03:32 EDT bug4 kernel: device-mapper: uevent: version 1.0.3
Tue 2021-08-03 18:03:32 EDT bug4 kernel: device-mapper: ioctl: 4.39.0-ioctl (2018-04-03) initialised: dm-de...@redhat.com
Tue 2021-08-03 18:03:38 EDT bug4 kernel: cryptd: max_cpu_qlen set to 1000
Tue 2021-08-03 18:03:39 EDT bug4 kernel: JFS: nTxBlock = 3865, nTxLock = 30926
Tue 2021-08-03 18:03:39 EDT bug4 kernel: QNX4 filesystem 0.2.3 registered.
Tue 2021-08-03 18:03:40 EDT bug4 kernel: raid6: sse2x1 gen() 3529 MB/s
Tue 2021-08-03 18:03:40 EDT bug4 kernel: raid6: sse2x1 xor() 3603 MB/s
Tue 2021-08-03 18:03:40 EDT bug4 kernel: raid6: sse2x2 gen() 5808 MB/s
Tue 2021-08-03 18:03:40 EDT bug4 kernel: raid6: sse2x2 xor() 6104 MB/s
Tue 2021-08-03 18:03:40 EDT bug4 kernel: raid6: sse2x4 gen() 7003 MB/s
Tue 2021-08-03 18:03:40 EDT bug4 kernel: raid6: sse2x4 xor() 3879 MB/s
Tue 2021-08-03 18:03:40 EDT bug4 kernel: raid6: using algorithm sse2x4 gen() 7003 MB/s
Tue 2021-08-03 18:03:40 EDT bug4 kernel: raid6: .... xor() 3879 MB/s, rmw enabled
Tue 2021-08-03 18:03:40 EDT bug4 kernel: raid6: using intx1 recovery algorithm
Tue 2021-08-03 18:03:40 EDT bug4 kernel: xor: measuring software checksum speed
Tue 2021-08-03 18:03:40 EDT bug4 kernel: prefetch64-sse: 10519.000 MB/sec
Tue 2021-08-03 18:03:40 EDT bug4 kernel: generic_sse: 10022.000 MB/sec
Tue 2021-08-03 18:03:40 EDT bug4 kernel: xor: using function: prefetch64-sse (10519.000 MB/sec)
Tue 2021-08-03 18:03:40 EDT bug4 kernel: Btrfs loaded, crc32c=crc32c-generic
Tue 2021-08-03 18:03:40 EDT bug4 kernel: fuse init (API version 7.27)
Tue 2021-08-03 18:03:40 EDT bug4 init.scope[1]: Mounting FUSE Control File System...
Tue 2021-08-03 18:03:40 EDT bug4 init.scope[1]: Mounted FUSE Control File System.
Tue 2021-08-03 18:04:51 EDT bug4 init.scope[1]: Reloading.
Tue 2021-08-03 18:04:52 EDT bug4 openvpn@server.service[1667]: event_wait : Interrupted system call (code=4)
Tue 2021-08-03 18:04:54 EDT bug4 openvpn@server.service[1667]: /sbin/ip route del 10.8.0.0/24
Tue 2021-08-03 18:04:54 EDT bug4 openvpn@server.service[1667]: Closing TUN/TAP interface
Tue 2021-08-03 18:04:54 EDT bug4 openvpn@server.service[1667]: /sbin/ip addr del dev tun0 local 10.8.0.1 peer 10.8.0.2
Tue 2021-08-03 18:04:54 EDT bug4 openvpn@server.service[1667]: SIGTERM[hard,] received, process exiting
Tue 2021-08-03 18:04:54 EDT bug4 init.scope[1]: openvpn@server.service: Succeeded.
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11776]: WARNING: file 'server.key' is group or others accessible
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11776]: OpenVPN 2.4.7 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Apr 28 2021
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11776]: library versions: OpenSSL 1.1.1d 10 Sep 2019, LZO 2.10
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11777]: Diffie-Hellman initialized with 2048 bit key
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11777]: Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11777]: Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11777]: ROUTE_GATEWAY 10.179.201.1/255.255.255.0 IFACE=eth0 HWADDR=52:54:00:ec:b2:f5
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11777]: TUN/TAP device tun0 opened
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11777]: TUN/TAP TX queue length set to 100
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11777]: /sbin/ip link set dev tun0 up mtu 1500
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11777]: /sbin/ip addr add dev tun0 local 10.8.0.1 peer 10.8.0.2
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11777]: /sbin/ip route add 10.8.0.0/24 via 10.8.0.2
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11777]: Could not determine IPv4/IPv6 protocol. Using AF_INET
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11777]: Socket Buffers: R=[212992->212992] S=[212992->212992]
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11777]: UDPv4 link local (bound): [AF_INET][undef]:1194
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11777]: UDPv4 link remote: [AF_UNSPEC]
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11777]: MULTI: multi_init called, r=256 v=256
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11777]: IFCONFIG POOL: base=10.8.0.4 size=62, ipv6=0
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11777]: IFCONFIG POOL LIST
Tue 2021-08-03 18:04:54 EDT bug4 apt-daily-upgrade.service[11777]: Initialization Sequence Completed
Tue 2021-08-03 18:04:54 EDT bug4 init.scope[1]: Reloading.
Tue 2021-08-03 18:04:56 EDT bug4 init.scope[1]: Reloading.
Tue 2021-08-03 18:04:58 EDT bug4 init.scope[1]: apt-daily-upgrade.service: Succeeded.
Tue 2021-08-03 18:04:58 EDT bug4 init.scope[1]: Started Daily apt upgrade and clean activities.
Log started: 2021-08-03 18:04:48
Preconfiguring packages ...
(Reading database ...
(Reading database ... 5%
(Reading database ... 10%
(Reading database ... 15%
(Reading database ... 20%
(Reading database ... 25%
(Reading database ... 30%
(Reading database ... 35%
(Reading database ... 40%
(Reading database ... 45%
(Reading database ... 50%
(Reading database ... 55%
(Reading database ... 60%
(Reading database ... 65%
(Reading database ... 70%
(Reading database ... 75%
(Reading database ... 80%
(Reading database ... 85%
(Reading database ... 90%
(Reading database ... 95%
(Reading database ... 100%
(Reading database ... 31585 files and directories currently installed.)
Preparing to unpack .../openvpn_2.4.7-1+deb10u1_amd64.deb ...
Unpacking openvpn (2.4.7-1+deb10u1) over (2.4.7-1) ...
Setting up openvpn (2.4.7-1+deb10u1) ...
Restarting virtual private network daemon.: server.
Processing triggers for man-db (2.8.5-2) ...
Processing triggers for systemd (241-7~deb10u8) ...
Log ended: 2021-08-03 18:04:56
