Source file being truncated results in duplicate events being emitted

[mkudukin]

I was testing a specific setup with the Vector 0.41.1 and observed duplicate events in my sink. The setup is the following.

I have the single log file, which Vector reads as a File Source. The file is the only included path without any wildcards. My application doesn't use any log rotation, it just opens the same log file, truncates it and starts logging from the beginning of the file.
It seems that Vector doesn't like it. Let me try to explain this step by step:

1. My app is started, logged something to the file. Let's say it logged 10 lines.
2. Vector started and consumed the file till the end, then continues watching for new data.
3. My app is restarted, truncated the file, and this time it quickly logs 100 lines to it.
4. Vector detects (using fingerprinting) that the file was replaced, and starts a new reader for it.
5. Vector reads all 100 lines. But afterwards the problem is happening.
6. The old reader of the file, which was kept at the offset of 10 lines, is forced to read the file up to EOF (i.e. lines 11-100). However, this is not the same file anymore!
7. This results lines 1-100 followed by 11-100 being sent to the sink.

The old reader was not shut down immediately. There are some seconds of timeout, after which that reader reads the file up to EOF and only then it is terminated. It is useful for the classic log rotation strategies, but breaks the case of one log file being actively overwritten.

Here is how it looks in the Vector's log:

INFO source{component_kind="source" component_id=file-BOTH-session-lb3mc2f6xk component_type=file}:file_server: vector::internal_events::file::source: Found new file to watch. file=/home/michael/file.log
INFO source{component_kind="source" component_id=file-BOTH-session-lb3mc2f6xk component_type=file}:file_server: vector::internal_events::file::source: Found new file to watch. file=/home/michael/file.log
INFO source{component_kind="source" component_id=file-BOTH-session-lb3mc2f6xk component_type=file}:file_server: vector::internal_events::file::source: Stopped watching file. file=/home/michael/file.log reached_eof="true"

1. 1st reader picks the file
2. 2nd reader picks the overwritten file
3. 1st reader reads the file and stops

I reproduced it on Windows 10 and Ubuntu (in WSL).

Thank you. Any thoughts welcome!

[pront]

Hi @mkudukin, if this is reproducible please open a bug https://github.com/vectordotdev/vector/issues/new?template=bug.yml so we can track it properly. Is this behavior deterministic? If yes, please also include reproduction steps. Otherwise, please include Vector config and any other details to help us reproduce on our side.

[mkudukin]

Thank you @pront, I opened the bug #23619, which have reproduction script attached.