@timestamp field is not using UTC

OpenSearch
1

Running OpenSearch v 2.12.0

I have a syslog data stream and index setup with a mapping to add a @timestamp field with a date type. It seems like OpenSearch is using the timestamp in the message field to create the @timestamp field.

Here’s a sample of two docs that came in sequentially.

{
        "_index": ".ds-logs-cribl-syslog-000001",
        "_id": "ZSothzTRbULChLp2",
        "_score": null,
        "_source": {
            "message": "91: *Mar 27 20:50:17.851: %SEC_LOGIN-5-LOGIN_SUCCESS: Login Success [user: marty] [Source: 192.168.1.158] [localport: 22] at 20:50:17 UTC Wed Mar 27 2024",
            "severity": 5,
            "facility": 23,
            "host": {
                "name": "192.168.1.30"
            },
            "severityName": "notice",
            "facilityName": "local7",
            "_raw": "<189>91: *Mar 27 20:50:17.851: %SEC_LOGIN-5-LOGIN_SUCCESS: Login Success [user: marty] [Source: 192.168.1.158] [localport: 22] at 20:50:17 UTC Wed Mar 27 2024",
            "cribl_pipe": "open_search",
            "@timestamp": "2024-03-27T20:50:18.894Z"
        },
        "sort": [
            1711572618894
        ]
    },
    {
        "_index": ".ds-logs-cribl-syslog-000001",
        "_id": "DouIRY1HUNFe9bFH",
        "_score": null,
        "_source": {
            "message": "[LAN_LOCAL-default-A]IN=eth1 OUT= MAC=e0:63:da:54:ab:15:3a:1f:2b:0f:5c:69:08:00 SRC=192.168.1.6 DST=192.168.1.1 LEN=52 TOS=0x00 PREC=0x00 TTL=64 ID=28764 DF PROTO=TCP SPT=8080 DPT=41088 WINDOW=501 RES=0x00 ACK FIN URGP=0 ",
            "severity": 4,
            "facility": 0,
            "host": {
                "name": "ubnt"
            },
            "appname": "kernel",
            "severityName": "warning",
            "facilityName": "kern",
            "_raw": "<4>Mar 27 16:52:47 ubnt kernel: [LAN_LOCAL-default-A]IN=eth1 OUT= MAC=e0:63:da:54:ab:15:3a:1f:2b:0f:5c:69:08:00 SRC=192.168.1.6 DST=192.168.1.1 LEN=52 TOS=0x00 PREC=0x00 TTL=64 ID=28764 DF PROTO=TCP SPT=8080 DPT=41088 WINDOW=501 RES=0x00 ACK FIN URGP=0 ",
            "cribl_pipe": "open_search",
            "@timestamp": "2024-03-27T16:52:47.000Z"
        },
        "sort": [
            1711558367000
        ]
    }

Here is the mapping for this index:

{
    "mappings": {
        "_data_stream_timestamp": {
            "enabled": true
        },
        "properties": {
            "@timestamp": {
                "type": "date"
            },
            "_raw": {
                "type": "text",
                "fields": {
                    "keyword": {
                        "type": "keyword",
                        "ignore_above": 256
                    }
                }
            },
            "appname": {
                "type": "text",
                "fields": {
                    "keyword": {
                        "type": "keyword",
                        "ignore_above": 256
                    }
                }
            },
            "cribl_pipe": {
                "type": "text",
                "fields": {
                    "keyword": {
                        "type": "keyword",
                        "ignore_above": 256
                    }
                }
            },
            "facility": {
                "type": "long"
            },
            "facilityName": {
                "type": "text",
                "fields": {
                    "keyword": {
                        "type": "keyword",
                        "ignore_above": 256
                    }
                }
            },
            "host": {
                "properties": {
                    "name": {
                        "type": "text",
                        "fields": {
                            "keyword": {
                                "type": "keyword",
                                "ignore_above": 256
                            }
                        }
                    }
                }
            },
            "message": {
                "type": "text",
                "fields": {
                    "keyword": {
                        "type": "keyword",
                        "ignore_above": 256
                    }
                }
            },
            "procid": {
                "type": "text",
                "fields": {
                    "keyword": {
                        "type": "keyword",
                        "ignore_above": 256
                    }
                }
            },
            "severity": {
                "type": "long"
            },
            "severityName": {
                "type": "text",
                "fields": {
                    "keyword": {
                        "type": "keyword",
                        "ignore_above": 256
                    }
                }
            }
        }
    }
}

Is there a way to configure OpenSearch so that it always uses UTC for the @timestamp field?

Thanks

2

Hey @sloan58

By default OpenSearch uses UTC.

3

Hi, @Gsmitt. Thanks for the help. I should have been more specific in my initial question. Does OpenSearch use a UTC timestamp based on the OpenSearch system time at the point of ingestion? If it does, that’s not what I’m seeing with my cluster. The two messages I provided came in sequentially within the span of a minute or two, but have timestamps that are very different, and seem to be relative to the date time that is in the _raw field. This becomes more obvious when you search for these logs in OpenSearch Dashboards. If I use the “Last 15 Minutes” filter, some messages do not display because of the time difference.

What I’d like is for OpenSearch to insert the @timestamp field as the UTC time of the OpenSearch system at the time of ingestion. Do you know if that’s possible? If that’s already expected, what could be wrong in my cluster that’s causing it to use a relative @timestamp value?

Thanks

4

@sloan58 I understand you want to ingest logs with the timestamp of the logs and not the ingestion time. I’ve got this working with Logstash.

filter {
 grok {
     match => ["message" => "%{TIMESTAMP_ISO8601:timestamp} %{GREEDYDATA:rest_of_the_message}"]
       }
 date {
    match => ["timestamp", "ISO8601"]
    timezone => "UTC"
  }
}

You could also consider using an OpenSearch pipeline with that filter to avoid using logstash between your syslog and OpenSearch.

Regarding OpenSearch Dashboards timezone view, it is configured in Dashboards Management → Advanced Settings

image
image1243×171 14.6 KB

5

Hi, @pablo. Thanks so much for the help. I’m sorry if it wasn’t clear from my initial question, but I’m actually trying to accomplish the opposite. My logs are coming in with different timezone settings but I want the OpenSearch document to be the UTC timestamp of when it was ingested. If you look at the two docs that I posted initially, they came into the system minutes apart but have very different timestamps and I’m not sure why. I’d like for OpenSearch to use current system UTC time for the @timestamp field. Any idea why OpenSearch would not use the current UTC time for the @timestamp field? I haven’t (intentionally) modified anything to change that behavior.

Thanks for the tip on pipelines! I think those will be very useful indeed. After I get the basics wired up correctly, I’ll start to explore the processing capabilities through pipelines.

6

Just another quick example to perhaps help clarify. This document just hit my OpenSearch db. I’m in US Eastern timezone and the @timestamp field is set to that TZ instead of UTC

{
        "_index": ".ds-logs-cribl-syslog-000001",
        "_id": "K4TW0RXtjQZgiVVx",
        "_score": null,
        "_source": {
          "message": "[LAN_LOCAL-default-A]IN=eth1 OUT= MAC=e0:63:da:54:ab:15:3a:1f:2b:0f:5c:69:08:00 SRC=192.168.1.6 DST=192.168.1.1 LEN=52 TOS=0x00 PREC=0x00 TTL=64 ID=48579 DF PROTO=TCP SPT=8080 DPT=45008 WINDOW=501 RES=0x00 ACK FIN URGP=0 ",
          "severity": 4,
          "facility": 0,
          "host": {
            "name": "ubnt"
          },
          "appname": "kernel",
          "severityName": "warning",
          "facilityName": "kern",
          "_raw": "<4>Mar 28 09:23:56 ubnt kernel: [LAN_LOCAL-default-A]IN=eth1 OUT= MAC=e0:63:da:54:ab:15:3a:1f:2b:0f:5c:69:08:00 SRC=192.168.1.6 DST=192.168.1.1 LEN=52 TOS=0x00 PREC=0x00 TTL=64 ID=48579 DF PROTO=TCP SPT=8080 DPT=45008 WINDOW=501 RES=0x00 ACK FIN URGP=0 ",
          "cribl_pipe": "open_search",
          "@timestamp": "2024-03-28T09:23:56.000Z"
        },
        "sort": [
          1711617836000
        ]
      },

This is the query I’m using:

GET logs-cribl-syslog/_search
{
  "sort": {
    "@timestamp": "desc"
  }
}

And due to the difference, the Dashboards queries are off

image
image3546×616 135 KB

Thanks again.

7

Hey @sloan58

Think I understand what your look for.

Have you tried this?

Go to Dashboards Management → Advanced settings

Scroll down to you hit this section.

image
image1227×469 56 KB

8

Thanks, @Gsmitt. Yeah, I’ve tried that. I spent some time in the Chrome developer tools, toggling different settings for the Dashboards timezone setting and I can see that Dashboards is sending a request that specifies the timezone correctly based on the setting in Dashboards Management.

The root of the issue is that OpenSearch is not using UTC for the @timestamp value during ingestion. If you look at the last example I posted, the time “09:23:56” is US Eastern timezone and that is what OpenSearch is using for the @timestamp value and I’m not sure why. If it was using UTC, the @timestamp value should be 09:23:56 +4. Because of this, in Dashboards things do not align since the communication flow expects the @timetamp value to be UTC. Any thoughts on how to ensure OpenSearch uses UTC for the @timestamp value?

9

@sloan58 I took a closer look at your _raw values from all documents. I think the problem is in the format.

The above have proper syslog format, however, the last one doesn’t.

Try testing these inputs with OpenSeach pipeline.

i.e.

PUT _ingest/pipeline/test_pipeline
{
  "processors" : [
      {
        "grok" : {
          "field" : "message",
          "on_failure" : [
          {
            "set" : {
              "field" : "error.message",
              "value" : "{{ _ingest.on_failure_message }}"}}],
          "patterns" : [
            "%{SYSLOGLINE}"
          ]
        }
      }
    ]
}

POST _ingest/pipeline/test_pipeline/_simulate  
{"docs":
  [
    {"_source":
      {"message":"<4>Mar 28 09:23:56 ubnt kernel: [LAN_LOCAL-default-A]IN=eth1 OUT= MAC=e0:63:da:54:ab:15:3a:1f:2b:0f:5c:69:08:00 SRC=192.168.1.6 DST=192.168.1.1 LEN=52 TOS=0x00 PREC=0x00 TTL=64 ID=48579 DF PROTO=TCP SPT=8080 DPT=45008 WINDOW=501 RES=0x00 ACK FIN URGP=0 "}
      }
    ]
}


POST _ingest/pipeline/test_pipeline/_simulate  
{"docs":
  [
    {"_source":
      {"message":"<189>91: *Mar 27 20:50:17.851: %SEC_LOGIN-5-LOGIN_SUCCESS: Login Success [user: marty] [Source: 192.168.1.158] [localport: 22] at 20:50:17 UTC Wed Mar 27 2024"}
      }
    ]
}

How do you ingest data into OpenSearch? Is it filebeat or another tool?

10

@pablo thanks for the suggestions. It sent me down a path to discover what the issue actually was and it was not OpenSearch. I’m sending the data into OpenSearch from Cribl and they have a pipeline on their side to normalize the timestamp field to UTC. I thought that OpenSearch was adding the @timestamp field but after reading some additional documentation, I found that Cribl is converting their internal _timestamp field to @timestamp when sending to OpenSearch. The log viewer in Cribl shows the payload prior to the conversion so I assumed OpenSearch was adding the @timestamp field.

Thank you for the assistance and insights on troubleshooting OpenSearch.

In case anyone is interested in the Cribl integration - Elasticsearch | Cribl Docs

1 Like