Logfiles analysieren
05.01.2010 in: Browser, Sicherheit, Suchmaschinen und Webdesign • Ein Kommentar
Letzte Änderung: 01.10.2010, 18:48 Uhr.
Mindestens einmal pro Monat grabe ich mich durch die Logfiles jeder von mir betreuten Website. Ein Statistikprogramm wie Piwik sieht zwar deutlich hübscher aus; es erfaßt aber nur einen kleinen Teil der Zugriffe. Anfragen an Newsfeeds, Stylesheets, Bilder und Skripte entgehen ihm meistens.
Grundlagen
Ein gewöhnlicher Eintrag im Accesslog sieht (nach manuellem Umbruch) so aus:
msnbot-65-55-106-204.search.msn.com
- -
[01/Jan/2010:01:03:10 +0100]
"GET /2009/ HTTP/1.1"
200
4303
"-"
"msnbot/2.0b (+http://search.msn.com/msnbot.htm)"
Logformat
Das entspricht dem Logformat:
%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"
… und kann übersetzt werden als
| Kürzel | Beschreibung | aktueller Wert |
|---|---|---|
| %h | Hostname | msnbot-65-55-106-204.search.msn.com |
| %l | Remote logname | (leer) |
| %u | Remote user | (leer) |
| %t | Zeitpunkt | 01/Jan/2010:01:03:10 +0100 |
| %r | Request (erste Zeile) | GET /2009/ HTTP/1.1 |
| %>s | Status (nach internem Rewrite) | 200 |
| %b | Übertragene Bytes (ohne Response-Header) | 4303 |
| %{Referer}i | Herkunft (URI) | (leer) |
| %{User-Agent}i | Software (Browser, Crawler) | msnbot/2.0b (+http://search.msn.com/msnbot.htm) |
Hostname oder IP-Adresse
Wenn der Server keinen Hostnamen findet oder anders konfiguriert worden ist, steht an erster Stelle die IP-Adresse. Ob man die nach deutschem Recht speichern darf, wird immer noch heftig umstritten.
Remote logname
Der Remote logname wird nur befüllt, wenn mod_ident aktiviert wurde und IdentityCheck auf On steht.
Remote user
Der Remote user wird befüllt, wenn man sich per Basic Authentication angemeldet hat.
Die beiden letztgenannten Einträge müssen natürlich auch als »personenbezogene Daten« gelten. Eine (zumindest langfristige) Speicherung dürfte sehr heikel werden.
Request
Der Request wird endlich richtig interessant.
Methode
Vorne steht die Methode: GET, POST oder HEAD. Die anderen Methoden verbiete ich normalerweise:
<LimitExcept HEAD GET POST> order deny,allow deny from all </LimitExcept>
Adresse
Dann folgt die angesprochene Adresse, hier /2009/. Darauf kommen wir gleich nochmal.
Protokoll
Und darauf wiederum folgt das Protokoll, hier HTTP/1.1. Das ist spannender, als es aussieht: In HTTP/1.0 gibt es nämlich keine Vary-Header. Den brauche ich aber für alle Ressourcen, die ich per gzip komprimiere, damit der Empfänger weiß, daß ich mindestens zwei Varianten vorhalte: die komprimierte und die unkomprimierte.
Ich sende also bei HTTP/1.1 den Header:
Vary: Accept-Encoding
Sehen wir uns den Request an, der dem hier genannten fünf Sekunden später folgt:
msnbot-65-55-106-204.search.msn.com - - [01/Jan/2010:01:03:15 +0100] "GET /2009/ HTTP/1.0" 200 18124 "-" "msnbot/2.0b (+http://search.msn.com/msnbot.htm)"
Der MSN-Bot holt sich auch die nicht komprimierte Variante. Warum? Weiß der Geier …
Der Internet Explorer benutzt HTTP/1.0, wenn er hinter einem Proxyserver sitzt. Vielleicht will der MSN-Bot herausfinden, ob er die Seite auch dann noch als Suchergebnis präsentieren darf.
Der Yahoo-Bot kann übrigens überhaupt kein HTTP/1.1. Es ist ja auch erst vom Juni 1999.
Statuscode
Nach dem Request kommt der Statuscode. Die wichtigsten:
| Code | Bedeutung |
|---|---|
| 200 | Ok. Inhalt gefunden und ausgeliefert. Der häufigste Eintrag. |
| 301 | Umleitung. Der Inhalt ist fortan unter einer neuen Adresse zu finden. Sehr wichtig, wenn man beispielsweise den Präfix www aus dem Domainnamen entfernt. |
| 302 | Noch eine Umleitung. Ob die neue Adresse Bestand hat, weiß der Server aber nicht, weil der Webmaster gepennt hat. |
| 304 | Nicht geändert. Wenn der User-Agent die Ressource schon im Cache liegen hat und nachfragt, ob er sie aktualisieren soll, sieht der Server nach und sendet 304, wenn alles noch stimmt. Dieser Statuscode sagt uns normalerweise, daß wir alles richtig gemacht haben. Wenn wir Ressourcen ohne Not mehrfach ausliefern, haben wir ein Cachingproblem. |
| 307 | Umleitung. Ganz gewiß nur temporär. |
| 401 | Anmeldung fehlgeschlagen. Beispielsweise beim Passwortschutz per .htaccess: Jemand gibt falsche oder gar keine Daten ein – und wird dann mit 401 versorgt. Damit er Bescheid weiß. |
| 403 | Verboten. Der normale Statuscode, den beispielsweise die Direktive deny from erzeugt. Zu Deutsch: Geh weg, du darfst hier nicht hinein. |
| 404 | Nicht gefunden. Der häufigste Fehler. Um den müssen wir uns kümmern. |
| 410 | Weg. Die Adresse gab’s zwar mal, aber jetzt wurde sie ersatzlos gestrichen. Wenn wir doch einen Ersatz haben, dann ist 301 der passende Statuscode. |
| 500 | Interner Serverfehler. Drama! Kann durch eine falsche Konfiguration (.htaccess oder httpd.conf) zustandekommen aber auch durch fehlerhafte Skripte. |
Größe
Dem Statuscode folgt die Menge der übertragenen Bytes ohne Response-Header. Wie man an den beiden MSN-Beispielen sieht, besteht zwischen komprimierten und nicht komprimierten Ressourcen ein erheblicher Unterschied.
Beim Statuscode 304 sollte die Menge 0 betragen, sonst hat etwas nicht geklappt.
Und eine Ressource sollte möglichst immer dieselbe Menge ausliefern, wenn sie sich nicht geändert hat. Der WordPress-Feed erfüllt diese Bedingung leider nicht immer; das wollte ich schon längst mal untersuchen …
Referer
Der nächste Eintrag (beim MSN-Bot immer leer) ist der Referer. Eigentlich heißt das englische Wort ja Referrer, aber vor vielen Jahren hat sich mal jemand beim Schreiben der Spezifikation vertippt, und seitdem fehlt das eine »r«. Da sieht man wieder, warum Korrekturlesen so wichtig ist.
Normalerweise steht im Referer die URI, von der aus auf die aktuelle Ressource zugegriffen wurde. Oft ist er aber auch leer, oder es steht Spam darin (sogenannter »Referer-Spam«). Manchmal auch feindlicher Code. Deshalb sollte dieser Wert nie ungeprüft in Skripten verwendet werden, und für eine Linkliste ohne Vorkontrolle eignet er sich ebenfalls nicht.
Beim Statuscode 404 kann er uns zuweilen verraten, ob jemand einen kaputten Link gesetzt hat. Da ist der Wert tatsächlich hilfreich.
User-Agent
Hier gelten die gleichen Sicherheitsregeln wie beim Referer. Ich benutze das Feld vorrangig, um Störenfriede loszuwerden. Generell ist es so glaubwürdig wie ein 3-Euro-Schein.
Suchmuster
Wonach suchen wir eigentlich? Nach allem, was ungewöhnlich oder ungewollt aussieht.
Ungewollt sind Fehler: Alle Anfragen, die mit einem 400er oder gar 500er Code beantwortet wurden, verdienen unsere erste Aufmerksamkeit.
400er
In einem Texteditor unserer Wahl suchen wir nach dem regulären Ausdruck " 4\d\d (ein Leerzeichen rechts). Damit finden wir alle 400er Statuscodes.
Die meisten angeforderten Adressen in dieser Zeile enthalten Parameter, über die jemand fremden Code einschleusen möchte:
web.weborange.hu - - [01/Jan/2010:01:32:51 +0100] "GET /2009/authentifizierung-php-utf-8/%252520%252520/?_SERVER%255bDOCUMENT_ROOT%255d=http:/example.com/member/one.txt%253f%253f%253f HTTP/1.1" 404 995 "-" "Mozilla/5.0"
Hier sieht man zweierlei: Der Angriff richtet sich gegen schlampig programmierte PHP-Skripte, und mein Doppelslashkiller hat die einzuschleusende URL entschärft. Selbst wenn ich also ein unsicheres Skript vorhielte, brächte der Angriff nichts, weil http:/example.com keine URL ist, mit der PHP oder eine andere Sprache etwas anfangen kann.
Ein paar Einträge über diesem steht der ursprüngliche Versuch mit den Doppelslashes und dem Statuscode 301. Den hat aber die .htaccess abgefangen und umgeleitet, ehe ihn auch nur ein Skript zu Gesicht bekommen konnte.
Ein weiterer Eintrag sieht so aus:
static.[anonymisiert].clients.your-server.de - - [01/Jan/2010:16:49:56 +0100] "GET /p1563/ HTTP/1.1" 404 995 "-" "Mozilla/5.0 (compatible; Rivva; http://rivva.de)"
Ich hatte ein paar Minuten zuvor bei Twitter einen ähnlichen Link gepostet:
Willkommen im alten Jahrzehnt: http://toscho.de/p1563 #gebloggt
Ähnlich! Der Rivva-Bot hat einen Slash angebaut und dann die falsche Adresse aufgerufen. Spannend wird jetzt die weitere Suche nach dem Rivva-Bot im Logfile: Kommt er nochmal, um die korrekte Adresse zu holen? Nein, tut er nicht.
So etwas verrät mir kein Statistikprogramm.
Ich habe darauf doppelt reagiert: Ich habe Rivva per Twitter Bescheid gegeben – und zwar keine Antwort bekommen, aber der Tweet wurde immerhin »gefavt«. Das ist vermutlich eine sehr subtile Methode, mir zu sagen: »Wir wissen jetzt davon und kümmern uns darum.«
Außerdem habe ich in die .htaccess eine Weiterleitung für genau diese und ähnlich kaputte Anfragen eingebaut:
RewriteEngine On
RewriteBase /
RewriteCond %{REQUEST_URI} ^/\%3fp\=(\d+)$ [OR]
RewriteCond %{REQUEST_URI} ^/p\=?(\d+)/?$
RewriteRule ^.* http://toscho.de/?p=%1 [L,R=301]
Und dann gibt es manchmal noch die 404er, die nicht wie Angriffe aussehen und unsere eigene Domain im Referer zeigen. Da haben wir vielleicht einen falschen Link gesetzt oder einen Fehler im Markup oder im Stylesheet. Logische Reaktion: Reparatur, Kontrolle, ein Schluck Kaffee.
500er
Regex: " 5\d\d (ein Leerzeichen rechts).
Wenn der Server aufgrund eines Fehlers in der .htaccess nicht mitspielt, sehen wir das sofort. Dazu reicht ein vergeblicher Aufruf der Website.
Anders sieht es mit gelegentlichen Ausfällen aus: Ein Skript mag unter ganz bestimmten Umständen PHP abstürzen lassen, oder der Server aus irgendeinem Grund manchmal überlastet sein. Wer sich einen Server mit anderen Websites teilt (Shared Hosting), kann davon auch betroffen werden, ohne die Ursache in die Hand zu bekommen.
Hierfür müssen wir ein zweites Logfile ansehen: Das Errorlog. Das ist so ähnlich aufgebaut wie das Accesslog, und darin steht, was genau passiert ist. Zumindest der Webhoster hat eins.
Massenabfragen
Manchmal sieht die einzelne Abfrage technisch ganz korrekt aus, aber der Blick aufs Ganze löst dann doch einen Würgereiz aus. So hatte ich unzählige Requests von einem Java/1.6.0_11 (die letzten Zahlen variieren). Diese Crawler haben gerne alle Feeds für alle Artikel und Kategorien abgeholt – 20 Mal pro Stunde.
Antwort:
RewriteEngine On
RewriteBase /
RewriteCond %{REQUEST_URI} !/greedy\.html
RewriteCond %{HTTP_USER_AGENT} ^Java/1\.\d [NC]
RewriteRule ^ /greedy.html [L,R=301]
Ebenfalls bedrückend aber derzeit nicht zu ändern: Kaum ein Crawler hält sich an die Vorgaben zur Aktualisierung des Newsfeeds. Wer freilich zu gierig wird, wird hinweggebeten. Man muß sich ja nicht alles gefallen lassen, und das Ziel sollte doch eine schnelle Website für richtige Besucher bleiben. Deshalb verteile ich meine begrenzten Ressourcen lieber effizient.
Einige Feed-Crawler verraten im User-Agent, wieviele Leute den Feed lesen:
38.99.68.203 - - [01/Jan/2010:19:45:18 +0100] "GET /feed/ HTTP/1.1" 200 16543 "-" "Mozilla/5.0 (compatible; FriendFeedBot/0.1; +Http://friendfeed.com/about/bot; 16 subscribers; feed-id=3418198305143441017)"
Das finde ich sehr freundlich. Logfiles können also auch Spaß machen.
Was irgendwie mal wieder zur Frage führt ob FeedBurner mitbekommt, wie viele Abonnenten zum Beispiel FriendFeed hat, da es ja keinen Zugriff auf das Log hat. Hach ja ... ich hab sowieso die Vermutung, das sich die Bots nicht sonderlich um den Redirect von FeedSmith kümmern. Noch lustiger wenn man bedenkt, das es Provider gibt, die keinen Zugriff auf die Logfiles erlauben :) Irgendwie schweife ich vom Thema ab :)