Setting Vector up in production env, but got some wired error msgs, please help us. Urgent!

[syzcch]

Hi Team,

We are trying to use Vector to fetch gzip log files in production environment and we are facing tight deadline but we got error messages like this:

2022-09-07T07:48:07.860813Z ERROR transform{component_kind="transform" component_id=parse_logs component_type=remap component_name=parse_logs}: vector::internal_eve
nts::remap: Internal log [Mapping failed with event.] has been rate limited 3711 times.
2022-09-07T07:48:07.860936Z ERROR transform{component_kind="transform" component_id=parse_logs component_type=remap component_name=parse_logs}: vector::internal_eve
nts::remap: Mapping failed with event. error="function call error for \"parse_json\" at (106:127): unable to parse json: invalid number at line 1 column 2" error_ty
pe="conversion_failed" stage="processing" internal_log_rate_secs=10
2022-09-07T07:48:07.861021Z ERROR transform{component_kind="transform" component_id=parse_logs component_type=remap component_name=parse_logs}: vector::internal_eve
nts::remap: Internal log [Mapping failed with event.] is being rate limited.
2022-09-07T07:48:31.829761Z ERROR transform{component_kind="transform" component_id=parse_logs component_type=remap component_name=parse_logs}: vector::internal_eve
nts::remap: Internal log [Mapping failed with event.] has been rate limited 4323 times.
2022-09-07T07:48:31.829801Z ERROR transform{component_kind="transform" component_id=parse_logs component_type=remap component_name=parse_logs}: vector::internal_eve
nts::remap: Mapping failed with event. error="function call error for \"parse_json\" at (106:127): unable to parse json: invalid number at line 1 column 2" error_ty
pe="conversion_failed" stage="processing" internal_log_rate_secs=10
2022-09-07T07:48:31.829894Z ERROR transform{component_kind="transform" component_id=parse_logs component_type=remap component_name=parse_logs}: vector::internal_eve
nts::remap: Internal log [Mapping failed with event.] is being rate limited.

And out config is like that

[sources.gz_logs]
    type = "file"
    max_line_bytes = 1024000
    include = [ "/.../**/*.gz" ]
    exclude = [ "/../**/*.gz" , "/.../**/*.gz" ......]
    multiline.mode = "halt_with"
    multiline.condition_pattern = "-----------------------------------------------------------------------"
    multiline.timeout_ms = 1000
    multiline.start_pattern = '^\{'
    # Parse gz_logs
[transforms.parse_logs]
    type = "remap"
    inputs = ["gz_logs"]
    source = """
    lines,err = split(.message, "\n")
    .message = lines[0] + lines[1]
    .message = to_string(.message)
    .message = parse_json!(.message)
    """
    # send parsed logs to Kafka
   ......

Could you please help us to figure the errors out? Thank you so much.

[jszwedko]

Hi @syzcch !

The error is indicating that .message is not valid JSON. I'd recommend logging out the event to see what it looks like with something like:

res, err = parse_json(.mesasge)
if err != nil {
  log(.message)
  abort
} else {
  .message = res
}

This will log messages that are invalid JSON. Hopefully this gets you pointed in the right direction.

[syzcch]

I don't see why Vector would be writing to a /local directory, no. It should be limited to writing to /home/user/vector_data. With that configuration I'd expect only checkpoints to be in the data directory.

It's another service writing log onto the disk. And we found that if disk space is almost full then we got the error messages like this from vector.

2022-09-07T07:48:07.860813Z ERROR transform{component_kind="transform" component_id=parse_logs component_type=remap component_name=parse_logs}: vector::internal_events::remap: Internal log [Mapping failed with event.] has been rate limited 3711 times.
2022-09-07T07:48:07.860936Z ERROR transform{component_kind="transform" component_id=parse_logs component_type=remap component_name=parse_logs}: vector::internal_events::remap: Mapping failed with event. error="function call error for \"parse_json\" at (106:127): unable to parse json: invalid number at line 1 column 2" error_type="conversion_failed" stage="processing" internal_log_rate_secs=10
2022-09-07T07:48:07.861021Z ERROR transform{component_kind="transform" component_id=parse_logs component_type=remap component_name=parse_logs}: vector::internal_events::remap: Internal log [Mapping failed with event.] is being rate limited.

Is that a reasonable behavior?

[bruceg]

No, it is not reasonable for vector to fail to parse data when the disk space is low. More likely is that the data being read is truncated in some form. I will echo @jszwedko's suggestion to log data that fails to parse so you can see what vector is having problems with and possibly correlate it with the actual data files for comparison.

[syzcch]

Hi @jszwedko @bruceg ,

One follow up question is we want to fetch the latest and new log files and ignore all existing log files and we are using exclude plus include to do it. Our config is like this:

exclude = [ "/logpath/Prod/2022/06/**/.gz" , "/logpath/Prod/2022/07/**/*.gz" ,"/logpath/Prod/2022/08/**/*.gz" ,"/logpath/Prod/2022/09/01/**/*.gz" ,"/logpath/Prod/2022/09/02/**/*.gz" ,  ...... ,"/logpath/Prod/2022/09/21/03/*.gz","/logpath/Prod/2022/09/21/04/*.gz"]

include = [ "/logpath/Prod/**/requests*.gz" ]

And the output is like this:

2022-09-22T09:19:46.463407Z  INFO vector::app: Log level is enabled. level="vector=info,codec=info,vrl=info,file_source=info,tower_limit=trace,rdkafka=info,buffers=info,kube=info"
2022-09-22T09:19:46.493744Z  INFO vector::app: Loading configs. paths=["/root/.vector/config/vector.toml"]
2022-09-22T09:19:46.816334Z  INFO vector::topology:🏃‍♂️ Running healthchecks.
2022-09-22T09:19:46.819711Z  INFO vector: Vector has started. debug="false" version="0.23.3" arch="x86_64" build_id="af8c9e1 2022-08-10"
2022-09-22T09:19:46.819763Z  INFO vector::app: API is disabled, enable by setting `api.enabled` to `true` and use commands like `vector top`.
2022-09-22T09:19:46.838182Z  INFO source{component_kind="source" component_id=gz_logs component_type=file component_name=gz_logs}: vector::sources::file: Starting file server. include
=...... , exclude=.......
2022-09-22T09:19:46.849570Z  INFO vector::topology::builder: Healthcheck: Passed.
2022-09-22T09:19:46.856036Z  INFO source{component_kind="source" component_id=gz_logs component_type=file component_name=gz_logs}:file_server: file_source::checkpointer: Loaded checkp
oint data.

There is no info about "find new file", so it could not get data from the log files.

If we delete exclude in the config and set include to point to a specific day, Vector works as expected. So could you please help us about that? How to update the config file to only fetch new generated logs after the vector progress started and ignore all existing log files. Thank you so much.

[summerance]

@jszwedko ,I'm also curious about syzcch's question above.why There is no info about "find new file" while the requests*.gz file mentioned in include does exist.Thanks!

[syzcch]

Hi @jszwedko ,

Could you please help me to check my question? Thank you so much. Very urgent and eager to done the deployment in Prod env.

[summerance]

@jszwedko @bruceg Hi,There are a steady stream of logs generated in my folder. Is there any configuration to ignore the previous logs in the folder and only find the logs generated after Vector is started? Looking forward to your reply!

[jszwedko]

Hi @summerance . You can use https://vector.dev/docs/reference/configuration/sources/file/#ignore_older_secs

[summerance]

Hi @summerance . You can use https://vector.dev/docs/reference/configuration/sources/file/#ignore_older_secs

I have set ignore_older_secs = 60, I restart Vector after 60 seconds, still can find the log generated before 60s

[summerance]

@jszwedko my configuration is

data_dir = "/.../log/"
[sources.gz_logs]
type = "file"
ignore_older_secs = 60
max_line_bytes = 1024000
include = [ "/.../log/*.gz" ]

Does 60 mean 60 seconds? And it does not take effect.Still can find the old log when run Vector.