Vector: Humio fails to recognize time zone

[binarylogic]

A user is reporting that the humio_logs sink is failing to recognize timestamp time zones. This was working on 0.8.2 but is being reported as broken in 0.9.1. I have test logs that I can share privately. Their config is as follows:

data_dir = "/home/vector"
[sources.syslog]
  type = "syslog" # required
  address = "0.0.0.0:514" # required, required when mode = "tcp" or mode = "udp"
  mode = "udp" # required
[sinks.humio]
  # REQUIRED - General
  inputs       = ["haproxy_response_headers_transform_grok"]
  type         = "humio_logs"        # must be: "humio_logs"
  token        = "REDACTED"
  host         = "https://cloud.humio.com"
  # OPTIONAL - General
  healthcheck  = true # default
  # Batch
  batch.max_size = 20980000 # bytes
  batch.timeout_secs = 10 # seconds
  # Buffer if type=memory
  buffer.type = "memory" # default
  buffer.max_events = 5000000 # events, required when type = "memory"
  buffer.when_full = "block" # default
  # Request
  request.in_flight_limit = 100 # requests
  request.rate_limit_duration_secs = 1 # seconds
  request.rate_limit_num = 150000 # default is 10
  request.retry_initial_backoff_secs = 1 # seconds
  request.retry_max_duration_secs = 10 # seconds
  request.timeout_secs = 600 # seconds
[transforms.haproxy_response_headers_transform_grok]
  # REQUIRED - General
  type = "grok_parser" # must be: "grok_parser"
  inputs = ["haproxy_transform"] # source id
  pattern = "%{DATA:response_header_content_type}[|]%{GREEDYDATA:response_header_x_client}"
  # OPTIONAL - General
  drop_field = false
  field      = "captured_response_headers"
[transforms.haproxy_transform]
  # REQUIRED - General
  type = "grok_parser" # must be: "grok_parser"
  inputs = ["haproxytcp_transform"] # source id
  pattern = '%{HAPROXYHTTPBASE}'  # vector comes with these patterns: https://github.com/daschl/grok/tree/master/patterns
  # OPTIONAL - General
  drop_field = true      # default
  field      = "message" # default
[transforms.haproxytcp_transform]
  # REQUIRED - General
  type = "grok_parser" # must be: "grok_parser"
  inputs = ["syslog"] # source id
  pattern = '%{IP:client_ip}:%{INT:client_port} \[%{HAPROXYDATE:accept_date}\] %{NOTSPACE:frontend_name} %{NOTSPACE:backend_name}/%{NOTSPACE:server_name} %{INT:time_queue}/%{INT:time_backend_connect}/%{NOTSPACE:time_duration} %{NOTSPACE:bytes_read} %{NOTSPACE:termination_state} %{INT:actconn}/%{INT:feconn}/%{INT:beconn}/%{INT:srvconn}/%{NOTSPACE:retries} %{INT:srv_queue}/%{INT:backend_queue}'
  # OPTIONAL - General
  drop_field = true      # default
  field      = "message" # default

We need to set up a test Humio account and verify that data is being ingested properly. Again, I have test data that I can share privately.

[binarylogic]

Noting, we need to manually test this against a real Humio account.

[bruceg]

FTR I had asked for clarification on the context of the test data, as I am unclear how it was generated (and so how to feed them back into vector) but have not received a response.

[jszwedko]

I made a preliminary investigation into this but I'm not sure I discovered the exact issue the user is facing.

To test, I followed the guide to run humio as a docker container and started with vector at v0.8.2 which was mentioned was running correctly.

I slimmed the config down to (v0.8.2-style):

[sources.in]
  type = "syslog"
  address = "0.0.0.0:11514"
  mode = "udp"

[sinks.out]
  inputs = ["in"]
  type = "console"
  encoding = "json"

[sinks.humio]
  inputs       = ["in"]
  type         = "humio_logs"
  token        = "REDACTED"
  host         = "http://localhost:8080"
  healthcheck  = true

The sample data provided, out-of-band, appeared to be syslog messages in RFC3164 format without the year.

One issue, probably unrelated, that I found that it appears to always parse the timestamp in UTC regardless of the system timezone which results in some funkiness if we assume the syslog forwarder is not in UTC. This appears to be due to the syslog_loose crate that we use:

https://github.com/FungusHumungus/syslog-loose/blob/3cbcc82efacf09df1dfb565848a88f254b2edc5e/src/timestamp.rs#L84-L92

I think a possible things we may want to do here would be:

• Parse timestamps in the system timezone if there is no timezone specifier
• Allow the user to specify a timezone to use if there is no timezone specifier; either globally or for a specific source

I was able to manifest this issue by setting my local timezone to ET and running:

echo 'Hello world' | logger -n 127.0.0.1 -d -P 11514 --rfc3164

With my local time:

$ date
Mon Jul 27 16:30:53 EDT 2020

This resulted in:

{"appname":"CORP\\jesse","facility":"user","host":"a-8cktst39ij0a","message":"Hello world 103","severity":"notice","source_type":"syslog","timestamp":"2020-07-27T16:30:53Z"}

Printed to the stdout sink. We can see there that it interpreted my local time as UTC.

This resulted in a message in Humio that the event I sent had a timestamp in the future (i.e. 4 hours in the future) and so was just reset to "now":

@error_msg timestamp was set to a value in the future. Setting it to now

The message sent to Humio looks like (collected by pointing the humio sink at nc -l):

POST /services/collector/event HTTP/1.1
content-type: application/json
authorization: Splunk REDACTED
host: localhost:8081
transfer-encoding: chunked

{"event":{"appname":"CORP\\jesse","facility":"user","host":"a-8cktst39ij0a","message":"Hello world 104","severity":"notice"},"fields":{},"time":1595868535}

I saw similar behavior with 0.9.1, using the updated config of:

[sources.in]
  type = "syslog"
  address = "0.0.0.0:11514"
  mode = "udp"

[sinks.out]
  inputs = ["in"]
  type = "console"
  encoding.codec = "json"

[sinks.humio]
  inputs       = ["in"]
  type         = "humio_logs"
  token        = "REDACTED"
  host         = "http://localhost:8080"
  healthcheck  = true # default

With 0.10.0, I ended up with an error from humio about parsing the timestamp:

@error_msg Error parsing timestamp. errormsg="Text '{"appname":"CORP\\jesse","facility":"user","host":"a-8cktst39ij0...' could not be parsed at index 0" zone="None" | timestamp was not set to a value after 1971. Setting it to now

I'm assuming this is the issue referred to by https://github.com/timberio/vector/issues/3082 as the message being sent to humio looks like:

POST /services/collector/event HTTP/1.1
content-type: application/json
authorization: Splunk REDACTED
user-agent: Vector/0.10.0 (v0.10.0 x86_64-unknown-linux-gnu 2020-07-27)
host: localhost:8081
content-length: 319

{"event":{"appname":"CORP\\jesse","facility":"user","host":"a-8cktst39ij0a","hostname":"a-8cktst39ij0a","message":"Hello world 105","severity":"notice","source_ip":"127.0.0.1:45296","source_type":"syslog","timeQuality":{"isSynced":"0","tzKnown":"1"},"version":1},"fields":{},"sourcetype":"syslog","time": 1595882540.555}

A possible issue here is that we do not send the timezone field to humio (which is the "timezone" field in the Splunk HEC format); however, it doesn't _seem_ like it should matter since all of our internal timestamps are in UTC and it defaults to UTC.

To summarize, I don't think I was able to exactly replicate the issue described here, but have found a couple of opportunities for improvement:

• Consider parsing timestamps in the system timezone if there is no timezone specifier (for syslog and any other places this might crop up like the coerce transform)
• Consider allowing the user to specify a timezone to use if there is no timezone specifier; either globally or for a specific source
• Send the timezone as part of the Splunk HEC. This will always be UTC for now, but could change if we encode the time internally to preserve its timestamp
• Consider maintaining the timezone of timestamp specifiers internally rather than converting to UTC so that they can be forwarded to sinks with their original timezone

And we do need to fix the issue with millisecond timestamps. We _appear_ to be sending it correctly according to https://docs.humio.com/integrations/data-shippers/hec/ but will need to verify further.

[jszwedko]

Actually, I do see in https://github.com/timberio/vector/issues/2568#issuecomment-659354566 that they were also getting "timestamp was set to a value in the future" which might indicate that their messages were encoded without a timezone (for example by RFC3164 syslog messages that don't have a timezone) but were encoded in a timezone that wasn't UTC. Would you be able to confirm that @msemik or @geekflyer ?

[geekflyer]

haven't ready through this entire thread, but I can say that currently I'm running successfully 0.9.0 on k8s with Humio. It has the limitation that timestamps being sent to humio only have second precision, but in 0.9.1 the timestamp encoding of the humio sink is completely broken. It should be fixed with https://github.com/timberio/vector/issues/2568#issuecomment-659354566 (with millisecond precision) which should be part of 0.9.2 or 0.10.0.

TLDR @binarylogic : plz tell the user to upgrade to 0.9.2 or 0.10.0 and then try again.

Also I'm happy to upgrade to 0.10++ once the new k8s integration landed (currently relying on the experimental 0.9.0 implementation).

[binarylogic]

Thanks @jszwedko and @geekflyer.

Consider parsing timestamps in the system timezone if there is no timezone specifier (for syslog and any other places this might crop up like the coerce transform)

@bruceg I thought you worked on this previously? I assume the recent changes to the syslog source regressed this behavior?

Consider allowing the user to specify a timezone to use if there is no timezone specifier; either globally or for a specific source

Agree, I like this.

Send the timezone as part of the Splunk HEC. This will always be UTC for now, but could change if we encode the time internally to preserve its timestamp

👍

Consider maintaining the timezone of timestamp specifiers internally rather than converting to UTC so that they can be forwarded to sinks with their original timezone

I'm curious if the changes in https://github.com/timberio/vector-product/issues/8 would help with this? Or, if metadata would help? We could preserve the original timestamp while maintaining a parsed, normalized version in the metadata.

[bruceg]

@bruceg I thought you worked on this previously? I assume the recent changes to the syslog source regressed this behavior?

My work was with timestamp parsing in type coercion in transforms, which isn't directly applicable here.

[jszwedko]

I'm curious if the changes in timberio/vector-product#8 would help with this? Or, if metadata would help? We could preserve the original timestamp while maintaining a parsed, normalized version in the metadata.

I'm lacking context on what we intend by reapproaching the data model is motivated by, but this feels like a smaller change. We already represent timestamps internally as structured types by parsing them, we just normalize them all to UTC. The change I'm suggesting would be to represent them internally with the timezone they were parsed with.

I realize I typo'd too, edit:

Send the timezone as part of the Splunk HEC. This will always be UTC for now, but could change if we encode the time internally to preserve its ~timestamp~ timezone

[jszwedko]

Closing this in-lieu of:

• Use the system timezone when parsing timezoneless times in the syslog source #3234
• Allow user to specify default/fallback timezone for fallback situations #3235
• Send timezone of timestamps to Humio #3332
• Encode timezone of parsed timestamps #3333