windows_events are not being sent to loki by promtail 2.3.0

[jantari]

Describe the bug
This has been hard for me to debug, which is why I'm coming here but:

After initially setting up promtail 2.3.0 on a Windows Server 2019 with the following config:

Details

clients:
- url: http://internal-loki:3100/loki/api/v1/push
positions:
  filename: 'C:\ProgramData\promtail\positions.yml'
scrape_configs:
- job_name: windows
  windows_events:
    bookmark_path: 'C:\ProgramData\promtail\event_bookmark_system.xml'
    eventlog_name: System
    locale: 1033
    use_incoming_timestamp: true
    xpath_query: '*'
- job_name: windows
  windows_events:
    bookmark_path: 'C:\ProgramData\promtail\event_bookmark_application.xml'
    eventlog_name: Application
    locale: 1033
    use_incoming_timestamp: true
    xpath_query: '*'
server:
  http_listen_port: 9080
  log_level: info

it worked for a very brief time (a few hours). This was ~3 weeks ago and since then I haven't been able to forward any more windows_events to loki.

• When I run .\promtail-windows-amd64.exe --config.file="C:\ProgramData\promtail\config.yml" --log.level=debug --dry-run --inspect I can see the windows events being captured, so promtail definitely sees them.
• When I run cat .\file.txt | .\promtail-windows-amd64.exe --stdin --config.file="C:\ProgramData\promtail\config.yml" --client.external-labels=test=yes the data immediately shows up in loki so there is no network or firewall problem. In fact the loki server and the windows server are on the same network, the only "complication" is that loki is running in docker, is connected to a docker network and port 3100 is mapped to the docker host
• I can see with sudo tcpdump -i any 'port 3100' on the loki server that there are packets coming from and to my Windows Server. Quite a few have 0 byte length but there are also packets containing data (usually between 600 and 1500 bytes)
• The promtail logfile on the Windows Server is absolutely empty, after the initial msg="Starting Promtail" there is no more entries.
• The loki logs don't contain anything directly related to this promtail client or the server it's on - mostly just table index messages

To Reproduce
I don't have a surefire way to reproduce unfortunately.
Basically:

1. Run promtail 2.3.0 on a Windows Server 2019 with the config I posted above
2. Observe logs possibly coming into loki (e.g. through grafana explore tab)
3. Wait a day, maybe reboot the windows server, maybe stop and start the promtail process a few times
4. Cross fingers?
5. Get into the state I have where no logs are being seen by loki. It can't be that rare because I have this on three servers now, the time for which it works never lasts long

Expected behavior
The windows event logs should be sent to loki and visible in grafanas explore tab.

Environment:

• Infrastructure:
  • loki and grafana docker containers on a Ubuntu 20.04.3 LTS host
  • promtail windows binary running on Windows Server 2019 Core ( Build 10.0.17763.2114 )
• Deployment tool: ansible for both, mostly internal roles

Screenshots, Promtail config, or terminal output
Logs being seen when dry-running:

Details

PS C:\Program Files\promtail> .\promtail-windows-amd64.exe --config.file="C:\ProgramData\promtail\config.yml" --log.level=debug --dry-run --inspect
Clients configured:
----------------------
url: http://internal-loki:3100/loki/api/v1/push
batchwait: 1s
batchsize: 1048576
follow_redirects: false
backoff_config:
  min_period: 500ms
  max_period: 5m0s
  max_retries: 10
timeout: 10s
tenant_id: ""

level=debug ts=2021-09-09T13:39:06.8490364Z caller=win_eventlog.go:397 msg="Subcribed with handle id" id=2
level=info ts=2021-09-09T13:39:06.8501032Z caller=server.go:239 http=[::]:9080 grpc=[::]:9095 msg="server listening on addresses"
level=info ts=2021-09-09T13:39:06.8506555Z caller=main.go:119 msg="Starting Promtail" version="(version=, branch=, revision=)"
2021-09-09T15:39:06.8527463+0200{channel="System", computer="server-with-promtail.domain.local"}{"source":"Service Control Manager","channel":"System","computer":"server-with-promtail.domain.local","event_id":7036,"level":4,"levelText":"Information","keywords":"Classic","timeCreated":"2021-09-09T13:22:48.502237200Z","eventRecordID":210902,"execution":{"processId":664,"threadId":10056,"processName":"services.exe"},"user_data":"\u003cData Name='param1'\u003eNetwork Setup Service\u003c/Data\u003e\u003cData Name='param2'\u003erunning\u003c/Data\u003e\u003cBinary\u003e4E0065007400530065007400750070005300760063002F0034000000\u003c/Binary\u003e","event_data":"\u003cData Name='param1'\u003eNetwork Setup Service\u003c/Data\u003e\u003cData Name='param2'\u003erunning\u003c/Data\u003e\u003cBinary\u003e4E0065007400530065007400750070005300760063002F0034000000\u003c/Binary\u003e","message":"The Network Setup Service service entered the running state."}
2021-09-09T15:39:06.8563497+0200{channel="System", computer="server-with-promtail.domain.local"}{"source":"Service Control Manager","channel":"System","computer":"server-with-promtail.domain.local","event_id":7036,"level":4,"levelText":"Information","keywords":"Classic","timeCreated":"2021-09-09T13:25:22.327619200Z","eventRecordID":210903,"execution":{"processId":664,"threadId":9460,"processName":"services.exe"},"user_data":"\u003cData Name='param1'\u003eBackground Intelligent Transfer Service\u003c/Data\u003e\u003cData Name='param2'\u003erunning\u003c/Data\u003e\u003cBinary\u003e42004900540053002F0034000000\u003c/Binary\u003e","event_data":"\u003cData Name='param1'\u003eBackground Intelligent Transfer Service\u003c/Data\u003e\u003cData Name='param2'\u003erunning\u003c/Data\u003e\u003cBinary\u003e42004900540053002F0034000000\u003c/Binary\u003e","message":"The Background Intelligent Transfer Service service entered the running state."}
2021-09-09T15:39:06.8563497+0200{channel="System", computer="server-with-promtail.domain.local"}{"source":"Service Control Manager","channel":"System","computer":"server-with-promtail.domain.local","event_id":7036,"level":4,"levelText":"Information","keywords":"Classic","timeCreated":"2021-09-09T13:25:23.140121500Z","eventRecordID":210904,"execution":{"processId":664,"threadId":10056,"processName":"services.exe"},"user_data":"\u003cData Name='param1'\u003eWMI Performance Adapter\u003c/Data\u003e\u003cData Name='param2'\u003erunning\u003c/Data\u003e\u003cBinary\u003e77006D006900410070005300720076002F0034000000\u003c/Binary\u003e","event_data":"\u003cData Name='param1'\u003eWMI Performance Adapter\u003c/Data\u003e\u003cData Name='param2'\u003erunning\u003c/Data\u003e\u003cBinary\u003e77006D006900410070005300720076002F0034000000\u003c/Binary\u003e","message":"The WMI Performance Adapter service entered the running state."}
2021-09-09T15:39:06.8593804+0200{channel="System", computer="server-with-promtail.domain.local"}{"source":"Service Control Manager","channel":"System","computer":"server-with-promtail.domain.local","event_id":7036,"level":4,"levelText":"Information","keywords":"Classic","timeCreated":"2021-09-09T13:27:23.631492800Z","eventRecordID":210905,"execution":{"processId":664,"threadId":7748,"processName":"services.exe"},"user_data":"\u003cData Name='param1'\u003eWMI Performance Adapter\u003c/Data\u003e\u003cData Name='param2'\u003estopped\u003c/Data\u003e\u003cBinary\u003e77006D006900410070005300720076002F0031000000\u003c/Binary\u003e","event_data":"\u003cData Name='param1'\u003eWMI Performance Adapter\u003c/Data\u003e\u003cData Name='param2'\u003estopped\u003c/Data\u003e\u003cBinary\u003e77006D006900410070005300720076002F0031000000\u003c/Binary\u003e","message":"The WMI Performance Adapter service entered the stopped state."}
[... more logs cut for brevity ...]

Data coming in example when piping from stdin:

Details

PS C:\Program Files\promtail> echo "Hello from promtail!" | .\promtail-windows-amd64.exe --stdin --config.file="C:\ProgramData\promtail\config.yml" --client.external-labels=test=yes
level=info ts=2021-09-09T13:43:44.4766404Z caller=server.go:239 http=[::]:9080 grpc=[::]:9095 msg="server listening on addresses"
level=info ts=2021-09-09T13:43:44.4766404Z caller=main.go:119 msg="Starting Promtail" version="(version=, branch=, revision=)"
PS C:\Program Files\promtail>

---

I realize this may not be much to go on and I'm sorry for that, but the logs just didn't give me much to work with. I will gather any additional information I can to assist in resolving this - we really want to use promtail for windows events.

Thank you!

[jantari]

Further information: I have noticed after just letting promtail run in this non-functional state for a few days that I also get the following log entry (stderr) around once every two hours to four times per hour:

caller=client.go:344 component=client host=internal-loki:3100 msg="error sending batch, will retry" status=-1 error="Post \"http://internal-loki:3100/loki/api/v1/push\": EOF"

I tried googling the EOF error but didn't find anything really. Because this error comes up only once every ~15-120 minutes, I feel like it might be normal? EOF because there's no data to send at that moment? If this was my underlying issue I feel like this would be logged every 1 or 10 seconds due to the default retry behavior.

[stale]

Hi! This issue has been automatically marked as stale because it has not had any
activity in the past 30 days.

We use a stalebot among other tools to help manage the state of issues in this project.
A stalebot can be very useful in closing issues in a number of cases; the most common
is closing issues or PRs where the original reporter has not responded.

Stalebots are also emotionless and cruel and can close issues which are still very relevant.

If this issue is important to you, please add a comment to keep it open. More importantly, please add a thumbs-up to the original issue entry.

We regularly sort for closed issues which have a stale label sorted by thumbs up.

We may also:

• Mark issues as revivable if we think it's a valid issue but isn't something we are likely
  to prioritize in the future (the issue will still remain closed).
• Add a keepalive label to silence the stalebot if the issue is very common/popular/important.

We are doing our best to respond, organize, and prioritize all issues but it can be a challenging task,
our sincere apologies if you find yourself at the mercy of the stalebot.