Refactor log file writer

Make the `*RotateFileWriter` specifically about writing
`logger.Message`'s, which is what it's used for.

This allows for future changes where the log writer can cache details
about log entries such as (e.g.) the timestamps included in a particular
log file, which can be used to optimize reads.

Signed-off-by: Brian Goff <cpuguy83@gmail.com>

daemon/logger/jsonfilelog/jsonfilelog.go

@@ -7,7 +7,6 @@ import (
 	"bytes"
 	"encoding/json"
 	"fmt"
-	"io"
 	"strconv"
 	"sync"
 
@@ -24,10 +23,7 @@ const Name = "json-file"
 
 // JSONFileLogger is Logger implementation for default Docker logging.
 type JSONFileLogger struct {
-	extra []byte // json-encoded extra attributes
-
 	mu      sync.RWMutex
-	buf     *bytes.Buffer // avoids allocating a new buffer on each call to `Log()`
 	closed  bool
 	writer  *loggerutils.RotateFileWriter
 	readers map[*logger.LogWatcher]struct{} // stores the active log followers
@@ -65,11 +61,6 @@ func New(info logger.Info) (logger.Logger, error) {
 		}
 	}
 
-	writer, err := loggerutils.NewRotateFileWriter(info.LogPath, capval, maxFiles)
-	if err != nil {
-		return nil, err
-	}
-
 	var extra []byte
 	attrs, err := info.ExtraAttributes(nil)
 	if err != nil {
@@ -83,33 +74,34 @@ func New(info logger.Info) (logger.Logger, error) {
 		}
 	}
 
+	buf := bytes.NewBuffer(nil)
+	marshalFunc := func(msg *logger.Message) ([]byte, error) {
+		if err := marshalMessage(msg, extra, buf); err != nil {
+			return nil, err
+		}
+		b := buf.Bytes()
+		buf.Reset()
+		return b, nil
+	}
+	writer, err := loggerutils.NewRotateFileWriter(info.LogPath, capval, maxFiles, marshalFunc)
+	if err != nil {
+		return nil, err
+	}
+
 	return &JSONFileLogger{
-		buf:     bytes.NewBuffer(nil),
 		writer:  writer,
 		readers: make(map[*logger.LogWatcher]struct{}),
-		extra:   extra,
 	}, nil
 }
 
 // Log converts logger.Message to jsonlog.JSONLog and serializes it to file.
 func (l *JSONFileLogger) Log(msg *logger.Message) error {
 	l.mu.Lock()
-	err := writeMessageBuf(l.writer, msg, l.extra, l.buf)
+	err := l.writer.WriteLogEntry(msg)
-	l.buf.Reset()
 	l.mu.Unlock()
 	return err
 }
 
-func writeMessageBuf(w io.Writer, m *logger.Message, extra json.RawMessage, buf *bytes.Buffer) error {
-	if err := marshalMessage(m, extra, buf); err != nil {
-		logger.PutMessage(m)
-		return err
-	}
-	logger.PutMessage(m)
-	_, err := w.Write(buf.Bytes())
-	return errors.Wrap(err, "error writing log entry")
-}
-
 func marshalMessage(msg *logger.Message, extra json.RawMessage, buf *bytes.Buffer) error {
 	logLine := msg.Line
 	if !msg.Partial {

daemon/logger/logger.go

@@ -140,3 +140,6 @@ type Capability struct {
 	// Determines if a log driver can read back logs
 	ReadLogs bool
 }
+
+// MarshalFunc is a func that marshals a message into an arbitrary format
+type MarshalFunc func(*Message) ([]byte, error)

daemon/logger/loggerutils/rotatefilewriter.go

@@ -1,12 +1,13 @@
 package loggerutils
 
 import (
-	"errors"
 	"os"
 	"strconv"
 	"sync"
 
+	"github.com/docker/docker/daemon/logger"
 	"github.com/docker/docker/pkg/pubsub"
+	"github.com/pkg/errors"
 )
 
 // RotateFileWriter is Logger implementation for default Docker logging.
@@ -18,10 +19,11 @@ type RotateFileWriter struct {
 	currentSize  int64 // current size of the latest file
 	maxFiles     int   //maximum number of files
 	notifyRotate *pubsub.Publisher
+	marshal      logger.MarshalFunc
 }
 
 //NewRotateFileWriter creates new RotateFileWriter
-func NewRotateFileWriter(logPath string, capacity int64, maxFiles int) (*RotateFileWriter, error) {
+func NewRotateFileWriter(logPath string, capacity int64, maxFiles int, marshaller logger.MarshalFunc) (*RotateFileWriter, error) {
 	log, err := os.OpenFile(logPath, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0640)
 	if err != nil {
 		return nil, err
@@ -38,27 +40,37 @@ func NewRotateFileWriter(logPath string, capacity int64, maxFiles int) (*RotateF
 		currentSize:  size,
 		maxFiles:     maxFiles,
 		notifyRotate: pubsub.NewPublisher(0, 1),
+		marshal:      marshaller,
 	}, nil
 }
 
-//WriteLog write log message to File
+// WriteLogEntry writes the provided log message to the current log file.
-func (w *RotateFileWriter) Write(message []byte) (int, error) {
+// This may trigger a rotation event if the max file/capacity limits are hit.
+func (w *RotateFileWriter) WriteLogEntry(msg *logger.Message) error {
+	b, err := w.marshal(msg)
+	if err != nil {
+		return errors.Wrap(err, "error marshalling log message")
+	}
+
+	logger.PutMessage(msg)
+
 	w.mu.Lock()
 	if w.closed {
 		w.mu.Unlock()
-		return -1, errors.New("cannot write because the output file was closed")
+		return errors.New("cannot write because the output file was closed")
-	}
-	if err := w.checkCapacityAndRotate(); err != nil {
-		w.mu.Unlock()
-		return -1, err
 	}
 
-	n, err := w.f.Write(message)
+	if err := w.checkCapacityAndRotate(); err != nil {
+		w.mu.Unlock()
+		return err
+	}
+
+	n, err := w.f.Write(b)
 	if err == nil {
 		w.currentSize += int64(n)
 	}
 	w.mu.Unlock()
-	return n, err
+	return err
 }
 
 func (w *RotateFileWriter) checkCapacityAndRotate() error {
@@ -69,7 +81,7 @@ func (w *RotateFileWriter) checkCapacityAndRotate() error {
 	if w.currentSize >= w.capacity {
 		name := w.f.Name()
 		if err := w.f.Close(); err != nil {
-			return err
+			return errors.Wrap(err, "error closing file")
 		}
 		if err := rotate(name, w.maxFiles); err != nil {
 			return err
@@ -94,12 +106,12 @@ func rotate(name string, maxFiles int) error {
 		toPath := name + "." + strconv.Itoa(i)
 		fromPath := name + "." + strconv.Itoa(i-1)
 		if err := os.Rename(fromPath, toPath); err != nil && !os.IsNotExist(err) {
-			return err
+			return errors.Wrap(err, "error rotating old log entries")
 		}
 	}
 
 	if err := os.Rename(name, name+".1"); err != nil && !os.IsNotExist(err) {
-		return err
+		return errors.Wrap(err, "error rotating current log")
 	}
 	return nil
 }