Why info level logs going to stderrstream.

[BhautikChudasama]

Describe the bug
I have deployed my application to kuberntes, and installed fluentbit that capture log and store to s3. But my every log is transfer to stderr stream.

Here is my logger initialization code.

logger, err := zap.NewProduction(zap.Hooks(func(e zapcore.Entry) error {
             // If log level is error, sentry capture the log
		if e.Level == zap.ErrorLevel {
			defer sentry.Flush(time.Second * 2)
			sentry.CaptureMessage(fmt.Sprintf("Error: %s\nCaller: %s\nStack: %s", e.Message, e.Caller, e.Stack))
		}
		return nil
}))

Here is the log from log file

{
  "date": "2023-03-18T08:00:16.435621Z",
  "log": "2023-03-18T09:00:02.155076073+01:00 stderr F {\"level\":\"info\",\"ts\":1679126402.1546938,\"caller\":\"jobs.go:55\",\"msg\":\"no pending things\",\"job\":\"job\"}",
  "kubernetes": {
    "pod_id": "6fc0b771-6a72-462d-a44d-a0b9514e14fd",
    "labels": {
      "controller-uid": "275c854e-b48c-4332-b896-029c81c3dda1",
    }
    "docker_id": "cc5a16cadad18b5d21c339968aff4c1e8574512872a851a422aa8b2d60afec56",
  }
}

I have removed some information from log due to security contraints.

[abhinav]

Hey, NewProduction writes all logs to stderr by default. (This is documented in NewProductionConfig; it will be made clearer in the next release since we added more docs there).

If you want logs that you're sending to Sentry to not go to stderr, you can't use hooks for that. Hooks are just observers--they can have side effects but they can't change the behavior of the logger.

To prevent logs you're writing to Sentry from going to the output stream, you'll want to wrap the core.

Zap's Core type has a Check method:

	// Check determines whether the supplied Entry should be logged (using the
	// embedded LevelEnabler and possibly some extra logic). If the entry
	// should be logged, the Core adds itself to the CheckedEntry and returns
	// the result.
	//
	// Callers must use Check before calling Write.
	Check(Entry, *CheckedEntry) *CheckedEntry

The key there is that the Core adds itself to the CheckedEntry (with CheckedEntry.AddCore) and returns the new CheckedEntry. The Logger will call CheckedEntry.Write which will call Core.Write for all added cores.

So, if you want Sentry-logged messages to not be sent to stderr, you need to:

• wrap the Core with a custom SentryCore
• In SentryCore.Check, if you want a message sent to Sentry, add the SentryCore to the entry. Otherwise, add the wrapped core to it.
• In SentryCore.Write, send the message to Sentry

So it should look roughly like this:

type sentryCore struct{ zapcore.Core }

// Adds self as the core for error or higher, and the base core for everything else.
// This has the effect of writing to sentryCore for every message that is an error or higher.
// And the wrapped core for everything else.
func (sc *sentryCore) Check(ent zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry {
  if ent.Level >= zapcore.ErrorLevel {
    return ce.AddCore(ent, sc)
  } else {
    return ce.AddCore(ent, sc.Core)
  }
}

// This is called only if we did ce.AddCore(ent, sc) above.
func (sc *sentryCore) Write(ent zapcore.Entry, fields []zapcore.Field) error {
  sentry.CaptureMessage(...)
}

[BhautikChudasama]

Thanks @abhinav for comment, Do I need to write Info, Debug method for sentryCore?

[abhinav]

No, you don't need to add Info, Debug, etc. methods to the Core implementation.
The Core is the lower level piece through which all log messages go.
Check out the interface definition at https://pkg.go.dev/go.uber.org/zap/zapcore#Core.
The level of a log message is on the Entry received by Core.Check.

type Entry struct {
	Level      Level

[BhautikChudasama]

Thanks @abhinav for your help, Here is my implementation. I posted late due to busy schedule.

type sentryCore struct {
	core   zapcore.Core
	client *sentry.Client
}

func (s *sentryCore) Enabled(level zapcore.Level) bool {
	return s.core.Enabled(level)
}

func (s *sentryCore) With(fields []zapcore.Field) zapcore.Core {
	return &sentryCore{
		core:   s.core.With(fields),
		client: s.client,
	}
}

func (s *sentryCore) Check(entry zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry {
	if s.Enabled(entry.Level) {
		return ce.AddCore(entry, s)
	} else {
		return ce
	}
}

func (s *sentryCore) Write(entry zapcore.Entry, fields []zapcore.Field) error {
	if entry.Level >= zapcore.ErrorLevel {
		event := sentry.NewEvent()
		event.Message = entry.Message
		event.Level = sentry.Level(sentry.LevelError)
		data := make(map[string]interface{})
		for _, field := range fields {
			if field.String != "" {
				data[field.Key] = field.String
			} else if field.Integer != 0 {
				data[field.Key] = field.Integer
			} else if field.Type == zapcore.ErrorType {
				data[field.Key] = fmt.Sprintf("%v", field.Interface)
			} else {
				data[field.Key] = field.Interface
			}
		}
		data["stackTrace"] = entry.Stack
		data["caller"] = entry.Caller
		event.Extra = data

		s.client.CaptureEvent(event, nil, nil)
	}

	return s.core.Write(entry, fields)
}

func (s *sentryCore) Sync() error {
	return s.core.Sync()
}

func GetLogger(config *config.Config) (*zap.Logger, error) {
	client, err := sentry.NewClient(sentry.ClientOptions{
		Dsn: config.App.SentryDSN,
	})

	if err != nil {
		return nil, err
	}

	encoderConfig := zap.NewProductionEncoderConfig()
	encoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder

	consoleOnly := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool {
		return lvl < zap.ErrorLevel
	})

	errOnly := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool {
		return lvl == zap.ErrorLevel
	})

	consoleCore := zapcore.NewCore(zapcore.NewJSONEncoder(encoderConfig), zapcore.Lock(os.Stdout), consoleOnly)
	errCore := zapcore.NewCore(zapcore.NewJSONEncoder(encoderConfig), zapcore.Lock(os.Stderr), errOnly)

	sentryCore := &sentryCore{core: errCore, client: client}
	logger := zap.New(zapcore.NewTee(sentryCore, consoleCore), zap.AddCaller(), zap.AddStacktrace(zap.ErrorLevel), zap.Fields())
	defer logger.Sync()

	return logger, nil
}