Remap: contradicting error messages around merge function

[spencergilbert]

Vector Version

timberio/vector:0.12.1-distroless-libc

Vector Configuration File

[transforms.normalize_rke]
type = "remap"
inputs = ["rke_logs"]
source = """
# Ensure all events are annotated with the "node" they originated from and the
# Vector agent that processed the log
.node = "$VECTOR_SELF_NODE_NAME"
.agent = "$VECTOR_SELF_POD_NAME"

structured, err = parse_json(.message)
if err != null {
        log(err, level: "error")
}
. = merge!(., structured, deep: true)
.message = del(.log)
"""

[transforms.normalize_system]
type = "remap"
inputs = ["system_logs"]
source = """
# Ensure all events are annotated with the "node" they originated from and the
# Vector agent that processed the log
.node = "$VECTOR_SELF_NODE_NAME"
.agent = "$VECTOR_SELF_POD_NAME"

structured, err = parse_syslog(.message)
if err != null {
        log(err, level: "error")
}
. = merge!(., structured, deep: true)
del(.hostname)
"""

[[tests]]
name = "rke:etcd"
[[tests.inputs]]
insert_at = "normalize_rke"
type = "log"
log_fields.file = "/var/lib/rancher/rke/log/etcd_a22beeac9bed291aa86d435db345f2bb97726a5e14f5e92592e5ebf616260b4d.log"
log_fields.message = '''{"log":"2021-03-16 22:09:03.386126 I | mvcc: store.index: compact 84077398\n","stream":"stderr","time":"2021-03-16T22:09:03.386410422Z"}'''
[[tests.outputs]]
extract_from = "normalize_rke"
[[tests.outputs.conditions]]
type = "remap"
source = '''
!exists(.log) &&
        .agent == "vector-agent-test" &&
        .message == "2021-03-16 22:09:03.386126 I | mvcc: store.index: compact 84077398\n" &&
        .node == "test"
'''
[[tests]]
name = "system:auth"
[[tests.inputs]]
insert_at = "normalize_system"
type = "log"
log_fields.file = "/var/log/auth.log"
log_fields.message = '''Mar 16 23:45:01 test CRON[20842]: pam_unix(cron:session): session opened for user root by (uid=0)'''
[[tests.outputs]]
extract_from = "normalize_system"
[[tests.outputs.conditions]]
type = "remap"
source = '''
.agent == "vector-agent-test" &&
        .appname == "CRON" &&
        !exists(.hostname) &&
        .message == "pam_unix(cron:session): session opened for user root by (uid=0)" &&
        .node == "test" &&
        .procid == 20842 &&
        .timestamp == to_timestamp!("2021-03-17T03:45:01Z")
'''

Debug Output

Expected Behavior

Unit tests are passing locally when run, but when deployed to my cluster the config errors. If I remove the abort instruction the unit tests fail locally. I'm not sure if I'm missing an edgecase or something more obvious but it seemed funky.

Actual Behavior

Mar 17 00:54:53.326 ERROR vector::topology: Configuration error. error=Transform "normalize_system":
Tue, Mar 16 2021 8:54:53 pm | error[E620]: can't abort infallible function
Tue, Mar 16 2021 8:54:53 pm | ┌─ :10:5
Tue, Mar 16 2021 8:54:53 pm | │
Tue, Mar 16 2021 8:54:53 pm | 10 │ . = merge!(., structured, deep: true)
Tue, Mar 16 2021 8:54:53 pm | │ ^^^^^- remove this abort-instruction
Tue, Mar 16 2021 8:54:53 pm | │ │
Tue, Mar 16 2021 8:54:53 pm | │ this function can't fail
Tue, Mar 16 2021 8:54:53 pm | │
Tue, Mar 16 2021 8:54:53 pm | = see documentation about error handling at https://errors.vrl.dev/#handling
Tue, Mar 16 2021 8:54:53 pm | = see language documentation at https://vrl.dev
Tue, Mar 16 2021 8:54:53 pm

Updated to not abort:

Mar 16 20:58:03.129 ERROR vector::unit_test: Failed to execute tests:
Failed to build test 'system:syslog':
  failed to build transform 'normalize_system':
  error[E103]: unhandled fallible assignment
     ┌─ :10:5
     │
  10 │ . = merge(., structured, deep: true)
     │ --- ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
     │ │   │
     │ │   this expression is fallible
     │ │   update the expression to be infallible
     │ or change this to an infallible assignment:
     │ , err = merge(., structured, true)
     │
     = see documentation about error handling at https://errors.vrl.dev/#handling
     = learn more about error code 103 at https://errors.vrl.dev/103
     = see language documentation at https://vrl.dev

[jszwedko]

A user hit this with split() too: https://discord.com/channels/742820443487993987/746070591097798688/821812665903087696

I am getting errors that something like this is fallible, and it won't compile
if (exists(.field)) { .field = split(.field, ",") }

If I change to be like this, I get an message to "remove this abort-instruction" and "this function can't fail":
if (exists(.field)) { .field = split!(.field, ",") }

[SyluxDX]

The same happens with the functions:

• replace
• contains
• downcase
• ends_with
• join
• match
• slice
• starts_with
• upcase
• truncate
• strip_whitespace
• strip_ansi_escape_codes

Basically all strings functions

[hhromic]

We stumbled into a very similar problem as well. However we are observing a very strange behaviour.

This does not work (error is expression can result in runtime error):

      .field1 = parse_timestamp!(.timestamp, format: "%Y-%m-%d")
      .field2 = to_int(.field1)

Now, let's go back and let's try to capture the runtime error:

      .field2, err = to_int(.field1)

We now get a this error assignment is unnecessary error because to_int() is infallible.

Now, the really puzzling observation is this (note assignment to a variable, not the . object):

      tmp = to_int(.field1)
      .field2 = tmp

The above DOES work.

And furthermore:

      tmp = to_int(.field1)
      .field2 = tmp
      .field3, err = to_int(.field1)

The direct assignment to .field3 now ALSO WORKS. To which I don't have an explanation :(

Somehow, the assignment to a temporary variable affects the behaviour of subsequent compile-time checks?

[jszwedko]

@spencergilbert I tried to reproduce what you have above with the following config:

[sources.in]
type = "stdin"

[transforms.normalize_rke]
type = "remap"
inputs = ["in"]
source = """
# Ensure all events are annotated with the "node" they originated from and the
# Vector agent that processed the log
.node = "$VECTOR_SELF_NODE_NAME"
.agent = "$VECTOR_SELF_POD_NAME"

structured, err = parse_json(.message)
if err != null {
        log(err, level: "error")
}
. = merge!(., structured, deep: true)
.message = del(.log)
"""

[transforms.normalize_system]
type = "remap"
inputs = ["in"]
source = """
# Ensure all events are annotated with the "node" they originated from and the
# Vector agent that processed the log
.node = "$VECTOR_SELF_NODE_NAME"
.agent = "$VECTOR_SELF_POD_NAME"

structured, err = parse_syslog(.message)
if err != null {
        log(err, level: "error")
}
. = merge!(., structured, deep: true)
del(.hostname)
"""

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

[[tests]]
name = "rke:etcd"
[[tests.inputs]]
insert_at = "normalize_rke"
type = "log"
log_fields.file = "/var/lib/rancher/rke/log/etcd_a22beeac9bed291aa86d435db345f2bb97726a5e14f5e92592e5ebf616260b4d.log"
log_fields.message = '''{"log":"2021-03-16 22:09:03.386126 I | mvcc: store.index: compact 84077398\n","stream":"stderr","time":"2021-03-16T22:09:03.386410422Z"}'''
[[tests.outputs]]
extract_from = "normalize_rke"
[[tests.outputs.conditions]]
type = "remap"
source = '''
!exists(.log) &&
        .agent == "vector-agent-test" &&
        .message == "2021-03-16 22:09:03.386126 I | mvcc: store.index: compact 84077398\n" &&
        .node == "test"
'''
[[tests]]
name = "system:auth"
[[tests.inputs]]
insert_at = "normalize_system"
type = "log"
log_fields.file = "/var/log/auth.log"
log_fields.message = '''Mar 16 23:45:01 test CRON[20842]: pam_unix(cron:session): session opened for user root by (uid=0)'''
[[tests.outputs]]
extract_from = "normalize_system"
[[tests.outputs.conditions]]
type = "remap"
source = '''
.agent == "vector-agent-test" &&
        .appname == "CRON" &&
        !exists(.hostname) &&
        .message == "pam_unix(cron:session): session opened for user root by (uid=0)" &&
        .node == "test" &&
        .procid == 20842 &&
        .timestamp == to_timestamp!("2021-03-17T03:45:01Z")
'''

However, I got the error about infallibility with both vector test and just running vector via vector --config:

Failed to build test 'system:auth':
  failed to build transform 'normalize_system':
  error[E620]: can't abort infallible function
     ┌─ :10:5
     │
  10 │ . = merge!(., structured, deep: true)
     │     ^^^^^- remove this abort-instruction
     │     │
     │     this function can't fail
     │
     = see documentation about error handling at https://errors.vrl.dev/#handling
     = see language documentation at https://vrl.dev

If I remove the ! as it suggests, both vector test and vector --config .. seem to work fine. Am I missing something?

[jszwedko]

@SyluxDX are you able to provide some complete vector configs that demonstrate what you are seeing? I'm actually having difficulty reproducing this.

I also haven't been able to reproduce the example from #6792 (comment) yet either.

[spencergilbert]

Let me look again and see if I can reproduce my own problem :) it's been a little while since I looked at it

EDIT: will try and reproduce with v0.12.2

[jszwedko]

@hhromic thanks for the test case! I was able to reproduce this one and opened #7118 to address it. The issue was that VRL was not correctly preserving type information across expressions.

[hhromic]

@jszwedko thanks! Happy to help!
I introduced Vector to my team and we are starting to use it more seriously for collecting observability data. This bug in particular was found by a colleague of mine. We have a number of use-cases for new features in VRL (and other parts) that might be interesting for you. I'll be opening feature-request issues for you to examine and consider.

[jszwedko]

@hhromic that would be great! We'd love the feedback and ideas. If you or your team are interested, we also have office hours every Friday we could use to discuss: https://calendly.com/jszwedko/vector-office-hours

[spencergilbert]

@jszwedko 🤷 I can't even reproduce it myself anymore, I tested a couple versions of vector to see if it had just been resolved somewhere but no dice. Maybe just gremlins?

[jszwedko]

Closing this as I believe the issues here are addressed by #7118 . It will be included in the next release on Tuesday (0.13).