[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

[wildum]

Hey everyone, I'm working on a new stage "windowsevent" which covers the same functionality as the eventlogmessage stage but with a different parser to correct the flaws that were discovered via this ticket. Here is the PR: #2545

I don't have experience monitoring Windows machines at scale so I'm not sure which events are actually interesting and if the parsing is optimal for these events. If you do, I'd appreciate if you could share some feedback on the PR.

The stage will be released in the experimental state so we can do breaking changes even after the PR is merged if needed.

@jkroepke I don't know if you are using the eventlogmessage but since you are a Windows expert you might be interested in this new stage.

@kelnage you also might want to have a look at it since you were involved in this topic in Loki

[Elpatii]

Hi @wildum, thanks for your work! How can we access the Windows build from this PR to test it?

[jkroepke]

Hi @wildum,

no experience about event log.

[Nachtfalkeaw]

@Elpatii
#2545 (comment)

[Elpatii]

@Nachtfalkeaw, found the link in the PR, but I don't see any download link. Or I don't know how to use it correctly 😂