Webserver log analyseren en output naar file schrijven

[Verwijderd]

Ik heb een vraag over het volgende;

Ik heb een gecombineerde logfile met info over GET/POST, HANDLE & RESPOND acties op verschillende servers.
Nu wil ik per worker & frontend server weten welke van de files in de log nu de traagste zijn zodat ik hier wat aan kan doen.
Ik kan natuurlijk een voor een alle timestamps van de acties gaan doorrekenen, maar volgens mij is er wel een handigere optie met bijv een bash script wat grep/awk gebruikt of zelfs een mooie oplossing in Python.

De logfile is als volgt opgebouwd:

timestamp, guid, actie, url, status, serverid:

2016-11-02T16:45:01.460000 7b27817b-c030-5e9e-bfa8-b504e7f37b2c GET /klant/notitie - front_01
2016-11-02T16:45:01.630000 7b27817b-c030-5e9e-bfa8-b504e7f37b2c HANDLE - work_02
2016-11-02T16:45:01.720000 7b27817b-c030-5e9e-bfa8-b504e7f37b2c RESPOND 200 front_01

Wat ik dus zou willen is aan de hand van de (grote) logfile een script/stukje code wat mij in een aparte logfile of op het scherm de serverid's geeft van de trage worker (work_NN) & fronted (front_NN) servers

Ik ben aan het kijken naar grep/awk, etc... maar kom er op het moment niet uit...mijn dank is groot als iemand met tips komt

[Ventieldopje]

Heb je al gekeken naar bestaande app/server monitoring diensten als NewRelic? Daar kun je tot in detail zien hoe je applicatie presteert en hoe dat komt.

[Verwijderd]

Bedankt,

Applicaties als NewRelic en dergelijken of een ELK stack voor log analyses heb ik inderdaad in mijn achterhoofd gehad, maar voor dit project is de wens dus een klein maar fijne oplossing in de vorm van een bash / python based script, vandaar ook mijn hoofdbrekens:-)

[Verwijderd]

Iemand nog enig idee voor wat te gebruiken? Alvast bedankt voor jullie waardevolle hulp!

[Swedish Clown]

Nergens voor nodig om na 1 uur al te bumpen.

Dit lijkt verdacht veel op vragen om een kant en klare oplossing. Wat heb je zelf al geprobeerd? Waar loop je tegen aan?

Met een beetje bash-magic moet dit niet te ingewikkeld zijn maar om nou een kant en klare oplossing voor je te schrijven zie ik niet zo zitten en is volgens het forum beleid ook niet de bedoeling

[marco282]

Mij lijkt dat je gewoon door de log heen loopt en langzaam een object opbouwt welke aan de hand van de timestamps deze data berekent die je graag wilt hebben.

Voorbeeld van hoe het object eruit kan zien, ik noem maar wat:

code:

{
    "7b27817b-c030-5e9e-bfa8-b504e7f37b2c": {
        "start": 1478105101,
        "handle": 1478105201,
        "done": 1478105301
        "handleTime": 100,
        "totalTime": 200,
        "worker": "worker1",
        "frontend": "frontend2",
    },
    "8b23717b-b140-12ea-cac9-b50ab3e214b": {
        "start": 1478105101,
        "handle": 1478105201,
        "done": 1478105301
        "handleTime": 100,
        "totalTime": 200,
        "worker": "worker2",
        "frontend": "frontend1",
    },
}

Dit zou eventueel een eind situatie kunnen zijn. Je loopt door alle loglines heen, (split("\n") -> foreach).
In elke each iteration check je of je alle data hebt om de totaltime/handletime uit te rekenen. Je zou voor de tijden de timestamp om kunnen zetten naar een datetime object en de functies voor tijdverschil te gebruiken of je zet het om naar een unix timestamp en rekent daar mee verder.

Ik weet niet of dit iets is waar je op doelt. Nadat je zo'n object hebt opgebouwt kan je eventuel sorteren op basis van start tijd oid en dan een mooi grafiekje van maken of je loopt er doorheen zodat je workers die een grote handleTime hebben kan echoen met tijdstamp erbij.

Het kan wellicht beter en makkelijker, maar als t ff iets snels is zou ik het op deze manier aanpakken.

[ Voor 15% gewijzigd door marco282 op 03-11-2016 21:17 ]

[pedorus]

Verwijderd schreef op donderdag 03 november 2016 @ 17:56:
De logfile is als volgt opgebouwd:

timestamp, guid, actie, url, status, serverid:

2016-11-02T16:45:01.460000 7b27817b-c030-5e9e-bfa8-b504e7f37b2c GET /klant/notitie - front_01
2016-11-02T16:45:01.630000 7b27817b-c030-5e9e-bfa8-b504e7f37b2c HANDLE - work_02
2016-11-02T16:45:01.720000 7b27817b-c030-5e9e-bfa8-b504e7f37b2c RESPOND 200 front_01

Kun je niet gewoon een fatsoenlijke logfile (laten) genereren? Eentje die per request 1 regel heeft met hoe lang die server er zelf over denkt te hebben gedaan zoals gebruikelijk is in mili- of nanoseconden, en welke op het einde van een request wordt gelogd..

Nu zou ik in dit voorbeeld niet eens kunnen vertellen hoelang "work_02" er zelf over gedaan denkt te hebben, want enige data ontbreekt volledig. Als er meer dan 0.01s doorgeeftijd is lijkt me dat trouwens superlang.

de serverid's geeft van de trage worker (work_NN) & fronted (front_NN) servers

Niet van trage requests? Trage servers zou ik vinden door naar een monitoring-tool te kijken, niet door de log-files te analyseren. Een server die het te druk heeft is meestal vrij makkelijk te vinden als er monitoring op is (van load, cpu, memory, network, disk io, etc).

[Verwijderd]

Bedankt Marco282!

Bedankt voor je hulp mbt de issue met de logfiles. Aangezien ik nog niet heel ervaren ben op dit gebied en nog veel moet leren. (ik wil later graag ontwikkelaar worden) Geeft dit antwoord me een duwtje in de goede richting.

Niet om heel brutaal te klinken, maar als ik nu zou beginnen met het inlezen van de logfile en dan met de door jou geadviseerde (split("\n")->foreach) doorga, hoe zou zoiets er dan in code uitzien?

Groet ,
Jens

[marco282]

Een nieuwe regel wordt meestal gedefined bet "\n" (newline).
Je zou dus de volgende functie in python kunnen gebruiken https://www.tutorialspoint.com/python/string_split.htm

Deze veranderd jou string in een lijst waarbij elke item in de lijst 1 regel is.
Daarnaast gebruik je een simpele for loopje om er door heen te lopen.

log = "alle text uit je log"
logLines = de log.split functie hier

for line in logLines:
print line;


Binnen de loop kan je met line aan de gang gaan, hier zul je dus data eruit moeten halen zoals welke server name, wat voor request, request id enz. zodat je een object kan opbouwen.
Dit kan doormiddel van strpos/substr of door gebruik te maken van regular expressions.

[MaNDaRK]

@shreddie, ik denk dat je met PHP bijvoorbeeld al heel wat kan.

Heb je misschien een grotere logfile? Dan kan ik eens kijken of ik een opzet zoals marco282 kan maken voor je.

[Morrar]

Jammer dat de velden niet consistent zijn per type logregel. Maar goed, dit lijkt me in Python niet heel erg moeilijk uit te programmeren. Even uit m'n hoofd:

Python:

import csv

# File settings
encoding = 'utf8'
logfile = 'log.txt'
csvfile = 'parsed.csv'

# CSV settings
csv_sep = ';'
csv_quote = '"'

# Output fields
csv_fields = [
  'Timestamp',
  'GUID',
  'Action',
  'URL',
  'Status',
  'Server',
]

# Open output file
with open(csvfile, 'w', newline='', encoding=encoding) as file_out:
  # Create CSV writer
  csv_out = csv.DictWriter(file_out, csv_fields, delimiter=csv_sep, quotechar=csv_quote)

  # Write header
  csv_out.writeheader()

  # Open the log file
  with open(logfile, 'r', encoding=encoding) as file_in:
    # Process line by line
    for line in file_in:
      # Create record
      rec = {}

      # Split on spaces
      vals = line.split()

      # Store common fields
      rec['Timestamp'] = vals[0]
      rec['GUID'] = vals[1]
      rec['Action'] = vals[2]

      # Request type specific fields
      if rec['Action'] in ['GET', 'POST']:
        rec['URL'] = vals[3]
        rec['Server'] = vals[5]   # 4 is dash

      elif rec['Action'] == 'RESPOND':
        rec['Status'] = vals[3]
        rec['Server'] = vals[4]
      
      elif rec['Action'] == 'HANDLE':
        rec['Server'] = vals[4]

      # Write record to CSV
      csv_out.writerow(rec)

Deze schrijft naar CSV, maar je kunt natuurlijk ook naar een RDMS wegschrijven. Verder gaat het regel voor regel, dus het geheugengebruik is constant. Bij grote logfiles neemt alleen wel de runtime toe natuurlijk.

Als je de drie records (GET/POST, HANDLE, RESPOND) wilt combineren tot 1 record, dan zou ik dat in een RDMS doen en niet in een script. Je kunt dat vrij makkelijk bereiken via twee LEFT JOINs van HANDLE en RESPOND op basis van GUID en (dicthsbijzijnde) Timestamp.

Verder zou ik dit denk ik eerder oppakken in logstash (en dan custom log format definieren) met ElasticSearch. Met Kibana kun je dan eenvoudig een dashboard maken om inzicht te krijgen in je data. Bij ELK 5.0 zit ook TImeLion, waarmee je tijdsreeksen goed kunt weergeven. Die oplossing lijkt me uiteindelijk stabieler dan zelf iets bouwen.


P.S. Als je de Timestamp in een ander format wilt, dan kun je de code als volgt aanpassen:

Python:

from datetime import datetime

en:

Python:

      rec['Timestamp'] = datetime.strptime(vals[0], '%Y-%m-%dT%H:%M:%S.%f').strftime('%Y-%m-%d %H:%M:%S.%f')

Waarbij je met het laatste format aangeeft hoe je het wilt wegschrijven.

[ Voor 13% gewijzigd door Morrar op 05-11-2016 11:09 ]

[RobIII]

MaNDaRK schreef op vrijdag 04 november 2016 @ 14:10:
Heb je misschien een grotere logfile? Dan kan ik eens kijken of ik een opzet zoals marco282 kan maken voor je.

Morrar schreef op zaterdag 05 november 2016 @ 10:48:
Jammer dat de velden niet consistent zijn per type logregel. Maar goed, dit lijkt me in Python niet heel erg moeilijk uit te programmeren. Even uit m'n hoofd:

Allemaal heel goed bedoeld hoor, daar niet van, maar ons motto hier is wel:

Give a man a fish and feed him for a day. Teach a man how to fish and feed him for a lifetime.

[Morrar]

RobIII schreef op zaterdag 05 november 2016 @ 11:08:
[...]


[...]


Allemaal heel goed bedoeld hoor, daar niet van, maar ons motto hier is wel:


[...]

Je moet mensen soms ook een beetje op weg helpen Rob Als iemand al vast loopt op welke tooling uberhaupt kan werken, kan een klein duwtje in de / een goede richting motiveren om aan de slag te gaan. Met dit opzetje kan hij van start en dan zelf proberen het uit te breiden / te verbeteren.

Althans zo zie ik het, maar ik snap ook jouw punt dat het hier niet een 'get your code here for free' forum moet worden

P.S. @Rob bug zou kunnen, had het uit m'n hoofd even snel uitgetikt. Net wel even kunnen testen, maar draaide prima. Maar goed, da's dan een mooie uitdaging dan lijkt me.

[ Voor 11% gewijzigd door Morrar op 05-11-2016 13:35 ]

[RobIII]

Morrar schreef op zaterdag 05 november 2016 @ 11:59:
Je moet mensen soms ook een beetje op weg helpen Rob

Je hebt op weg helpen en je hebt (zo goed als compleet) voorkauwen En daar neigt de post die ik quotte toch wel aardig naar (hoewel ik al minimaal 1 bug zie )

[MaNDaRK]

@RobbIII je hebt helmaal gelijk. Maar ik dacht alleen maar een kleine opzet te maken om shreddie op weg te helpen