Apache Log Analyse per PowerShell

Durch die unsanfte Abschaltung der MSXFAQ habe ich natürlich mit auch nach dem Umzug die Zugriffe genauer anschaut. Ich lade mit daher vom Hoster immer mal wieder die access.log-Dateien der Webservers herunter und werte diese aus.

Dieses Seite ist zugleich ein Beispiel, wie flexibel man mal eben schnell Zahlenreihen auswerten kann.

Dateigröße

Der erste Blick gilt erst mal der Dateigröße. Jeder Zugriff hinterlässt ein paar Zeichen und bei genug Zugriffen ist schon die Dateigröße ein gutes Kriterium auf größere Unregelmäßigkeiten.

Hier sehen Sie die minimal Last vor der Umstellung und dass am 15.5.2020 das Volumen dann sprunghaft angestiegen ist. Auch die Wochenende (z.B. 17.05.2020) sind anhand deutlich reduzierter Abfragen gut zu erkennen. Allerdings sind es schon noch viele Anfragen.

Rohformat

Die vom Hoster bereitgestellten Logs sind gepackt, was bei Textdateien auch eine sehr gute Idee ist um Plattenplatz und Übertragungsvolumen zu sparen. Aus den 4,8 MB GZIP-Datei werden dann 101 Megabyte Text-Datei:

Dies ist ein Auszug kurz nach Mitternacht, so dass die automatischen Aufruf der RSS-Feed-Datei "msxfaq.xml" und das Format ist recht schnell zu verstehen:

194.113.141.33 - - [26/May/2020:00:00:04 +0200] "GET /newsletter/msxfaq.xml HTTP/1.1" 301 251 "-" "curl/7.61.1" "www.msxfaq.de"
194.113.141.33 - - [26/May/2020:00:00:04 +0200] "GET /newsletter/msxfaq.xml HTTP/1.1" 200 7968 "-" "curl/7.61.1" "www.msxfaq.de"
139.18.224.1 - - [26/May/2020:00:00:04 +0200] "GET /newsletter/msxfaq.xml HTTP/1.1" 301 251 "-" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 10.0; WOW64; Tride..." "www.msexchangefaq.de"
139.18.224.1 - - [26/May/2020:00:00:04 +0200] "GET /newsletter/msxfaq.xml HTTP/1.1" 200 1990 "-" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 10.0; WOW64; Tride..." "www.msxfaq.de"
37.138.45.253 - - [26/May/2020:00:00:10 +0200] "GET /newsletter/msxfaq.xml HTTP/1.1" 301 251 "-" "curl/7.29.0" "www.msxfaq.de"
37.138.45.253 - - [26/May/2020:00:00:10 +0200] "GET /newsletter/msxfaq.xml HTTP/1.1" 200 7968 "-" "curl/7.29.0" "www.msxfaq.de"
80.228.7.114 - - [26/May/2020:00:00:10 +0200] "GET /newsletter/msxfaq.xml HTTP/1.1" 304 0 "-" "NextCloud-News/1.0" "www.msxfaq.de"
2003:cf:1f1e:f200:7918:4de6:aa6a:839e - - [26/May/2020:00:00:10 +0200] "GET /newsletter/msxfaq.xml HTTP/1.1" 200 1990 "-" "rss2email/2.70 +http://www.allthingsrss.com/rss2email/" "www.msxfaq.de"
46.229.168.134 - - [26/May/2020:00:00:10 +0200] "GET /skype_for_business/hosting/lynchostingzielgruppe.htm HTTP/1.1" 301 282 "-" "Mozilla/5.0 (compatible; SemrushBot/6~bl; +http://www.semrush.com/bot.html)" "www.msxfaq.de"
178.208.113.249 - - [26/May/2020:00:00:11 +0200] "GET /newsletter/msxfaq.xml HTTP/1.1" 301 251 "-" "Mozilla/4.0 (compatible; ms-office; MSOffice 16)" "www.msxfaq.de"
85.25.177.219 - - [26/May/2020:00:00:11 +0200] "GET /cloud/sfbonline/acp.htm HTTP/1.1" 200 7454 "-" "Mozilla/5.0 (compatible; adscanner/)/1.0 (http://seocompany.store; spider@seocompany.store)" "www.msxfaq.de"
178.208.113.249 - - [26/May/2020:00:00:11 +0200] "GET /newsletter/msxfaq.xml HTTP/1.1" 200 1990 "-" "Mozilla/4.0 (compatible; ms-office; MSOffice 16)" "www.msxfaq.de"
85.13.137.165 - - [26/May/2020:00:00:12 +0200] "GET /newsletter/msxfaq.xml HTTP/1.1" 301 251 "-" "Tiny Tiny RSS/19.8 (http://tt-rss.org/)" "www.msxfaq.de"
85.13.137.165 - - [26/May/2020:00:00:12 +0200] "GET /newsletter/msxfaq.xml HTTP/1.1" 304 0 "-" "Tiny Tiny RSS/19.8 (http://tt-rss.org/)" "www.msxfaq.de"
46.229.168.133 - - [26/May/2020:00:00:12 +0200] "GET /skype_for_business/hosting/lynchostingzielgruppe.htm HTTP/1.1" 200 7678 "-" "Mozilla/5.0 (compatible; SemrushBot/6~bl; +http://www.semrush.com/bot.html)" "www.msxfaq.de"
84.152.253.31 - - [26/May/2020:00:00:16 +0200] "GET /newsletter/msxfaq.xml HTTP/1.1" 301 251 "-" "Tiny Tiny RSS/19.8 (81bf112) (http://tt-rss.org/)" "www.msxfaq.de"
84.152.253.31 - - [26/May/2020:00:00:16 +0200] "GET /newsletter/msxfaq.xml HTTP/1.1" 304 0 "-" "Tiny Tiny RSS/19.8 (81bf112) (http://tt-rss.org/)" "www.msxfaq.de"
144.91.122.161 - - [26/May/2020:00:00:18 +0200] "GET /newsletter/msxfaq.xml HTTP/1.1" 304 0 "-" "NextCloud-News/1.0" "www.msxfaq.de"
2a02:908:530:33c0:6c8e:12e4:75ee:d67c - - [26/May/2020:00:00:25 +0200] "GET /skype_for_business/mobile/sfb_und_iospush.htm HTTP/1.1" 2

Damit ich nicht immer die Datei wieder lesen muss, lade ich sie einmal in eine Variable. Da der Datei aber ein "Header" fehlt", muss ich den manuell angeben.

$log= import-csv .\access_log_2020-05-27_00-34.txt -Delimiter " " -Header IP,a1,a2,datetime,offset,request,code,byte,a3,useragent,hostname

Etwas unschön ist, dass der Zeitstempel zwischen Datum/Uhrzeit und Zeitverschiebung ein Leerzeichen hat aber nicht in Anführungsstrichen eingebunden ist. Das Einlesen selbst dauert ca. 1 Sekunden und der Speicherbedarf der PowerShell steigt auf 1,4GB!.

Get-Process pwsh

 NPM(K)    PM(M)      WS(M)     CPU(s)      Id  SI ProcessName
 ------    -----      -----     ------      --  -- -----------
     68 1.461,46   1.496,66      16,45   16360   2 pwsh

Die Speicherung von Variablen in CSV-Objekten ist in Powershell damit nicht gerade "effektiv" aber für Adhoc-Analysen kann man damit arbeiten. Die ersten Checks gehen schnell:

PowerShell

Beschreibung

Anzahl der Requests

$log.count 
438383

Auch an diesem "normalen Tag" habe ich fast eine halbe Million Requests gehabt.

($log | group ip -NoElement).count
10858

Die Anfragen kamen von über zehntausend unterschiedlichen IP-Adressen

Requests nach IP-Adresse

($log | group ip -NoElement) | sort count -Descending -Top 10

Count Name
----- ----
 3258 46.85.249.97
 1363 85.25.177.219
 1237 66.249.70.62
 1147 2003:e2:7f1a:700:8d16:87…
 1062 46.85.240.47
  942 194.39.218.10
  689 52.162.211.179
  600 17.58.96.167
  586 195.145.206.114
  563 193.5.216.100

Das waren die "Top 10" Requester. Ein Angreifer von genau einer Adresse könnte man damit schon gut ausmachen. Noch sind nur wenige IPv6-Clients dabei.

Als Erweiterung könnte man nun noch die IP-Adresse auf einen Provider mappen.

  • 46.85.249.97
    Das dürfte dann meine eigene Überwachung sein. Die Adresse gehört zur Telekom und der UserAgent verweist auf PRTG
  • 85.25.177.219
    Dahinter verbirgt sich laut UserAgent ein WebCrawler, "Mozilla/5.0 (compatible; adscanner/)/1.0 (http://seocompany.store; spider@seocompany.store)".
  • 66.249.70.62
    Die Adresse gehört zu Google

Was macht die eine aktivste IP-Adresse

($log | where {$_.ip -eq "46.85.249.97"} | group code -NoElement)

Count Name
----- ----
 3258 GET / HTTP/1.1

Mich hat natürlich der "TopUser" interessiert, was der macht. Sie sehen hier aber, dass alle 3258 Requests nur die Homepage betroffen haben. über 24 Stunden sind das 2 Requests/Minute. Das scheint also ein "Monitoring" zu sein. Die IP-Adresse gehörte damals zu einer Telekom-DialUp-Adressen

C:>nslookup 46.85.249.97

Name:    p2e55f961.dip0.t-ipconnect.de
Address:  46.85.249.97

Das dürfte also mein eigenes Monitoring sein.

HTTP Statuscode Auswertung

$log `
| group code -NoElement `
| sort count -Descending `
| ft -AutoSize

 Count Name
 ----- ----
409739 200
 14225 301
  9686 304
  3147 499
  1339 404
   128 302
    84 206
    23 400
    12 429

Da der Webserver auch den Result-Code protokolliert, habe ich mir dessen Verteilung ausgeben lassen. Die hohe Anzahl an "200 OK"-Meldungen ist natürlich gut. Die 301 Meldungen sind Umleitungen von anderen Adressen wie msxfaq.net, msxfaq.com auf die msxfaq.de. Ich hätte aber gedacht, das es noch mehr 304 Meldungen sind, die ein "Not Modified" bedeuten, d.h. der Client könnte die Daten aus dem Cache liefern.

Die 4xx Meldungen aber sind mal genauer zu überprüfen. Sicher gibt es ein paar ungültige URLs aber so viele 499 machen neugierig.

Häufigkeit nach URL

$log `
| group request -NoElement `
| sort count -Descending -top 10 `
| ft -AutoSize

Count Name
----- ----
19884 GET /newsletter/msxfaq.xml HTTP/1.1
 9640 GET /banner/topbanner.htm HTTP/1.1
 9033 GET /banner/aktion.htm HTTP/1.1
 8403 GET /msxfaq2020.css HTTP/1.1
 7910 GET /images/mobile-bars.gif HTTP/1.1
 7871 GET /images/mobilearrowuphover3.gif HTTP/1.1
 7842 GET /banner/aktion.css HTTP/1.1
 7697 GET /images/msxfaqlogo2016b.jpg HTTP/1.1
 7601 GET /images/submenuplus.gif HTTP/1.1
 7565 GET /images/menulogo/menulogo-cloud48x48.png HTTP/1.1

Dass bei den Top10 URLs die XML-Datei für den RSS-Feed so heraussticht, ist bemerkenswert. Ich dachte, dass RSS schon fast nicht mehr genutzt wird. Da habe ich mich wohl getäuscht. RSS ist eben immer noch ein ganz pfiffiger Weg Änderungen auf Webseiten nachzuhalten.

Welche Quelle ruft die aktivste URL ab

$log `
| Where {$_.request -eq "GET /newsletter/msxfaq.xml HTTP/1.1"} `
| group ip -NoElement `
| sort count -Descending -top 10 `
| ft -AutoSize

Count Name
----- ----
  586 195.145.206.114
  550 156.67.166.249
  448 37.138.39.145
  340 2a00:17c8:0:8000::202
  336 194.113.141.33
  328 185.156.125.1
  288 80.228.7.114
  285 144.91.122.161
  257 2a00:17c8::203
  248 87.135.154.38

Also habe ich mir die IP-Adressen zu all den Clients genauer angeschaut, die den RSS-Feed laden. Da ich keine Wiederholrate vorgebe, ist jeder Client selbst für das Abrufintervall zuständig. Einmal in der Stunde wäre ja ausreichend aber einige Clients scheinen damit dann alle 2 Minuten nach einem Update zu suchen.

Wenn ich dann nach "Count" noch mal gruppiere, dann sieht man eine klare Häufung bei 94-96 Requests, was auf 20Min Abstände vieler Clients hinweist. Warum aber einige Clients quasi "Realtime" ein update haben wollen, ist ihnen überlassen.

Man könnte nun natürlich noch schauen, ob sie schlau genug sind, erst einmal das Datum zu checken, ehe sie die 7kByte laden.

Verhältnis IPv4 zu IPv6

($log | where {$_.ip.contains(":")}).count
64014

($log | where {$_.ip.contains(":")}).count
374369

IPv6-Addressen unterscheiden sich einfach durch den "Doppelpunkt" in der Adresse. Mich hat also interessiert, wie das Verhältnis zwischen IPv4 und IPv6. Da sind immer noch die IPV4-Adressen mit dem Faktor 6 vertreten. Ich erkläre mir das durch die überwiegende Nutzung aus Firmenanschlüssen, die noch alle IPv4 können. Die Anzahl der Besucher über DSL/Mobil-Privatanschlüsse und IPv6 ist geringer. das sieht man ja auch an der Zeitverteilung

Verteilung über die Tageszeit

$log| %{$_.datetime.Split(":")[1]} | group -NoElement | ft name,count

Name Count
---- -----
00    5108
01    3024
02    1961
03    2134
04    2008
05    2790
06    5339
07   14711
08   28489
09   38966
10   42055
11   38930
12   30314
13   36095
14   39740
15   35383
16   28979
17   18536
18   13753
19   11929
20   10697
21    9829
22    9077
23    8536

Den Berg zur Mittagszeit können Sie sehr gut sehen, wenn Sie das Feld "DateTime" ([26/May/2020:00:00:03) an den Doppelpunkten auftrennen und dann das Ergebnis gruppieren.

Gegen 07:00 morgens geht es los und zwischen 9 bis 15 Uhr sind die Abrufzahlen konstant über 30.000, ehe Sie dann zum Abend hin abflachen.

Detail zu den HTTP-Fehlern

$log `
| where{$_.code -eq "499"} `
| group request -NoElement `
| ft -AutoSize

Ich war ja noch ein paar Analysen zu den HTTP-Errors schuld:

  • 499 Client Closed Request
    Ein Client fragt und wartet die Antwort nicht ab? Da kann bei mobilen Clients schon mal passieren. Ein Muster konnte ich in den Daten nicht finden.
  • 429 to many Requests
    Leider kenne ich die Details der Apache-Konfiguration nicht, anhand der ein 429 geliefert wird. Es war an dem Tag ein einzelner IPv6 Client mit 12 Anfragen auf HTML-Seiten.
    Es war ein WebCrawler (Hier http://webmeup-crawler.com/), der erst auf msexchangefaq.de einen 301 auf msxfaq.de einfängt und dann die eigentliche Seite abholt. Er hat aber insgesamt nur 64 Requests ausgelöst.

Die genaue

Sonderfall 404 Fehler

$log `
| where{$_.code -eq "404"} `
| group request -NoElement `
| ft -AutoSize 

Die Analyse der 404-Fehler ist immer besonders interessant, dann sie zeigt mir zum einen, welche URLs noch abgerufen werden, die aber aufgrund einer Umorganisation nicht mehr dort liegen. Man findet dort aber auch alle versuchten Angriffe auf nicht existente URLs.

Hostname auswerten

$log | group hostname -NoElement | ft -AutoSize

 Count Name
 ----- ----
     1
    17 178.77.117.98
    75 msexchangefaq.de
    16 msxfaq.com
   662 msxfaq.de
    59 msxfaq.net
  1305 www.msexchangefaq.de
    28 www.msxfaq.com
435389 www.msxfaq.de
   637 www.msxfaq.net

Wenn, wie in meinem Fall, mehrere Webseiten auf der gleichen virtuellen Instanz laufen, dann ist das letzte Feld für die Auswertung relevant, da hier die angesprochene Domain steht. Ich kann mir eine Trennung sparen, da es alles ein Top ist.

Sonderfall 404

Die URLs hinter einem 404 Fehler sind besonders interessant, da sie zwei Fälle aufzeigen:

  • falsch verlinkte Seiten
    Leider muss ich manchmal auch die MSXFAQ umorganisieren und damit ändern sich auch Verzeichnisse und Pfade. SharePoint Designer sortiert das natürlich um aber es gibt auch einen "Staging"-Bereich. Manchmal übersehe ich Dateien.
    6 GET /_pending/adsync-deletion07a.gif HTTP/1.1
    6 GET /_pending/adsync-deletion08.gif HTTP/1.1
   13 GET /_pending/graph_und_exchange03.gif HTTP/1.1
  • Böse URLs
    Es finden sich natürlich auch jede Menge URLs, die es auf der MSXFAQ nicht gibt und aufzeigen, welchen Angriffen Webseiten heute unterliegen. Dies ist nur ein Auszug aber an diesem Tag waren es nur ca. 400 Requests, also 1 Promille. Sie sehen gut, dass die Angreifer zum einen versuchen das CMS dahinter zu ermitteln aber auch Schwachstellen zu finden.
    8 GET /.env HTTP/1.1
    1 GET /.well-known/assetlinks.json HTTP/1.1
    1 GET /.well-known/dnt-policy.txt HTTP/1.1
    4 GET //2018/wp-includes/wlwmanifest.xml HTTP/1.1
    4 GET //2019/wp-includes/wlwmanifest.xml HTTP/1.1
    7 GET //blog/wp-includes/wlwmanifest.xml HTTP/1.1
    7 GET //cms/wp-includes/wlwmanifest.xml HTTP/1.1
    4 GET //media/wp-includes/wlwmanifest.xml HTTP/1.1
    7 GET //news/wp-includes/wlwmanifest.xml HTTP/1.1
    4 GET //shop/wp-includes/wlwmanifest.xml HTTP/1.1
    7 GET //site/wp-includes/wlwmanifest.xml HTTP/1.1
    7 GET //sito/wp-includes/wlwmanifest.xml HTTP/1.1
    7 GET //test/wp-includes/wlwmanifest.xml HTTP/1.1
    7 GET //web/wp-includes/wlwmanifest.xml HTTP/1.1
    7 GET //website/wp-includes/wlwmanifest.xml HTTP/1.1
    7 GET //wordpress/wp-includes/wlwmanifest.xml HTTP/1.1
    7 GET //wp/wp-includes/wlwmanifest.xml HTTP/1.1
    7 GET //wp1/wp-includes/wlwmanifest.xml HTTP/1.1
    7 GET //wp2/wp-includes/wlwmanifest.xml HTTP/1.1
    7 GET //wp-includes/wlwmanifest.xml HTTP/1.1
    7 GET //xmlrpc.php?rsd HTTP/1.1
    1 GET /typo3/sysext/css_styled_content/static/constants.txt HTTP/1.1
    1 GET /typo3/sysext/css_styled_content/static/setup.txt HTTP/1.1
    1 GET /typo3/sysext/extbase/ext_tables.sql HTTP/1.1

Nun könnten Sie natürlich überlegen, wie Sie mit dem Wissen umgehen. Wer so etwas macht, führt ja im Grund nichts Gutes im Schilde. Eine Blockade der IP-Adresse oder des Providers bringt aber nicht viel, da Angreifer diese in der Regel schnell wechseln. Man könnte aber schon überlegen, die IP-Bereiche von Rechenzentren zu blocken, wenn die Besucher eben nicht auf einem Terminal Server im Rechenzentrum sitzen. Angreifer mieten sich nämlich schon die ein oder andere VM für ihre Angriffe.

Interessant wäre es aber die IP-Adresse für einige Tage auf eine "Watchlist" zu setzen und deren weiteres Verhalten zu analysieren. Das ist besonders dann wichtig, wenn es so einer Adresse gelängt dann einen "200 OK" zu erzeugen

Falsche 200er

Ich kann anhand meiner Dateistrukturen genau sagen, welche URLs "gültig" sind und welcher URLs so gar nicht auf der MSXFAQ existieren können. Es wäre so möglich aus den Logs die gültigen URLs mit einem "200 OK" und auch die mit einem 404 abgelehnten ungültigen Zugriffe auszublenden. Alle anderen URLs wären dann der Rest. Insbesondere die mit einem "200 OK" beantworteten aber per Definition ungültigen URLs sollten einen Alarm auslösen.

Eine solche ausgefeilte Log-Verarbeitung habe ich aber nicht umgesetzt. Ehe Sie aber nun solche Lösungen selbst umsetzen, sollten Sie sich SIEM-Systeme wie z.B. Elastics Services, Splunk u.a. anschauen, die eine Vielzahl von Logs annehmen und aufbereiten kann. Dann macht auch ein Realtime oder zumindest "Neartime"-Logging sinn, welches nicht erst am Ende des Tages die große Logdatei importiert.

Grenzen von PowerShell

Die Stärke von PowerShell ist die einfache und schnelle Verarbeitung der Daten, die aber als interpretierter Code nicht immer Speicheroptimiert ist. Zudem sind nur einfache Auswertungen über einen Einzeiler möglich. Eine Nachverfolgung bestimmter Clients wird damit sehr aufwändig und die Daten geben, außer Zeitpunkt und IP-Adresse auch nicht mehr her. Speziell zweidimensionale Abfragen sind nicht einfach aufzubereiten, z.B. wenn ich zu den 499 Fehlern noch wissen möchte ob die sich auf bestimmte Clients häufen, was ein Hinweis auf eine instabile Verbindung von diesem Provider sein könnte.

Es ist auch nicht gerade einfach per PowerShell entsprechende Grafiken aufzubereiten oder sogar eine Oberfläche mit Auswahlmöglichkeiten zu bauen. Aber es gibt andere Produkte, die hier dann den Faden aufnehmen können.

Weitere Links