Event time doesn't refer to field defined by time_key

[23henne]

Bugs should be filed for issues encountered whilst operating logging-operator.
You should first attempt to resolve your issues through the community support
channels, e.g. Slack, in order to rule out individual configuration errors. #logging-operator
Please provide as much detail as possible.

Describe the bug:
I'm trying to ship container's stdout to elasticsearch cluster. Input on worker node level looks like this:

{"log":"[26/Apr/2023:06:56:48 +0000] 10.1.1.1 - - http HTTP/1.1 \"GET /health\" 200 0.000 94 - - \"-\" \"kube-probe/1.21\" \"-\" \"-\" \"10.2.1.1:8000\" \"-\"\n","stream":"stdout","time":"2023-04-26T06:56:48.118043458Z"}

I have set up appropriate flow as follows:

apiVersion: logging.banzaicloud.io/v1beta1
kind: Flow
metadata:
  name: some-flow
  namespace: some-namespace
spec:
  globalOutputRefs: []
  localOutputRefs:
    - some-output
  match:
    - select:
        container_names:
          - some-container-name
        hosts: []
        labels: {}
  filters:
  - tag_normaliser: {}
  - parser:
      key_name: log
      remove_key_name_field: false
      reserve_data: true
      parse:
        type: multi_format
        patterns:
          - format: regexp
            expression: /^\[(?<http.timestamp>[^\]]+)\]\s+(?<http.clientip>[0-9\.]+)\s+(?<http.remoteUser>\S+)\s+((?<http.x_forwarded_forProxy>\S+)|-)(,\s+(?<http.x_forwarded_for>\S+))*\s+(?<http.scheme>\w+)\s+HTTP/(?<http.version>[0-9\.]+)\s+\"(?<http.methode>\w+)\s+(?<http.request>[^\"]+)\"\s+(?<http.statusCode>\d+)\s+(?<http.requestTime>[0-9\.]+)\s+(?<http.bytesSent>\d+)\s+(?<http.upstreamStatusCode>\d+|-)\s+((?<http.upstreamResponseTime>[0-9\.]+)|-)\s+\"(?<http.referrer>[^\"]+)\"\s+\"(?<http.useragent>.*?(?=(\w{40})?))\"\s+\"(?<SESSIONID>[^\"]*)\"\s+\"(?<http.upstream_addr>[^\"]+)\"\s+\"(?<http.host>[^\"]+)\"\s+\"(?<http.location>[^\"]+)\"$/
            time_format: "%d/%b/%Y:%H:%M:%S %z"
            time_key: "http.timestamp"
            keep_time_key: true
            types: "http.statusCode:integer, http.requestTime:integer, http.bytesSent:integer, http.upstreamStatusCode:integer, http.upstreamResponseTime:integer"
          - format: none

Parsing works quite well but it uses time instead of http.timestamp as event time.

_id
asdasdasd1234

_index
some-index

_score
 - 

SESSIONID
-

http.bytesSent
94

http.clientip
10.1.1.1

http.host
10.2.1.1:8000

http.location
-

http.methode
GET

http.referrer
-

http.remoteUser
-

http.request
/health

http.requestTime
0

http.scheme
http

http.statusCode
200

http.timestamp
26/Apr/2023:06:56:48 +0000

http.upstream_addr
-

http.upstreamStatusCode
0

http.useragent
kube-probe/1.21

http.version
1.1

http.x_forwarded_forProxy
-

...

log
[26/Apr/2023:06:56:48 +0000] 10.1.1.1 - - http HTTP/1.1 "GET /health" 200 0.000 94 - - "-" "kube-probe/1.21" "-" "-" "10.2.1.1:8000" "-"

stream
stdout

time
Apr 26, 2023 @ 06:56:48.118

Why is it?

Expected behaviour:
I'm using fluentbit as a sidecar for another project and when setting Time_Key timestamp in elastic there is a field named @timestamp as date. I'd expect same in this scenario.

Steps to reproduce the bug:
Use input and flow from above to reproduce the issue.

Additional context:
Nothing at all.

Environment details:

• Kubernetes version v1.21.14
• Cloud-provider/provisioner: RKE (self-managed)
• Resource definition (possibly in YAML format) that caused the issue, without sensitive data: Added above

/kind bug

[pepov]

I can't see that this issue has anything to do with the logging operator, so converting this to a discussion, with Q&A category.

[steffeneichler]

@pepov I think @23henne tried to extract http.timestamp and use it as timestamp for the elastic document. But time is used.
In his own deployment via sidecar it seemed to work.