[loki.process] stage.eventlogmessage - invalid line parsed from message

[Elpatii]

What's wrong?

message not parsed from loki.source.windowsevent

Steps to reproduce

1. Install Grafana Alloy v1.1.1.
2. Apply the following configuration (according to documentation: https://grafana.com/docs/alloy/latest/reference/components/loki.process/#stageeventlogmessage-block):

logging {
	level = "warn"
}

loki.source.windowsevent "security" {
    eventlog_name = "Security"
    forward_to    = [loki.process.parse.receiver]
}

loki.process "parse" {
    forward_to = [loki.write.default.receiver]

    stage.json {
        expressions = {
            message = "message",
            Overwritten = "",
        }
    }

    stage.eventlogmessage {
        source = "message"
        overwrite_existing = true
    }
}

loki.write "default" {
    endpoint {
        url = "http://loki:3100/loki/api/v1/push"
    }
}

3. Observe Windows Event Logs, in Application. There will be plenty of these message:

ts=2024-06-04T15:46:34.3625895Z level=warn msg="invalid line parsed from message" component_path=/ component_id=loki.process.logformat component=stage type=eventlogmessage line=""
ts=2024-06-04T15:46:34.3625895Z level=warn msg="invalid line parsed from message" component_path=/ component_id=loki.process.logformat component=stage type=eventlogmessage line=""
ts=2024-06-04T15:46:34.3625895Z level=warn msg="invalid line parsed from message" component_path=/ component_id=loki.process.logformat component=stage type=eventlogmessage line=""
ts=2024-06-04T15:46:34.3625895Z level=warn msg="invalid line parsed from message" component_path=/ component_id=loki.process.logformat component=stage type=eventlogmessage line=""
ts=2024-06-04T15:46:34.3625895Z level=warn msg="invalid line parsed from message" component_path=/ component_id=loki.process.logformat component=stage type=eventlogmessage line="\t\t\t\tSYNCHRONIZE"
ts=2024-06-04T15:46:34.3625895Z level=warn msg="invalid line parsed from message" component_path=/ component_id=loki.process.logformat component=stage type=eventlogmessage line="\t\t\t\tReadData (or ListDirectory)"
ts=2024-06-04T15:46:34.3625895Z level=warn msg="invalid line parsed from message" component_path=/ component_id=loki.process.logformat component=stage type=eventlogmessage line="\t\t\t\tReadEA"
ts=2024-06-04T15:46:34.3625895Z level=warn msg="invalid line parsed from message" component_path=/ component_id=loki.process.logformat component=stage type=eventlogmessage line="\t\t\t\tReadAttributes"
ts=2024-06-04T15:46:34.3625895Z level=warn msg="invalid line parsed from message" component_path=/ component_id=loki.process.logformat component=stage type=eventlogmessage line="\t\t\t\t"
ts=2024-06-04T15:46:34.3625895Z level=warn msg="invalid line parsed from message" component_path=/ component_id=loki.process.logformat component=stage type=eventlogmessage line="\t\t\t\t"

4. Observe logs sent to Loki: no parsing done. Example:

"message": "A handle to an object was requested.\r\n\r\nSubject:\r\n\tSecurity ID:\t\tS-1-5-21-1200248480-620207695-2785191293-500\r\n\tAccount Name:\t\tAdministrator\r\n\tAccount Domain:\t\tALLOY01\r\n\tLogon ID:\t\t0x193A06\r\n\r\nObject:\r\n\tObject Server:\t\tSecurity\r\n\tObject Type:\t\tFile\r\n\tObject Name:\t\tC:\\Windows\\WinSxS\\FileMaps\\$$_system32_windowspowershell_v1.0_3f102d555ee05d33.cdf-ms\r\n\tHandle ID:\t\t0x1b54\r\n\tResource Attributes:\t-\r\n\r\nProcess Information:\r\n\tProcess ID:\t\t0x16a4\r\n\tProcess Name:\t\tC:\\Windows\\explorer.exe\r\n\r\nAccess Request Information:\r\n\tTransaction ID:\t\t{00000000-0000-0000-0000-000000000000}\r\n\tAccesses:\t\tREAD_CONTROL\r\n\t\t\t\tSYNCHRONIZE\r\n\t\t\t\tReadData (or ListDirectory)\r\n\t\t\t\tReadEA\r\n\t\t\t\tReadAttributes\r\n\t\t\t\t\r\n\tAccess Reasons:\t\tREAD_CONTROL:\tGranted by\tD:(A;;0x1200a9;;;BA)\r\n\t\t\t\tSYNCHRONIZE:\tGranted by\tD:(A;;0x1200a9;;;BA)\r\n\t\t\t\tReadData (or ListDirectory):\tGranted by\tD:(A;;0x1200a9;;;BA)\r\n\t\t\t\tReadEA:\tGranted by\tD:(A;;0x1200a9;;;BA)\r\n\t\t\t\tReadAttributes:\tGranted by\tD:(A;;0x1200a9;;;BA)\r\n\t\t\t\t\r\n\tAccess Mask:\t\t0x120089\r\n\tPrivileges Used for Access Check:\t-\r\n\tRestricted SID Count:\t0"

System information

Microsoft Windows Server 2022 Standard - 10.0.20348 N/A Build 20348

Software version

alloy, version v1.1.1 (branch: HEAD, revision: 2687a2d)

Configuration

No response

Logs

No response

[MvrckTheBald]

same here. Up

[axiomen]

Same setup, same problem. Any help/news on this?

[matm-dec]

Again same setup, same problem!

[StefanSa]

Hi there,
i also have the same problem with the latest alloy version.
Can someone please address this problem, it's been six months and the function would be important.

Thanks for the help

[Nachtfalkeaw]

I found the Same issue and openwd a separate Ticket before i found this.

grafana/loki#15093

[wildum]

Hello, thanks for reporting this bug. What's happening is that the eventlogmessage stage is expecting the windows message to contain a list of key-value pairs split by new lines. This is incorrect because windows messages sometimes contain empty lines or lines that don't have ":" (https://learn.microsoft.com/en-us/previous-versions/windows/desktop/bb226812(v=vs.85)#message-format).

As a result, it logs a warning for every line that's not a key-value pair. The other lines are properly extracted and can be used by the other stages (for example the stage.labels if you want to have some of the values as labels). There is a trick here though: the non-alphabetical characters are transformed into "_" and that counts for "\t" as well. So if you have "\tSecurity ID", you can get it as "SecurityID" label with:

stage.labels {
    values = {
      SecurityID  = "_Security_ID",         
    }
}

This is definitely not ideal + the info that's not formatted as key-value is lost (and the key-value pairs that have values on several lines are truncated).

This stage definitely needs some improvements. I suggest that we should first change the log level from Warn to Debug.
Then we should improve the parser

[Elpatii]

Hello @wildum, thanks for taking a look.
We should change the log level to debug on Windows and give logs here?

[wildum]

No, I'm changing the internal Alloy logs from "Warn" to "Debug" to avoid unnecessary spam. I created the PR here: #2336. This way you won't get spammed by useless warnings anymore.

The next step will be to improve the parser, here is the ticket: #2337