fixes races with Output/OnHup on FileWriterOutput

atomics_safe.go

@@ -0,0 +1,37 @@
+// Copyright (C) 2016 Space Monkey, Inc.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//   http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+// +build appengine
+
+package spacelog
+
+import "sync"
+
+// TODO(jeff): make this mutex smaller scoped, perhaps based on the arguments
+// to the atomics?
+var bigHonkinMutex sync.Mutex
+
+func loadWriterOutput(addr **WriterOutput) (val *WriterOutput) {
+	bigHonkinMutex.Lock()
+	val = *addr
+	bigHonkinMutex.Unlock()
+	return val
+}
+
+func storeWriterOutput(addr **WriterOutput, val *WriterOutput) {
+	bigHonkinMutex.Lock()
+	*addr = val
+	bigHonkinMutex.Unlock()
+	return s
+}

atomics_unsafe.go

@@ -0,0 +1,33 @@
+// Copyright (C) 2016 Space Monkey, Inc.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//   http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+// +build !appengine
+
+package spacelog
+
+import (
+	"sync/atomic"
+	"unsafe"
+)
+
+func loadWriterOutput(addr **WriterOutput) (val *WriterOutput) {
+	return (*WriterOutput)(atomic.LoadPointer(
+		(*unsafe.Pointer)(unsafe.Pointer(addr))))
+}
+
+func storeWriterOutput(addr **WriterOutput, val *WriterOutput) {
+	atomic.StorePointer(
+		(*unsafe.Pointer)(unsafe.Pointer(addr)),
+		unsafe.Pointer(val))
+}

output.go

@@ -115,6 +115,7 @@ type HupHandlingTextOutput interface {
 // to open the file previously, or if an appropriate signal has been received.
 type FileWriterOutput struct {
 	*WriterOutput
+	mu   sync.Mutex
 	path string
 }
 
@@ -145,34 +146,67 @@ func (fo *FileWriterOutput) fallbackLog(tmpl string, args ...interface{}) {
 	fmt.Fprintf(os.Stderr, tmpl, args...)
 }
 
-// Output a log line by writing it to the file. If the file has been
-// released, try to open it again. If that fails, cry for a little
-// while, then throw away the message and carry on.
+// Output a log line by writing it to the file.
 func (fo *FileWriterOutput) Output(ll LogLevel, message []byte) {
-	if fo.WriterOutput == nil {
-		fh, err := fo.openFile()
-		if err != nil {
-			fo.fallbackLog("Could not open %#v: %s", fo.path, err)
-			return
-		}
-		fo.WriterOutput = NewWriterOutput(fh)
+	wo := fo.loadWriterOutput()
+	if wo == nil {
+		return
 	}
-	fo.WriterOutput.Output(ll, message)
+	wo.Output(ll, message)
+}
+
+// loadWriterOutput tries to load the most recent version of fo.WriterOutput.
+// It uses atomics first, and falls back to a mutex if it's nil. If the file
+// has been  released, try to open it again. If that fails, cry for a little
+// while, then throw away the message and carry on.
+func (fo *FileWriterOutput) loadWriterOutput() (wo *WriterOutput) {
+	wo = loadWriterOutput(&fo.WriterOutput)
+	if wo != nil {
+		return wo
+	}
+
+	fo.mu.Lock()
+
+	wo = loadWriterOutput(&fo.WriterOutput)
+	if wo != nil {
+		fo.mu.Unlock()
+		return wo
+	}
+
+	fh, err := fo.openFile()
+	if err != nil {
+		fo.mu.Unlock()
+		fo.fallbackLog("Could not open %#v: %s", fo.path, err)
+		return nil
+	}
+
+	wo = NewWriterOutput(fh)
+	storeWriterOutput(&fo.WriterOutput, wo)
+	fo.mu.Unlock()
+
+	return wo
 }
 
 // Throw away any references/handles to the output file. This probably
 // means the admin wants to rotate the file out and have this process
 // open a new one. Close the underlying io.Writer if that is a thing
-// that it knows how to do.
+// that it knows how to do. Note that any concurrent Output calls with an
+// OnHup may end up attempting to write to some Closed output.
 func (fo *FileWriterOutput) OnHup() {
-	if fo.WriterOutput != nil {
-		wc, ok := fo.WriterOutput.w.(io.Closer)
-		if ok {
-			err := wc.Close()
-			if err != nil {
-				fo.fallbackLog("Closing %#v failed: %s", fo.path, err)
-			}
+	fo.mu.Lock()
+	wo := loadWriterOutput(&fo.WriterOutput)
+	if wo == nil {
+		fo.mu.Unlock()
+		return
+	}
+	storeWriterOutput(&fo.WriterOutput, nil)
+	fo.mu.Unlock()
+
+	wc, ok := wo.w.(io.Closer)
+	if ok {
+		err := wc.Close()
+		if err != nil {
+			fo.fallbackLog("Closing %#v failed: %s", fo.path, err)
 		}
-		fo.WriterOutput = nil
 	}
 }

output_test.go

@@ -0,0 +1,65 @@
+// Copyright (C) 2016 Space Monkey, Inc.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//   http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package spacelog
+
+import (
+	"io/ioutil"
+	"os"
+	"runtime"
+	"testing"
+)
+
+func TestFileWriterOutput(t *testing.T) {
+	stack := func() string {
+		var buf [4096]byte
+		return string(buf[:runtime.Stack(buf[:], false)])
+	}
+	assertNoError := func(err error) {
+		if err != nil {
+			t.Fatalf("error: %v\n%s", err, stack())
+		}
+	}
+	assertContents := func(path, contents string) {
+		data, err := ioutil.ReadFile(path)
+		assertNoError(err)
+		if string(data) != contents {
+			t.Fatalf("%q != %q\n%s", data, contents, stack())
+		}
+	}
+
+	fh, err := ioutil.TempFile("", "spacelog-")
+	assertNoError(err)
+	assertNoError(fh.Close())
+
+	name := fh.Name()
+	rotated_name := name + ".1"
+	defer os.Remove(name)
+	defer os.Remove(rotated_name)
+
+	fwo, err := NewFileWriterOutput(fh.Name())
+	assertNoError(err)
+
+	fwo.Output(Critical, []byte("hello world"))
+	assertContents(name, "hello world\n")
+
+	fwo.OnHup()
+
+	assertNoError(os.Rename(name, rotated_name))
+	assertContents(rotated_name, "hello world\n")
+
+	fwo.Output(Critical, []byte("hello universe"))
+	assertContents(name, "hello universe\n")
+	assertContents(rotated_name, "hello world\n")
+}