diff --git a/handlers/backend_handler.go b/handlers/backend_handler.go index 0d4bb184..b8f2d010 100644 --- a/handlers/backend_handler.go +++ b/handlers/backend_handler.go @@ -14,8 +14,7 @@ import ( "time" "github.com/prometheus/client_golang/prometheus" - - "github.com/alphagov/router/logger" + "github.com/rs/zerolog" ) var TLSSkipVerify bool @@ -24,7 +23,7 @@ func NewBackendHandler( backendID string, backendURL *url.URL, connectTimeout, headerTimeout time.Duration, - logger logger.Logger, + logger zerolog.Logger, ) http.Handler { proxy := httputil.NewSingleHostReverseProxy(backendURL) @@ -67,7 +66,7 @@ type backendTransport struct { backendID string wrapped *http.Transport - logger logger.Logger + logger zerolog.Logger } // Construct a backendTransport that wraps an http.Transport and implements http.RoundTripper. @@ -76,7 +75,7 @@ type backendTransport struct { func newBackendTransport( backendID string, connectTimeout, headerTimeout time.Duration, - logger logger.Logger, + logger zerolog.Logger, ) *backendTransport { transport := http.Transport{} @@ -161,11 +160,13 @@ func (bt *backendTransport) RoundTrip(req *http.Request) (resp *http.Response, e responseCode = http.StatusInternalServerError } closeBody(resp) - logger.NotifySentry(logger.ReportableError{Error: err, Request: req, Response: resp}) - bt.logger.LogFromBackendRequest( - map[string]interface{}{"error": err.Error(), "status": responseCode}, - req, - ) + bt.logger.Error(). + Err(err). + Int("status", responseCode). + Str("method", req.Method). + Str("url", req.URL.String()). + Msg("backend request error") + return newErrorResponse(responseCode), nil } responseCode = resp.StatusCode diff --git a/handlers/backend_handler_test.go b/handlers/backend_handler_test.go index 1fc5f45b..40f8b11d 100644 --- a/handlers/backend_handler_test.go +++ b/handlers/backend_handler_test.go @@ -5,23 +5,23 @@ import ( "net/http" "net/http/httptest" "net/url" + "os" "time" . "github.com/onsi/ginkgo/v2" . "github.com/onsi/gomega" "github.com/onsi/gomega/ghttp" + "github.com/rs/zerolog" "github.com/prometheus/client_golang/prometheus" promtest "github.com/prometheus/client_golang/prometheus/testutil" prommodel "github.com/prometheus/client_model/go" - - log "github.com/alphagov/router/logger" ) var _ = Describe("Backend handler", func() { var ( timeout = 1 * time.Second - logger log.Logger + logger zerolog.Logger backend *ghttp.Server backendURL *url.URL @@ -33,8 +33,7 @@ var _ = Describe("Backend handler", func() { BeforeEach(func() { var err error - logger, err = log.New(GinkgoWriter) - Expect(err).NotTo(HaveOccurred(), "Could not create logger") + logger = zerolog.New(os.Stdout) backend = ghttp.NewServer() diff --git a/handlers/redirect_handler.go b/handlers/redirect_handler.go index 6d5795bd..70d7ad1d 100644 --- a/handlers/redirect_handler.go +++ b/handlers/redirect_handler.go @@ -9,7 +9,7 @@ import ( "github.com/prometheus/client_golang/prometheus" - "github.com/alphagov/router/logger" + "github.com/rs/zerolog" ) const ( @@ -20,12 +20,12 @@ const ( downcaseRedirectHandlerType = "downcase-redirect-handler" ) -func NewRedirectHandler(source, target string, preserve bool) http.Handler { +func NewRedirectHandler(source, target string, preserve bool, logger zerolog.Logger) http.Handler { status := http.StatusMovedPermanently if preserve { - return &pathPreservingRedirectHandler{source, target, status} + return &pathPreservingRedirectHandler{source, target, status, logger} } - return &redirectHandler{target, status} + return &redirectHandler{target, status, logger} } func addCacheHeaders(w http.ResponseWriter) { @@ -33,30 +33,34 @@ func addCacheHeaders(w http.ResponseWriter) { w.Header().Set("Cache-Control", fmt.Sprintf("max-age=%d, public", cacheDuration/time.Second)) } -func addGAQueryParam(target string, r *http.Request) string { +func addGAQueryParam(target string, r *http.Request) (string, error) { if ga := r.URL.Query().Get("_ga"); ga != "" { u, err := url.Parse(target) if err != nil { - defer logger.NotifySentry(logger.ReportableError{Error: err, Request: r}) - return target + return target, err } values := u.Query() values.Set("_ga", ga) u.RawQuery = values.Encode() - return u.String() + return u.String(), nil } - return target + return target, nil } type redirectHandler struct { - url string - code int + url string + code int + logger zerolog.Logger } func (handler *redirectHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { addCacheHeaders(w) - target := addGAQueryParam(handler.url, r) + target, err := addGAQueryParam(handler.url, r) + if err != nil { + handler.logger.Error().Err(err).Msg("failed to add GA query param") + } + http.Redirect(w, r, target, handler.code) redirectCountMetric.With(prometheus.Labels{ @@ -68,6 +72,7 @@ type pathPreservingRedirectHandler struct { sourcePrefix string targetPrefix string code int + logger zerolog.Logger } func (handler *pathPreservingRedirectHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { diff --git a/handlers/redirect_handler_test.go b/handlers/redirect_handler_test.go index a8828e32..48dadc94 100644 --- a/handlers/redirect_handler_test.go +++ b/handlers/redirect_handler_test.go @@ -4,10 +4,12 @@ import ( "fmt" "net/http" "net/http/httptest" + "os" "time" . "github.com/onsi/ginkgo/v2" . "github.com/onsi/gomega" + "github.com/rs/zerolog" "github.com/prometheus/client_golang/prometheus" promtest "github.com/prometheus/client_golang/prometheus/testutil" @@ -17,16 +19,18 @@ var _ = Describe("A redirect handler", func() { var handler http.Handler var rr *httptest.ResponseRecorder const url = "https://source.example.com/source/path/subpath?q1=a&q2=b" + var logger zerolog.Logger BeforeEach(func() { rr = httptest.NewRecorder() + logger = zerolog.New(os.Stdout) }) // These behaviours apply to all combinations of both NewRedirectHandler flags. for _, preserve := range []bool{true, false} { Context(fmt.Sprintf("where preserve=%t", preserve), func() { BeforeEach(func() { - handler = NewRedirectHandler("/source", "/target", preserve) + handler = NewRedirectHandler("/source", "/target", preserve, logger) handler.ServeHTTP(rr, httptest.NewRequest(http.MethodGet, url, nil)) }) @@ -49,7 +53,7 @@ var _ = Describe("A redirect handler", func() { Context("where preserve=true", func() { BeforeEach(func() { - handler = NewRedirectHandler("/source", "/target", true) + handler = NewRedirectHandler("/source", "/target", true, logger) handler.ServeHTTP(rr, httptest.NewRequest(http.MethodGet, url, nil)) }) @@ -60,7 +64,7 @@ var _ = Describe("A redirect handler", func() { Context("where preserve=false", func() { BeforeEach(func() { - handler = NewRedirectHandler("/source", "/target", false) + handler = NewRedirectHandler("/source", "/target", false, logger) }) It("returns only the configured path in the location header", func() { @@ -80,7 +84,7 @@ var _ = Describe("A redirect handler", func() { Entry(nil, false, http.StatusMovedPermanently), Entry(nil, true, http.StatusMovedPermanently), func(preserve bool, expectedStatus int) { - handler = NewRedirectHandler("/source", "/target", preserve) + handler = NewRedirectHandler("/source", "/target", preserve, logger) handler.ServeHTTP(rr, httptest.NewRequest(http.MethodGet, url, nil)) Expect(rr.Result().StatusCode).To(Equal(expectedStatus)) }) @@ -95,7 +99,7 @@ var _ = Describe("A redirect handler", func() { lbls := prometheus.Labels{"redirect_type": typeLabel} before := promtest.ToFloat64(redirectCountMetric.With(lbls)) - handler = NewRedirectHandler("/source", "/target", preserve) + handler = NewRedirectHandler("/source", "/target", preserve, logger) handler.ServeHTTP(rr, httptest.NewRequest(http.MethodGet, url, nil)) after := promtest.ToFloat64(redirectCountMetric.With(lbls)) diff --git a/lib/backends.go b/lib/backends.go index 85c04c43..e6dbfc65 100644 --- a/lib/backends.go +++ b/lib/backends.go @@ -1,7 +1,6 @@ package router import ( - "fmt" "net/http" "net/url" "os" @@ -9,10 +8,10 @@ import ( "time" "github.com/alphagov/router/handlers" - "github.com/alphagov/router/logger" + "github.com/rs/zerolog" ) -func loadBackendsFromEnv(connTimeout, headerTimeout time.Duration, logger logger.Logger) (backends map[string]http.Handler) { +func loadBackendsFromEnv(connTimeout, headerTimeout time.Duration, logger zerolog.Logger) (backends map[string]http.Handler) { backends = make(map[string]http.Handler) for _, envvar := range os.Environ() { @@ -26,13 +25,13 @@ func loadBackendsFromEnv(connTimeout, headerTimeout time.Duration, logger logger backendURL := pair[1] if backendURL == "" { - logWarn(fmt.Errorf("router: couldn't find URL for backend %s, skipping", backendID)) + logger.Warn().Msgf("no URL for backend %s provided, skipping", backendID) continue } backend, err := url.Parse(backendURL) if err != nil { - logWarn(fmt.Errorf("router: couldn't parse URL %s for backend %s (error: %w), skipping", backendURL, backendID, err)) + logger.Warn().Err(err).Msgf("failed to parse URL %s for backend %s, skipping", backendURL, backendID) continue } diff --git a/lib/backends_test.go b/lib/backends_test.go index 5d1f5748..847172c6 100644 --- a/lib/backends_test.go +++ b/lib/backends_test.go @@ -6,15 +6,20 @@ import ( . "github.com/onsi/ginkgo/v2" . "github.com/onsi/gomega" + "github.com/rs/zerolog" ) var _ = Describe("Backends", func() { + var ( + logger = zerolog.New(os.Stdout) + ) + Context("When calling loadBackendsFromEnv", func() { It("should load backends from environment variables", func() { os.Setenv("BACKEND_URL_testBackend", "http://example.com") defer os.Unsetenv("BACKEND_URL_testBackend") - backends := loadBackendsFromEnv(1*time.Second, 20*time.Second, nil) + backends := loadBackendsFromEnv(1*time.Second, 20*time.Second, logger) Expect(backends).To(HaveKey("testBackend")) Expect(backends["testBackend"]).ToNot(BeNil()) @@ -24,7 +29,7 @@ var _ = Describe("Backends", func() { os.Setenv("BACKEND_URL_emptyBackend", "") defer os.Unsetenv("BACKEND_URL_emptyBackend") - backends := loadBackendsFromEnv(1*time.Second, 20*time.Second, nil) + backends := loadBackendsFromEnv(1*time.Second, 20*time.Second, logger) Expect(backends).ToNot(HaveKey("emptyBackend")) }) @@ -33,7 +38,7 @@ var _ = Describe("Backends", func() { os.Setenv("BACKEND_URL_invalidBackend", "://invalid-url") defer os.Unsetenv("BACKEND_URL_invalidBackend") - backends := loadBackendsFromEnv(1*time.Second, 20*time.Second, nil) + backends := loadBackendsFromEnv(1*time.Second, 20*time.Second, logger) Expect(backends).ToNot(HaveKey("invalidBackend")) }) diff --git a/lib/load_routes.go b/lib/load_routes.go index 590177fc..d80ec8f3 100644 --- a/lib/load_routes.go +++ b/lib/load_routes.go @@ -11,12 +11,11 @@ import ( "github.com/jackc/pgx/v5" "github.com/jackc/pgx/v5/pgconn" - "github.com/jackc/pgxlisten" "github.com/prometheus/client_golang/prometheus" + "github.com/rs/zerolog" "github.com/alphagov/router/handlers" - "github.com/alphagov/router/logger" "github.com/alphagov/router/triemux" ) @@ -27,19 +26,17 @@ type PgxIface interface { Query(context.Context, string, ...interface{}) (pgx.Rows, error) } -func addHandler(mux *triemux.Mux, route *Route, backends map[string]http.Handler) error { +func addHandler(mux *triemux.Mux, route *Route, backends map[string]http.Handler, logger zerolog.Logger) error { if route.IncomingPath == nil || route.RouteType == nil { - logWarn(fmt.Sprintf("router: found route %+v with nil fields, skipping!", route)) + logger.Warn().Interface("route", route).Msg("ignoring route with nil fields") return nil } prefix := (*route.RouteType == RouteTypePrefix) - // the database contains paths with % encoded routes. - // Unescape them here because the http.Request objects we match against contain the unescaped variants. incomingURL, err := url.Parse(*route.IncomingPath) if err != nil { - logWarn(fmt.Sprintf("router: found route %+v with invalid incoming path '%s', skipping!", route, *route.IncomingPath)) + logger.Warn().Interface("route", route).Str("incoming_path", *route.IncomingPath).Msg("ignoring route with invalid incoming path") return nil //nolint:nilerr } @@ -47,42 +44,38 @@ func addHandler(mux *triemux.Mux, route *Route, backends map[string]http.Handler case HandlerTypeBackend: backend := route.backend() if backend == nil { - logWarn(fmt.Sprintf("router: found route %+v with nil backend_id, skipping!", *route.IncomingPath)) + logger.Warn().Str("incoming_path", *route.IncomingPath).Msg("ignoring route with nil backend_id") return nil } handler, ok := backends[*backend] if !ok { - logWarn(fmt.Sprintf("router: found route %+v with unknown backend "+ - "%s, skipping!", *route.IncomingPath, *route.BackendID)) + logger.Warn().Str("incoming_path", *route.IncomingPath).Str("backend_id", *route.BackendID).Msg("ignoring route with unknown backend") return nil } mux.Handle(incomingURL.Path, prefix, handler) case HandlerTypeRedirect: if route.RedirectTo == nil { - logWarn(fmt.Sprintf("router: found route %+v with nil redirect_to, skipping!", *route.IncomingPath)) + logger.Warn().Str("incoming_path", *route.IncomingPath).Msg("ignoring route with nil redirect_to") return nil } - handler := handlers.NewRedirectHandler(incomingURL.Path, *route.RedirectTo, shouldPreserveSegments(*route.RouteType, route.segmentsMode())) + handler := handlers.NewRedirectHandler(incomingURL.Path, *route.RedirectTo, shouldPreserveSegments(*route.RouteType, route.segmentsMode()), logger) mux.Handle(incomingURL.Path, prefix, handler) case HandlerTypeGone: mux.Handle(incomingURL.Path, prefix, http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { http.Error(w, "410 Gone", http.StatusGone) })) default: - logWarn(fmt.Sprintf("router: found route %+v with unknown handler type "+ - "%s, skipping!", route, route.handlerType())) + logger.Warn().Interface("route", route).Str("handler_type", route.handlerType()).Msg("ignoring route with unknown handler type") return nil } return nil } -func loadRoutes(pool PgxIface, mux *triemux.Mux, backends map[string]http.Handler) error { +func loadRoutes(pool PgxIface, mux *triemux.Mux, backends map[string]http.Handler, logger zerolog.Logger) error { rows, err := pool.Query(context.Background(), loadRoutesQuery) - if err != nil { return err } - defer rows.Close() for rows.Next() { @@ -102,7 +95,7 @@ func loadRoutes(pool PgxIface, mux *triemux.Mux, backends map[string]http.Handle return err } - err = addHandler(mux, route, backends) + err = addHandler(mux, route, backends, logger) if err != nil { return err } @@ -178,23 +171,20 @@ func (rt *Router) reloadRoutes(pool PgxIface) { success = true if r := recover(); r != nil { success = false - logWarn("router: recovered from panic in reloadRoutes:", r) - logInfo("router: original content store routes have not been modified") - errorMessage := fmt.Sprintf("panic: %v", r) - err := logger.RecoveredError{ErrorMessage: errorMessage} - logger.NotifySentry(logger.ReportableError{Error: err}) + rt.Logger.Err(fmt.Errorf("%v", r)).Msgf("recovered from panic in reloadRoutes") + rt.Logger.Info().Msg("reload failed and existing routes have not been modified") } timer.ObserveDuration() }() rt.lastAttemptReloadTime = time.Now() - logInfo("router: reloading routes from content store") - newmux := triemux.NewMux() + rt.Logger.Info().Msg("reloading routes from content store") + newmux := triemux.NewMux(rt.Logger) - err := loadRoutes(pool, newmux, rt.backends) + err := loadRoutes(pool, newmux, rt.backends, rt.Logger) if err != nil { - logWarn(fmt.Sprintf("router: error reloading routes from content store: %v", err)) + rt.Logger.Warn().Err(err).Msg("error reloading routes") return } @@ -204,6 +194,6 @@ func (rt *Router) reloadRoutes(pool PgxIface) { rt.mux = newmux rt.lock.Unlock() - logInfo(fmt.Sprintf("router: reloaded %d routes from content store", routeCount)) + rt.Logger.Info().Int("route_count", routeCount).Msg("reloaded routes") routesCountMetric.WithLabelValues("content-store").Set(float64(routeCount)) } diff --git a/lib/load_routes_test.go b/lib/load_routes_test.go index d414d4cd..28c1a197 100644 --- a/lib/load_routes_test.go +++ b/lib/load_routes_test.go @@ -4,12 +4,14 @@ import ( "fmt" "net/http" "net/http/httptest" + "os" "sync" "github.com/alphagov/router/triemux" . "github.com/onsi/ginkgo/v2" . "github.com/onsi/gomega" "github.com/pashagolub/pgxmock/v4" + "github.com/rs/zerolog" ) var _ = Describe("loadRoutes", func() { @@ -17,6 +19,7 @@ var _ = Describe("loadRoutes", func() { mockPool pgxmock.PgxPoolIface mux *triemux.Mux backends map[string]http.Handler + logger zerolog.Logger ) BeforeEach(func() { @@ -24,7 +27,9 @@ var _ = Describe("loadRoutes", func() { mockPool, err = pgxmock.NewPool() Expect(err).NotTo(HaveOccurred()) - mux = triemux.NewMux() + logger := zerolog.New(os.Stdout) + + mux = triemux.NewMux(logger) backends = map[string]http.Handler{ "backend1": http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusOK) @@ -53,7 +58,7 @@ var _ = Describe("loadRoutes", func() { mockPool.ExpectQuery("WITH").WillReturnRows(rows) - err := loadRoutes(mockPool, mux, backends) + err := loadRoutes(mockPool, mux, backends, logger) Expect(err).NotTo(HaveOccurred()) }) @@ -88,7 +93,7 @@ var _ = Describe("loadRoutes", func() { mockPool.ExpectQuery("WITH").WillReturnRows(rows) - err := loadRoutes(mockPool, mux, backends) + err := loadRoutes(mockPool, mux, backends, logger) Expect(err).NotTo(HaveOccurred()) }) @@ -146,7 +151,7 @@ var _ = Describe("loadRoutes", func() { AddRow(nil, stringPtr("/redirect-prefix-preserve"), stringPtr("prefix"), stringPtr("/redirected-prefix-preserve"), stringPtr("preserve"), stringPtr("redirect"), nil) mockPool.ExpectQuery("WITH").WillReturnRows(rows) - err := loadRoutes(mockPool, mux, backends) + err := loadRoutes(mockPool, mux, backends, logger) Expect(err).NotTo(HaveOccurred()) }) diff --git a/lib/logcompat.go b/lib/logcompat.go deleted file mode 100644 index 3d85228d..00000000 --- a/lib/logcompat.go +++ /dev/null @@ -1,15 +0,0 @@ -package router - -// TODO: remove this file and use rs/zerolog throughout. - -import "log" - -var EnableDebugOutput bool - -func logWarn(msg ...interface{}) { - log.Println(msg...) -} - -func logInfo(msg ...interface{}) { - log.Println(msg...) -} diff --git a/lib/router.go b/lib/router.go index 453c4682..c90dc5fe 100644 --- a/lib/router.go +++ b/lib/router.go @@ -10,8 +10,8 @@ import ( "github.com/jackc/pgx/v5/pgxpool" "github.com/prometheus/client_golang/prometheus" + "github.com/rs/zerolog" - "github.com/alphagov/router/logger" "github.com/alphagov/router/triemux" ) @@ -31,17 +31,17 @@ type Router struct { backends map[string]http.Handler mux *triemux.Mux lock sync.RWMutex - logger logger.Logger opts Options ReloadChan chan bool pool *pgxpool.Pool lastAttemptReloadTime time.Time + Logger zerolog.Logger } type Options struct { BackendConnTimeout time.Duration BackendHeaderTimeout time.Duration - LogFileName string + Logger zerolog.Logger RouteReloadInterval time.Duration } @@ -53,13 +53,7 @@ func RegisterMetrics(r prometheus.Registerer) { } func NewRouter(o Options) (rt *Router, err error) { - l, err := logger.New(o.LogFileName) - if err != nil { - return nil, err - } - logInfo("router: logging errors as JSON to", o.LogFileName) - - backends := loadBackendsFromEnv(o.BackendConnTimeout, o.BackendHeaderTimeout, l) + backends := loadBackendsFromEnv(o.BackendConnTimeout, o.BackendHeaderTimeout, o.Logger) var pool *pgxpool.Pool @@ -67,13 +61,13 @@ func NewRouter(o Options) (rt *Router, err error) { if err != nil { return nil, err } - logInfo("router: postgres connection pool created") + o.Logger.Info().Msg("postgres connection pool created") reloadChan := make(chan bool, 1) rt = &Router{ backends: backends, - mux: triemux.NewMux(), - logger: l, + mux: triemux.NewMux(o.Logger), + Logger: o.Logger, opts: o, ReloadChan: reloadChan, pool: pool, @@ -83,7 +77,7 @@ func NewRouter(o Options) (rt *Router, err error) { go func() { if err := rt.listenForContentStoreUpdates(context.Background()); err != nil { - logWarn(fmt.Sprintf("router: error in listenForContentStoreUpdates: %v", err)) + rt.Logger.Error().Err(err).Msg("failed to listen for content store updates") } }() @@ -97,16 +91,7 @@ func NewRouter(o Options) (rt *Router, err error) { func (rt *Router) ServeHTTP(w http.ResponseWriter, req *http.Request) { defer func() { if r := recover(); r != nil { - logWarn("router: recovered from panic in ServeHTTP:", r) - - errorMessage := fmt.Sprintf("panic: %v", r) - err := logger.RecoveredError{ErrorMessage: errorMessage} - - logger.NotifySentry(logger.ReportableError{Error: err, Request: req}) - rt.logger.LogFromClientRequest(map[string]interface{}{ - "error": errorMessage, - "status": http.StatusInternalServerError, - }, req) + rt.Logger.Err(fmt.Errorf("%v", r)).Msgf("recovered from panic in ServeHTTP") w.WriteHeader(http.StatusInternalServerError) diff --git a/lib/router_api.go b/lib/router_api.go index ab0a4fbe..fda2876c 100644 --- a/lib/router_api.go +++ b/lib/router_api.go @@ -17,19 +17,15 @@ func NewAPIHandler(rout *Router) (api http.Handler, err error) { w.WriteHeader(http.StatusMethodNotAllowed) return } - // Send a message to the Router goroutine which will check the latest - // oplog optime and start a reload if necessary. - // If the channel is already full, no message will be sent and the request - // won't be blocked. select { case rout.ReloadChan <- true: default: } - logInfo("router: reload queued") + rout.Logger.Info().Msg("reload queued") w.WriteHeader(http.StatusAccepted) _, err := w.Write([]byte("Reload queued")) if err != nil { - logWarn(err) + rout.Logger.Warn().Err(err).Msg("failed to write response") } }) @@ -42,7 +38,7 @@ func NewAPIHandler(rout *Router) (api http.Handler, err error) { _, err := w.Write([]byte("OK")) if err != nil { - logWarn(err) + rout.Logger.Warn().Err(err).Msg("failed to write response") } }) @@ -58,12 +54,13 @@ func NewAPIHandler(rout *Router) (api http.Handler, err error) { jsonData, err := json.MarshalIndent(memStats, "", " ") if err != nil { http.Error(w, err.Error(), http.StatusInternalServerError) + rout.Logger.Error().Err(err).Msg("failed to marshal memory stats") return } _, err = w.Write(jsonData) if err != nil { - logWarn(err) + rout.Logger.Warn().Err(err).Msg("failed to write response") http.Error(w, err.Error(), http.StatusInternalServerError) } }) diff --git a/logger/logger.go b/logger/logger.go deleted file mode 100644 index 752bae9b..00000000 --- a/logger/logger.go +++ /dev/null @@ -1,103 +0,0 @@ -package logger - -import ( - "encoding/json" - "fmt" - "io" - "log" - "net/http" - "os" - "time" -) - -type Logger interface { - Log(fields map[string]interface{}) - LogFromClientRequest(fields map[string]interface{}, req *http.Request) - LogFromBackendRequest(fields map[string]interface{}, req *http.Request) -} - -type logEntry struct { - Timestamp time.Time `json:"@timestamp"` - Fields map[string]interface{} `json:"@fields"` -} - -type jsonLogger struct { - writer io.Writer - lines chan *[]byte -} - -// New creates a new Logger. The output variable sets the -// destination to which log data will be written. This can be -// either an io.Writer, or a string. With the latter, this is either -// one of "STDOUT" or "STDERR", or the path to the file to log to. -func New(output interface{}) (logger Logger, err error) { - l := &jsonLogger{} - l.writer, err = openWriter(output) - if err != nil { - return nil, err - } - l.lines = make(chan *[]byte, 100) - go l.writeLoop() - return l, nil -} - -func openWriter(output interface{}) (w io.Writer, err error) { - switch out := output.(type) { - case io.Writer: - w = out - case string: - switch out { - case "STDERR": - w = os.Stderr - case "STDOUT": - w = os.Stdout - default: - w, err = os.OpenFile(out, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0600) - if err != nil { - return nil, err - } - } - default: - return nil, fmt.Errorf("invalid output type %T(%v)", output, output) - } - return -} - -func (l *jsonLogger) writeLoop() { - for { - line := <-l.lines - _, err := l.writer.Write(*line) - if err != nil { - log.Printf("router: Error writing to error log: %v", err) - } - } -} - -func (l *jsonLogger) writeLine(line []byte) { - line = append(line, 10) // Append a newline - l.lines <- &line -} - -func (l *jsonLogger) Log(fields map[string]interface{}) { - entry := &logEntry{time.Now(), fields} - line, err := json.Marshal(entry) - if err != nil { - log.Printf("router/logger: Error encoding JSON: %v", err) - } - l.writeLine(line) -} - -func (l *jsonLogger) LogFromClientRequest(fields map[string]interface{}, req *http.Request) { - fields["request_method"] = req.Method - fields["request"] = fmt.Sprintf("%s %s %s", req.Method, req.RequestURI, req.Proto) - - l.Log(fields) -} - -func (l *jsonLogger) LogFromBackendRequest(fields map[string]interface{}, req *http.Request) { - // The request at this point is the request to the backend, not the original client request, - // hence the backend host details are in the req.Host field - fields["upstream_addr"] = req.Host - - l.LogFromClientRequest(fields, req) -} diff --git a/logger/sentry.go b/logger/sentry.go deleted file mode 100644 index b77d20b0..00000000 --- a/logger/sentry.go +++ /dev/null @@ -1,61 +0,0 @@ -package logger - -import ( - "errors" - "log" - "net" - "net/http" - - sentry "github.com/getsentry/sentry-go" -) - -// TODO: use the Sentry API as intended + remove these wonky, reinvented wheels. -// See https://docs.sentry.io/platforms/go/guides/http/. - -type RecoveredError struct { - ErrorMessage string -} - -func (re RecoveredError) Error() string { - return re.ErrorMessage -} - -type ReportableError struct { - Error error - Request *http.Request - Response *http.Response -} - -func InitSentry() { - if err := sentry.Init(sentry.ClientOptions{}); err != nil { - log.Printf("sentry.Init failed: %v\n", err) - } -} - -// Timeout returns true if and only if this ReportableError is a timeout. -func (re ReportableError) Timeout() bool { - var oerr *net.OpError - if errors.As(re.Error, &oerr) { - return oerr.Timeout() - } - return false -} - -// NotifySentry sends an event to sentry.io. Sentry is configurable via the -// environment variables SENTRY_ENVIRONMENT, SENTRY_DSN, SENTRY_RELEASE. -func NotifySentry(re ReportableError) { - if re.Timeout() { - return - } - - hub := sentry.CurrentHub().Clone() - hub.WithScope(func(s *sentry.Scope) { - if re.Request != nil { - s.SetRequest(re.Request) - } - if re.Response != nil { - s.SetExtra("Response Status", re.Response.Status) - } - hub.CaptureException(re.Error) - }) -} diff --git a/main.go b/main.go index 319e5138..4c2fca65 100644 --- a/main.go +++ b/main.go @@ -11,9 +11,11 @@ import ( "github.com/alphagov/router/handlers" router "github.com/alphagov/router/lib" - "github.com/alphagov/router/logger" - sentry "github.com/getsentry/sentry-go" + + "github.com/getsentry/sentry-go" + sentryzerolog "github.com/getsentry/sentry-go/zerolog" "github.com/prometheus/client_golang/prometheus" + "github.com/rs/zerolog" ) func usage() { @@ -83,11 +85,34 @@ func main() { os.Exit(0) } - router.EnableDebugOutput = os.Getenv("ROUTER_DEBUG") != "" + // Initialize Sentry + if err := sentry.Init(sentry.ClientOptions{}); err != nil { + panic(err) + } + + defer sentry.Flush(2 * time.Second) + + // Configure Sentry Zerolog Writer + writer, err := sentryzerolog.New(sentryzerolog.Config{ + ClientOptions: sentry.ClientOptions{}, + Options: sentryzerolog.Options{ + Levels: []zerolog.Level{zerolog.ErrorLevel, zerolog.FatalLevel}, + FlushTimeout: 3 * time.Second, + WithBreadcrumbs: true, + }, + }) + if err != nil { + panic(err) + } + defer writer.Close() + + // Initialize Zerolog + m := zerolog.MultiLevelWriter(os.Stderr, writer) + logger := zerolog.New(m).With().Timestamp().Logger() + var ( pubAddr = getenv("ROUTER_PUBADDR", ":8080") apiAddr = getenv("ROUTER_APIADDR", ":8081") - errorLogFile = getenv("ROUTER_ERROR_LOG", "STDERR") tlsSkipVerify = os.Getenv("ROUTER_TLS_SKIP_VERIFY") != "" beConnTimeout = getenvDuration("ROUTER_BACKEND_CONNECT_TIMEOUT", "1s") beHeaderTimeout = getenvDuration("ROUTER_BACKEND_HEADER_TIMEOUT", "20s") @@ -96,14 +121,13 @@ func main() { routeReloadInterval = getenvDuration("ROUTER_ROUTE_RELOAD_INTERVAL", "1m") ) - log.Printf("using frontend read timeout: %v", feReadTimeout) - log.Printf("using frontend write timeout: %v", feWriteTimeout) - log.Printf("using GOMAXPROCS value of %d", runtime.GOMAXPROCS(0)) + logger.Info().Msgf("frontend read timeout: %v", feReadTimeout) + logger.Info().Msgf("frontend write timeout: %v", feWriteTimeout) + logger.Info().Msgf("GOMAXPROCS value of %d", runtime.GOMAXPROCS(0)) if tlsSkipVerify { handlers.TLSSkipVerify = true - log.Printf("skipping verification of TLS certificates; " + - "Do not use this option in a production environment.") + logger.Warn().Msg("skipping verification of TLS certificates; Do not use this option in a production environment.") } router.RegisterMetrics(prometheus.DefaultRegisterer) @@ -111,25 +135,22 @@ func main() { rout, err := router.NewRouter(router.Options{ BackendConnTimeout: beConnTimeout, BackendHeaderTimeout: beHeaderTimeout, - LogFileName: errorLogFile, RouteReloadInterval: routeReloadInterval, + Logger: logger, }) if err != nil { - log.Fatal(err) + logger.Fatal().Err(err).Msg("failed to create router") } go rout.PeriodicRouteUpdates() go listenAndServeOrFatal(pubAddr, rout, feReadTimeout, feWriteTimeout) - log.Printf("router: listening for requests on %v", pubAddr) + logger.Info().Msgf("listening for requests on %v", pubAddr) api, err := router.NewAPIHandler(rout) if err != nil { - log.Fatal(err) + logger.Fatal().Err(err).Msg("failed to create API handler") } - logger.InitSentry() - defer sentry.Flush(2 * time.Second) - - log.Printf("router: listening for API requests on %v", apiAddr) + logger.Info().Msgf("listening for API requests on %v", apiAddr) listenAndServeOrFatal(apiAddr, api, feReadTimeout, feWriteTimeout) } diff --git a/triemux/mux.go b/triemux/mux.go index b410b51e..719e9121 100644 --- a/triemux/mux.go +++ b/triemux/mux.go @@ -10,8 +10,8 @@ import ( "sync" "github.com/alphagov/router/handlers" - "github.com/alphagov/router/logger" "github.com/alphagov/router/trie" + "github.com/rs/zerolog" ) type Mux struct { @@ -20,14 +20,16 @@ type Mux struct { prefixTrie *trie.Trie[http.Handler] count int downcaser http.Handler + logger zerolog.Logger } // NewMux makes a new empty Mux. -func NewMux() *Mux { +func NewMux(logger zerolog.Logger) *Mux { return &Mux{ exactTrie: trie.NewTrie[http.Handler](), prefixTrie: trie.NewTrie[http.Handler](), downcaser: handlers.NewDowncaseRedirectHandler(), + logger: logger, } } @@ -38,10 +40,7 @@ func NewMux() *Mux { func (mux *Mux) ServeHTTP(w http.ResponseWriter, r *http.Request) { if mux.count == 0 { w.WriteHeader(http.StatusServiceUnavailable) - logger.NotifySentry(logger.ReportableError{ - Error: logger.RecoveredError{ErrorMessage: "route table is empty"}, - Request: r, - }) + mux.logger.Error().Msg("route table is empty") internalServiceUnavailableCountMetric.Inc() return } diff --git a/triemux/mux_test.go b/triemux/mux_test.go index 8da612b9..832d40fa 100644 --- a/triemux/mux_test.go +++ b/triemux/mux_test.go @@ -8,6 +8,7 @@ import ( "testing" promtest "github.com/prometheus/client_golang/prometheus/testutil" + "github.com/rs/zerolog" ) func TestSplitPath(t *testing.T) { @@ -204,7 +205,8 @@ func TestLookup(t *testing.T) { } func testLookup(t *testing.T, ex LookupExample) { - mux := NewMux() + zerologger := zerolog.New(os.Stdout) + mux := NewMux(zerologger) for _, r := range ex.registrations { t.Logf("Register(path:%v, prefix:%v, handler:%v)", r.path, r.prefix, r.handler) mux.Handle(r.path, r.prefix, r.handler) @@ -227,7 +229,8 @@ var statsExample = []Registration{ } func TestRouteCount(t *testing.T) { - mux := NewMux() + zerologger := zerolog.New(os.Stdout) + mux := NewMux(zerologger) for _, reg := range statsExample { mux.Handle(reg.path, reg.prefix, reg.handler) } @@ -247,8 +250,8 @@ func loadStrings(filename string) []string { func benchSetup() *Mux { routes := loadStrings("testdata/routes") - - tm := NewMux() + zerologger := zerolog.New(os.Stdout) + tm := NewMux(zerologger) tm.Handle("/government", true, a) for _, l := range routes {