Skip to content

vlagent: panic on unreadable file outside fileCollector.glob during rotated-file lookup #1796

Description

@Adriankusiak

Describe the bug

vlagent panics and exits when a file it was never configured to read exists in the same directory as a tailed log file and is not readable by the vlagent user.

With -fileCollector.glob=/app/logs/*.log I would expect vlagent to only need access to *.log in that directory. However, on checkpoint recovery findRenamedFile scans the entire directory to locate a rotated file by inode, and opens every entry to stat it

In our case a JVM heap dump (mode 0600, owned by the application user) was written into the log directory and vlagent died on it.

To Reproduce

  1. A log directory containing one log file and one unreadable non-log file:
   mkdir -p /tmp/vlrepro/logs /tmp/vlrepro/data
   echo "line one" > /tmp/vlrepro/logs/app.log
   touch /tmp/vlrepro/logs/heap.hprof && chmod 000 /tmp/vlrepro/logs/heap.hprof
  1. Start vlagent tailing only *.log, so the unreadable file is out of scope:
   ./vlagent-prod -fileCollector.glob='/tmp/vlrepro/logs/*.log'
     -remoteWrite.url=http://127.0.0.1:19428/insert/native
     -tmpDataPath=/tmp/vlrepro/data -httpListenAddr=127.0.0.1:19429
  1. Stop it with SIGTERM so the checkpoint is flushed:
   cat /tmp/vlrepro/data/vlagent-file-checkpoints.json
   [{"path":"/tmp/vlrepro/logs/app.log","inode":93608490,"fingerprint":...,"offset":9}]
  1. Rotate so the inode changes, without leaving the old file behind:
   rm /tmp/vlrepro/logs/app.log
   echo "line two" > /tmp/vlrepro/logs/app.log
  1. Start vlagent again with the same flags. It panics and exits 2:
   panic  VictoriaLogs/app/vlagent/tail/tailer.go:359
   FATAL: cannot open file: open /tmp/vlrepro/logs/heap.hprof: permission denied

Version

Deployed (where the incident occurred): vlagent-20260617-045332-tags-v1.51.0-0-gb6524fb773
Reproduced on latest release: vlagent-20260716-022218-tags-v1.52.0-0-g46a54c976f

Logs

Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]: panic: FATAL: cannot open file: open /sfx1/4/siege/apps/sfx/logs/20-client-destinations-dump.hprof: permission de>
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]: goroutine 176 [running]:
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]: sync.(*WaitGroup).Go.func1.1()
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]:         sync/waitgroup.go:251 +0x45
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]: panic({0xb1f720?, 0x2efcf3c5e0a0?})
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]:         runtime/panic.go:860 +0x13a
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]: github.com/VictoriaMetrics/VictoriaMetrics/lib/logger.logMessageInternal({0xbd400b, 0x5}, {0x2efcf37d60e0, 0x6e},>
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]:         github.com/VictoriaMetrics/VictoriaMetrics@v1.145.1-0.20260616130439-5b31a047a5bf/lib/logger/logger.go:32>
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]: github.com/VictoriaMetrics/VictoriaMetrics/lib/logger.logLevelSkipframes(0xc8cb40?, {0xbd400b, 0x5}, {0xbe68a9, 0>
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]:         github.com/VictoriaMetrics/VictoriaMetrics@v1.145.1-0.20260616130439-5b31a047a5bf/lib/logger/logger.go:16>
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]: github.com/VictoriaMetrics/VictoriaMetrics/lib/logger.logLevel(...)
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]:         github.com/VictoriaMetrics/VictoriaMetrics@v1.145.1-0.20260616130439-5b31a047a5bf/lib/logger/logger.go:147
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]: github.com/VictoriaMetrics/VictoriaMetrics/lib/logger.Panicf(...)
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]:         github.com/VictoriaMetrics/VictoriaMetrics@v1.145.1-0.20260616130439-5b31a047a5bf/lib/logger/logger.go:143
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]: github.com/VictoriaMetrics/VictoriaLogs/app/vlagent/tail.openFileWithInode({0x2efcf3d1a1c0?, 0x2?})
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]:         github.com/VictoriaMetrics/VictoriaLogs/app/vlagent/tail/tailer.go:359 +0xc6
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]: github.com/VictoriaMetrics/VictoriaLogs/app/vlagent/tail.findRenamedFile({0x2efcf3769ac0?, 0x3e?}, 0x103293)
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]:         github.com/VictoriaMetrics/VictoriaLogs/app/vlagent/tail/tailer.go:277 +0x21a
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]: github.com/VictoriaMetrics/VictoriaLogs/app/vlagent/tail.tryResumeFromCheckpoint({0x2efcf397acc0, 0x3e}, {{0x2efc>
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]:         github.com/VictoriaMetrics/VictoriaLogs/app/vlagent/tail/tailer.go:127 +0xaa
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]: github.com/VictoriaMetrics/VictoriaLogs/app/vlagent/tail.(*Tailer).openLogFile(0x2efcf38a78c0, {0x2efcf397acc0, 0>
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]:         github.com/VictoriaMetrics/VictoriaLogs/app/vlagent/tail/tailer.go:102 +0xb7
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]: github.com/VictoriaMetrics/VictoriaLogs/app/vlagent/tail.(*Tailer).StartRead.func1()
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]:         github.com/VictoriaMetrics/VictoriaLogs/app/vlagent/tail/tailer.go:90 +0x36
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]: sync.(*WaitGroup).Go.func1()
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]:         sync/waitgroup.go:258 +0x4a
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]: created by sync.(*WaitGroup).Go in goroutine 60
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal vic-vlagent[554523]:         sync/waitgroup.go:238 +0x73
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal systemd[1]: vic-vlagent.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal systemd[1]: vic-vlagent.service: Failed with result 'exit-code'.
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal systemd[1]: Stopped vic-vlagent.service - VictoriaLogs agent service.
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal systemd[1]: vic-vlagent.service: Start request repeated too quickly.
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal systemd[1]: vic-vlagent.service: Failed with result 'exit-code'.
Sep 17 09:45:35 ip-172-31-17-21.eu-west-1.compute.internal systemd[1]: Failed to start vic-vlagent.service - VictoriaLogs agent service.

Screenshots

No response

Used command-line flags

ExecStart=/usr/local/bin/vlagent-prod --remoteWrite.url=http://172.31.64.54:9428/insert/native?extra_fields=instance=host20%%2Cenv=UAT  --tmpDataPath=/var/lib/vlagent  --httpListenAddr=127.0.0.1:9429  --fileCollector.glob=/sfx1/1/siege/apps/sfx/logs/*.log  --fileCollector.glob=/sfx3/3/siege/apps/sfx/logs/*.log  --fileCollector.glob=/sfx1/4/siege/apps/sfx/logs/*.log  --fileCollector.extraFields='{"app": "core", "env": "UAT", "instance": "host20"}'  --fileCollector.extraFields='{"app": "secondary-core", "env": "UAT", "instance": "host20"}'  --fileCollector.extraFields='{"app": "tertiary-core", "env": "UAT", "instance": "host20"}'  --fileCollector.streamFields=hostname,app,env,file,instance

Additional information

No response

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't workingvlagentRelated to vlagent component

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions