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

@@ -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
 }

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()
 }

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")

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("")
 		}
 	}
 }

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)
 		}
 	}
 

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)
 		}