After removal of checkpoint files multiline logs ingested line by line

[podshivalovdv]

Hi :)
I'm testing configuration for Vector and need to be able to re-ingest the same data in staging system to make sure that it is ingested properly (I did tests on samples, now need real data).

The logs are multiline and have timestamp in the beginning of each message. I use source like this :

  api_logs:
    type: file
    glob_minimum_cooldown_ms: 2000
    include:
      - /opt/app/data/logs/*.log
    multiline.start_pattern: '^[0-9]{4}-[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}'
    multiline.condition_pattern: '^[0-9]{4}-[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}'
    multiline.mode: "halt_before"
    multiline.timeout_ms: 1000

And that data is send to Vector's console. Logs are not that big.

And I've noticed a strange behavior: if I remove a checkpoint file related to api_logs and restart Vector then vector disregards the multiline configuration and emerges several one-line events instead of a multiline event.

More over, some times I have to restart Vector service several times I see data from some of the files in the console.

Is this an expected behavior or is it a bug?

Thanks.

[bruceg]

This sounds like you've hit a bug. Does it produce all the logs as one-line events, or just some of them?

Could you clarify what you mean by you see data from some of the files in the console when you restart? If I understand your configuration, this would be the usual case (file source, console sink).

[podshivalovdv]

Hi,

This is happening for at least 2 log files which have multiple lines per event.

Could you clarify what you mean by you see data from some of the files in the console when you restart? If I understand your configuration, this would be the usual case (file source, console sink).
Sorry, I was not clear, what I meant is that I saw that the same source file was read 2 times by the Vector and the same data appeared 2 times (but not in the same form).

I've made a simplified example to illustrate the problem. Please see bellow. Please note that that is not the exact configuration and files/datasourses are renamed, I've also skipped the Transform which does parsing as it is too big, but I hope it will illustrate the problem well enough.

Here is how the test file looks like:
cat /var/log/log_samples/integrations.log

2022-08-28 12:56:44: sendData
HTTP Method: POST
RequestData: {xxx}
Response: {
  "response": {
    "caseId": "12345"
  },
  "errors": []
}

2022-08-28 15:08:30: sendData
HTTP Method: POST
RequestData: {yyy}
Response: {
  "response": {
    "caseId": "67890"
  },
  "errors": []
}

And here is the source and the sink:

sourses:
  api_logs:
    type: file
    glob_minimum_cooldown_ms: 2000
    include:
      - /var/log/log_samples/*.log
    multiline.start_pattern: '^[0-9]{4}-[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}'
    multiline.condition_pattern: '^[0-9]{4}-[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}'
    multiline.mode: "halt_before"
    multiline.timeout_ms: 1000

sinks:
  vector_test:
    type: console
    inputs:
      - api_logs
    encoding: json

Now I'm removing the checkpoints.json and restarting the vector 2 times

rm -rf /var/lib/vector/api_logs/checkpoints.json
systemctl restart vector
systemctl restart vector

Everything looks normal in the Vector's console after the first restart - I'm getting 2 properly parsed events in Json format.
But after the second restart, Vector goes nuts and emits last 9 lines from integrations.log as individual events:

tail -n 500 /var/log/vector |grep -E "Vector has stopped|healthcheck|integrations.log"

2022-08-31T08:12:36.026543Z  INFO vector: Vector has stopped.
2022-08-31T08:12:36.270552Z  INFO vector::topology::running: Running healthchecks.
2022-08-31T08:12:36.312589Z  INFO source{component_kind="source" component_id=api_logs component_type=file component_name=api_logs}:file_server: vector::internal_events::file::source: Found new file to watch. file=/var/log/log_samples/integrations.log
{"file":"/var/log/log_samples/integrations.log","host":"vector","message":"sendData\nHTTP Method: POST \nRequestData: {xxx}\nResponse: {\n  \"response\": {\n    \"caseId\": \"12345\"\n  },\n  \"errors\": []\n}\n","orig_message":"2022-08-28 12:56:44: sendData\nHTTP Method: POST \nRequestData: {xxx}\nResponse: {\n  \"response\": {\n    \"caseId\": \"12345\"\n  },\n  \"errors\": []\n}\n","private_ip":"172.17.0.2","source_type":"file","timestamp":"2022-08-28T12:56:44Z"}
{"file":"/var/log/log_samples/integrations.log","host":"vector","message":"sendData\nHTTP Method: POST \nRequestData: {yyy}\nResponse: {\n  \"response\": {\n    \"caseId\": \"67890\"\n  },\n  \"errors\": []\n}\n","orig_message":"2022-08-28 15:08:30: sendData\nHTTP Method: POST \nRequestData: {yyy}\nResponse: {\n  \"response\": {\n    \"caseId\": \"67890\"\n  },\n  \"errors\": []\n}\n","private_ip":"172.17.0.2","source_type":"file","timestamp":"2022-08-28T15:08:30Z"}
2022-08-31T08:13:00.934188Z  INFO vector: Vector has stopped.
2022-08-31T08:13:01.444771Z  INFO vector::topology::running: Running healthchecks.
2022-08-31T08:13:01.470377Z  INFO source{component_kind="source" component_id=api_logs component_type=file component_name=api_logs}:file_server: vector::internal_events::file::source: Resuming to watch file. file=/var/log/log_samples/integrations.log file_position=171
{"file":"/var/log/log_samples/integrations.log","host":"vector","message":"HTTP Method: POST ","orig_message":"HTTP Method: POST ","private_ip":"172.17.0.2","source_type":"file","timestamp":"2022-08-31T08:13:01.472449200Z"}
{"file":"/var/log/log_samples/integrations.log","host":"vector","message":"RequestData: {yyy}","orig_message":"RequestData: {yyy}","private_ip":"172.17.0.2","source_type":"file","timestamp":"2022-08-31T08:13:01.472460200Z"}
{"file":"/var/log/log_samples/integrations.log","host":"vector","message":"Response: {","orig_message":"Response: {","private_ip":"172.17.0.2","source_type":"file","timestamp":"2022-08-31T08:13:01.472470900Z"}
{"file":"/var/log/log_samples/integrations.log","host":"vector","message":"  \"response\": {","orig_message":"  \"response\": {","private_ip":"172.17.0.2","source_type":"file","timestamp":"2022-08-31T08:13:01.472483200Z"}
{"file":"/var/log/log_samples/integrations.log","host":"vector","message":"    \"caseId\": \"67890\"","orig_message":"    \"caseId\": \"67890\"","private_ip":"172.17.0.2","source_type":"file","timestamp":"2022-08-31T08:13:01.472494100
Z"}
{"file":"/var/log/log_samples/integrations.log","host":"vector","message":"  },","orig_message":"  },","private_ip":"172.17.0.2","source_type":"file","timestamp":"2022-08-31T08:13:01.472505Z"}
{"file":"/var/log/log_samples/integrations.log","host":"vector","message":"  \"errors\": []","orig_message":"  \"errors\": []","private_ip":"172.17.0.2","source_type":"file","timestamp":"2022-08-31T08:13:01.472516200Z"}
{"file":"/var/log/log_samples/integrations.log","host":"vector","message":"}","orig_message":"}","private_ip":"172.17.0.2","source_type":"file","timestamp":"2022-08-31T08:13:01.472528500Z"}
{"file":"/var/log/log_samples/integrations.log","host":"vector","message":"","orig_message":"","private_ip":"172.17.0.2","source_type":"file","timestamp":"2022-08-31T08:13:01.472538700Z"}

[bruceg]

Thank you for the comprehensive detail. I have confirmed this bug in the current source and have opened up an issue to track it.

[podshivalovdv]

Super, thanks a lot!