search

grafana / loki

Like Prometheus, but for logs.
https://grafana.com/loki
GNU Affero General Public License v3.0
24.1k stars 3.47k forks source link

loki.source.windowsevent and loki.process --> stage.eventlogmessage : invalid line parsed from message #15093

Open Nachtfalkeaw opened 1 week ago

Nachtfalkeaw commented 1 week ago

Describe the bug I want to collect windows eventlogs from german windows 10 with grafana alloy 1.5.0 and loki 3.3.0.

As a result some of my windows eventlogs with channel "security" can not be parsed correctly.

To Reproduce I am only logged in. I do not have any specific applications running. I can not say which process triggers these issues. I think it is enough to have a Windows 10 computer or maybe any other recent WIndows system - maybe german language and alloy installed.

Expected behavior Should parse all the logs correctly

Environment: Windows 10, German, Alloy 1.5.0, Loki 3.3.0

Screenshots, Promtail config, or terminal output

//=======================================================================================
// BEGINN: WINDOWS EVENT LOGS NACH LOKI SENDEN
//=======================================================================================

            // Vordefinierter loki.source für Windows Event logs. "eventlog_name" ist in der software/doku vorgegeben
loki.source.windowsevent "application"  {
    eventlog_name = "Application"

            // Alle 4 Windows Eventlog Typen fassen wir unter dem "service_name" = "windows_eventlog" zusammen.
            // Die Logs haben noch automatisch Label "channel" was definiert aus welchem Windows Channel es kommt: "Application", "security", "System", "Setup"
    labels = {
      "service_name"  = "windows_eventlog",
      "instance"      = constants.hostname,
    }

    forward_to = [loki.process.windows_eventlog.receiver]
    // forward_to = [loki.relabel.windows_eventlog_debug.receiver]        // bei Debug aktivieren, da wurde noch nichts "manipuliert" und man kan live debugging machen
}

//
//=======================================================================================
//

            // Vordefinierter loki.source für Windows Event logs. "eventlog_name" ist in der software/doku vorgegeben
loki.source.windowsevent "security"  {
    eventlog_name = "Security"

            // Alle 4 Windows Eventlog Typen fassen wir unter dem "service_name" = "windows_eventlog" zusammen.
            // Die Logs haben noch automatisch Label "channel" was definiert aus welchem Windows Channel es kommt: "Application", "security", "System", "Setup"
    labels = {
      "service_name"  = "windows_eventlog",
    }

    forward_to = [loki.process.windows_eventlog.receiver]
    // forward_to = [loki.relabel.windows_eventlog_debug.receiver]        // bei Debug aktivieren, da wurde noch nichts "manipuliert" und man kan live debugging machen
}

//
//=======================================================================================
//

            // Vordefinierter loki.source für Windows Event logs. "eventlog_name" ist in der software/doku vorgegeben
loki.source.windowsevent "setup"  {
    eventlog_name = "Setup"

            // Alle 4 Windows Eventlog Typen fassen wir unter dem "service_name" = "windows_eventlog" zusammen.
            // Die Logs haben noch automatisch Label "channel" was definiert aus welchem Windows Channel es kommt: "Application", "security", "System", "Setup"
    labels = {
      "service_name"  = "windows_eventlog",
    }

    forward_to = [loki.process.windows_eventlog.receiver]
    // forward_to = [loki.relabel.windows_eventlog_debug.receiver]        // bei Debug aktivieren, da wurde noch nichts "manipuliert" und man kan live debugging machen
}

//
//=======================================================================================
//

            // Vordefinierter loki.source für Windows Event logs. "eventlog_name" ist in der software/doku vorgegeben
loki.source.windowsevent "system"  {
    eventlog_name = "System"

            // Alle 4 Windows Eventlog Typen fassen wir unter dem "service_name" = "windows_eventlog" zusammen.
            // Die Logs haben noch automatisch Label "channel" was definiert aus welchem Windows Channel es kommt: "Application", "security", "System", "Setup"
    labels = {
      "service_name"  = "windows_eventlog",
    }

    forward_to = [loki.process.windows_eventlog.receiver]
    // forward_to = [loki.relabel.windows_eventlog_debug.receiver]        // bei Debug aktivieren, da wurde noch nichts "manipuliert" und man kan live debugging machen
}

//
//=======================================================================================
//

            // Reine debugging stage für "Live Debugging"
            // Dazu oben bei "loki.source.windowsevent" jeweils den forward_to ändern
loki.relabel "windows_eventlog_debug" {

  rule {
    source_labels    = ["service_name"]
    target_label     = "service_name"
  }

  forward_to = [loki.process.windows_eventlog.receiver]

}

//
//=======================================================================================
//

            // Wir parsen das Log im json Format um alle Felder zu bekommen.
            // Feldname im json wir als Label oder structured_metadata übernommen. Ausnahme "execution" und "security", dort übernehmen wir alles. Siehe nächste stage.json.
loki.process "windows_eventlog" {

  stage.json {
      expressions = {
        source            = "source",
        channel           = "channel",
        computer          = "computer",
        event_id          = "event_id",
        level             = "level",
        levelText         = "levelText",
        opCodeText        = "opCodeText",
        keywords          = "keywords",
        timeCreated       = "timeCreated",
        eventRecordID     = "eventRecordID",
        event_data        = "event_data",
        user_data         = "user_data",
        message           = "message",
        task              = "task",
        taskText          = "taskText",
        version           = "version",
        opCode            = "opCode",
        execution         = "",
        security          = "",
      }
  }

            // im json gibt es Felder, die innerhalb nochmals json formatierte Felder haben. Diese extrahieren wir
            // z.B. "execution" beinhaltet weitere json formatierte Felder z.B. "processId" und "threadId"
  stage.json {
      source              = "execution"
      expressions = {
        processId         = "processId",
        threadId          = "threadId",
        processName       = "processName",
      }
  }

            // im json gibt es Felder, die innerhalb nochmals json formatierte Felder haben. Diese extrahieren wir
            // z.B. "execution" beinhaltet weitere json formatierte Felder z.B. "processId" und "threadId"
  stage.json {
      source              = "security"
      expressions = {
        userId            = "userId",
        userName          = "userName",
      }
  }

            // Nachem nun alle Felder extrahiert haben und umgeschrieben wurden werden sie nun aus "structured_metadata" geschrieben.
  stage.structured_metadata {
    values = {
        source            = "source",                 //
        channel           = "channel",                //
        computer          = "computer",               //
        event_id          = "event_id",               //
        // level             = "level",               // setzen wir in stage.labels und hier nicht doppelt
        levelText         = "levelText",              //
        opCodeText        = "opCodeText",             //
        keywords          = "keywords",               //
        timeCreated       = "timeCreated",            //
        eventRecordID     = "eventRecordID",          //
        event_data        = "event_data",             // Unklar, inwiefern das wichtig ist im Vergleich zu "message" und wie man es parsen kann.
        user_data         = "user_data",              // Genauso seltsam wie "event_data"
        // message           = "message",             // Haben wir in der Logzeile, brauchen wir nicht als metadata nochmal
        task              = "task",                   //
        taskText          = "taskText",               //
        // execution         = "execution",           // Nicht nötig, da Inhalt extrahiert nach "processId" + "threadId" + "processName"
        // security          = "security",            // Nicht nötig, da Inhalt extrahiert nach "userId" + "userName"
        processId         = "processId",              //
        threadId          = "threadId",               //
        processName       = "processName",            //
        userId            = "userId",                 //
        userName          = "userName",               //
        version           = "version",                // 
        opCode            = "opCode",                 // 
    }
  }

            // Wir droppen Alloy logs aus Windows event, weil sie sich schlecht parsen lassen und wir zudem eine eigene logging .alloy file haben und diese anders parsen.
  stage.drop {
      source = "source"                               // extrahierte Daten aus dem Windows Event Log mit dem Feld "source" und dem Wert "Alloy"
      value  = "Alloy"
      drop_counter_reason = "windows_eventlog_alloy"  // Metrik: loki_process_dropped_lines_total   eine drop Reason für Labels, damit man sieht, wieviele Logs deswegen gelöscht werden.
  }

            // wir setzen den Wert aus dem Log
  stage.labels {
      values = {
        level     = "level",                      // "level" aus stage.json
     // labelname = "labelInhalt",
      }
  }

            // Loki bietet einen vordefinierten parser für den "messages" Bereich von Windows Eventlogs. Wir wählen das zuvor per json extrahierte "message" Feld als "source" aus
            // Und lassen es umwandeln. Sollten im Message Feld Informationen stehen, die es zuvor schon gab, werden diese "overwritten" und nicht ein separates Label erstellt.
  stage.eventlogmessage {
      source = "message"
      overwrite_existing = true
  }

            // Als Logzeile exportieren wir nur den "message" Teil. Alle anderen Infos als structured_metadata in den Log Details.
  stage.output {
      source = "message"
  }

            // Wichtig, ohne timestamp stage wird die "ingested" time genommen, die vom tatsächlichen Log abweichen kann.
  stage.timestamp {
      source = "timeCreated"
      format = "2006-01-02T15:04:05,0000000Z"         // Beispielformat WindowsEvent Log: format = "2024-11-22T13:43:10.0622404Z"
  }

    forward_to = [loki.relabel.hostname.receiver]

}

Example of live_debugging of "loki.process"

[IN]: timestamp: 2024-11-24T22:46:35.4665804+01:00, entry: ts=2024-11-24T21:46:35.4665804Z level=warn msg="invalid line parsed from message" component_path=/ component_id=loki.process.windows_eventlog component=stage type=eventlogmessage line="Die Felder für die Authentifizierungsinformationen enthalten detaillierte Informationen zu dieser speziellen Anmeldeanforderung."
, labels: {component="alloy"}
[OUT]: timestamp: 2024-11-24T22:46:35.4665804+01:00, entry: invalid line parsed from message, labels: {level="warn", service_name="alloy"}
[OUT]: timestamp: 2024-11-24T22:46:35.4665804+01:00, entry: invalid line parsed from message, labels: {level="warn", service_name="alloy"}

This is the Windows event log:

Ein Konto wurde erfolgreich angemeldet.

Antragsteller:
    Sicherheits-ID:     SYSTEM
    Kontoname:      NACHTFALKE$
    Kontodomäne:        WORKGROUP
    Anmelde-ID:     0x3E7

Anmeldeinformationen:
    Anmeldetyp:     5
    Eingeschränkter Administratormodus: -
    Virtuelles Konto:       Nein
    Token mit erhöhten Rechten:     Ja

Identitätswechselebene:     Identitätswechsel

Neue Anmeldung:
    Sicherheits-ID:     SYSTEM
    Kontoname:      SYSTEM
    Kontodomäne:        NT-AUTORITÄT
    Anmelde-ID:     0x3E7
    Verknüpfte Anmelde-ID:      0x0
    Netzwerk-Kontoname: -
    Netzwerk-Kontodomäne:   -
    Anmelde-GUID:       {00000000-0000-0000-0000-000000000000}

Prozessinformationen:
    Prozess-ID:     0x27c
    Prozessname:        C:\Windows\System32\services.exe

Netzwerkinformationen:
    Arbeitsstationsname:    -
    Quellnetzwerkadresse:   -
    Quellport:      -

Detaillierte Authentifizierungsinformationen:
    Anmeldeprozess:     Advapi  
    Authentifizierungspaket:    Negotiate
    Übertragene Dienste:    -
    Paketname (nur NTLM):   -
    Schlüssellänge:     0

Dieses Ereignis wird beim Erstellen einer Anmeldesitzung generiert. Es wird auf dem Computer generiert, auf den zugegriffen wurde.

Die Antragstellerfelder geben das Konto auf dem lokalen System an, von dem die Anmeldung angefordert wurde. Dies ist meistens ein Dienst wie der Serverdienst oder ein lokaler Prozess wie "Winlogon.exe" oder "Services.exe".

Das Anmeldetypfeld gibt den jeweiligen Anmeldetyp an. Die häufigsten Typen sind 2 (interaktiv) und 3 (Netzwerk).

Die Felder für die neue Anmeldung geben das Konto an, für das die neue Anmeldung erstellt wurde, d. h. das angemeldete Konto.

Die Netzwerkfelder geben die Quelle einer Remoteanmeldeanforderung an. Der Arbeitsstationsname ist nicht immer verfügbar und kann in manchen Fällen leer bleiben.

Das Feld für die Identitätswechselebene gibt an, in welchem Umfang ein Prozess in der Anmeldesitzung einen Identitätswechsel vornehmen kann.

Die Felder für die Authentifizierungsinformationen enthalten detaillierte Informationen zu dieser speziellen Anmeldeanforderung.
    - Die Anmelde-GUID ist ein eindeutiger Bezeichner, der verwendet werden kann, um dieses Ereignis mit einem KDC-Ereignis zu korrelieren.
    - Die übertragenen Dienste geben an, welche Zwischendienste an der Anmeldeanforderung beteiligt waren.
    - Der Paketname gibt das in den NTLM-Protokollen verwendete Unterprotokoll an.
    - Die Schlüssellänge gibt die Länge des generierten Sitzungsschlüssels an. Wenn kein Sitzungsschlüssel angefordert wurde, ist dieser Wert 0.

New example:

[IN]: timestamp: 2024-11-24T22:46:35.4660508+01:00, entry: ts=2024-11-24T21:46:35.4660508Z level=warn msg="invalid line parsed from message" component_path=/ component_id=loki.process.windows_eventlog component=stage type=eventlogmessage line="Ein Konto wurde erfolgreich angemeldet."
, labels: {component="alloy"}
[IN]: timestamp: 2024-11-24T22:46:35.4660508+01:00, entry: ts=2024-11-24T21:46:35.4660508Z level=warn msg="invalid line parsed from message" component_path=/ component_id=loki.process.windows_eventlog component=stage type=eventlogmessage line=""
, labels: {component="alloy"}
[IN]: timestamp: 2024-11-24T22:46:35.4660508+01:00, entry: ts=2024-11-24T21:46:35.4660508Z level=warn msg="invalid line parsed from message" component_path=/ component_id=loki.process.windows_eventlog component=stage type=eventlogmessage line=""
, labels: {component="alloy"}
[IN]: timestamp: 2024-11-24T22:46:35.4660508+01:00, entry: ts=2024-11-24T21:46:35.4660508Z level=warn msg="invalid line parsed from message" component_path=/ component_id=loki.process.windows_eventlog component=stage type=eventlogmessage line=""
, labels: {component="alloy"}
[IN]: timestamp: 2024-11-24T22:46:35.4660508+01:00, entry: ts=2024-11-24T21:46:35.4660508Z level=warn msg="invalid line parsed from message" component_path=/ component_id=loki.process.windows_eventlog component=stage type=eventlogmessage line=""
, labels: {component="alloy"}
[OUT]: timestamp: 2024-11-24T22:46:35.4660508+01:00, entry: invalid line parsed from message, labels: {level="warn", service_name="alloy"}
[OUT]: timestamp: 2024-11-24T22:46:35.4660508+01:00, entry: invalid line parsed from message, labels: {level="warn", service_name="alloy"}
[OUT]: timestamp: 2024-11-24T22:46:35.4660508+01:00, entry: invalid line parsed from message, labels: {level="warn", service_name="alloy"}
[OUT]: timestamp: 2024-11-24T22:46:35.4660508+01:00, entry: invalid line parsed from message, labels: {level="warn", service_name="alloy"}
[IN]: timestamp: 2024-11-24T22:46:35.4665804+01:00, entry: ts=2024-11-24T21:46:35.4660508Z level=warn msg="invalid line parsed from message" component_path=/ component_id=loki.process.windows_eventlog component=stage type=eventlogmessage line=""
, labels: {component="alloy"}
[OUT]: timestamp: 2024-11-24T22:46:35.4660508+01:00, entry: invalid line parsed from message, labels: {level="warn", service_name="alloy"}

Windows Event log:

Einer neuen Anmeldung wurden besondere Rechte zugewiesen.

Antragsteller:
    Sicherheits-ID:     SYSTEM
    Kontoname:      SYSTEM
    Kontodomäne:        NT-AUTORITÄT
    Anmelde-ID:     0x3E7

Berechtigungen:     SeAssignPrimaryTokenPrivilege
            SeTcbPrivilege
            SeSecurityPrivilege
            SeTakeOwnershipPrivilege
            SeLoadDriverPrivilege
            SeBackupPrivilege
            SeRestorePrivilege
            SeDebugPrivilege
            SeAuditPrivilege
            SeSystemEnvironmentPrivilege
            SeImpersonatePrivilege
            SeDelegateSessionUserImpersonatePrivilege
wildum commented 1 week ago

Hi, the stage.eventlogmessage expects the log lines to have the format "key:value": https://github.com/grafana/alloy/blob/main/internal/component/loki/process/stages/eventlogmessage.go#L79 In the debug that you pasted, the empty lines and the lines "Ein Konto wurde erfolgreich angemeldet." and "Die Felder für die Authentifizierungsinformationen enthalten detaillierte Informationen zu dieser speziellen Anmeldeanforderung." don't follow this format, that's why the warning is triggered. Are you using the loki.source.windowsevent component to retrieve the windows logs?

Nachtfalkeaw commented 6 days ago

@wildum Yes I use loki.source.windowsevent

and later stage.eventlogmessage

wildum commented 5 days ago

I see, that's weird because the loki.source.windowsevent is supposed to output json formated data. A few more debugging steps:

Nachtfalkeaw commented 4 days ago

@wildum I am not sure but it looks like there are issues with parsing the timestamps. I use "timeCreated" label for "stage.timestamp" However it looks like the parsing I do is wrong.

How would you parse these timestamps?

2024-11-30T22:04:42.5148570Z
2024-11-30T22:04:00.0038331Z

stage.timestamp {
  source     = "ts"
  format     = "2006-01-02T15:04:05.???????Z"
  location   = "Europe/Berlin"
}

It looks like it is a fixed length of fractions of seconds with 7 digits.

And how would you format these timestamps?

2024-11-30T22:09:12.93555Z  
2024-11-30T22:16:06.895674Z 
2024-11-30T22:16:06.8987616Z
2024-11-30T22:06:13.0831491Z

The documentation is not clear for me: https://grafana.com/docs/alloy/latest/reference/components/loki/loki.process/#stagetimestamp-block

Do I have to use in the first example .000000000Z or .0000000Z ? And in the second example .999Z or .99999Z or .9999999Z ?

--- edit 2024-12-01 --- I think I found the issue. If the loki.process stage contains a "stage.timestamo" with "location" set and the format itself contains a timezone indicator like "Z" then the process fails. live_debugging then only shows [IN] but never [OUT].

INVALID:

stage.timestamp {
  source     = "ts"
  format     = "2006-01-02T15:04:05.0000000Z"
  location   = "Europe/Berlin"
}

VALID

stage.timestamp {
  source     = "ts"
  format     = "2006-01-02T15:04:05.0000000Z"
}

Back to the eventlog topic: I can replicate the issue if I do the following:

I attached 3 logfiles from "live_debugging"

01_debug_direct_after_loki_source_windowsevent_security.log 02_debug_after_loki_source_windowsevent_security_in_loki_process.log 03_debug_grafan_alloy_logging_block_severiy_warn.log