From 5ca7ede9e41bce3bc7c1d3122c8c8d8fc728899e Mon Sep 17 00:00:00 2001 From: Anbraten Date: Sat, 3 Sep 2022 20:41:23 +0200 Subject: [PATCH] Improve logging (#1158) * switch default log level to info add start message and cleanup server start * refactor code * fix agent debug / trace logging --- cmd/agent/agent.go | 28 +-- cmd/server/server.go | 160 +++++++++--------- cmd/server/setup.go | 2 +- server/router/middleware/logger.go | 6 +- server/router/middleware/token/token.go | 2 +- server/store/datastore/migration/migration.go | 2 +- 6 files changed, 104 insertions(+), 96 deletions(-) diff --git a/cmd/agent/agent.go b/cmd/agent/agent.go index 78eba3ed5..12bb576af 100644 --- a/cmd/agent/agent.go +++ b/cmd/agent/agent.go @@ -37,6 +37,7 @@ import ( "github.com/woodpecker-ci/woodpecker/pipeline/backend" "github.com/woodpecker-ci/woodpecker/pipeline/rpc" "github.com/woodpecker-ci/woodpecker/shared/utils" + "github.com/woodpecker-ci/woodpecker/version" ) func loop(c *cli.Context) error { @@ -69,11 +70,7 @@ func loop(c *cli.Context) error { ) } - zerolog.SetGlobalLevel(zerolog.WarnLevel) - if zerolog.GlobalLevel() <= zerolog.DebugLevel { - log.Logger = log.With().Caller().Logger() - } - + zerolog.SetGlobalLevel(zerolog.InfoLevel) if c.IsSet("log-level") { logLevelFlag := c.String("log-level") lvl, err := zerolog.ParseLevel(logLevelFlag) @@ -82,6 +79,9 @@ func loop(c *cli.Context) error { } zerolog.SetGlobalLevel(lvl) } + if zerolog.GlobalLevel() <= zerolog.DebugLevel { + log.Logger = log.With().Caller().Logger() + } counter.Polling = c.Int("max-procs") counter.Running = 0 @@ -138,17 +138,17 @@ func loop(c *cli.Context) error { parallel := c.Int("max-procs") wg.Add(parallel) + // new engine + engine, err := backend.FindEngine(c.String("backend-engine")) + if err != nil { + log.Error().Err(err).Msgf("cannot find backend engine '%s'", c.String("backend-engine")) + return err + } + for i := 0; i < parallel; i++ { go func() { defer wg.Done() - // new engine - engine, err := backend.FindEngine(c.String("backend-engine")) - if err != nil { - log.Error().Err(err).Msgf("cannot find backend engine '%s'", c.String("backend-engine")) - return - } - // load engine (e.g. init api client) err = engine.Load() if err != nil { @@ -174,6 +174,10 @@ func loop(c *cli.Context) error { }() } + log.Info().Msgf( + "Starting Woodpecker agent with version '%s' and backend '%s' running up to %d pipelines in parallel", + version.String(), engine.Name(), parallel) + wg.Wait() return nil } diff --git a/cmd/server/server.go b/cmd/server/server.go index 658c13b9e..f02cab86f 100644 --- a/cmd/server/server.go +++ b/cmd/server/server.go @@ -50,6 +50,7 @@ import ( "github.com/woodpecker-ci/woodpecker/server/router/middleware" "github.com/woodpecker-ci/woodpecker/server/store" "github.com/woodpecker-ci/woodpecker/server/web" + "github.com/woodpecker-ci/woodpecker/version" ) func run(c *cli.Context) error { @@ -63,7 +64,7 @@ func run(c *cli.Context) error { } // TODO: format output & options to switch to json aka. option to add channels to send logs to - zerolog.SetGlobalLevel(zerolog.WarnLevel) + zerolog.SetGlobalLevel(zerolog.InfoLevel) if c.IsSet("log-level") { logLevelFlag := c.String("log-level") lvl, err := zerolog.ParseLevel(logLevelFlag) @@ -118,37 +119,14 @@ func run(c *cli.Context) error { setupEvilGlobals(c, _store, _remote) - proxyWebUI := c.String("www-proxy") - - var webUIServe func(w http.ResponseWriter, r *http.Request) - - if proxyWebUI == "" { - webUIServe = web.New().ServeHTTP - } else { - origin, _ := url.Parse(proxyWebUI) - - director := func(req *http.Request) { - req.Header.Add("X-Forwarded-Host", req.Host) - req.Header.Add("X-Origin-Host", origin.Host) - req.URL.Scheme = origin.Scheme - req.URL.Host = origin.Host - } - - proxy := &httputil.ReverseProxy{Director: director} - webUIServe = proxy.ServeHTTP - } - - // setup the server and start the listener - handler := router.Load( - webUIServe, - middleware.Logger(time.RFC3339, true), - middleware.Version, - middleware.Config(c), - middleware.Store(c, _store), - ) - var g errgroup.Group + setupMetrics(&g, _store) + + g.Go(func() error { + return cron.Start(c.Context, _store, _remote) + }) + // start the grpc server g.Go(func() error { lis, err := net.Listen("tcp", c.String("grpc-addr")) @@ -184,17 +162,36 @@ func run(c *cli.Context) error { return nil }) - setupMetrics(&g, _store) + proxyWebUI := c.String("www-proxy") + var webUIServe func(w http.ResponseWriter, r *http.Request) - g.Go(func() error { - return cron.Start(c.Context, _store, _remote) - }) + if proxyWebUI == "" { + webUIServe = web.New().ServeHTTP + } else { + origin, _ := url.Parse(proxyWebUI) + + director := func(req *http.Request) { + req.Header.Add("X-Forwarded-Host", req.Host) + req.Header.Add("X-Origin-Host", origin.Host) + req.URL.Scheme = origin.Scheme + req.URL.Host = origin.Host + } + + proxy := &httputil.ReverseProxy{Director: director} + webUIServe = proxy.ServeHTTP + } + + // setup the server and start the listener + handler := router.Load( + webUIServe, + middleware.Logger(time.RFC3339, true), + middleware.Version, + middleware.Config(c), + middleware.Store(c, _store), + ) - // start the server with tls enabled if c.String("server-cert") != "" { - g.Go(func() error { - return http.ListenAndServe(":http", http.HandlerFunc(redirect)) - }) + // start the server with tls enabled g.Go(func() error { serve := &http.Server{ Addr: ":https", @@ -208,48 +205,55 @@ func run(c *cli.Context) error { c.String("server-key"), ) }) - return g.Wait() - } - // start the server without tls enabled - if !c.Bool("lets-encrypt") { - return http.ListenAndServe( - c.String("server-addr"), - handler, - ) - } - - // start the server with lets encrypt enabled - // listen on ports 443 and 80 - address, err := url.Parse(c.String("server-host")) - if err != nil { - return err - } - - dir := cacheDir() - if err := os.MkdirAll(dir, 0o700); err != nil { - return err - } - - manager := &autocert.Manager{ - Prompt: autocert.AcceptTOS, - HostPolicy: autocert.HostWhitelist(address.Host), - Cache: autocert.DirCache(dir), - } - g.Go(func() error { - return http.ListenAndServe(":http", manager.HTTPHandler(http.HandlerFunc(redirect))) - }) - g.Go(func() error { - serve := &http.Server{ - Addr: ":https", - Handler: handler, - TLSConfig: &tls.Config{ - GetCertificate: manager.GetCertificate, - NextProtos: []string{"h2", "http/1.1"}, - }, + // http to https redirect + g.Go(func() error { + return http.ListenAndServe(":http", http.HandlerFunc(redirect)) + }) + } else if c.Bool("lets-encrypt") { + // start the server with lets-encrypt + address, err := url.Parse(c.String("server-host")) + if err != nil { + return err } - return serve.ListenAndServeTLS("", "") - }) + + dir := cacheDir() + if err := os.MkdirAll(dir, 0o700); err != nil { + return err + } + + manager := &autocert.Manager{ + Prompt: autocert.AcceptTOS, + HostPolicy: autocert.HostWhitelist(address.Host), + Cache: autocert.DirCache(dir), + } + g.Go(func() error { + serve := &http.Server{ + Addr: ":https", + Handler: handler, + TLSConfig: &tls.Config{ + GetCertificate: manager.GetCertificate, + NextProtos: []string{"h2", "http/1.1"}, + }, + } + return serve.ListenAndServeTLS("", "") + }) + + // http to https redirect + g.Go(func() error { + return http.ListenAndServe(":http", manager.HTTPHandler(http.HandlerFunc(redirect))) + }) + } else { + // start the server without tls + g.Go(func() error { + return http.ListenAndServe( + c.String("server-addr"), + handler, + ) + }) + } + + log.Info().Msgf("Starting Woodpecker server with version '%s'", version.String()) return g.Wait() } diff --git a/cmd/server/setup.go b/cmd/server/setup.go index bfaf803ee..b5a952b63 100644 --- a/cmd/server/setup.go +++ b/cmd/server/setup.go @@ -376,7 +376,7 @@ func setupSignatureKeys(_store store.Store) (crypto.PrivateKey, crypto.PublicKey log.Fatal().Err(err).Msgf("Failed to generate private key") return nil, nil } - log.Info().Msg("Created private key") + log.Debug().Msg("Created private key") return privKey, privKey.Public() } else if err != nil { log.Fatal().Err(err).Msgf("Failed to load private key") diff --git a/server/router/middleware/logger.go b/server/router/middleware/logger.go index 76d495a61..73fc37eb9 100644 --- a/server/router/middleware/logger.go +++ b/server/router/middleware/logger.go @@ -13,8 +13,8 @@ import ( // Requests without errors are logged using log.Info(). // // It receives: -// 1. A time package format string (e.g. time.RFC3339). -// 2. A boolean stating whether to use UTC time zone or local. +// 1. A time package format string (e.g. time.RFC3339). +// 2. A boolean stating whether to use UTC time zone or local. func Logger(timeFormat string, utc bool) gin.HandlerFunc { return func(c *gin.Context) { start := time.Now() @@ -42,7 +42,7 @@ func Logger(timeFormat string, utc bool) gin.HandlerFunc { // Append error field if this is an erroneous request. log.Error().Str("error", c.Errors.String()).Fields(entry).Msg("") } else { - log.Info().Fields(entry).Msg("") + log.Debug().Fields(entry).Msg("") } } } diff --git a/server/router/middleware/token/token.go b/server/router/middleware/token/token.go index 62dd87e80..fc7870246 100644 --- a/server/router/middleware/token/token.go +++ b/server/router/middleware/token/token.go @@ -64,7 +64,7 @@ func Refresh(c *gin.Context) { // if we really want to fail the request, do we? log.Error().Msgf("cannot refresh access token for %s. %s", user.Login, err) } else { - log.Info().Msgf("refreshed access token for %s", user.Login) + log.Debug().Msgf("refreshed access token for %s", user.Login) } } diff --git a/server/store/datastore/migration/migration.go b/server/store/datastore/migration/migration.go index c5f10a050..4cd0f9aae 100644 --- a/server/store/datastore/migration/migration.go +++ b/server/store/datastore/migration/migration.go @@ -143,7 +143,7 @@ func runTasks(sess *xorm.Session, tasks []*task) error { log.Error().Err(err).Msgf("migration task '%s' failed but is not required", task.name) continue } - log.Info().Msgf("migration task '%s' done", task.name) + log.Debug().Msgf("migration task '%s' done", task.name) } else { log.Trace().Msgf("skip migration task '%s'", task.name) }