mtail fails to read log file with initially incorrect permissions that are later fixed

[deltaroe]

Was working with a log that during rotation initially gets created with permissions such that mtail can't read it. Even if those permissions are later fixed mtail seems to be stuck in a state where it thinks it's already reading that file. The last log lines repeat forever

I0420 22:51:33.882236      21 tail.go:368] glob matches: [/pvc/logs/postfix.log]
I0420 22:51:33.882412      21 tail.go:378] watched path is "/pvc/logs/postfix.log"
I0420 22:51:33.882430      21 tail.go:272] already got a logstream on "/pvc/logs/postfix.log"
I0420 22:51:34.132697      21 filestream.go:260] &{0xc000094420}: Wake received
I0420 22:51:34.132713      21 tail.go:368] glob matches: [/pvc/logs/postfix.log]
I0420 22:51:34.132775      21 filestream.go:105] &{0xc000094420}: read 95 bytes, err is <nil>
I0420 22:51:34.132787      21 filestream.go:109] &{0xc000094420}: decode and send
I0420 22:51:34.132797      21 decode.go:64] sendline
I0420 22:51:34.132796      21 tail.go:378] watched path is "/pvc/logs/postfix.log"
I0420 22:51:34.132810      21 tail.go:272] already got a logstream on "/pvc/logs/postfix.log"
I0420 22:51:34.132815      21 filestream.go:105] &{0xc000094420}: read 0 bytes, err is EOF
I0420 22:51:34.132836      21 filestream.go:141] &{0xc000094420}: eof an no bytes
I0420 22:51:34.132858      21 filestream.go:169] &{0xc000094420}: adding a new file routine
I0420 22:51:34.132894      21 filestream.go:171] open /pvc/logs/postfix.log: permission denied
I0420 22:51:34.132938      21 filestream.go:93] &{0xc000094420}: read total 483 bytes from /pvc/logs/postfix.log
I0420 22:51:34.132948      21 filestream.go:94] &{0xc000094420}: closing file descriptor
I0420 22:51:34.382196      21 tail.go:368] glob matches: [/pvc/logs/postfix.log]
I0420 22:51:34.382254      21 tail.go:378] watched path is "/pvc/logs/postfix.log"
I0420 22:51:34.382267      21 tail.go:272] already got a logstream on "/pvc/logs/postfix.log"
I0420 22:51:34.632582      21 tail.go:368] glob matches: [/pvc/logs/postfix.log]
I0420 22:51:34.632631      21 tail.go:378] watched path is "/pvc/logs/postfix.log"
I0420 22:51:34.632643      21 tail.go:272] already got a logstream on "/pvc/logs/postfix.log"
I0420 22:51:34.881913      21 tail.go:368] glob matches: [/pvc/logs/postfix.log]

mtail version v3.0.0-rc51-47-g44534e9e git revision 44534e9ec10bbd09640dff6c213822eb25e21951 go version go1.20.3 go arch amd64 go os linux

[jaqx0r]

The permissions checking in the tailer was specifically supposed to address this use case! Thanks for the report.

[jaqx0r]

Interpreting the logs:

• tail.go sees there's /pvc/logs/postfix.log and notices it already has created a filestream for that log file.
• a filestream (0x94420) is woken, and 95 bytes are read, no error, then sent to the runtime
• the same filestream looks like it thinks there's a log rotation, so creates a new filestream for it and closes itself, reporting it read 483 bytes total.

How odd. The filestream should not be trying to reopen itself on permission denied; the tested path is that the pattern is continuously polled and the stream is created once the log file is readable.

Did the stream start out as readable and then become unreadable? Is the title of the bug somehow backwards?