write error: sync /dev/stdout: invalid argument

[toefel18]

Thanks for opensourcing this library!

Everything is fine during program execution, but when the application shuts down (due to an error) zap logs to stderr: write error: sync /dev/stdout: invalid argument

Output:

2017-02-20T17:25:14.708+0100	info	starting
2017-02-20T17:25:14.708+0100	info	publishing	{"port": 8080}
2017-02-20T17:45:54.522+0100	fatal	Error publishing the API	{"error": "listen tcp :8080: bind: address already in use"}
2017-02-20 17:25:14.708574765 +0100 CET write error: sync /dev/stdout: invalid argument
exit status 1

Relevant set-up code:

config.FileLoggingEnabled = false
config.EncodeLogsAsJson = false
...
encCfg := zapcore.EncoderConfig{
	TimeKey:        "@timestamp",
	LevelKey:       "level",
	NameKey:        "logger",
	CallerKey:      "caller",
	MessageKey:     "msg",
	StacktraceKey:  "stacktrace",
	EncodeLevel:    zapcore.LowercaseLevelEncoder,
	EncodeTime:     zapcore.ISO8601TimeEncoder,
	EncodeDuration: zapcore.NanosDurationEncoder,
}
...
func Configure() {
	writers := []zapcore.WriteSyncer{os.Stdout}
	if config.FileLoggingEnabled {
		writers = append(writers, newRollingFile(....))
	}
        GlobalLogger = newZapLogger(config.EncodeLogsAsJson, zapcore.NewMultiWriteSyncer(writers...))
}

func newZapLogger(encodeAsJSON bool, output zapcore.WriteSyncer) *zap.Logger {
	encoder := zapcore.NewConsoleEncoder(encoderCfg)
	if encodeAsJSON {
		encoder = zapcore.NewJSONEncoder(encoderCfg)
	}
	return zap.New(zapcore.NewCore(encoder, output, zap.NewAtomicLevel()))
}

[akshayjshah]

These logs are coming from zapcore.CheckedEntry.Write, which is attempting to inform you that writing your last log messages failed. In particular, it looks like zapcore.ioCore.Write failed to Sync after your panic- or fatal-level logs.

That shouldn't happen when syncing os.Stdout, and the "invalid argument" error isn't coming from within zap.

Can you provide one or more of:

• a stacktrace
• a minimal reproduction
• a link to the code you're showing snippets of (in particular, what are the arguments and implementation of newRollingFile)?

[toefel18]

please see this gist for the code: uber-zap-logger.go

To reproduce:

1. make package uber-logger-test inside GOPATH/src

   import (
       "uber-logger-test/log"
       "go.uber.org/zap"
       "os"
       "strings"
       "time"
       "gopkg.in/gin-gonic/gin.v1"
   )
   
   func main() {
   	log.Configure(log.Config{
   		EncodeLogsAsJson:   false,
   		FileLoggingEnabled: false,
   		Directory:          "/var/log/uber-test",
   		Filename:           "uberlogger.log",
   		MaxSize:            20, //MB
   		MaxBackups:         1,
   		MaxAge:             31, //Days
   	})
   
   	router := gin.New()
   	router.GET("/hello", func(c *gin.Context){
   		c.String(200, "test")
   	})
   
   	if err := router.Run(":8080"); err != nil {
   		log.Fatal("Error publishing the API", zap.Error(err))
   		os.Exit(30)
   	}
   }      
   

2. paste the code below in main.go

3. place the gist file in uber-logger-test/log package

4. go run the application twice, so that the second run gets a address already in use error.

5. observe logging of the failed run with:

2017-02-21 09:37:59.757838684 +0100 CET write error: sync /dev/stdout: invalid argument

There is no stacktrace I can help you with

[akshayjshah]

Can you trim that example code back? There's a lot there, and I suspect that most of it isn't relevant to this issue. If you can show me the smallest possible code snippet that fails this way, I'm happy to debug from there.

[Ulexus]

This is trivial to reproduce:

package main

import "go.uber.org/zap"

func main() {
	log, err := zap.NewDevelopment()
	if err != nil {
		return
	}
	log.Fatal("dying now")
}

~/t/testzap $ go run main.go
2017-03-03T23:37:09.333-0500	FATAL	/home/scmccord/tmp/testzap/main.go:10	dying now
goroutine 1 [running]:
go.uber.org/zap.takeStacktrace(0xc420039800, 0x400, 0x400, 0x0, 0x0, 0xc420057c01)
	/home/scmccord/go/src/go.uber.org/zap/stacktrace.go:33 +0x64
go.uber.org/zap.Stack(0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/home/scmccord/go/src/go.uber.org/zap/field.go:205 +0x7a
go.uber.org/zap.(*Logger).check(0xc420014360, 0xc420010f05, 0x694c26, 0x9, 0x0)
	/home/scmccord/go/src/go.uber.org/zap/logger.go:268 +0x212
go.uber.org/zap.(*Logger).Fatal(0xc420014360, 0x694c26, 0x9, 0x0, 0x0, 0x0)
	/home/scmccord/go/src/go.uber.org/zap/logger.go:208 +0x44
main.main()
	/home/scmccord/tmp/testzap/main.go:10 +0x92

2017-03-03 23:37:09.33311913 -0500 EST write error: sync /dev/stderr: invalid argument
exit status 1

[toefel18]

Thanks a lot @Ulexus, I forgot to come back to this

[Ulexus]

This points out a surprise I had in the API. Since the logging output is buffered, I would have expected the API to offer some sort of Sync() or Flush() option to prevent something like this from occurring, but either I am blind or nonesuch exists.

[akshayjshah]

@Ulexus I'm unable to reproduce, which suggests that this is somehow environment-dependent.

$  cat main.go
package main

import "go.uber.org/zap"

func main() {
	l, err := zap.NewDevelopment()
	if err != nil {
		return
	}
	l.Fatal("the world is too cruel")
}

$  go run main.go
2017-03-04T14:59:19.706-0800	FATAL	/Users/ashah/src/github.com/akshayjshah/gobits/cmd/testzap/main.go:10	the world is too cruel
goroutine 1 [running]:
go.uber.org/zap.takeStacktrace(0xc420060c00, 0x400, 0x400, 0x0, 0x0, 0xc42004dc01)
	/Users/ashah/src/go.uber.org/zap/stacktrace.go:33 +0x64
go.uber.org/zap.Stack(0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/Users/ashah/src/go.uber.org/zap/field.go:205 +0x7a
go.uber.org/zap.(*Logger).check(0xc4200722a0, 0xc420079105, 0x26d691, 0x16, 0x0)
	/Users/ashah/src/go.uber.org/zap/logger.go:268 +0x208
go.uber.org/zap.(*Logger).Fatal(0xc4200722a0, 0x26d691, 0x16, 0x0, 0x0, 0x0)
	/Users/ashah/src/go.uber.org/zap/logger.go:208 +0x44
main.main()
	/Users/ashah/src/github.com/akshayjshah/gobits/cmd/testzap/main.go:10 +0x88

exit status 1

If you and @toefel18 can post the output of go version and go env, that might help.

Regarding your API question, output isn't buffered by default. WriteSyncers may buffer, and they're responsible for flushing their buffers on potentially crashing logs (panic and above). There's a separate discussion about how we'd add buffering by default, and how we want to let users ensure that the buffer is flushed before main exits. See #281 for an early draft; we're working on something a bit nicer.

[Ulexus]

$ go version ; go env
go version go1.8 linux/amd64
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/scmccord/go"
GORACE=""
GOROOT="/usr/lib/go"
GOTOOLDIR="/usr/lib/go/pkg/tool/linux_amd64"
GCCGO="/usr/bin/gccgo"
CC="x86_64-pc-linux-gnu-gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build562226690=/tmp/go-build -gno-record-gcc-switches"
CXX="x86_64-pc-linux-gnu-g++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

and thanks for the clarification on buffering

[Ulexus]

I have also verified that the same problem occurs running in Docker containers using the golang:1.7 and golang:1.6 images. (the original result is from my workstation outside of a container).

It also occurs whether executing a built binary (go build; ./testgo) or when using go run (as above).

[prashantv]

Thanks for the report @toefel18 and @Ulexus

The issue here is that fsync behaves differently on OSX and Linux. When doing a Fatal, zap calls Sync on os.Stdout, which ends up calling fsync.

The documentation for fsync specifies that EINVAL may be returned depending on the type of file passed in, but does not explicitly call out whether it will work for stdout. The Linux documentation says:

       EROFS, EINVAL
              fd is bound to a special file which does not support synchronization.

The OSX documentation is similar:

     [EINVAL]           fildes refers to a file type (e.g., a socket) that does not support this operation.

This simple example reproduces the issue with fsync behaving differently:

$ cat main.go
package main

import (
	"fmt"
	"os"
)

func main() {
	fmt.Println(os.Stdout.Sync())
}

OSX:

$ uname -a
Darwin prashant-[...] 15.6.0 Darwin Kernel Version 15.6.0: Mon Jan  9 23:07:29 PST 2017; root:xnu-3248.60.11.2.1~1/RELEASE_X86_64 x86_64


$ go run main.go
<nil>

Linux:

$ uname -a
Linux [..] 4.4.27 #1 SMP Sun Oct 23 18:20:55 UTC 2016 x86_64 GNU/Linux
$ go run main.go
fsync: invalid argument

@akshayjshah We have a couple of options here:

1. Ignore all errors from Sync
2. Specifically ignore EINVAL errors (harder to detect and more error prone)

[Ulexus]

Aha; that makes sense, then.

It looks like ErrInvalid is fine to ignore except for the case that the writer is nil... and I'm not altogether certain it really matters then for the purposes of the logger. Since Go offers a sentinel error for EINVAL (os.ErrInvalid) in this context, that should be pretty error-free for anything which is an os.File.

Thus, you can try a type assertion on zapcore.WriteSyncer to *os.File, and if that works, you can safely ignore os.ErrInvalid when calling Sync(). I think I'd wrap it or flag it so you don't have to check the type assertion on each call to Sync, of course.

[akshayjshah]

Ah, the joys of platform-dependent behavior. Thanks for the detailed report and follow-up!

@Ulexus are you interested in opening a PR to fix this?

[prashantv]

@Ulexus Unfortunately os.ErrInvalid is not a platform independent way to check for EINVAL,

https://golang.org/src/os/error.go#L13:

ErrInvalid    = errors.New("invalid argument") // methods on File will return this error when the receiver is nil

The specific error returned seems to be dependent on the os and syscall packages, and Go version.

[Ulexus]

Since os.ErrInvalid is just a constant, I'm pretty sure that is platform-agnostic. I was referencing precisely that line when I mentioned it before... what am I missing which might indicate lack of platform agnosticity?

It is true that if the WriteSyncer is not an instance of os.File, the error will be different, but that is why I suggested doing a type assertion before handling the error.

I'll see if I can whip something up as a PR, sure.

[prashantv]

Sorry, what I meant to say is that ErrInvalid is not the error that's returned in this case. As the comment on ErrInvalid says, the error is only returned when the *File methods are called with *File is nil. This snippet shows that the returned error is not os.ErrInvalid in the case when Sync fails:

package main

import (
	"fmt"
	"os"
)

func main() {
	err := os.Stdout.Sync()
	fmt.Println("err", err)
	fmt.Println("is ErrInvalid", err == os.ErrInvalid)
}

Output on Linux:

$ go run main.go
err fsync: invalid argument
is ErrInvalid false

[Ulexus]

Aha; I did not interpret that comment as an exclusive description. I see from your example that it is.

I think the easiest solution here is to just modify zapcore.AddSync() to test-call w.Sync(), and if that (first) call to Sync() returns an error (regardless of the reason), use the writerWrapper instead.

Does that sound reasonable?

[Ulexus]

In particular, something like this:

func AddSync(w io.Writer) WriteSyncer {
	switch w := w.(type) {
	case WriteSyncer:
		if !checkSync(w) {
			return writerWrapper{w}
		}
		return w
	default:
		return writerWrapper{w}
	}
}

// checkSync executes a Sync() on the WriteSyncer to check whether it operates
// cleanly.  In the particular case of the WriteSyncer being a special file,
// calling Sync will return an `os.ErrInvalid` error.  If, for whatever reason,
// the call of `Sync()` returns an error, this will return a `false`.
func checkSync(w WriteSyncer) bool {
	if err := w.Sync(); err != nil {
		return false
	}
	return true
}

[prashantv]

I think that checking the first error and then deciding whether to ignore errors might be a little surprising. I think I'd prefer to either always ignore, or write a function to detect these EINVAL errors and test it thoroughly to make sure it works across the cross product of OS/Go versions, and only ignore those errors.

I think @peter-edge had some thoughts on the PR as well.

[akshayjshah]

I'd prefer to ignore these errors entirely (in the short term, at least). This isn't a breaking API change, and I'd like to tread cautiously when introducing Go version and OS-dependent behavior.

In practice, there's little that the user can do about failures to sync files. Network-backed WriteSyncers (e.g., Kafka clients) should emit their own logs and/or metrics.

We can always revisit this later - I'll file a separate issue to track that.

[BatmanAoD]

I'm a bit confused. When writing to stdout, is flushing even necessary, or does each logging message automatically flush the buffer? (Or does zap not even have an internal buffer?)

[stevenh]

If you want to check for this invalid argument you can do so with:

if errors.Is(syncErr, syscall.EINVAL) {
    // Sync is not supported on os.Stderr / os.Stdout on all platforms.
}

[BatmanAoD]

@stevenh I'm not sure if that's intended as a response to my question, or unrelated. In my case, I know the error will always occur, because I'm always logging to stdout and only run on Linux and Mac OS. What I'm wondering is whether there is any internal buffering in zap itself that is flushed on Sync calls.

[stevenh]

@stevenh I'm not sure if that's intended as a response to my question, or unrelated. In my case, I know the error will always occur, because I'm always logging to stdout and only run on Linux and Mac OS. What I'm wondering is whether there is any internal buffering in zap itself that is flushed on Sync calls.

My intent was to let people know its syscall.EINVAL instead of os.ErrInvalid I saw listed above, but flagged didn't work. I've confirmed this works.

With regards to buffering, even if there isn't buffering it's good practice to flush your output to avoid loss. This can happen even if its at the OS layer, so beyond go's control.

By default os.Stdout / os.Stderr is unbuffered in golang, to make it buffered you can use:

writer := bufio.NewWriter(os.Stdout)