Skip to content

Commit

Permalink
Add structured logging
Browse files Browse the repository at this point in the history
  • Loading branch information
imranismail committed Sep 21, 2022
1 parent 13b2261 commit 7a03301
Show file tree
Hide file tree
Showing 5 changed files with 185 additions and 67 deletions.
85 changes: 85 additions & 0 deletions bfflog/bfflog.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,85 @@
package bfflog

import (
"encoding/json"
"fmt"
"net/http"
"strings"

"github.com/google/martian/v3"
"github.com/google/martian/v3/parse"
"github.com/imranismail/bff/log"
"github.com/rs/zerolog"
)

// Logger is a modifier that logs requests and responses.
type Logger struct{}

type loggerJSON struct {
Scope []parse.ModifierType `json:"scope"`
}

func init() {
parse.Register("log.Logger", loggerFromJSON)
}

// NewLogger returns a logger that logs requests and responses, optionally
// logging the body. Log function defaults to martian.Infof.
func NewLogger() *Logger {
return &Logger{}
}

// ModifyRequest logs the request
func (l *Logger) ModifyRequest(req *http.Request) error {
ctx := martian.NewContext(req)
if ctx.SkippingLogging() {
return nil
}

hdrs := zerolog.Dict()

for key, val := range req.Header {
hdrs.Str(key, strings.Join(val, ", "))
}

log.Logger.Zlog.Info().Str("path", req.URL.Path).Str("method", req.Method).Str("scheme", req.URL.Scheme).Str("host", req.Host).Dict("headers", hdrs).Msg(fmt.Sprintf("Request to %s", req.URL))

return nil
}

// ModifyResponse logs the response
func (l *Logger) ModifyResponse(res *http.Response) error {
ctx := martian.NewContext(res.Request)
if ctx.SkippingLogging() {
return nil
}

hdrs := zerolog.Dict()

for key, val := range res.Header {
hdrs.Str(key, strings.Join(val, ", "))
}

log.Logger.Zlog.Info().Str("path", res.Request.URL.Path).Str("method", res.Request.Method).Str("scheme", res.Request.URL.Scheme).Str("host", res.Request.Host).Dict("headers", hdrs).Msg(fmt.Sprintf("Response from %s", res.Request.URL))

return nil
}

// loggerFromJSON builds a logger from JSON.
//
// Example JSON:
// {
// "log.Logger": {
// "scope": ["request", "response"]
// }
// }
func loggerFromJSON(b []byte) (*parse.Result, error) {
msg := &loggerJSON{}
if err := json.Unmarshal(b, msg); err != nil {
return nil, err
}

l := NewLogger()

return parse.NewResult(l, msg.Scope)
}
23 changes: 17 additions & 6 deletions cmd/root.go
Original file line number Diff line number Diff line change
Expand Up @@ -6,17 +6,16 @@ import (
"path"
"strings"

"github.com/fsnotify/fsnotify"
"github.com/imranismail/bff/config"
"github.com/imranismail/bff/log"
"github.com/imranismail/bff/proxy"
"github.com/spf13/cobra"

"github.com/rs/zerolog"

"github.com/adrg/xdg"
"github.com/spf13/viper"
)

var log = zerolog.New(zerolog.NewConsoleWriter()).With().Timestamp().Logger()
var cfgFile string
var cfgPath = path.Join(xdg.ConfigHome, "bff")

Expand All @@ -35,7 +34,7 @@ and modifing HTTP request and response.`,
// This is called by main.main(). It only needs to happen once to the rootCmd.
func Execute() {
if err := rootCmd.Execute(); err != nil {
log.Error().Msgf("Root: %v", err)
log.Errorf("Root: %v", err)
os.Exit(1)
}
}
Expand All @@ -59,6 +58,9 @@ func init() {
rootCmd.Flags().IntP("verbosity", "v", 2, "Verbosity")
viper.BindPFlag("verbosity", rootCmd.Flags().Lookup("verbosity"))

rootCmd.Flags().BoolP("pretty", "r", false, "Pretty logs")
viper.BindPFlag("pretty", rootCmd.Flags().Lookup("pretty"))

rootCmd.Flags().StringP("url", "u", "", "Proxied URL")
viper.BindPFlag("url", rootCmd.Flags().Lookup("url"))

Expand Down Expand Up @@ -90,9 +92,18 @@ func initConfig() {

// If a config file is found, read it in
if err == nil {
log.Info().Msgf("Using config file: %v", viper.ConfigFileUsed())
viper.WatchConfig()
log.Infof("Using config file: %v", viper.ConfigFileUsed())
}

log.Configure()

viper.OnConfigChange(func(evt fsnotify.Event) {
log.Infof("Reconfiguring: %v", evt.Name)
log.Configure()
proxy.Configure()
})

viper.WatchConfig()
}

func hasPipedInput() bool {
Expand Down
67 changes: 67 additions & 0 deletions log/log.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,67 @@
package log

import (
"io"
"os"

mlog "github.com/google/martian/v3/log"
"github.com/rs/zerolog"
"github.com/spf13/viper"
)

var Logger = NewLogger()

func NewLogger() logger {
return logger{Zlog: zerolog.New(os.Stderr).With().Timestamp().Logger()}
}

type logger struct {
Zlog zerolog.Logger
}

func (l *logger) Infof(format string, args ...interface{}) {
l.Zlog.Info().Msgf(format, args...)
}

func (l *logger) Debugf(format string, args ...interface{}) {
l.Zlog.Debug().Msgf(format, args...)
}

func (l *logger) Errorf(format string, args ...interface{}) {
l.Zlog.Error().Msgf(format, args...)
}

func (l *logger) Configure() {
level, err := zerolog.ParseLevel(viper.GetString("verbosity"))

if err != nil {
l.Zlog.Fatal().Msgf("Failed to parse verbosity: %v", err)
}

var output io.Writer

if viper.GetBool("pretty") {
output = zerolog.NewConsoleWriter()
} else {
output = os.Stderr
}

l.Zlog = l.Zlog.Level(level).Output(output)
mlog.SetLogger(l)
}

func Infof(format string, args ...interface{}) {
Logger.Infof(format, args...)
}

func Debugf(format string, args ...interface{}) {
Logger.Debugf(format, args...)
}

func Errorf(format string, args ...interface{}) {
Logger.Errorf(format, args...)
}

func Configure() {
Logger.Configure()
}
39 changes: 0 additions & 39 deletions logger/log.go

This file was deleted.

38 changes: 16 additions & 22 deletions proxy/proxy.go
Original file line number Diff line number Diff line change
Expand Up @@ -11,12 +11,10 @@ import (
"os/signal"
"time"

"github.com/fsnotify/fsnotify"
"github.com/google/martian/v3"
"github.com/google/martian/v3/httpspec"
"github.com/google/martian/v3/log"
"github.com/google/martian/v3/martianlog"
"github.com/google/martian/v3/parse"
"github.com/imranismail/bff/bfflog"
"github.com/imranismail/bff/healthcheck"
"github.com/spf13/cobra"
"github.com/spf13/viper"
Expand Down Expand Up @@ -44,17 +42,18 @@ import (
_ "github.com/imranismail/bff/bffurl"
_ "github.com/imranismail/bff/body"
"github.com/imranismail/bff/config"
"github.com/imranismail/bff/logger"
"github.com/imranismail/bff/log"
)

var Proxy *martian.Proxy

// Serve start the webserver
func Serve(cmd *cobra.Command, args []string) {
logger := logger.NewLogger()
log.SetLogger(&logger)

proxy := martian.NewProxy()
defer proxy.Close()

Proxy = proxy

if url, err := url.Parse(viper.GetString("url")); err != nil {
proxy.SetDownstreamProxy(url)
}
Expand All @@ -73,13 +72,6 @@ func Serve(cmd *cobra.Command, args []string) {

configureProxy(proxy)

viper.OnConfigChange(func(evt fsnotify.Event) {
log.Infof("proxy.Serve: Reconfiguring: %v", evt.Name)
configureProxy(proxy)
log.Infof("logger: Reconfiguring: %v", evt.Name)
logger.Configure()
})

listener, err := net.Listen("tcp", fmt.Sprintf(":%s", viper.GetString("port")))

if err != nil {
Expand All @@ -99,12 +91,16 @@ func Serve(cmd *cobra.Command, args []string) {
log.Infof("bff: shutting down")
}

func configureProxy(proxy *martian.Proxy) {
func Configure() {
configureProxy(Proxy)
}

func configureProxy(*martian.Proxy) {
outer, inner := httpspec.NewStack("bff")

main := NewErrorBoundary()
proxy.SetRequestModifier(main)
proxy.SetResponseModifier(main)
Proxy.SetRequestModifier(main)
Proxy.SetResponseModifier(main)

main.SetRequestModifier(outer)
main.SetResponseModifier(outer)
Expand Down Expand Up @@ -145,9 +141,7 @@ func configureProxy(proxy *martian.Proxy) {
}
}

lm := martianlog.NewLogger()
lm.SetDecode(false)
lm.SetHeadersOnly(true)
outer.AddRequestModifier(lm)
outer.AddResponseModifier(lm)
ml := bfflog.NewLogger()
outer.AddRequestModifier(ml)
outer.AddResponseModifier(ml)
}

0 comments on commit 7a03301

Please sign in to comment.