post parsing already parsed fields...

[dss010101]

i've converted my toml to use the parse_grok function. i have two questions:

1. the 'msg' field i parse out may contain other patterns i want to parse out, such as 'app_id=app_1234'. Can i post parse msg and add these fields afterwards, rather than have to keep adding patterns for each? It seems it would be cleaner to post parses for optional fields that may or may not be present in the parsed 'msg' field?

2. This all now parses and ends up in loki/grafana as json, but the fields do not end up as labels i can use in queries. i still am limited to 'app' and 'env' only (labels added by the 'sink.to_indexer' section in my toml. So im still forced to do a text search to find certain things i'm looking for.

toml

[sources.app_logs]
type = "file"
#ignore_older_secs = 600
include = ["/var/logs/*.log"]
read_from = "beginning"

[sources.app_logs.multiline]
start_pattern = "^[^\\s]"
mode = "continue_through"
condition_pattern = "^[\\s]+from"
timeout_ms = 1000

[transforms.log_parser]
type   = "remap"
inputs = ["app_logs"]
source = '''
    . |= parse_groks!(
            .message, 
            patterns:[
                "\\[%{TIMESTAMP_ISO8601:log_time}\\]\\[%{INT:process}:%{INT:thread}\\]\\[%{WORD:severity}\\]\\[%{WORD:module}.%{WORD:func}\\] app_id:%{NOTSPACE:app_id} %{GREEDYDATA:msg}",
                "\\[%{TIMESTAMP_ISO8601:log_time}\\]\\[%{INT:process}:%{INT:thread}\\]\\[%{WORD:severity}\\]\\[%{WORD:module}.%{WORD:func}\\] %{GREEDYDATA:msg}",
                "\\[%{TIMESTAMP_ISO8601:log_time}\\]\\[%{INT:process}:%{INT:thread}\\]%{WORD:severity}:%{WORD:module}:%{GREEDYDATA:msg}"
            ]
    )

'''

[sinks.to_indexer]
type = "loki"
inputs = ["log_parser"]
endpoint = "http://loki:3100"
encoding.codec = "json"
labels = {app="app_logs", env="dev"}
healthcheck = false

'''

example logs with/and without app_id:

[2023-05-15 11:52:29,401][2555:140431094425152][INFO][default.run] initalizing application
[2023-05-15 11:52:29,401][2555:140431094425152][INFO][default.run] app_id:my_app_12345 initialized.

[jszwedko]

• the 'msg' field i parse out may contain other patterns i want to parse out, such as 'app_id=app_1234'. Can i post parse msg and add these fields afterwards, rather than have to keep adding patterns for each? It seems it would be cleaner to post parses for optional fields that may or may not be present in the parsed 'msg' field?

Yes you could parse out msg first and then parse msg using another parse_grok to pull out additional fields.

• This all now parses and ends up in loki/grafana as json, but the fields do not end up as labels i can use in queries. i still am limited to 'app' and 'env' only (labels added by the 'sink.to_indexer' section in my toml. So im still forced to do a text search to find certain things i'm looking for.

Only labels added via labels in the Loki sink configuration will be searchable. In this case you probably want to add additional ones like:

labels = { app="app_logs", env="dev", app_id="{{app_id}"}

The app_id label uses Vector's template syntax.

[dss010101]

Yes you could parse out msg first and then parse msg using another parse_grok to pull out additional fields.

Thanks for the quick reply. i was reading the vrml documentation/examples here: https://vector.dev/docs/reference/vrl/examples/#multiple-parsing-strategies

and trying this...but while i dont see any errors, it also doesnt seem to parse/push any data:

source = '''
    parsed_fields = 
        parse_groks(
            .message, 
            patterns:[
                "\\[%{TIMESTAMP_ISO8601:log_time}\\]\\[%{INT:process}:%{INT:thread}\\]\\[%{WORD:severity}\\]\\[%{WORD:module}.%{WORD:func}\\] %{GREEDYDATA:msg}",
                "\\[%{TIMESTAMP_ISO8601:log_time}\\]\\[%{INT:process}:%{INT:thread}\\]%{WORD:severity}:%{WORD:module}:%{GREEDYDATA:msg}"
            ]
        ) ??
        parse_regex(.msg,r' app_id:(?P<app_id>\w+) (?P<msg>.*)$')
    . = merge(., parsed_fields)
'''

[dss010101]

wondering if this may be causing my most recent issues...
Is there a way to show what log line this is trying to parse?
When you have multiple patterns, what happens if none match the pattern? does it ship the entire line as is anyway?
WIth an array of patterns, like i have defined, does it match only one? is there an order precedence based on the list order?

2023-05-15T23:47:53.543728Z ERROR transform{component_kind="transform" component_id=log_parser component_type=remap component_name=log_parser}: vector::internal_events::remap: Mapping failed with event. error="function call error for \"parse_groks\" at (9:391): unable to parse grok: value does not match any rule" error_type="conversion_failed" stage="processing" internal_log_rate_limit=true
2023-05-15T23:47:53.543785Z ERROR transform{component_kind="transform" component_id=log_parser component_type=remap component_name=log_parser}: vector::internal_events::remap: Internal log [Mapping failed with event.] is being rate limited.

[jszwedko]

You can do something like:

parsed, err = parse_groks(...)
if err != null {
  log(.)
}

To log the event if it failed to parse.

I believe parse_groks will try to parse in the order you define the patterns until one parses correctly.

[dss010101]

this is helpful, thank you!

[dss010101]

@jszwedko quite strange..if add error handling and then query by 'file' in grafana, i get only one record populated, and the rest are empty entries ...if i remove the error handling, clean the volumes and restart the containers, i see all the entries. any ideas?

source = '''
    ., err |= parse_groks(
            .message, 
            patterns:[
                "\\[%{TIMESTAMP_ISO8601:log_time}\\]\\[%{INT:pid}:%{INT:tid}\\]\\[%{WORD:severity}\\]\\[%{WORD:module}.%{WORD:func}\\] app_id:%{NOTSPACE:app_id} %{GREEDYDATA:msg}",
                "\\[%{TIMESTAMP_ISO8601:log_time}\\]\\[%{INT:pid}:%{INT:tid}\\]\\[%{WORD:severity}\\]\\[%{WORD:module}.%{WORD:func}\\] %{GREEDYDATA:msg}",
                "\\[%{TIMESTAMP_ISO8601:log_time}\\]\\[%{INT:pid}:%{INT:tid}\\]%{WORD:severity}:%{WORD:module}:%{GREEDYDATA:msg}"
            ]
    )
    if err != null {
        log("XXX")
        log(.)
    }
'''

[spencergilbert]

The issue with this program appears to be the following:

    ., err |= parse_groks(...

You wouldn't want to merge there, and instead:

parsed, err = parse_groks(...)
if err != null {
  parsed = parse_regex(...)
} else {
  . = merge(., parsed)
}

[dss010101]

The issue with this program appears to be the following:

    ., err |= parse_groks(...

You wouldn't want to merge there, and instead:

parsed, err = parse_groks(...)
if err != null {
  parsed = parse_regex(...)
} else {
  . = merge(., parsed)
}

If im reading this code right..does this mean if there is an error, essentially 'parsed' on that first line of your code is ignored?
it looks like your re-assigning parsed again if there is an error - so im assuming if an error is raised, then parsed is null/empty, correct?
what are the conditions that would cause an error - is it more run time, or does it raise an error if none of the patterns match?
if the latter, then i assume '.' is just the entire line, correct?

[dss010101]

think i finally got this to work they way i wanted. thanks alot for the help @jszwedko

source = '''
    . |= parse_groks!(
            .message, 
            patterns:[
                "\\[%{TIMESTAMP_ISO8601:log_time}\\]\\[%{INT:pid}:%{INT:tid}\\]\\[%{WORD:severity}\\]\\[%{WORD:module}.%{WORD:func}\\] app_id:%{NOTSPACE:app_id} %{GREEDYDATA:msg}",
                "\\[%{TIMESTAMP_ISO8601:log_time}\\]\\[%{INT:pid}:%{INT:tid}\\]\\[%{WORD:severity}\\]\\[%{WORD:module}.%{WORD:func}\\] %{GREEDYDATA:msg}",
                "\\[%{TIMESTAMP_ISO8601:log_time}\\]\\[%{INT:pid}:%{INT:tid}\\]%{WORD:severity}:%{WORD:module}:%{GREEDYDATA:msg}"
            ]
    )
    if .app_id == null{
        parsed = parse_regex!(.message, r'^.+app_id:(?P<app_id>\w+) (?P<msg>.*)$')
        . = merge(., parsed)
    }
    
'''

Still not sure why the error handler causes that output above though. im guessing maybe if you are returning an error, it maybe exiting early so you can do the handling. which would mean that multiple parsers in such a case isn't a good idea, since you likely are going to have the more specific patterns at the top - the ones that are more likely to cause a miss/error.

[dss010101]

So i did some more testing with this today and it really is puzzling -

source = '''
    . |= parse_groks!(
            .message, patterns:[
                "\\[%{TIMESTAMP_ISO8601:log_time}\\]\\[%{INT:pid}:%{INT:tid}\\]\\[%{LOGLEVEL:log_level}\\]\\[%{WORD:module}.%{NOTSPACE:func}\\] run_id:%{NOTSPACE:run_id} %{GREEDYDATA:msg}",
                "\\[%{TIMESTAMP_ISO8601:log_time}\\]\\[%{INT:pid}:%{INT:tid}\\]\\[%{LOGLEVEL:log_level}\\]\\[%{WORD:module}.%{NOTSPACE:func}\\] %{GREEDYDATA:msg}",          
                "\\[%{TIMESTAMP_ISO8601:log_time}\\]\\[%{INT:pid}:%{INT:tid}\\]%{LOGLEVEL:log_level}:%{WORD:module}:%{GREEDYDATA:msg}",                
            ]
    )
'''

My log file patterns has changed over the past few months.
The bottom pattern should match logs from about 2 month ago.
The 2nd pattern from about a month ago.
And the first pattern should match log entries from a few weeks to current.

With all three grok patterns in the toml file, i see data only from about 2 months ago and older.
With only first two two patterns, i see ONLY data from about a month ago and older
With only the first pattern, i see the most recent logs.

I have no clue what's going on here because the grok statements do parse the various log lines fine when testing standalone.

I am seeing these errors on startup of vector...feels like for earlier logs, an exception is happening on the first grok pattern and it is causing maybe the entire log/file to not be processed. Either that or maybe these brackets are causing issues. i dont know

2023-05-30T02:17:20.703817Z ERROR transform{component_kind="transform" component_id=log_parser component_type=remap component_name=log_parser}: vector::internal_events::remap: Mapping failed with event. error="function call error for \"parse_groks\" at (9:611): unable to parse grok: value does not match any rule" error_type="conversion_failed" stage="processing" internal_log_rate_limit=true
2023-05-30T02:17:20.703908Z ERROR transform{component_kind="transform" component_id=log_parser component_type=remap component_name=log_parser}: vector::internal_events::remap: Internal log [Mapping failed with event.] is being rate limited.
2023-05-30T02:17:21.539541Z ERROR sink{component_kind="sink" component_id=to_indexer component_type=loki component_name=to_indexer}:request{request_id=1}: vector::sinks::util::retries: Non-retriable error; dropping the request. error=Server responded with an error: 400 Bad Request internal_log_rate_limit=true
2023-05-30T02:17:21.539561Z ERROR sink{component_kind="sink" component_id=to_indexer component_type=loki component_name=to_indexer}:request{request_id=1}: vector_common::internal_event::service: Service call failed. No retries or retries exhausted. error=Some(ServerError { code: 400 }) request_id=1 error_type="request_failed" stage="sending" internal_log_rate_limit=true