diff --git a/apiserver/controllers/controllers.go b/apiserver/controllers/controllers.go index 8e42f320..d7dd5f44 100644 --- a/apiserver/controllers/controllers.go +++ b/apiserver/controllers/controllers.go @@ -15,9 +15,10 @@ package controllers import ( + "context" "encoding/json" "io" - "log" + "log/slog" "net/http" "strings" @@ -60,7 +61,7 @@ type APIController struct { controllerID string } -func handleError(w http.ResponseWriter, err error) { +func handleError(ctx context.Context, w http.ResponseWriter, err error) { w.Header().Set("Content-Type", "application/json") origErr := errors.Cause(err) apiErr := params.APIErrorResponse{ @@ -90,14 +91,14 @@ func handleError(w http.ResponseWriter, err error) { } if err := json.NewEncoder(w).Encode(apiErr); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } -func (a *APIController) webhookMetricLabelValues(valid, reason string) []string { +func (a *APIController) webhookMetricLabelValues(ctx context.Context, valid, reason string) []string { controllerInfo, err := a.r.GetControllerInfo(auth.GetAdminContext()) if err != nil { - log.Printf("failed to get controller info: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to get controller info") // If labels are empty, not attempt will be made to record webhook. return []string{} } @@ -107,11 +108,11 @@ func (a *APIController) webhookMetricLabelValues(valid, reason string) []string } } -func (a *APIController) handleWorkflowJobEvent(w http.ResponseWriter, r *http.Request) { +func (a *APIController) handleWorkflowJobEvent(ctx context.Context, w http.ResponseWriter, r *http.Request) { defer r.Body.Close() body, err := io.ReadAll(r.Body) if err != nil { - handleError(w, gErrors.NewBadRequestError("invalid post body: %s", err)) + handleError(ctx, w, gErrors.NewBadRequestError("invalid post body: %s", err)) return } @@ -124,28 +125,30 @@ func (a *APIController) handleWorkflowJobEvent(w http.ResponseWriter, r *http.Re return } if err := metrics.RecordWebhookWithLabels(labelValues...); err != nil { - log.Printf("failed to record metric: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to record metric") } }() if err := a.r.DispatchWorkflowJob(hookType, signature, body); err != nil { if errors.Is(err, gErrors.ErrNotFound) { - labelValues = a.webhookMetricLabelValues("false", "owner_unknown") - log.Printf("got not found error from DispatchWorkflowJob. webhook not meant for us?: %q", err) + labelValues = a.webhookMetricLabelValues(ctx, "false", "owner_unknown") + slog.With(slog.Any("error", err)).ErrorContext(ctx, "got not found error from DispatchWorkflowJob. webhook not meant for us?") return } else if strings.Contains(err.Error(), "signature") { // TODO: check error type - labelValues = a.webhookMetricLabelValues("false", "signature_invalid") + labelValues = a.webhookMetricLabelValues(ctx, "false", "signature_invalid") } else { - labelValues = a.webhookMetricLabelValues("false", "unknown") + labelValues = a.webhookMetricLabelValues(ctx, "false", "unknown") } - handleError(w, err) + handleError(ctx, w, err) return } - labelValues = a.webhookMetricLabelValues("true", "") + labelValues = a.webhookMetricLabelValues(ctx, "true", "") } func (a *APIController) WebhookHandler(w http.ResponseWriter, r *http.Request) { + ctx := r.Context() + vars := mux.Vars(r) controllerID, ok := vars["controllerID"] // If the webhook URL includes a controller ID, we validate that it's meant for us. We still @@ -154,7 +157,7 @@ func (a *APIController) WebhookHandler(w http.ResponseWriter, r *http.Request) { // via garm. We cannot tag a webhook URL on github, so there is no way to determine ownership. // Using a controllerID suffix is a simple way to denote ownership. if ok && controllerID != a.controllerID { - log.Printf("ignoring webhook meant for controller %s", util.SanitizeLogEntry(controllerID)) + slog.InfoContext(ctx, "ignoring webhook meant for foreign controller", "req_controller_id", controllerID) return } @@ -163,10 +166,9 @@ func (a *APIController) WebhookHandler(w http.ResponseWriter, r *http.Request) { event := runnerParams.Event(headers.Get("X-Github-Event")) switch event { case runnerParams.WorkflowJobEvent: - a.handleWorkflowJobEvent(w, r) + a.handleWorkflowJobEvent(ctx, w, r) default: - log.Printf("ignoring unknown event %s", util.SanitizeLogEntry(string(event))) - return + slog.InfoContext(ctx, "ignoring unknown event", "gh_event", util.SanitizeLogEntry(string(event))) } } @@ -175,19 +177,19 @@ func (a *APIController) WSHandler(writer http.ResponseWriter, req *http.Request) if !auth.IsAdmin(ctx) { writer.WriteHeader(http.StatusForbidden) if _, err := writer.Write([]byte("you need admin level access to view logs")); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } if a.hub == nil { - handleError(writer, gErrors.NewBadRequestError("log streamer is disabled")) + handleError(ctx, writer, gErrors.NewBadRequestError("log streamer is disabled")) return } conn, err := a.upgrader.Upgrade(writer, req, nil) if err != nil { - log.Printf("error upgrading to websockets: %v", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "error upgrading to websockets") return } @@ -198,11 +200,11 @@ func (a *APIController) WSHandler(writer http.ResponseWriter, req *http.Request) // the client once the token expires. client, err := wsWriter.NewClient(conn, a.hub) if err != nil { - log.Printf("failed to create new client: %v", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to create new client") return } if err := a.hub.Register(client); err != nil { - log.Printf("failed to register new client: %v", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to register new client") return } client.Go() @@ -210,6 +212,7 @@ func (a *APIController) WSHandler(writer http.ResponseWriter, req *http.Request) // NotFoundHandler is returned when an invalid URL is acccessed func (a *APIController) NotFoundHandler(w http.ResponseWriter, r *http.Request) { + ctx := r.Context() apiErr := params.APIErrorResponse{ Details: "Resource not found", Error: "Not found", @@ -218,7 +221,7 @@ func (a *APIController) NotFoundHandler(w http.ResponseWriter, r *http.Request) w.Header().Set("Content-Type", "application/json") w.WriteHeader(http.StatusNotFound) if err := json.NewEncoder(w).Encode(apiErr); err != nil { - log.Printf("failet to write response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failet to write response") } } @@ -233,19 +236,19 @@ func (a *APIController) MetricsTokenHandler(w http.ResponseWriter, r *http.Reque ctx := r.Context() if !auth.IsAdmin(ctx) { - handleError(w, gErrors.ErrUnauthorized) + handleError(ctx, w, gErrors.ErrUnauthorized) return } token, err := a.auth.GetJWTMetricsToken(ctx) if err != nil { - handleError(w, err) + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") err = json.NewEncoder(w).Encode(runnerParams.JWTResponse{Token: token}) if err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -266,32 +269,32 @@ func (a *APIController) MetricsTokenHandler(w http.ResponseWriter, r *http.Reque // // LoginHandler returns a jwt token func (a *APIController) LoginHandler(w http.ResponseWriter, r *http.Request) { + ctx := r.Context() var loginInfo runnerParams.PasswordLoginParams if err := json.NewDecoder(r.Body).Decode(&loginInfo); err != nil { - handleError(w, gErrors.ErrBadRequest) + handleError(ctx, w, gErrors.ErrBadRequest) return } if err := loginInfo.Validate(); err != nil { - handleError(w, err) + handleError(ctx, w, err) return } - ctx := r.Context() ctx, err := a.auth.AuthenticateUser(ctx, loginInfo) if err != nil { - handleError(w, err) + handleError(ctx, w, err) return } tokenString, err := a.auth.GetJWTToken(ctx) if err != nil { - handleError(w, err) + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(runnerParams.JWTResponse{Token: tokenString}); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -310,28 +313,27 @@ func (a *APIController) LoginHandler(w http.ResponseWriter, r *http.Request) { // 200: User // 400: APIErrorResponse func (a *APIController) FirstRunHandler(w http.ResponseWriter, r *http.Request) { + ctx := r.Context() if a.auth.IsInitialized() { err := gErrors.NewConflictError("already initialized") - handleError(w, err) + handleError(ctx, w, err) return } - ctx := r.Context() - var newUserParams runnerParams.NewUserParams if err := json.NewDecoder(r.Body).Decode(&newUserParams); err != nil { - handleError(w, gErrors.ErrBadRequest) + handleError(ctx, w, gErrors.ErrBadRequest) return } newUser, err := a.auth.InitController(ctx, newUserParams) if err != nil { - handleError(w, err) + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(newUser); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -346,13 +348,13 @@ func (a *APIController) ListCredentials(w http.ResponseWriter, r *http.Request) ctx := r.Context() creds, err := a.r.ListCredentials(ctx) if err != nil { - handleError(w, err) + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(creds); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -367,13 +369,13 @@ func (a *APIController) ListProviders(w http.ResponseWriter, r *http.Request) { ctx := r.Context() providers, err := a.r.ListProviders(ctx) if err != nil { - handleError(w, err) + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(providers); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -388,13 +390,13 @@ func (a *APIController) ListAllJobs(w http.ResponseWriter, r *http.Request) { ctx := r.Context() jobs, err := a.r.ListAllJobs(ctx) if err != nil { - handleError(w, err) + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(jobs); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -409,12 +411,12 @@ func (a *APIController) ControllerInfoHandler(w http.ResponseWriter, r *http.Req ctx := r.Context() info, err := a.r.GetControllerInfo(ctx) if err != nil { - handleError(w, err) + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(info); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } diff --git a/apiserver/controllers/enterprises.go b/apiserver/controllers/enterprises.go index 6a015df2..39abb223 100644 --- a/apiserver/controllers/enterprises.go +++ b/apiserver/controllers/enterprises.go @@ -16,7 +16,7 @@ package controllers import ( "encoding/json" - "log" + "log/slog" "net/http" gErrors "github.com/cloudbase/garm-provider-common/errors" @@ -45,20 +45,20 @@ func (a *APIController) CreateEnterpriseHandler(w http.ResponseWriter, r *http.R var enterpriseData runnerParams.CreateEnterpriseParams if err := json.NewDecoder(r.Body).Decode(&enterpriseData); err != nil { - handleError(w, gErrors.ErrBadRequest) + handleError(ctx, w, gErrors.ErrBadRequest) return } enterprise, err := a.r.CreateEnterprise(ctx, enterpriseData) if err != nil { - log.Printf("error creating enterprise: %+v", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "error creating enterprise") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(enterprise); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -74,14 +74,14 @@ func (a *APIController) ListEnterprisesHandler(w http.ResponseWriter, r *http.Re enterprise, err := a.r.ListEnterprises(ctx) if err != nil { - log.Printf("listing enterprise: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing enterprise") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(enterprise); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -110,21 +110,21 @@ func (a *APIController) GetEnterpriseByIDHandler(w http.ResponseWriter, r *http. Error: "Bad Request", Details: "No enterprise ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } enterprise, err := a.r.GetEnterpriseByID(ctx, enterpriseID) if err != nil { - log.Printf("fetching enterprise: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "fetching enterprise") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(enterprise); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -152,14 +152,14 @@ func (a *APIController) DeleteEnterpriseHandler(w http.ResponseWriter, r *http.R Error: "Bad Request", Details: "No enterprise ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } if err := a.r.DeleteEnterprise(ctx, enterpriseID); err != nil { - log.Printf("removing enterprise: %+v", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "removing enterprise") + handleError(ctx, w, err) return } @@ -198,27 +198,27 @@ func (a *APIController) UpdateEnterpriseHandler(w http.ResponseWriter, r *http.R Error: "Bad Request", Details: "No enterprise ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } var updatePayload runnerParams.UpdateEntityParams if err := json.NewDecoder(r.Body).Decode(&updatePayload); err != nil { - handleError(w, gErrors.ErrBadRequest) + handleError(ctx, w, gErrors.ErrBadRequest) return } enterprise, err := a.r.UpdateEnterprise(ctx, enterpriseID, updatePayload) if err != nil { - log.Printf("error updating enterprise: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "error updating enterprise: %s") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(enterprise); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -253,28 +253,28 @@ func (a *APIController) CreateEnterprisePoolHandler(w http.ResponseWriter, r *ht Error: "Bad Request", Details: "No enterprise ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } var poolData runnerParams.CreatePoolParams if err := json.NewDecoder(r.Body).Decode(&poolData); err != nil { - log.Printf("failed to decode: %s", err) - handleError(w, gErrors.ErrBadRequest) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to decode") + handleError(ctx, w, gErrors.ErrBadRequest) return } pool, err := a.r.CreateEnterprisePool(ctx, enterpriseID, poolData) if err != nil { - log.Printf("error creating enterprise pool: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "error creating enterprise pool") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(pool); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -302,21 +302,21 @@ func (a *APIController) ListEnterprisePoolsHandler(w http.ResponseWriter, r *htt Error: "Bad Request", Details: "No enterprise ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } pools, err := a.r.ListEnterprisePools(ctx, enterpriseID) if err != nil { - log.Printf("listing pools: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing pools") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(pools); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -352,21 +352,21 @@ func (a *APIController) GetEnterprisePoolHandler(w http.ResponseWriter, r *http. Error: "Bad Request", Details: "No enterprise or pool ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } pool, err := a.r.GetEnterprisePoolByID(ctx, enterpriseID, poolID) if err != nil { - log.Printf("listing pools: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing pools") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(pool); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -401,14 +401,14 @@ func (a *APIController) DeleteEnterprisePoolHandler(w http.ResponseWriter, r *ht Error: "Bad Request", Details: "No enterprise or pool ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } if err := a.r.DeleteEnterprisePool(ctx, enterpriseID, poolID); err != nil { - log.Printf("removing pool: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "removing pool") + handleError(ctx, w, err) return } @@ -455,27 +455,27 @@ func (a *APIController) UpdateEnterprisePoolHandler(w http.ResponseWriter, r *ht Error: "Bad Request", Details: "No enterprise or pool ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } var poolData runnerParams.UpdatePoolParams if err := json.NewDecoder(r.Body).Decode(&poolData); err != nil { - log.Printf("failed to decode: %s", err) - handleError(w, gErrors.ErrBadRequest) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to decode") + handleError(ctx, w, gErrors.ErrBadRequest) return } pool, err := a.r.UpdateEnterprisePool(ctx, enterpriseID, poolID, poolData) if err != nil { - log.Printf("error creating enterprise pool: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "error creating enterprise pool") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(pool); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } diff --git a/apiserver/controllers/instances.go b/apiserver/controllers/instances.go index e95a99d4..6cf43dd9 100644 --- a/apiserver/controllers/instances.go +++ b/apiserver/controllers/instances.go @@ -16,7 +16,7 @@ package controllers import ( "encoding/json" - "log" + "log/slog" "net/http" "strconv" @@ -51,21 +51,21 @@ func (a *APIController) ListPoolInstancesHandler(w http.ResponseWriter, r *http. Error: "Bad Request", Details: "No pool ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } instances, err := a.r.ListPoolInstances(ctx, poolID) if err != nil { - log.Printf("listing pool instances: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing pool instances") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(instances); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -93,21 +93,21 @@ func (a *APIController) GetInstanceHandler(w http.ResponseWriter, r *http.Reques Error: "Bad Request", Details: "No runner name specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } instance, err := a.r.GetInstance(ctx, instanceName) if err != nil { - log.Printf("listing instances: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing instances") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(instance); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -140,15 +140,15 @@ func (a *APIController) DeleteInstanceHandler(w http.ResponseWriter, r *http.Req Error: "Bad Request", Details: "No instance name specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } forceRemove, _ := strconv.ParseBool(r.URL.Query().Get("forceRemove")) if err := a.r.DeleteRunner(ctx, instanceName, forceRemove); err != nil { - log.Printf("removing runner: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "removing runner") + handleError(ctx, w, err) return } @@ -180,21 +180,21 @@ func (a *APIController) ListRepoInstancesHandler(w http.ResponseWriter, r *http. Error: "Bad Request", Details: "No repo ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } instances, err := a.r.ListRepoInstances(ctx, repoID) if err != nil { - log.Printf("listing pools: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing pools") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(instances); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -222,21 +222,21 @@ func (a *APIController) ListOrgInstancesHandler(w http.ResponseWriter, r *http.R Error: "Bad Request", Details: "No org ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } instances, err := a.r.ListOrgInstances(ctx, orgID) if err != nil { - log.Printf("listing instances: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing instances") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(instances); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -264,21 +264,21 @@ func (a *APIController) ListEnterpriseInstancesHandler(w http.ResponseWriter, r Error: "Bad Request", Details: "No enterprise ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } instances, err := a.r.ListEnterpriseInstances(ctx, enterpriseID) if err != nil { - log.Printf("listing instances: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing instances") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(instances); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -294,14 +294,14 @@ func (a *APIController) ListAllInstancesHandler(w http.ResponseWriter, r *http.R instances, err := a.r.ListAllInstances(ctx) if err != nil { - log.Printf("listing instances: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing instances") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(instances); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -310,14 +310,14 @@ func (a *APIController) InstanceStatusMessageHandler(w http.ResponseWriter, r *h var updateMessage runnerParams.InstanceUpdateMessage if err := json.NewDecoder(r.Body).Decode(&updateMessage); err != nil { - log.Printf("failed to decode: %s", err) - handleError(w, gErrors.ErrBadRequest) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to decode") + handleError(ctx, w, gErrors.ErrBadRequest) return } if err := a.r.AddInstanceStatusMessage(ctx, updateMessage); err != nil { - log.Printf("error saving status message: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "error saving status message") + handleError(ctx, w, err) return } @@ -330,14 +330,14 @@ func (a *APIController) InstanceSystemInfoHandler(w http.ResponseWriter, r *http var updateMessage runnerParams.UpdateSystemInfoParams if err := json.NewDecoder(r.Body).Decode(&updateMessage); err != nil { - log.Printf("failed to decode: %s", err) - handleError(w, gErrors.ErrBadRequest) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to decode") + handleError(ctx, w, gErrors.ErrBadRequest) return } if err := a.r.UpdateSystemInfo(ctx, updateMessage); err != nil { - log.Printf("error saving status message: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "error saving status message") + handleError(ctx, w, err) return } diff --git a/apiserver/controllers/metadata.go b/apiserver/controllers/metadata.go index 664d46a6..1b7e215d 100644 --- a/apiserver/controllers/metadata.go +++ b/apiserver/controllers/metadata.go @@ -17,7 +17,7 @@ package controllers import ( "encoding/json" "fmt" - "log" + "log/slog" "net/http" "github.com/cloudbase/garm/apiserver/params" @@ -29,14 +29,14 @@ func (a *APIController) InstanceGithubRegistrationTokenHandler(w http.ResponseWr token, err := a.r.GetInstanceGithubRegistrationToken(ctx) if err != nil { - handleError(w, err) + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") w.WriteHeader(http.StatusOK) if _, err := w.Write([]byte(token)); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -50,7 +50,7 @@ func (a *APIController) JITCredentialsFileHandler(w http.ResponseWriter, r *http Error: "Not Found", Details: "Not Found", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } @@ -59,8 +59,8 @@ func (a *APIController) JITCredentialsFileHandler(w http.ResponseWriter, r *http data, err := a.r.GetJITConfigFile(ctx, dotFileName) if err != nil { - log.Printf("getting JIT config file: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "getting JIT config file") + handleError(ctx, w, err) return } @@ -71,7 +71,7 @@ func (a *APIController) JITCredentialsFileHandler(w http.ResponseWriter, r *http w.Header().Set("Content-Length", fmt.Sprintf("%d", len(data))) w.WriteHeader(http.StatusOK) if _, err := w.Write(data); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -80,14 +80,14 @@ func (a *APIController) SystemdServiceNameHandler(w http.ResponseWriter, r *http serviceName, err := a.r.GetRunnerServiceName(ctx) if err != nil { - handleError(w, err) + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "text/plain") w.WriteHeader(http.StatusOK) if _, err := w.Write([]byte(serviceName)); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -97,14 +97,14 @@ func (a *APIController) SystemdUnitFileHandler(w http.ResponseWriter, r *http.Re data, err := a.r.GenerateSystemdUnitFile(ctx, runAsUser) if err != nil { - handleError(w, err) + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "text/plain") w.WriteHeader(http.StatusOK) if _, err := w.Write(data); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -113,12 +113,12 @@ func (a *APIController) RootCertificateBundleHandler(w http.ResponseWriter, r *h bundle, err := a.r.GetRootCertificateBundle(ctx) if err != nil { - handleError(w, err) + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(bundle); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } diff --git a/apiserver/controllers/organizations.go b/apiserver/controllers/organizations.go index 02f93fc4..8495d351 100644 --- a/apiserver/controllers/organizations.go +++ b/apiserver/controllers/organizations.go @@ -16,7 +16,7 @@ package controllers import ( "encoding/json" - "log" + "log/slog" "net/http" "strconv" @@ -46,20 +46,20 @@ func (a *APIController) CreateOrgHandler(w http.ResponseWriter, r *http.Request) var orgData runnerParams.CreateOrgParams if err := json.NewDecoder(r.Body).Decode(&orgData); err != nil { - handleError(w, gErrors.ErrBadRequest) + handleError(ctx, w, gErrors.ErrBadRequest) return } org, err := a.r.CreateOrganization(ctx, orgData) if err != nil { - log.Printf("error creating organization: %+v", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "error creating organization") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(org); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -75,14 +75,14 @@ func (a *APIController) ListOrgsHandler(w http.ResponseWriter, r *http.Request) orgs, err := a.r.ListOrganizations(ctx) if err != nil { - log.Printf("listing orgs: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing orgs") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(orgs); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -111,21 +111,21 @@ func (a *APIController) GetOrgByIDHandler(w http.ResponseWriter, r *http.Request Error: "Bad Request", Details: "No org ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } org, err := a.r.GetOrganizationByID(ctx, orgID) if err != nil { - log.Printf("fetching org: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "fetching org") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(org); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -159,7 +159,7 @@ func (a *APIController) DeleteOrgHandler(w http.ResponseWriter, r *http.Request) Error: "Bad Request", Details: "No org ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } @@ -167,8 +167,8 @@ func (a *APIController) DeleteOrgHandler(w http.ResponseWriter, r *http.Request) keepWebhook, _ := strconv.ParseBool(r.URL.Query().Get("keepWebhook")) if err := a.r.DeleteOrganization(ctx, orgID, keepWebhook); err != nil { - log.Printf("removing org: %+v", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "removing org") + handleError(ctx, w, err) return } @@ -208,27 +208,27 @@ func (a *APIController) UpdateOrgHandler(w http.ResponseWriter, r *http.Request) Error: "Bad Request", Details: "No org ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } var updatePayload runnerParams.UpdateEntityParams if err := json.NewDecoder(r.Body).Decode(&updatePayload); err != nil { - handleError(w, gErrors.ErrBadRequest) + handleError(ctx, w, gErrors.ErrBadRequest) return } org, err := a.r.UpdateOrganization(ctx, orgID, updatePayload) if err != nil { - log.Printf("error updating organization: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "error updating organization") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(org); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -263,28 +263,28 @@ func (a *APIController) CreateOrgPoolHandler(w http.ResponseWriter, r *http.Requ Error: "Bad Request", Details: "No org ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } var poolData runnerParams.CreatePoolParams if err := json.NewDecoder(r.Body).Decode(&poolData); err != nil { - log.Printf("failed to decode: %s", err) - handleError(w, gErrors.ErrBadRequest) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to decode") + handleError(ctx, w, gErrors.ErrBadRequest) return } pool, err := a.r.CreateOrgPool(ctx, orgID, poolData) if err != nil { - log.Printf("error creating organization pool: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "error creating organization pool") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(pool); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -312,21 +312,21 @@ func (a *APIController) ListOrgPoolsHandler(w http.ResponseWriter, r *http.Reque Error: "Bad Request", Details: "No org ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } pools, err := a.r.ListOrgPools(ctx, orgID) if err != nil { - log.Printf("listing pools: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing pools") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(pools); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -361,21 +361,21 @@ func (a *APIController) GetOrgPoolHandler(w http.ResponseWriter, r *http.Request Error: "Bad Request", Details: "No org or pool ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } pool, err := a.r.GetOrgPoolByID(ctx, orgID, poolID) if err != nil { - log.Printf("listing pools: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing pools") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(pool); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -410,14 +410,14 @@ func (a *APIController) DeleteOrgPoolHandler(w http.ResponseWriter, r *http.Requ Error: "Bad Request", Details: "No org or pool ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } if err := a.r.DeleteOrgPool(ctx, orgID, poolID); err != nil { - log.Printf("removing pool: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "removing pool") + handleError(ctx, w, err) return } @@ -464,28 +464,28 @@ func (a *APIController) UpdateOrgPoolHandler(w http.ResponseWriter, r *http.Requ Error: "Bad Request", Details: "No org or pool ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } var poolData runnerParams.UpdatePoolParams if err := json.NewDecoder(r.Body).Decode(&poolData); err != nil { - log.Printf("failed to decode: %s", err) - handleError(w, gErrors.ErrBadRequest) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to decode") + handleError(ctx, w, gErrors.ErrBadRequest) return } pool, err := a.r.UpdateOrgPool(ctx, orgID, poolID, poolData) if err != nil { - log.Printf("error creating organization pool: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "error creating organization pool") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(pool); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -521,28 +521,28 @@ func (a *APIController) InstallOrgWebhookHandler(w http.ResponseWriter, r *http. Error: "Bad Request", Details: "No org ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } var hookParam runnerParams.InstallWebhookParams if err := json.NewDecoder(r.Body).Decode(&hookParam); err != nil { - log.Printf("failed to decode: %s", err) - handleError(w, gErrors.ErrBadRequest) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to decode") + handleError(ctx, w, gErrors.ErrBadRequest) return } info, err := a.r.InstallOrgWebhook(ctx, orgID, hookParam) if err != nil { - log.Printf("installing webhook: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "installing webhook") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(info); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -570,14 +570,14 @@ func (a *APIController) UninstallOrgWebhookHandler(w http.ResponseWriter, r *htt Error: "Bad Request", Details: "No org ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } if err := a.r.UninstallOrgWebhook(ctx, orgID); err != nil { - log.Printf("removing webhook: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "removing webhook") + handleError(ctx, w, err) return } @@ -610,20 +610,20 @@ func (a *APIController) GetOrgWebhookInfoHandler(w http.ResponseWriter, r *http. Error: "Bad Request", Details: "No org ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } info, err := a.r.GetOrgWebhookInfo(ctx, orgID) if err != nil { - log.Printf("getting webhook info: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "getting webhook info") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(info); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } diff --git a/apiserver/controllers/pools.go b/apiserver/controllers/pools.go index 34403759..3f7a81b1 100644 --- a/apiserver/controllers/pools.go +++ b/apiserver/controllers/pools.go @@ -16,7 +16,7 @@ package controllers import ( "encoding/json" - "log" + "log/slog" "net/http" gErrors "github.com/cloudbase/garm-provider-common/errors" @@ -39,14 +39,14 @@ func (a *APIController) ListAllPoolsHandler(w http.ResponseWriter, r *http.Reque pools, err := a.r.ListAllPools(ctx) if err != nil { - log.Printf("listing pools: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing pools") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(pools); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -75,15 +75,15 @@ func (a *APIController) GetPoolByIDHandler(w http.ResponseWriter, r *http.Reques Error: "Bad Request", Details: "No pool ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } pool, err := a.r.GetPoolByID(ctx, poolID) if err != nil { - log.Printf("fetching pool: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "fetching pool") + handleError(ctx, w, err) return } @@ -91,7 +91,7 @@ func (a *APIController) GetPoolByIDHandler(w http.ResponseWriter, r *http.Reques w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(pool); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -119,14 +119,14 @@ func (a *APIController) DeletePoolByIDHandler(w http.ResponseWriter, r *http.Req Error: "Bad Request", Details: "No pool ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } if err := a.r.DeletePoolByID(ctx, poolID); err != nil { - log.Printf("removing pool: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "removing pool") + handleError(ctx, w, err) return } @@ -165,27 +165,27 @@ func (a *APIController) UpdatePoolByIDHandler(w http.ResponseWriter, r *http.Req Error: "Bad Request", Details: "No pool ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } var poolData runnerParams.UpdatePoolParams if err := json.NewDecoder(r.Body).Decode(&poolData); err != nil { - log.Printf("failed to decode: %s", err) - handleError(w, gErrors.ErrBadRequest) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to decode") + handleError(ctx, w, gErrors.ErrBadRequest) return } pool, err := a.r.UpdatePoolByID(ctx, poolID, poolData) if err != nil { - log.Printf("fetching pool: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "fetching pool") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(pool); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } diff --git a/apiserver/controllers/repositories.go b/apiserver/controllers/repositories.go index ae2a3040..6831dda4 100644 --- a/apiserver/controllers/repositories.go +++ b/apiserver/controllers/repositories.go @@ -16,7 +16,7 @@ package controllers import ( "encoding/json" - "log" + "log/slog" "net/http" "strconv" @@ -46,20 +46,20 @@ func (a *APIController) CreateRepoHandler(w http.ResponseWriter, r *http.Request var repoData runnerParams.CreateRepoParams if err := json.NewDecoder(r.Body).Decode(&repoData); err != nil { - handleError(w, gErrors.ErrBadRequest) + handleError(ctx, w, gErrors.ErrBadRequest) return } repo, err := a.r.CreateRepository(ctx, repoData) if err != nil { - log.Printf("error creating repository: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "error creating repository") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(repo); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -75,14 +75,14 @@ func (a *APIController) ListReposHandler(w http.ResponseWriter, r *http.Request) repos, err := a.r.ListRepositories(ctx) if err != nil { - log.Printf("listing repos: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing repositories") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(repos); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -111,21 +111,21 @@ func (a *APIController) GetRepoByIDHandler(w http.ResponseWriter, r *http.Reques Error: "Bad Request", Details: "No repo ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } repo, err := a.r.GetRepositoryByID(ctx, repoID) if err != nil { - log.Printf("fetching repo: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "fetching repository") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(repo); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -159,15 +159,15 @@ func (a *APIController) DeleteRepoHandler(w http.ResponseWriter, r *http.Request Error: "Bad Request", Details: "No repo ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } keepWebhook, _ := strconv.ParseBool(r.URL.Query().Get("keepWebhook")) if err := a.r.DeleteRepository(ctx, repoID, keepWebhook); err != nil { - log.Printf("fetching repo: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "fetching repository") + handleError(ctx, w, err) return } @@ -207,27 +207,27 @@ func (a *APIController) UpdateRepoHandler(w http.ResponseWriter, r *http.Request Error: "Bad Request", Details: "No repo ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } var updatePayload runnerParams.UpdateEntityParams if err := json.NewDecoder(r.Body).Decode(&updatePayload); err != nil { - handleError(w, gErrors.ErrBadRequest) + handleError(ctx, w, gErrors.ErrBadRequest) return } repo, err := a.r.UpdateRepository(ctx, repoID, updatePayload) if err != nil { - log.Printf("error updating repository: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "error updating repository") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(repo); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -262,28 +262,28 @@ func (a *APIController) CreateRepoPoolHandler(w http.ResponseWriter, r *http.Req Error: "Bad Request", Details: "No repo ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } var poolData runnerParams.CreatePoolParams if err := json.NewDecoder(r.Body).Decode(&poolData); err != nil { - log.Printf("failed to decode: %s", err) - handleError(w, gErrors.ErrBadRequest) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to decode") + handleError(ctx, w, gErrors.ErrBadRequest) return } pool, err := a.r.CreateRepoPool(ctx, repoID, poolData) if err != nil { - log.Printf("error creating repository pool: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "error creating repository pool") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(pool); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -311,21 +311,21 @@ func (a *APIController) ListRepoPoolsHandler(w http.ResponseWriter, r *http.Requ Error: "Bad Request", Details: "No repo ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } pools, err := a.r.ListRepoPools(ctx, repoID) if err != nil { - log.Printf("listing pools: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing pools") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(pools); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -360,21 +360,21 @@ func (a *APIController) GetRepoPoolHandler(w http.ResponseWriter, r *http.Reques Error: "Bad Request", Details: "No repo or pool ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } pool, err := a.r.GetRepoPoolByID(ctx, repoID, poolID) if err != nil { - log.Printf("listing pools: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing pools") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(pool); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -409,14 +409,14 @@ func (a *APIController) DeleteRepoPoolHandler(w http.ResponseWriter, r *http.Req Error: "Bad Request", Details: "No repo or pool ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } if err := a.r.DeleteRepoPool(ctx, repoID, poolID); err != nil { - log.Printf("removing pool: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "removing pool") + handleError(ctx, w, err) return } @@ -463,28 +463,28 @@ func (a *APIController) UpdateRepoPoolHandler(w http.ResponseWriter, r *http.Req Error: "Bad Request", Details: "No repo or pool ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } var poolData runnerParams.UpdatePoolParams if err := json.NewDecoder(r.Body).Decode(&poolData); err != nil { - log.Printf("failed to decode: %s", err) - handleError(w, gErrors.ErrBadRequest) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to decode") + handleError(ctx, w, gErrors.ErrBadRequest) return } pool, err := a.r.UpdateRepoPool(ctx, repoID, poolID, poolData) if err != nil { - log.Printf("error creating repository pool: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "error creating repository pool") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(pool); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -520,28 +520,28 @@ func (a *APIController) InstallRepoWebhookHandler(w http.ResponseWriter, r *http Error: "Bad Request", Details: "No repository ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } var hookParam runnerParams.InstallWebhookParams if err := json.NewDecoder(r.Body).Decode(&hookParam); err != nil { - log.Printf("failed to decode: %s", err) - handleError(w, gErrors.ErrBadRequest) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to decode") + handleError(ctx, w, gErrors.ErrBadRequest) return } info, err := a.r.InstallRepoWebhook(ctx, repoID, hookParam) if err != nil { - log.Printf("installing webhook: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "installing webhook") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(info); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -569,14 +569,14 @@ func (a *APIController) UninstallRepoWebhookHandler(w http.ResponseWriter, r *ht Error: "Bad Request", Details: "No repository ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } if err := a.r.UninstallRepoWebhook(ctx, repoID); err != nil { - log.Printf("removing webhook: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "removing webhook") + handleError(ctx, w, err) return } @@ -609,20 +609,20 @@ func (a *APIController) GetRepoWebhookInfoHandler(w http.ResponseWriter, r *http Error: "Bad Request", Details: "No repository ID specified", }); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } info, err := a.r.GetRepoWebhookInfo(ctx, repoID) if err != nil { - log.Printf("getting webhook info: %s", err) - handleError(w, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "getting webhook info") + handleError(ctx, w, err) return } w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(info); err != nil { - log.Printf("failed to encode response: %q", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } diff --git a/apiserver/routers/routers.go b/apiserver/routers/routers.go index 52e4b62a..5e6de6cd 100644 --- a/apiserver/routers/routers.go +++ b/apiserver/routers/routers.go @@ -47,14 +47,14 @@ package routers import ( _ "expvar" // Register the expvar handlers - "io" + "log/slog" "net/http" _ "net/http/pprof" // Register the pprof handlers + "github.com/felixge/httpsnoop" "github.com/gorilla/mux" "github.com/prometheus/client_golang/prometheus/promhttp" - "github.com/cloudbase/garm-provider-common/util" "github.com/cloudbase/garm/apiserver/controllers" "github.com/cloudbase/garm/auth" ) @@ -82,10 +82,28 @@ func WithDebugServer(parentRouter *mux.Router) *mux.Router { return parentRouter } -func NewAPIRouter(han *controllers.APIController, logWriter io.Writer, authMiddleware, initMiddleware, instanceMiddleware auth.Middleware, manageWebhooks bool) *mux.Router { +func requestLogger(h http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + // gathers metrics from the upstream handlers + metrics := httpsnoop.CaptureMetrics(h, w, r) + + //prints log and metrics + slog.Info( + "access_log", + slog.String("method", r.Method), + slog.String("uri", r.URL.RequestURI()), + slog.String("user_agent", r.Header.Get("User-Agent")), + slog.String("ip", r.RemoteAddr), + slog.Int("code", metrics.Code), + slog.Int64("bytes", metrics.Written), + slog.Duration("request_time", metrics.Duration), + ) + }) +} + +func NewAPIRouter(han *controllers.APIController, authMiddleware, initMiddleware, instanceMiddleware auth.Middleware, manageWebhooks bool) *mux.Router { router := mux.NewRouter() - logMiddleware := util.NewLoggingMiddleware(logWriter) - router.Use(logMiddleware) + router.Use(requestLogger) // Handles github webhooks webhookRouter := router.PathPrefix("/webhooks").Subrouter() diff --git a/auth/init_required.go b/auth/init_required.go index 6265649e..7dcc655b 100644 --- a/auth/init_required.go +++ b/auth/init_required.go @@ -16,7 +16,7 @@ package auth import ( "encoding/json" - "log" + "log/slog" "net/http" "github.com/cloudbase/garm/apiserver/params" @@ -37,16 +37,17 @@ type initRequired struct { // Middleware implements the middleware interface func (i *initRequired) Middleware(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + ctx := r.Context() ctrlInfo, err := i.store.ControllerInfo() if err != nil || ctrlInfo.ControllerID.String() == "" { w.Header().Add("Content-Type", "application/json") w.WriteHeader(http.StatusConflict) if err := json.NewEncoder(w).Encode(params.InitializationRequired); err != nil { - log.Printf("failed to encode response: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } return } - ctx := r.Context() + next.ServeHTTP(w, r.WithContext(ctx)) }) } diff --git a/auth/instance_middleware.go b/auth/instance_middleware.go index 4e947099..71147c78 100644 --- a/auth/instance_middleware.go +++ b/auth/instance_middleware.go @@ -111,13 +111,13 @@ func (amw *instanceMiddleware) Middleware(next http.Handler) http.Handler { ctx := r.Context() authorizationHeader := r.Header.Get("authorization") if authorizationHeader == "" { - invalidAuthResponse(w) + invalidAuthResponse(ctx, w) return } bearerToken := strings.Split(authorizationHeader, " ") if len(bearerToken) != 2 { - invalidAuthResponse(w) + invalidAuthResponse(ctx, w) return } @@ -130,30 +130,30 @@ func (amw *instanceMiddleware) Middleware(next http.Handler) http.Handler { }) if err != nil { - invalidAuthResponse(w) + invalidAuthResponse(ctx, w) return } if !token.Valid { - invalidAuthResponse(w) + invalidAuthResponse(ctx, w) return } ctx, err = amw.claimsToContext(ctx, claims) if err != nil { - invalidAuthResponse(w) + invalidAuthResponse(ctx, w) return } if InstanceID(ctx) == "" { - invalidAuthResponse(w) + invalidAuthResponse(ctx, w) return } runnerStatus := InstanceRunnerStatus(ctx) if runnerStatus != params.RunnerInstalling && runnerStatus != params.RunnerPending { // Instances that have finished installing can no longer authenticate to the API - invalidAuthResponse(w) + invalidAuthResponse(ctx, w) return } diff --git a/auth/jwt.go b/auth/jwt.go index fb1833c6..8516a02f 100644 --- a/auth/jwt.go +++ b/auth/jwt.go @@ -18,7 +18,7 @@ import ( "context" "encoding/json" "fmt" - "log" + "log/slog" "net/http" "strings" @@ -73,14 +73,14 @@ func (amw *jwtMiddleware) claimsToContext(ctx context.Context, claims *JWTClaims return ctx, nil } -func invalidAuthResponse(w http.ResponseWriter) { +func invalidAuthResponse(ctx context.Context, w http.ResponseWriter) { w.Header().Add("Content-Type", "application/json") w.WriteHeader(http.StatusUnauthorized) if err := json.NewEncoder(w).Encode( apiParams.APIErrorResponse{ Error: "Authentication failed", }); err != nil { - log.Printf("failed to encode response: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to encode response") } } @@ -91,13 +91,13 @@ func (amw *jwtMiddleware) Middleware(next http.Handler) http.Handler { ctx := r.Context() authorizationHeader := r.Header.Get("authorization") if authorizationHeader == "" { - invalidAuthResponse(w) + invalidAuthResponse(ctx, w) return } bearerToken := strings.Split(authorizationHeader, " ") if len(bearerToken) != 2 { - invalidAuthResponse(w) + invalidAuthResponse(ctx, w) return } @@ -110,22 +110,22 @@ func (amw *jwtMiddleware) Middleware(next http.Handler) http.Handler { }) if err != nil { - invalidAuthResponse(w) + invalidAuthResponse(ctx, w) return } if !token.Valid { - invalidAuthResponse(w) + invalidAuthResponse(ctx, w) return } ctx, err = amw.claimsToContext(ctx, claims) if err != nil { - invalidAuthResponse(w) + invalidAuthResponse(ctx, w) return } if !IsEnabled(ctx) { - invalidAuthResponse(w) + invalidAuthResponse(ctx, w) return } diff --git a/auth/metrics.go b/auth/metrics.go index 7494fe2f..3be4577a 100644 --- a/auth/metrics.go +++ b/auth/metrics.go @@ -27,13 +27,13 @@ func (m *MetricsMiddleware) Middleware(next http.Handler) http.Handler { ctx := r.Context() authorizationHeader := r.Header.Get("authorization") if authorizationHeader == "" { - invalidAuthResponse(w) + invalidAuthResponse(ctx, w) return } bearerToken := strings.Split(authorizationHeader, " ") if len(bearerToken) != 2 { - invalidAuthResponse(w) + invalidAuthResponse(ctx, w) return } @@ -46,18 +46,18 @@ func (m *MetricsMiddleware) Middleware(next http.Handler) http.Handler { }) if err != nil { - invalidAuthResponse(w) + invalidAuthResponse(ctx, w) return } if !token.Valid { - invalidAuthResponse(w) + invalidAuthResponse(ctx, w) return } // we fully trust the claims if !claims.ReadMetrics { - invalidAuthResponse(w) + invalidAuthResponse(ctx, w) return } diff --git a/cmd/garm-cli/cmd/log.go b/cmd/garm-cli/cmd/log.go index 9e6669ce..c8e61fa0 100644 --- a/cmd/garm-cli/cmd/log.go +++ b/cmd/garm-cli/cmd/log.go @@ -4,6 +4,7 @@ import ( "encoding/json" "fmt" "log" + "log/slog" "net/http" "net/url" "os" @@ -36,7 +37,7 @@ var logCmd = &cobra.Command{ wsScheme = "wss" } u := url.URL{Scheme: wsScheme, Host: parsedURL.Host, Path: "/api/v1/ws"} - log.Printf("connecting to %s", u.String()) + slog.Debug("connecting", "url", u.String()) header := http.Header{} header.Add("Authorization", fmt.Sprintf("Bearer %s", mgr.Token)) @@ -59,10 +60,10 @@ var logCmd = &cobra.Command{ for { _, message, err := c.ReadMessage() if err != nil { - log.Printf("read: %q", err) + slog.With(slog.Any("error", err)).Error("reading log message") return } - log.Print(util.SanitizeLogEntry(string(message))) + fmt.Print(util.SanitizeLogEntry(string(message))) } }() diff --git a/cmd/garm/main.go b/cmd/garm/main.go index 5399fee0..217ba994 100644 --- a/cmd/garm/main.go +++ b/cmd/garm/main.go @@ -20,6 +20,7 @@ import ( "fmt" "io" "log" + "log/slog" "net" "net/http" "os" @@ -36,6 +37,7 @@ import ( "github.com/cloudbase/garm/database/common" "github.com/cloudbase/garm/metrics" "github.com/cloudbase/garm/runner" + garmUtil "github.com/cloudbase/garm/util" "github.com/cloudbase/garm/util/appdefaults" "github.com/cloudbase/garm/websocket" lumberjack "gopkg.in/natefinch/lumberjack.v2" @@ -69,22 +71,9 @@ func maybeInitController(db common.Store) error { return nil } -func main() { - flag.Parse() - if *version { - fmt.Println(Version) - return - } - ctx, stop := signal.NotifyContext(context.Background(), signals...) - defer stop() - fmt.Println(ctx) - - cfg, err := config.NewConfig(*conf) - if err != nil { - log.Fatalf("Fetching config: %+v", err) - } - - logWriter, err := util.GetLoggingWriter(cfg.Default.LogFile) +func setupLogging(ctx context.Context, cfg *config.Config, hub *websocket.Hub) { + logCfg := cfg.GetLoggingConfig() + logWriter, err := util.GetLoggingWriter(logCfg.LogFile) if err != nil { log.Fatalf("fetching log writer: %+v", err) } @@ -102,7 +91,7 @@ func main() { // we got a SIGHUP. Rotate log file. if logger, ok := logWriter.(*lumberjack.Logger); ok { if err := logger.Rotate(); err != nil { - log.Printf("failed to rotate log file: %v", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to rotate log file") } } } @@ -112,18 +101,72 @@ func main() { var writers []io.Writer = []io.Writer{ logWriter, } + + if hub != nil { + writers = append(writers, hub) + } + + wr := io.MultiWriter(writers...) + + var logLevel slog.Level + switch logCfg.LogLevel { + case config.LevelDebug: + logLevel = slog.LevelDebug + case config.LevelInfo: + logLevel = slog.LevelInfo + case config.LevelWarn: + logLevel = slog.LevelWarn + case config.LevelError: + logLevel = slog.LevelError + default: + logLevel = slog.LevelInfo + } + + // logger options + opts := slog.HandlerOptions{ + AddSource: logCfg.LogSource, + Level: logLevel, + } + + var han slog.Handler + switch logCfg.LogFormat { + case config.FormatJSON: + han = slog.NewJSONHandler(wr, &opts) + default: + han = slog.NewTextHandler(wr, &opts) + } + + wrapped := garmUtil.ContextHandler{ + Handler: han, + } + slog.SetDefault(slog.New(wrapped)) + +} + +func main() { + flag.Parse() + if *version { + fmt.Println(Version) + return + } + ctx, stop := signal.NotifyContext(context.Background(), signals...) + defer stop() + + cfg, err := config.NewConfig(*conf) + if err != nil { + log.Fatalf("Fetching config: %+v", err) + } + var hub *websocket.Hub - if cfg.Default.EnableLogStreamer { + if cfg.Default.EnableLogStreamer != nil && *cfg.Default.EnableLogStreamer { hub = websocket.NewHub(ctx) if err := hub.Start(); err != nil { log.Fatal(err) } defer hub.Stop() //nolint - writers = append(writers, hub) } - multiWriter := io.MultiWriter(writers...) - log.SetOutput(multiWriter) + setupLogging(ctx, cfg, hub) db, err := database.NewDatabase(ctx, cfg.Database) if err != nil { @@ -170,19 +213,19 @@ func main() { log.Fatal(err) } - router := routers.NewAPIRouter(controller, multiWriter, jwtMiddleware, initMiddleware, instanceMiddleware, cfg.Default.EnableWebhookManagement) + router := routers.NewAPIRouter(controller, jwtMiddleware, initMiddleware, instanceMiddleware, cfg.Default.EnableWebhookManagement) if cfg.Metrics.Enable { - log.Printf("registering prometheus metrics collectors") + slog.InfoContext(ctx, "registering prometheus metrics collectors") if err := metrics.RegisterCollectors(runner); err != nil { log.Fatal(err) } - log.Printf("setting up metric routes") + slog.InfoContext(ctx, "setting up metric routes") router = routers.WithMetricsRouter(router, cfg.Metrics.DisableAuth, metricsMiddleware) } if cfg.Default.DebugServer { - log.Printf("setting up debug routes") + slog.InfoContext(ctx, "setting up debug routes") router = routers.WithDebugServer(router) } @@ -207,11 +250,11 @@ func main() { go func() { if cfg.APIServer.UseTLS { if err := srv.ServeTLS(listener, cfg.APIServer.TLSConfig.CRT, cfg.APIServer.TLSConfig.Key); err != nil { - log.Printf("Listening: %+v", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "Listening") } } else { if err := srv.Serve(listener); err != http.ErrServerClosed { - log.Printf("Listening: %+v", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "Listening") } } }() @@ -220,12 +263,12 @@ func main() { shutdownCtx, shutdownCancel := context.WithTimeout(context.Background(), 60*time.Second) defer shutdownCancel() if err := srv.Shutdown(shutdownCtx); err != nil { - log.Printf("graceful api server shutdown failed: %+v", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "graceful api server shutdown failed") } - log.Printf("waiting for runner to stop") + slog.With(slog.Any("error", err)).ErrorContext(ctx, "waiting for runner to stop") if err := runner.Wait(); err != nil { - log.Printf("failed to shutdown workers: %+v", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to shutdown workers") os.Exit(1) } } diff --git a/config/config.go b/config/config.go index 89335306..26505ae3 100644 --- a/config/config.go +++ b/config/config.go @@ -18,7 +18,7 @@ import ( "crypto/tls" "crypto/x509" "fmt" - "log" + "log/slog" "net" "net/url" "os" @@ -33,6 +33,8 @@ import ( ) type DBBackendType string +type LogLevel string +type LogFormat string const ( // MySQLBackend represents the MySQL DB backend @@ -44,6 +46,24 @@ const ( EnvironmentVariablePrefix = "GARM" ) +const ( + // LevelDebug is the debug log level + LevelDebug LogLevel = "debug" + // LevelInfo is the info log level + LevelInfo LogLevel = "info" + // LevelWarn is the warn log level + LevelWarn LogLevel = "warn" + // LevelError is the error log level + LevelError LogLevel = "error" +) + +const ( + // FormatText is the text log format + FormatText LogFormat = "text" + // FormatJSON is the json log format + FormatJSON LogFormat = "json" +) + // NewConfig returns a new Config func NewConfig(cfgFile string) (*Config, error) { var config Config @@ -64,6 +84,7 @@ type Config struct { Providers []Provider `toml:"provider,omitempty" json:"provider,omitempty"` Github []Github `toml:"github,omitempty"` JWTAuth JWTAuth `toml:"jwt_auth" json:"jwt-auth"` + Logging Logging `toml:"logging" json:"logging"` } // Validate validates the config @@ -89,6 +110,10 @@ func (c *Config) Validate() error { return errors.Wrap(err, "validating jwt config") } + if err := c.Logging.Validate(); err != nil { + return errors.Wrap(err, "validating logging config") + } + providerNames := map[string]int{} for _, provider := range c.Providers { @@ -107,6 +132,52 @@ func (c *Config) Validate() error { return nil } +func (c *Config) GetLoggingConfig() Logging { + logging := c.Logging + if logging.LogFormat == "" { + logging.LogFormat = FormatText + } + + if logging.LogLevel == "" { + logging.LogLevel = LevelInfo + } + + // maintain backwards compatibility + if logging.LogFile == "" && c.Default.LogFile != "" { + logging.LogFile = c.Default.LogFile + } + if logging.EnableLogStreamer == nil && c.Default.EnableLogStreamer != nil { + logging.EnableLogStreamer = c.Default.EnableLogStreamer + } + + return logging +} + +type Logging struct { + // LogFile is the location of the log file. + LogFile string `toml:"log_file,omitempty" json:"log-file"` + // EnableLogStreamer enables the log streamer over websockets. + EnableLogStreamer *bool `toml:"enable_log_streamer,omitempty" json:"enable-log-streamer,omitempty"` + // LogLevel is the log level. + LogLevel LogLevel `toml:"log_level" json:"log-format"` + // LogFormat is the log format. + LogFormat LogFormat `toml:"log_format" json:"log-level"` + // LogSource enables the log source. + LogSource bool `toml:"log_source" json:"log-source"` +} + +func (l *Logging) Validate() error { + if l.LogLevel != LevelDebug && l.LogLevel != LevelInfo && l.LogLevel != LevelWarn && l.LogLevel != LevelError && l.LogLevel != "" { + return fmt.Errorf("invalid log level: %s", l.LogLevel) + } + + if l.LogFormat != FormatText && l.LogFormat != FormatJSON && l.LogFormat != "" { + return fmt.Errorf("invalid log format: %s", l.LogFormat) + } + + return nil +} + type Default struct { // CallbackURL is the URL where the instances can send back status reports. CallbackURL string `toml:"callback_url" json:"callback-url"` @@ -120,7 +191,7 @@ type Default struct { // LogFile is the location of the log file. LogFile string `toml:"log_file,omitempty" json:"log-file"` - EnableLogStreamer bool `toml:"enable_log_streamer"` + EnableLogStreamer *bool `toml:"enable_log_streamer,omitempty" json:"enable-log-streamer,omitempty"` DebugServer bool `toml:"debug_server" json:"debug-server"` } @@ -438,7 +509,7 @@ func (d *timeToLive) ParseDuration() (time.Duration, error) { func (d *timeToLive) Duration() time.Duration { duration, err := d.ParseDuration() if err != nil { - log.Printf("failed to parse duration: %s", err) + slog.With(slog.Any("error", err)).Error("failed to parse duration") return appdefaults.DefaultJWTTTL } // TODO(gabriel-samfira): should we have a minimum TTL? diff --git a/database/sql/jobs.go b/database/sql/jobs.go index 1d050f01..e0ed7ef8 100644 --- a/database/sql/jobs.go +++ b/database/sql/jobs.go @@ -3,7 +3,7 @@ package sql import ( "context" "encoding/json" - "log" + "log/slog" runnerErrors "github.com/cloudbase/garm-provider-common/errors" "github.com/cloudbase/garm/database/common" @@ -53,7 +53,7 @@ func sqlWorkflowJobToParamsJob(job WorkflowJob) (params.Job, error) { return jobParam, nil } -func (s *sqlDatabase) paramsJobToWorkflowJob(job params.Job) (WorkflowJob, error) { +func (s *sqlDatabase) paramsJobToWorkflowJob(ctx context.Context, job params.Job) (WorkflowJob, error) { asJson, err := json.Marshal(job.Labels) if err != nil { return WorkflowJob{}, errors.Wrap(err, "marshaling labels") @@ -83,7 +83,7 @@ func (s *sqlDatabase) paramsJobToWorkflowJob(job params.Job) (WorkflowJob, error if job.RunnerName != "" { instance, err := s.getInstanceByName(s.ctx, job.RunnerName) if err != nil { - log.Printf("failed to get instance by name: %v", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to get instance by name") } else { workflofJob.InstanceID = &instance.ID } @@ -218,7 +218,7 @@ func (s *sqlDatabase) CreateOrUpdateJob(ctx context.Context, job params.Job) (pa if err == nil { workflowJob.InstanceID = &instance.ID } else { - log.Printf("failed to get instance by name: %v", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to get instance by name") } } @@ -237,7 +237,7 @@ func (s *sqlDatabase) CreateOrUpdateJob(ctx context.Context, job params.Job) (pa return params.Job{}, errors.Wrap(err, "saving job") } } else { - workflowJob, err := s.paramsJobToWorkflowJob(job) + workflowJob, err := s.paramsJobToWorkflowJob(ctx, job) if err != nil { return params.Job{}, errors.Wrap(err, "converting job") } diff --git a/database/sql/sql.go b/database/sql/sql.go index 47c6ef02..e513be42 100644 --- a/database/sql/sql.go +++ b/database/sql/sql.go @@ -17,7 +17,7 @@ package sql import ( "context" "fmt" - "log" + "log/slog" "strings" "github.com/pkg/errors" @@ -151,7 +151,7 @@ func (s *sqlDatabase) cascadeMigrationSQLite(model interface{}, name string, jus if model != nil { if err := s.conn.Migrator().AutoMigrate(model); err != nil { if err := s.conn.Exec(fmt.Sprintf(restoreNameTemplate, name, name, name)).Error; err != nil { - log.Printf("failed to restore table %s: %s", name, err) + slog.With(slog.Any("error", err)).Error("failed to restore table", "table", name) } return fmt.Errorf("failed to create table %s: %w", name, err) } @@ -193,13 +193,13 @@ func (s *sqlDatabase) cascadeMigration() error { func (s *sqlDatabase) migrateDB() error { if s.conn.Migrator().HasIndex(&Organization{}, "idx_organizations_name") { if err := s.conn.Migrator().DropIndex(&Organization{}, "idx_organizations_name"); err != nil { - log.Printf("failed to drop index idx_organizations_name: %s", err) + slog.With(slog.Any("error", err)).Error("failed to drop index idx_organizations_name") } } if s.conn.Migrator().HasIndex(&Repository{}, "idx_owner") { if err := s.conn.Migrator().DropIndex(&Repository{}, "idx_owner"); err != nil { - log.Printf("failed to drop index idx_owner: %s", err) + slog.With(slog.Any("error", err)).Error("failed to drop index idx_owner") } } diff --git a/go.mod b/go.mod index 89a019c7..04ff9ec1 100644 --- a/go.mod +++ b/go.mod @@ -5,6 +5,7 @@ go 1.21 require ( github.com/BurntSushi/toml v1.3.2 github.com/cloudbase/garm-provider-common v0.1.1 + github.com/felixge/httpsnoop v1.0.4 github.com/go-openapi/errors v0.21.0 github.com/go-openapi/runtime v0.26.2 github.com/go-openapi/strfmt v0.21.10 @@ -41,7 +42,6 @@ require ( github.com/cespare/xxhash/v2 v2.2.0 // indirect github.com/chzyer/readline v1.5.1 // indirect github.com/davecgh/go-spew v1.1.1 // indirect - github.com/felixge/httpsnoop v1.0.4 // indirect github.com/go-logr/logr v1.3.0 // indirect github.com/go-logr/stdr v1.2.2 // indirect github.com/go-openapi/analysis v0.21.5 // indirect diff --git a/metrics/enterprise.go b/metrics/enterprise.go index 53ddfc5e..ddba98aa 100644 --- a/metrics/enterprise.go +++ b/metrics/enterprise.go @@ -1,7 +1,7 @@ package metrics import ( - "log" + "log/slog" "strconv" "github.com/cloudbase/garm/auth" @@ -14,7 +14,7 @@ func (c *GarmCollector) CollectEnterpriseMetric(ch chan<- prometheus.Metric, hos enterprises, err := c.runner.ListEnterprises(ctx) if err != nil { - log.Printf("listing providers: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing providers") return } @@ -28,7 +28,7 @@ func (c *GarmCollector) CollectEnterpriseMetric(ch chan<- prometheus.Metric, hos enterprise.ID, // label: id ) if err != nil { - log.Printf("cannot collect enterpriseInfo metric: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "cannot collect enterpriseInfo metric") continue } ch <- enterpriseInfo @@ -42,7 +42,7 @@ func (c *GarmCollector) CollectEnterpriseMetric(ch chan<- prometheus.Metric, hos strconv.FormatBool(enterprise.PoolManagerStatus.IsRunning), // label: running ) if err != nil { - log.Printf("cannot collect enterprisePoolManagerStatus metric: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "cannot collect enterprisePoolManagerStatus metric") continue } ch <- enterprisePoolManagerStatus diff --git a/metrics/health.go b/metrics/health.go index 4cc9e83a..da4b67dc 100644 --- a/metrics/health.go +++ b/metrics/health.go @@ -1,7 +1,7 @@ package metrics import ( - "log" + "log/slog" "github.com/prometheus/client_golang/prometheus" ) @@ -15,7 +15,7 @@ func (c *GarmCollector) CollectHealthMetric(ch chan<- prometheus.Metric, hostnam controllerID, ) if err != nil { - log.Printf("error on creating health metric: %s", err) + slog.With(slog.Any("error", err)).Error("error on creating health metric") return } ch <- m diff --git a/metrics/instance.go b/metrics/instance.go index 8bf234c4..d89409ed 100644 --- a/metrics/instance.go +++ b/metrics/instance.go @@ -1,7 +1,7 @@ package metrics import ( - "log" + "log/slog" "github.com/cloudbase/garm/auth" "github.com/prometheus/client_golang/prometheus" @@ -14,13 +14,13 @@ func (c *GarmCollector) CollectInstanceMetric(ch chan<- prometheus.Metric, hostn instances, err := c.runner.ListAllInstances(ctx) if err != nil { - log.Printf("cannot collect metrics, listing instances: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "cannot collect metrics, listing instances") return } pools, err := c.runner.ListAllPools(ctx) if err != nil { - log.Printf("listing pools: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing pools") return } @@ -71,7 +71,7 @@ func (c *GarmCollector) CollectInstanceMetric(ch chan<- prometheus.Metric, hostn ) if err != nil { - log.Printf("cannot collect runner metric: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "cannot collect runner metric") continue } ch <- m diff --git a/metrics/metrics.go b/metrics/metrics.go index 1032a88f..61d02015 100644 --- a/metrics/metrics.go +++ b/metrics/metrics.go @@ -1,7 +1,7 @@ package metrics import ( - "log" + "log/slog" "github.com/cloudbase/garm/auth" "github.com/cloudbase/garm/params" @@ -192,7 +192,7 @@ func (c *GarmCollector) Describe(ch chan<- *prometheus.Desc) { func (c *GarmCollector) Collect(ch chan<- prometheus.Metric) { controllerInfo, err := c.runner.GetControllerInfo(auth.GetAdminContext()) if err != nil { - log.Printf("failed to get controller info: %s", err) + slog.With(slog.Any("error", err)).Error("failed to get controller info") return } diff --git a/metrics/organization.go b/metrics/organization.go index b5c57f08..e5ea8292 100644 --- a/metrics/organization.go +++ b/metrics/organization.go @@ -1,7 +1,7 @@ package metrics import ( - "log" + "log/slog" "strconv" "github.com/cloudbase/garm/auth" @@ -14,7 +14,7 @@ func (c *GarmCollector) CollectOrganizationMetric(ch chan<- prometheus.Metric, h organizations, err := c.runner.ListOrganizations(ctx) if err != nil { - log.Printf("listing providers: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing providers") return } @@ -28,7 +28,7 @@ func (c *GarmCollector) CollectOrganizationMetric(ch chan<- prometheus.Metric, h organization.ID, // label: id ) if err != nil { - log.Printf("cannot collect organizationInfo metric: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "cannot collect organizationInfo metric") continue } ch <- organizationInfo @@ -42,7 +42,7 @@ func (c *GarmCollector) CollectOrganizationMetric(ch chan<- prometheus.Metric, h strconv.FormatBool(organization.PoolManagerStatus.IsRunning), // label: running ) if err != nil { - log.Printf("cannot collect organizationPoolManagerStatus metric: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "cannot collect organizationPoolManagerStatus metric") continue } ch <- organizationPoolManagerStatus diff --git a/metrics/pool.go b/metrics/pool.go index deefd06e..110812bd 100644 --- a/metrics/pool.go +++ b/metrics/pool.go @@ -1,7 +1,7 @@ package metrics import ( - "log" + "log/slog" "strconv" "strings" @@ -15,7 +15,7 @@ func (c *GarmCollector) CollectPoolMetric(ch chan<- prometheus.Metric, hostname pools, err := c.runner.ListAllPools(ctx) if err != nil { - log.Printf("listing pools: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing pools") return } @@ -64,7 +64,7 @@ func (c *GarmCollector) CollectPoolMetric(ch chan<- prometheus.Metric, hostname poolNames[pool.ID].Type, // label: pool_type ) if err != nil { - log.Printf("cannot collect poolInfo metric: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "cannot collect poolInfo metric") continue } ch <- poolInfo @@ -77,7 +77,7 @@ func (c *GarmCollector) CollectPoolMetric(ch chan<- prometheus.Metric, hostname strconv.FormatBool(pool.Enabled), // label: enabled ) if err != nil { - log.Printf("cannot collect poolStatus metric: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "cannot collect poolStatus metric") continue } ch <- poolStatus @@ -89,7 +89,7 @@ func (c *GarmCollector) CollectPoolMetric(ch chan<- prometheus.Metric, hostname pool.ID, // label: id ) if err != nil { - log.Printf("cannot collect poolMaxRunners metric: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "cannot collect poolMaxRunners metric") continue } ch <- poolMaxRunners @@ -101,7 +101,7 @@ func (c *GarmCollector) CollectPoolMetric(ch chan<- prometheus.Metric, hostname pool.ID, // label: id ) if err != nil { - log.Printf("cannot collect poolMinIdleRunners metric: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "cannot collect poolMinIdleRunners metric") continue } ch <- poolMinIdleRunners @@ -113,7 +113,7 @@ func (c *GarmCollector) CollectPoolMetric(ch chan<- prometheus.Metric, hostname pool.ID, // label: id ) if err != nil { - log.Printf("cannot collect poolBootstrapTimeout metric: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "cannot collect poolBootstrapTimeout metric") continue } ch <- poolBootstrapTimeout diff --git a/metrics/provider.go b/metrics/provider.go index e2e903f3..e51f295e 100644 --- a/metrics/provider.go +++ b/metrics/provider.go @@ -1,7 +1,7 @@ package metrics import ( - "log" + "log/slog" "github.com/cloudbase/garm/auth" "github.com/prometheus/client_golang/prometheus" @@ -13,7 +13,7 @@ func (c *GarmCollector) CollectProviderMetric(ch chan<- prometheus.Metric, hostn providers, err := c.runner.ListProviders(ctx) if err != nil { - log.Printf("listing providers: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing providers") return } @@ -28,7 +28,7 @@ func (c *GarmCollector) CollectProviderMetric(ch chan<- prometheus.Metric, hostn provider.Description, // label: description ) if err != nil { - log.Printf("cannot collect providerInfo metric: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "cannot collect providerInfo metric") continue } ch <- providerInfo diff --git a/metrics/repository.go b/metrics/repository.go index 4d0f3d78..b778782e 100644 --- a/metrics/repository.go +++ b/metrics/repository.go @@ -1,7 +1,7 @@ package metrics import ( - "log" + "log/slog" "strconv" "github.com/cloudbase/garm/auth" @@ -14,7 +14,7 @@ func (c *GarmCollector) CollectRepositoryMetric(ch chan<- prometheus.Metric, hos repositories, err := c.runner.ListRepositories(ctx) if err != nil { - log.Printf("listing providers: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "listing providers") return } @@ -29,7 +29,7 @@ func (c *GarmCollector) CollectRepositoryMetric(ch chan<- prometheus.Metric, hos repository.ID, // label: id ) if err != nil { - log.Printf("cannot collect repositoryInfo metric: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "cannot collect repositoryInfo metric") continue } ch <- repositoryInfo @@ -43,7 +43,7 @@ func (c *GarmCollector) CollectRepositoryMetric(ch chan<- prometheus.Metric, hos strconv.FormatBool(repository.PoolManagerStatus.IsRunning), // label: running ) if err != nil { - log.Printf("cannot collect repositoryPoolManagerStatus metric: %s", err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "cannot collect repositoryPoolManagerStatus metric") continue } ch <- repositoryPoolManagerStatus diff --git a/runner/enterprises.go b/runner/enterprises.go index b86a4284..cf2ca46e 100644 --- a/runner/enterprises.go +++ b/runner/enterprises.go @@ -3,7 +3,7 @@ package runner import ( "context" "fmt" - "log" + "log/slog" "strings" runnerErrors "github.com/cloudbase/garm-provider-common/errors" @@ -47,7 +47,9 @@ func (r *Runner) CreateEnterprise(ctx context.Context, param params.CreateEnterp defer func() { if err != nil { if deleteErr := r.store.DeleteEnterprise(ctx, enterprise.ID); deleteErr != nil { - log.Printf("failed to delete enterprise: %s", deleteErr) + slog.With(slog.Any("error", deleteErr)).ErrorContext( + ctx, "failed to delete enterprise", + "enterprise_id", enterprise.ID) } } }() @@ -59,7 +61,9 @@ func (r *Runner) CreateEnterprise(ctx context.Context, param params.CreateEnterp } if err := poolMgr.Start(); err != nil { if deleteErr := r.poolManagerCtrl.DeleteEnterprisePoolManager(enterprise); deleteErr != nil { - log.Printf("failed to cleanup pool manager for enterprise %s", enterprise.ID) + slog.With(slog.Any("error", deleteErr)).ErrorContext( + ctx, "failed to cleanup pool manager for enterprise", + "enterprise_id", enterprise.ID) } return params.Enterprise{}, errors.Wrap(err, "starting enterprise pool manager") } diff --git a/runner/metadata.go b/runner/metadata.go index 7fa8f782..7890434e 100644 --- a/runner/metadata.go +++ b/runner/metadata.go @@ -6,7 +6,7 @@ import ( "encoding/base64" "fmt" "html/template" - "log" + "log/slog" "strings" "github.com/cloudbase/garm-provider-common/defaults" @@ -44,7 +44,6 @@ func validateInstanceState(ctx context.Context) (params.Instance, error) { instance, err := auth.InstanceParams(ctx) if err != nil { - log.Printf("failed to get instance params: %s", err) return params.Instance{}, runnerErrors.ErrUnauthorized } return instance, nil @@ -53,13 +52,16 @@ func validateInstanceState(ctx context.Context) (params.Instance, error) { func (r *Runner) GetRunnerServiceName(ctx context.Context) (string, error) { instance, err := validateInstanceState(ctx) if err != nil { - log.Printf("failed to get instance params: %s", err) + slog.With(slog.Any("error", err)).ErrorContext( + ctx, "failed to get instance params") return "", runnerErrors.ErrUnauthorized } pool, err := r.store.GetPoolByID(r.ctx, instance.PoolID) if err != nil { - log.Printf("failed to get pool: %s", err) + slog.With(slog.Any("error", err)).ErrorContext( + ctx, "failed to get pool", + "pool_id", instance.PoolID) return "", errors.Wrap(err, "fetching pool") } @@ -109,7 +111,8 @@ func (r *Runner) GenerateSystemdUnitFile(ctx context.Context, runAsUser string) func (r *Runner) GetJITConfigFile(ctx context.Context, file string) ([]byte, error) { instance, err := validateInstanceState(ctx) if err != nil { - log.Printf("failed to get instance params: %s", err) + slog.With(slog.Any("error", err)).ErrorContext( + ctx, "failed to get instance params") return nil, runnerErrors.ErrUnauthorized } jitConfig := instance.JitConfiguration @@ -142,7 +145,8 @@ func (r *Runner) GetInstanceGithubRegistrationToken(ctx context.Context) (string instance, err := auth.InstanceParams(ctx) if err != nil { - log.Printf("failed to get instance params: %s", err) + slog.With(slog.Any("error", err)).ErrorContext( + ctx, "failed to get instance params") return "", runnerErrors.ErrUnauthorized } @@ -175,7 +179,8 @@ func (r *Runner) GetInstanceGithubRegistrationToken(ctx context.Context) (string func (r *Runner) GetRootCertificateBundle(ctx context.Context) (params.CertificateBundle, error) { instance, err := auth.InstanceParams(ctx) if err != nil { - log.Printf("failed to get instance params: %s", err) + slog.With(slog.Any("error", err)).ErrorContext( + ctx, "failed to get instance params") return params.CertificateBundle{}, runnerErrors.ErrUnauthorized } @@ -186,7 +191,10 @@ func (r *Runner) GetRootCertificateBundle(ctx context.Context) (params.Certifica bundle, err := poolMgr.RootCABundle() if err != nil { - log.Printf("failed to get root CA bundle: %s", err) + slog.With(slog.Any("error", err)).ErrorContext( + ctx, "failed to get root CA bundle", + "instance", instance.Name, + "pool_manager", poolMgr.ID()) // The root CA bundle is invalid. Return an empty bundle to the runner and log the event. return params.CertificateBundle{ RootCertificates: make(map[string][]byte), diff --git a/runner/organizations.go b/runner/organizations.go index 8e8c2a70..c86af1fb 100644 --- a/runner/organizations.go +++ b/runner/organizations.go @@ -17,7 +17,7 @@ package runner import ( "context" "fmt" - "log" + "log/slog" "strings" runnerErrors "github.com/cloudbase/garm-provider-common/errors" @@ -60,7 +60,9 @@ func (r *Runner) CreateOrganization(ctx context.Context, param params.CreateOrgP defer func() { if err != nil { if deleteErr := r.store.DeleteOrganization(ctx, org.ID); deleteErr != nil { - log.Printf("failed to delete org: %s", deleteErr) + slog.With(slog.Any("error", deleteErr)).ErrorContext( + ctx, "failed to delete org", + "org_id", org.ID) } } }() @@ -71,7 +73,9 @@ func (r *Runner) CreateOrganization(ctx context.Context, param params.CreateOrgP } if err := poolMgr.Start(); err != nil { if deleteErr := r.poolManagerCtrl.DeleteOrgPoolManager(org); deleteErr != nil { - log.Printf("failed to cleanup pool manager for org %s", org.ID) + slog.With(slog.Any("error", deleteErr)).ErrorContext( + ctx, "failed to cleanup pool manager for org", + "org_id", org.ID) } return params.Organization{}, errors.Wrap(err, "starting org pool manager") } @@ -156,7 +160,9 @@ func (r *Runner) DeleteOrganization(ctx context.Context, orgID string, keepWebho if err := poolMgr.UninstallWebhook(ctx); err != nil { // TODO(gabriel-samfira): Should we error out here? - log.Printf("failed to uninstall webhook: %s", err) + slog.With(slog.Any("error", err)).ErrorContext( + ctx, "failed to uninstall webhook", + "org_id", org.ID) } } diff --git a/runner/pool/enterprise.go b/runner/pool/enterprise.go index 05911e4a..f03947b5 100644 --- a/runner/pool/enterprise.go +++ b/runner/pool/enterprise.go @@ -5,7 +5,7 @@ import ( "encoding/base64" "encoding/json" "fmt" - "log" + "log/slog" "net/http" "strings" "sync" @@ -25,6 +25,7 @@ import ( var _ poolHelper = &enterprise{} func NewEnterprisePoolManager(ctx context.Context, cfg params.Enterprise, cfgInternal params.Internal, providers map[string]common.Provider, store dbCommon.Store) (common.PoolManager, error) { + ctx = util.WithContext(ctx, slog.Any("pool_mgr", cfg.Name), slog.Any("pool_type", params.EnterprisePool)) ghc, ghEnterpriseClient, err := util.GithubClient(ctx, cfgInternal.OAuth2Token, cfgInternal.GithubCredentialsDetails) if err != nil { return nil, errors.Wrap(err, "getting github client") @@ -134,7 +135,9 @@ func (r *enterprise) GetJITConfig(ctx context.Context, instance string, pool par defer func() { if err != nil && runner != nil { _, innerErr := r.ghcEnterpriseCli.RemoveRunner(r.ctx, r.cfg.Name, runner.GetID()) - log.Printf("failed to remove runner: %v", innerErr) + slog.With(slog.Any("error", innerErr)).ErrorContext( + ctx, "failed to remove runner", + "runner_id", runner.GetID(), "organization", r.cfg.Name) } }() diff --git a/runner/pool/organization.go b/runner/pool/organization.go index 4a88443d..0f534508 100644 --- a/runner/pool/organization.go +++ b/runner/pool/organization.go @@ -19,7 +19,7 @@ import ( "encoding/base64" "encoding/json" "fmt" - "log" + "log/slog" "net/http" "strings" "sync" @@ -39,6 +39,7 @@ import ( var _ poolHelper = &organization{} func NewOrganizationPoolManager(ctx context.Context, cfg params.Organization, cfgInternal params.Internal, providers map[string]common.Provider, store dbCommon.Store) (common.PoolManager, error) { + ctx = util.WithContext(ctx, slog.Any("pool_mgr", cfg.Name), slog.Any("pool_type", params.OrganizationPool)) ghc, _, err := util.GithubClient(ctx, cfgInternal.OAuth2Token, cfgInternal.GithubCredentialsDetails) if err != nil { return nil, errors.Wrap(err, "getting github client") @@ -146,7 +147,9 @@ func (r *organization) GetJITConfig(ctx context.Context, instance string, pool p defer func() { if err != nil && runner != nil { _, innerErr := r.ghcli.RemoveOrganizationRunner(r.ctx, r.cfg.Name, runner.GetID()) - log.Printf("failed to remove runner: %v", innerErr) + slog.With(slog.Any("error", innerErr)).ErrorContext( + ctx, "failed to remove runner", + "runner_id", runner.GetID(), "organization", r.cfg.Name) } }() @@ -369,7 +372,7 @@ func (r *organization) InstallHook(ctx context.Context, req *github.Hook) (param } if _, err := r.ghcli.PingOrgHook(ctx, r.cfg.Name, hook.GetID()); err != nil { - log.Printf("failed to ping hook %d: %v", *hook.ID, err) + slog.With(slog.Any("error", err)).ErrorContext(ctx, "failed to ping hook", "hook_id", hook.GetID()) } return hookToParamsHookInfo(hook), nil diff --git a/runner/pool/pool.go b/runner/pool/pool.go index 77fe515e..b7b48281 100644 --- a/runner/pool/pool.go +++ b/runner/pool/pool.go @@ -17,7 +17,7 @@ package pool import ( "context" "fmt" - "log" + "log/slog" "math" "net/http" "strconv" @@ -134,23 +134,30 @@ func (r *basePoolManager) HandleWorkflowJob(job params.WorkflowJob) error { _, err := r.store.GetJobByID(r.ctx, jobParams.ID) if err != nil { if !errors.Is(err, runnerErrors.ErrNotFound) { - r.log("failed to get job %d: %s", jobParams.ID, err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to get job", + "job_id", jobParams.ID) return } // This job is new to us. Check if we have a pool that can handle it. potentialPools, err := r.store.FindPoolsMatchingAllTags(r.ctx, r.helper.PoolType(), r.helper.ID(), jobParams.Labels) if err != nil { - r.log("failed to find pools matching tags %s: %s; not recording job", strings.Join(jobParams.Labels, ", "), err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to find pools matching tags; not recording job", + "requested_tags", strings.Join(jobParams.Labels, ", ")) return } if len(potentialPools) == 0 { - r.log("no pools matching tags %s; not recording job", strings.Join(jobParams.Labels, ", ")) + slog.WarnContext( + r.ctx, "no pools matching tags; not recording job", + "requested_tags", strings.Join(jobParams.Labels, ", ")) return } } if _, jobErr := r.store.CreateOrUpdateJob(r.ctx, jobParams); jobErr != nil { - r.log("failed to update job %d: %s", jobParams.ID, jobErr) + slog.With(slog.Any("error", jobErr)).ErrorContext( + r.ctx, "failed to update job", "job_id", jobParams.ID) } if triggeredBy != 0 && jobParams.ID != triggeredBy { @@ -159,7 +166,9 @@ func (r *basePoolManager) HandleWorkflowJob(job params.WorkflowJob) error { // still queued and we don't remove the lock, it will linger until the lock timeout is reached. // That may take a long time, so we break the lock here and allow it to be scheduled again. if err := r.store.BreakLockJobIsQueued(r.ctx, triggeredBy); err != nil { - r.log("failed to break lock for job %d: %s", triggeredBy, err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to break lock for job", + "job_id", triggeredBy) } } }() @@ -189,15 +198,21 @@ func (r *basePoolManager) HandleWorkflowJob(job params.WorkflowJob) error { if errors.Is(err, runnerErrors.ErrNotFound) { return nil } - r.log("failed to update runner %s status: %s", util.SanitizeLogEntry(jobParams.RunnerName), err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to update runner status", + "runner_name", util.SanitizeLogEntry(jobParams.RunnerName)) return errors.Wrap(err, "updating runner") } - r.log("marking instance %s as pending_delete", util.SanitizeLogEntry(jobParams.RunnerName)) + slog.DebugContext( + r.ctx, "marking instance as pending_delete", + "runner_name", util.SanitizeLogEntry(jobParams.RunnerName)) if _, err := r.setInstanceStatus(jobParams.RunnerName, commonParams.InstancePendingDelete, nil); err != nil { if errors.Is(err, runnerErrors.ErrNotFound) { return nil } - r.log("failed to update runner %s status: %s", util.SanitizeLogEntry(jobParams.RunnerName), err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to update runner status", + "runner_name", util.SanitizeLogEntry(jobParams.RunnerName)) return errors.Wrap(err, "updating runner") } case "in_progress": @@ -220,7 +235,9 @@ func (r *basePoolManager) HandleWorkflowJob(job params.WorkflowJob) error { if errors.Is(err, runnerErrors.ErrNotFound) { return nil } - r.log("failed to update runner %s status: %s", util.SanitizeLogEntry(jobParams.RunnerName), err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to update runner status", + "runner_name", util.SanitizeLogEntry(jobParams.RunnerName)) return errors.Wrap(err, "updating runner") } // Set triggeredBy here so we break the lock on any potential queued job. @@ -233,7 +250,9 @@ func (r *basePoolManager) HandleWorkflowJob(job params.WorkflowJob) error { return errors.Wrap(err, "getting pool") } if err := r.ensureIdleRunnersForOnePool(pool); err != nil { - r.log("error ensuring idle runners for pool %s: %s", pool.ID, err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "error ensuring idle runners for pool", + "pool_id", pool.ID) } } return nil @@ -253,12 +272,16 @@ func jobIdFromLabels(labels []string) int64 { } func (r *basePoolManager) startLoopForFunction(f func() error, interval time.Duration, name string, alwaysRun bool) { - r.log("starting %s loop for %s", name, r.helper.String()) + slog.InfoContext( + r.ctx, "starting loop for entity", + "loop_name", name) ticker := time.NewTicker(interval) r.wg.Add(1) defer func() { - r.log("%s loop exited for pool %s", name, r.helper.String()) + slog.InfoContext( + r.ctx, "pool loop exited", + "loop_name", name) ticker.Stop() r.wg.Done() }() @@ -273,7 +296,9 @@ func (r *basePoolManager) startLoopForFunction(f func() error, interval time.Dur select { case <-ticker.C: if err := f(); err != nil { - r.log("error in loop %s: %q", name, err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "error in loop", + "loop_name", name) if errors.Is(err, runnerErrors.ErrUnauthorized) { r.setPoolRunningState(false, err.Error()) } @@ -304,7 +329,8 @@ func (r *basePoolManager) updateTools() error { // Update tools cache. tools, err := r.helper.FetchTools() if err != nil { - r.log("failed to update tools for repo %s: %s", r.helper.String(), err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to update tools for repo") r.setPoolRunningState(false, err.Error()) r.waitForTimeoutOrCanceled(common.BackoffTimer) return fmt.Errorf("failed to update tools for repo %s: %w", r.helper.String(), err) @@ -313,7 +339,7 @@ func (r *basePoolManager) updateTools() error { r.tools = tools r.mux.Unlock() - r.log("successfully updated tools") + slog.DebugContext(r.ctx, "successfully updated tools") r.setPoolRunningState(true, "") return err } @@ -365,7 +391,9 @@ func (r *basePoolManager) cleanupOrphanedProviderRunners(runners []*github.Runne runnerNames := map[string]bool{} for _, run := range runners { if !r.isManagedRunner(labelsFromRunner(run)) { - r.log("runner %s is not managed by a pool belonging to %s", *run.Name, r.helper.String()) + slog.DebugContext( + r.ctx, "runner is not managed by a pool we manage", + "runner_name", run.GetName()) continue } runnerNames[*run.Name] = true @@ -374,7 +402,9 @@ func (r *basePoolManager) cleanupOrphanedProviderRunners(runners []*github.Runne for _, instance := range dbInstances { lockAcquired := r.keyMux.TryLock(instance.Name) if !lockAcquired { - r.log("failed to acquire lock for instance %s", instance.Name) + slog.DebugContext( + r.ctx, "failed to acquire lock for instance", + "runner_name", instance.Name) continue } defer r.keyMux.Unlock(instance.Name, false) @@ -397,21 +427,27 @@ func (r *basePoolManager) cleanupOrphanedProviderRunners(runners []*github.Runne case params.RunnerPending, params.RunnerInstalling: if time.Since(instance.UpdatedAt).Minutes() < float64(pool.RunnerTimeout()) { // runner is still installing. We give it a chance to finish. - r.log("runner %s is still installing, give it a chance to finish", instance.Name) + slog.DebugContext( + r.ctx, "runner is still installing, give it a chance to finish", + "runner_name", instance.Name) continue } } if time.Since(instance.UpdatedAt).Minutes() < 5 { // instance was updated recently. We give it a chance to register itself in github. - r.log("instance %s was updated recently, skipping check", instance.Name) + slog.DebugContext( + r.ctx, "instance was updated recently, skipping check", + "runner_name", instance.Name) continue } if ok := runnerNames[instance.Name]; !ok { // Set pending_delete on DB field. Allow consolidate() to remove it. if _, err := r.setInstanceStatus(instance.Name, commonParams.InstancePendingDelete, nil); err != nil { - r.log("failed to update runner %s status: %s", instance.Name, err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to update runner", + "runner_name", instance.Name) return errors.Wrap(err, "updating runner") } } @@ -431,17 +467,23 @@ func (r *basePoolManager) reapTimedOutRunners(runners []*github.Runner) error { runnersByName := map[string]*github.Runner{} for _, run := range runners { if !r.isManagedRunner(labelsFromRunner(run)) { - r.log("runner %s is not managed by a pool belonging to %s", *run.Name, r.helper.String()) + slog.DebugContext( + r.ctx, "runner is not managed by a pool we manage", + "runner_name", run.GetName()) continue } runnersByName[*run.Name] = run } for _, instance := range dbInstances { - r.log("attempting to lock instance %s", instance.Name) + slog.DebugContext( + r.ctx, "attempting to lock instance", + "runner_name", instance.Name) lockAcquired := r.keyMux.TryLock(instance.Name) if !lockAcquired { - r.log("failed to acquire lock for instance %s", instance.Name) + slog.DebugContext( + r.ctx, "failed to acquire lock for instance", + "runner_name", instance.Name) continue } defer r.keyMux.Unlock(instance.Name, false) @@ -460,9 +502,13 @@ func (r *basePoolManager) reapTimedOutRunners(runners []*github.Runner) error { // never started on the instance. // * A JIT config was created, but the runner never joined github. if runner, ok := runnersByName[instance.Name]; !ok || runner.GetStatus() == "offline" { - r.log("reaping timed-out/failed runner %s", instance.Name) + slog.InfoContext( + r.ctx, "reaping timed-out/failed runner", + "runner_name", instance.Name) if err := r.DeleteRunner(instance, false); err != nil { - r.log("failed to update runner %s status: %s", instance.Name, err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to update runner status", + "runner_name", instance.Name) return errors.Wrap(err, "updating runner") } } @@ -488,7 +534,9 @@ func (r *basePoolManager) cleanupOrphanedGithubRunners(runners []*github.Runner) g, ctx := errgroup.WithContext(r.ctx) for _, runner := range runners { if !r.isManagedRunner(labelsFromRunner(runner)) { - r.log("runner %s is not managed by a pool belonging to %s", *runner.Name, r.helper.String()) + slog.DebugContext( + r.ctx, "runner is not managed by a pool we manage", + "runner_name", runner.GetName()) continue } @@ -505,7 +553,9 @@ func (r *basePoolManager) cleanupOrphanedGithubRunners(runners []*github.Runner) } // We no longer have a DB entry for this instance, and the runner appears offline in github. // Previous forceful removal may have failed? - r.log("Runner %s has no database entry in garm, removing from github", *runner.Name) + slog.InfoContext( + r.ctx, "Runner has no database entry in garm, removing from github", + "runner_name", runner.GetName()) resp, err := r.helper.RemoveGithubRunner(*runner.ID) if err != nil { // Removed in the meantime? @@ -524,14 +574,18 @@ func (r *basePoolManager) cleanupOrphanedGithubRunners(runners []*github.Runner) continue case commonParams.InstancePendingCreate, commonParams.InstanceCreating: // instance is still being created. We give it a chance to finish. - r.log("instance %s is still being created, give it a chance to finish", dbInstance.Name) + slog.DebugContext( + r.ctx, "instance is still being created, give it a chance to finish", + "runner_name", dbInstance.Name) continue case commonParams.InstanceRunning: // this check is not strictly needed, but can help avoid unnecessary strain on the provider. // At worst, we will have a runner that is offline in github for 5 minutes before we reap it. if time.Since(dbInstance.UpdatedAt).Minutes() < 5 { // instance was updated recently. We give it a chance to register itself in github. - r.log("instance %s was updated recently, skipping check", dbInstance.Name) + slog.DebugContext( + r.ctx, "instance was updated recently, skipping check", + "runner_name", dbInstance.Name) continue } } @@ -550,7 +604,9 @@ func (r *basePoolManager) cleanupOrphanedGithubRunners(runners []*github.Runner) var poolInstances []commonParams.ProviderInstance poolInstances, ok = poolInstanceCache[pool.ID] if !ok { - r.log("updating instances cache for pool %s", pool.ID) + slog.DebugContext( + r.ctx, "updating instances cache for pool", + "pool_id", pool.ID) poolInstances, err = provider.ListInstances(r.ctx, pool.ID) if err != nil { return errors.Wrapf(err, "fetching instances for pool %s", pool.ID) @@ -560,7 +616,9 @@ func (r *basePoolManager) cleanupOrphanedGithubRunners(runners []*github.Runner) lockAcquired := r.keyMux.TryLock(dbInstance.Name) if !lockAcquired { - r.log("failed to acquire lock for instance %s", dbInstance.Name) + slog.DebugContext( + r.ctx, "failed to acquire lock for instance", + "runner_name", dbInstance.Name) continue } @@ -575,18 +633,24 @@ func (r *basePoolManager) cleanupOrphanedGithubRunners(runners []*github.Runner) if !ok { // The runner instance is no longer on the provider, and it appears offline in github. // It should be safe to force remove it. - r.log("Runner instance for %s is no longer on the provider, removing from github", dbInstance.Name) + slog.InfoContext( + r.ctx, "Runner instance is no longer on the provider, removing from github", + "runner_name", dbInstance.Name) resp, err := r.helper.RemoveGithubRunner(*runner.ID) if err != nil { // Removed in the meantime? if resp != nil && resp.StatusCode == http.StatusNotFound { - r.log("runner dissapeared from github") + slog.DebugContext( + r.ctx, "runner dissapeared from github", + "runner_name", dbInstance.Name) } else { return errors.Wrap(err, "removing runner from github") } } // Remove the database entry for the runner. - r.log("Removing %s from database", dbInstance.Name) + slog.InfoContext( + r.ctx, "Removing from database", + "runner_name", dbInstance.Name) if err := r.store.DeleteInstance(ctx, dbInstance.PoolID, dbInstance.Name); err != nil { return errors.Wrap(err, "removing runner from database") } @@ -598,10 +662,14 @@ func (r *basePoolManager) cleanupOrphanedGithubRunners(runners []*github.Runner) // instance is running, but github reports runner as offline. Log the event. // This scenario may require manual intervention. // Perhaps it just came online and github did not yet change it's status? - r.log("instance %s is online but github reports runner as offline", dbInstance.Name) + slog.WarnContext( + r.ctx, "instance is online but github reports runner as offline", + "runner_name", dbInstance.Name) return nil } else { - r.log("instance %s was found in stopped state; starting", dbInstance.Name) + slog.InfoContext( + r.ctx, "instance was found in stopped state; starting", + "runner_name", dbInstance.Name) //start the instance if err := provider.Start(r.ctx, dbInstance.ProviderID); err != nil { return errors.Wrapf(err, "starting instance %s", dbInstance.ProviderID) @@ -708,7 +776,8 @@ func (r *basePoolManager) AddRunner(ctx context.Context, poolID string, aditiona // Attempt to create JIT config jitConfig, runner, err = r.helper.GetJITConfig(ctx, name, pool, labels) if err != nil { - r.log("failed to get JIT config, falling back to registration token: %s", err) + slog.With(slog.Any("error", err)).ErrorContext( + ctx, "failed to get JIT config, falling back to registration token") } } @@ -739,14 +808,18 @@ func (r *basePoolManager) AddRunner(ctx context.Context, poolID string, aditiona if err != nil { if instance.ID != "" { if err := r.DeleteRunner(instance, false); err != nil { - r.log("failed to cleanup instance: %s", instance.Name) + slog.With(slog.Any("error", err)).ErrorContext( + ctx, "failed to cleanup instance", + "runner_name", instance.Name) } } if runner != nil { _, runnerCleanupErr := r.helper.RemoveGithubRunner(runner.GetID()) if err != nil { - r.log("failed to remove runner %d: %s", runner.GetID(), runnerCleanupErr) + slog.With(slog.Any("error", runnerCleanupErr)).ErrorContext( + ctx, "failed to remove runner", + "gh_runner_id", runner.GetID()) } } } @@ -765,7 +838,8 @@ func (r *basePoolManager) Status() params.PoolManagerStatus { } func (r *basePoolManager) waitForTimeoutOrCanceled(timeout time.Duration) { - r.log("sleeping for %.2f minutes", timeout.Minutes()) + slog.DebugContext( + r.ctx, fmt.Sprintf("sleeping for %.2f minutes", timeout.Minutes())) select { case <-time.After(timeout): case <-r.ctx.Done(): @@ -842,7 +916,9 @@ func (r *basePoolManager) addInstanceToProvider(instance params.Instance) error if instanceIDToDelete != "" { if err := provider.DeleteInstance(r.ctx, instanceIDToDelete); err != nil { if !errors.Is(err, runnerErrors.ErrNotFound) { - r.log("failed to cleanup instance: %s", instanceIDToDelete) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to cleanup instance", + "provider_id", instanceIDToDelete) } } } @@ -882,23 +958,23 @@ func (r *basePoolManager) getRunnerDetailsFromJob(job params.WorkflowJob) (param } // Runner name was not set in WorkflowJob by github. We can still attempt to // fetch the info we need, using the workflow run ID, from the API. - r.log("runner name not found in workflow job, attempting to fetch from API") + slog.InfoContext( + r.ctx, "runner name not found in workflow job, attempting to fetch from API", + "job_id", job.WorkflowJob.ID) runnerInfo, err = r.helper.GetRunnerInfoFromWorkflow(job) if err != nil { return params.RunnerInfo{}, errors.Wrap(err, "fetching runner name from API") } } - runnerDetails, err := r.store.GetInstanceByName(context.Background(), runnerInfo.Name) + _, err = r.store.GetInstanceByName(context.Background(), runnerInfo.Name) if err != nil { - r.log("could not find runner details for %s", util.SanitizeLogEntry(runnerInfo.Name)) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "could not find runner details", + "runner_name", util.SanitizeLogEntry(runnerInfo.Name)) return params.RunnerInfo{}, errors.Wrap(err, "fetching runner details") } - if _, err := r.helper.GetPoolByID(runnerDetails.PoolID); err != nil { - r.log("runner %s (pool ID: %s) does not belong to any pool we manage: %s", runnerDetails.Name, runnerDetails.PoolID, err) - return params.RunnerInfo{}, errors.Wrap(err, "fetching pool for instance") - } return runnerInfo, nil } @@ -989,9 +1065,13 @@ func (r *basePoolManager) updateArgsFromProviderInstance(providerInstance common } func (r *basePoolManager) scaleDownOnePool(ctx context.Context, pool params.Pool) error { - r.log("scaling down pool %s", pool.ID) + slog.DebugContext( + ctx, "scaling down pool", + "pool_id", pool.ID) if !pool.Enabled { - r.log("pool %s is disabled, skipping scale down", pool.ID) + slog.DebugContext( + ctx, "pool is disabled, skipping scale down", + "pool_id", pool.ID) return nil } @@ -1035,13 +1115,18 @@ func (r *basePoolManager) scaleDownOnePool(ctx context.Context, pool params.Pool lockAcquired := r.keyMux.TryLock(instanceToDelete.Name) if !lockAcquired { - r.log("failed to acquire lock for instance %s", instanceToDelete.Name) + slog.With(slog.Any("error", err)).ErrorContext( + ctx, "failed to acquire lock for instance", + "provider_id", instanceToDelete.Name) continue } defer r.keyMux.Unlock(instanceToDelete.Name, false) g.Go(func() error { - r.log("scaling down idle worker %s from pool %s\n", instanceToDelete.Name, pool.ID) + slog.InfoContext( + ctx, "scaling down idle worker from pool %s", + "runner_name", instanceToDelete.Name, + "pool_id", pool.ID) if err := r.DeleteRunner(instanceToDelete, false); err != nil { return fmt.Errorf("failed to delete instance %s: %w", instanceToDelete.ID, err) } @@ -1065,7 +1150,9 @@ func (r *basePoolManager) scaleDownOnePool(ctx context.Context, pool params.Pool for _, job := range queued { if time.Since(job.CreatedAt).Minutes() > 10 && pool.HasRequiredLabels(job.Labels) { if err := r.store.DeleteJob(ctx, job.ID); err != nil && !errors.Is(err, runnerErrors.ErrNotFound) { - r.log("failed to delete job %d: %s", job.ID, err) + slog.With(slog.Any("error", err)).ErrorContext( + ctx, "failed to delete job", + "job_id", job.ID) } } } @@ -1109,7 +1196,10 @@ func (r *basePoolManager) ensureIdleRunnersForOnePool(pool params.Pool) error { } if uint(len(existingInstances)) >= pool.MaxRunners { - r.log("max workers (%d) reached for pool %s, skipping idle worker creation", pool.MaxRunners, pool.ID) + slog.DebugContext( + r.ctx, "max workers reached for pool, skipping idle worker creation", + "max_runners", pool.MaxRunners, + "pool_id", pool.ID) return nil } @@ -1134,7 +1224,9 @@ func (r *basePoolManager) ensureIdleRunnersForOnePool(pool params.Pool) error { } for i := 0; i < required; i++ { - r.log("adding new idle worker to pool %s", pool.ID) + slog.InfoContext( + r.ctx, "adding new idle worker to pool", + "pool_id", pool.ID) if err := r.AddRunner(r.ctx, pool.ID, nil); err != nil { return fmt.Errorf("failed to add new instance for pool %s: %w", pool.ID, err) } @@ -1146,7 +1238,9 @@ func (r *basePoolManager) retryFailedInstancesForOnePool(ctx context.Context, po if !pool.Enabled { return nil } - r.log("running retry failed instances for pool %s", pool.ID) + slog.DebugContext( + ctx, "running retry failed instances for pool", + "pool_id", pool.ID) existingInstances, err := r.store.ListPoolInstances(r.ctx, pool.ID) if err != nil { @@ -1162,10 +1256,14 @@ func (r *basePoolManager) retryFailedInstancesForOnePool(ctx context.Context, po continue } - r.log("attempting to retry failed instance %s", instance.Name) + slog.DebugContext( + ctx, "attempting to retry failed instance", + "runner_name", instance.Name) lockAcquired := r.keyMux.TryLock(instance.Name) if !lockAcquired { - r.log("failed to acquire lock for instance %s", instance.Name) + slog.DebugContext( + ctx, "failed to acquire lock for instance", + "runner_name", instance.Name) continue } @@ -1176,7 +1274,9 @@ func (r *basePoolManager) retryFailedInstancesForOnePool(ctx context.Context, po // this has the potential to create many API requests to the target provider. // TODO(gabriel-samfira): implement request throttling. if err := r.deleteInstanceFromProvider(errCtx, instance); err != nil { - r.log("failed to delete instance %s from provider: %s", instance.Name, err) + slog.With(slog.Any("error", err)).ErrorContext( + ctx, "failed to delete instance from provider", + "runner_name", instance.Name) // Bail here, otherwise we risk creating multiple failing instances, and losing track // of them. If Create instance failed to return a proper provider ID, we rely on the // name to delete the instance. If we don't bail here, and end up with multiple @@ -1197,10 +1297,14 @@ func (r *basePoolManager) retryFailedInstancesForOnePool(ctx context.Context, po Status: commonParams.InstancePendingCreate, RunnerStatus: params.RunnerPending, } - r.log("queueing previously failed instance %s for retry", instance.Name) + slog.DebugContext( + ctx, "queueing previously failed instance for retry", + "runner_name", instance.Name) // Set instance to pending create and wait for retry. if _, err := r.updateInstance(instance.Name, updateParams); err != nil { - r.log("failed to update runner %s status: %s", instance.Name, err) + slog.With(slog.Any("error", err)).ErrorContext( + ctx, "failed to update runner status", + "runner_name", instance.Name) } return nil }) @@ -1243,7 +1347,9 @@ func (r *basePoolManager) scaleDown() error { for _, pool := range pools { pool := pool g.Go(func() error { - r.log("running scale down for pool %s", pool.ID) + slog.DebugContext( + ctx, "running scale down for pool", + "pool_id", pool.ID) return r.scaleDownOnePool(ctx, pool) }) } @@ -1304,17 +1410,23 @@ func (r *basePoolManager) deletePendingInstances() error { return fmt.Errorf("failed to fetch instances from store: %w", err) } - r.log("removing instances in pending_delete") + slog.DebugContext( + r.ctx, "removing instances in pending_delete") for _, instance := range instances { if instance.Status != commonParams.InstancePendingDelete && instance.Status != commonParams.InstancePendingForceDelete { // not in pending_delete status. Skip. continue } - r.log("removing instance %s in pool %s", instance.Name, instance.PoolID) + slog.InfoContext( + r.ctx, "removing instance from pool", + "runner_name", instance.Name, + "pool_id", instance.PoolID) lockAcquired := r.keyMux.TryLock(instance.Name) if !lockAcquired { - r.log("failed to acquire lock for instance %s", instance.Name) + slog.InfoContext( + r.ctx, "failed to acquire lock for instance", + "runner_name", instance.Name) continue } @@ -1322,7 +1434,9 @@ func (r *basePoolManager) deletePendingInstances() error { // Set the status to deleting before launching the goroutine that removes // the runner from the provider (which can take a long time). if _, err := r.setInstanceStatus(instance.Name, commonParams.InstanceDeleting, nil); err != nil { - r.log("failed to update runner %s status: %q", instance.Name, err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to update runner status", + "runner_name", instance.Name) r.keyMux.Unlock(instance.Name, false) continue } @@ -1334,29 +1448,41 @@ func (r *basePoolManager) deletePendingInstances() error { }() defer func(instance params.Instance) { if err != nil { - r.log("failed to remove instance %s: %s", instance.Name, err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to remove instance", + "runner_name", instance.Name) // failed to remove from provider. Set status to previous value, which will retry // the operation. if _, err := r.setInstanceStatus(instance.Name, currentStatus, nil); err != nil { - r.log("failed to update runner %s status: %s", instance.Name, err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to update runner status", + "runner_name", instance.Name) } } }(instance) - r.log("removing instance %s from provider", instance.Name) + slog.DebugContext( + r.ctx, "removing instance from provider", + "runner_name", instance.Name) err = r.deleteInstanceFromProvider(r.ctx, instance) if err != nil { if currentStatus != commonParams.InstancePendingForceDelete { return fmt.Errorf("failed to remove instance from provider: %w", err) } - log.Printf("failed to remove instance %s from provider (continuing anyway): %s", instance.Name, err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to remove instance from provider (continuing anyway)", + "instance", instance.Name) } - r.log("removing instance %s from database", instance.Name) + slog.InfoContext( + r.ctx, "removing instance from database", + "runner_name", instance.Name) if deleteErr := r.store.DeleteInstance(r.ctx, instance.PoolID, instance.Name); deleteErr != nil { return fmt.Errorf("failed to delete instance from database: %w", deleteErr) } deleteMux = true - r.log("instance %s was successfully removed", instance.Name) + slog.InfoContext( + r.ctx, "instance was successfully removed", + "runner_name", instance.Name) return nil }(instance) //nolint } @@ -1376,17 +1502,24 @@ func (r *basePoolManager) addPendingInstances() error { continue } - r.log("attempting to acquire lock for instance %s (create)", instance.Name) + slog.DebugContext( + r.ctx, "attempting to acquire lock for instance", + "runner_name", instance.Name, + "action", "create_pending") lockAcquired := r.keyMux.TryLock(instance.Name) if !lockAcquired { - r.log("failed to acquire lock for instance %s", instance.Name) + slog.DebugContext( + r.ctx, "failed to acquire lock for instance", + "runner_name", instance.Name) continue } // Set the instance to "creating" before launching the goroutine. This will ensure that addPendingInstances() // won't attempt to create the runner a second time. if _, err := r.setInstanceStatus(instance.Name, commonParams.InstanceCreating, nil); err != nil { - r.log("failed to update runner %s status: %s", instance.Name, err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to update runner status", + "runner_name", instance.Name) r.keyMux.Unlock(instance.Name, false) // We failed to transition the instance to Creating. This means that garm will retry to create this instance // when the loop runs again and we end up with multiple instances. @@ -1395,14 +1528,21 @@ func (r *basePoolManager) addPendingInstances() error { go func(instance params.Instance) { defer r.keyMux.Unlock(instance.Name, false) - r.log("creating instance %s in pool %s", instance.Name, instance.PoolID) + slog.InfoContext( + r.ctx, "creating instance in pool", + "runner_name", instance.Name, + "pool_id", instance.PoolID) if err := r.addInstanceToProvider(instance); err != nil { - r.log("failed to add instance to provider: %s", err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to add instance to provider") errAsBytes := []byte(err.Error()) - if _, err := r.setInstanceStatus(instance.Name, commonParams.InstanceError, errAsBytes); err != nil { - r.log("failed to update runner %s status: %s", instance.Name, err) + if _, statusErr := r.setInstanceStatus(instance.Name, commonParams.InstanceError, errAsBytes); statusErr != nil { + slog.With(slog.Any("error", statusErr)).ErrorContext( + r.ctx, "failed to update runner status", + "runner_name", instance.Name) } - r.log("failed to create instance in provider: %s", err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to create instance in provider") } }(instance) } @@ -1425,7 +1565,8 @@ func (r *basePoolManager) Wait() error { } func (r *basePoolManager) runnerCleanup() (err error) { - r.log("running runner cleanup") + slog.DebugContext( + r.ctx, "running runner cleanup") runners, err := r.helper.GetGithubRunners() if err != nil { return fmt.Errorf("failed to fetch github runners: %w", err) @@ -1519,12 +1660,14 @@ func (r *basePoolManager) DeleteRunner(runner params.Instance, forceRemove bool) return errors.Wrapf(runnerErrors.ErrBadRequest, "removing runner: %q", err) case http.StatusNotFound: // Runner may have been deleted by a finished job, or manually by the user. - r.log("runner with agent id %d was not found in github", runner.AgentID) + slog.DebugContext( + r.ctx, "runner was not found in github", + "agent_id", runner.AgentID) case http.StatusUnauthorized: // Mark the pool as offline from this point forward - failureReason := fmt.Sprintf("failed to remove runner: %q", err) - r.setPoolRunningState(false, failureReason) - log.Print(failureReason) + r.setPoolRunningState(false, fmt.Sprintf("failed to remove runner: %q", err)) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to remove runner") // evaluate the next switch case. fallthrough default: @@ -1542,9 +1685,14 @@ func (r *basePoolManager) DeleteRunner(runner params.Instance, forceRemove bool) instanceStatus = commonParams.InstancePendingForceDelete } - r.log("setting instance status for %v to %v", runner.Name, instanceStatus) + slog.InfoContext( + r.ctx, "setting instance status", + "runner_name", runner.Name, + "status", instanceStatus) if _, err := r.setInstanceStatus(runner.Name, instanceStatus, nil); err != nil { - r.log("failed to update runner %s status: %s", runner.Name, err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to update runner", + "runner_name", runner.Name) return errors.Wrap(err, "updating runner") } return nil @@ -1581,17 +1729,24 @@ func (r *basePoolManager) consumeQueuedJobs() error { poolsCache := poolsForTags{} - r.log("found %d queued jobs for %s", len(queued), r.helper.String()) + slog.DebugContext( + r.ctx, "found queued jobs", + "job_count", len(queued)) for _, job := range queued { if job.LockedBy != uuid.Nil && job.LockedBy.String() != r.ID() { // Job was handled by us or another entity. - r.log("job %d is locked by %s", job.ID, job.LockedBy.String()) + slog.DebugContext( + r.ctx, "job is locked", + "job_id", job.ID, + "locking_entity", job.LockedBy.String()) continue } if time.Since(job.UpdatedAt) < time.Second*30 { // give the idle runners a chance to pick up the job. - r.log("job %d was updated less than 30 seconds ago. Skipping", job.ID) + slog.DebugContext( + r.ctx, "job was updated less than 30 seconds ago. Skipping", + "job_id", job.ID) continue } @@ -1601,7 +1756,9 @@ func (r *basePoolManager) consumeQueuedJobs() error { // the runner. if err := r.store.UnlockJob(r.ctx, job.ID, r.ID()); err != nil { // TODO: Implament a cache? Should we return here? - r.log("failed to unlock job %d: %q", job.ID, err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to unlock job", + "job_id", job.ID) continue } } @@ -1611,7 +1768,9 @@ func (r *basePoolManager) consumeQueuedJobs() error { // TODO(gabriel-samfira): create an in-memory state of existing runners that we can easily // check for existing pending or idle runners. If we can't find any, attempt to allocate another // runner. - r.log("job %d is locked by us", job.ID) + slog.DebugContext( + r.ctx, "job is locked by us", + "job_id", job.ID) continue } @@ -1619,20 +1778,23 @@ func (r *basePoolManager) consumeQueuedJobs() error { if !ok { potentialPools, err := r.store.FindPoolsMatchingAllTags(r.ctx, r.helper.PoolType(), r.helper.ID(), job.Labels) if err != nil { - r.log("error finding pools matching labels: %s", err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "error finding pools matching labels") continue } poolRR = poolsCache.Add(job.Labels, potentialPools) } if poolRR.Len() == 0 { - r.log("could not find pools with labels %s", strings.Join(job.Labels, ",")) + slog.DebugContext(r.ctx, "could not find pools with labels", "requested_labels", strings.Join(job.Labels, ",")) continue } runnerCreated := false if err := r.store.LockJob(r.ctx, job.ID, r.ID()); err != nil { - r.log("could not lock job %d: %s", job.ID, err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "could not lock job", + "job_id", job.ID) continue } @@ -1642,31 +1804,45 @@ func (r *basePoolManager) consumeQueuedJobs() error { for i := 0; i < poolRR.Len(); i++ { pool, err := poolRR.Next() if err != nil { - r.log("could not find a pool to create a runner for job %d: %s", job.ID, err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "could not find a pool to create a runner for job", + "job_id", job.ID) break } - r.log("attempting to create a runner in pool %s for job %d", pool.ID, job.ID) + slog.InfoContext( + r.ctx, "attempting to create a runner in pool", + "pool_id", pool.ID, + "job_id", job.ID) if err := r.addRunnerToPool(pool, jobLabels); err != nil { - r.log("[PoolRR] could not add runner to pool %s: %s", pool.ID, err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "could not add runner to pool", + "pool_id", pool.ID) continue } - r.log("a new runner was added to pool %s as a response to queued job %d", pool.ID, job.ID) + slog.DebugContext(r.ctx, "a new runner was added as a response to queued job", + "pool_id", pool.ID, + "job_id", job.ID) runnerCreated = true break } if !runnerCreated { - r.log("could not create a runner for job %d; unlocking", job.ID) + slog.WarnContext( + r.ctx, "could not create a runner for job; unlocking", + "job_id", job.ID) if err := r.store.UnlockJob(r.ctx, job.ID, r.ID()); err != nil { - r.log("failed to unlock job: %d", job.ID) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to unlock job", + "job_id", job.ID) return errors.Wrap(err, "unlocking job") } } } if err := r.store.DeleteCompletedJobs(r.ctx); err != nil { - r.log("failed to delete completed jobs: %q", err) + slog.With(slog.Any("error", err)).ErrorContext( + r.ctx, "failed to delete completed jobs") } return nil } diff --git a/runner/pool/repository.go b/runner/pool/repository.go index 9abe387e..0505eece 100644 --- a/runner/pool/repository.go +++ b/runner/pool/repository.go @@ -19,7 +19,7 @@ import ( "encoding/base64" "encoding/json" "fmt" - "log" + "log/slog" "net/http" "strings" "sync" @@ -39,6 +39,7 @@ import ( var _ poolHelper = &repository{} func NewRepositoryPoolManager(ctx context.Context, cfg params.Repository, cfgInternal params.Internal, providers map[string]common.Provider, store dbCommon.Store) (common.PoolManager, error) { + ctx = util.WithContext(ctx, slog.Any("pool_mgr", fmt.Sprintf("%s/%s", cfg.Owner, cfg.Name)), slog.Any("pool_type", params.RepositoryPool)) ghc, _, err := util.GithubClient(ctx, cfgInternal.OAuth2Token, cfgInternal.GithubCredentialsDetails) if err != nil { return nil, errors.Wrap(err, "getting github client") @@ -110,7 +111,11 @@ func (r *repository) GetJITConfig(ctx context.Context, instance string, pool par defer func() { if err != nil && runner != nil { _, innerErr := r.ghcli.RemoveRunner(r.ctx, r.cfg.Owner, r.cfg.Name, runner.GetID()) - log.Printf("failed to remove runner: %v", innerErr) + slog.With(slog.Any("error", innerErr)).ErrorContext( + ctx, "failed to remove runner", + "runner_id", runner.GetID(), + "repo", r.cfg.Name, + "owner", r.cfg.Owner) } }() @@ -332,7 +337,11 @@ func (r *repository) InstallHook(ctx context.Context, req *github.Hook) (params. } if _, err := r.ghcli.PingRepoHook(ctx, r.cfg.Owner, r.cfg.Name, hook.GetID()); err != nil { - log.Printf("failed to ping hook %d: %v", hook.GetID(), err) + slog.With(slog.Any("error", err)).ErrorContext( + ctx, "failed to ping hook", + "hook_id", hook.GetID(), + "repo", r.cfg.Name, + "owner", r.cfg.Owner) } return hookToParamsHookInfo(hook), nil diff --git a/runner/pool/util.go b/runner/pool/util.go index 4a8c09e3..b97bf26f 100644 --- a/runner/pool/util.go +++ b/runner/pool/util.go @@ -1,7 +1,6 @@ package pool import ( - "log" "sort" "strings" "sync" @@ -57,11 +56,3 @@ func (p *poolsForTags) Add(tags []string, pools []params.Pool) *poolRoundRobin { v, _ := p.pools.LoadOrStore(key, poolRR) return v.(*poolRoundRobin) } - -func (r *basePoolManager) log(msg string, args ...interface{}) { - msgArgs := []interface{}{ - r.helper.String(), - } - msgArgs = append(msgArgs, args...) - log.Printf("[Pool mgr %s] "+msg, msgArgs...) -} diff --git a/runner/providers/external/external.go b/runner/providers/external/external.go index bf4cd3fc..fe74ecc1 100644 --- a/runner/providers/external/external.go +++ b/runner/providers/external/external.go @@ -4,7 +4,7 @@ import ( "context" "encoding/json" "fmt" - "log" + "log/slog" "os/exec" "github.com/cloudbase/garm-provider-common/execution" @@ -51,7 +51,7 @@ type external struct { environmentVariables []string } -func (e *external) validateResult(inst commonParams.ProviderInstance) error { +func (e *external) validateResult(ctx context.Context, inst commonParams.ProviderInstance) error { if inst.ProviderID == "" { return garmErrors.NewProviderError("missing provider ID") } @@ -62,7 +62,9 @@ func (e *external) validateResult(inst commonParams.ProviderInstance) error { if inst.OSName == "" || inst.OSArch == "" || inst.OSType == "" { // we can still function without this info (I think) - log.Printf("WARNING: missing OS information") + slog.WarnContext( + ctx, "missing OS information", + "instance", inst.Name) } if !IsValidProviderStatus(inst.Status) { return garmErrors.NewProviderError("invalid status returned (%s)", inst.Status) @@ -96,12 +98,14 @@ func (e *external) CreateInstance(ctx context.Context, bootstrapParams commonPar return commonParams.ProviderInstance{}, garmErrors.NewProviderError("failed to decode response from binary: %s", err) } - if err := e.validateResult(param); err != nil { + if err := e.validateResult(ctx, param); err != nil { return commonParams.ProviderInstance{}, garmErrors.NewProviderError("failed to validate result: %s", err) } retAsJs, _ := json.MarshalIndent(param, "", " ") - log.Printf("provider returned: %s", string(retAsJs)) + slog.DebugContext( + ctx, "provider returned", + "output", string(retAsJs)) return param, nil } @@ -148,7 +152,7 @@ func (e *external) GetInstance(ctx context.Context, instance string) (commonPara return commonParams.ProviderInstance{}, garmErrors.NewProviderError("failed to decode response from binary: %s", err) } - if err := e.validateResult(param); err != nil { + if err := e.validateResult(ctx, param); err != nil { return commonParams.ProviderInstance{}, garmErrors.NewProviderError("failed to validate result: %s", err) } @@ -177,7 +181,7 @@ func (e *external) ListInstances(ctx context.Context, poolID string) ([]commonPa ret := make([]commonParams.ProviderInstance, len(param)) for idx, inst := range param { - if err := e.validateResult(inst); err != nil { + if err := e.validateResult(ctx, inst); err != nil { return []commonParams.ProviderInstance{}, garmErrors.NewProviderError("failed to validate result: %s", err) } ret[idx] = inst diff --git a/runner/providers/providers.go b/runner/providers/providers.go index 5d4e58f1..e9bb48ed 100644 --- a/runner/providers/providers.go +++ b/runner/providers/providers.go @@ -16,7 +16,7 @@ package providers import ( "context" - "log" + "log/slog" "github.com/cloudbase/garm/config" "github.com/cloudbase/garm/params" @@ -31,7 +31,9 @@ import ( func LoadProvidersFromConfig(ctx context.Context, cfg config.Config, controllerID string) (map[string]common.Provider, error) { providers := make(map[string]common.Provider, len(cfg.Providers)) for _, providerCfg := range cfg.Providers { - log.Printf("Loading provider %s", providerCfg.Name) + slog.InfoContext( + ctx, "Loading provider", + "provider", providerCfg.Name) switch providerCfg.ProviderType { case params.ExternalProvider: conf := providerCfg diff --git a/runner/repositories.go b/runner/repositories.go index 54859c4e..143bbd06 100644 --- a/runner/repositories.go +++ b/runner/repositories.go @@ -17,7 +17,7 @@ package runner import ( "context" "fmt" - "log" + "log/slog" "strings" runnerErrors "github.com/cloudbase/garm-provider-common/errors" @@ -60,7 +60,9 @@ func (r *Runner) CreateRepository(ctx context.Context, param params.CreateRepoPa defer func() { if err != nil { if deleteErr := r.store.DeleteRepository(ctx, repo.ID); deleteErr != nil { - log.Printf("failed to delete repository: %s", deleteErr) + slog.With(slog.Any("error", deleteErr)).ErrorContext( + ctx, "failed to delete repository", + "repository_id", repo.ID) } } }() @@ -71,7 +73,9 @@ func (r *Runner) CreateRepository(ctx context.Context, param params.CreateRepoPa } if err := poolMgr.Start(); err != nil { if deleteErr := r.poolManagerCtrl.DeleteRepoPoolManager(repo); deleteErr != nil { - log.Printf("failed to cleanup pool manager for repo %s", repo.ID) + slog.With(slog.Any("error", deleteErr)).ErrorContext( + ctx, "failed to cleanup pool manager for repo", + "repository_id", repo.ID) } return params.Repository{}, errors.Wrap(err, "starting repo pool manager") } @@ -155,7 +159,9 @@ func (r *Runner) DeleteRepository(ctx context.Context, repoID string, keepWebhoo if err := poolMgr.UninstallWebhook(ctx); err != nil { // TODO(gabriel-samfira): Should we error out here? - log.Printf("failed to uninstall webhook: %s", err) + slog.With(slog.Any("error", err)).ErrorContext( + ctx, "failed to uninstall webhook", + "pool_manager_id", poolMgr.ID()) } } diff --git a/runner/runner.go b/runner/runner.go index b257dd47..05eed3f6 100644 --- a/runner/runner.go +++ b/runner/runner.go @@ -23,7 +23,7 @@ import ( "encoding/json" "fmt" "hash" - "log" + "log/slog" "os" "strings" "sync" @@ -449,7 +449,9 @@ func (r *Runner) loadReposOrgsAndEnterprises() error { for _, repo := range repos { repo := repo g.Go(func() error { - log.Printf("creating pool manager for repo %s/%s", repo.Owner, repo.Name) + slog.InfoContext( + r.ctx, "creating pool manager for repo", + "repo_owner", repo.Owner, "repo_name", repo.Name) _, err := r.poolManagerCtrl.CreateRepoPoolManager(r.ctx, repo, r.providers, r.store) return err }) @@ -458,7 +460,7 @@ func (r *Runner) loadReposOrgsAndEnterprises() error { for _, org := range orgs { org := org g.Go(func() error { - log.Printf("creating pool manager for organization %s", org.Name) + slog.InfoContext(r.ctx, "creating pool manager for organization", "org_name", org.Name) _, err := r.poolManagerCtrl.CreateOrgPoolManager(r.ctx, org, r.providers, r.store) return err }) @@ -467,7 +469,7 @@ func (r *Runner) loadReposOrgsAndEnterprises() error { for _, enterprise := range enterprises { enterprise := enterprise g.Go(func() error { - log.Printf("creating pool manager for enterprise %s", enterprise.Name) + slog.InfoContext(r.ctx, "creating pool manager for enterprise", "enterprise_name", enterprise.Name) _, err := r.poolManagerCtrl.CreateEnterprisePoolManager(r.ctx, enterprise, r.providers, r.store) return err }) @@ -630,7 +632,7 @@ func (r *Runner) Wait() error { go func(id string, poolMgr common.PoolManager) { defer wg.Done() if err := poolMgr.Wait(); err != nil { - log.Printf("timed out waiting for pool manager %s to exit", id) + slog.With(slog.Any("error", err)).ErrorContext(r.ctx, "timed out waiting for pool manager to exit", "pool_id", id, "pool_mgr_id", poolMgr.ID()) } }(poolId, repo) } @@ -640,7 +642,7 @@ func (r *Runner) Wait() error { go func(id string, poolMgr common.PoolManager) { defer wg.Done() if err := poolMgr.Wait(); err != nil { - log.Printf("timed out waiting for pool manager %s to exit", id) + slog.With(slog.Any("error", err)).ErrorContext(r.ctx, "timed out waiting for pool manager to exit", "pool_id", id) } }(poolId, org) } @@ -650,7 +652,7 @@ func (r *Runner) Wait() error { go func(id string, poolMgr common.PoolManager) { defer wg.Done() if err := poolMgr.Wait(); err != nil { - log.Printf("timed out waiting for pool manager %s to exit", id) + slog.With(slog.Any("error", err)).ErrorContext(r.ctx, "timed out waiting for pool manager to exit", "pool_id", id) } }(poolId, enterprise) } @@ -717,12 +719,20 @@ func (r *Runner) DispatchWorkflowJob(hookTargetType, signature string, jobData [ switch HookTargetType(hookTargetType) { case RepoHook: - log.Printf("got hook for repo %s/%s", util.SanitizeLogEntry(job.Repository.Owner.Login), util.SanitizeLogEntry(job.Repository.Name)) + slog.DebugContext( + r.ctx, "got hook for repo", + "repo_owner", util.SanitizeLogEntry(job.Repository.Owner.Login), + "repo_name", util.SanitizeLogEntry(job.Repository.Name)) poolManager, err = r.findRepoPoolManager(job.Repository.Owner.Login, job.Repository.Name) case OrganizationHook: - log.Printf("got hook for org %s", util.SanitizeLogEntry(job.Organization.Login)) + slog.DebugContext( + r.ctx, "got hook for organization", + "organization", util.SanitizeLogEntry(job.Organization.Login)) poolManager, err = r.findOrgPoolManager(job.Organization.Login) case EnterpriseHook: + slog.DebugContext( + r.ctx, "got hook for enterprise", + "enterprise", util.SanitizeLogEntry(job.Enterprise.Slug)) poolManager, err = r.findEnterprisePoolManager(job.Enterprise.Slug) default: return runnerErrors.NewBadRequestError("cannot handle hook target type %s", hookTargetType) @@ -861,7 +871,7 @@ func (r *Runner) AddInstanceStatusMessage(ctx context.Context, param params.Inst func (r *Runner) UpdateSystemInfo(ctx context.Context, param params.UpdateSystemInfoParams) error { instanceID := auth.InstanceID(ctx) if instanceID == "" { - log.Printf("missing instance ID") + slog.ErrorContext(ctx, "missing instance ID") return runnerErrors.ErrUnauthorized } diff --git a/test/integration/e2e/client.go b/test/integration/e2e/client.go index 536420fe..2ab81695 100644 --- a/test/integration/e2e/client.go +++ b/test/integration/e2e/client.go @@ -1,7 +1,7 @@ package e2e import ( - "log" + "log/slog" "net/url" "github.com/cloudbase/garm/client" @@ -32,7 +32,7 @@ func InitClient(baseURL string) { } func FirstRun(adminUsername, adminPassword, adminFullName, adminEmail string) *params.User { - log.Println("First run") + slog.Info("First run") newUser := params.NewUserParams{ Username: adminUsername, Password: adminPassword, @@ -47,7 +47,7 @@ func FirstRun(adminUsername, adminPassword, adminFullName, adminEmail string) *p } func Login(username, password string) { - log.Println("Login") + slog.Info("Login") loginParams := params.PasswordLoginParams{ Username: username, Password: password, diff --git a/test/integration/e2e/e2e.go b/test/integration/e2e/e2e.go index b94c0652..0c0c27e2 100644 --- a/test/integration/e2e/e2e.go +++ b/test/integration/e2e/e2e.go @@ -2,7 +2,7 @@ package e2e import ( "fmt" - "log" + "log/slog" "os" "time" @@ -10,7 +10,7 @@ import ( ) func ListCredentials() params.Credentials { - log.Println("List credentials") + slog.Info("List credentials") credentials, err := listCredentials(cli, authToken) if err != nil { panic(err) @@ -19,7 +19,7 @@ func ListCredentials() params.Credentials { } func ListProviders() params.Providers { - log.Println("List providers") + slog.Info("List providers") providers, err := listProviders(cli, authToken) if err != nil { panic(err) @@ -28,7 +28,7 @@ func ListProviders() params.Providers { } func GetMetricsToken() { - log.Println("Get metrics token") + slog.Info("Get metrics token") _, err := getMetricsToken(cli, authToken) if err != nil { panic(err) @@ -36,7 +36,7 @@ func GetMetricsToken() { } func GetControllerInfo() *params.ControllerInfo { - log.Println("Get controller info") + slog.Info("Get controller info") controllerInfo, err := getControllerInfo(cli, authToken) if err != nil { panic(err) @@ -62,7 +62,7 @@ func GracefulCleanup() { if _, err := updatePool(cli, authToken, pool.ID, poolParams); err != nil { panic(err) } - log.Printf("Pool %s disabled", pool.ID) + slog.Info("Pool disabled", "pool_id", pool.ID) } // delete all the instances @@ -75,7 +75,7 @@ func GracefulCleanup() { if err := deleteInstance(cli, authToken, instance.Name, false); err != nil { panic(err) } - log.Printf("Instance %s deletion initiated", instance.Name) + slog.Info("Instance deletion initiated", "instance", instance.Name) } } @@ -91,7 +91,7 @@ func GracefulCleanup() { if err := deletePool(cli, authToken, pool.ID); err != nil { panic(err) } - log.Printf("Pool %s deleted", pool.ID) + slog.Info("Pool deleted", "pool_id", pool.ID) } // delete all the repositories @@ -103,7 +103,7 @@ func GracefulCleanup() { if err := deleteRepo(cli, authToken, repo.ID); err != nil { panic(err) } - log.Printf("Repo %s deleted", repo.ID) + slog.Info("Repo deleted", "repo_id", repo.ID) } // delete all the organizations @@ -115,14 +115,14 @@ func GracefulCleanup() { if err := deleteOrg(cli, authToken, org.ID); err != nil { panic(err) } - log.Printf("Org %s deleted", org.ID) + slog.Info("Org deleted", "org_id", org.ID) } } func appendCtrlInfoToGitHubEnv(controllerInfo *params.ControllerInfo) error { envFile, found := os.LookupEnv("GITHUB_ENV") if !found { - log.Printf("GITHUB_ENV not set, skipping appending controller info") + slog.Info("GITHUB_ENV not set, skipping appending controller info") return nil } file, err := os.OpenFile(envFile, os.O_WRONLY|os.O_APPEND, os.ModeAppend) diff --git a/test/integration/e2e/github_client_utils.go b/test/integration/e2e/github_client_utils.go index 8eee927c..81ced630 100644 --- a/test/integration/e2e/github_client_utils.go +++ b/test/integration/e2e/github_client_utils.go @@ -3,14 +3,14 @@ package e2e import ( "context" "fmt" - "log" + "log/slog" "github.com/google/go-github/v57/github" "golang.org/x/oauth2" ) func TriggerWorkflow(ghToken, orgName, repoName, workflowFileName, labelName string) { - log.Printf("Trigger workflow with label %s", labelName) + slog.Info("Trigger workflow", "label", labelName) client := getGithubClient(ghToken) eventReq := github.CreateWorkflowDispatchEventRequest{ @@ -26,7 +26,7 @@ func TriggerWorkflow(ghToken, orgName, repoName, workflowFileName, labelName str } func GhOrgRunnersCleanup(ghToken, orgName, controllerID string) error { - log.Printf("Cleanup Github runners, labelled with controller ID %s, from org %s", controllerID, orgName) + slog.Info("Cleanup Github runners", "controller_id", controllerID, "org_name", orgName) client := getGithubClient(ghToken) ghOrgRunners, _, err := client.Actions.ListOrganizationRunners(context.Background(), orgName, nil) @@ -42,10 +42,10 @@ func GhOrgRunnersCleanup(ghToken, orgName, controllerID string) error { if _, err := client.Actions.RemoveOrganizationRunner(context.Background(), orgName, orgRunner.GetID()); err != nil { // We don't fail if we can't remove a single runner. This // is a best effort to try and remove all the orphan runners. - log.Printf("Failed to remove organization runner %s: %v", orgRunner.GetName(), err) + slog.With(slog.Any("error", err)).Info("Failed to remove organization runner", "org_runner", orgRunner.GetName()) break } - log.Printf("Removed organization runner %s", orgRunner.GetName()) + slog.Info("Removed organization runner", "org_runner", orgRunner.GetName()) break } } @@ -55,7 +55,7 @@ func GhOrgRunnersCleanup(ghToken, orgName, controllerID string) error { } func GhRepoRunnersCleanup(ghToken, orgName, repoName, controllerID string) error { - log.Printf("Cleanup Github runners, labelled with controller ID %s, from repo %s/%s", controllerID, orgName, repoName) + slog.Info("Cleanup Github runners", "controller_id", controllerID, "org_name", orgName, "repo_name", repoName) client := getGithubClient(ghToken) ghRepoRunners, _, err := client.Actions.ListRunners(context.Background(), orgName, repoName, nil) @@ -71,10 +71,10 @@ func GhRepoRunnersCleanup(ghToken, orgName, repoName, controllerID string) error if _, err := client.Actions.RemoveRunner(context.Background(), orgName, repoName, repoRunner.GetID()); err != nil { // We don't fail if we can't remove a single runner. This // is a best effort to try and remove all the orphan runners. - log.Printf("Failed to remove repository runner %s: %v", repoRunner.GetName(), err) + slog.With(slog.Any("error", err)).Error("Failed to remove repository runner", "runner_name", repoRunner.GetName()) break } - log.Printf("Removed repository runner %s", repoRunner.GetName()) + slog.Info("Removed repository runner", "runner_name", repoRunner.GetName()) break } } @@ -124,7 +124,7 @@ func ValidateRepoWebhookUninstalled(ghToken, url, orgName, repoName string) { } func GhOrgWebhookCleanup(ghToken, webhookURL, orgName string) error { - log.Printf("Cleanup Github webhook with url %s for org %s", webhookURL, orgName) + slog.Info("Cleanup Github webhook", "webhook_url", webhookURL, "org_name", orgName) hook, err := getGhOrgWebhook(webhookURL, ghToken, orgName) if err != nil { return err @@ -136,14 +136,14 @@ func GhOrgWebhookCleanup(ghToken, webhookURL, orgName string) error { if _, err := client.Organizations.DeleteHook(context.Background(), orgName, hook.GetID()); err != nil { return err } - log.Printf("Github webhook with url %s for org %s was removed", webhookURL, orgName) + slog.Info("Github webhook removed", "webhook_url", webhookURL, "org_name", orgName) } return nil } func GhRepoWebhookCleanup(ghToken, webhookURL, orgName, repoName string) error { - log.Printf("Cleanup Github webhook with url %s for repo %s/%s", webhookURL, orgName, repoName) + slog.Info("Cleanup Github webhook", "webhook_url", webhookURL, "org_name", orgName, "repo_name", repoName) hook, err := getGhRepoWebhook(webhookURL, ghToken, orgName, repoName) if err != nil { @@ -156,7 +156,7 @@ func GhRepoWebhookCleanup(ghToken, webhookURL, orgName, repoName string) error { if _, err := client.Repositories.DeleteHook(context.Background(), orgName, repoName, hook.GetID()); err != nil { return err } - log.Printf("Github webhook with url %s for repo %s/%s was removed", webhookURL, orgName, repoName) + slog.Info("Github webhook with", "webhook_url", webhookURL, "org_name", orgName, "repo_name", repoName) } return nil diff --git a/test/integration/e2e/instances.go b/test/integration/e2e/instances.go index 7b0de20b..1200f3a3 100644 --- a/test/integration/e2e/instances.go +++ b/test/integration/e2e/instances.go @@ -2,7 +2,7 @@ package e2e import ( "fmt" - "log" + "log/slog" "time" commonParams "github.com/cloudbase/garm-provider-common/params" @@ -13,13 +13,13 @@ func waitInstanceStatus(name string, status commonParams.InstanceStatus, runnerS var timeWaited time.Duration = 0 var instance *params.Instance - log.Printf("Waiting for instance %s status to reach status %s and runner status %s", name, status, runnerStatus) + slog.Info("Waiting for instance to reach desired status", "instance", name, "desired_status", status, "desired_runner_status", runnerStatus) for timeWaited < timeout { instance, err := getInstance(cli, authToken, name) if err != nil { return nil, err } - log.Printf("Instance %s status %s and runner status %s", name, instance.Status, instance.RunnerStatus) + slog.Info("Instance status", "instance_name", name, "status", instance.Status, "runner_status", instance.RunnerStatus) if instance.Status == status && instance.RunnerStatus == runnerStatus { return instance, nil } @@ -37,14 +37,14 @@ func DeleteInstance(name string, forceRemove bool) { if err := deleteInstance(cli, authToken, name, forceRemove); err != nil { panic(err) } - log.Printf("Instance %s deletion initiated", name) + slog.Info("Instance deletion initiated", "instance_name", name) } func WaitInstanceToBeRemoved(name string, timeout time.Duration) error { var timeWaited time.Duration = 0 var instance *params.Instance - log.Printf("Waiting for instance %s to be removed", name) + slog.Info("Waiting for instance to be removed", "instance_name", name) for timeWaited < timeout { instances, err := listInstances(cli, authToken) if err != nil { @@ -82,7 +82,7 @@ func WaitPoolInstances(poolID string, status commonParams.InstanceStatus, runner return err } - log.Printf("Waiting for pool %s instances to reach status: %s and runner status: %s", poolID, status, runnerStatus) + slog.Info("Waiting for pool instances to reach desired status", "pool_id", poolID, "desired_status", status, "desired_runner_status", runnerStatus) for timeWaited < timeout { poolInstances, err := listPoolInstances(cli, authToken, poolID) if err != nil { @@ -96,7 +96,13 @@ func WaitPoolInstances(poolID string, status commonParams.InstanceStatus, runner } } - log.Printf("Pool %s instance reached status: %s and runner status: %s: %d/%d", poolID, status, runnerStatus, instancesCount, len(poolInstances)) + slog.Info( + "Pool instance reached status", + "pool_id", poolID, + "status", status, + "runner_status", runnerStatus, + "desired_instance_count", instancesCount, + "pool_instance_count", len(poolInstances)) if instancesCount == int(pool.MinIdleRunners) && instancesCount == len(poolInstances) { return nil } diff --git a/test/integration/e2e/jobs.go b/test/integration/e2e/jobs.go index d8abccf2..f3a1f3c6 100644 --- a/test/integration/e2e/jobs.go +++ b/test/integration/e2e/jobs.go @@ -2,7 +2,7 @@ package e2e import ( "fmt" - "log" + "log/slog" "time" commonParams "github.com/cloudbase/garm-provider-common/params" @@ -10,7 +10,7 @@ import ( ) func ValidateJobLifecycle(label string) { - log.Printf("Validate GARM job lifecycle with label %s", label) + slog.Info("Validate GARM job lifecycle", "label", label) // wait for job list to be updated job, err := waitLabelledJob(label, 4*time.Minute) @@ -58,7 +58,7 @@ func waitLabelledJob(label string, timeout time.Duration) (*params.Job, error) { var jobs params.Jobs var err error - log.Printf("Waiting for job with label %s", label) + slog.Info("Waiting for job", "label", label) for timeWaited < timeout { jobs, err = listJobs(cli, authToken) if err != nil { @@ -85,7 +85,7 @@ func waitJobStatus(id int64, status params.JobStatus, timeout time.Duration) (*p var timeWaited time.Duration = 0 var job *params.Job - log.Printf("Waiting for job %d to reach status %s", id, status) + slog.Info("Waiting for job to reach status", "job_id", id, "status", status) for timeWaited < timeout { jobs, err := listJobs(cli, authToken) if err != nil { diff --git a/test/integration/e2e/organizations.go b/test/integration/e2e/organizations.go index 490ca784..8f511215 100644 --- a/test/integration/e2e/organizations.go +++ b/test/integration/e2e/organizations.go @@ -1,7 +1,7 @@ package e2e import ( - "log" + "log/slog" "time" commonParams "github.com/cloudbase/garm-provider-common/params" @@ -9,7 +9,7 @@ import ( ) func CreateOrg(orgName, credentialsName, orgWebhookSecret string) *params.Organization { - log.Printf("Create org %s", orgName) + slog.Info("Create org", "org_name", orgName) orgParams := params.CreateOrgParams{ Name: orgName, CredentialsName: credentialsName, @@ -23,7 +23,7 @@ func CreateOrg(orgName, credentialsName, orgWebhookSecret string) *params.Organi } func UpdateOrg(id, credentialsName string) *params.Organization { - log.Printf("Update org %s", id) + slog.Info("Update org", "org_id", id) updateParams := params.UpdateEntityParams{ CredentialsName: credentialsName, } @@ -35,7 +35,7 @@ func UpdateOrg(id, credentialsName string) *params.Organization { } func InstallOrgWebhook(id string) *params.HookInfo { - log.Printf("Install org %s webhook", id) + slog.Info("Install org webhook", "org_id", id) webhookParams := params.InstallWebhookParams{ WebhookEndpointType: params.WebhookEndpointDirect, } @@ -51,14 +51,14 @@ func InstallOrgWebhook(id string) *params.HookInfo { } func UninstallOrgWebhook(id string) { - log.Printf("Uninstall org %s webhook", id) + slog.Info("Uninstall org webhook", "org_id", id) if err := uninstallOrgWebhook(cli, authToken, id); err != nil { panic(err) } } func CreateOrgPool(orgID string, poolParams params.CreatePoolParams) *params.Pool { - log.Printf("Create org %s pool", orgID) + slog.Info("Create org pool", "org_id", orgID) pool, err := createOrgPool(cli, authToken, orgID, poolParams) if err != nil { panic(err) @@ -67,7 +67,7 @@ func CreateOrgPool(orgID string, poolParams params.CreatePoolParams) *params.Poo } func GetOrgPool(orgID, orgPoolID string) *params.Pool { - log.Printf("Get org %s pool %s", orgID, orgPoolID) + slog.Info("Get org pool", "org_id", orgID, "pool_id", orgPoolID) pool, err := getOrgPool(cli, authToken, orgID, orgPoolID) if err != nil { panic(err) @@ -76,7 +76,7 @@ func GetOrgPool(orgID, orgPoolID string) *params.Pool { } func UpdateOrgPool(orgID, orgPoolID string, maxRunners, minIdleRunners uint) *params.Pool { - log.Printf("Update org %s pool %s", orgID, orgPoolID) + slog.Info("Update org pool", "org_id", orgID, "pool_id", orgPoolID) poolParams := params.UpdatePoolParams{ MinIdleRunners: &minIdleRunners, MaxRunners: &maxRunners, @@ -89,7 +89,7 @@ func UpdateOrgPool(orgID, orgPoolID string, maxRunners, minIdleRunners uint) *pa } func DeleteOrgPool(orgID, orgPoolID string) { - log.Printf("Delete org %s pool %s", orgID, orgPoolID) + slog.Info("Delete org pool", "org_id", orgID, "pool_id", orgPoolID) if err := deleteOrgPool(cli, authToken, orgID, orgPoolID); err != nil { panic(err) } @@ -111,7 +111,7 @@ func WaitOrgRunningIdleInstances(orgID string, timeout time.Duration) { func dumpOrgInstancesDetails(orgID string) error { // print org details - log.Printf("Dumping org %s details", orgID) + slog.Info("Dumping org details", "org_id", orgID) org, err := getOrg(cli, authToken, orgID) if err != nil { return err @@ -121,7 +121,7 @@ func dumpOrgInstancesDetails(orgID string) error { } // print org instances details - log.Printf("Dumping org %s instances details", orgID) + slog.Info("Dumping org instances details", "org_id", orgID) instances, err := listOrgInstances(cli, authToken, orgID) if err != nil { return err @@ -131,7 +131,7 @@ func dumpOrgInstancesDetails(orgID string) error { if err != nil { return err } - log.Printf("Instance %s info:", instance.Name) + slog.Info("Instance info", "instance_name", instance.Name) if err := printJsonResponse(instance); err != nil { return err } diff --git a/test/integration/e2e/pools.go b/test/integration/e2e/pools.go index 34d530f2..f00e07eb 100644 --- a/test/integration/e2e/pools.go +++ b/test/integration/e2e/pools.go @@ -2,7 +2,7 @@ package e2e import ( "fmt" - "log" + "log/slog" "time" "github.com/cloudbase/garm/params" @@ -13,13 +13,13 @@ func waitPoolNoInstances(id string, timeout time.Duration) error { var pool *params.Pool var err error - log.Printf("Wait until pool %s has no instances", id) + slog.Info("Wait until pool has no instances", "pool_id", id) for timeWaited < timeout { pool, err = getPool(cli, authToken, id) if err != nil { return err } - log.Printf("Current pool instances: %d", len(pool.Instances)) + slog.Info("Current pool instances", "instance_count", len(pool.Instances)) if len(pool.Instances) == 0 { return nil } @@ -45,7 +45,7 @@ func dumpPoolInstancesDetails(poolID string) error { if err != nil { return err } - log.Printf("Instance %s details:", instance.Name) + slog.Info("Instance details", "instance_name", instance.Name) if err := printJsonResponse(instanceDetails); err != nil { return err } diff --git a/test/integration/e2e/repositories.go b/test/integration/e2e/repositories.go index 72c10e32..b1e9236d 100644 --- a/test/integration/e2e/repositories.go +++ b/test/integration/e2e/repositories.go @@ -1,7 +1,7 @@ package e2e import ( - "log" + "log/slog" "time" commonParams "github.com/cloudbase/garm-provider-common/params" @@ -9,7 +9,7 @@ import ( ) func CreateRepo(orgName, repoName, credentialsName, repoWebhookSecret string) *params.Repository { - log.Printf("Create repository %s/%s", orgName, repoName) + slog.Info("Create repository", "owner_name", orgName, "repo_name", repoName) createParams := params.CreateRepoParams{ Owner: orgName, Name: repoName, @@ -24,7 +24,7 @@ func CreateRepo(orgName, repoName, credentialsName, repoWebhookSecret string) *p } func UpdateRepo(id, credentialsName string) *params.Repository { - log.Printf("Update repo %s", id) + slog.Info("Update repo", "repo_id", id) updateParams := params.UpdateEntityParams{ CredentialsName: credentialsName, } @@ -36,7 +36,7 @@ func UpdateRepo(id, credentialsName string) *params.Repository { } func InstallRepoWebhook(id string) *params.HookInfo { - log.Printf("Install repo %s webhook", id) + slog.Info("Install repo webhook", "repo_id", id) webhookParams := params.InstallWebhookParams{ WebhookEndpointType: params.WebhookEndpointDirect, } @@ -52,14 +52,14 @@ func InstallRepoWebhook(id string) *params.HookInfo { } func UninstallRepoWebhook(id string) { - log.Printf("Uninstall repo %s webhook", id) + slog.Info("Uninstall repo webhook", "repo_id", id) if err := uninstallRepoWebhook(cli, authToken, id); err != nil { panic(err) } } func CreateRepoPool(repoID string, poolParams params.CreatePoolParams) *params.Pool { - log.Printf("Create repo %s pool", repoID) + slog.Info("Create repo pool", "repo_id", repoID) pool, err := createRepoPool(cli, authToken, repoID, poolParams) if err != nil { panic(err) @@ -68,7 +68,7 @@ func CreateRepoPool(repoID string, poolParams params.CreatePoolParams) *params.P } func GetRepoPool(repoID, repoPoolID string) *params.Pool { - log.Printf("Get repo %s pool %s", repoID, repoPoolID) + slog.Info("Get repo pool", "repo_id", repoID, "pool_id", repoPoolID) pool, err := getRepoPool(cli, authToken, repoID, repoPoolID) if err != nil { panic(err) @@ -77,7 +77,7 @@ func GetRepoPool(repoID, repoPoolID string) *params.Pool { } func UpdateRepoPool(repoID, repoPoolID string, maxRunners, minIdleRunners uint) *params.Pool { - log.Printf("Update repo %s pool %s", repoID, repoPoolID) + slog.Info("Update repo pool", "repo_id", repoID, "pool_id", repoPoolID) poolParams := params.UpdatePoolParams{ MinIdleRunners: &minIdleRunners, MaxRunners: &maxRunners, @@ -90,14 +90,14 @@ func UpdateRepoPool(repoID, repoPoolID string, maxRunners, minIdleRunners uint) } func DeleteRepoPool(repoID, repoPoolID string) { - log.Printf("Delete repo %s pool %s", repoID, repoPoolID) + slog.Info("Delete repo pool", "repo_id", repoID, "pool_id", repoPoolID) if err := deleteRepoPool(cli, authToken, repoID, repoPoolID); err != nil { panic(err) } } func DisableRepoPool(repoID, repoPoolID string) { - log.Printf("Disable repo %s pool %s", repoID, repoPoolID) + slog.Info("Disable repo pool", "repo_id", repoID, "pool_id", repoPoolID) enabled := false poolParams := params.UpdatePoolParams{Enabled: &enabled} if _, err := updateRepoPool(cli, authToken, repoID, repoPoolID, poolParams); err != nil { @@ -121,7 +121,7 @@ func WaitRepoRunningIdleInstances(repoID string, timeout time.Duration) { func dumpRepoInstancesDetails(repoID string) error { // print repo details - log.Printf("Dumping repo %s details", repoID) + slog.Info("Dumping repo details", "repo_id", repoID) repo, err := getRepo(cli, authToken, repoID) if err != nil { return err @@ -131,7 +131,7 @@ func dumpRepoInstancesDetails(repoID string) error { } // print repo instances details - log.Printf("Dumping repo %s instances details", repoID) + slog.Info("Dumping repo instances details", "repo_id", repoID) instances, err := listRepoInstances(cli, authToken, repoID) if err != nil { return err @@ -141,7 +141,7 @@ func dumpRepoInstancesDetails(repoID string) error { if err != nil { return err } - log.Printf("Instance %s info:", instance.Name) + slog.Info("Instance info", "instance_name", instance.Name) if err := printJsonResponse(instance); err != nil { return err } diff --git a/test/integration/e2e/utils.go b/test/integration/e2e/utils.go index d849b797..ed8c2d62 100644 --- a/test/integration/e2e/utils.go +++ b/test/integration/e2e/utils.go @@ -2,7 +2,7 @@ package e2e import ( "encoding/json" - "log" + "log/slog" ) func printJsonResponse(resp interface{}) error { @@ -10,6 +10,6 @@ func printJsonResponse(resp interface{}) error { if err != nil { return err } - log.Println(string(b)) + slog.Info(string(b)) return nil } diff --git a/test/integration/gh_cleanup/main.go b/test/integration/gh_cleanup/main.go index 25773684..b841652e 100644 --- a/test/integration/gh_cleanup/main.go +++ b/test/integration/gh_cleanup/main.go @@ -2,7 +2,7 @@ package main import ( "fmt" - "log" + "log/slog" "os" "github.com/cloudbase/garm/test/integration/e2e" @@ -21,7 +21,7 @@ func main() { _ = e2e.GhOrgRunnersCleanup(ghToken, orgName, controllerID) _ = e2e.GhRepoRunnersCleanup(ghToken, orgName, repoName, controllerID) } else { - log.Println("Env variable GARM_CONTROLLER_ID is not set, skipping GitHub runners cleanup") + slog.Warn("Env variable GARM_CONTROLLER_ID is not set, skipping GitHub runners cleanup") } baseURL, baseUrlFound := os.LookupEnv("GARM_BASE_URL") @@ -30,6 +30,6 @@ func main() { _ = e2e.GhOrgWebhookCleanup(ghToken, webhookURL, orgName) _ = e2e.GhRepoWebhookCleanup(ghToken, webhookURL, orgName, repoName) } else { - log.Println("Env variables GARM_CONTROLLER_ID & GARM_BASE_URL are not set, skipping webhooks cleanup") + slog.Warn("Env variables GARM_CONTROLLER_ID & GARM_BASE_URL are not set, skipping webhooks cleanup") } } diff --git a/test/integration/main.go b/test/integration/main.go index 04b96861..06f22edc 100644 --- a/test/integration/main.go +++ b/test/integration/main.go @@ -2,7 +2,7 @@ package main import ( "fmt" - "log" + "log/slog" "os" "time" @@ -120,19 +120,19 @@ func main() { _ = e2e.UpdateRepoPool(repo.ID, repoPool2.ID, repoPoolParams2.MaxRunners, 1) err := e2e.WaitPoolInstances(repoPool2.ID, commonParams.InstanceRunning, params.RunnerPending, 1*time.Minute) if err != nil { - log.Printf("Failed to wait for instance to be running: %v", err) + slog.With(slog.Any("error", err)).Error("Failed to wait for instance to be running") } repoPool2 = e2e.GetRepoPool(repo.ID, repoPool2.ID) e2e.DisableRepoPool(repo.ID, repoPool2.ID) e2e.DeleteInstance(repoPool2.Instances[0].Name, false) err = e2e.WaitPoolInstances(repoPool2.ID, commonParams.InstancePendingDelete, params.RunnerPending, 1*time.Minute) if err != nil { - log.Printf("Failed to wait for instance to be running: %v", err) + slog.With(slog.Any("error", err)).Error("Failed to wait for instance to be running") } e2e.DeleteInstance(repoPool2.Instances[0].Name, true) // delete instance with forceRemove err = e2e.WaitInstanceToBeRemoved(repoPool2.Instances[0].Name, 1*time.Minute) if err != nil { - log.Printf("Failed to wait for instance to be removed: %v", err) + slog.With(slog.Any("error", err)).Error("Failed to wait for instance to be removed") } e2e.DeleteRepoPool(repo.ID, repoPool2.ID) diff --git a/testdata/config.toml b/testdata/config.toml index 34465cb7..b9905553 100644 --- a/testdata/config.toml +++ b/testdata/config.toml @@ -35,15 +35,36 @@ webhook_url = "https://garm.example.com/webhooks" # webhooks for repositories or organizations. enable_webhook_management = true +# DEPRECATED: Use the [logging] section to set this option. # Uncomment this line if you'd like to log to a file instead of standard output. # log_file = "/tmp/runner-manager.log" +# DEPRECATED: Use the [logging] section to set this option. # Enable streaming logs via web sockets. Use garm-cli debug-log. enable_log_streamer = false # Enable the golang debug server. See the documentation in the "doc" folder for more information. debug_server = false + +[logging] +# Uncomment this line if you'd like to log to a file instead of standard output. +# log_file = "/tmp/runner-manager.log" + +# enable_log_streamer enables streaming the logs over websockets +enable_log_streamer = true +# log_format is the output format of the logs. GARM uses structured logging and can +# output as "text" or "json" +log_format = "text" +# log_level is the logging level GARM will output. Available log levels are: +# * debug +# * info +# * warn +# * error +log_level = "debug" +# log_source will output information about the function that generated the log line. +log_source = false + [metrics] # Toggle metrics. If set to false, the API endpoint for metrics collection will # be disabled. diff --git a/util/logging.go b/util/logging.go new file mode 100644 index 00000000..ac35863b --- /dev/null +++ b/util/logging.go @@ -0,0 +1,30 @@ +package util + +import ( + "context" + "log/slog" +) + +type slogContextKey string + +const ( + slogCtxFields slogContextKey = "slog_ctx_fields" +) + +type ContextHandler struct { + slog.Handler +} + +func (h ContextHandler) Handle(ctx context.Context, r slog.Record) error { + attrs, ok := ctx.Value(slogCtxFields).([]slog.Attr) + if ok { + for _, v := range attrs { + r.AddAttrs(v) + } + } + return h.Handler.Handle(ctx, r) +} + +func WithContext(ctx context.Context, attrs ...slog.Attr) context.Context { + return context.WithValue(ctx, slogCtxFields, attrs) +} diff --git a/websocket/client.go b/websocket/client.go index 28429a3a..ef420460 100644 --- a/websocket/client.go +++ b/websocket/client.go @@ -1,7 +1,7 @@ package websocket import ( - "log" + "log/slog" "time" "github.com/google/uuid" @@ -56,7 +56,7 @@ func (c *Client) clientReader() { }() c.conn.SetReadLimit(maxMessageSize) if err := c.conn.SetReadDeadline(time.Now().Add(pongWait)); err != nil { - log.Printf("failed to set read deadline: %s", err) + slog.With(slog.Any("error", err)).Error("failed to set read deadline") } c.conn.SetPongHandler(func(string) error { if err := c.conn.SetReadDeadline(time.Now().Add(pongWait)); err != nil { @@ -86,23 +86,23 @@ func (c *Client) clientWriter() { select { case message, ok := <-c.send: if err := c.conn.SetWriteDeadline(time.Now().Add(writeWait)); err != nil { - log.Printf("failed to set write deadline: %s", err) + slog.With(slog.Any("error", err)).Error("failed to set write deadline") } if !ok { // The hub closed the channel. if err := c.conn.WriteMessage(websocket.CloseMessage, []byte{}); err != nil { - log.Printf("failed to write message: %s", err) + slog.With(slog.Any("error", err)).Error("failed to write message") } return } if err := c.conn.WriteMessage(websocket.TextMessage, message); err != nil { - log.Printf("error sending message: %v", err) + slog.With(slog.Any("error", err)).Error("error sending message") return } case <-ticker.C: if err := c.conn.SetWriteDeadline(time.Now().Add(writeWait)); err != nil { - log.Printf("failed to set write deadline: %s", err) + slog.With(slog.Any("error", err)).Error("failed to set write deadline") } if err := c.conn.WriteMessage(websocket.PingMessage, nil); err != nil { return