pomerium/internal/log/log_test.go

package log_test

import (
	"context"
	"errors"
	"flag"
	"os"
	"time"

	"github.com/rs/zerolog"
	zerologlog "github.com/rs/zerolog/log"

	"github.com/pomerium/pomerium/internal/log"
)

func captureOutput(f func()) {
	// In order to always output a static time to stdout for these
	// examples to pass, we need to override zerolog.TimestampFunc
	// and log.Logger globals -- you would not normally need to do this
	originalTimestampFunc := zerolog.TimestampFunc
	zerolog.TimestampFunc = func() time.Time {
		return time.Date(2008, 1, 8, 17, 5, 5, 0, time.UTC)
	}

	originalLogger := zerologlog.Logger
	newLogger := originalLogger.
		Output(os.Stdout).
		Level(zerolog.TraceLevel)
	zerologlog.Logger = newLogger
	zerolog.DefaultContextLogger = &newLogger

	f()

	zerolog.DefaultContextLogger = &originalLogger
	zerolog.TimestampFunc = originalTimestampFunc
	zerologlog.Logger = originalLogger
}

// Simple logging example using the Print function in the log package
// Note that both Print and Printf are at the debug log level by default
func ExamplePrint() {
	captureOutput(func() {
		log.Print("hello world")
	})
	// Output: {"level":"debug","time":"2008-01-08T17:05:05Z","message":"hello world"}
}

func ExampleWith() {
	captureOutput(func() {
		sublog := log.With().Str("foo", "bar").Logger()
		sublog.Debug().Msg("hello world")
	})
	// Output: {"level":"debug","foo":"bar","time":"2008-01-08T17:05:05Z","message":"hello world"}
}

// Simple logging example using the Printf function in the log package
func ExamplePrintf() {
	captureOutput(func() {
		log.Printf("hello %s", "world")
	})
	// Output: {"level":"debug","time":"2008-01-08T17:05:05Z","message":"hello world"}
}

// Example of a log with no particular "level"
func ExampleLog() {
	captureOutput(func() {
		log.Log(context.Background()).Msg("hello world")
	})
	// Output: {"time":"2008-01-08T17:05:05Z","message":"hello world"}
}

// Example of a log at a particular "level" (in this case, "debug")
func ExampleDebug() {
	captureOutput(func() {
		log.Debug(context.Background()).Msg("hello world")
	})
	// Output: {"level":"debug","time":"2008-01-08T17:05:05Z","message":"hello world"}
}

// Example of a log at a particular "level" (in this case, "info")
func ExampleInfo() {
	captureOutput(func() {
		log.Info(context.Background()).Msg("hello world")
	})
	// Output: {"level":"info","time":"2008-01-08T17:05:05Z","message":"hello world"}
}

// Example of a log at a particular "level" (in this case, "warn")
func ExampleWarn() {
	captureOutput(func() {
		log.Warn(context.Background()).Msg("hello world")
	})
	// Output: {"level":"warn","time":"2008-01-08T17:05:05Z","message":"hello world"}
}

// Example of a log at a particular "level" (in this case, "error")
func ExampleError() {
	captureOutput(func() {
		log.Error(context.Background()).Msg("hello world")
	})
	// Output: {"level":"error","time":"2008-01-08T17:05:05Z","message":"hello world"}
}

// Example of a log at a particular "level" (in this case, "fatal")
func ExampleFatal() {
	captureOutput(func() {
		err := errors.New("a repo man spends his life getting into tense situations")
		service := "myservice"

		log.Fatal().
			Err(err).
			Str("service", service).
			Msg("Cannot start")
	})
	// Outputs: {"level":"fatal","time":"2008-01-08T17:05:05Z","error":"a repo man spends his life getting into tense situations","service":"myservice","message":"Cannot start myservice"}
}

// This example uses command-line flags to demonstrate various outputs
// depending on the chosen log level.
func Example() {
	captureOutput(func() {
		debug := flag.Bool("debug", false, "sets log level to debug")

		flag.Parse()

		// Default level for this example is info, unless debug flag is present
		zerolog.SetGlobalLevel(zerolog.InfoLevel)
		if *debug {
			zerolog.SetGlobalLevel(zerolog.DebugLevel)
		}

		log.Debug(context.Background()).Msg("This message appears only when log level set to Debug")
		log.Info(context.Background()).Msg("This message appears when log level set to Debug or Info")

		if e := log.Debug(context.Background()); e.Enabled() {
			// Compute log output only if enabled.
			value := "bar"
			e.Str("foo", value).Msg("some debug message")
		}
	})
	// Output: {"level":"info","time":"2008-01-08T17:05:05Z","message":"This message appears when log level set to Debug or Info"}
}

func ExampleSetLevel() {
	captureOutput(func() {
		log.SetLevel(zerolog.InfoLevel)
		log.Debug(context.Background()).Msg("Debug")
		log.Info(context.Background()).Msg("Debug or Info")
		log.SetLevel(zerolog.WarnLevel)
		log.Debug(context.Background()).Msg("Debug")
		log.Info(context.Background()).Msg("Debug or Info")
		log.Warn(context.Background()).Msg("Debug or Info or Warn")
		log.SetLevel(zerolog.ErrorLevel)
		log.Debug(context.Background()).Msg("Debug")
		log.Info(context.Background()).Msg("Debug or Info")
		log.Warn(context.Background()).Msg("Debug or Info or Warn")
		log.Error(context.Background()).Msg("Debug or Info or Warn or Error")
		log.SetLevel(zerolog.DebugLevel)
		log.Debug(context.Background()).Msg("Debug")
	})
	// Output:
	// {"level":"info","time":"2008-01-08T17:05:05Z","message":"Debug or Info"}
	// {"level":"warn","time":"2008-01-08T17:05:05Z","message":"Debug or Info or Warn"}
	// {"level":"error","time":"2008-01-08T17:05:05Z","message":"Debug or Info or Warn or Error"}
	// {"level":"debug","time":"2008-01-08T17:05:05Z","message":"Debug"}
}

func ExampleContext() {
	captureOutput(func() {
		bg := context.Background()
		ctx1 := log.WithContext(bg, func(c zerolog.Context) zerolog.Context {
			return c.Str("param_one", "one")
		})
		ctx2 := log.WithContext(ctx1, func(c zerolog.Context) zerolog.Context {
			return c.Str("param_two", "two")
		})

		log.Warn(bg).Str("non_context_param", "value").Msg("background")
		log.Warn(ctx1).Str("non_context_param", "value").Msg("first")
		log.Warn(ctx2).Str("non_context_param", "value").Msg("second")

		for i := 0; i < 10; i++ {
			ctx1 = log.WithContext(ctx1, func(c zerolog.Context) zerolog.Context {
				return c.Int("counter", i)
			})
		}
		log.Info(ctx1).Str("non_ctx_param", "value").Msg("after counter")
	})
	// Output:
	// {"level":"warn","non_context_param":"value","time":"2008-01-08T17:05:05Z","message":"background"}
	// {"level":"warn","param_one":"one","non_context_param":"value","time":"2008-01-08T17:05:05Z","message":"first"}
	// {"level":"warn","param_one":"one","param_two":"two","non_context_param":"value","time":"2008-01-08T17:05:05Z","message":"second"}
	// {"level":"info","param_one":"one","counter":0,"counter":1,"counter":2,"counter":3,"counter":4,"counter":5,"counter":6,"counter":7,"counter":8,"counter":9,"non_ctx_param":"value","time":"2008-01-08T17:05:05Z","message":"after counter"}
}