github.com/openshift/moby-moby@v1.13.2-0.20170601211448-f5ec1e2936dc/daemon/logger/jsonfilelog/read.go (about)

     1  package jsonfilelog
     2  
     3  import (
     4  	"bytes"
     5  	"encoding/json"
     6  	"errors"
     7  	"fmt"
     8  	"io"
     9  	"os"
    10  	"time"
    11  
    12  	"github.com/fsnotify/fsnotify"
    13  	"golang.org/x/net/context"
    14  
    15  	"github.com/Sirupsen/logrus"
    16  	"github.com/docker/docker/daemon/logger"
    17  	"github.com/docker/docker/pkg/filenotify"
    18  	"github.com/docker/docker/pkg/ioutils"
    19  	"github.com/docker/docker/pkg/jsonlog"
    20  	"github.com/docker/docker/pkg/tailfile"
    21  )
    22  
    23  const maxJSONDecodeRetry = 20000
    24  
    25  func decodeLogLine(dec *json.Decoder, l *jsonlog.JSONLog) (*logger.Message, error) {
    26  	l.Reset()
    27  	if err := dec.Decode(l); err != nil {
    28  		return nil, err
    29  	}
    30  	msg := &logger.Message{
    31  		Source:    l.Stream,
    32  		Timestamp: l.Created,
    33  		Line:      []byte(l.Log),
    34  		Attrs:     l.Attrs,
    35  	}
    36  	return msg, nil
    37  }
    38  
    39  // ReadLogs implements the logger's LogReader interface for the logs
    40  // created by this driver.
    41  func (l *JSONFileLogger) ReadLogs(config logger.ReadConfig) *logger.LogWatcher {
    42  	logWatcher := logger.NewLogWatcher()
    43  
    44  	go l.readLogs(logWatcher, config)
    45  	return logWatcher
    46  }
    47  
    48  func (l *JSONFileLogger) readLogs(logWatcher *logger.LogWatcher, config logger.ReadConfig) {
    49  	defer close(logWatcher.Msg)
    50  
    51  	// lock so the read stream doesn't get corrupted due to rotations or other log data written while we read
    52  	// This will block writes!!!
    53  	l.mu.Lock()
    54  
    55  	pth := l.writer.LogPath()
    56  	var files []io.ReadSeeker
    57  	for i := l.writer.MaxFiles(); i > 1; i-- {
    58  		f, err := os.Open(fmt.Sprintf("%s.%d", pth, i-1))
    59  		if err != nil {
    60  			if !os.IsNotExist(err) {
    61  				logWatcher.Err <- err
    62  				break
    63  			}
    64  			continue
    65  		}
    66  		defer f.Close()
    67  
    68  		files = append(files, f)
    69  	}
    70  
    71  	latestFile, err := os.Open(pth)
    72  	if err != nil {
    73  		logWatcher.Err <- err
    74  		l.mu.Unlock()
    75  		return
    76  	}
    77  	defer latestFile.Close()
    78  
    79  	if config.Tail != 0 {
    80  		tailer := ioutils.MultiReadSeeker(append(files, latestFile)...)
    81  		tailFile(tailer, logWatcher, config.Tail, config.Since)
    82  	}
    83  
    84  	// close all the rotated files
    85  	for _, f := range files {
    86  		if err := f.(io.Closer).Close(); err != nil {
    87  			logrus.WithField("logger", "json-file").Warnf("error closing tailed log file: %v", err)
    88  		}
    89  	}
    90  
    91  	if !config.Follow {
    92  		if err := latestFile.Close(); err != nil {
    93  			logrus.Errorf("Error closing file: %v", err)
    94  		}
    95  		l.mu.Unlock()
    96  		return
    97  	}
    98  
    99  	if config.Tail >= 0 {
   100  		latestFile.Seek(0, os.SEEK_END)
   101  	}
   102  
   103  	l.readers[logWatcher] = struct{}{}
   104  	l.mu.Unlock()
   105  
   106  	notifyRotate := l.writer.NotifyRotate()
   107  	followLogs(latestFile, logWatcher, notifyRotate, config.Since)
   108  
   109  	l.mu.Lock()
   110  	delete(l.readers, logWatcher)
   111  	l.mu.Unlock()
   112  
   113  	l.writer.NotifyRotateEvict(notifyRotate)
   114  }
   115  
   116  func tailFile(f io.ReadSeeker, logWatcher *logger.LogWatcher, tail int, since time.Time) {
   117  	var rdr io.Reader
   118  	rdr = f
   119  	if tail > 0 {
   120  		ls, err := tailfile.TailFile(f, tail)
   121  		if err != nil {
   122  			logWatcher.Err <- err
   123  			return
   124  		}
   125  		rdr = bytes.NewBuffer(bytes.Join(ls, []byte("\n")))
   126  	}
   127  	dec := json.NewDecoder(rdr)
   128  	l := &jsonlog.JSONLog{}
   129  	for {
   130  		msg, err := decodeLogLine(dec, l)
   131  		if err != nil {
   132  			if err != io.EOF {
   133  				logWatcher.Err <- err
   134  			}
   135  			return
   136  		}
   137  		if !since.IsZero() && msg.Timestamp.Before(since) {
   138  			continue
   139  		}
   140  		select {
   141  		case <-logWatcher.WatchClose():
   142  			return
   143  		case logWatcher.Msg <- msg:
   144  		}
   145  	}
   146  }
   147  
   148  func watchFile(name string) (filenotify.FileWatcher, error) {
   149  	fileWatcher, err := filenotify.New()
   150  	if err != nil {
   151  		return nil, err
   152  	}
   153  
   154  	if err := fileWatcher.Add(name); err != nil {
   155  		logrus.WithField("logger", "json-file").Warnf("falling back to file poller due to error: %v", err)
   156  		fileWatcher.Close()
   157  		fileWatcher = filenotify.NewPollingWatcher()
   158  
   159  		if err := fileWatcher.Add(name); err != nil {
   160  			fileWatcher.Close()
   161  			logrus.Debugf("error watching log file for modifications: %v", err)
   162  			return nil, err
   163  		}
   164  	}
   165  	return fileWatcher, nil
   166  }
   167  
   168  func followLogs(f *os.File, logWatcher *logger.LogWatcher, notifyRotate chan interface{}, since time.Time) {
   169  	dec := json.NewDecoder(f)
   170  	l := &jsonlog.JSONLog{}
   171  
   172  	name := f.Name()
   173  	fileWatcher, err := watchFile(name)
   174  	if err != nil {
   175  		logWatcher.Err <- err
   176  		return
   177  	}
   178  	defer func() {
   179  		f.Close()
   180  		fileWatcher.Remove(name)
   181  		fileWatcher.Close()
   182  	}()
   183  
   184  	ctx, cancel := context.WithCancel(context.Background())
   185  	defer cancel()
   186  	go func() {
   187  		select {
   188  		case <-logWatcher.WatchClose():
   189  			fileWatcher.Remove(name)
   190  			cancel()
   191  		case <-ctx.Done():
   192  			return
   193  		}
   194  	}()
   195  
   196  	var retries int
   197  	handleRotate := func() error {
   198  		f.Close()
   199  		fileWatcher.Remove(name)
   200  
   201  		// retry when the file doesn't exist
   202  		for retries := 0; retries <= 5; retries++ {
   203  			f, err = os.Open(name)
   204  			if err == nil || !os.IsNotExist(err) {
   205  				break
   206  			}
   207  		}
   208  		if err != nil {
   209  			return err
   210  		}
   211  		if err := fileWatcher.Add(name); err != nil {
   212  			return err
   213  		}
   214  		dec = json.NewDecoder(f)
   215  		return nil
   216  	}
   217  
   218  	errRetry := errors.New("retry")
   219  	errDone := errors.New("done")
   220  	waitRead := func() error {
   221  		select {
   222  		case e := <-fileWatcher.Events():
   223  			switch e.Op {
   224  			case fsnotify.Write:
   225  				dec = json.NewDecoder(f)
   226  				return nil
   227  			case fsnotify.Rename, fsnotify.Remove:
   228  				select {
   229  				case <-notifyRotate:
   230  				case <-ctx.Done():
   231  					return errDone
   232  				}
   233  				if err := handleRotate(); err != nil {
   234  					return err
   235  				}
   236  				return nil
   237  			}
   238  			return errRetry
   239  		case err := <-fileWatcher.Errors():
   240  			logrus.Debug("logger got error watching file: %v", err)
   241  			// Something happened, let's try and stay alive and create a new watcher
   242  			if retries <= 5 {
   243  				fileWatcher.Close()
   244  				fileWatcher, err = watchFile(name)
   245  				if err != nil {
   246  					return err
   247  				}
   248  				retries++
   249  				return errRetry
   250  			}
   251  			return err
   252  		case <-ctx.Done():
   253  			return errDone
   254  		}
   255  	}
   256  
   257  	handleDecodeErr := func(err error) error {
   258  		if err == io.EOF {
   259  			for {
   260  				err := waitRead()
   261  				if err == nil {
   262  					break
   263  				}
   264  				if err == errRetry {
   265  					continue
   266  				}
   267  				return err
   268  			}
   269  			return nil
   270  		}
   271  		// try again because this shouldn't happen
   272  		if _, ok := err.(*json.SyntaxError); ok && retries <= maxJSONDecodeRetry {
   273  			dec = json.NewDecoder(f)
   274  			retries++
   275  			return nil
   276  		}
   277  		// io.ErrUnexpectedEOF is returned from json.Decoder when there is
   278  		// remaining data in the parser's buffer while an io.EOF occurs.
   279  		// If the json logger writes a partial json log entry to the disk
   280  		// while at the same time the decoder tries to decode it, the race condition happens.
   281  		if err == io.ErrUnexpectedEOF && retries <= maxJSONDecodeRetry {
   282  			reader := io.MultiReader(dec.Buffered(), f)
   283  			dec = json.NewDecoder(reader)
   284  			retries++
   285  			return nil
   286  		}
   287  		return err
   288  	}
   289  
   290  	// main loop
   291  	for {
   292  		msg, err := decodeLogLine(dec, l)
   293  		if err != nil {
   294  			if err := handleDecodeErr(err); err != nil {
   295  				if err == errDone {
   296  					return
   297  				}
   298  				// we got an unrecoverable error, so return
   299  				logWatcher.Err <- err
   300  				return
   301  			}
   302  			// ready to try again
   303  			continue
   304  		}
   305  
   306  		retries = 0 // reset retries since we've succeeded
   307  		if !since.IsZero() && msg.Timestamp.Before(since) {
   308  			continue
   309  		}
   310  		select {
   311  		case logWatcher.Msg <- msg:
   312  		case <-ctx.Done():
   313  			logWatcher.Msg <- msg
   314  			for {
   315  				msg, err := decodeLogLine(dec, l)
   316  				if err != nil {
   317  					return
   318  				}
   319  				if !since.IsZero() && msg.Timestamp.Before(since) {
   320  					continue
   321  				}
   322  				logWatcher.Msg <- msg
   323  			}
   324  		}
   325  	}
   326  }