From 4a909a1ab2653ac3bb52b1bd08a95a929193c6c0 Mon Sep 17 00:00:00 2001 From: Nataly Musilah <115026536+Musilah@users.noreply.github.com> Date: Wed, 24 Jan 2024 20:01:35 +0300 Subject: [PATCH] MG-234 - Improve Logging Middleware (#272) Signed-off-by: Musilah --- auth/api/logging.go | 308 +++++++++++++++++++++-------- bootstrap/api/logging.go | 156 ++++++++++----- certs/api/logging.go | 72 +++++-- coap/api/logging.go | 40 ++-- consumers/notifiers/api/logging.go | 71 +++++-- consumers/writers/api/logging.go | 10 +- internal/groups/api/logging.go | 157 +++++++++++---- invitations/middleware/logging.go | 58 ++++-- lora/api/logging.go | 98 ++++++--- opcua/api/logging.go | 99 +++++++--- pkg/messaging/handler/logging.go | 106 +++------- provision/api/logging.go | 32 ++- readers/api/logging.go | 22 ++- things/api/logging.go | 186 ++++++++++++----- twins/api/logging.go | 93 ++++++--- users/api/logging.go | 269 +++++++++++++++++-------- ws/api/logging.go | 14 +- 17 files changed, 1248 insertions(+), 543 deletions(-) diff --git a/auth/api/logging.go b/auth/api/logging.go index f73b9b05fe..a99fd2a92d 100644 --- a/auth/api/logging.go +++ b/auth/api/logging.go @@ -28,12 +28,16 @@ func LoggingMiddleware(svc auth.Service, logger *slog.Logger) auth.Service { func (lm *loggingMiddleware) ListObjects(ctx context.Context, pr auth.PolicyReq, nextPageToken string, limit int32) (p auth.PolicyPage, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_objects took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Int64("limit", int64(limit)), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List objects failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List objects completed successfully", args...) }(time.Now()) return lm.svc.ListObjects(ctx, pr, nextPageToken, limit) @@ -41,12 +45,21 @@ func (lm *loggingMiddleware) ListObjects(ctx context.Context, pr auth.PolicyReq, func (lm *loggingMiddleware) ListAllObjects(ctx context.Context, pr auth.PolicyReq) (p auth.PolicyPage, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_all_objects took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("policy_request", + slog.String("object_type", pr.ObjectType), + slog.String("subject_id", pr.Subject), + slog.String("subject_type", pr.SubjectType), + slog.String("permission", pr.Permission), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List all objects failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List all objects completed successfully", args...) }(time.Now()) return lm.svc.ListAllObjects(ctx, pr) @@ -54,24 +67,30 @@ func (lm *loggingMiddleware) ListAllObjects(ctx context.Context, pr auth.PolicyR func (lm *loggingMiddleware) CountObjects(ctx context.Context, pr auth.PolicyReq) (count int, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method count_objects took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Count objects failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Count objects completed successfully", args...) }(time.Now()) return lm.svc.CountObjects(ctx, pr) } func (lm *loggingMiddleware) ListSubjects(ctx context.Context, pr auth.PolicyReq, nextPageToken string, limit int32) (p auth.PolicyPage, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_subjects took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List subjects failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List subjects completed successfully", args...) }(time.Now()) return lm.svc.ListSubjects(ctx, pr, nextPageToken, limit) @@ -79,12 +98,21 @@ func (lm *loggingMiddleware) ListSubjects(ctx context.Context, pr auth.PolicyReq func (lm *loggingMiddleware) ListAllSubjects(ctx context.Context, pr auth.PolicyReq) (p auth.PolicyPage, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_all_subjects took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("policy_request", + slog.String("sybject_type", pr.SubjectType), + slog.String("object_id", pr.Object), + slog.String("object_type", pr.ObjectType), + slog.String("permission", pr.Permission), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List all subjects failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List all subjects completed successfully", args...) }(time.Now()) return lm.svc.ListAllSubjects(ctx, pr) @@ -92,24 +120,37 @@ func (lm *loggingMiddleware) ListAllSubjects(ctx context.Context, pr auth.Policy func (lm *loggingMiddleware) CountSubjects(ctx context.Context, pr auth.PolicyReq) (count int, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_subjects took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Count subjects failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Count subjects completed successfully", args...) }(time.Now()) return lm.svc.CountSubjects(ctx, pr) } func (lm *loggingMiddleware) ListPermissions(ctx context.Context, pr auth.PolicyReq, filterPermissions []string) (p auth.Permissions, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_permissions took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Any("filter_permissions", filterPermissions), + slog.Group("policy_request", + slog.String("object_id", pr.Object), + slog.String("object_type", pr.ObjectType), + slog.String("subject_id", pr.Subject), + slog.String("subject_type", pr.SubjectType), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List permissions failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List permissions completed successfully", args...) }(time.Now()) return lm.svc.ListPermissions(ctx, pr, filterPermissions) @@ -117,16 +158,19 @@ func (lm *loggingMiddleware) ListPermissions(ctx context.Context, pr auth.Policy func (lm *loggingMiddleware) Issue(ctx context.Context, token string, key auth.Key) (tkn auth.Token, err error) { defer func(begin time.Time) { - d := "" - if key.Type != auth.AccessKey && !key.ExpiresAt.IsZero() { - d = fmt.Sprintf("with expiration date %v", key.ExpiresAt) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("key", + slog.String("subject", key.Subject), + slog.Any("type", key.Type), + ), } - message := fmt.Sprintf("Method issue for %d key %s took %s to complete", key.Type, d, time.Since(begin)) if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Issue key failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Issue key completed successfully", args...) }(time.Now()) return lm.svc.Issue(ctx, token, key) @@ -134,12 +178,16 @@ func (lm *loggingMiddleware) Issue(ctx context.Context, token string, key auth.K func (lm *loggingMiddleware) Revoke(ctx context.Context, token, id string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method revoke for key %s took %s to complete", id, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("key_id", id), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Revoke key failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Revoke key completed successfully", args...) }(time.Now()) return lm.svc.Revoke(ctx, token, id) @@ -147,12 +195,16 @@ func (lm *loggingMiddleware) Revoke(ctx context.Context, token, id string) (err func (lm *loggingMiddleware) RetrieveKey(ctx context.Context, token, id string) (key auth.Key, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method retrieve for key %s took %s to complete", id, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("key_id", id), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Retrieve key failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Retrieve key completed successfully", args...) }(time.Now()) return lm.svc.RetrieveKey(ctx, token, id) @@ -160,12 +212,19 @@ func (lm *loggingMiddleware) RetrieveKey(ctx context.Context, token, id string) func (lm *loggingMiddleware) Identify(ctx context.Context, token string) (id auth.Key, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method identify took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("key", + slog.String("subject", id.Subject), + slog.Any("type", id.Type), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Identify key failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Identify key completed successfully", args...) }(time.Now()) return lm.svc.Identify(ctx, token) @@ -173,36 +232,62 @@ func (lm *loggingMiddleware) Identify(ctx context.Context, token string) (id aut func (lm *loggingMiddleware) Authorize(ctx context.Context, pr auth.PolicyReq) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method authorize took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("object", + slog.String("id", pr.Object), + slog.String("type", pr.ObjectType), + ), + slog.Group("subject", + slog.String("id", pr.Subject), + slog.String("kind", pr.SubjectKind), + slog.String("type", pr.SubjectType), + ), + slog.String("permission", pr.Permission), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Authorize failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Authorize completed successfully", args...) }(time.Now()) return lm.svc.Authorize(ctx, pr) } func (lm *loggingMiddleware) AddPolicy(ctx context.Context, pr auth.PolicyReq) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method add_policy took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("policy_request", + slog.String("object_id", pr.Object), + slog.String("object_type", pr.ObjectType), + slog.String("subject_id", pr.Subject), + slog.String("subject_type", pr.SubjectType), + slog.String("relation", pr.Relation), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Add policy failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Add policy completed successfully", args...) }(time.Now()) return lm.svc.AddPolicy(ctx, pr) } func (lm *loggingMiddleware) AddPolicies(ctx context.Context, prs []auth.PolicyReq) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method create_policy_bulk took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn(fmt.Sprintf("Add %d policies failed to complete successfully", len(prs)), args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info(fmt.Sprintf("Add %d policies completed successfully", len(prs)), args...) }(time.Now()) return lm.svc.AddPolicies(ctx, prs) @@ -210,132 +295,199 @@ func (lm *loggingMiddleware) AddPolicies(ctx context.Context, prs []auth.PolicyR func (lm *loggingMiddleware) DeletePolicy(ctx context.Context, pr auth.PolicyReq) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method delete_policy took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("policy_request", + slog.String("object_id", pr.Object), + slog.String("object_type", pr.ObjectType), + slog.String("subject_id", pr.Subject), + slog.String("subject_type", pr.SubjectType), + slog.String("relation", pr.Relation), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Delete policy failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Delete policy completed successfully", args...) }(time.Now()) return lm.svc.DeletePolicy(ctx, pr) } func (lm *loggingMiddleware) DeletePolicies(ctx context.Context, prs []auth.PolicyReq) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method delete_policies took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn(fmt.Sprintf("Delete %d policies failed to complete successfully", len(prs)), args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info(fmt.Sprintf("Delete %d policies completed successfully", len(prs)), args...) }(time.Now()) return lm.svc.DeletePolicies(ctx, prs) } func (lm *loggingMiddleware) CreateDomain(ctx context.Context, token string, d auth.Domain) (do auth.Domain, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method create_domain took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("domain", + slog.String("id", d.ID), + slog.String("name", d.Name), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args := append(args, slog.String("error", err.Error())) + lm.logger.Warn("Create domain failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Create domain completed successfully", args...) }(time.Now()) return lm.svc.CreateDomain(ctx, token, d) } func (lm *loggingMiddleware) RetrieveDomain(ctx context.Context, token, id string) (do auth.Domain, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method retrieve_domain for domain id %s took %s to complete", id, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("domain_id", id), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Retrieve domain failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Retrieve domain completed successfully", args...) }(time.Now()) return lm.svc.RetrieveDomain(ctx, token, id) } func (lm *loggingMiddleware) RetrieveDomainPermissions(ctx context.Context, token, id string) (permissions auth.Permissions, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method retrieve_domain_permissions for domain id %s took %s to complete", id, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("domain_id", id), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Retrieve domain permissions failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Retrieve domain permissions completed successfully", args...) }(time.Now()) return lm.svc.RetrieveDomainPermissions(ctx, token, id) } func (lm *loggingMiddleware) UpdateDomain(ctx context.Context, token, id string, d auth.DomainReq) (do auth.Domain, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method update_domain for domain id %s took %s to complete", id, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("domain", + slog.String("id", id), + slog.Any("name", d.Name), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Update domain failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Update domain completed successfully", args...) }(time.Now()) return lm.svc.UpdateDomain(ctx, token, id, d) } func (lm *loggingMiddleware) ChangeDomainStatus(ctx context.Context, token, id string, d auth.DomainReq) (do auth.Domain, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method change_domain_status for domain id %s took %s to complete", id, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("domain", + slog.String("id", id), + slog.String("name", do.Name), + slog.Any("status", d.Status), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Change domain status failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Change domain status completed successfully", args...) }(time.Now()) return lm.svc.ChangeDomainStatus(ctx, token, id, d) } func (lm *loggingMiddleware) ListDomains(ctx context.Context, token string, page auth.Page) (do auth.DomainsPage, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_domains took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("page", + slog.Uint64("limit", page.Limit), + slog.Uint64("offset", page.Offset), + slog.Uint64("total", page.Total), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List domains failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List domains completed successfully", args...) }(time.Now()) return lm.svc.ListDomains(ctx, token, page) } func (lm *loggingMiddleware) AssignUsers(ctx context.Context, token, id string, userIds []string, relation string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method assign_users took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("domain_id", id), + slog.String("relation", relation), + slog.Any("user_ids", userIds), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Assign users to domain failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Assign users to domain completed successfully", args...) }(time.Now()) return lm.svc.AssignUsers(ctx, token, id, userIds, relation) } func (lm *loggingMiddleware) UnassignUsers(ctx context.Context, token, id string, userIds []string, relation string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method unassign_users took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("domain_id", id), + slog.String("relation", relation), + slog.Any("user_ids", userIds), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Unassign users to domain failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Unassign users to domain completed successfully", args...) }(time.Now()) return lm.svc.UnassignUsers(ctx, token, id, userIds, relation) } func (lm *loggingMiddleware) ListUserDomains(ctx context.Context, token, userID string, page auth.Page) (do auth.DomainsPage, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_user_domains took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("user_id", userID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List user domains failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List user domains completed successfully", args...) }(time.Now()) return lm.svc.ListUserDomains(ctx, token, userID, page) } diff --git a/bootstrap/api/logging.go b/bootstrap/api/logging.go index 43658a58e8..53fb12c4d9 100644 --- a/bootstrap/api/logging.go +++ b/bootstrap/api/logging.go @@ -7,7 +7,6 @@ package api import ( "context" - "fmt" "log/slog" "time" @@ -30,12 +29,16 @@ func LoggingMiddleware(svc bootstrap.Service, logger *slog.Logger) bootstrap.Ser // If the request fails, it logs the error. func (lm *loggingMiddleware) Add(ctx context.Context, token string, cfg bootstrap.Config) (saved bootstrap.Config, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method add using token %s with thing %s took %s to complete", token, saved.ThingID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", saved.ThingID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Add new bootstrap failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Add new bootstrap completed successfully", args...) }(time.Now()) return lm.svc.Add(ctx, token, cfg) @@ -45,87 +48,120 @@ func (lm *loggingMiddleware) Add(ctx context.Context, token string, cfg bootstra // If the request fails, it logs the error. func (lm *loggingMiddleware) View(ctx context.Context, token, id string) (saved bootstrap.Config, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method view using token %s with thing %s took %s to complete", token, saved.ThingID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", id), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("View thing config failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("View thing config completed successfully", args...) }(time.Now()) return lm.svc.View(ctx, token, id) } -// Update logs the update request. It logs token, bootstrap thing ID and the time it took to complete the request. +// Update logs the update request. It logs bootstrap thing ID and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) Update(ctx context.Context, token string, cfg bootstrap.Config) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method update using token %s with thing %s took %s to complete", token, cfg.ThingID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("config", + slog.String("thing_id", cfg.ThingID), + slog.String("name", cfg.Name), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Update boostrap config failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Update boostrap config completed successfully", args...) }(time.Now()) return lm.svc.Update(ctx, token, cfg) } -// UpdateCert logs the update_cert request. It logs token, thing ID and the time it took to complete the request. +// UpdateCert logs the update_cert request. It logs thing ID and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) UpdateCert(ctx context.Context, token, thingID, clientCert, clientKey, caCert string) (cfg bootstrap.Config, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method update_cert using token %s with thing id %s took %s to complete", token, thingID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", cfg.ThingID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Update bootstrap config certificate failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Update bootstrap config certificate completed successfully", args...) }(time.Now()) return lm.svc.UpdateCert(ctx, token, thingID, clientCert, clientKey, caCert) } -// UpdateConnections logs the update_connections request. It logs token, bootstrap ID and the time it took to complete the request. +// UpdateConnections logs the update_connections request. It logs bootstrap ID and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) UpdateConnections(ctx context.Context, token, id string, connections []string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method update_connections using token %s with thing %s took %s to complete", token, id, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", id), + slog.Any("connections", connections), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Update config connections failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Update config connections completed successfully", args...) }(time.Now()) return lm.svc.UpdateConnections(ctx, token, id, connections) } -// List logs the list request. It logs token, offset, limit and the time it took to complete the request. +// List logs the list request. It logs offset, limit and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) List(ctx context.Context, token string, filter bootstrap.Filter, offset, limit uint64) (res bootstrap.ConfigsPage, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list using token %s with offset %d and limit %d took %s to complete", token, offset, limit, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("page", + slog.Any("filter", filter), + slog.Uint64("offset", offset), + slog.Uint64("limit", limit), + slog.Uint64("total", res.Total), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List configs failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List configs completed successfully", args...) }(time.Now()) return lm.svc.List(ctx, token, filter, offset, limit) } -// Remove logs the remove request. It logs token, bootstrap ID and the time it took to complete the request. +// Remove logs the remove request. It logs bootstrap ID and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) Remove(ctx context.Context, token, id string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method remove using token %s with thing %s took %s to complete", token, id, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", id), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Remove bootstrap config failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Remove bootstrap config completed successfully", args...) }(time.Now()) return lm.svc.Remove(ctx, token, id) @@ -133,12 +169,16 @@ func (lm *loggingMiddleware) Remove(ctx context.Context, token, id string) (err func (lm *loggingMiddleware) Bootstrap(ctx context.Context, externalKey, externalID string, secure bool) (cfg bootstrap.Config, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method bootstrap for thing with external id %s took %s to complete", externalID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("external_id", externalID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("View bootstrap config failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("View bootstrap completed successfully", args...) }(time.Now()) return lm.svc.Bootstrap(ctx, externalKey, externalID, secure) @@ -146,12 +186,17 @@ func (lm *loggingMiddleware) Bootstrap(ctx context.Context, externalKey, externa func (lm *loggingMiddleware) ChangeState(ctx context.Context, token, id string, state bootstrap.State) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method change_state for token %s and thing %s took %s to complete", token, id, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("id", id), + slog.Any("state", state), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Change thing state failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Change thing state completed successfully", args...) }(time.Now()) return lm.svc.ChangeState(ctx, token, id, state) @@ -159,12 +204,20 @@ func (lm *loggingMiddleware) ChangeState(ctx context.Context, token, id string, func (lm *loggingMiddleware) UpdateChannelHandler(ctx context.Context, channel bootstrap.Channel) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method update_channel_handler for channel %s took %s to complete", channel.ID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("channel", + slog.String("id", channel.ID), + slog.String("name", channel.Name), + slog.Any("metadata", channel.Metadata), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Update channel handler failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Update channel handler completed successfully", args...) }(time.Now()) return lm.svc.UpdateChannelHandler(ctx, channel) @@ -172,12 +225,16 @@ func (lm *loggingMiddleware) UpdateChannelHandler(ctx context.Context, channel b func (lm *loggingMiddleware) RemoveConfigHandler(ctx context.Context, id string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method remove_config_handler for config %s took %s to complete", id, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("config_id", id), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Remove config handler failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Remove config handler completed successfully", args...) }(time.Now()) return lm.svc.RemoveConfigHandler(ctx, id) @@ -185,12 +242,16 @@ func (lm *loggingMiddleware) RemoveConfigHandler(ctx context.Context, id string) func (lm *loggingMiddleware) RemoveChannelHandler(ctx context.Context, id string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method remove_channel_handler for channel %s took %s to complete", id, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("channel_id", id), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Remove channel handler failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Remove channel handler completed successfully", args...) }(time.Now()) return lm.svc.RemoveChannelHandler(ctx, id) @@ -198,12 +259,17 @@ func (lm *loggingMiddleware) RemoveChannelHandler(ctx context.Context, id string func (lm *loggingMiddleware) DisconnectThingHandler(ctx context.Context, channelID, thingID string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method disconnect_thing_handler for channel %s and thing %s took %s to complete", channelID, thingID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("channel_id", channelID), + slog.String("thing_id", thingID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Disconnect thing handler failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Disconnect thing handler completed successfully", args...) }(time.Now()) return lm.svc.DisconnectThingHandler(ctx, channelID, thingID) diff --git a/certs/api/logging.go b/certs/api/logging.go index 63eba824c2..e83e0ac95c 100644 --- a/certs/api/logging.go +++ b/certs/api/logging.go @@ -7,7 +7,6 @@ package api import ( "context" - "fmt" "log/slog" "time" @@ -26,75 +25,106 @@ func LoggingMiddleware(svc certs.Service, logger *slog.Logger) certs.Service { return &loggingMiddleware{logger, svc} } -// IssueCert logs the issue_cert request. It logs the token, thing ID and the time it took to complete the request. +// IssueCert logs the issue_cert request. It logs the ttl, thing ID and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) IssueCert(ctx context.Context, token, thingID, ttl string) (c certs.Cert, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method issue_cert using token %s and thing %s took %s to complete", token, thingID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", thingID), + slog.String("ttl", ttl), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Issue certificate failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Issue certificate completed successfully", args...) }(time.Now()) return lm.svc.IssueCert(ctx, token, thingID, ttl) } -// ListCerts logs the list_certs request. It logs the token, thing ID and the time it took to complete the request. +// ListCerts logs the list_certs request. It logs the thing ID and the time it took to complete the request. func (lm *loggingMiddleware) ListCerts(ctx context.Context, token, thingID string, offset, limit uint64) (cp certs.Page, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_certs using token %s and thing id %s took %s to complete", token, thingID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", thingID), + slog.Group("page", + slog.Uint64("offset", cp.Offset), + slog.Uint64("limit", cp.Limit), + slog.Uint64("total", cp.Total), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List certificates failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List certificates completed successfully", args...) }(time.Now()) return lm.svc.ListCerts(ctx, token, thingID, offset, limit) } -// ListSerials logs the list_serials request. It logs the token, thing ID and the time it took to complete the request. +// ListSerials logs the list_serials request. It logs the thing ID and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) ListSerials(ctx context.Context, token, thingID string, offset, limit uint64) (cp certs.Page, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_serials using token %s and thing id %s took %s to complete", token, thingID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", thingID), + slog.Group("page", + slog.Uint64("offset", cp.Offset), + slog.Uint64("limit", cp.Limit), + slog.Uint64("total", cp.Total), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List certifcates serials failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List certificates serials completed successfully", args...) }(time.Now()) return lm.svc.ListSerials(ctx, token, thingID, offset, limit) } -// ViewCert logs the view_cert request. It logs the token, serial ID and the time it took to complete the request. +// ViewCert logs the view_cert request. It logs the serial ID and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) ViewCert(ctx context.Context, token, serialID string) (c certs.Cert, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method view_cert using token %s and serial id %s took %s to complete", token, serialID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("serial_id", serialID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("View certificate failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("View certificate completed successfully", args...) }(time.Now()) return lm.svc.ViewCert(ctx, token, serialID) } -// RevokeCert logs the revoke_cert request. It logs the token, thing ID and the time it took to complete the request. +// RevokeCert logs the revoke_cert request. It logs the thing ID and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) RevokeCert(ctx context.Context, token, thingID string) (c certs.Revoke, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method revoke_cert using token %s and thing %s took %s to complete", token, thingID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", thingID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Revoke certificate failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Revoke certificate completed successfully", args...) }(time.Now()) return lm.svc.RevokeCert(ctx, token, thingID) diff --git a/coap/api/logging.go b/coap/api/logging.go index 6d0a612481..0818110802 100644 --- a/coap/api/logging.go +++ b/coap/api/logging.go @@ -7,7 +7,6 @@ package api import ( "context" - "fmt" "log/slog" "time" @@ -31,16 +30,19 @@ func LoggingMiddleware(svc coap.Service, logger *slog.Logger) coap.Service { // If the request fails, it logs the error. func (lm *loggingMiddleware) Publish(ctx context.Context, key string, msg *messaging.Message) (err error) { defer func(begin time.Time) { - destChannel := msg.GetChannel() + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("channel_id", msg.GetChannel()), + } if msg.GetSubtopic() != "" { - destChannel = fmt.Sprintf("%s.%s", destChannel, msg.GetSubtopic()) + args = append(args, slog.String("subtopic", msg.GetSubtopic())) } - message := fmt.Sprintf("Method publish to %s took %s to complete", destChannel, time.Since(begin)) if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Publish message failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Publish message completed successfully", args...) }(time.Now()) return lm.svc.Publish(ctx, key, msg) @@ -50,16 +52,19 @@ func (lm *loggingMiddleware) Publish(ctx context.Context, key string, msg *messa // If the request fails, it logs the error. func (lm *loggingMiddleware) Subscribe(ctx context.Context, key, chanID, subtopic string, c coap.Client) (err error) { defer func(begin time.Time) { - destChannel := chanID + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("channel_id", chanID), + } if subtopic != "" { - destChannel = fmt.Sprintf("%s.%s", destChannel, subtopic) + args = append(args, slog.String("subtopic", subtopic)) } - message := fmt.Sprintf("Method subscribe to %s for client %s took %s to complete", destChannel, c.Token(), time.Since(begin)) if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Subscribe failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Subscribe completed successfully", args...) }(time.Now()) return lm.svc.Subscribe(ctx, key, chanID, subtopic, c) @@ -69,16 +74,19 @@ func (lm *loggingMiddleware) Subscribe(ctx context.Context, key, chanID, subtopi // If the request fails, it logs the error. func (lm *loggingMiddleware) Unsubscribe(ctx context.Context, key, chanID, subtopic, token string) (err error) { defer func(begin time.Time) { - destChannel := chanID + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("channel_id", chanID), + } if subtopic != "" { - destChannel = fmt.Sprintf("%s.%s", destChannel, subtopic) + args = append(args, slog.String("subtopic", subtopic)) } - message := fmt.Sprintf("Method unsubscribe for the client %s from the channel %s took %s to complete", token, destChannel, time.Since(begin)) if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Unsubscribe failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Unsubscribe completed successfully", args...) }(time.Now()) return lm.svc.Unsubscribe(ctx, key, chanID, subtopic, token) diff --git a/consumers/notifiers/api/logging.go b/consumers/notifiers/api/logging.go index e8e0ebba2d..50b3bffa2d 100644 --- a/consumers/notifiers/api/logging.go +++ b/consumers/notifiers/api/logging.go @@ -7,7 +7,6 @@ package api import ( "context" - "fmt" "log/slog" "time" @@ -26,76 +25,106 @@ func LoggingMiddleware(svc notifiers.Service, logger *slog.Logger) notifiers.Ser return &loggingMiddleware{logger, svc} } -// CreateSubscription logs the create_subscription request. It logs token and subscription ID and the time it took to complete the request. +// CreateSubscription logs the create_subscription request. It logs subscription ID and topic and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) CreateSubscription(ctx context.Context, token string, sub notifiers.Subscription) (id string, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method create_subscription with the id %s for token %s took %s to complete", id, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("subscription", + slog.String("topic", sub.Topic), + slog.String("id", id), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Create subscription failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Create subscription completed successfully", args...) }(time.Now()) return lm.svc.CreateSubscription(ctx, token, sub) } -// ViewSubscription logs the view_subscription request. It logs token and subscription topic and the time it took to complete the request. +// ViewSubscription logs the view_subscription request. It logs subscription topic and id and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) ViewSubscription(ctx context.Context, token, topic string) (sub notifiers.Subscription, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method view_subscription with the topic %s for token %s took %s to complete", topic, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("subscription", + slog.String("topic", topic), + slog.String("id", sub.ID), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("View subscription failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("View subscription completed successfully", args...) }(time.Now()) return lm.svc.ViewSubscription(ctx, token, topic) } -// ListSubscriptions logs the list_subscriptions request. It logs token and subscription topic and the time it took to complete the request. +// ListSubscriptions logs the list_subscriptions request. It logs page metadata and subscription topic and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) ListSubscriptions(ctx context.Context, token string, pm notifiers.PageMetadata) (res notifiers.Page, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_subscriptions for topic %s and token %s took %s to complete", pm.Topic, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("page", + slog.String("topic", pm.Topic), + slog.Int("limit", pm.Limit), + slog.Uint64("offset", uint64(pm.Offset)), + slog.Uint64("total", uint64(res.Total)), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List subscriptions failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List subscriptions completed successfully", args...) }(time.Now()) return lm.svc.ListSubscriptions(ctx, token, pm) } -// RemoveSubscription logs the remove_subscription request. It logs token and subscription ID and the time it took to complete the request. +// RemoveSubscription logs the remove_subscription request. It logs subscription ID and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) RemoveSubscription(ctx context.Context, token, id string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method remove_subscription for subscription %s took %s to complete", id, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("subscription_id", id), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Remove subscription failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Remove subscription completed successfully", args...) }(time.Now()) return lm.svc.RemoveSubscription(ctx, token, id) } -// ConsumeBlocking logs the consume_blocking request. It logs the message and the time it took to complete the request. +// ConsumeBlocking logs the consume_blocking request. It logs the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) ConsumeBlocking(ctx context.Context, msg interface{}) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method consume took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Blocking consumer failed to consume messages successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Blocking consumer consumed messages successfully", args...) }(time.Now()) return lm.svc.ConsumeBlocking(ctx, msg) diff --git a/consumers/writers/api/logging.go b/consumers/writers/api/logging.go index f5c3f41a31..77e5f91449 100644 --- a/consumers/writers/api/logging.go +++ b/consumers/writers/api/logging.go @@ -7,7 +7,6 @@ package api import ( "context" - "fmt" "log/slog" "time" @@ -33,12 +32,15 @@ func LoggingMiddleware(consumer consumers.BlockingConsumer, logger *slog.Logger) // If the request fails, it logs the error. func (lm *loggingMiddleware) ConsumeBlocking(ctx context.Context, msgs interface{}) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method consume took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Blocking consumer failed to consume messages successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Blocking consumer consumed messages successfully", args...) }(time.Now()) return lm.consumer.ConsumeBlocking(ctx, msgs) diff --git a/internal/groups/api/logging.go b/internal/groups/api/logging.go index 69fd42a1f8..5f7befc15d 100644 --- a/internal/groups/api/logging.go +++ b/internal/groups/api/logging.go @@ -5,7 +5,6 @@ package api import ( "context" - "fmt" "log/slog" "time" @@ -28,122 +27,187 @@ func LoggingMiddleware(svc groups.Service, logger *slog.Logger) groups.Service { // If the request fails, it logs the error. func (lm *loggingMiddleware) CreateGroup(ctx context.Context, token, kind string, group groups.Group) (g groups.Group, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method create_group for %s %s with id %s using token %s took %s to complete", g.Name, kind, g.ID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("group", + slog.String("id", g.ID), + slog.String("name", g.Name), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Create group failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Create group completed successfully", args...) }(time.Now()) return lm.svc.CreateGroup(ctx, token, kind, group) } -// UpdateGroup logs the update_group request. It logs the group name, id and token and the time it took to complete the request. +// UpdateGroup logs the update_group request. It logs the group name, id and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) UpdateGroup(ctx context.Context, token string, group groups.Group) (g groups.Group, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method update_group for group %s with id %s using token %s took %s to complete", g.Name, g.ID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("group", + slog.String("id", group.ID), + slog.String("name", group.Name), + slog.Any("metadata", group.Metadata), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Update group failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Update group completed successfully", args...) }(time.Now()) return lm.svc.UpdateGroup(ctx, token, group) } -// ViewGroup logs the view_group request. It logs the group name, id and token and the time it took to complete the request. +// ViewGroup logs the view_group request. It logs the group name, id and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) ViewGroup(ctx context.Context, token, id string) (g groups.Group, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method view_group for group %s with id %s using token %s took %s to complete", g.Name, g.ID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("group", + slog.String("id", g.ID), + slog.String("name", g.Name), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("View group failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("View group completed successfully", args...) }(time.Now()) return lm.svc.ViewGroup(ctx, token, id) } -// ViewGroupPerms logs the view_group request. It logs the group name, id and token and the time it took to complete the request. +// ViewGroupPerms logs the view_group request. It logs the group id and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) ViewGroupPerms(ctx context.Context, token, id string) (p []string, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method view_group_perms for group with id %s using token %s took %s to complete", id, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("group_id", id), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("View group permissions failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("View group permissions completed successfully", args...) }(time.Now()) return lm.svc.ViewGroupPerms(ctx, token, id) } -// ListGroups logs the list_groups request. It logs the token and the time it took to complete the request. +// ListGroups logs the list_groups request. It logs the page metadata and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) ListGroups(ctx context.Context, token, memberKind, memberID string, gp groups.Page) (cg groups.Page, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_groups %d groups using token %s took %s to complete", cg.Total, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("member", + slog.String("id", memberID), + slog.String("kind", memberKind), + ), + slog.Group("page", + slog.Uint64("limit", gp.Limit), + slog.Uint64("offset", gp.Offset), + slog.Uint64("total", cg.Total), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List groups failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List groups completed successfully", args...) }(time.Now()) return lm.svc.ListGroups(ctx, token, memberKind, memberID, gp) } -// EnableGroup logs the enable_group request. It logs the group name, id and token and the time it took to complete the request. +// EnableGroup logs the enable_group request. It logs the group name, id and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) EnableGroup(ctx context.Context, token, id string) (g groups.Group, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method enable_group for group with id %s using token %s took %s to complete", g.ID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("group", + slog.String("id", id), + slog.String("name", g.Name), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Enable group failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Enable group completed successfully", args...) }(time.Now()) return lm.svc.EnableGroup(ctx, token, id) } -// DisableGroup logs the disable_group request. It logs the group name, id and token and the time it took to complete the request. +// DisableGroup logs the disable_group request. It logs the group id and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) DisableGroup(ctx context.Context, token, id string) (g groups.Group, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method disable_group for group with id %s using token %s took %s to complete", g.ID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("group", + slog.String("id", id), + slog.String("name", g.Name), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Disable group failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Disable group completed successfully", args...) }(time.Now()) return lm.svc.DisableGroup(ctx, token, id) } -// ListMembers logs the list_members request. It logs the groupID and token and the time it took to complete the request. +// ListMembers logs the list_members request. It logs the groupID and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) ListMembers(ctx context.Context, token, groupID, permission, memberKind string) (mp groups.MembersPage, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_memberships for group with id %s using token %s took %s to complete", groupID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("group_id", groupID), + slog.String("permission", permission), + slog.String("member_kind", memberKind), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List members failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List members completed successfully", args...) }(time.Now()) return lm.svc.ListMembers(ctx, token, groupID, permission, memberKind) } func (lm *loggingMiddleware) Assign(ctx context.Context, token, groupID, relation, memberKind string, memberIDs ...string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method assign for token %s and member %s group id %s took %s to complete", token, memberIDs, groupID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("group_id", groupID), + slog.String("relation", relation), + slog.String("member_kind", memberKind), + slog.Any("member_ids", memberIDs), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Assign member to group failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Assign member to group completed successfully", args...) }(time.Now()) return lm.svc.Assign(ctx, token, groupID, relation, memberKind, memberIDs...) @@ -151,12 +215,19 @@ func (lm *loggingMiddleware) Assign(ctx context.Context, token, groupID, relatio func (lm *loggingMiddleware) Unassign(ctx context.Context, token, groupID, relation, memberKind string, memberIDs ...string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method unassign for token %s and member %s group id %s took %s to complete", token, memberIDs, groupID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("group_id", groupID), + slog.String("relation", relation), + slog.String("member_kind", memberKind), + slog.Any("member_ids", memberIDs), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Unassign member to group failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Unassign member to group completed successfully", args...) }(time.Now()) return lm.svc.Unassign(ctx, token, groupID, relation, memberKind, memberIDs...) @@ -164,12 +235,16 @@ func (lm *loggingMiddleware) Unassign(ctx context.Context, token, groupID, relat func (lm *loggingMiddleware) DeleteGroup(ctx context.Context, token, id string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method delete_group for group with id %s using token %s took %s to complete", id, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("group_id", id), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Delete group failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Delete group completed successfully", args...) }(time.Now()) return lm.svc.DeleteGroup(ctx, token, id) } diff --git a/invitations/middleware/logging.go b/invitations/middleware/logging.go index 49524a9c9e..6acf135eed 100644 --- a/invitations/middleware/logging.go +++ b/invitations/middleware/logging.go @@ -5,7 +5,6 @@ package middleware import ( "context" - "fmt" "log/slog" "time" @@ -25,60 +24,87 @@ func Logging(logger *slog.Logger, svc invitations.Service) invitations.Service { func (lm *logging) SendInvitation(ctx context.Context, token string, invitation invitations.Invitation) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method send_invitation to user_id %s from domain_id %s took %s to complete", invitation.UserID, invitation.DomainID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("user_id", invitation.UserID), + slog.String("domain_id", invitation.DomainID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Send invitation failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Send invitation completed successfully", args...) }(time.Now()) return lm.svc.SendInvitation(ctx, token, invitation) } func (lm *logging) ViewInvitation(ctx context.Context, token, userID, domainID string) (invitation invitations.Invitation, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method view_invitation took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("user_id", userID), + slog.String("domain_id", domainID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("View invitation failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("View invitation completed successfully", args...) }(time.Now()) return lm.svc.ViewInvitation(ctx, token, userID, domainID) } func (lm *logging) ListInvitations(ctx context.Context, token string, page invitations.Page) (invs invitations.InvitationPage, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_invitations took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("page", + slog.Uint64("offset", page.Offset), + slog.Uint64("limit", page.Limit), + slog.Uint64("total", invs.Total), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List invitations failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List invitations completed successfully", args...) }(time.Now()) return lm.svc.ListInvitations(ctx, token, page) } func (lm *logging) AcceptInvitation(ctx context.Context, token, domainID string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method accept_invitation took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("domain_id", domainID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Accept invitation failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Accept invitation completed successfully", args...) }(time.Now()) return lm.svc.AcceptInvitation(ctx, token, domainID) } func (lm *logging) DeleteInvitation(ctx context.Context, token, userID, domainID string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method delete_invitation took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("user_id", userID), + slog.String("domain_id", domainID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Delete invitation failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Delete invitation completed successfully", args...) }(time.Now()) return lm.svc.DeleteInvitation(ctx, token, userID, domainID) } diff --git a/lora/api/logging.go b/lora/api/logging.go index fb9a37cfea..8190e700c8 100644 --- a/lora/api/logging.go +++ b/lora/api/logging.go @@ -7,7 +7,6 @@ package api import ( "context" - "fmt" "log/slog" "time" @@ -31,12 +30,17 @@ func LoggingMiddleware(svc lora.Service, logger *slog.Logger) lora.Service { func (lm loggingMiddleware) CreateThing(ctx context.Context, thingID, loraDevEUI string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("create_thing for thing %s and lora-dev-eui %s took %s to complete", thingID, loraDevEUI, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", thingID), + slog.String("dev_eui", loraDevEUI), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Create thing route-map failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Create thing route-map completed successfully", args...) }(time.Now()) return lm.svc.CreateThing(ctx, thingID, loraDevEUI) @@ -44,12 +48,17 @@ func (lm loggingMiddleware) CreateThing(ctx context.Context, thingID, loraDevEUI func (lm loggingMiddleware) UpdateThing(ctx context.Context, thingID, loraDevEUI string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("update_thing for thing %s and lora-dev-eui %s took %s to complete", thingID, loraDevEUI, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", thingID), + slog.String("dev_eui", loraDevEUI), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Update thing route-map failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Update thing route-map completed successfully", args...) }(time.Now()) return lm.svc.UpdateThing(ctx, thingID, loraDevEUI) @@ -57,12 +66,16 @@ func (lm loggingMiddleware) UpdateThing(ctx context.Context, thingID, loraDevEUI func (lm loggingMiddleware) RemoveThing(ctx context.Context, thingID string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("remove_thing for thing %s took %s to complete", thingID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", thingID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Remove thing route-map failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Remove thing route-map completed successfully", args...) }(time.Now()) return lm.svc.RemoveThing(ctx, thingID) @@ -70,12 +83,17 @@ func (lm loggingMiddleware) RemoveThing(ctx context.Context, thingID string) (er func (lm loggingMiddleware) CreateChannel(ctx context.Context, chanID, loraApp string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("create_channel for channel %s and lora-app %s took %s to complete", chanID, loraApp, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("channel_id", chanID), + slog.String("lora_app", loraApp), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Create channel route-map failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Create channel route-map completed successfully", args...) }(time.Now()) return lm.svc.CreateChannel(ctx, chanID, loraApp) @@ -83,12 +101,16 @@ func (lm loggingMiddleware) CreateChannel(ctx context.Context, chanID, loraApp s func (lm loggingMiddleware) UpdateChannel(ctx context.Context, chanID, loraApp string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("update_channel for channel %s and lora-app %s took %s to complete", chanID, loraApp, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("channel_id", chanID), + slog.String("lora_app", loraApp), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + lm.logger.Warn("Update channel route-map failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Update channel route-map completed successfully", args...) }(time.Now()) return lm.svc.UpdateChannel(ctx, chanID, loraApp) @@ -96,12 +118,15 @@ func (lm loggingMiddleware) UpdateChannel(ctx context.Context, chanID, loraApp s func (lm loggingMiddleware) RemoveChannel(ctx context.Context, chanID string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("remove_channel for channel %s took %s to complete", chanID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("channel_id", chanID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + lm.logger.Warn("Remove channel route-map failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Remove channel route-map completed successfully", args...) }(time.Now()) return lm.svc.RemoveChannel(ctx, chanID) @@ -109,12 +134,17 @@ func (lm loggingMiddleware) RemoveChannel(ctx context.Context, chanID string) (e func (lm loggingMiddleware) ConnectThing(ctx context.Context, chanID, thingID string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("connect_thing for channel %s and thing %s, took %s to complete", chanID, thingID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("channel_id", chanID), + slog.String("thing_id", thingID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args := append(args, slog.String("error", err.Error())) + lm.logger.Warn("Connect thing to channel failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Connect thing to channel completed successfully", args...) }(time.Now()) return lm.svc.ConnectThing(ctx, chanID, thingID) @@ -122,12 +152,17 @@ func (lm loggingMiddleware) ConnectThing(ctx context.Context, chanID, thingID st func (lm loggingMiddleware) DisconnectThing(ctx context.Context, chanID, thingID string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("disconnect_thing mgx-%s : mgx-%s, took %s to complete", chanID, thingID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("channel_id", chanID), + slog.String("thing_id", thingID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args := append(args, slog.String("error", err.Error())) + lm.logger.Warn("Disconnect thing from channel failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Disconnect thing from channel completed successfully", args...) }(time.Now()) return lm.svc.DisconnectThing(ctx, chanID, thingID) @@ -135,12 +170,19 @@ func (lm loggingMiddleware) DisconnectThing(ctx context.Context, chanID, thingID func (lm loggingMiddleware) Publish(ctx context.Context, msg *lora.Message) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("publish application/%s/device/%s/rx took %s to complete", msg.ApplicationID, msg.DevEUI, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("message", + slog.String("application_id", msg.ApplicationID), + slog.String("device_eui", msg.DevEUI), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Publish failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Publish completed successfully", args...) }(time.Now()) return lm.svc.Publish(ctx, msg) diff --git a/opcua/api/logging.go b/opcua/api/logging.go index 27eeb6ce03..e58e97abba 100644 --- a/opcua/api/logging.go +++ b/opcua/api/logging.go @@ -7,7 +7,6 @@ package api import ( "context" - "fmt" "log/slog" "time" @@ -31,12 +30,17 @@ func LoggingMiddleware(svc opcua.Service, logger *slog.Logger) opcua.Service { func (lm loggingMiddleware) CreateThing(ctx context.Context, mgxThing, opcuaNodeID string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("create_thing %s with NodeID %s, took %s to complete", mgxThing, opcuaNodeID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", mgxThing), + slog.String("node_id", opcuaNodeID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Create thing route-map failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Create thing route-map completed successfully", args...) }(time.Now()) return lm.svc.CreateThing(ctx, mgxThing, opcuaNodeID) @@ -44,12 +48,17 @@ func (lm loggingMiddleware) CreateThing(ctx context.Context, mgxThing, opcuaNode func (lm loggingMiddleware) UpdateThing(ctx context.Context, mgxThing, opcuaNodeID string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("update_thing %s with NodeID %s, took %s to complete", mgxThing, opcuaNodeID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", mgxThing), + slog.String("node_id", opcuaNodeID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Update thing route-map failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Update thing route-map completed successfully", args...) }(time.Now()) return lm.svc.UpdateThing(ctx, mgxThing, opcuaNodeID) @@ -57,12 +66,16 @@ func (lm loggingMiddleware) UpdateThing(ctx context.Context, mgxThing, opcuaNode func (lm loggingMiddleware) RemoveThing(ctx context.Context, mgxThing string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("remove_thing %s, took %s to complete", mgxThing, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", mgxThing), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Remove thing route-map failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Remove thing route-map completed successfully", args...) }(time.Now()) return lm.svc.RemoveThing(ctx, mgxThing) @@ -70,12 +83,17 @@ func (lm loggingMiddleware) RemoveThing(ctx context.Context, mgxThing string) (e func (lm loggingMiddleware) CreateChannel(ctx context.Context, mgxChan, opcuaServerURI string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("create_channel %s with ServerURI %s, took %s to complete", mgxChan, opcuaServerURI, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("channel_id", mgxChan), + slog.String("server_uri", opcuaServerURI), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Create channel route-map failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Create channel route-map completed successfully", args...) }(time.Now()) return lm.svc.CreateChannel(ctx, mgxChan, opcuaServerURI) @@ -83,12 +101,17 @@ func (lm loggingMiddleware) CreateChannel(ctx context.Context, mgxChan, opcuaSer func (lm loggingMiddleware) UpdateChannel(ctx context.Context, mgxChanID, opcuaServerURI string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("update_channel %s with ServerURI %s, took %s to complete", mgxChanID, opcuaServerURI, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("channel_id", mgxChanID), + slog.String("server_uri", opcuaServerURI), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Update channel route-map failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Update channel route-map completed successfully", args...) }(time.Now()) return lm.svc.UpdateChannel(ctx, mgxChanID, opcuaServerURI) @@ -96,12 +119,16 @@ func (lm loggingMiddleware) UpdateChannel(ctx context.Context, mgxChanID, opcuaS func (lm loggingMiddleware) RemoveChannel(ctx context.Context, mgxChanID string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("remove_channel %s, took %s to complete", mgxChanID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("channel_id", mgxChanID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Remove channel route-map failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Remove channel route-map completed successfully", args...) }(time.Now()) return lm.svc.RemoveChannel(ctx, mgxChanID) @@ -109,12 +136,17 @@ func (lm loggingMiddleware) RemoveChannel(ctx context.Context, mgxChanID string) func (lm loggingMiddleware) ConnectThing(ctx context.Context, mgxChanID, mgxThingID string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("connect_thing for channel %s and thing %s, took %s to complete", mgxChanID, mgxThingID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("channel_id", mgxChanID), + slog.String("thing_id", mgxThingID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Connect thing to channel failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Connect thing to channel completed successfully", args...) }(time.Now()) return lm.svc.ConnectThing(ctx, mgxChanID, mgxThingID) @@ -122,12 +154,17 @@ func (lm loggingMiddleware) ConnectThing(ctx context.Context, mgxChanID, mgxThin func (lm loggingMiddleware) DisconnectThing(ctx context.Context, mgxChanID, mgxThingID string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("disconnect_thing mgx-%s : mgx-%s, took %s to complete", mgxChanID, mgxThingID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("channel_id", mgxChanID), + slog.String("thing_id", mgxThingID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Disconnect thing from channel failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Disconnect thing from channel completed successfully", args...) }(time.Now()) return lm.svc.DisconnectThing(ctx, mgxChanID, mgxThingID) @@ -135,12 +172,18 @@ func (lm loggingMiddleware) DisconnectThing(ctx context.Context, mgxChanID, mgxT func (lm loggingMiddleware) Browse(ctx context.Context, serverURI, namespace, identifier string) (nodes []opcua.BrowsedNode, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("browse server URI %s and node %s;%s, took %s to complete", serverURI, namespace, identifier, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("server_uri", serverURI), + slog.String("namespace", namespace), + slog.String("identifier", identifier), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Browse available nodes failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Browse available nodes completed successfully", args...) }(time.Now()) return lm.svc.Browse(ctx, serverURI, namespace, identifier) diff --git a/pkg/messaging/handler/logging.go b/pkg/messaging/handler/logging.go index 5019c20b4b..6b92ca67b9 100644 --- a/pkg/messaging/handler/logging.go +++ b/pkg/messaging/handler/logging.go @@ -7,7 +7,6 @@ package handler import ( "context" - "fmt" "log/slog" "time" @@ -23,118 +22,65 @@ type loggingMiddleware struct { // AuthConnect implements session.Handler. func (lm *loggingMiddleware) AuthConnect(ctx context.Context) (err error) { - defer func(begin time.Time) { - message := fmt.Sprintf("Method auth connect took %s to complete", time.Since(begin)) - if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) - return - } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) - }(time.Now()) - - return lm.svc.AuthConnect(ctx) + return lm.logAction(ctx, "AuthConnect", nil) } // AuthPublish implements session.Handler. func (lm *loggingMiddleware) AuthPublish(ctx context.Context, topic *string, payload *[]byte) (err error) { - defer func(begin time.Time) { - message := fmt.Sprintf("Method auth publish took %s to complete", time.Since(begin)) - if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) - return - } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) - }(time.Now()) - - return lm.svc.AuthPublish(ctx, topic, payload) + return lm.logAction(ctx, "AuthPublish", &[]string{*topic}) } // AuthSubscribe implements session.Handler. func (lm *loggingMiddleware) AuthSubscribe(ctx context.Context, topics *[]string) (err error) { - defer func(begin time.Time) { - message := fmt.Sprintf("Method auth subscribe took %s to complete", time.Since(begin)) - if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) - return - } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) - }(time.Now()) - - return lm.svc.AuthSubscribe(ctx, topics) + return lm.logAction(ctx, "AuthSubscribe", topics) } // Connect implements session.Handler. func (lm *loggingMiddleware) Connect(ctx context.Context) (err error) { - defer func(begin time.Time) { - message := fmt.Sprintf("Method connect took %s to complete", time.Since(begin)) - if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) - return - } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) - }(time.Now()) - - return lm.svc.Connect(ctx) + return lm.logAction(ctx, "Connect", nil) } // Disconnect implements session.Handler. func (lm *loggingMiddleware) Disconnect(ctx context.Context) (err error) { - defer func(begin time.Time) { - message := fmt.Sprintf("Method disconnect took %s to complete", time.Since(begin)) - if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) - return - } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) - }(time.Now()) - - return lm.svc.Disconnect(ctx) + return lm.logAction(ctx, "Disconnect", nil) } // Publish logs the publish request. It logs the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) Publish(ctx context.Context, topic *string, payload *[]byte) (err error) { - defer func(begin time.Time) { - message := fmt.Sprintf("Method publish to channel %s took %s to complete", *topic, time.Since(begin)) - if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) - return - } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) - }(time.Now()) - - return lm.svc.Publish(ctx, topic, payload) + return lm.logAction(ctx, "Publish", &[]string{*topic}) } // Subscribe implements session.Handler. func (lm *loggingMiddleware) Subscribe(ctx context.Context, topics *[]string) (err error) { - defer func(begin time.Time) { - message := fmt.Sprintf("Method subscribe took %s to complete", time.Since(begin)) - if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) - return - } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) - }(time.Now()) - - return lm.svc.Subscribe(ctx, topics) + return lm.logAction(ctx, "Subscribe", topics) } // Unsubscribe implements session.Handler. func (lm *loggingMiddleware) Unsubscribe(ctx context.Context, topics *[]string) (err error) { + return lm.logAction(ctx, "Unsubscribe", topics) +} + +// LoggingMiddleware adds logging facilities to the adapter. +func LoggingMiddleware(svc session.Handler, logger *slog.Logger) session.Handler { + return &loggingMiddleware{logger, svc} +} + +func (lm *loggingMiddleware) logAction(ctx context.Context, action string, topics *[]string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method unsubscribe took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + } + if topics != nil { + args = append(args, slog.Any("topics", *topics)) + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn(action+"() failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info(action+"() completed successfully", args...) }(time.Now()) - return lm.svc.Unsubscribe(ctx, topics) -} - -// LoggingMiddleware adds logging facilities to the adapter. -func LoggingMiddleware(svc session.Handler, logger *slog.Logger) session.Handler { - return &loggingMiddleware{logger, svc} + return nil } diff --git a/provision/api/logging.go b/provision/api/logging.go index f1dfd948e0..c6aa58fbc0 100644 --- a/provision/api/logging.go +++ b/provision/api/logging.go @@ -6,7 +6,6 @@ package api import ( - "fmt" "log/slog" "time" @@ -27,12 +26,17 @@ func NewLoggingMiddleware(svc provision.Service, logger *slog.Logger) provision. func (lm *loggingMiddleware) Provision(token, name, externalID, externalKey string) (res provision.Result, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method provision for token: %s and things: %v took %s to complete", token, res.Things, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("name", name), + slog.String("external_id", externalID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Provision failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors", message)) + lm.logger.Info("Provision completed successfully", args...) }(time.Now()) return lm.svc.Provision(token, name, externalID, externalKey) @@ -40,12 +44,17 @@ func (lm *loggingMiddleware) Provision(token, name, externalID, externalKey stri func (lm *loggingMiddleware) Cert(token, thingID, duration string) (cert, key string, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method cert for token: %s and thing: %v took %s to complete", token, thingID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", thingID), + slog.String("ttl", duration), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Thing certificate failed to create successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors", message)) + lm.logger.Info("Thing certificate created successfully", args...) }(time.Now()) return lm.svc.Cert(token, thingID, duration) @@ -53,12 +62,15 @@ func (lm *loggingMiddleware) Cert(token, thingID, duration string) (cert, key st func (lm *loggingMiddleware) Mapping(token string) (res map[string]interface{}, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method mapping for token: %s took %s to complete", token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Mapping failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors", message)) + lm.logger.Info("Mapping completed successfully", args...) }(time.Now()) return lm.svc.Mapping(token) diff --git a/readers/api/logging.go b/readers/api/logging.go index 73bb9dcffa..614337df95 100644 --- a/readers/api/logging.go +++ b/readers/api/logging.go @@ -6,7 +6,6 @@ package api import ( - "fmt" "log/slog" "time" @@ -30,12 +29,27 @@ func LoggingMiddleware(svc readers.MessageRepository, logger *slog.Logger) reade func (lm *loggingMiddleware) ReadAll(chanID string, rpm readers.PageMetadata) (page readers.MessagesPage, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method read_all for channel %s with query %v took %s to complete", chanID, rpm, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("channel_id", chanID), + slog.Group("page", + slog.Uint64("offset", rpm.Offset), + slog.Uint64("limit", rpm.Limit), + slog.Uint64("total", page.Total), + ), + } + if rpm.Subtopic != "" { + args = append(args, slog.String("subtopic", rpm.Subtopic)) + } + if rpm.Publisher != "" { + args = append(args, slog.String("publisher", rpm.Publisher)) + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Read all failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Read all completed successfully", args...) }(time.Now()) return lm.svc.ReadAll(chanID, rpm) diff --git a/things/api/logging.go b/things/api/logging.go index 134c8eea82..86ae568038 100644 --- a/things/api/logging.go +++ b/things/api/logging.go @@ -27,180 +27,276 @@ func LoggingMiddleware(svc things.Service, logger *slog.Logger) things.Service { func (lm *loggingMiddleware) CreateThings(ctx context.Context, token string, clients ...mgclients.Client) (cs []mgclients.Client, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method create_things %d things using token %s took %s to complete", len(cs), token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn(fmt.Sprintf("Create %d things failed to complete successfully", len(clients)), args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info(fmt.Sprintf("Create %d things completed successfully", len(clients)), args...) }(time.Now()) return lm.svc.CreateThings(ctx, token, clients...) } func (lm *loggingMiddleware) ViewClient(ctx context.Context, token, id string) (c mgclients.Client, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method view_thing for thing with id %s using token %s took %s to complete", id, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("thing", + slog.String("id", c.ID), + slog.String("name", c.Name), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("View thing failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("View thing completed successfully", args...) }(time.Now()) return lm.svc.ViewClient(ctx, token, id) } func (lm *loggingMiddleware) ViewClientPerms(ctx context.Context, token, id string) (p []string, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method view_thing_permissions for thing with id %s using token %s took %s to complete", id, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", id), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("View thing permissions failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("View thing permissions completed successfully", args...) }(time.Now()) return lm.svc.ViewClientPerms(ctx, token, id) } func (lm *loggingMiddleware) ListClients(ctx context.Context, token, reqUserID string, pm mgclients.Page) (cp mgclients.ClientsPage, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_things using token %s took %s to complete", token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("user_id", reqUserID), + slog.Group("page", + slog.Uint64("limit", pm.Limit), + slog.Uint64("offset", pm.Offset), + slog.Uint64("total", cp.Total), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List things failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List things completed successfully", args...) }(time.Now()) return lm.svc.ListClients(ctx, token, reqUserID, pm) } func (lm *loggingMiddleware) UpdateClient(ctx context.Context, token string, client mgclients.Client) (c mgclients.Client, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method update_thing_name_and_metadata for thing with id %s using token %s took %s to complete", c.ID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("thing", + slog.String("id", client.ID), + slog.String("name", client.Name), + slog.Any("metadata", client.Metadata), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Update thing failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Update thing completed successfully", args...) }(time.Now()) return lm.svc.UpdateClient(ctx, token, client) } func (lm *loggingMiddleware) UpdateClientTags(ctx context.Context, token string, client mgclients.Client) (c mgclients.Client, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method update_thing_tags for thing with id %s using token %s took %s to complete", c.ID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("thing", + slog.String("id", c.ID), + slog.String("name", c.Name), + slog.Any("tags", c.Tags), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args := append(args, slog.String("error", err.Error())) + lm.logger.Warn("Update thing tags failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Update thing tags completed successfully", args...) }(time.Now()) return lm.svc.UpdateClientTags(ctx, token, client) } func (lm *loggingMiddleware) UpdateClientSecret(ctx context.Context, token, oldSecret, newSecret string) (c mgclients.Client, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method update_thing_secret for thing with id %s using token %s took %s to complete", c.ID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("thing", + slog.String("id", c.ID), + slog.String("name", c.Name), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Update thing secret failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Update thing secret completed successfully", args...) }(time.Now()) return lm.svc.UpdateClientSecret(ctx, token, oldSecret, newSecret) } func (lm *loggingMiddleware) EnableClient(ctx context.Context, token, id string) (c mgclients.Client, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method enable_thing for thing with id %s using token %s took %s to complete", id, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("thing", + slog.String("id", id), + slog.String("name", c.Name), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Enable thing failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Enable thing completed successfully", args...) }(time.Now()) return lm.svc.EnableClient(ctx, token, id) } func (lm *loggingMiddleware) DisableClient(ctx context.Context, token, id string) (c mgclients.Client, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method disable_thing for thing with id %s using token %s took %s to complete", id, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("thing", + slog.String("id", id), + slog.String("name", c.Name), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Disable thing failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Disable thing completed successfully", args...) }(time.Now()) return lm.svc.DisableClient(ctx, token, id) } func (lm *loggingMiddleware) ListClientsByGroup(ctx context.Context, token, channelID string, cp mgclients.Page) (mp mgclients.MembersPage, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_things_by_channel for channel with id %s using token %s took %s to complete", channelID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("channel_id", channelID), + slog.Group("page", + slog.Uint64("offset", cp.Offset), + slog.Uint64("limit", cp.Limit), + slog.Uint64("total", mp.Total), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List things by group failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List things by group completed successfully", args...) }(time.Now()) return lm.svc.ListClientsByGroup(ctx, token, channelID, cp) } func (lm *loggingMiddleware) Identify(ctx context.Context, key string) (id string, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method identify for thing with id %s and key %s took %s to complete", id, key, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", id), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Identify thing failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Identify thing completed successfully", args...) }(time.Now()) return lm.svc.Identify(ctx, key) } func (lm *loggingMiddleware) Authorize(ctx context.Context, req *magistrala.AuthorizeReq) (id string, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method authorize for thing key %s and channnel %s took %s to complete", req.Subject, req.Object, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("object", req.GetObject()), + slog.String("object_type", req.GetObjectType()), + slog.String("subject_type", req.GetSubjectType()), + slog.String("permission", req.GetPermission()), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Authorize failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Authorize completed successfully", args...) }(time.Now()) return lm.svc.Authorize(ctx, req) } func (lm *loggingMiddleware) Share(ctx context.Context, token, id, relation string, userids ...string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method share for thing id %s with relation %s for users %v took %s to complete", id, relation, userids, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", id), + slog.Any("user_ids", userids), + slog.String("relation", relation), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Share thing failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Share thing completed successfully", args...) }(time.Now()) return lm.svc.Share(ctx, token, id, relation, userids...) } func (lm *loggingMiddleware) Unshare(ctx context.Context, token, id, relation string, userids ...string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method unshare for thing id %s with relation %s for users %v took %s to complete", id, relation, userids, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", id), + slog.Any("user_ids", userids), + slog.String("relation", relation), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Unshare thing failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Unshare thing completed successfully", args...) }(time.Now()) return lm.svc.Unshare(ctx, token, id, relation, userids...) } func (lm *loggingMiddleware) DeleteClient(ctx context.Context, token, id string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method delete_client for thing id %s took %s to complete", id, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("thing_id", id), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Delete thing failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Delete thing completed successfully", args...) }(time.Now()) return lm.svc.DeleteClient(ctx, token, id) } diff --git a/twins/api/logging.go b/twins/api/logging.go index c8b65305d1..eff62e13a6 100644 --- a/twins/api/logging.go +++ b/twins/api/logging.go @@ -7,7 +7,6 @@ package api import ( "context" - "fmt" "log/slog" "time" @@ -29,12 +28,20 @@ func LoggingMiddleware(svc twins.Service, logger *slog.Logger) twins.Service { func (lm *loggingMiddleware) AddTwin(ctx context.Context, token string, twin twins.Twin, def twins.Definition) (tw twins.Twin, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method add_twin for token %s and twin %s took %s to complete", token, twin.ID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("twin", + slog.String("id", tw.ID), + slog.String("name", tw.Name), + slog.Any("definitions", tw.Definitions), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Add twin failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Add twin completed successfully", args...) }(time.Now()) return lm.svc.AddTwin(ctx, token, twin, def) @@ -42,12 +49,20 @@ func (lm *loggingMiddleware) AddTwin(ctx context.Context, token string, twin twi func (lm *loggingMiddleware) UpdateTwin(ctx context.Context, token string, twin twins.Twin, def twins.Definition) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method update_twin for token %s and twin %s took %s to complete", token, twin.ID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("twin", + slog.String("id", twin.ID), + slog.String("name", twin.Name), + slog.Any("definitions", def), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Update twin failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Update twin completed successfully", args...) }(time.Now()) return lm.svc.UpdateTwin(ctx, token, twin, def) @@ -55,12 +70,16 @@ func (lm *loggingMiddleware) UpdateTwin(ctx context.Context, token string, twin func (lm *loggingMiddleware) ViewTwin(ctx context.Context, token, twinID string) (tw twins.Twin, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method view_twin for token %s and twin %s took %s to complete", token, twinID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("twin_id", twinID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("View twin failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("View twin completed successfully", args...) }(time.Now()) return lm.svc.ViewTwin(ctx, token, twinID) @@ -68,12 +87,21 @@ func (lm *loggingMiddleware) ViewTwin(ctx context.Context, token, twinID string) func (lm *loggingMiddleware) ListTwins(ctx context.Context, token string, offset, limit uint64, name string, metadata twins.Metadata) (page twins.Page, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_twins for token %s took %s to complete", token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("page", + slog.String("name", name), + slog.Uint64("offset", offset), + slog.Uint64("limit", limit), + slog.Uint64("total", page.Total), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List twins failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List twins completed successfully", args...) }(time.Now()) return lm.svc.ListTwins(ctx, token, offset, limit, name, metadata) @@ -81,12 +109,20 @@ func (lm *loggingMiddleware) ListTwins(ctx context.Context, token string, offset func (lm *loggingMiddleware) SaveStates(ctx context.Context, msg *messaging.Message) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method save_states took %s to complete", time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("message", + slog.String("channel", msg.GetChannel()), + slog.String("subtopic", msg.GetSubtopic()), + slog.String("publisher", msg.GetPublisher()), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Save states failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Save states completed successfully", args...) }(time.Now()) return lm.svc.SaveStates(ctx, msg) @@ -94,12 +130,21 @@ func (lm *loggingMiddleware) SaveStates(ctx context.Context, msg *messaging.Mess func (lm *loggingMiddleware) ListStates(ctx context.Context, token string, offset, limit uint64, twinID string) (page twins.StatesPage, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_states for token %s took %s to complete", token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("twin_id", twinID), + slog.Group("page", + slog.Uint64("offset", offset), + slog.Uint64("limit", limit), + slog.Uint64("total", page.Total), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List states failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List states completed successfully", args...) }(time.Now()) return lm.svc.ListStates(ctx, token, offset, limit, twinID) @@ -107,12 +152,16 @@ func (lm *loggingMiddleware) ListStates(ctx context.Context, token string, offse func (lm *loggingMiddleware) RemoveTwin(ctx context.Context, token, twinID string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method remove_twin for token %s and twin %s took %s to complete", token, twinID, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("twin_id", twinID), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Remove twin failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Remove twin completed successfully", args...) }(time.Now()) return lm.svc.RemoveTwin(ctx, token, twinID) diff --git a/users/api/logging.go b/users/api/logging.go index ac60fea545..70b693694f 100644 --- a/users/api/logging.go +++ b/users/api/logging.go @@ -5,7 +5,6 @@ package api import ( "context" - "fmt" "log/slog" "time" @@ -26,34 +25,44 @@ func LoggingMiddleware(svc users.Service, logger *slog.Logger) users.Service { return &loggingMiddleware{logger, svc} } -// RegisterClient logs the register_client request. It logs the client id and token and the time it took to complete the request. +// RegisterClient logs the register_client request. It logs the client id and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) RegisterClient(ctx context.Context, token string, client mgclients.Client) (c mgclients.Client, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method register_client with id %s using token %s took %s to complete", c.ID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("user", + slog.String("id", c.ID), + slog.String("name", c.Name), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Register user failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Register user completed successfully", args...) }(time.Now()) return lm.svc.RegisterClient(ctx, token, client) } -// IssueToken logs the issue_token request. It logs the client identity and token type and the time it took to complete the request. +// IssueToken logs the issue_token request. It logs the client identity type and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) IssueToken(ctx context.Context, identity, secret, domainID string) (t *magistrala.Token, err error) { defer func(begin time.Time) { - message := "Method issue_token" - if t != nil { - message = fmt.Sprintf("%s of type %s", message, t.AccessType) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("domain_id", domainID), + } + if t.AccessType != "" { + args = append(args, slog.String("access_type", t.AccessType)) } - message = fmt.Sprintf("%s for client %s took %s to complete", message, identity, time.Since(begin)) if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Issue token failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Issue token completed successfully", args...) }(time.Now()) return lm.svc.IssueToken(ctx, identity, secret, domainID) } @@ -62,225 +71,329 @@ func (lm *loggingMiddleware) IssueToken(ctx context.Context, identity, secret, d // If the request fails, it logs the error. func (lm *loggingMiddleware) RefreshToken(ctx context.Context, refreshToken, domainID string) (t *magistrala.Token, err error) { defer func(begin time.Time) { - message := "Method refresh_token" - if t != nil { - message = fmt.Sprintf("%s of type %s", message, t.AccessType) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("domain_id", domainID), + } + if t.AccessType != "" { + args = append(args, slog.String("access_type", t.AccessType)) } - message = fmt.Sprintf("%s for refresh token %s took %s to complete", message, refreshToken, time.Since(begin)) if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Refresh token failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Refresh token completed successfully", args...) }(time.Now()) return lm.svc.RefreshToken(ctx, refreshToken, domainID) } -// ViewClient logs the view_client request. It logs the client id and token and the time it took to complete the request. +// ViewClient logs the view_client request. It logs the client id and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) ViewClient(ctx context.Context, token, id string) (c mgclients.Client, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method view_client with id %s using token %s took %s to complete", c.ID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("user", + slog.String("id", id), + slog.String("name", c.Name), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("View user failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("View user completed successfully", args...) }(time.Now()) return lm.svc.ViewClient(ctx, token, id) } -// ViewProfile logs the view_profile request. It logs the client id and token and the time it took to complete the request. +// ViewProfile logs the view_profile request. It logs the client id and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) ViewProfile(ctx context.Context, token string) (c mgclients.Client, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method view_profile with id %s using token %s took %s to complete", c.ID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("user", + slog.String("id", c.ID), + slog.String("name", c.Name), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("View profile failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("View profile completed successfully", args...) }(time.Now()) return lm.svc.ViewProfile(ctx, token) } -// ListClients logs the list_clients request. It logs the token and page metadata and the time it took to complete the request. +// ListClients logs the list_clients request. It logs the page metadata and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) ListClients(ctx context.Context, token string, pm mgclients.Page) (cp mgclients.ClientsPage, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_clients %d clients using token %s took %s to complete", cp.Total, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("page", + slog.Uint64("limit", pm.Limit), + slog.Uint64("offset", pm.Offset), + slog.Uint64("total", cp.Total), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List users failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List users completed successfully", args...) }(time.Now()) return lm.svc.ListClients(ctx, token, pm) } -// UpdateClient logs the update_client request. It logs the client id and token and the time it took to complete the request. +// UpdateClient logs the update_client request. It logs the client id and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) UpdateClient(ctx context.Context, token string, client mgclients.Client) (c mgclients.Client, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method update_client_name_and_metadata for client with id %s using token %s took %s to complete", c.ID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("user", + slog.String("id", c.ID), + slog.String("name", c.Name), + slog.Any("metadata", c.Metadata), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Update user failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Update user completed successfully", args...) }(time.Now()) return lm.svc.UpdateClient(ctx, token, client) } -// UpdateClientTags logs the update_client_tags request. It logs the client id and token and the time it took to complete the request. +// UpdateClientTags logs the update_client_tags request. It logs the client id and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) UpdateClientTags(ctx context.Context, token string, client mgclients.Client) (c mgclients.Client, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method update_client_tags for client with id %s using token %s took %s to complete", c.ID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("user", + slog.String("id", c.ID), + slog.String("name", c.Name), + slog.Any("tags", c.Tags), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Update user tags failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Update user tags completed successfully", args...) }(time.Now()) return lm.svc.UpdateClientTags(ctx, token, client) } -// UpdateClientIdentity logs the update_client_identity request. It logs the client id and token and the time it took to complete the request. +// UpdateClientIdentity logs the update_identity request. It logs the client id and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) UpdateClientIdentity(ctx context.Context, token, id, identity string) (c mgclients.Client, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method update_client_identity for client with id %s using token %s took %s to complete", c.ID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("user", + slog.String("id", c.ID), + slog.String("name", c.Name), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Update client identity failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Update client identity completed successfully", args...) }(time.Now()) return lm.svc.UpdateClientIdentity(ctx, token, id, identity) } -// UpdateClientSecret logs the update_client_secret request. It logs the client id and token and the time it took to complete the request. +// UpdateClientSecret logs the update_client_secret request. It logs the client id and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) UpdateClientSecret(ctx context.Context, token, oldSecret, newSecret string) (c mgclients.Client, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method update_client_secret for client with id %s using token %s took %s to complete", c.ID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("user", + slog.String("id", c.ID), + slog.String("name", c.Name), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Update user secret failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Update user secret completed successfully", args...) }(time.Now()) return lm.svc.UpdateClientSecret(ctx, token, oldSecret, newSecret) } -// GenerateResetToken logs the generate_reset_token request. It logs the email and host and the time it took to complete the request. +// GenerateResetToken logs the generate_reset_token request. It logs the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) GenerateResetToken(ctx context.Context, email, host string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method generate_reset_token for email %s and host %s took %s to complete", email, host, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("host", host), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Generate reset token failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Generate reset token completed successfully", args...) }(time.Now()) return lm.svc.GenerateResetToken(ctx, email, host) } -// ResetSecret logs the reset_secret request. It logs the token and the time it took to complete the request. +// ResetSecret logs the reset_secret request. It logs the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) ResetSecret(ctx context.Context, token, secret string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method reset_secret using token %s took %s to complete", token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Reset secret failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Reset secret completed successfully", args...) }(time.Now()) return lm.svc.ResetSecret(ctx, token, secret) } -// SendPasswordReset logs the send_password_reset request. It logs the token and the time it took to complete the request. +// SendPasswordReset logs the send_password_reset request. It logs the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) SendPasswordReset(ctx context.Context, host, email, user, token string) (err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method send_password_reset using token %s took %s to complete", token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("host", host), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Send password reset failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Send password reset completed successfully", args...) }(time.Now()) return lm.svc.SendPasswordReset(ctx, host, email, user, token) } -// UpdateClientRole logs the update_client_role request. It logs the client id and token and the time it took to complete the request. +// UpdateClientRole logs the update_client_role request. It logs the client id and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) UpdateClientRole(ctx context.Context, token string, client mgclients.Client) (c mgclients.Client, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method update_client_role for client with id %s using token %s took %s to complete", c.ID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("user", + slog.String("id", c.ID), + slog.String("name", c.Name), + slog.String("role", client.Role.String()), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Update user role failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Update user role completed successfully", args...) }(time.Now()) return lm.svc.UpdateClientRole(ctx, token, client) } -// EnableClient logs the enable_client request. It logs the client id and token and the time it took to complete the request. +// EnableClient logs the enable_client request. It logs the client id and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) EnableClient(ctx context.Context, token, id string) (c mgclients.Client, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method enable_client for client with id %s using token %s took %s to complete", c.ID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("user", + slog.String("id", id), + slog.String("name", c.Name), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Enable user failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Enable user completed successfully", args...) }(time.Now()) return lm.svc.EnableClient(ctx, token, id) } -// DisableClient logs the disable_client request. It logs the client id and token and the time it took to complete the request. +// DisableClient logs the disable_client request. It logs the client id and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) DisableClient(ctx context.Context, token, id string) (c mgclients.Client, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method disable_client for client with id %s using token %s took %s to complete", c.ID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("user", + slog.String("id", id), + slog.String("name", c.Name), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Disable user failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Disable user completed successfully", args...) }(time.Now()) return lm.svc.DisableClient(ctx, token, id) } -// ListMembers logs the list_members request. It logs the group id, token and the time it took to complete the request. +// ListMembers logs the list_members request. It logs the group id, and the time it took to complete the request. // If the request fails, it logs the error. func (lm *loggingMiddleware) ListMembers(ctx context.Context, token, objectKind, objectID string, cp mgclients.Page) (mp mgclients.MembersPage, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method list_members %d members for object kind %s and object id %s and token %s took %s to complete", mp.Total, objectKind, objectID, token, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.Group("object", + slog.String("kind", objectKind), + slog.String("id", objectID), + ), + slog.Group("page", + slog.Uint64("limit", cp.Limit), + slog.Uint64("offset", cp.Offset), + slog.Uint64("total", mp.Total), + ), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("List members failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("List members completed successfully", args...) }(time.Now()) return lm.svc.ListMembers(ctx, token, objectKind, objectID, cp) } -// Identify logs the identify request. It logs the token and the time it took to complete the request. +// Identify logs the identify request. It logs the time it took to complete the request. func (lm *loggingMiddleware) Identify(ctx context.Context, token string) (id string, err error) { defer func(begin time.Time) { - message := fmt.Sprintf("Method identify for token %s with id %s took %s to complete", token, id, time.Since(begin)) + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("user_id", id), + } if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s.", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Identify user failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Identify user completed successfully", args...) }(time.Now()) return lm.svc.Identify(ctx, token) } diff --git a/ws/api/logging.go b/ws/api/logging.go index c04e932501..7ecce696fa 100644 --- a/ws/api/logging.go +++ b/ws/api/logging.go @@ -5,7 +5,6 @@ package api import ( "context" - "fmt" "log/slog" "time" @@ -28,16 +27,19 @@ func LoggingMiddleware(svc ws.Service, logger *slog.Logger) ws.Service { // If the request fails, it logs the error. func (lm *loggingMiddleware) Subscribe(ctx context.Context, thingKey, chanID, subtopic string, c *ws.Client) (err error) { defer func(begin time.Time) { - destChannel := chanID + args := []any{ + slog.String("duration", time.Since(begin).String()), + slog.String("channel_id", chanID), + } if subtopic != "" { - destChannel = fmt.Sprintf("%s.%s", destChannel, subtopic) + args = append(args, "subtopic", subtopic) } - message := fmt.Sprintf("Method subscribe to channel %s took %s to complete", destChannel, time.Since(begin)) if err != nil { - lm.logger.Warn(fmt.Sprintf("%s with error: %s", message, err)) + args = append(args, slog.Any("error", err)) + lm.logger.Warn("Subscibe failed to complete successfully", args...) return } - lm.logger.Info(fmt.Sprintf("%s without errors.", message)) + lm.logger.Info("Subscribe completed successfully", args...) }(time.Now()) return lm.svc.Subscribe(ctx, thingKey, chanID, subtopic, c)