Winlogbeat messages pipeline yields wrong timezone

Hello everyone,

I have a pipeline for incoming messages, that adds a field “hour” to each message, so that I can easily filter messages that arrived out of business hours. Unfortunately, this pipeline works differently for messages that arrive through winlogbeat. For these messages the timezone UTC is assumed and the hour field is incorrectly set to UTC time. For all other incoming syslog messages, the correct timezone Europe/Berlin is assumed and hour is set correctly.

The pipeline rule looks like this:

// Tag messages with hour of day
// Check Yoda time for time functions https://www.joda.org/joda-time/

rule "Hour of day"
when
    has_field("timestamp")
then
    set_field("hour", to_long(to_date($message.timestamp).hourOfDay));
end

Message from winlogbeat with incorrect hour value:

 4f4290d1-44fa-11ef-8405-005056ad10dd

Timestamp
    2024-07-18 13:38:51.279
Received by
    Active Directory Events on 

     3eed53b1 / XXXXXXX
Stored in index
    graylog_366
Routed into streams

        All messages

beats_type
    winlogbeat
hour
    11
message
    An account was logged off.

    Subject:
    	Security ID:		S-1-5-21-XXXXX-1971
    	Account Name:		XXXXX
    	Account Domain:		XXXXX
    	Logon ID:		0x19046B6B

    Logon Type:			3

    This event is generated when a logon session is destroyed. It may be positively correlated with a logon event using the Logon ID value. Logon IDs are only unique between reboots on the same computer.
out_of_business_hours
    false
source
    XXXXXXXX
timestamp
    2024-07-18T11:38:51.279Z
weekend
    false

All other messages from sysloggers, etc.:

 89692a00-44fd-11ef-8405-005056ad10dd

Timestamp
    2024-07-18 14:01:59.454
Received by
    Syslog UDP on 

     3eed53b1 / XXXXXXX
Stored in index
    graylog_366
Routed into streams

        All messages

facility
    local4
facility_num
    20
hour
    14
level
    6
message
    XXXXXX sandboxd[2098480]: --> [context]zKq7AVICAgAAAP////8Jc2FuZGJveGQAAANZQWxpYnZtYWNvcmUuc28AAI4PNwCieicA0HsnAI4xKACwTCgAS9lJAYJ6AGxpYnB0aHJlYWQuc28uMAAC7y4PbGliYy5zby42AA==[/context]
out_of_business_hours
    false
source
    XXXXXX
timestamp
    2024-07-18T12:01:59.454Z
weekend
    false
  • OS Information:
Linux XXXXXX 5.15.0-116-generic #126-Ubuntu SMP Mon Jul 1 10:14:24 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux

XXX@XXX:~$ timedatectl
               Local time: Thu 2024-07-18 14:06:57 CEST
           Universal time: Thu 2024-07-18 12:06:57 UTC
                 RTC time: Thu 2024-07-18 12:06:57
                Time zone: Europe/Berlin (CEST, +0200)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no

XXX@XXX $ cat /etc/graylog/server/server.conf | grep zone
# The time zone setting of the root user. See http://www.joda.org/joda-time/timezones.html for a list of valid time zons.
#root_timezone = UTC
root_timezone = Europe/Berlin
  • Package Version:
XXX@XXX:~$ dpkg -l graylog-server
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name           Version      Architecture Description
+++-==============-============-============-=================================
ii  graylog-server 4.2.13-1     all          Graylog server
  • Service logs, configurations, and environment variables:

3. What steps have you already taken to try and solve the problem?

  • Changed timezone on server to UTC
  • Added locale to winlogbeat configuration
processors:
  - add_locale:
      format: abbreviation
  • Changed timezone in server.conf to UTC
  • Changed rule to include the timezone
set_field("hour", to_long(to_date($message.timestamp, "Europe/Berlin").hourOfDay));

Unfortunately, none of this helps. Can someone point me in the right direction and help me figure out why winlogbeat messages get handled differently by the pipeline rule?

Hey @al_ex

If all the other syslog messages have correct time zone then I would check the remote device sending the incorrect timestamp.

All these message using the same INPUT?

On your Web UI under Time Configuration do all your setting look the same?

Thanks, gsmith!

I’ve checked the Time configuration and it is correct and identical for all three instances (web UI, server, user).

They don’t use the same input. All “good” messages come from INPUT syslog. All “bad” messages come from Beats.

The remote devices have the correct timezone and the winlogbeat sidecar seems to have the correct timestamps in its log file:

2024-07-21T01:04:35.271+0200	INFO	beater/eventlogger.go:88	EventLog[Security] successfully published 1 events
2024-07-21T01:04:42.324+0200	INFO	beater/eventlogger.go:88	EventLog[Security] successfully published 3 events
2024-07-21T01:04:44.359+0200	INFO	beater/eventlogger.go:88	EventLog[Security] successfully published 8 events
2024-07-21T01:04:47.408+0200	INFO	beater/eventlogger.go:88	EventLog[Security] successfully published 17 events
2024-07-21T01:04:48.414+0200	INFO	beater/eventlogger.go:88	EventLog[Security] successfully published 1 events
2024-07-21T01:05:04.720+0200	INFO	[monitoring]	log/log.go:144	Non-zero metrics in the last 30s	{"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":371390,"time":{"ms":125}},"total":{"ticks":820077,"time":{"ms":234},"value":820077},"user":{"ticks":448687,"time":{"ms":109}}},"handles":{"open":206},"info":{"ephemeral_id":"aeeb0541-34d1-44c2-af05-3f7799366c76","uptime":{"ms":223320064}},"memstats":{"gc_next":12068208,"memory_alloc":6129072,"memory_total":82694664440,"rss":42196992},"runtime":{"goroutines":25}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":30,"active":0,"batches":5,"total":30},"read":{"bytes":30},"write":{"bytes":14470}},"pipeline":{"clients":3,"events":{"active":0,"published":29,"total":29},"queue":{"acked":30}}},"msg_file_cache":{"SecurityHits":29},"published_events":{"Security":30,"total":30}}}}
2024-07-21T01:05:06.480+0200	INFO	beater/eventlogger.go:88	EventLog[Security] successfully published 1 events

Hey @al_ex

That’s strange, by chance does your fields have a winlog prefix (i.e., winlog_) to each of them?

Perhaps try to disable it on the input? Just taking a guess im not sure why your have t timestamp issue.

image

Hey gsmith,

this option is turned off here. Some of the fields do have the winlogbeat_ prefix. Here are some time related fields:

Timestamp
    2024-07-23 11:16:53.718

hour
    9

beats_type
    winlogbeat

timestamp
    2024-07-23T09:16:53.718Z

winlogbeat_@metadata_version
    7.11.1

winlogbeat_@timestamp
    2024-07-23T09:16:53.718Z

winlogbeat_@timestamp
    2024-07-23T09:16:53.718Z

I don’t understand why my pipeline rule works for all other messages except the ones coming from winlogbeat. It should calculate the hour based on the $message.timestamp field:

rule "Hour of day"
when
    has_field("timestamp")
then
    set_field("hour", to_long(to_date($message.timestamp, "Europe/Berlin").hourOfDay));
end

Maybe I should be working on $message.winlogbeat_@timestamp?

Hey @al_ex

correct, your timestamp field is called “winlogbeat_@timestamp” if you remove the prefix it will go back to “timestamp” then it should work as expected.

Hey gsmith,

I am really grateful that you’re having a look into this with me, because I am stumped…

I just disabled the winlogbeat-prefixing, but it didn’t help. The timestamp on the message is good and correct (10:31), but @timestamp and @event_created has the UTC time and my calculated hour field is based on this - unfortunately.

 52c6c991-4a60-11ef-8405-005056ad10dd

Timestamp
    2024-07-25 10:31:40.913
Received by
    Active Directory Events on 

Stored in index
    graylog_369
Routed into streams

        All messages

@metadata_beat
    winlogbeat
@metadata_type
    _doc
@metadata_version
    7.11.1
@timestamp
    2024-07-25T08:31:40.913Z
agent_ephemeral_id
    aeeb0541-34d1-44c2-af05-3f7799366c76
agent_id
    ab0652b1-52fb-4a00-8cf5-93277612439b
agent_type
    winlogbeat
agent_version
    7.11.1
beats_type
    winlogbeat
ecs_version
    1.7.0
event_action
    Logon
event_code
    4624
event_created
    2024-07-25T08:31:42.777Z
hour
    8

Hey @al_ex

Ah I see now. you may need to use another pipeline to convert that timestamp field you want then have your other pipe after it.

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