Logging With Concurrency

[mattnenterprise]

I tried using this logger in a concurrent application, but the messages will run overtop of each other in the log. I am wondering if I am using it wrong, or the library isn't concurrent safe. I have a simple example:

package main

import "github.com/uber-go/zap"

var logger zap.Logger

func main() {
    logger = zap.NewJSON()

    for i := 0; i < 800; i++ {
        go printer(i)
    }
}

func printer(i int) {
    logger.Info("Counting",
        zap.Int("i", i),
    )
}

Here is a section of output from the above program:

{"msg":"Counting","level":"info","ts":1469196244924860064,"fields":{"i":8}}
{"msg":"Counting","level":"info","ts":1469196244924867134,"fields":{"i":42}}
{"msg":"Counting","level":"info","ts":1469196244924866589,"fields":{"i":20}}
{"msg":"Counti{"msg":"Counting","level":"info","ts":1469196244924879429,"fields":{"i":21}}
ng","level":"info","ts":1469196244924870959,"fields":{"i":9}}
{"msg":"Counting","level":"info","ts":1469196244924879050,"fields":{"i":36}}
{"msg":"Counting","level":"info","ts":1469196244924873937,"fields":{"i":43}}
{"msg":"Counting","level":"info","ts":1469196244924904543,"fields":{"i":22}}
{"msg":"Counting","level":"info","ts":1469196244924910632,"fields":{"i":10}}
{"msg":"Counting","level":"info","ts":1469196244924916792,"fields":{"i":23}}

[belak]

The given example will die early, not always writing all lines. I haven't been able to reproduce this under the following example, but this should at least ensure all lines are written.

package main

import (
    "sync"

    "github.com/uber-go/zap"
)

func main() {
    logger := zap.NewJSON()

    var wg sync.WaitGroup
    wg.Add(800)
    for i := 0; i < 800; i++ {
        go func(i int) {
            logger.Info("Counting",
                zap.Int("i", i),
            )
            wg.Done()
        }(i)
    }
    wg.Wait()
}

[mattnenterprise]

I have used your example and it still doesn't log the messages correctly. This is a section from the output:

{"msg":"Counting","level":"info","ts":1469218045539957730,"fields":{"i":724}}
{"msg":"Counting","level":"info","ts":1469218045539958356,"fields":{"i":745}}
{"msg":"Counting","level":"info","ts":1469218045539960912,"fields":{"i":6{"msg":"Counting","level":"info","ts":1469218045539963269,"fields":{"i":666}}
87}}
{"msg":"Counting","level":"info","ts":1469218045539966673,"fields":{"i":761}}
{"msg":"Counting","level":"info","ts":1469218045539966669,"fields":{"i":647}}
{"msg":"Counting","level":"info","ts":1469218045539968960,"fields":{"i":725}}
{"msg":"Counting","level":"info","ts":1469218045539968964,"fields":{"i":676}}

[tv42]

os.File.Write is just a loop over a syscall that can write less than what was requested. https://golang.org/src/os/file_unix.go#L243

You need to hold a mutex while writing. Should be easy to have that in jsonLogger. See https://golang.org/src/log/log.go#L48 field mu

[prashantv]

Thanks for filing this issue @mattnenterprise, you're right that zap does not protect multiple Write calls.

In this case, I don't think having a lock in the jsonLogger object is good enough -- it's possible that you have multiple loggers that are writing to the same underlying output, and you'll still see the same issues (intermixed logging between the different loggers).

I think we'll have to enforce this in the WriteSyncer output. We need to figure out:

• should zap serialize writes by wrapping all WriteSyncer types with a locking writer implementation
• is there use cases where a WriteSyncer might want to opt out of serialized Write calls (e.g., if it already handles concurrency or is capable of handling concurrent writes).

[MonsieurHorse]

"go" do not ensure the code output in line, which has no matter with zap log.