Sonntag, 19. September 2021
Gestern lüpfte ich einen zweiten OpenVPN-Server von Debian Stretch auf Bullseye.
Das erfolgte leider nicht kurz- und schmerzlos. Ich kämpfte mit und debuggte während 16 Stunden (abzüglich 7 Stunden Schlaf) an folgenden Problemen:
Konsolen-, SSH- und Telnet-Logins dauern 1min30sec
D.h. nach Eingabe des Passwortes scheint das System zu hängen. Wer sich in Geduld übt, landet nach eineinhalb Minuten in der gewohnten Shell.
Bei mir bildeten sich in diesen ersten 90 Sekunden bereits viele Schweissperlen, denn wie flickt man ein Debian GNU/Linux, wenn man sich nicht mehr einloggen kann? Mittels grub in den Single User/Recovery Mode zu booten wäre ein noch grösserer Alptraum geworden …
Meldungen in syslog:
...
Sep 18 22:40:43 OPENVPN2 systemd[1]: Starting User Manager for UID 1000...
Sep 18 22:42:13 OPENVPN2 systemd[1]: user@1000.service: Main process exited, code=exited, status=1/FAILURE
Sep 18 22:42:13 OPENVPN2 systemd[1]: user@1000.service: Killing process 89451 (gpgconf) with signal SIGKILL.
Sep 18 22:42:13 OPENVPN2 systemd[1]: user@1000.service: Killing process 89452 (awk) with signal SIGKILL.
Sep 18 22:42:13 OPENVPN2 systemd[1]: user@1000.service: Killing process 89457 (dirmngr) with signal SIGKILL.
Sep 18 22:42:13 OPENVPN2 systemd[1]: user@1000.service: Killing process 89452 (awk) with signal SIGKILL.
Sep 18 22:42:13 OPENVPN2 systemd[1]: user@1000.service: Killing process 89457 (dirmngr) with signal SIGKILL.
Sep 18 22:42:13 OPENVPN2 systemd[1]: user@1000.service: Failed with result 'exit-code'.
Sep 18 22:42:13 OPENVPN2 systemd[1]: user@1000.service: Unit process 89452 (awk) remains running after unit stopped.
Sep 18 22:42:13 OPENVPN2 systemd[1]: user@1000.service: Unit process 89457 (dirmngr) remains running after unit stopped.
Sep 18 22:42:13 OPENVPN17 systemd[1]: Failed to start User Manager for UID 1000.
...
Die Lösung:
# apt-get remove gpgconf
...
The following packages will be REMOVED:
dirmngr duplicity gnupg gnupg-agent gnupg2 gpg gpg-agent gpg-wks-client gpg-wks-server gpgconf gpgsm libgmime-2.6-0 libgpgme11
libnotmuch4 mutt python3-gpg samba-dsdb-modules scdaemon
Die vielen zu deinstallierenden Pakete liessen mich kurz zweifeln, aber das System lief nach deren Deinstallation problemlos weiter.
Quelle: WireGuard Bounce Server Setup
Wobei, wenn ich die Kommentare so lese: Eventuell war gpgconf gar nicht das Problem, sondern der Nameserver, der nicht reagierte (siehe unten).
Netzwerkprobleme
Probleme mit named und localhost
BIND 9 ist zwar an localhost (127.0.0.1) gebunden und lauscht auf dem Interface …
# lsof -i :53
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
named 653 bind 23u IPv4 15673 0t0 UDP localhost:domain
named 653 bind 24u IPv4 15679 0t0 UDP localhost:domain
named 653 bind 25u IPv4 15680 0t0 TCP localhost:domain (LISTEN)
named 653 bind 27u IPv4 15681 0t0 TCP localhost:domain (LISTEN)
named 653 bind 29u IPv4 15682 0t0 UDP 10.1.2.3:domain
named 653 bind 30u IPv4 15683 0t0 UDP 10.1.2.3:domain
named 653 bind 31u IPv4 15684 0t0 TCP 10.1.2.3:domain (LISTEN)
named 653 bind 32u IPv4 15685 0t0 TCP 10.1.2.3:domain (LISTEN)
… aber die Namensauflösung funktioniert nicht. Wenn man mit telnet 127.0.0.1 53 eine Session aufbauen will, hängt die Verbindung.
Mittels strace analysierte ich dann was im Hintergrund genau vor sich ging, und verglich die Ausgabe mit einem strace auf einem Server, bei dem die Namensauflösung funktionierte:
Defekter Server:
# strace ping -c 1 emeidi.com
...
socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 5
setsockopt(5, SOL_IP, IP_RECVERR, [1], 4) = 0
connect(5, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
clock_gettime(CLOCK_REALTIME, {tv_sec=1631995746, tv_nsec=794103764}) = 0
poll([{fd=5, events=POLLOUT}], 1, 0) = 1 ([{fd=5, revents=POLLOUT}])
sendto(5, "{\311\1\0\0\1\0\0\0\0\0\0\6emeidi\3com\0\0\1\0\1", 28, MSG_NOSIGNAL, NULL, 0) = 28
poll([{fd=5, events=POLLIN}], 1, 1000) = 0 (Timeout)
clock_gettime(CLOCK_REALTIME, {tv_sec=1631995747, tv_nsec=795739261}) = 0
poll([{fd=5, events=POLLOUT}], 1, 0) = 1 ([{fd=5, revents=POLLOUT}])
sendto(5, "{\311\1\0\0\1\0\0\0\0\0\0\6emeidi\3com\0\0\1\0\1", 28, MSG_NOSIGNAL, NULL, 0) = 28
poll([{fd=5, events=POLLIN}], 1, 1000) = 0 (Timeout)
close(5) = 0
...
Funktionierender Server:
# strace ping -c 1 emeidi.com
...
socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 5
setsockopt(5, SOL_IP, IP_RECVERR, [1], 4) = 0
connect(5, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
poll([{fd=5, events=POLLOUT}], 1, 0) = 1 ([{fd=5, revents=POLLOUT}])
sendto(5, "UK\1\0\0\1\0\0\0\0\0\0\6emeidi\3com\0\0\1\0\1", 28, MSG_NOSIGNAL, NULL, 0) = 28
poll([{fd=5, events=POLLIN}], 1, 1000) = 1 ([{fd=5, revents=POLLIN}])
ioctl(5, FIONREAD, [463]) = 0
recvfrom(5, "UK\201\200\0\1\0\1\0\r\0\r\6emeidi\3com\0\0\1\0\1\300\f\0\1"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.1")}, [28->16]) = 463
poll([{fd=5, events=POLLOUT}], 1, 999) = 1 ([{fd=5, revents=POLLOUT}])
sendto(5, "W}\1\0\0\1\0\0\0\0\0\0\6emeidi\3com\0\0\34\0\1", 28, MSG_NOSIGNAL, NULL, 0) = 28
poll([{fd=5, events=POLLIN}], 1, 998) = 1 ([{fd=5, revents=POLLIN}])
ioctl(5, FIONREAD, [278]) = 0
recvfrom(5, "W}\201\200\0\1\0\0\0\0\0\r\6emeidi\3com\0\0\34\0\1\1a\fr"..., 65536, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.1")}, [28->16]) = 278
close(5) = 0
...
Macht man dasselbe mit der internen IP des Servers (bspw. 10.1.2.3) kann eine Session aufgebaut werden. Die Namensauflösung konnte ich nicht durchführen, weil mir der oder die Befehle nicht geläufig waren — im Nachhinein aber las ich dann, dass es sich bei DNS-Abfragen nicht um Klartextkommandos handelt.
Nun gut, dies bewog mich zu einem Workaround, ohne das eigentliche Problem zu beseitigen. Ich passte kurzerhand meine /etc/resolv.conf an:
#nameserver 127.0.0.1
nameserver 10.1.2.3
options timeout:1
options single-request
Ich vermutete zuerst Probleme in systemd-resolved. Installieren resp. entfernen tut man das Paket mit:
# apt-get install libnss-resolve
# apt-get remove libnss-resolve
Ist das Paket installiert, hat man neben /etc/resolv.conf auch noch Konfigurationen in /etc/systemd/resolved.conf und /run/systemd/resolve/resolve.conf. Typischer systemd-Wahnsinn. (siehe dazu Ubuntu – 18.04 Unable to connect to server due to “Temporary failure in name resolution” sowie Ubuntu 18.04 DNS resolution fails after a while)
Als ich systemd-resolved mit meinen Pröbelein zerschossen hatte, tauchten in /var/log/syslog noch folgende Fehlermeldungen auf:
Sep 18 20:35:04 localhost dbus-daemon[329]: [system] Activating via systemd: service name='org.freedesktop.resolve1' unit='dbus-org.freedesktop.resolve1.service' requested by ':1.15' (uid=0 pid=2015 comm="resolvectl ")
Sep 18 20:35:04 localhost dbus-daemon[329]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.resolve1.service': Unit dbus-org.freedesktop.resolve1.service not found.
Siehe auch Activation via systemd failed for unit ‚dbus-org.freedesktop.resolve1.service‘: Unit dbus-org.freedesktop.resolve1.service not found
Site-to-site OpenVPN erlaubt Pings in nur eine Richtung
Die Sache wurde immer mysteriöser: Aus dem entfernten Subnetz, in welchem der hier Probleme verursachende Server steht, konnte ich problemlos zur anderen Site pingen. Sowohl den VPN-Endpunkt, als auch alle anderen IPs im Subnetz hier. Das funktionierte auch von anderen Geräten im entfernten Subnetz aus.
Doch im Umkehrschluss funktionierte das nicht; d.h. von meinem Heimnetzwerk konnte ich nur den OpenVPN-Endpunkt pingen, aber nichts im entfernten Subnetz. Die ICMP-Pakete kamen zwar beim Zielgerät an (bspw. dem Internet-Router), dieser antwortete, aber das Antwortpaket wurde dann von auf dem entfernten OpenVPN-Endpunkt nicht von eth0 auf tun0 weitergeleitet.
Immerhin lernte ich für das Debugging nützliche tcpdump-Befehle kennen:
# tcpdump -n icmp and host 10.1.2.1
# tcpdump -i tun0 -n icmp and host 10.1.2.1
# tcpdump -i eth0 -n icmp and host 10.1.2.1
Die Ausgabe ist auch deshalb hilfreich, weil derselbe ping-Prozess immer dieselbe id trägt. Und die Sequenznummern sieht man auch gleich angezeigt. So konnte man isolieren, wo genau die ICMP-Pakete „verloren“ gingen respektive noch durchkamen.
Ausserdem kann man iptables so konfigurieren, dass sie verarbeitete Pakete ins syslog loggen (eine Regel iptables -I FORWARD -i eth0 -o tun0 -j ACCEPT existiert dabei schon und ist aktiv):
# iptables -I FORWARD -i eth0 -o tun0 -j LOG --log-prefix "OUTGOING "
# iptables -I FORWARD -i tun0 -o eth0 -j LOG --log-prefix "INCOMING "
Das Logging wird deaktiviert, indem man die Regel wieder entfernt:
# iptables -D FORWARD -i eth0 -o tun0 -j LOG --log-prefix "OUTGOING "
# iptables -D FORWARD -i tun17 -o eth0 -j LOG --log-prefix "INCOMING "
In dmesg entdeckte ich dann auch noch folgende Fehlermeldungen, was mich bewog, den Kernel zu aktualisieren:
...
cgroup2: unknown option "nsdelegate,memory_recursiveprot"
...
Die finale Lösung: Aktualisiere von Kernel-Version 4.9.0-16 auf 5.10.46-4, und Neustart.
# apt-get install linux-image-amd64
