From 2885eff98e88fa127c9d11640dd21b5dd0842569 Mon Sep 17 00:00:00 2001 From: qwerty287 Date: Wed, 10 Jan 2024 14:33:51 +0100 Subject: [PATCH 1/2] Clean up logging --- agent/rpc/client_grpc.go | 14 +++++++------- cli/internal/util.go | 6 +++--- cmd/agent/agent.go | 4 ++-- cmd/server/setup.go | 12 ++++++------ pipeline/backend/kubernetes/kubernetes.go | 4 ++-- pipeline/backend/kubernetes/pod.go | 2 +- pipeline/backend/local/local.go | 2 +- server/api/login.go | 16 ++++++++-------- server/api/org.go | 2 +- server/api/repo.go | 2 +- server/api/stream.go | 8 ++++---- server/grpc/auth_server.go | 2 +- server/grpc/rpc.go | 2 +- server/pipeline/restart.go | 5 ++--- server/plugins/encryption/tink_keyset.go | 2 +- server/plugins/encryption/tink_keyset_watcher.go | 4 ++-- server/queue/fifo.go | 12 ------------ server/queue/persistent.go | 2 +- server/router/middleware/session/repo.go | 7 ++++--- server/router/middleware/session/user.go | 2 +- server/web/config.go | 4 ++-- 21 files changed, 51 insertions(+), 63 deletions(-) diff --git a/agent/rpc/client_grpc.go b/agent/rpc/client_grpc.go index 838bffd102..39e7e2365a 100644 --- a/agent/rpc/client_grpc.go +++ b/agent/rpc/client_grpc.go @@ -89,7 +89,7 @@ func (c *client) Next(ctx context.Context, f rpc.Filter) (*rpc.Workflow, error) // https://github.com/woodpecker-ci/woodpecker/issues/717#issuecomment-1049365104 log.Trace().Err(err).Msg("grpc: to many keepalive pings without sending data") } else { - log.Err(err).Msgf("grpc error: done(): code: %v: %s", status.Code(err), err) + log.Error().Err(err).Msgf("grpc error: done(): code: %v", status.Code(err)) } switch status.Code(err) { @@ -136,7 +136,7 @@ func (c *client) Wait(ctx context.Context, id string) (err error) { break } - log.Err(err).Msgf("grpc error: wait(): code: %v: %s", status.Code(err), err) + log.Error().Err(err).Msgf("grpc error: wait(): code: %v", status.Code(err)) switch status.Code(err) { case @@ -177,7 +177,7 @@ func (c *client) Init(ctx context.Context, id string, state rpc.State) (err erro break } - log.Err(err).Msgf("grpc error: init(): code: %v: %s", status.Code(err), err) + log.Error().Err(err).Msgf("grpc error: init(): code: %v", status.Code(err)) switch status.Code(err) { case @@ -218,7 +218,7 @@ func (c *client) Done(ctx context.Context, id string, state rpc.State) (err erro break } - log.Err(err).Msgf("grpc error: done(): code: %v: %s", status.Code(err), err) + log.Error().Err(err).Msgf("grpc error: done(): code: %v", status.Code(err)) switch status.Code(err) { case @@ -252,7 +252,7 @@ func (c *client) Extend(ctx context.Context, id string) (err error) { break } - log.Err(err).Msgf("grpc error: extend(): code: %v: %s", status.Code(err), err) + log.Error().Err(err).Msgf("grpc error: extend(): code: %v", status.Code(err)) switch status.Code(err) { case @@ -293,7 +293,7 @@ func (c *client) Update(ctx context.Context, id string, state rpc.State) (err er break } - log.Err(err).Msgf("grpc error: update(): code: %v: %s", status.Code(err), err) + log.Error().Err(err).Msgf("grpc error: update(): code: %v", status.Code(err)) switch status.Code(err) { case @@ -332,7 +332,7 @@ func (c *client) Log(ctx context.Context, logEntry *rpc.LogEntry) (err error) { break } - log.Err(err).Msgf("grpc error: log(): code: %v: %s", status.Code(err), err) + log.Error().Err(err).Msgf("grpc error: log(): code: %v", status.Code(err)) switch status.Code(err) { case diff --git a/cli/internal/util.go b/cli/internal/util.go index e71b7558dd..47eff719ad 100644 --- a/cli/internal/util.go +++ b/cli/internal/util.go @@ -44,16 +44,16 @@ func NewClient(c *cli.Context) (woodpecker.Client, error) { // if no server url is provided we can default // to the hosted Woodpecker service. if len(server) == 0 { - return nil, fmt.Errorf("Error: you must provide the Woodpecker server address") + return nil, fmt.Errorf("you must provide the Woodpecker server address") } if len(token) == 0 { - return nil, fmt.Errorf("Error: you must provide your Woodpecker access token") + return nil, fmt.Errorf("you must provide your Woodpecker access token") } // attempt to find system CA certs certs, err := x509.SystemCertPool() if err != nil { - log.Error().Msgf("failed to find system CA certs: %v", err) + log.Error().Err(err).Msg("failed to find system CA certs") } tlsConfig := &tls.Config{ RootCAs: certs, diff --git a/cmd/agent/agent.go b/cmd/agent/agent.go index fc9c6f0c28..b551db3d3e 100644 --- a/cmd/agent/agent.go +++ b/cmd/agent/agent.go @@ -64,7 +64,7 @@ func run(c *cli.Context) error { if c.Bool("healthcheck") { go func() { if err := http.ListenAndServe(c.String("healthcheck-addr"), nil); err != nil { - log.Error().Msgf("cannot listen on address %s: %v", c.String("healthcheck-addr"), err) + log.Error().Err(err).Msgf("cannot listen on address %s", c.String("healthcheck-addr")) } }() } @@ -212,7 +212,7 @@ func run(c *cli.Context) error { err := client.ReportHealth(ctx) if err != nil { - log.Err(err).Msgf("Failed to report health") + log.Err(err).Msg("Failed to report health") return } diff --git a/cmd/server/setup.go b/cmd/server/setup.go index 5a2c0ebf93..6539fadece 100644 --- a/cmd/server/setup.go +++ b/cmd/server/setup.go @@ -64,9 +64,9 @@ func setupStore(c *cli.Context) store.Store { if driver == "sqlite3" { if datastore.SupportedDriver("sqlite3") { - log.Debug().Msgf("server has sqlite3 support") + log.Debug().Msg("server has sqlite3 support") } else { - log.Debug().Msgf("server was built without sqlite3 support!") + log.Debug().Msg("server was built without sqlite3 support!") } } @@ -301,23 +301,23 @@ func setupSignatureKeys(_store store.Store) (crypto.PrivateKey, crypto.PublicKey if errors.Is(err, types.RecordNotExist) { _, privKey, err := ed25519.GenerateKey(rand.Reader) if err != nil { - log.Fatal().Err(err).Msgf("Failed to generate private key") + log.Fatal().Err(err).Msg("Failed to generate private key") return nil, nil } err = _store.ServerConfigSet(privKeyID, hex.EncodeToString(privKey)) if err != nil { - log.Fatal().Err(err).Msgf("Failed to generate private key") + log.Fatal().Err(err).Msg("Failed to generate private key") return nil, nil } log.Debug().Msg("Created private key") return privKey, privKey.Public() } else if err != nil { - log.Fatal().Err(err).Msgf("Failed to load private key") + log.Fatal().Err(err).Msg("Failed to load private key") return nil, nil } privKeyStr, err := hex.DecodeString(privKey) if err != nil { - log.Fatal().Err(err).Msgf("Failed to decode private key") + log.Fatal().Err(err).Msg("Failed to decode private key") return nil, nil } privateKey := ed25519.PrivateKey(privKeyStr) diff --git a/pipeline/backend/kubernetes/kubernetes.go b/pipeline/backend/kubernetes/kubernetes.go index 81aaf24e1c..f1631be594 100644 --- a/pipeline/backend/kubernetes/kubernetes.go +++ b/pipeline/backend/kubernetes/kubernetes.go @@ -99,13 +99,13 @@ func configFromCliContext(ctx context.Context) (*config, error) { // Unmarshal label and annotation settings here to ensure they're valid on startup if labels := c.String("backend-k8s-pod-labels"); labels != "" { if err := yaml.Unmarshal([]byte(labels), &config.PodLabels); err != nil { - log.Error().Msgf("could not unmarshal pod labels '%s': %s", c.String("backend-k8s-pod-labels"), err) + log.Error().Err(err).Msgf("could not unmarshal pod labels '%s'", c.String("backend-k8s-pod-labels")) return nil, err } } if annotations := c.String("backend-k8s-pod-annotations"); annotations != "" { if err := yaml.Unmarshal([]byte(c.String("backend-k8s-pod-annotations")), &config.PodAnnotations); err != nil { - log.Error().Msgf("could not unmarshal pod annotations '%s': %s", c.String("backend-k8s-pod-annotations"), err) + log.Error().Err(err).Msgf("could not unmarshal pod annotations '%s'", c.String("backend-k8s-pod-annotations")) return nil, err } } diff --git a/pipeline/backend/kubernetes/pod.go b/pipeline/backend/kubernetes/pod.go index dbf860870a..6a8ee4d47e 100644 --- a/pipeline/backend/kubernetes/pod.go +++ b/pipeline/backend/kubernetes/pod.go @@ -258,7 +258,7 @@ func resourceList(resources map[string]string) (v1.ResourceList, error) { resName := v1.ResourceName(key) resVal, err := resource.ParseQuantity(val) if err != nil { - return nil, fmt.Errorf("resource request '%v' quantity '%v': %w", key, val, err) + return nil, fmt.Errorf("resource request '%s' quantity '%s': %w", key, val, err) } requestResources[resName] = resVal } diff --git a/pipeline/backend/local/local.go b/pipeline/backend/local/local.go index 5eafe224e4..da4b99a684 100644 --- a/pipeline/backend/local/local.go +++ b/pipeline/backend/local/local.go @@ -235,7 +235,7 @@ func (e *local) DestroyStep(_ context.Context, _ *types.Step, _ string) error { // DestroyWorkflow the pipeline environment. func (e *local) DestroyWorkflow(_ context.Context, _ *types.Config, taskUUID string) error { - log.Trace().Str("taskUUID", taskUUID).Msgf("delete workflow environment") + log.Trace().Str("taskUUID", taskUUID).Msg("delete workflow environment") state, err := e.getState(taskUUID) if err != nil { diff --git a/server/api/login.go b/server/api/login.go index 29d25d7b1a..75b5a494d6 100644 --- a/server/api/login.go +++ b/server/api/login.go @@ -44,17 +44,17 @@ func HandleAuth(c *gin.Context) { _store := store.FromContext(c) _forge := server.Config.Services.Forge - // when dealing with redirects we may need to adjust the content type. I + // when dealing with redirects, we may need to adjust the content type. I // cannot, however, remember why, so need to revisit this line. c.Writer.Header().Del("Content-Type") tmpuser, err := _forge.Login(c, c.Writer, c.Request) if err != nil { - log.Error().Msgf("cannot authenticate user. %s", err) + log.Error().Err(err).Msg("cannot authenticate user") c.Redirect(http.StatusSeeOther, server.Config.Server.RootPath+"/login?error=oauth_error") return } - // this will happen when the user is redirected by the forge as + // this will happen when the forge redirects the user as // part of the authorization workflow. if tmpuser == nil { return @@ -101,7 +101,7 @@ func HandleAuth(c *gin.Context) { // insert the user into the database if err := _store.CreateUser(u); err != nil { - log.Error().Msgf("cannot insert %s. %s", u.Login, err) + log.Error().Err(err).Msgf("cannot insert %s", u.Login) c.Redirect(http.StatusSeeOther, server.Config.Server.RootPath+"/login?error=internal_error") return } @@ -137,7 +137,7 @@ func HandleAuth(c *gin.Context) { } if err := _store.UpdateUser(u); err != nil { - log.Error().Msgf("cannot update %s. %s", u.Login, err) + log.Error().Err(err).Msgf("cannot update %s", u.Login) c.Redirect(http.StatusSeeOther, server.Config.Server.RootPath+"/login?error=internal_error") return } @@ -145,7 +145,7 @@ func HandleAuth(c *gin.Context) { exp := time.Now().Add(server.Config.Server.SessionExpires).Unix() tokenString, err := token.New(token.SessToken, u.Login).SignExpires(u.Hash, exp) if err != nil { - log.Error().Msgf("cannot create token for %s. %s", u.Login, err) + log.Error().Msgf("cannot create token for %s", u.Login) c.Redirect(http.StatusSeeOther, server.Config.Server.RootPath+"/login?error=internal_error") return } @@ -157,7 +157,7 @@ func HandleAuth(c *gin.Context) { continue } if err != nil { - log.Error().Msgf("cannot list repos for %s. %s", u.Login, err) + log.Error().Err(err).Msgf("cannot list repos for %s", u.Login) c.Redirect(http.StatusSeeOther, "/login?error=internal_error") return } @@ -173,7 +173,7 @@ func HandleAuth(c *gin.Context) { perm.UserID = u.ID perm.Synced = time.Now().Unix() if err := _store.PermUpsert(perm); err != nil { - log.Error().Msgf("cannot update permissions for %s. %s", u.Login, err) + log.Error().Err(err).Msgf("cannot update permissions for %s", u.Login) c.Redirect(http.StatusSeeOther, "/login?error=internal_error") return } diff --git a/server/api/org.go b/server/api/org.go index e3b5999990..1efd078761 100644 --- a/server/api/org.go +++ b/server/api/org.go @@ -140,7 +140,7 @@ func LookupOrg(c *gin.Context) { } else if !user.Admin { perm, err := server.Config.Services.Membership.Get(c, user, org.Name) if err != nil { - log.Error().Msgf("Failed to check membership: %v", err) + log.Error().Err(err).Msg("Failed to check membership") c.Status(http.StatusInternalServerError) return } diff --git a/server/api/repo.go b/server/api/repo.go index db16a49d77..21f7ccf099 100644 --- a/server/api/repo.go +++ b/server/api/repo.go @@ -576,7 +576,7 @@ func repairRepo(c *gin.Context, repo *model.Repo, withPerms, skipOnErr bool) { if !skipOnErr { c.AbortWithStatus(http.StatusNotFound) } - log.Error().Err(err).Msgf("could not get user on repo repair") + log.Error().Err(err).Msg("could not get user on repo repair") } else { _ = c.AbortWithError(http.StatusInternalServerError, err) } diff --git a/server/api/stream.go b/server/api/stream.go index ca65ebc9d8..45777cff73 100644 --- a/server/api/stream.go +++ b/server/api/stream.go @@ -160,7 +160,7 @@ func LogStreamSSE(c *gin.Context) { } pl, err := _store.GetPipelineNumber(repo, pipeline) if err != nil { - log.Debug().Msgf("stream cannot get pipeline number: %v", err) + log.Debug().Err(err).Msg("stream cannot get pipeline number") logWriteStringErr(io.WriteString(rw, "event: error\ndata: pipeline not found\n\n")) return } @@ -173,7 +173,7 @@ func LogStreamSSE(c *gin.Context) { } step, err := _store.StepLoad(stepID) if err != nil { - log.Debug().Msgf("stream cannot get step number: %v", err) + log.Debug().Err(err).Msg("stream cannot get step number") logWriteStringErr(io.WriteString(rw, "event: error\ndata: process not found\n\n")) return } @@ -197,12 +197,12 @@ func LogStreamSSE(c *gin.Context) { context.Background(), ) - log.Debug().Msgf("log stream: connection opened") + log.Debug().Msg("log stream: connection opened") defer func() { cancel(nil) close(logc) - log.Debug().Msgf("log stream: connection closed") + log.Debug().Msg("log stream: connection closed") }() go func() { diff --git a/server/grpc/auth_server.go b/server/grpc/auth_server.go index 362e74b4c2..d6413e07ec 100644 --- a/server/grpc/auth_server.go +++ b/server/grpc/auth_server.go @@ -69,7 +69,7 @@ func (s *WoodpeckerAuthServer) getAgent(agentID int64, agentToken string) (*mode agent.Capacity = -1 err := s.store.AgentCreate(agent) if err != nil { - log.Err(err).Msgf("Error creating system agent: %s", err) + log.Error().Err(err).Msg("Error creating system agent") return nil, err } return agent, nil diff --git a/server/grpc/rpc.go b/server/grpc/rpc.go index ea1e9ae151..01afe3801c 100644 --- a/server/grpc/rpc.go +++ b/server/grpc/rpc.go @@ -212,7 +212,7 @@ func (s *RPC) Init(c context.Context, id string, state rpc.State) error { Pipeline: *currentPipeline, }) if err != nil { - log.Error().Err(err).Msgf("could not marshal JSON") + log.Error().Err(err).Msg("could not marshal JSON") return } s.pubsub.Publish(message) diff --git a/server/pipeline/restart.go b/server/pipeline/restart.go index 125f40d775..89fb8193cd 100644 --- a/server/pipeline/restart.go +++ b/server/pipeline/restart.go @@ -41,9 +41,8 @@ func Restart(ctx context.Context, store store.Store, lastPipeline *model.Pipelin // fetch the old pipeline config from the database configs, err := store.ConfigsForPipeline(lastPipeline.ID) if err != nil { - msg := fmt.Sprintf("failure to get pipeline config for %s. %s", repo.FullName, err) - log.Error().Msgf(msg) - return nil, &ErrNotFound{Msg: msg} + log.Error().Err(err).Msgf("failure to get pipeline config for %s", repo.FullName) + return nil, &ErrNotFound{Msg: fmt.Sprintf("failure to get pipeline config for %s. %s", repo.FullName, err)} } for _, y := range configs { diff --git a/server/plugins/encryption/tink_keyset.go b/server/plugins/encryption/tink_keyset.go index 4218a704eb..482b178140 100644 --- a/server/plugins/encryption/tink_keyset.go +++ b/server/plugins/encryption/tink_keyset.go @@ -37,7 +37,7 @@ func (svc *tinkEncryptionService) loadKeyset() error { defer func(file *os.File) { err = file.Close() if err != nil { - log.Err(err).Msgf(logTemplateTinkFailedClosingKeysetFile, svc.keysetFilePath) + log.Error().Err(err).Msgf(logTemplateTinkFailedClosingKeysetFile, svc.keysetFilePath) } }(file) diff --git a/server/plugins/encryption/tink_keyset_watcher.go b/server/plugins/encryption/tink_keyset_watcher.go index 15c0e3ec56..e321c3d6d0 100644 --- a/server/plugins/encryption/tink_keyset_watcher.go +++ b/server/plugins/encryption/tink_keyset_watcher.go @@ -48,13 +48,13 @@ func (svc *tinkEncryptionService) handleFileEvents() { log.Warn().Msgf(logTemplateTinkKeysetFileChanged, event.Name) err := svc.rotate() if err != nil { - log.Fatal().Err(err).Msgf(errMessageFailedRotatingEncryption) + log.Fatal().Err(err).Msg(errMessageFailedRotatingEncryption) } return } case err, ok := <-svc.keysetFileWatcher.Errors: if !ok { - log.Fatal().Err(err).Msgf(errMessageTinkKeysetFileWatchFailed) + log.Fatal().Err(err).Msg(errMessageTinkKeysetFileWatchFailed) } } } diff --git a/server/queue/fifo.go b/server/queue/fifo.go index f86c2a8664..086f1644f5 100644 --- a/server/queue/fifo.go +++ b/server/queue/fifo.go @@ -17,7 +17,6 @@ package queue import ( "container/list" "context" - "runtime" "sync" "time" @@ -241,17 +240,6 @@ func (q *fifo) process() { return } - defer func() { - // the risk of panic is low. This code can probably be removed - // once the code has been used in real world installs without issue. - if err := recover(); err != nil { - const size = 64 << 10 - buf := make([]byte, size) - buf = buf[:runtime.Stack(buf, false)] - log.Error().Msgf("queue: unexpected panic: %v\n%s", err, buf) - } - }() - q.resubmitExpiredPipelines() q.filterWaiting() for pending, worker := q.assignToWorker(); pending != nil && worker != nil; pending, worker = q.assignToWorker() { diff --git a/server/queue/persistent.go b/server/queue/persistent.go index fc4b6cf6d4..afb21609cd 100644 --- a/server/queue/persistent.go +++ b/server/queue/persistent.go @@ -78,7 +78,7 @@ func (q *persistentQueue) Poll(c context.Context, agentID int64, f FilterFn) (*m if task != nil { log.Debug().Msgf("pull queue item: %s: remove from backup", task.ID) if derr := q.store.TaskDelete(task.ID); derr != nil { - log.Error().Msgf("pull queue item: %s: failed to remove from backup: %s", task.ID, derr) + log.Error().Err(derr).Msgf("pull queue item: %s: failed to remove from backup", task.ID) } else { log.Debug().Msgf("pull queue item: %s: successfully removed from backup", task.ID) } diff --git a/server/router/middleware/session/repo.go b/server/router/middleware/session/repo.go index 93366887e3..e7c5f938cd 100644 --- a/server/router/middleware/session/repo.go +++ b/server/router/middleware/session/repo.go @@ -23,6 +23,7 @@ import ( "github.com/gin-gonic/gin" "github.com/rs/zerolog/log" + "go.woodpecker-ci.org/woodpecker/v2/server" "go.woodpecker-ci.org/woodpecker/v2/server/model" @@ -73,7 +74,7 @@ func SetRepo() gin.HandlerFunc { } // debugging - log.Debug().Err(err).Msgf("Cannot find repository %s.", fullName) + log.Debug().Err(err).Msgf("Cannot find repository %s", fullName) if user == nil { c.AbortWithStatus(http.StatusUnauthorized) @@ -112,8 +113,8 @@ func SetPerm() gin.HandlerFunc { var err error perm, err = _store.PermFind(user, repo) if err != nil { - log.Error().Msgf("Error fetching permission for %s %s. %s", - user.Login, repo.FullName, err) + log.Error().Err(err).Msgf("Error fetching permission for %s %s", + user.Login, repo.FullName) } if time.Unix(perm.Synced, 0).Add(time.Hour).Before(time.Now()) { _repo, err := server.Config.Services.Forge.Repo(c, user, repo.ForgeRemoteID, repo.Owner, repo.Name) diff --git a/server/router/middleware/session/user.go b/server/router/middleware/session/user.go index 0e40bffff5..514ff8035b 100644 --- a/server/router/middleware/session/user.go +++ b/server/router/middleware/session/user.go @@ -147,7 +147,7 @@ func MustOrgMember(admin bool) gin.HandlerFunc { perm, err := server.Config.Services.Membership.Get(c, user, org.Name) if err != nil { - log.Error().Msgf("Failed to check membership: %v", err) + log.Error().Err(err).Msg("Failed to check membership") c.String(http.StatusInternalServerError, http.StatusText(http.StatusInternalServerError)) c.Abort() return diff --git a/server/web/config.go b/server/web/config.go index 0efbe88cbb..630ae9ee47 100644 --- a/server/web/config.go +++ b/server/web/config.go @@ -54,7 +54,7 @@ func Config(c *gin.Context) { "json": func(v any) string { a, err := json.Marshal(v) if err != nil { - log.Error().Err(err).Msgf("could not marshal JSON") + log.Error().Err(err).Msg("could not marshal JSON") return "" } return string(a) @@ -65,7 +65,7 @@ func Config(c *gin.Context) { tmpl := template.Must(template.New("").Funcs(funcMap).Parse(configTemplate)) if err := tmpl.Execute(c.Writer, configData); err != nil { - log.Error().Err(err).Msgf("could not execute template") + log.Error().Err(err).Msg("could not execute template") c.AbortWithStatus(http.StatusInternalServerError) return } From d7e676ec3fa21c0cb7fa9430b42b5e3a78efd6ff Mon Sep 17 00:00:00 2001 From: qwerty287 Date: Wed, 10 Jan 2024 15:38:12 +0100 Subject: [PATCH 2/2] revert --- server/queue/fifo.go | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/server/queue/fifo.go b/server/queue/fifo.go index 086f1644f5..f86c2a8664 100644 --- a/server/queue/fifo.go +++ b/server/queue/fifo.go @@ -17,6 +17,7 @@ package queue import ( "container/list" "context" + "runtime" "sync" "time" @@ -240,6 +241,17 @@ func (q *fifo) process() { return } + defer func() { + // the risk of panic is low. This code can probably be removed + // once the code has been used in real world installs without issue. + if err := recover(); err != nil { + const size = 64 << 10 + buf := make([]byte, size) + buf = buf[:runtime.Stack(buf, false)] + log.Error().Msgf("queue: unexpected panic: %v\n%s", err, buf) + } + }() + q.resubmitExpiredPipelines() q.filterWaiting() for pending, worker := q.assignToWorker(); pending != nil && worker != nil; pending, worker = q.assignToWorker() {