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