Die verschwundenen Requests im httpd
Vor nun fast einem Jahr war unsere Uberspace 7 Betaphase in voller Fahrt.
Eine Hand voll User prügelte so lange auf U7 ein, bis so ziemlich alle Edgecases ausgereizeit waren. Viele der so gefunden Bugs waren schnell gefixt. Eines Tages bekamen wir allerdings eine vergleichsweise merkwürdige Meldung:
Seit ca. 3 Minuten: Wenn ich https://usr.betahost.uberspace.de/ aufrufe, lande ich auf einer Loginseite von “Mattermost”. Ich hab aber doch gar kein Mattermost auf meinem uberspace.
… und ein paar Minuten später:
Das Problem scheint momentan wieder behoben. Kann jemand erklären, was das war?
Tja.. hm. So direkt leider nicht so wirklich, nein. 😕🤔
Auf den Domains eines Uberspaces sollten selbstverständlich nur Inhalte aus eben diesem Uberspace ausgeliefert werden. Wenn dort plötzlich eine ganz andere Applikation zu sehen ist, ist das eher so “worst case”.
Da unsere Config im nginx und Apache, was die Zuordnung von Domains und Inhalten angeht, relativ simpel ist, haben wir zunächst eine mangelhafte Konfiguration innerhalb des Uberspaces vermutet. Ein fehlgeleiteter Redirect? Tippfehler in irgendeinem Port? Falsche Domain aufgeschaltet?
Die Uberspaces
Initial haben wir also erstmal gecheckt, was der User so im Web-Bereich tut: eine index.html (Inhalt: Hallo, Welt!), keine .htaccess und keine anderen Abweichungen vom Standardsetup. Einfacher wird es wirklich nicht. Die User-Config kann also nicht die Quelle des Problems sein. Auch die automatisch generierte Apache-Config des Users enthält nur für den Uberspace gedachte Domains.
Unser nächster Schritt war die Suche nach dem verlorenen Mattermost. Das war schnell erledigt: auf dem Host läuft nur eine einzige Instanz der Software. Angebunden ist sie sehr klassisch via .htaccess:
RewriteEngine On
RewriteCond %{REQUEST_URI} ^/api/v3/users/websocket [NC,OR]
RewriteCond %{REQUEST_URI} ^/api/v4/users/websocket [NC,OR]
RewriteCond %{HTTP:UPGRADE} ^WebSocket$ [NC,OR]
RewriteCond %{HTTP:CONNECTION} ^Upgrade$ [NC]
RewriteRule .* ws://127.0.0.1:42656%{REQUEST_URI} [P,QSA,L]
RewriteCond %{DOCUMENT_ROOT}/%{REQUEST_FILENAME} !-f
RewriteRule .* http://127.0.0.1:42656%{REQUEST_URI} [P,QSA,L]
Klingt eigentlich alles gut. Kurz zur Erläuterung: Ankommende Requests werden hier in zwei Kategorien aufgeteilt: .../websocket und alles andere. Die folgenden RewriteRules zeigen zwar beide auf den selben Port, nutzen aber dann jeweils Websockets oder normales HTTP um die Verbindung aufzubauen. Das entspricht auch dem von Mattermost empfohlenen Setup.
Abgesehen davon, dass eine .htaccess-Datei innerhalb von einem Uberspace ohnehin unter keinen Umständen Einfluss auf irgendetwas außerhalb des Uberspaces haben sollte, sind hier also auch keine Absurditäten zu erkennen, die Requests fehlleiten könnten.
Die Suche muss also weitergehen..
Unser Setup
Wie in früheren Blogposts schon geschildert, ist unser HTTP-Setup derzeit mehrstufig: client ==> nginx ==> apache. Neben Apache kommt also auch nginx als Problemquelle in Frage. Da nginx allerdings im Moment keine Entscheidungen über Domains oder Content trifft, sondern nur als simpler HTTPS-Endpoint agiert, hatten wir den Apachen im Verdacht.
Nach ein bisschen Hin und Her ist es uns gelungen selbst einen fehlgeleiteten Request zu erzeugen:
2a00:d0c0:: "GET /?d=28781 HTTP/1.1" 200 14 "-" "curl/7.29.0" upstream:127.0.0.1:81
2a00:d0c0:: "GET /?d=10155 HTTP/1.1" 200 3113 "-" "curl/7.29.0" upstream:127.0.0.1:81
2a00:d0c0:: "GET /?d=337 HTTP/1.1" 200 14 "-" "curl/7.29.0" upstream:127.0.0.1:81
An der Response-Größe nach nach dem Status-Code (200) sieht man gut, welcher Request in die Hose gegangen ist: Hello, World mit Headern ist gerademal 14 Bytes lang. Die von Mattermost generiete HTML-Response ist mit 3.113 Bytes natürlich viel länger.
Im Apache-Log erwarten wir wir ein ähnliches Bild. Also mal reingeschaut:
2a00:d0c0:: "GET /?d=28781 HTTP/1.1" 200 14
2a00:d0c0:: "GET /?d=337 HTTP/1.1" 200 14
Gut zu sehen sind hier wieder die beiden 14 Bytes langen Requests; verschwunden ist jedoch der fehlgeleitete Mittlere. Unser erste Gedanke war hier natürlich, dass nginx den Request gar nicht zum Apache, sondern irgendwo anders hinschickt. Allerdings gibt er - wie oben im Log zu sehen - klar an, dass der verwendete Upstream-Server 127.0.0.1:81 ist. Einen anderen gibt es im gesamten nginx-Setup auch gar nicht. Zusätzlich haben wir den Request mit tcpdump mitgeschnitten und konnten so sehen, dass der Request wirklich an Port 81 zugestellt und auch von dort beantwortet wird. Nginx macht also alles richtig.
Wir habens es also nachweislich mit Requests zu tun, die dem falschen Account zugeordnet werden und dabei keine Log-Einträge erzeugen. Bingo?
An diesem Punkt wurde es mir zu bunt und ich habe Jonas hinzugezogen, weil seine Erfahrung mit dem lieben Apache doch schon ein paar Jahre weiter zurück geht als meine. Nach ein bisschen initialiem Rumprobieren haben wir erstmal die höchste Debug-Log-Stufe des mod_rewrite-Moduls aktiviert, aber auch so: keine Spur von den Requests. Anschließend haben wir noch das mod_log_forensic-Modul oben drauf gepackt: absolut nichts - wie als wären sie gar nicht da. Nach dieser Erkenntnis ging dann selbst unserem Jonas langsam die Geduld aus:
Und im RewriteLog sieht es auch so aus. Ich habe die Requests extra im 2-Sekunden-Abstand gemacht, damit ich’s deutlich sehe, und: Zwischen zwei Debug-Einträgen liegen 4 Sekunden.
Un-fucking-fassbar.
Und das bei einem Modul, das sich mod_FORENSIC nennt. Das Dran-Vorbei-Wurschteln an der Forensik gibt’s offenbar kostenlos dazu.
Wir haben uns dann noch ein Weilchen länger damit beschäftigt, doch …
… die Auflösung …
gab es nie. Es ist uns auch nach mehreren Tagen Debugging nicht gelungen zu ermitteln, was genau hier falsch läuft. Durch den Websocket-Kontext der .htaccess konnten wir den Fehler relativ flott auf das mod_proxy_wstunnel-Modul eingrenzen. Weiter sind wir jedoch nie gekommen. Letzten Endes musste wir das Modul noch vor dem U7 Release deaktivieren, um sicherzustellen, dass alle Requests auch wirklich im passenden Uberspace landen.
Auch wenn wir hier nie zu einer klaren Diagnose oder gar zu einer echten Lösung gekommen sind, ist es doch eine echt spannende Geschichte. Die wollten wir euch, wenn nun auch mit etwas Zeitversatz, nicht vorenthalten. Manchmal klappt es einfach nicht.
Die logische Folge aus dem deaktivierten wstunnel-Modul ist natürlich, dass U7 wie auch U6 keine Websockets zu User-Services durchreichen kann. Eigentlich schade. Diese Möglichkeit hätten wir euch wirklich gerne schon zum Launch in die Hände gegeben. Doch was beim Launch nichts wurde, kommt nun bald. Seid gespannt und beobachtet diesen Blog.. :)