Monitoring Log Volume

zerolog

Writing a custom write adapter

package log_instrumentation

import (
	"io"

	"github.com/rs/zerolog"

	"github.com/prometheus/client_golang/prometheus"
	"github.com/prometheus/client_golang/prometheus/promauto"
)

var (
	logMessagesLines = promauto.NewCounterVec(prometheus.CounterOpts{
		Name: "log_messages_lines_total",
		Help: "Total number of log messages.",
	}, []string{"level"})

	logMessagesBytes = promauto.NewCounterVec(prometheus.CounterOpts{
		Name: "log_messages_size_bytes_total",
		Help: "Total size of log messages.",
	}, []string{"level"})
)

type InstrumentedWriteAdapter struct {
	io.Writer
}

func (lw InstrumentedWriteAdapter) WriteLevel(l zerolog.Level, p []byte) (n int, err error) {
	level := l.String()
	logMessagesLines.WithLabelValues(level).Inc()
	logMessagesBytes.WithLabelValues(level).Add(float64(len(p)))
	return lw.Write(p)
}

func (lw InstrumentedWriteAdapter) Close() error {
	if closer, ok := lw.Writer.(io.Closer); ok {
		return closer.Close()
	}
	return nil
}

Usage

package log_instrumentation

import (
	"os"
	"testing"

	"github.com/rs/zerolog"

	"github.com/prometheus/client_golang/prometheus/testutil"

	"github.com/stretchr/testify/assert"
)

func TestHook(t *testing.T) {
	logger := zerolog.New(os.Stdout).With().Logger()
	logger = logger.Output(&InstrumentedWriteAdapter{os.Stdout})

	logger.Info().Msg("hello world")
	logger.Info().Msg("hello world")
	logger.Error().Msg("hello world")

	assert.Equal(t, float64(2), testutil.ToFloat64(logMessagesLines.WithLabelValues("info")))
	assert.Equal(t, float64(82), testutil.ToFloat64(logMessagesBytes.WithLabelValues("info")))

	assert.Equal(t, float64(1), testutil.ToFloat64(logMessagesLines.WithLabelValues("error")))
	assert.Equal(t, float64(42), testutil.ToFloat64(logMessagesBytes.WithLabelValues("error")))
}

logrus

Writing a custom formatter

package log_instrumentation

import (
	"github.com/sirupsen/logrus"

	"github.com/prometheus/client_golang/prometheus"
	"github.com/prometheus/client_golang/prometheus/promauto"
)

var (
	logMessagesLines = promauto.NewCounterVec(prometheus.CounterOpts{
		Name: "log_messages_lines_total",
		Help: "Total number of log messages.",
	}, []string{"level"})

	logMessagesBytes = promauto.NewCounterVec(prometheus.CounterOpts{
		Name: "log_messages_size_bytes_total",
		Help: "Total size of log messages.",
	}, []string{"level"})
)

type InstrumentedTextFormatter struct {
	logrus.TextFormatter
}

func (f *InstrumentedTextFormatter) Format(e *logrus.Entry) ([]byte, error) {
	bs, err := f.TextFormatter.Format(e)
	level := e.Level.String()
	logMessagesLines.WithLabelValues(level).Inc()
	logMessagesBytes.WithLabelValues(level).Add(float64(len(bs)))
	return bs, err
}

type InstrumentedJsonFormatter struct {
	logrus.JSONFormatter
}

func (f *InstrumentedJsonFormatter) Format(e *logrus.Entry) ([]byte, error) {
	bs, err := f.JSONFormatter.Format(e)
	level := e.Level.String()
	logMessagesLines.WithLabelValues(level).Inc()
	logMessagesBytes.WithLabelValues(level).Add(float64(len(bs)))
	return bs, err
}

Usage

package log_instrumentation

import (
	"testing"

	"github.com/sirupsen/logrus"

	"github.com/prometheus/client_golang/prometheus/testutil"

	"github.com/stretchr/testify/assert"
)

func TestHook(t *testing.T) {
	formatter := &InstrumentedTextFormatter{}
	formatter.DisableTimestamp = true

	logger := logrus.New()
	logger.SetFormatter(formatter)

	logger.Info("hello world")
	logger.Info("hello world")
	logger.Error("hello world")

	assert.Equal(t, float64(2), testutil.ToFloat64(logMessagesLines.WithLabelValues("info")))
	assert.Equal(t, float64(58), testutil.ToFloat64(logMessagesBytes.WithLabelValues("info")))

	assert.Equal(t, float64(1), testutil.ToFloat64(logMessagesLines.WithLabelValues("error")))
	assert.Equal(t, float64(30), testutil.ToFloat64(logMessagesBytes.WithLabelValues("error")))
}

go-kit/log

Using a custom formatter

// log/fmt.go
package log

import (
	"sync"
	"bytes"
	"io"

	"github.com/go-logfmt/logfmt"
	"github.com/go-kit/log/level"
	logkit "github.com/go-kit/log"
)

type logfmtEncoder struct {
	*logfmt.Encoder
	buf bytes.Buffer
}

func (l *logfmtEncoder) Reset() {
	l.Encoder.Reset()
	l.buf.Reset()
}

var logfmtEncoderPool = sync.Pool{
	New: func() interface{} {
		var enc logfmtEncoder
		enc.Encoder = logfmt.NewEncoder(&enc.buf)
		return &enc
	},
}

type logfmtLogger struct {
	w io.Writer
}

func NewLogfmtLogger(w io.Writer) logkit.Logger {
	return &logfmtLogger{w}
}

func (l logfmtLogger) Log(keyvals ...interface{}) error {
	enc := logfmtEncoderPool.Get().(*logfmtEncoder)
	enc.Reset()
	defer logfmtEncoderPool.Put(enc)

	if err := enc.EncodeKeyvals(keyvals...); err != nil {
		return err
	}

	if err := enc.EndRecord(); err != nil {
		return err
	}

	n, err := l.w.Write(enc.buf.Bytes())

	lev := "unknown"
	for i := 1; i < len(keyvals); i += 2 {
		if v, ok := keyvals[i].(level.Value); ok {
			lev = v.String()
			break
		}
	}

	logMessages.WithLabelValues(lev).Inc()
	logMessagesSize.WithLabelValues(lev).Add(float64(n))

	return err
}

Tracking lines and size by severity

// log/log.go
package log

import (
	"os"

	logkit "github.com/go-kit/log"
	"github.com/go-kit/log/level"

	"github.com/prometheus/client_golang/prometheus"
)

var (
	logMessages = prometheus.NewCounterVec(prometheus.CounterOpts{
		Name: "log_messages_total",
		Help: "Total number of log messages.",
	}, []string{"level"})

	logMessagesSize = prometheus.NewCounterVec(prometheus.CounterOpts{
		Name: "log_messages_size_total",
		Help: "Total size of log messages.",
	}, []string{"level"})

	supportedLevels = []level.Value{
		level.DebugValue(),
		level.InfoValue(),
		level.WarnValue(),
		level.ErrorValue(),
	}
)

func init() {
	prometheus.MustRegister(logMessages)
	prometheus.MustRegister(logMessagesSize)
}

type InstrumentedLogger struct {
	logger logkit.Logger
}

func NewInstrumentedLogger(options level.Value, keyvals ...interface{}) (logkit.Logger, error) {
	logger := NewLogfmtLogger(logkit.NewSyncWriter(os.Stderr))

	logger = logkit.With(logger, "ts", logkit.DefaultTimestampUTC)
	logger = logkit.With(logger, keyvals...)
	logger = level.NewFilter(logger, level.Allow(options))

	for _, level := range supportedLevels {
		logMessages.WithLabelValues(level.String())
		logMessagesSize.WithLabelValues(level.String())
	}

	return &InstrumentedLogger{
		logger: logger,
	}, nil
}

func (pl *InstrumentedLogger) Log(kv ...interface{}) error {
	pl.logger.Log(kv...)
	return nil
}

Usage

// main.go
package main

import (
	"net/http"

	"github.com/mircodz/log/log"

	"github.com/go-kit/log/level"

	"github.com/prometheus/client_golang/prometheus/promhttp"
)

func main() {
	logger, err := log.NewInstrumentedLogger(level.DebugValue())
	if err != nil {
		panic(err)
	}

	level.Debug(logger).Log("message", "Hello, World!")
	level.Info(logger).Log("message", "Hello, World!")
	level.Warn(logger).Log("message", "Hello, World!")
	level.Error(logger).Log("message", "Hello, World!")

	http.Handle("/metrics", promhttp.Handler())
    http.ListenAndServe(":2112", nil)
}

Spring

Writing a custom encoder

package com.commons.logging;

import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.spi.ILoggingEvent;
import io.micrometer.core.instrument.MeterRegistry;
import net.logstash.logback.encoder.LogstashEncoder;

public class InstrumentedEncoder extends LogstashEncoder {

    private static final String METRIC_LINES_NAME = "log_messages_lines";
    private static final String METRIC_SIZE_BYTES_NAME = "log_messages_size_bytes";
    private static final String LABEL_LEVEL_NAME = "level";

    private static MeterRegistry meterRegistry;
    private static InstrumentedEncoder instance;

    public InstrumentedEncoder() {
        instance = this;
    }

    public static InstrumentedEncoder bind(MeterRegistry other) {
        meterRegistry = other;
        return instance;
    }

    @Override
    public byte[] encode(ILoggingEvent event) {
        byte[] bytes = super.encode(event);
        if (meterRegistry != null) {
            final String level = switch (event.getLevel().levelInt) {
                case Level.ERROR_INT -> "error";
                case Level.WARN_INT -> "warn";
                case Level.INFO_INT -> "info";
                case Level.DEBUG_INT -> "debug";
                case Level.TRACE_INT -> "trace";
                default -> "unknown";
            };
            meterRegistry.counter(METRIC_LINES_NAME, LABEL_LEVEL_NAME, level).increment();
            meterRegistry.counter(METRIC_SIZE_BYTES_NAME, LABEL_LEVEL_NAME, level).increment(bytes.length);
        }
        return bytes;
    }
}

Usage

<!-- logback.xml -->
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="com.commons.logging.InstrumentedEncoder">
        </encoder>
    </appender>

    <root level="debug">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>
@Configuration
public class AppConfig {

    @Bean
    public InstrumentedEncoder instrumentedLogger(MeterRegistry meterRegistry) {
        return InstrumentedEncoder.bind(meterRegistry);
    }

}