"Unknown beats protocol version: 3" using winlogbeat v5.1.1


(João Ciocca) #1

So, at first I thought I found an existing topic with my problem, while looking only at the logbeat side. But then I found another that took me to the Internal Log plugin and this “version: 3” error came up, so I decided to start a new thread. Sorry if I should have kept to that topic.

I’m new to Graylog, still trying to figure out how it works and how to make it work - so far, only errors trying logbeat with sysmon :cry:

Anyway - this was new. After installing the internal log plugin and starting the sidecar again, I found this error which I couldn’t see before: graylog was complaining about beats protocol version. I’m using the sidecar installer from Graylog_Sysmon at github, so I thought everything was already in order.

In any case, I decided to check on winlogbeat.exe version, and it says winlogbeat version 5.1.1 (amd64), libbeat 5.1.1 - and not “3” as the log points out. Any ideas I could try to solve this?

Just noticed that there’s another version of the error… but this one is even weirder:

Version 22?!


(Jan Doberstein) #2

hej @joaociocca

what Sidecar Version did you install and what Graylog version are you running?

regards
Jan


(João Ciocca) #3

Sidecar 0.1.0-rc.1 (b400a83) and Graylog 2.2.3-1 OVA.


(Jan Doberstein) #4

hej @joaociocca

you should update to the latest Version and your bug should be gone.


(João Ciocca) #5

Sidecar was installed using


And I tried updating graylog via omnibus, but still errors.

@jan could you ellaborate that?


(Jan Doberstein) #6

the batch file installed an old outdated version of the collector sidecar.

Download and install the current (latest) release direct from github.

Your Graylog is the current latest stable Version already. No need to update.


(João Ciocca) #7

Ok, seems to be working now… but there are still some weird errors on sidecar starting:

time="2017-06-08T12:30:36-03:00" level=debug msg="Add collector backend: winlogbeat" 
time="2017-06-08T12:30:36-03:00" level=info msg="Starting signal distributor" 
time="2017-06-08T12:30:36-03:00" level=debug msg="[signal-processor] (seq=1) handling cmd: restart" 
time="2017-06-08T12:30:36-03:00" level=info msg="[winlogbeat] Starting (exec driver)" 
time="2017-06-08T12:30:36-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:36-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:36-03:00" level=debug msg="[signal-processor] (seq=1) cmd done: restart" 
time="2017-06-08T12:30:37-03:00" level=error msg="[winlogbeat] Backend finished unexpectedly, trying to restart 1/3." 
time="2017-06-08T12:30:37-03:00" level=debug msg="[signal-processor] (seq=2) handling cmd: restart" 
time="2017-06-08T12:30:37-03:00" level=info msg="[winlogbeat] Stopping" 
time="2017-06-08T12:30:39-03:00" level=debug msg="[winlogbeat] SIGHUP ignored, killing process" 
time="2017-06-08T12:30:39-03:00" level=debug msg="[winlogbeat] Failed to kill process invalid argument" 
time="2017-06-08T12:30:39-03:00" level=info msg="[winlogbeat] Starting (exec driver)" 
time="2017-06-08T12:30:39-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:39-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:39-03:00" level=debug msg="[signal-processor] (seq=2) cmd done: restart" 
time="2017-06-08T12:30:40-03:00" level=error msg="[winlogbeat] Backend finished unexpectedly, trying to restart 2/3." 
time="2017-06-08T12:30:40-03:00" level=debug msg="[signal-processor] (seq=3) handling cmd: restart" 
time="2017-06-08T12:30:40-03:00" level=info msg="[winlogbeat] Stopping" 
time="2017-06-08T12:30:42-03:00" level=debug msg="[winlogbeat] SIGHUP ignored, killing process" 
time="2017-06-08T12:30:42-03:00" level=debug msg="[winlogbeat] Failed to kill process invalid argument" 
time="2017-06-08T12:30:42-03:00" level=info msg="[winlogbeat] Starting (exec driver)" 
time="2017-06-08T12:30:42-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:42-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:42-03:00" level=debug msg="[signal-processor] (seq=3) cmd done: restart" 
time="2017-06-08T12:30:43-03:00" level=error msg="[winlogbeat] Backend finished unexpectedly, trying to restart 3/3." 
time="2017-06-08T12:30:43-03:00" level=debug msg="[signal-processor] (seq=4) handling cmd: restart" 
time="2017-06-08T12:30:43-03:00" level=info msg="[winlogbeat] Stopping" 
time="2017-06-08T12:30:45-03:00" level=debug msg="[winlogbeat] SIGHUP ignored, killing process" 
time="2017-06-08T12:30:45-03:00" level=debug msg="[winlogbeat] Failed to kill process invalid argument" 
time="2017-06-08T12:30:45-03:00" level=info msg="[winlogbeat] Starting (exec driver)" 
time="2017-06-08T12:30:45-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:45-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:45-03:00" level=debug msg="[signal-processor] (seq=4) cmd done: restart" 
time="2017-06-08T12:30:46-03:00" level=error msg="[winlogbeat] Unable to start collector after 3 tries, giving up!" 
time="2017-06-08T12:30:49-03:00" level=info msg="[winlogbeat] Configuration change detected, rewriting configuration file." 
time="2017-06-08T12:30:49-03:00" level=debug msg="[signal-processor] (seq=5) handling cmd: restart" 
time="2017-06-08T12:30:49-03:00" level=info msg="[winlogbeat] Stopping" 
time="2017-06-08T12:30:51-03:00" level=debug msg="[winlogbeat] SIGHUP ignored, killing process" 
time="2017-06-08T12:30:51-03:00" level=debug msg="[winlogbeat] Failed to kill process invalid argument" 
time="2017-06-08T12:30:51-03:00" level=info msg="[winlogbeat] Starting (exec driver)" 
time="2017-06-08T12:30:51-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:51-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:51-03:00" level=debug msg="[signal-processor] (seq=5) cmd done: restart" 
time="2017-06-08T12:30:59-03:00" level=debug msg="[RequestConfiguration] No configuration update available, skipping update." 
time="2017-06-08T12:31:09-03:00" level=debug msg="[RequestConfiguration] No configuration update available, skipping update." 
time="2017-06-08T12:31:19-03:00" level=debug msg="[RequestConfiguration] No configuration update available, skipping update."

(Jan Doberstein) #8

you need to create a configuration and add a tag - then this error will be gone.


(João Ciocca) #9

but I’ve done that, @jan! as I mentioned, the collector was configured… and it worked in the end - when the debug goes

[RequestConfiguration] No configuration update available, skipping update.

after this piece of log, the collector shows up on Graylog and logs are being received nicely… but those errors on the top still show up. Anyway, I’ll double check this tomorrow at work to make sure.

Next step - make a installer similar to the one at https://github.com/ion-storm/Graylog_Sysmon/tree/master/Installers which retrieves the latest sidecar from https://github.com/Graylog2/collector-sidecar/releases so I don’t have those problems anymore and start cracking at the real work!

Thanks anyway, @jan! =D


(Jan Doberstein) #10

Hej @joaociocca

sorry mis-read - that line is not an error. Just the notice that no update of the configuration need to be written or requested from the Graylog Server.


(João Ciocca) #11

no problem, happens in the best of families =p but this is the part that worries me:

time="2017-06-08T12:30:36-03:00" level=debug msg="[signal-processor] (seq=1) handling cmd: restart" 
time="2017-06-08T12:30:36-03:00" level=info msg="[winlogbeat] Starting (exec driver)" 
time="2017-06-08T12:30:36-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:36-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:36-03:00" level=debug msg="[signal-processor] (seq=1) cmd done: restart" 
time="2017-06-08T12:30:37-03:00" level=error msg="[winlogbeat] Backend finished unexpectedly, trying to restart 1/3." 
time="2017-06-08T12:30:37-03:00" level=debug msg="[signal-processor] (seq=2) handling cmd: restart" 
time="2017-06-08T12:30:37-03:00" level=info msg="[winlogbeat] Stopping" 
time="2017-06-08T12:30:39-03:00" level=debug msg="[winlogbeat] SIGHUP ignored, killing process" 
time="2017-06-08T12:30:39-03:00" level=debug msg="[winlogbeat] Failed to kill process invalid argument" 
time="2017-06-08T12:30:39-03:00" level=info msg="[winlogbeat] Starting (exec driver)" 
time="2017-06-08T12:30:39-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:39-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:39-03:00" level=debug msg="[signal-processor] (seq=2) cmd done: restart" 
time="2017-06-08T12:30:40-03:00" level=error msg="[winlogbeat] Backend finished unexpectedly, trying to restart 2/3." 
time="2017-06-08T12:30:40-03:00" level=debug msg="[signal-processor] (seq=3) handling cmd: restart" 
time="2017-06-08T12:30:40-03:00" level=info msg="[winlogbeat] Stopping" 
time="2017-06-08T12:30:42-03:00" level=debug msg="[winlogbeat] SIGHUP ignored, killing process" 
time="2017-06-08T12:30:42-03:00" level=debug msg="[winlogbeat] Failed to kill process invalid argument" 
time="2017-06-08T12:30:42-03:00" level=info msg="[winlogbeat] Starting (exec driver)" 
time="2017-06-08T12:30:42-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:42-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:42-03:00" level=debug msg="[signal-processor] (seq=3) cmd done: restart" 
time="2017-06-08T12:30:43-03:00" level=error msg="[winlogbeat] Backend finished unexpectedly, trying to restart 3/3." 
time="2017-06-08T12:30:43-03:00" level=debug msg="[signal-processor] (seq=4) handling cmd: restart" 
time="2017-06-08T12:30:43-03:00" level=info msg="[winlogbeat] Stopping" 
time="2017-06-08T12:30:45-03:00" level=debug msg="[winlogbeat] SIGHUP ignored, killing process" 
time="2017-06-08T12:30:45-03:00" level=debug msg="[winlogbeat] Failed to kill process invalid argument" 
time="2017-06-08T12:30:45-03:00" level=info msg="[winlogbeat] Starting (exec driver)" 
time="2017-06-08T12:30:45-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:45-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:45-03:00" level=debug msg="[signal-processor] (seq=4) cmd done: restart" 
time="2017-06-08T12:30:46-03:00" level=error msg="[winlogbeat] Unable to start collector after 3 tries, giving up!"

(Jan Doberstein) #12

you should check the winlogbeat log file - something in the configuration is not well so the backend can’t be started.


(João Ciocca) #13

ok, let me review things here. Winlogbeat.log shows nothing. Hasn’t even been created.
I’m testing Graylog server on a VM IP 172.97.28.4 and Sidecar on two different machines: a windows VM running at 10.2.11.142 and a notebook that when I at cable on work runs at 10.2.16.60, but also connects at work via Wi-Fi and from home via VPN.

Both sidecars get this initial error messages:

time="2017-06-08T12:30:36-03:00" level=debug msg="[signal-processor] (seq=1) handling cmd: restart" 
time="2017-06-08T12:30:36-03:00" level=info msg="[winlogbeat] Starting (exec driver)" 
time="2017-06-08T12:30:36-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:36-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:36-03:00" level=debug msg="[signal-processor] (seq=1) cmd done: restart" 
time="2017-06-08T12:30:37-03:00" level=error msg="[winlogbeat] Backend finished unexpectedly, trying to restart 1/3." 
time="2017-06-08T12:30:37-03:00" level=debug msg="[signal-processor] (seq=2) handling cmd: restart" 
time="2017-06-08T12:30:37-03:00" level=info msg="[winlogbeat] Stopping" 
time="2017-06-08T12:30:39-03:00" level=debug msg="[winlogbeat] SIGHUP ignored, killing process" 
time="2017-06-08T12:30:39-03:00" level=debug msg="[winlogbeat] Failed to kill process invalid argument" 
time="2017-06-08T12:30:39-03:00" level=info msg="[winlogbeat] Starting (exec driver)" 
time="2017-06-08T12:30:39-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:39-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:39-03:00" level=debug msg="[signal-processor] (seq=2) cmd done: restart" 
time="2017-06-08T12:30:40-03:00" level=error msg="[winlogbeat] Backend finished unexpectedly, trying to restart 2/3." 
time="2017-06-08T12:30:40-03:00" level=debug msg="[signal-processor] (seq=3) handling cmd: restart" 
time="2017-06-08T12:30:40-03:00" level=info msg="[winlogbeat] Stopping" 
time="2017-06-08T12:30:42-03:00" level=debug msg="[winlogbeat] SIGHUP ignored, killing process" 
time="2017-06-08T12:30:42-03:00" level=debug msg="[winlogbeat] Failed to kill process invalid argument" 
time="2017-06-08T12:30:42-03:00" level=info msg="[winlogbeat] Starting (exec driver)" 
time="2017-06-08T12:30:42-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:42-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:42-03:00" level=debug msg="[signal-processor] (seq=3) cmd done: restart" 
time="2017-06-08T12:30:43-03:00" level=error msg="[winlogbeat] Backend finished unexpectedly, trying to restart 3/3." 
time="2017-06-08T12:30:43-03:00" level=debug msg="[signal-processor] (seq=4) handling cmd: restart" 
time="2017-06-08T12:30:43-03:00" level=info msg="[winlogbeat] Stopping" 
time="2017-06-08T12:30:45-03:00" level=debug msg="[winlogbeat] SIGHUP ignored, killing process" 
time="2017-06-08T12:30:45-03:00" level=debug msg="[winlogbeat] Failed to kill process invalid argument" 
time="2017-06-08T12:30:45-03:00" level=info msg="[winlogbeat] Starting (exec driver)" 
time="2017-06-08T12:30:45-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:45-03:00" level=debug msg="Creating rotated log writer for: C:\\Program Files\\graylog\\collector-sidecar\\logs\\winlogbeat_stderr.log.%Y%m%d%H%M" 
time="2017-06-08T12:30:45-03:00" level=debug msg="[signal-processor] (seq=4) cmd done: restart" 
time="2017-06-08T12:30:46-03:00" level=error msg="[winlogbeat] Unable to start collector after 3 tries, giving up!"

After the “giving up!” message, the Windows VM starts sending logs to Graylog, so we can see it showing up on Sources quick values graph:

This is where the scenario problems connects with my other post on the forum:

https://community.graylog.org/t/ova-not-listening-refusing-connection-on-443/?source_topic_id=1335

I was having this connection refusal problem on both machines. Followed documentation and created a self-signed certificate. Now, Windows VM is able to send logs (where before it couldn’t), but the Windows notebook is receiving a new error message:

time="2017-06-10T12:52:55-03:00" level=error msg="[RequestConfiguration] Fetching configuration failed: Get https://172.28.97.4:443/api/plugins/org.graylog.plugins.collector/281fbe5f-9222-4877-9b9d-00240350bc91?tags=%5B%22windows%22%2C%22desktop%22%5D: x509: certificate signed by unknown authority" 
time="2017-06-10T12:52:57-03:00" level=error msg="[UpdateRegistration] Failed to report collector status to server: Put https://172.28.97.4:443/api/plugins/org.graylog.plugins.collector/collectors/281fbe5f-9222-4877-9b9d-00240350bc91: x509: certificate signed by unknown authority" 

But both cases start with that same “error package”, saying the backend finished unexpectedly - even though the VM sidecar and winlogbeat backend are working.


OVA not listening/refusing connection on 443
(system) #14

This topic was automatically closed 14 days after the last reply. New replies are no longer allowed.