Feedback on new log event data model

[jszwedko]

Discussion to collect feedback on the newly released log namespacing feature. See https://vector.dev/blog/log-namespacing/ for the feature announcement. Let us know what you think below!

[jalaziz]

I've been trying to get log namespacing to work, but I must be doing something wrong.

The event metadata seems to be empty, but so does the actual underlying message. The only fields that are set are the events that are set explicitly.

Here's an example config:

api:
  enabled: true
  address: 0.0.0.0:8686
data_dir: "/vector-data-dir"
schema:
    log_namespace: true

sources:
  kubernetes:
    type: kubernetes_logs

transforms:

  enrich_event:
    type: remap
    inputs:
      - kubernetes
    source: |
      . = {"msg": .}
      .metadata = {
        "cluster_name": "cluster",
        "sender": "vector",
      }
      .vector = %vector
      .all_metadata = %

sinks:
  console:
    type: console
    inputs:
      - enrich_event
    encoding:
      codec: logfmt

Here's sample events:

metadata.cluster_name=cluster metadata.sender=vector vector=null
metadata.cluster_name=cluster metadata.sender=vector vector=null

I even tried dropping the transform step by connecting the source and sink together and all I get is empty lines.

[jalaziz]

@jszwedko I am using helm and the image version is timberio/vector:0.31.0-distroless-libc.

The full agent version is: vector 0.31.0 (aarch64-unknown-linux-gnu 0f13b22 2023-07-06 13:52:34.591204470)

I didn't have encoding / format on the source, let me try that.

[jalaziz]

@jszwedko okay, I was able to confirm everything works with demo_logs. It seems the issue may be with kubernetes_logs specifically.

[jszwedko]

Thanks for trying! I'll try the kubernetes_logs source.

[jszwedko]

I was able to reproduce this with the kubernetes_logs source. We'll take a look. Thanks for flagging @jalaziz !

[jszwedko]

Opened #18018 to track this bug.

[hhromic]

Thanks for implementing log namespacing!
This was something we wished Vector had since the very beginning to keep input data separated from metadata indeed :)

I played a bit with this feature now and I have the following feedback to give.

• At the moment, the %vector metadata is a bit barebones. It would be nice if it can include more information about the source that produced the event. For example the source ID would be very useful and would partially solve sources: add customisable source_label field to emitted events #11544 for us. In the case of socket sources, previously the source would include host and port fields that are missing in the new log metadata.

• The fields in the %vector metadata should be formally typed. For example the ingest_timestamp field cannot be used directly in functions expecting timestamp type arguments without passing it by the timestamp() type assertion function:

  # Trying to do '.ts = to_unix_timestamp(%vector.ingest_timestamp)' does not work directly
  error[E103]: unhandled fallible assignment
    ┌─ :1:7
    │
  1 │ .ts = to_unix_timestamp(%vector.ingest_timestamp)
    │ ----- ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    │ │     │
    │ │     this expression is fallible
    │ │     update the expression to be infallible
    │ or change this to an infallible assignment:
    │ .ts, err = to_unix_timestamp(@vector.ingest_timestamp)
  
  # But this is okay
  ts = timestamp!(%vector.ingest_timestamp)
  .ts = to_unix_timestamp(ts)
  

  My expectation was that the ingest_timestamp field is guaranteed to be of timestamp type because it was generated by Vector itself. The same would apply for any other field such as port that should be of int type.

In general this feature is really nice and I can't wait to start using it in our Vector pipelines, specially when more metadata from the sources is added as we use fields like host and port extensively.

EDIT: I just noticed that the error message shown above is suggesting @vector instead of %vector. Probably a bug there!

[pront]

Thank you for the great feedback @hhromic. For the VRL specific feedback:

• The ingest_timestamp type is an interesting point. We will discuss internally and come back to you.
• Created an issue for the @vector error: Fix VRL error message - use %vector instead of @vector vrl#373

[fuchsnj]

The fields in the %vector metadata should be formally typed. For example the ingest_timestamp field cannot be used directly in functions expecting timestamp type arguments without passing it by the timestamp() type assertion function:

I agree, and this is actually already implemented. However, it's a large enough change that we were planning on releasing it as a separate feature soon. It's currently undocumented, but feel free to play around with the "full" schemas by setting schema.enabled = true in your config.

[hhromic]

I agree, and this is actually already implemented. However, it's a large enough change that we were planning on releasing it as a separate feature soon. It's currently undocumented, but feel free to play around with the "full" schemas by setting schema.enabled = true in your config.

Ah nice! I just gave it a try and doing this indeed worked perfectly with schema.enabled = true !

.ts = to_unix_timestamp(%vector.ingest_timestamp)

This is really a powerful/nice feature, hope to see the remaining (typed) metadata fields from sources implemented too!

[gkoz]

I guess the reduce transform hasn't been made compatible with this mode yet because it can't handle logs that are strings rather than objects.

More importantly, is the reduce transform supposed to preserve the event metadata? Currently it doesn't:

sources:
  demo:
    type: demo_logs
    format: apache_common
transforms:
  wrap1:
    type: remap
    inputs:
      - demo
    source: |
      . = { "log1": ., "meta1": % }
  reduce:
    type: reduce
    inputs:
      - wrap1
    max_events: 1
  wrap2:
    type: remap
    inputs:
      - reduce
    source: |
      . = { "log2": ., "meta2": % }
sinks:
  debug:
    type: file
    encoding:
      codec: native_json
    inputs:
      - wrap2
    path: /tmp/vector.log

{
  "log": {
    "log2": {
      "log1": "10.180.217.92 - benefritz [07/Aug/2023:19:54:45 +0000] \"PATCH /user/booperbot124 HTTP/1.0\" 401 9250",
      "meta1": {
        "demo_logs": {
          "service": "vector"
        },
        "vector": {
          "ingest_timestamp": "2023-08-07T19:54:45.201513665Z",
          "source_type": "demo_logs"
        }
      }
    },
    "meta2": {}
  }
}

[fuchsnj]

I created #18219 to track this issue.

[hhromic]

Hello, today we found the limitation in Vector that events need to be objects and therefore we cannot assign null directly as an event. Jesse suggested to try using the schema.log_namespace feature which should lift this limitation and while it worked, we discovered another inconsistency that likely is a bug.

Consider the following example pipeline:

schema:
  log_namespace: true
sources:
  stdin:
    type: stdin
transforms:
  remap:
    type: remap
    inputs: ["stdin"]
    source: '. = parse_json!(.)'
sinks:
  console:
    type: console
    inputs: ["remap"]
    encoding:
      codec: json

This pipeline simply reads from stdin, parses the input lines as JSON, assigns the parsing result into the event itself (.) and then shows the result in the console encoded as JSON.

Now consider the following input data in JSON format:

{"hello":"world"}
[{"charlie":"diego"},{"alice":"bob"}]
null
[null,null]
[{"edgar":"flavio"},null]

It is understood that assigning arrays to the output event (.) produces multiple events to the next component.

However, when we run Vector with the above input and pipeline, the result is this:

{"hello":"world"}
{"charlie":"diego"}
{"alice":"bob"}
null
{"message":null}
{"message":null}
{"edgar":"flavio"}
{"message":null}

As it can be seen, the lone null data example is correctly parsed and assigned to the event as null, however in the remaining examples the null values are wrapped into {"message":null} objects. Maybe the log namespace is not applied to arrays of events?

[fuchsnj]

Thanks for reporting this. I have created a fix for it: #18372

[hhromic]

Great @fuchsnj !
From taking a look at the PR, it will only fix this on the remap transform right?
The codecs will be still affected?

[fuchsnj]

The codecs issue is a separate issue, I'm still looking into that one.

[fuchsnj]

The codec issue is fixed here: #18379

[hhromic]

Just tested latest master with your recent fixes, all working great now with log namespace enabled! 🎉
Looking forward for this feature to graduate to stable :)