2015-10-08 16:55:28 -04:00
|
|
|
package jsonfilelog
|
|
|
|
|
|
|
|
import (
|
|
|
|
"bytes"
|
|
|
|
"encoding/json"
|
|
|
|
"fmt"
|
|
|
|
"io"
|
|
|
|
"os"
|
|
|
|
"time"
|
|
|
|
|
2016-10-31 14:22:28 -04:00
|
|
|
"github.com/fsnotify/fsnotify"
|
2016-10-26 08:56:10 -04:00
|
|
|
"golang.org/x/net/context"
|
2016-07-11 16:31:42 -04:00
|
|
|
|
2017-07-18 22:01:20 -04:00
|
|
|
"github.com/docker/docker/api/types/backend"
|
2015-10-08 16:55:28 -04:00
|
|
|
"github.com/docker/docker/daemon/logger"
|
2017-09-25 15:57:45 -04:00
|
|
|
"github.com/docker/docker/daemon/logger/jsonfilelog/jsonlog"
|
2017-06-01 19:22:00 -04:00
|
|
|
"github.com/docker/docker/daemon/logger/jsonfilelog/multireader"
|
2016-02-23 21:07:38 -05:00
|
|
|
"github.com/docker/docker/pkg/filenotify"
|
2015-10-08 16:55:28 -04:00
|
|
|
"github.com/docker/docker/pkg/tailfile"
|
2017-06-30 13:13:32 -04:00
|
|
|
"github.com/pkg/errors"
|
2017-07-26 17:42:13 -04:00
|
|
|
"github.com/sirupsen/logrus"
|
2015-10-08 16:55:28 -04:00
|
|
|
)
|
|
|
|
|
2016-02-23 21:07:38 -05:00
|
|
|
const maxJSONDecodeRetry = 20000
|
|
|
|
|
2015-10-08 16:55:28 -04:00
|
|
|
func decodeLogLine(dec *json.Decoder, l *jsonlog.JSONLog) (*logger.Message, error) {
|
|
|
|
l.Reset()
|
|
|
|
if err := dec.Decode(l); err != nil {
|
|
|
|
return nil, err
|
|
|
|
}
|
2017-07-18 22:01:20 -04:00
|
|
|
var attrs []backend.LogAttr
|
|
|
|
if len(l.Attrs) != 0 {
|
|
|
|
attrs = make([]backend.LogAttr, 0, len(l.Attrs))
|
|
|
|
for k, v := range l.Attrs {
|
|
|
|
attrs = append(attrs, backend.LogAttr{Key: k, Value: v})
|
|
|
|
}
|
|
|
|
}
|
2015-10-08 16:55:28 -04:00
|
|
|
msg := &logger.Message{
|
|
|
|
Source: l.Stream,
|
|
|
|
Timestamp: l.Created,
|
|
|
|
Line: []byte(l.Log),
|
2017-07-18 22:01:20 -04:00
|
|
|
Attrs: attrs,
|
2015-10-08 16:55:28 -04:00
|
|
|
}
|
|
|
|
return msg, nil
|
|
|
|
}
|
|
|
|
|
|
|
|
// ReadLogs implements the logger's LogReader interface for the logs
|
|
|
|
// created by this driver.
|
|
|
|
func (l *JSONFileLogger) ReadLogs(config logger.ReadConfig) *logger.LogWatcher {
|
|
|
|
logWatcher := logger.NewLogWatcher()
|
2016-02-23 21:07:38 -05:00
|
|
|
|
2015-10-08 16:55:28 -04:00
|
|
|
go l.readLogs(logWatcher, config)
|
|
|
|
return logWatcher
|
|
|
|
}
|
|
|
|
|
|
|
|
func (l *JSONFileLogger) readLogs(logWatcher *logger.LogWatcher, config logger.ReadConfig) {
|
|
|
|
defer close(logWatcher.Msg)
|
|
|
|
|
2017-06-30 13:13:32 -04:00
|
|
|
// lock so the read stream doesn't get corrupted due to rotations or other log data written while we open these files
|
2016-07-11 16:31:42 -04:00
|
|
|
// This will block writes!!!
|
2017-06-30 13:13:32 -04:00
|
|
|
l.mu.RLock()
|
2016-07-11 16:31:42 -04:00
|
|
|
|
2017-06-30 13:13:32 -04:00
|
|
|
// TODO it would be nice to move a lot of this reader implementation to the rotate logger object
|
2015-11-14 18:02:06 -05:00
|
|
|
pth := l.writer.LogPath()
|
2015-10-08 16:55:28 -04:00
|
|
|
var files []io.ReadSeeker
|
2015-11-14 18:02:06 -05:00
|
|
|
for i := l.writer.MaxFiles(); i > 1; i-- {
|
2015-10-08 16:55:28 -04:00
|
|
|
f, err := os.Open(fmt.Sprintf("%s.%d", pth, i-1))
|
|
|
|
if err != nil {
|
|
|
|
if !os.IsNotExist(err) {
|
|
|
|
logWatcher.Err <- err
|
2017-06-30 13:13:32 -04:00
|
|
|
l.mu.RUnlock()
|
|
|
|
return
|
2015-10-08 16:55:28 -04:00
|
|
|
}
|
|
|
|
continue
|
|
|
|
}
|
2016-06-24 23:57:21 -04:00
|
|
|
defer f.Close()
|
2015-10-08 16:55:28 -04:00
|
|
|
files = append(files, f)
|
|
|
|
}
|
|
|
|
|
|
|
|
latestFile, err := os.Open(pth)
|
|
|
|
if err != nil {
|
2017-06-30 13:13:32 -04:00
|
|
|
logWatcher.Err <- errors.Wrap(err, "error opening latest log file")
|
|
|
|
l.mu.RUnlock()
|
2015-10-08 16:55:28 -04:00
|
|
|
return
|
|
|
|
}
|
2016-06-24 23:57:21 -04:00
|
|
|
defer latestFile.Close()
|
2015-10-08 16:55:28 -04:00
|
|
|
|
2017-06-30 13:13:32 -04:00
|
|
|
latestChunk, err := newSectionReader(latestFile)
|
|
|
|
|
|
|
|
// Now we have the reader sectioned, all fd's opened, we can unlock.
|
|
|
|
// New writes/rotates will not affect seeking through these files
|
|
|
|
l.mu.RUnlock()
|
|
|
|
|
|
|
|
if err != nil {
|
|
|
|
logWatcher.Err <- err
|
|
|
|
return
|
|
|
|
}
|
|
|
|
|
2015-10-08 16:55:28 -04:00
|
|
|
if config.Tail != 0 {
|
2017-06-30 13:13:32 -04:00
|
|
|
tailer := multireader.MultiReadSeeker(append(files, latestChunk)...)
|
2015-10-08 16:55:28 -04:00
|
|
|
tailFile(tailer, logWatcher, config.Tail, config.Since)
|
|
|
|
}
|
|
|
|
|
2016-03-17 12:13:23 -04:00
|
|
|
// close all the rotated files
|
|
|
|
for _, f := range files {
|
|
|
|
if err := f.(io.Closer).Close(); err != nil {
|
|
|
|
logrus.WithField("logger", "json-file").Warnf("error closing tailed log file: %v", err)
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2017-03-15 11:41:12 -04:00
|
|
|
if !config.Follow || l.closed {
|
2015-10-08 16:55:28 -04:00
|
|
|
return
|
|
|
|
}
|
|
|
|
|
2017-03-15 11:41:12 -04:00
|
|
|
notifyRotate := l.writer.NotifyRotate()
|
|
|
|
defer l.writer.NotifyRotateEvict(notifyRotate)
|
|
|
|
|
2017-06-30 13:13:32 -04:00
|
|
|
l.mu.Lock()
|
2015-10-08 16:55:28 -04:00
|
|
|
l.readers[logWatcher] = struct{}{}
|
|
|
|
l.mu.Unlock()
|
|
|
|
|
2016-02-23 21:07:38 -05:00
|
|
|
followLogs(latestFile, logWatcher, notifyRotate, config.Since)
|
2015-10-08 16:55:28 -04:00
|
|
|
|
|
|
|
l.mu.Lock()
|
|
|
|
delete(l.readers, logWatcher)
|
|
|
|
l.mu.Unlock()
|
|
|
|
}
|
|
|
|
|
2017-06-30 13:13:32 -04:00
|
|
|
func newSectionReader(f *os.File) (*io.SectionReader, error) {
|
|
|
|
// seek to the end to get the size
|
|
|
|
// we'll leave this at the end of the file since section reader does not advance the reader
|
|
|
|
size, err := f.Seek(0, os.SEEK_END)
|
|
|
|
if err != nil {
|
|
|
|
return nil, errors.Wrap(err, "error getting current file size")
|
|
|
|
}
|
|
|
|
return io.NewSectionReader(f, 0, size), nil
|
|
|
|
}
|
|
|
|
|
2015-10-08 16:55:28 -04:00
|
|
|
func tailFile(f io.ReadSeeker, logWatcher *logger.LogWatcher, tail int, since time.Time) {
|
2017-09-11 14:55:05 -04:00
|
|
|
rdr := io.Reader(f)
|
2015-10-08 16:55:28 -04:00
|
|
|
if tail > 0 {
|
|
|
|
ls, err := tailfile.TailFile(f, tail)
|
|
|
|
if err != nil {
|
|
|
|
logWatcher.Err <- err
|
|
|
|
return
|
|
|
|
}
|
|
|
|
rdr = bytes.NewBuffer(bytes.Join(ls, []byte("\n")))
|
|
|
|
}
|
|
|
|
dec := json.NewDecoder(rdr)
|
|
|
|
for {
|
2017-09-22 16:20:50 -04:00
|
|
|
msg, err := decodeLogLine(dec, &jsonlog.JSONLog{})
|
2015-10-08 16:55:28 -04:00
|
|
|
if err != nil {
|
|
|
|
if err != io.EOF {
|
|
|
|
logWatcher.Err <- err
|
|
|
|
}
|
|
|
|
return
|
|
|
|
}
|
|
|
|
if !since.IsZero() && msg.Timestamp.Before(since) {
|
|
|
|
continue
|
|
|
|
}
|
2017-01-17 16:12:50 -05:00
|
|
|
select {
|
|
|
|
case <-logWatcher.WatchClose():
|
|
|
|
return
|
|
|
|
case logWatcher.Msg <- msg:
|
|
|
|
}
|
2015-10-08 16:55:28 -04:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2016-07-11 16:31:42 -04:00
|
|
|
func watchFile(name string) (filenotify.FileWatcher, error) {
|
|
|
|
fileWatcher, err := filenotify.New()
|
|
|
|
if err != nil {
|
|
|
|
return nil, err
|
|
|
|
}
|
|
|
|
|
|
|
|
if err := fileWatcher.Add(name); err != nil {
|
|
|
|
logrus.WithField("logger", "json-file").Warnf("falling back to file poller due to error: %v", err)
|
|
|
|
fileWatcher.Close()
|
|
|
|
fileWatcher = filenotify.NewPollingWatcher()
|
|
|
|
|
|
|
|
if err := fileWatcher.Add(name); err != nil {
|
|
|
|
fileWatcher.Close()
|
|
|
|
logrus.Debugf("error watching log file for modifications: %v", err)
|
|
|
|
return nil, err
|
|
|
|
}
|
|
|
|
}
|
|
|
|
return fileWatcher, nil
|
|
|
|
}
|
|
|
|
|
2016-02-23 21:07:38 -05:00
|
|
|
func followLogs(f *os.File, logWatcher *logger.LogWatcher, notifyRotate chan interface{}, since time.Time) {
|
|
|
|
dec := json.NewDecoder(f)
|
|
|
|
l := &jsonlog.JSONLog{}
|
2015-10-08 16:55:28 -04:00
|
|
|
|
2016-07-11 16:31:42 -04:00
|
|
|
name := f.Name()
|
|
|
|
fileWatcher, err := watchFile(name)
|
2016-02-23 21:07:38 -05:00
|
|
|
if err != nil {
|
|
|
|
logWatcher.Err <- err
|
2016-07-11 16:31:42 -04:00
|
|
|
return
|
2016-02-23 21:07:38 -05:00
|
|
|
}
|
2016-03-17 12:13:23 -04:00
|
|
|
defer func() {
|
|
|
|
f.Close()
|
2016-10-26 08:56:10 -04:00
|
|
|
fileWatcher.Remove(name)
|
2016-03-17 12:13:23 -04:00
|
|
|
fileWatcher.Close()
|
|
|
|
}()
|
|
|
|
|
2016-10-26 08:56:10 -04:00
|
|
|
ctx, cancel := context.WithCancel(context.Background())
|
|
|
|
defer cancel()
|
|
|
|
go func() {
|
|
|
|
select {
|
|
|
|
case <-logWatcher.WatchClose():
|
|
|
|
fileWatcher.Remove(name)
|
|
|
|
cancel()
|
|
|
|
case <-ctx.Done():
|
|
|
|
return
|
|
|
|
}
|
|
|
|
}()
|
|
|
|
|
2016-07-11 16:31:42 -04:00
|
|
|
var retries int
|
|
|
|
handleRotate := func() error {
|
|
|
|
f.Close()
|
|
|
|
fileWatcher.Remove(name)
|
2016-03-17 12:13:23 -04:00
|
|
|
|
2016-07-11 16:31:42 -04:00
|
|
|
// retry when the file doesn't exist
|
|
|
|
for retries := 0; retries <= 5; retries++ {
|
|
|
|
f, err = os.Open(name)
|
|
|
|
if err == nil || !os.IsNotExist(err) {
|
|
|
|
break
|
|
|
|
}
|
|
|
|
}
|
|
|
|
if err != nil {
|
|
|
|
return err
|
|
|
|
}
|
2016-03-17 12:13:23 -04:00
|
|
|
if err := fileWatcher.Add(name); err != nil {
|
2016-07-11 16:31:42 -04:00
|
|
|
return err
|
2016-03-17 12:13:23 -04:00
|
|
|
}
|
2016-07-11 16:31:42 -04:00
|
|
|
dec = json.NewDecoder(f)
|
|
|
|
return nil
|
2016-03-17 12:13:23 -04:00
|
|
|
}
|
2015-10-08 16:55:28 -04:00
|
|
|
|
2016-07-11 16:31:42 -04:00
|
|
|
errRetry := errors.New("retry")
|
|
|
|
errDone := errors.New("done")
|
|
|
|
waitRead := func() error {
|
|
|
|
select {
|
|
|
|
case e := <-fileWatcher.Events():
|
|
|
|
switch e.Op {
|
|
|
|
case fsnotify.Write:
|
|
|
|
dec = json.NewDecoder(f)
|
|
|
|
return nil
|
|
|
|
case fsnotify.Rename, fsnotify.Remove:
|
|
|
|
select {
|
|
|
|
case <-notifyRotate:
|
2016-10-26 08:56:10 -04:00
|
|
|
case <-ctx.Done():
|
2016-07-11 16:31:42 -04:00
|
|
|
return errDone
|
2016-02-23 21:07:38 -05:00
|
|
|
}
|
2016-07-11 16:31:42 -04:00
|
|
|
if err := handleRotate(); err != nil {
|
|
|
|
return err
|
2016-02-23 21:07:38 -05:00
|
|
|
}
|
2016-07-11 16:31:42 -04:00
|
|
|
return nil
|
2016-02-23 21:07:38 -05:00
|
|
|
}
|
2016-07-11 16:31:42 -04:00
|
|
|
return errRetry
|
|
|
|
case err := <-fileWatcher.Errors():
|
|
|
|
logrus.Debug("logger got error watching file: %v", err)
|
|
|
|
// Something happened, let's try and stay alive and create a new watcher
|
|
|
|
if retries <= 5 {
|
|
|
|
fileWatcher.Close()
|
|
|
|
fileWatcher, err = watchFile(name)
|
|
|
|
if err != nil {
|
|
|
|
return err
|
2016-03-17 12:13:23 -04:00
|
|
|
}
|
2016-07-11 16:31:42 -04:00
|
|
|
retries++
|
|
|
|
return errRetry
|
|
|
|
}
|
|
|
|
return err
|
2016-10-26 08:56:10 -04:00
|
|
|
case <-ctx.Done():
|
2016-07-11 16:31:42 -04:00
|
|
|
return errDone
|
|
|
|
}
|
|
|
|
}
|
2016-03-17 12:13:23 -04:00
|
|
|
|
2016-07-11 16:31:42 -04:00
|
|
|
handleDecodeErr := func(err error) error {
|
|
|
|
if err == io.EOF {
|
2017-02-15 21:00:29 -05:00
|
|
|
for {
|
|
|
|
err := waitRead()
|
|
|
|
if err == nil {
|
|
|
|
break
|
|
|
|
}
|
2016-07-11 16:31:42 -04:00
|
|
|
if err == errRetry {
|
|
|
|
continue
|
2016-03-17 12:13:23 -04:00
|
|
|
}
|
2016-07-11 16:31:42 -04:00
|
|
|
return err
|
|
|
|
}
|
|
|
|
return nil
|
|
|
|
}
|
|
|
|
// try again because this shouldn't happen
|
|
|
|
if _, ok := err.(*json.SyntaxError); ok && retries <= maxJSONDecodeRetry {
|
|
|
|
dec = json.NewDecoder(f)
|
|
|
|
retries++
|
|
|
|
return nil
|
|
|
|
}
|
|
|
|
// io.ErrUnexpectedEOF is returned from json.Decoder when there is
|
|
|
|
// remaining data in the parser's buffer while an io.EOF occurs.
|
|
|
|
// If the json logger writes a partial json log entry to the disk
|
|
|
|
// while at the same time the decoder tries to decode it, the race condition happens.
|
|
|
|
if err == io.ErrUnexpectedEOF && retries <= maxJSONDecodeRetry {
|
|
|
|
reader := io.MultiReader(dec.Buffered(), f)
|
|
|
|
dec = json.NewDecoder(reader)
|
|
|
|
retries++
|
|
|
|
return nil
|
|
|
|
}
|
|
|
|
return err
|
|
|
|
}
|
|
|
|
|
|
|
|
// main loop
|
|
|
|
for {
|
|
|
|
msg, err := decodeLogLine(dec, l)
|
|
|
|
if err != nil {
|
|
|
|
if err := handleDecodeErr(err); err != nil {
|
|
|
|
if err == errDone {
|
2016-02-23 21:07:38 -05:00
|
|
|
return
|
|
|
|
}
|
2016-07-11 16:31:42 -04:00
|
|
|
// we got an unrecoverable error, so return
|
|
|
|
logWatcher.Err <- err
|
|
|
|
return
|
2015-10-08 16:55:28 -04:00
|
|
|
}
|
2016-07-11 16:31:42 -04:00
|
|
|
// ready to try again
|
|
|
|
continue
|
2015-10-08 16:55:28 -04:00
|
|
|
}
|
|
|
|
|
2016-02-23 21:07:38 -05:00
|
|
|
retries = 0 // reset retries since we've succeeded
|
|
|
|
if !since.IsZero() && msg.Timestamp.Before(since) {
|
|
|
|
continue
|
2015-10-08 16:55:28 -04:00
|
|
|
}
|
|
|
|
select {
|
2016-02-23 21:07:38 -05:00
|
|
|
case logWatcher.Msg <- msg:
|
2016-10-26 08:56:10 -04:00
|
|
|
case <-ctx.Done():
|
2016-02-23 21:07:38 -05:00
|
|
|
logWatcher.Msg <- msg
|
|
|
|
for {
|
|
|
|
msg, err := decodeLogLine(dec, l)
|
|
|
|
if err != nil {
|
2015-10-08 16:55:28 -04:00
|
|
|
return
|
|
|
|
}
|
2016-02-23 21:07:38 -05:00
|
|
|
if !since.IsZero() && msg.Timestamp.Before(since) {
|
|
|
|
continue
|
2015-10-08 16:55:28 -04:00
|
|
|
}
|
2016-02-23 21:07:38 -05:00
|
|
|
logWatcher.Msg <- msg
|
2015-10-08 16:55:28 -04:00
|
|
|
}
|
|
|
|
}
|
|
|
|
}
|
|
|
|
}
|