From ae327f545e75e422685e2eba1ef2c8573d1492e8 Mon Sep 17 00:00:00 2001 From: Christoph Kluge Date: Fri, 25 Oct 2024 15:23:49 +0200 Subject: [PATCH 1/8] add logging to rest stopJobHandler --- internal/api/rest.go | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/internal/api/rest.go b/internal/api/rest.go index e43cf51..f143a7f 100644 --- a/internal/api/rest.go +++ b/internal/api/rest.go @@ -473,11 +473,11 @@ func (api *RestApi) getCompleteJobById(rw http.ResponseWriter, r *http.Request) job, err = api.JobRepository.FindById(id) } else { - handleError(errors.New("the parameter 'id' is required"), http.StatusBadRequest, rw) + handleError(fmt.Errorf("the parameter 'id' is required"), http.StatusBadRequest, rw) return } if err != nil { - handleError(fmt.Errorf("finding job failed: %w", err), http.StatusUnprocessableEntity, rw) + handleError(fmt.Errorf("finding job with db id %s failed: %w", id, err), http.StatusUnprocessableEntity, rw) return } @@ -506,7 +506,7 @@ func (api *RestApi) getCompleteJobById(rw http.ResponseWriter, r *http.Request) if r.URL.Query().Get("all-metrics") == "true" { data, err = metricdata.LoadData(job, nil, scopes, r.Context()) if err != nil { - log.Warn("Error while loading job data") + log.Warnf("REST: error while loading all-metrics job data for JobID %d on %s", job.JobID, job.Cluster) return } } @@ -571,7 +571,7 @@ func (api *RestApi) getJobById(rw http.ResponseWriter, r *http.Request) { return } if err != nil { - handleError(fmt.Errorf("finding job failed: %w", err), http.StatusUnprocessableEntity, rw) + handleError(fmt.Errorf("finding job with db id %s failed: %w", id, err), http.StatusUnprocessableEntity, rw) return } @@ -603,7 +603,7 @@ func (api *RestApi) getJobById(rw http.ResponseWriter, r *http.Request) { data, err := metricdata.LoadData(job, metrics, scopes, r.Context()) if err != nil { - log.Warn("Error while loading job data") + log.Warnf("REST: error while loading job data for JobID %d on %s", job.JobID, job.Cluster) return } @@ -1096,12 +1096,12 @@ func (api *RestApi) deleteJobBefore(rw http.ResponseWriter, r *http.Request) { func (api *RestApi) checkAndHandleStopJob(rw http.ResponseWriter, job *schema.Job, req StopJobApiRequest) { // Sanity checks if job == nil || job.StartTime.Unix() >= req.StopTime || job.State != schema.JobStateRunning { - handleError(errors.New("stopTime must be larger than startTime and only running jobs can be stopped"), http.StatusBadRequest, rw) + handleError(fmt.Errorf("jobId %d (id %d) on %s : stopTime %d must be larger than startTime %d and only running jobs can be stopped (state is: %s)", job.JobID, job.ID, job.Cluster, req.StopTime, job.StartTime.Unix(), job.State), http.StatusBadRequest, rw) return } if req.State != "" && !req.State.Valid() { - handleError(fmt.Errorf("invalid job state: %#v", req.State), http.StatusBadRequest, rw) + handleError(fmt.Errorf("jobId %d (id %d) on %s : invalid requested job state: %#v", job.JobID, job.ID, job.Cluster, req.State), http.StatusBadRequest, rw) return } else if req.State == "" { req.State = schema.JobStateCompleted @@ -1111,11 +1111,11 @@ func (api *RestApi) checkAndHandleStopJob(rw http.ResponseWriter, job *schema.Jo job.Duration = int32(req.StopTime - job.StartTime.Unix()) job.State = req.State if err := api.JobRepository.Stop(job.ID, job.Duration, job.State, job.MonitoringStatus); err != nil { - handleError(fmt.Errorf("marking job as stopped failed: %w", err), http.StatusInternalServerError, rw) + handleError(fmt.Errorf("jobId %d (id %d) on %s : marking job as '%s' (duration: %d) in DB failed: %w", job.JobID, job.ID, job.Cluster, job.State, job.Duration, err), http.StatusInternalServerError, rw) return } - log.Printf("archiving job... (dbid: %d): cluster=%s, jobId=%d, user=%s, startTime=%s", job.ID, job.Cluster, job.JobID, job.User, job.StartTime) + log.Printf("archiving job... (dbid: %d): cluster=%s, jobId=%d, user=%s, startTime=%s, duration=%d, state=%s", job.ID, job.Cluster, job.JobID, job.User, job.StartTime, job.Duration, job.State) // Send a response (with status OK). This means that erros that happen from here on forward // can *NOT* be communicated to the client. If reading from a MetricDataRepository or From f5cc5d07fd1e60b915eddaa898e639634a6f1086 Mon Sep 17 00:00:00 2001 From: Christoph Kluge Date: Tue, 29 Oct 2024 17:01:05 +0100 Subject: [PATCH 2/8] add more logging to rest api stopJobByRequest --- internal/api/rest.go | 1 + 1 file changed, 1 insertion(+) diff --git a/internal/api/rest.go b/internal/api/rest.go index f143a7f..d38a94d 100644 --- a/internal/api/rest.go +++ b/internal/api/rest.go @@ -929,6 +929,7 @@ func (api *RestApi) stopJobByRequest(rw http.ResponseWriter, r *http.Request) { return } + log.Printf("loading db job from request for stopJobByRequest... : jobId=%d, cluster=%s, startTime=%d", *req.JobId, *req.Cluster, *req.StartTime) job, err = api.JobRepository.Find(req.JobId, req.Cluster, req.StartTime) if err != nil { From c4a901504d59d3be147ea06b9173f67e2143e8e0 Mon Sep 17 00:00:00 2001 From: Christoph Kluge Date: Tue, 29 Oct 2024 18:25:41 +0100 Subject: [PATCH 3/8] change debug format key --- internal/api/rest.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/api/rest.go b/internal/api/rest.go index d38a94d..25f78b5 100644 --- a/internal/api/rest.go +++ b/internal/api/rest.go @@ -929,7 +929,7 @@ func (api *RestApi) stopJobByRequest(rw http.ResponseWriter, r *http.Request) { return } - log.Printf("loading db job from request for stopJobByRequest... : jobId=%d, cluster=%s, startTime=%d", *req.JobId, *req.Cluster, *req.StartTime) + log.Printf("loading db job from request for stopJobByRequest... : jobId=%d, cluster=%v, startTime=%d", req.JobId, req.Cluster, req.StartTime) job, err = api.JobRepository.Find(req.JobId, req.Cluster, req.StartTime) if err != nil { From 597ee1dad761155666b35cb29660a5d3b692d392 Mon Sep 17 00:00:00 2001 From: Christoph Kluge Date: Tue, 29 Oct 2024 18:39:23 +0100 Subject: [PATCH 4/8] change log to request and sql prints --- internal/api/rest.go | 2 +- internal/repository/job.go | 3 +++ 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/internal/api/rest.go b/internal/api/rest.go index 25f78b5..eed30b9 100644 --- a/internal/api/rest.go +++ b/internal/api/rest.go @@ -929,7 +929,7 @@ func (api *RestApi) stopJobByRequest(rw http.ResponseWriter, r *http.Request) { return } - log.Printf("loading db job from request for stopJobByRequest... : jobId=%d, cluster=%v, startTime=%d", req.JobId, req.Cluster, req.StartTime) + log.Printf("loading db job for stopJobByRequest... : stopJobApiRequest=%#v", req) job, err = api.JobRepository.Find(req.JobId, req.Cluster, req.StartTime) if err != nil { diff --git a/internal/repository/job.go b/internal/repository/job.go index b42598d..54ec6d0 100644 --- a/internal/repository/job.go +++ b/internal/repository/job.go @@ -235,6 +235,9 @@ func (r *JobRepository) Find( q = q.Where("job.start_time = ?", *startTime) } + s, _, _ := q.ToSql() + log.Printf("trying to find db job with query: %s", s) + log.Debugf("Timer Find %s", time.Since(start)) return scanJob(q.RunWith(r.stmtCache).QueryRow()) } From c120d6517fb32493bb14455917873167757fdd01 Mon Sep 17 00:00:00 2001 From: Christoph Kluge Date: Wed, 30 Oct 2024 16:24:58 +0100 Subject: [PATCH 5/8] change logging key, add args, add orderby id job.Find() --- internal/api/rest.go | 2 +- internal/repository/job.go | 6 ++++-- 2 files changed, 5 insertions(+), 3 deletions(-) diff --git a/internal/api/rest.go b/internal/api/rest.go index eed30b9..78b28af 100644 --- a/internal/api/rest.go +++ b/internal/api/rest.go @@ -929,7 +929,7 @@ func (api *RestApi) stopJobByRequest(rw http.ResponseWriter, r *http.Request) { return } - log.Printf("loading db job for stopJobByRequest... : stopJobApiRequest=%#v", req) + log.Printf("loading db job for stopJobByRequest... : stopJobApiRequest=%v", req) job, err = api.JobRepository.Find(req.JobId, req.Cluster, req.StartTime) if err != nil { diff --git a/internal/repository/job.go b/internal/repository/job.go index 54ec6d0..644d427 100644 --- a/internal/repository/job.go +++ b/internal/repository/job.go @@ -235,8 +235,10 @@ func (r *JobRepository) Find( q = q.Where("job.start_time = ?", *startTime) } - s, _, _ := q.ToSql() - log.Printf("trying to find db job with query: %s", s) + q = q.OrderBy("job.id DESC") // always use newest matching job by db id + + s, args, _ := q.ToSql() + log.Printf("trying to find db job with query: %s | %v", s, args) log.Debugf("Timer Find %s", time.Since(start)) return scanJob(q.RunWith(r.stmtCache).QueryRow()) From eabc6212eaea3e229882947da3bb1273f58e8647 Mon Sep 17 00:00:00 2001 From: Christoph Kluge Date: Thu, 31 Oct 2024 13:36:27 +0100 Subject: [PATCH 6/8] add debug logging for user context and web render --- internal/repository/user.go | 3 ++- internal/routerConfig/routes.go | 11 +++++++++++ 2 files changed, 13 insertions(+), 1 deletion(-) diff --git a/internal/repository/user.go b/internal/repository/user.go index 3b7d945..cd7efe9 100644 --- a/internal/repository/user.go +++ b/internal/repository/user.go @@ -321,9 +321,10 @@ const ContextUserKey ContextKey = "user" func GetUserFromContext(ctx context.Context) *schema.User { x := ctx.Value(ContextUserKey) if x == nil { + log.Warnf("no user retrieved from context") return nil } - + log.Infof("user retrieved from context: %v", x.(*schema.User)) return x.(*schema.User) } diff --git a/internal/routerConfig/routes.go b/internal/routerConfig/routes.go index 1dd6dee..9ed5638 100644 --- a/internal/routerConfig/routes.go +++ b/internal/routerConfig/routes.go @@ -254,6 +254,9 @@ func SetupRoutes(router *mux.Router, buildInfo web.Build) { for _, route := range routes { route := route router.HandleFunc(route.Route, func(rw http.ResponseWriter, r *http.Request) { + + log.Info(">>> HELLO ROUTE HANDLER ...") + conf, err := userCfgRepo.GetUIConfig(repository.GetUserFromContext(r.Context())) if err != nil { http.Error(rw, err.Error(), http.StatusInternalServerError) @@ -261,15 +264,21 @@ func SetupRoutes(router *mux.Router, buildInfo web.Build) { } title := route.Title + log.Infof(">>> >>> ROUTE TITLE : %s ", title) + infos := route.Setup(map[string]interface{}{}, r) if id, ok := infos["id"]; ok { title = strings.Replace(route.Title, "", id.(string), 1) } + log.Infof(">>> >>> ROUTE INFOS : %v ", infos) // Get User -> What if NIL? user := repository.GetUserFromContext(r.Context()) + log.Infof(">>> >>> ROUTE USER : %v ", *user) + // Get Roles availableRoles, _ := schema.GetValidRolesMap(user) + log.Infof(">>> >>> ROUTE AVAILABLE ROLES : %v ", availableRoles) page := web.Page{ Title: title, @@ -279,10 +288,12 @@ func SetupRoutes(router *mux.Router, buildInfo web.Build) { Config: conf, Infos: infos, } + log.Infof(">>> >>> ROUTE PAGE : %v ", page) if route.Filter { page.FilterPresets = buildFilterPresets(r.URL.Query()) } + log.Infof(">>> >>> ROUTE FILTER : %v ", page.FilterPresets) web.RenderTemplate(rw, route.Template, &page) }) From 2c8b73e2e2ed0c4b62d07faa9a2e9154c8e6df64 Mon Sep 17 00:00:00 2001 From: Christoph Kluge Date: Thu, 31 Oct 2024 14:34:32 +0100 Subject: [PATCH 7/8] add logged timing to homeroute calls --- internal/repository/user.go | 2 +- internal/routerConfig/routes.go | 17 +++++++++-------- 2 files changed, 10 insertions(+), 9 deletions(-) diff --git a/internal/repository/user.go b/internal/repository/user.go index cd7efe9..19364dc 100644 --- a/internal/repository/user.go +++ b/internal/repository/user.go @@ -324,7 +324,7 @@ func GetUserFromContext(ctx context.Context) *schema.User { log.Warnf("no user retrieved from context") return nil } - log.Infof("user retrieved from context: %v", x.(*schema.User)) + // log.Infof("user retrieved from context: %v", x.(*schema.User)) return x.(*schema.User) } diff --git a/internal/routerConfig/routes.go b/internal/routerConfig/routes.go index 9ed5638..9540cd3 100644 --- a/internal/routerConfig/routes.go +++ b/internal/routerConfig/routes.go @@ -51,15 +51,21 @@ func setupHomeRoute(i InfoType, r *http.Request) InfoType { jobRepo := repository.GetJobRepository() groupBy := model.AggregateCluster + log.Infof(">>> HELLO HOME ROUTE") + + startJobCount := time.Now() stats, err := jobRepo.JobCountGrouped(r.Context(), nil, &groupBy) if err != nil { log.Warnf("failed to count jobs: %s", err.Error()) } + log.Infof("Timer HOME ROUTE startJobCount: %s", time.Since(startJobCount)) + startRunningJobCount := time.Now() stats, err = jobRepo.AddJobCountGrouped(r.Context(), nil, &groupBy, stats, "running") if err != nil { log.Warnf("failed to count running jobs: %s", err.Error()) } + log.Infof("Timer HOME ROUTE startRunningJobCount: %s", time.Since(startRunningJobCount)) i["clusters"] = stats @@ -72,6 +78,8 @@ func setupHomeRoute(i InfoType, r *http.Request) InfoType { } } + log.Infof("... BYE HOME ROUTE") + return i } @@ -254,7 +262,6 @@ func SetupRoutes(router *mux.Router, buildInfo web.Build) { for _, route := range routes { route := route router.HandleFunc(route.Route, func(rw http.ResponseWriter, r *http.Request) { - log.Info(">>> HELLO ROUTE HANDLER ...") conf, err := userCfgRepo.GetUIConfig(repository.GetUserFromContext(r.Context())) @@ -264,21 +271,16 @@ func SetupRoutes(router *mux.Router, buildInfo web.Build) { } title := route.Title - log.Infof(">>> >>> ROUTE TITLE : %s ", title) - infos := route.Setup(map[string]interface{}{}, r) if id, ok := infos["id"]; ok { title = strings.Replace(route.Title, "", id.(string), 1) } - log.Infof(">>> >>> ROUTE INFOS : %v ", infos) // Get User -> What if NIL? user := repository.GetUserFromContext(r.Context()) - log.Infof(">>> >>> ROUTE USER : %v ", *user) // Get Roles availableRoles, _ := schema.GetValidRolesMap(user) - log.Infof(">>> >>> ROUTE AVAILABLE ROLES : %v ", availableRoles) page := web.Page{ Title: title, @@ -288,12 +290,11 @@ func SetupRoutes(router *mux.Router, buildInfo web.Build) { Config: conf, Infos: infos, } - log.Infof(">>> >>> ROUTE PAGE : %v ", page) if route.Filter { page.FilterPresets = buildFilterPresets(r.URL.Query()) } - log.Infof(">>> >>> ROUTE FILTER : %v ", page.FilterPresets) + log.Infof("... ROUTE HANDLED: %s for %v", page.Title, page.User) web.RenderTemplate(rw, route.Template, &page) }) From 939dd2320a9c4b5c48e0afdf22546c9c76b14f5d Mon Sep 17 00:00:00 2001 From: Christoph Kluge Date: Thu, 31 Oct 2024 15:47:45 +0100 Subject: [PATCH 8/8] Cleanup debug logging, keep orderBy param for repo.Find --- internal/api/rest.go | 2 +- internal/repository/job.go | 6 +++--- internal/routerConfig/routes.go | 15 ++++----------- 3 files changed, 8 insertions(+), 15 deletions(-) diff --git a/internal/api/rest.go b/internal/api/rest.go index 78b28af..5f8e15c 100644 --- a/internal/api/rest.go +++ b/internal/api/rest.go @@ -929,7 +929,7 @@ func (api *RestApi) stopJobByRequest(rw http.ResponseWriter, r *http.Request) { return } - log.Printf("loading db job for stopJobByRequest... : stopJobApiRequest=%v", req) + // log.Printf("loading db job for stopJobByRequest... : stopJobApiRequest=%v", req) job, err = api.JobRepository.Find(req.JobId, req.Cluster, req.StartTime) if err != nil { diff --git a/internal/repository/job.go b/internal/repository/job.go index 644d427..84b13a0 100644 --- a/internal/repository/job.go +++ b/internal/repository/job.go @@ -235,10 +235,10 @@ func (r *JobRepository) Find( q = q.Where("job.start_time = ?", *startTime) } - q = q.OrderBy("job.id DESC") // always use newest matching job by db id + q = q.OrderBy("job.id DESC") // always use newest matching job by db id if more than one match - s, args, _ := q.ToSql() - log.Printf("trying to find db job with query: %s | %v", s, args) + // s, args, _ := q.ToSql() + // log.Printf("trying to find db job with query: %s | %v", s, args) log.Debugf("Timer Find %s", time.Since(start)) return scanJob(q.RunWith(r.stmtCache).QueryRow()) diff --git a/internal/routerConfig/routes.go b/internal/routerConfig/routes.go index 9540cd3..e7dc924 100644 --- a/internal/routerConfig/routes.go +++ b/internal/routerConfig/routes.go @@ -51,21 +51,19 @@ func setupHomeRoute(i InfoType, r *http.Request) InfoType { jobRepo := repository.GetJobRepository() groupBy := model.AggregateCluster - log.Infof(">>> HELLO HOME ROUTE") - - startJobCount := time.Now() + // startJobCount := time.Now() stats, err := jobRepo.JobCountGrouped(r.Context(), nil, &groupBy) if err != nil { log.Warnf("failed to count jobs: %s", err.Error()) } - log.Infof("Timer HOME ROUTE startJobCount: %s", time.Since(startJobCount)) + // log.Infof("Timer HOME ROUTE startJobCount: %s", time.Since(startJobCount)) - startRunningJobCount := time.Now() + // startRunningJobCount := time.Now() stats, err = jobRepo.AddJobCountGrouped(r.Context(), nil, &groupBy, stats, "running") if err != nil { log.Warnf("failed to count running jobs: %s", err.Error()) } - log.Infof("Timer HOME ROUTE startRunningJobCount: %s", time.Since(startRunningJobCount)) + // log.Infof("Timer HOME ROUTE startRunningJobCount: %s", time.Since(startRunningJobCount)) i["clusters"] = stats @@ -78,8 +76,6 @@ func setupHomeRoute(i InfoType, r *http.Request) InfoType { } } - log.Infof("... BYE HOME ROUTE") - return i } @@ -262,8 +258,6 @@ func SetupRoutes(router *mux.Router, buildInfo web.Build) { for _, route := range routes { route := route router.HandleFunc(route.Route, func(rw http.ResponseWriter, r *http.Request) { - log.Info(">>> HELLO ROUTE HANDLER ...") - conf, err := userCfgRepo.GetUIConfig(repository.GetUserFromContext(r.Context())) if err != nil { http.Error(rw, err.Error(), http.StatusInternalServerError) @@ -294,7 +288,6 @@ func SetupRoutes(router *mux.Router, buildInfo web.Build) { if route.Filter { page.FilterPresets = buildFilterPresets(r.URL.Query()) } - log.Infof("... ROUTE HANDLED: %s for %v", page.Title, page.User) web.RenderTemplate(rw, route.Template, &page) })