blob: 45d4a6567800bf670311137012c5746530422a3d [file]
// Copyright 2015 The Chromium Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.
package cloudtail
import (
"bytes"
"context"
"fmt"
"io"
"os"
"path/filepath"
"time"
"gopkg.in/fsnotify.v1"
"go.chromium.org/luci/common/clock"
"go.chromium.org/luci/common/logging"
"infra/tools/cloudtail/internal"
)
// See corresponding fields of TailerOptions.
const (
DefaultRotationCheckPeriod = 5 * time.Second
DefaultPollingPeriod = 500 * time.Millisecond
DefaultReadBufferLen = 1024 * 256
)
// TailerOptions is passed to NewTailer.
type TailerOptions struct {
// Path identifies a file to watch.
Path string
// PushBuffer knows how to forward log entries to the client.
PushBuffer PushBuffer
// TeeOutput (if not nil) receives raw text lines before they are sent to
// the parser. Write errors are logged, but otherwise ignored.
TeeOutput io.Writer
// Parser converts text lines into log entries, default is StdParser().
Parser LogParser
// SeekToEnd is true to seek to file's end before tailing.
SeekToEnd bool
// UsePolling is true to disable fsnotify watchers and use polling.
UsePolling bool
// RotationCheckPeriod defines how often to call os.Stat to see whether
// the file has been moved or truncated.
RotationCheckPeriod time.Duration
// PollingPeriod defines how often to poll file for changes if fsnotify system
// is not working.
PollingPeriod time.Duration
// ReadBufferLen is maximum number of bytes read from file in one operation.
ReadBufferLen int
// initializedSignal is used for synchronization in unit tests. It is closed
// after poller has initialized it's state and starts polling.
initializedSignal chan struct{}
}
// Tailer watches a file for changes and pushes new lines to a the buffer.
type Tailer struct {
opts TailerOptions
stopping chan struct{} // closed when Stop is called
}
// NewTailer prepares a Tailer.
//
// Use its 'Run' method to start tailing a file.
func NewTailer(opts TailerOptions) (*Tailer, error) {
var err error
opts.Path, err = filepath.Abs(opts.Path)
if err != nil {
return nil, err
}
if opts.Parser == nil {
opts.Parser = StdParser()
}
if opts.RotationCheckPeriod == 0 {
opts.RotationCheckPeriod = DefaultRotationCheckPeriod
}
if opts.PollingPeriod == 0 {
opts.PollingPeriod = DefaultPollingPeriod
}
if opts.ReadBufferLen == 0 {
opts.ReadBufferLen = DefaultReadBufferLen
}
return &Tailer{
opts: opts,
stopping: make(chan struct{}),
}, nil
}
// Run watches a file for changes and pushes new lines to the buffer.
//
// Use Stop() (from another goroutine) to gracefully terminate the tailer, or
// cancel the context to abort it ASAP.
func (tailer *Tailer) Run(ctx context.Context) {
// The inner context is canceled when tailer.Stop is called. It aborts all
// tailer guts, but doesn't stop 'drainChannel' (so all pending data still can
// be sent).
innerCtx, abort := context.WithCancel(ctx)
go func() {
select {
case <-tailer.stopping:
abort()
case <-innerCtx.Done(): // to avoid leaking this goroutine
}
}()
defer abort() // this would kill the goroutine above for sure
// Wakes up on file change notifications. Closes after innerCtx is closed
// and all pending notifications are sent.
var changeSignal chan checkType
if !tailer.opts.UsePolling {
var err error
changeSignal, err = signalOnChanges(innerCtx, tailer.opts.Path, tailer.opts.PollingPeriod)
if err != nil {
logging.Warningf(innerCtx, "Failed to initialize fsnotify, polling instead: %s", err)
}
}
if changeSignal == nil {
changeSignal = signalPeriodically(innerCtx, tailer.opts.PollingPeriod)
}
// poller.Poll() -> source -> optional teeChannel -> PushBuffer (in drainChannel).
source := make(chan string)
go func() {
defer close(source)
poller := filePoller{path: tailer.opts.Path}
poller.Init(ctx, tailer.opts.SeekToEnd, tailer.opts.ReadBufferLen)
defer poller.Close()
if tailer.opts.initializedSignal != nil {
close(tailer.opts.initializedSignal)
}
lastCheck := time.Time{}
forceCheck := true
// The final poll is happening with the outer context. So if inner context
// is canceled (e.g. on Stop), we are still able to send stuff (to terminate
// gracefully). If outer context is canceled too, 'Poll' does nothing.
defer func() {
logging.Debugf(ctx, "Doing the final tailer poll...")
poller.Poll(ctx, false, source)
}()
for {
// Do os.Stat scan after each wakeup timeout (forceCheck == true) or at
// least each RotationCheckPeriod.
now := clock.Now(innerCtx)
checkExistence := forceCheck || now.Sub(lastCheck) > tailer.opts.RotationCheckPeriod
if checkExistence {
lastCheck = now
}
forceCheck = false
// Read new lines, push them downstream (via 'source' channel).
err := poller.Poll(innerCtx, checkExistence, source)
if err != nil && !os.IsNotExist(err) {
logging.Errorf(innerCtx, "tail error: %s", err)
}
// Wake up periodically to make os.Stat check to detect file truncation.
wakeupIn := lastCheck.Add(tailer.opts.RotationCheckPeriod).Sub(clock.Now(innerCtx))
if wakeupIn < 0 {
wakeupIn = 0
}
// Wait for wakeup timer or for incoming change notification.
// changeSignal is closed when the watcher goroutine exits (happens when
// tailer.stopping is closed, i.e. when Stop() is called).
select {
case res := <-clock.After(innerCtx, wakeupIn):
if res.Err != nil {
return // the context was canceled
}
forceCheck = true
case check, alive := <-changeSignal:
if !alive {
return
}
forceCheck = check == statCheck
}
// Drain all pending change notifications, no need to run Poll() multiple
// times in a row.
drained := false
for !drained {
select {
case check, alive := <-changeSignal:
if !alive {
return
}
if check == statCheck {
forceCheck = true
}
default:
drained = true
}
}
}
}()
// Tee the lines to TeeOutput before parsing them and sending them to the
// push buffer.
toDrain := source
if tailer.opts.TeeOutput != nil {
toDrain = teeChannel(ctx, source, tailer.opts.TeeOutput)
}
// Note: canceled context here would cause all logs from 'toDrain' to be
// simply dropped.
drainChannel(ctx, toDrain, tailer.opts.Parser, tailer.opts.PushBuffer)
}
// Stop asynchronously notifies tailer to stop (i.e. 'Run' to unblock and
// return). Panics if called twice.
func (tailer *Tailer) Stop() {
close(tailer.stopping)
}
/// File state poller.
// filePoller knows how to read changes made to a file between two 'Poll' calls.
// It can detect file appearing and disappearing, file rotation and truncation.
// Used from single goroutine only.
type filePoller struct {
path string
file *os.File // non nil if currently tailing some file
stat os.FileInfo // used for os.SameFile call to detect rotation
offset int64 // position of the file pointer
incompleteLine []byte // last unfinished line of the file
buf []byte // temporary space to avoid reallocating it all the time
}
// Init prepares poller for operations.
func (p *filePoller) Init(ctx context.Context, seekToEnd bool, readBufferLen int) {
p.buf = make([]byte, readBufferLen)
// Ignore errors here (e.g. file is missing). They are discovered and
// reported in 'Poll'. The polling loop is more smart with respect to error
// handling.
if p.reopen(ctx) == nil && seekToEnd {
offset, err := p.file.Seek(0, os.SEEK_END)
if err == nil {
p.offset = offset
}
}
}
// Poll reads all new lines since last call to Poll and pushes them to 'sink'.
//
// Exits ASAP if the context is canceled.
func (p *filePoller) Poll(ctx context.Context, checkExistence bool, sink chan string) error {
// Slow code path (doing extra os.Stat) if there's suspicion the file has
// been moved.
if checkExistence {
exists := true
stat, err := os.Stat(p.path)
if err != nil {
// Treat permission errors as if file doesn't exist.
if !os.IsNotExist(err) && !os.IsPermission(err) {
return err
}
exists = false
}
// Was missing and still missing? Do nothing.
if p.file == nil && !exists {
return os.ErrNotExist
}
// Suddenly deleted, rotated, moved or truncated? Read what we can from
// still open file handle and close it. New one is reopened below.
if p.file != nil {
if !exists || !os.SameFile(p.stat, stat) || stat.Size() < p.offset {
p.readLines(ctx, sink)
if len(p.incompleteLine) != 0 {
select {
case sink <- string(p.incompleteLine):
case <-ctx.Done():
}
}
p.reset()
}
}
}
if p.file == nil {
if err := p.reopen(ctx); err != nil {
return err
}
}
p.readLines(ctx, sink)
return nil
}
func (p *filePoller) Close() {
p.reset()
}
func (p *filePoller) reopen(ctx context.Context) error {
if p.file != nil {
return fmt.Errorf("file is already open")
}
logging.Debugf(ctx, "Opening the file for tailing: %s", p.path)
f, err := internal.OpenForSharedRead(p.path)
if err != nil {
return err
}
stat, err := f.Stat()
if err != nil {
f.Close()
return err
}
p.file = f
p.stat = stat
p.offset = 0
p.incompleteLine = nil
return nil
}
func (p *filePoller) reset() {
if p.file != nil {
p.file.Close()
p.file = nil
}
p.stat = nil
p.offset = 0
p.incompleteLine = nil
}
func (p *filePoller) readLines(ctx context.Context, sink chan string) {
for {
size, err := p.file.Read(p.buf)
p.offset += int64(size)
// Read() can read something and return error at the same time. So parse
// output regardless of err value.
buf := p.buf[:size]
for len(buf) > 0 {
idx := bytes.IndexByte(buf, '\n')
if idx == -1 {
p.incompleteLine = append(p.incompleteLine, buf...)
break
}
newLine := buf[:idx]
buf = buf[idx+1:] // skip '\n' itself
// Avoid uselessly copying newLine into new buffer.
if p.incompleteLine == nil {
select {
case sink <- string(newLine):
case <-ctx.Done():
}
} else {
p.incompleteLine = append(p.incompleteLine, newLine...)
select {
case sink <- string(p.incompleteLine):
case <-ctx.Done():
}
p.incompleteLine = nil
}
}
if err != nil {
return // usually EOF
}
// Canceled?
if ctx.Err() != nil {
return
}
}
}
/// File change watchers.
type checkType int
const (
// normalCheck is returned to instruct poller to attempt to read file.
normalCheck checkType = iota
// statCheck is returned to instruct poller to os.Stat and read the file.
// Watcher returns it when there's suspicion tailed file has been moved or
// truncated or when it doesn't exist.
statCheck
)
// signalPeriodically returns a channel that receives normalCheck value each
// 'interval' milliseconds.
//
// Can be used for dumb polling of the file state.
//
// Returned channel closes when the context is canceled.
func signalPeriodically(ctx context.Context, interval time.Duration) chan checkType {
out := make(chan checkType)
go func() {
defer close(out)
for {
select {
case res := <-clock.After(ctx, interval):
if res.Err != nil {
return // context closed
}
out <- normalCheck
}
}
}()
return out
}
// signalOnChanges returns a channel that receives some checkType whenever
// file specified by 'path' changes.
//
// Caller must be prepared for false events, for the file being unexpectedly
// missing and all other conditions. Consider 'signalOnChanges' to be a smart
// version of 'signalPeriodically'.
//
// The returned channel closes when the context is closed.
func signalOnChanges(ctx context.Context, path string, interval time.Duration) (chan checkType, error) {
watcher, err := fsnotify.NewWatcher()
if err != nil {
return nil, err
}
out := make(chan checkType)
go func() {
defer close(out)
defer watcher.Close()
lastLogMsg := ""
spamLog := func(f string, args ...interface{}) {
msg := fmt.Sprintf(f, args...)
if lastLogMsg != msg {
logging.Debugf(ctx, msg)
lastLogMsg = msg
}
}
added := false
for {
// A watcher can be placed only on existing file. So until 'path' is
// successfully added to watcher, use polling.
if !added {
if err := watcher.Add(path); err != nil {
spamLog("fsnotify: failed to add watcher - %s, polling", err)
} else {
added = true
logging.Debugf(ctx, "Added file system watch: %s", path)
}
}
var timeout <-chan clock.TimerResult
if !added {
timeout = clock.After(ctx, interval)
}
select {
case <-ctx.Done():
return
case res := <-timeout:
if res.Err != nil {
return // the context was canceled
}
out <- statCheck
case err := <-watcher.Errors:
watcher.Remove(path)
added = false
spamLog("fsnotify: unexpected error - %s, polling", err)
case ev := <-watcher.Events:
if ev.Op == fsnotify.Rename || ev.Op == fsnotify.Remove {
added = false
logging.Debugf(ctx, "The file is gone, removing the watch: %s", ev)
watcher.Remove(path)
out <- statCheck
} else {
out <- normalCheck
}
}
}
}()
return out, nil
}
/// Helper to tee the log lines to io.Writer.
func teeChannel(ctx context.Context, source chan string, out io.Writer) chan string {
// If 'out' breaks, there can be a ton of errors. Throttle them.
lastLogTime := time.Time{}
logError := func(err error) {
if lastLogTime.IsZero() || clock.Since(ctx, lastLogTime) > 5*time.Second {
lastLogTime = clock.Now(ctx)
logging.Errorf(ctx, "Failed to tee the log - %s", err)
}
}
teed := make(chan string)
go func() {
defer close(teed)
for line := range source {
_, err1 := out.Write([]byte(line))
_, err2 := out.Write([]byte{'\n'})
switch {
case err1 != nil:
logError(err1)
case err2 != nil:
logError(err2)
}
teed <- line
}
}()
return teed
}