Why custom encoding is lost after calling logger.With in Uber Zap?

Question

(based on this question: Uber Zap Logger: how to prepend every log entry with a string)

I replaced the Encoder of my uber-zap logger with a custom one to prepend every log entry with a SystemD-friendly error level (<LEVEL>), but now after I use the logger with additional fields (With(fields ...Field)), the custom prepending is gone:

package main

import (
    "os"

    "go.uber.org/zap"
    "go.uber.org/zap/buffer"
    "go.uber.org/zap/zapcore"
)

func getConfig() zap.Config {
    // your current config options
    return zap.NewProductionConfig()
}

type prependEncoder struct {
    // embed a zapcore encoder
    // this makes prependEncoder implement the interface without extra work
    zapcore.Encoder

    // zap buffer pool
    pool buffer.Pool
}

// EncodeEntry implementing only EncodeEntry
func (e *prependEncoder) EncodeEntry(entry zapcore.Entry, fields []zapcore.Field) (*buffer.Buffer, error) {
    // new log buffer
    buf := e.pool.Get()

    // prepend the JournalD prefix based on the entry level
    buf.AppendString(e.toJournaldPrefix(entry.Level))
    buf.AppendString(" ")

    // calling the embedded encoder's EncodeEntry to keep the original encoding format
    consolebuf, err := e.Encoder.EncodeEntry(entry, fields)
    if err != nil {
        return nil, err
    }

    // just write the output into your own buffer
    _, err = buf.Write(consolebuf.Bytes())
    if err != nil {
        return nil, err
    }
    return buf, nil
}

// some mapper function
func (e *prependEncoder) toJournaldPrefix(lvl zapcore.Level) string {
    switch lvl {
    case zapcore.DebugLevel:
        return "<7>"
    case zapcore.InfoLevel:
        return "<6>"
    case zapcore.WarnLevel:
        return "<4>"
    }
    return ""
}

func main() {
    cfg := getConfig()

    // constructing our prependEncoder with a ConsoleEncoder using your original configs
    enc := &prependEncoder{
        Encoder: zapcore.NewConsoleEncoder(cfg.EncoderConfig),
        pool:    buffer.NewPool(),
    }

    logger := zap.New(
        zapcore.NewCore(
            enc,
            os.Stdout,
            zapcore.DebugLevel,
        ),
        // this mimics the behavior of NewProductionConfig.Build
        zap.ErrorOutput(os.Stderr),
    )

    logger.Info("this is info")
    logger.Debug("this is debug")
    logger.Warn("this is warn")

    logger = logger.With(zap.String("foo", "bar"))

    logger.With(zap.String("foo", "bar")).Info("this does not have the prefix :(")
}

The output I get is:

<6> 1.640656130756576e+09   info    this is info
<7> 1.640656130756611e+09   debug   this is debug
<4> 1.640656130756615e+09   warn    this is warn
1.6406561307566311e+09  info    this does not have the prefix :(    {"foo": "bar"}

What am I doing wrong?

Answer 1

You have to also implement Clone() from the zapcore.Encoder interface. If you wish to keep the parent logger unaltered, you have to construct an actual clone — possibly with the same config, so you might want to store it as a field:

type prependEncoder struct {
    zapcore.Encoder
    pool buffer.Pool
    cfg  zapcore.EncoderConfig
}

func (e *prependEncoder) Clone() zapcore.Encoder {
    return &prependEncoder{
        // cloning the encoder with the base config
        Encoder: zapcore.NewConsoleEncoder(e.cfg),
        pool:    buffer.NewPool(),
        cfg:     e.cfg,
    }
}

If you don't implement it, the method that runs is the next shallowest one when calling logger.Clone(), which is the Clone() declared on the embedded zapcore.Encoder. That one then doesn't have your custom EncodeEntry anymore.

Now running the following:

    logger.Info("this is info")
    logger.Debug("this is debug")
    logger.Warn("this is warn")
    child := logger.With(zap.String("foo", "bar"))
    logger.Warn("original")
    child.Info("new one")

Outputs:

<6> INFO        this is info
<7> DEBUG       this is debug
<4> WARN        this is warn
cloning...
<4> WARN        original
<6> INFO        new one {"foo": "bar"}