VRL test input isn't able to set event metadata

[GreyTeardrop]

A note for the community

• Please vote on this issue by adding a 👍 reaction to the original issue to help the community and maintainers prioritize this request
• If you are interested in working on this issue or have submitted a pull request, please leave a comment

Problem

When running in Log Namespacing mode, there seems to be no way to set the input event's metadata. I tried using the VRL test event source and the % = … syntax inside the VRL code, but it appears to update the event, not the metadata.

Configuration

# $schema: ./vector.schema.json

schema:
  log_namespace: true

sources:
  sample_logs:
    type: demo_logs
    format: apache_common

transforms:
  sample_transform:
    inputs:
      - sample_logs
    type: remap
    source: |
      .event = .
      .metadata = %

sinks:
  console:
    inputs:
      - sample_transform
    type: console
    encoding:
      codec: json

tests:
  - name: sample test
    inputs:
      - insert_at: sample_transform
        type: vrl
        source: |
          . = "Event"
          % = "Metadata"
    outputs:
      - extract_from: sample_transform
        conditions:
          - type: vrl
            source: |
              assert_eq!(.event, "Event")
              assert_eq!(.metadata, "Metadata")

Version

vector 0.35.0 (x86_64-apple-darwin e57c0c0 2024-01-08 14:42:10.103908779)

Debug Output

2024-01-17T09:06:53.909662Z DEBUG vector::app: Internal log rate limit configured. internal_log_rate_secs=10
2024-01-17T09:06:53.911585Z  INFO vector::app: Log level is enabled. level="trace"
2024-01-17T09:06:53.911817Z DEBUG vector::app: messaged="Building runtime." worker_threads=10
2024-01-17T09:06:53.913855Z TRACE mio::poll: registering event source with poller: token=Token(1), interests=READABLE
Running tests
2024-01-17T09:06:53.979368Z DEBUG vector::topology::builder: Building new source. component=sample_transform-source-adbbb00d-d7c9-403b-a429-24444bc0521e
2024-01-17T09:06:53.983619Z DEBUG vector::topology::builder: Building new transform. component=sample_transform
2024-01-17T09:06:53.986445Z DEBUG vector::topology::builder: Building new sink. component=sample_transform-sink-adbbb00d-d7c9-403b-a429-24444bc0521e
2024-01-17T09:06:53.989029Z  INFO vector::topology::running: Running healthchecks.
2024-01-17T09:06:53.989220Z DEBUG vector::topology::running: Connecting changed/added component(s).
2024-01-17T09:06:53.989465Z  INFO vector::topology::builder: Healthcheck passed.
2024-01-17T09:06:53.989511Z DEBUG vector::topology::running: Configuring outputs for source. component=sample_transform-source-adbbb00d-d7c9-403b-a429-24444bc0521e
2024-01-17T09:06:53.989684Z DEBUG vector::topology::running: Configuring output for component. component=sample_transform-source-adbbb00d-d7c9-403b-a429-24444bc0521e output_id=None
2024-01-17T09:06:53.989701Z DEBUG vector::topology::running: Configuring outputs for transform. component=sample_transform
2024-01-17T09:06:53.989707Z DEBUG vector::topology::running: Configuring output for component. component=sample_transform output_id=None
2024-01-17T09:06:53.989713Z DEBUG vector::topology::running: Connecting inputs for transform. component=sample_transform
2024-01-17T09:06:53.989874Z DEBUG vector::topology::running: Adding component input to fanout. component=sample_transform fanout_id=sample_transform-source-adbbb00d-d7c9-403b-a429-24444bc0521e
2024-01-17T09:06:53.989954Z DEBUG vector::topology::running: Connecting inputs for sink. component=sample_transform-sink-adbbb00d-d7c9-403b-a429-24444bc0521e
2024-01-17T09:06:53.989975Z DEBUG vector::topology::running: Adding component input to fanout. component=sample_transform-sink-adbbb00d-d7c9-403b-a429-24444bc0521e fanout_id=sample_transform
2024-01-17T09:06:53.990373Z DEBUG vector::topology::running: Spawning new source. key=sample_transform-source-adbbb00d-d7c9-403b-a429-24444bc0521e
2024-01-17T09:06:53.990484Z DEBUG vector::topology::running: Spawning new transform. key=sample_transform
2024-01-17T09:06:53.990554Z TRACE vector::topology::running: Spawning new sink. key=sample_transform-sink-adbbb00d-d7c9-403b-a429-24444bc0521e
2024-01-17T09:06:53.991266Z DEBUG source{component_kind="source" component_id=sample_transform-source-adbbb00d-d7c9-403b-a429-24444bc0521e component_type=unit_test}: vector::topology::builder: Source pump supervisor starting.
2024-01-17T09:06:53.991280Z DEBUG sink{component_kind="sink" component_id=sample_transform-sink-adbbb00d-d7c9-403b-a429-24444bc0521e component_type=unit_test}: vector::topology::builder: Sink starting.
2024-01-17T09:06:53.991286Z DEBUG source{component_kind="source" component_id=sample_transform-source-adbbb00d-d7c9-403b-a429-24444bc0521e component_type=unit_test}: vector::topology::builder: Source starting.
2024-01-17T09:06:53.991284Z DEBUG transform{component_kind="transform" component_id=sample_transform component_type=remap}: vector::topology::builder: Synchronous transform starting.
2024-01-17T09:06:53.991853Z DEBUG source{component_kind="source" component_id=sample_transform-source-adbbb00d-d7c9-403b-a429-24444bc0521e component_type=unit_test}: vector::topology::builder: Source pump starting.
2024-01-17T09:06:53.992039Z TRACE source{component_kind="source" component_id=sample_transform-source-adbbb00d-d7c9-403b-a429-24444bc0521e component_type=unit_test}: vector_buffers::topology::channel::limited_queue: Sent item.
2024-01-17T09:06:53.992196Z TRACE source{component_kind="source" component_id=sample_transform-source-adbbb00d-d7c9-403b-a429-24444bc0521e component_type=unit_test}: vector_common::internal_event::events_sent: Events sent. count=1 byte_size=12 output=_default
2024-01-17T09:06:53.992246Z  INFO vector_common::shutdown: All sources have finished.
2024-01-17T09:06:53.992357Z DEBUG source{component_kind="source" component_id=sample_transform-source-adbbb00d-d7c9-403b-a429-24444bc0521e component_type=unit_test}: vector::topology::builder: Source finished normally.
2024-01-17T09:06:53.992972Z TRACE source{component_kind="source" component_id=sample_transform-source-adbbb00d-d7c9-403b-a429-24444bc0521e component_type=unit_test}: vector_core::fanout: Processing control message outside of send: ControlMessage::Add(ComponentKey { id: "sample_transform" })
2024-01-17T09:06:53.993385Z TRACE source{component_kind="source" component_id=sample_transform-source-adbbb00d-d7c9-403b-a429-24444bc0521e component_type=unit_test}: vector_core::fanout: Processing control message inside of send: None
2024-01-17T09:06:53.993709Z TRACE source{component_kind="source" component_id=sample_transform-source-adbbb00d-d7c9-403b-a429-24444bc0521e component_type=unit_test}: vector_buffers::topology::channel::limited_queue: Sent item.
2024-01-17T09:06:53.993805Z DEBUG sink{component_kind="sink" component_id=sample_transform-sink-adbbb00d-d7c9-403b-a429-24444bc0521e component_type=unit_test}: vector::utilization: utilization=0.11474761708347414
2024-01-17T09:06:53.994164Z TRACE source{component_kind="source" component_id=sample_transform-source-adbbb00d-d7c9-403b-a429-24444bc0521e component_type=unit_test}: vector_core::fanout: Sent item to fanout.
2024-01-17T09:06:53.994176Z DEBUG source{component_kind="source" component_id=sample_transform-source-adbbb00d-d7c9-403b-a429-24444bc0521e component_type=unit_test}: vector::topology::builder: Source pump finished normally.
2024-01-17T09:06:53.994381Z DEBUG source{component_kind="source" component_id=sample_transform-source-adbbb00d-d7c9-403b-a429-24444bc0521e component_type=unit_test}: vector::topology::builder: Source pump supervisor task finished normally.
2024-01-17T09:06:53.994425Z TRACE transform{component_kind="transform" component_id=sample_transform component_type=remap}: vector_common::internal_event::events_received: Events received. count=1 byte_size=12
2024-01-17T09:06:53.995653Z TRACE transform{component_kind="transform" component_id=sample_transform component_type=remap}: vector_core::fanout: Processing control message outside of send: ControlMessage::Add(ComponentKey { id: "sample_transform-sink-adbbb00d-d7c9-403b-a429-24444bc0521e" })
2024-01-17T09:06:53.995677Z TRACE transform{component_kind="transform" component_id=sample_transform component_type=remap}: vector_core::fanout: Processing control message inside of send: None
2024-01-17T09:06:53.995848Z TRACE transform{component_kind="transform" component_id=sample_transform component_type=remap}: vector_buffers::topology::channel::limited_queue: Sent item.
2024-01-17T09:06:53.995869Z TRACE transform{component_kind="transform" component_id=sample_transform component_type=remap}: vector_core::fanout: Sent item to fanout.
2024-01-17T09:06:53.995880Z TRACE transform{component_kind="transform" component_id=sample_transform component_type=remap}: vector_common::internal_event::events_sent: Events sent. count=1 byte_size=36 output=_default
2024-01-17T09:06:53.996408Z DEBUG transform{component_kind="transform" component_id=sample_transform component_type=remap}: vector::topology::builder: Synchronous transform finished normally.
2024-01-17T09:06:53.996459Z TRACE sink{component_kind="sink" component_id=sample_transform-sink-adbbb00d-d7c9-403b-a429-24444bc0521e component_type=unit_test}: vector_common::internal_event::events_received: Events received. count=1 byte_size=36
2024-01-17T09:06:53.998801Z DEBUG sink{component_kind="sink" component_id=sample_transform-sink-adbbb00d-d7c9-403b-a429-24444bc0521e component_type=unit_test}: vector::topology::builder: Sink finished normally.
test sample test ... failed

failures:

test sample test:

check[0] for transforms ["sample_transform"] failed conditions:

  condition[0]: source execution failed:
error[E000]: function call error for "assert_eq" at (0:27): assertion failed: "Metadata" == "Event"
  ┌─ :1:1
  │
1 │ assert_eq!(.event, "Event")
  │ ^^^^^^^^^^^^^^^^^^^^^^^^^^^ assertion failed: "Metadata" == "Event"
  │
  = see language documentation at https://vrl.dev
  = try your code in the VRL REPL, learn more at https://vrl.dev/examples


output payloads from ["sample_transform"] (events encoded as JSON):
  {"event":"Metadata","metadata":{}}

Example Data

No response

Additional Context

No response

References

No response

[jszwedko]

I think I see the issue here. For the vrl test inputs, it uses whatever the "return" of the program is (rather than using the event, .). That is:

          . = "Event"
          % = "Metadata"

Ends up returning % as the "input" to use. That is, it is the same as:

          . = "Event"
          % = "Metadata"
          %

As it stands, it looks like there isn't a way to set metadata on input events using the vrl input type. I could see it making sense to not use the last value of the program but instead use the value of . after the program runs.

[jszwedko]

@MartinEmrich as the contributor who added this feature, I'm just curious if you have thoughts. It would mean, rather than using v here:

https://github.com/vectordotdev/vector/pull/19107/files#diff-9d91acb243d1abd67886929ac77ad81632ce3a00f581278b283490ca1507f312R584

It'd use target instead.

[GreyTeardrop]

Thank you, @jszwedko! I've applied your suggestion in #19729. I'm a complete Rust newbie, though, so that might not be what's needed, although it seems to work locally.

[MartinEmrich]

@jszwedko Sure you mean me? I have no idea what this is about, I cannot remember a contribution touching his.

[jszwedko]

Doh, I'm sorry @MartinEmrich . I meant to tag @MichaHoffmann instead who contributed #19107.

@MichaHoffmann I'm curious for your thoughts on #19729

[MichaHoffmann]

I dont really know the VRL api all that well i got to admit, but ignoring the mapped value and returning target feels somewhat weird structurally to me!

Edit: But if tests pass I'm happy!

[GreyTeardrop]

Should be fixed by #19729.