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

[Nachtfalkeaw]

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]

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]

@wildum
Yes I use
loki.source.windowsevent

and later
stage.eventlogmessage

[wildum]

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

• put the logging level to debug (see https://grafana.com/docs/alloy/latest/reference/config-blocks/logging/) and see if there is anything hint in the log that could explain this
• add a loki.echo component after one of the loki.source.windowsevent / or an empty loki.process and check live debugging . The idea here is to see the log lines right after they exit the windowsevent component.
• you could also start with only one windowsevent component to see whether this affects all of them or not

[Nachtfalkeaw]

@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:

• set grafana alloy logging block to a severity lower than "error". In this case "warn"
• Lock the windows computer and then login with the correct password.
• This results in the grafana alloy logging error messages.

I attached 3 logfiles from "live_debugging"

• 01_ is directly after the "loki.source.windowsevent "security" {}" block
• 02_ is the "loki.process" stage
• 03_ is the logging of the alloy logging block.

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

edit 2024-12-06

@wildum any idea or more logs needed?

[Nachtfalkeaw]

grafana/alloy#982

[wildum]

hey sorry I was away, thanks for all the info, I will investigate