Slow file reads/writes on log forwarding

[ahoiroman]

Question

Hi there,

I am taking my first steps with vector, so please be kind ;-)

What I want to do: At the moment, my webserver and php-fpm are logging to /var/log/. The structure is like this:

root@server1:~# tree /var/log/caddy/
/var/log/caddy/
├── user_bazqux
│   └── bazqux.com
│       └── bazqux.com.log
├── user_foo-bar
│   └── foo-bar.com
│       └── foo-bar.com.log
├── user_foobar
│   └── foobar.com
│       └── foobar.com.log
├── user_test1
│   └── test1.com
│       └── test1.com.log
├── user_test2
│   └── test2.com
│       └── test2.com.log
├── user_test3
│   └── test3.com
│       └── test3.com.log
├── user_test4
│   └── test4.com
│       └── test4.com.log
├── user_test5
│   └── test5.com
│       └── test5.com.log
├── user_test6
│   └── test6.com
│       └── test6.com.log
└── user_test7
    └── test7.com
        └── test7.com.log

21 directories, 10 files

Same for PHP:

root@server1:~# tree /var/log/php/
/var/log/php/
├── user_foo-bar
│   └── foo-bar.com
├── user_foobar
│   └── foobar.com
│       └── error.log
├── user_test1
│   └── test1.com
├── user_test2
│   └── test2.com
├── user_test3
│   └── test3.com
├── user_test4
│   └── test4.com
├── user_test5
│   └── test5.com
├── user_test6
│   └── test6.com
└── user_test7
    └── test7.com

My users are used to have logs as files - so for a transformation period, I want to redirect these logs to the user's home dir:

    /var/log/caddy/user_test6/test6.com/ -> /home/user_test6/logs/caddy/test6.com

That works and while I need to rotate them manually, this is also quite stable. But it is slow. Sometimes logs that are present in the caddy log immediately after page hit take up to 10s to be visible in the forwarded log file. And that on a local test system without real traffic.

This is an indicator for me that I am doing something that is not correct.

Vector Config

data_dir: "/var/lib/vector"

sources:
  caddy_logs:
    type: "file"
    include:
      - "/var/log/caddy/**/*.log"
    ignore_older_secs: 86400
    read_from: "end"
    max_line_bytes: 102400
    glob_minimum_cooldown_ms: 1000
    fingerprinting:
      strategy: "device_and_inode"
      ignored_header_bytes: 0

  php_logs:
    type: "file"
    include:
      - "/var/log/php/**/*.log"
    ignore_older_secs: 86400
    read_from: "end"
    max_line_bytes: 102400
    glob_minimum_cooldown_ms: 1000
    fingerprinting:
      strategy: "device_and_inode"
      ignored_header_bytes: 0

transforms:
  extract_paths:
    type: "remap"
    inputs: ["caddy_logs"]
    source: |
      path_parts = split(string!(.file), "/")
      if length(path_parts) >= 7 {
        tenant = string!(path_parts[4])
        domain = string!(path_parts[5])
        .target_path = "/home/" + tenant + "/logs/caddy/" + domain + "/access.log"
        del(.file)
      } else {
        abort
      }

  extract_php_paths:
    type: "remap"
    inputs: ["php_logs"]
    source: |
      path_parts = split(string!(.file), "/")
      if length(path_parts) >= 7 {
        user = string!(path_parts[4])
        domain = string!(path_parts[5])
        filename = string!(path_parts[6])
        .target_path = "/home/" + user + "/logs/php/" + domain + "/" + filename
        del(.file)
      } else {
        abort
      }

sinks:
  user_file_output:
    type: "file"
    inputs: ["extract_paths", "extract_php_paths"]
    path: "{{ target_path }}"
    encoding:
      codec: "text"
    buffer:
      type: "memory"
      max_events: 1000
      when_full: "block"

Vector Logs

root@server1:~# journalctl -u vector --no-pager
Jul 25 02:56:49 server1 systemd[1]: Starting vector.service - Vector...
Jul 25 02:56:49 server1 vector[69442]: √ Loaded ["/etc/vector/vector.yaml"]
Jul 25 02:56:49 server1 vector[69442]: √ Component configuration
Jul 25 02:56:49 server1 vector[69442]: √ Health check "user_file_output"
Jul 25 02:56:49 server1 vector[69442]: ------------------------------------
Jul 25 02:56:49 server1 vector[69442]:                            Validated
Jul 25 02:56:49 server1 systemd[1]: Started vector.service - Vector.
Jul 25 02:56:49 server1 vector[69445]: 2025-07-25T07:56:49.675944Z  INFO vector::app: Log level is enabled. level="info"
Jul 25 02:56:49 server1 vector[69445]: 2025-07-25T07:56:49.676111Z  INFO vector::app: Loading configs. paths=["/etc/vector/vector.yaml"]
Jul 25 02:56:49 server1 vector[69445]: 2025-07-25T07:56:49.680433Z  INFO vector::topology::running: Running healthchecks.
Jul 25 02:56:49 server1 vector[69445]: 2025-07-25T07:56:49.680515Z  INFO vector::topology::builder: Healthcheck passed.
Jul 25 02:56:49 server1 vector[69445]: 2025-07-25T07:56:49.680808Z  INFO vector: Vector has started. debug="false" version="0.48.0" arch="aarch64" revision="a67e4e2 2025-06-30 18:25:45.272082383"
Jul 25 02:56:49 server1 vector[69445]: 2025-07-25T07:56:49.680817Z  INFO vector::app: API is disabled, enable by setting `api.enabled` to `true` and use commands like `vector top`.
Jul 25 02:56:49 server1 vector[69445]: 2025-07-25T07:56:49.681067Z  INFO source{component_kind="source" component_id=php_logs component_type=file}: vector::sources::file: Starting file server. include=["/var/log/php/**/*.log"] exclude=[]
Jul 25 02:56:49 server1 vector[69445]: 2025-07-25T07:56:49.681148Z  INFO source{component_kind="source" component_id=caddy_logs component_type=file}: vector::sources::file: Starting file server. include=["/var/log/caddy/**/*.log"] exclude=[]
Jul 25 02:56:49 server1 vector[69445]: 2025-07-25T07:56:49.681752Z  INFO source{component_kind="source" component_id=php_logs component_type=file}:file_server: file_source::checkpointer: Attempting to read legacy checkpoint files.
Jul 25 02:56:49 server1 vector[69445]: 2025-07-25T07:56:49.681753Z  INFO source{component_kind="source" component_id=caddy_logs component_type=file}:file_server: file_source::checkpointer: Attempting to read legacy checkpoint files.
Jul 25 02:56:49 server1 vector[69445]: 2025-07-25T07:56:49.684117Z  INFO source{component_kind="source" component_id=caddy_logs component_type=file}:file_server: vector::internal_events::file::source: Found new file to watch. file=/var/log/caddy/user_foobar/foobar.com/foobar.com.log
Jul 25 02:56:49 server1 vector[69445]: 2025-07-25T07:56:49.684136Z  INFO source{component_kind="source" component_id=caddy_logs component_type=file}:file_server: vector::internal_events::file::source: Internal log [Found new file to watch.] is being suppressed to avoid flooding.
Jul 25 03:39:19 server1 vector[69445]: 2025-07-25T08:39:19.151902Z  INFO source{component_kind="source" component_id=php_logs component_type=file}:file_server: vector::internal_events::file::source: Found new file to watch. file=/var/log/php/user_foobar/foobar.com/error.log

[thomasqueirozb]

Hi @ahoiroman, it looks like you aren't doing anything wrong and you hit a weird issue with the file source/sink. I looked into it and got a minimal config:

data_dir: /tmp/vector_data_dir/

api:
  enabled: true

sources:
  in:
    type: "file"
    include:
      - "/tmp/in/*.log"

transforms:
  set_target_path:
    type: "remap"
    inputs: ["in"]
    source: |
      path_parts = split(string!(.file), "/")
      filename = path_parts[3]
      .target_path = "/tmp/out/" + filename

sinks:
  out:
    type: "file"
    inputs: ["set_target_path"]
    path: "{{ target_path }}"
    encoding:
      codec: "raw_message"
    buffer:
      type: "memory"
      max_events: 10
      when_full: "block"

and used this small script to test it

#!/usr/bin/env python3
import os
import time

IN              = "/tmp/in"
COPY            = "/tmp/out"
NUM_FILES       = 10      # number of files
WRITE_SIZE      = 10     # bytes to write per file each interval
INTERVAL        = 1.0     # seconds between write/check rounds
THRESHOLD       = WRITE_SIZE # warn if delta ≥ this many bytes

filenames = [f"test{i}.log" for i in range(1, NUM_FILES + 1)]

# Prepare file handles and corresponding copy paths
files = []
copy_paths = []

for filename in filenames:
    orig = os.path.join(IN, filename)
    copy = os.path.join(COPY, filename)

    # ensure directories exist
    os.makedirs(os.path.dirname(orig), exist_ok=True)

    # open originals unbuffered for append
    files.append(open(orig, "ab", buffering=0))

    copy_paths.append(copy)

print(f"Opened {len(files)} files for testing.")
iteration = 0

try:
    while True:
        iteration += 1
        # Write random bytes to each original file
        for f in files:
            data = os.urandom(WRITE_SIZE)
            f.write(data)
            f.flush()
            os.fsync(f.fileno())

        # Report sizes and check differences
        print(f"\n--- Iteration {iteration} ---")

        time.sleep(INTERVAL)
        for idx, (f, copy_path) in enumerate(zip(files, copy_paths), 1):
            orig_sz = os.path.getsize(f.name)
            copy_sz = os.path.getsize(copy_path) if os.path.exists(copy_path) else 0
            delta  = abs(orig_sz - copy_sz)
            line = f"[File #{idx:02}] orig={orig_sz:>5}B, copy={copy_sz:>5}B"
            if delta >= THRESHOLD:
              line += f"  ⚠️ Δ={delta:>5}B ≥ {THRESHOLD}"
            print(line)

except KeyboardInterrupt:
    print("\nInterrupted by user, closing files…")
finally:
    for f in files:
        f.close()

It seems like Vector is kind of slow to process/send small changes in files. If you tweak some of the values and write a couple of kb/sec before spinning up Vector and let to file grow to a couple of kb and then spin up Vector you'll see that the output file size will catch up in < 1 sec but it will consistently stay a few bytes behind. This issue is even more visible when writes are smaller. Using vector tap I was able to see the data being written which makes it seem like it is an issue in the file source.

One "solution" I found is to limit max_events: 1 so that you'll see more consistent/full writes but I wouldn't really recommend this since you might hit issues during high loads. I don't have a definitive solution at this time but you can always look into it and submit a PR if you find the underlying issue. One last thing I'll mention is that there is a PR for a new file source which may fix this issue but I haven't tested it