logfile: Check if log is closed on close error during rotate

This prevents getting into a situation where a container log cannot make
progress because we tried to rotate a file, got an error, and now the
file is closed. The next time we try to write a log entry it will try
and rotate again but error that the file is already closed.

I wonder if there is more we can do to beef up this rotation logic.
Found this issue while investigating missing logs with errors in the
docker daemon logs like:

```
Failed to log message for json-file: error closing file: close <file>:
file already closed
```

I'm not sure why the original rotation failed since the data was no
longer available.

Signed-off-by: Brian Goff <cpuguy83@gmail.com>
(cherry picked from commit 3989f91075)
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
This commit is contained in:
Brian Goff 2020-05-06 09:35:13 -07:00
parent edf2c49410
commit 7d4dd91a52
2 changed files with 69 additions and 2 deletions

View file

@ -175,8 +175,11 @@ func (w *LogFile) checkCapacityAndRotate() error {
w.rotateMu.Lock() w.rotateMu.Lock()
fname := w.f.Name() fname := w.f.Name()
if err := w.f.Close(); err != nil { if err := w.f.Close(); err != nil {
w.rotateMu.Unlock() // if there was an error during a prior rotate, the file could already be closed
return errors.Wrap(err, "error closing file") if !errors.Is(err, os.ErrClosed) {
w.rotateMu.Unlock()
return errors.Wrap(err, "error closing file")
}
} }
if err := rotate(fname, w.maxFiles, w.compress); err != nil { if err := rotate(fname, w.maxFiles, w.compress); err != nil {
w.rotateMu.Unlock() w.rotateMu.Unlock()

View file

@ -11,6 +11,7 @@ import (
"time" "time"
"github.com/docker/docker/daemon/logger" "github.com/docker/docker/daemon/logger"
"github.com/docker/docker/pkg/pubsub"
"github.com/docker/docker/pkg/tailfile" "github.com/docker/docker/pkg/tailfile"
"gotest.tools/assert" "gotest.tools/assert"
) )
@ -201,3 +202,66 @@ func TestFollowLogsProducerGone(t *testing.T) {
default: default:
} }
} }
func TestCheckCapacityAndRotate(t *testing.T) {
dir, err := ioutil.TempDir("", t.Name())
assert.NilError(t, err)
defer os.RemoveAll(dir)
f, err := ioutil.TempFile(dir, "log")
assert.NilError(t, err)
l := &LogFile{
f: f,
capacity: 5,
maxFiles: 3,
compress: true,
notifyRotate: pubsub.NewPublisher(0, 1),
perms: 0600,
marshal: func(msg *logger.Message) ([]byte, error) {
return msg.Line, nil
},
}
defer l.Close()
assert.NilError(t, l.WriteLogEntry(&logger.Message{Line: []byte("hello world!")}))
dStringer := dirStringer{dir}
_, err = os.Stat(f.Name() + ".1")
assert.Assert(t, os.IsNotExist(err), dStringer)
assert.NilError(t, l.WriteLogEntry(&logger.Message{Line: []byte("hello world!")}))
_, err = os.Stat(f.Name() + ".1")
assert.NilError(t, err, dStringer)
assert.NilError(t, l.WriteLogEntry(&logger.Message{Line: []byte("hello world!")}))
_, err = os.Stat(f.Name() + ".1")
assert.NilError(t, err, dStringer)
_, err = os.Stat(f.Name() + ".2.gz")
assert.NilError(t, err, dStringer)
// Now let's simulate a failed rotation where the file was able to be closed but something else happened elsewhere
// down the line.
// We want to make sure that we can recover in the case that `l.f` was closed while attempting a rotation.
l.f.Close()
assert.NilError(t, l.WriteLogEntry(&logger.Message{Line: []byte("hello world!")}))
}
type dirStringer struct {
d string
}
func (d dirStringer) String() string {
ls, err := ioutil.ReadDir(d.d)
if err != nil {
return ""
}
var s strings.Builder
s.WriteString("\n")
for _, fi := range ls {
s.WriteString(fi.Name() + "\n")
}
return s.String()
}