From cde27367a71f61772b72e8522048ebe547a0add8 Mon Sep 17 00:00:00 2001 From: Gaurav Gahlot Date: Wed, 19 Aug 2020 20:17:46 +0530 Subject: [PATCH 1/2] fixed log format Signed-off-by: Gaurav Gahlot --- grpc-server/tinkerbell.go | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/grpc-server/tinkerbell.go b/grpc-server/tinkerbell.go index 732ff2ecc..66b621831 100644 --- a/grpc-server/tinkerbell.go +++ b/grpc-server/tinkerbell.go @@ -2,6 +2,7 @@ package grpcserver import ( "context" + "fmt" "time" "github.com/tinkerbell/tink/db" @@ -90,7 +91,7 @@ func (s *server) ReportActionStatus(context context.Context, req *pb.WorkflowAct return nil, status.Errorf(codes.InvalidArgument, errInvalidActionName) } - logger.Info(msgReceivedStatus, req.GetActionStatus()) + logger.Info(fmt.Sprintf(msgReceivedStatus, req.GetActionStatus())) wfContext, err := s.db.GetWorkflowContexts(context, wfID) if err != nil { @@ -130,7 +131,7 @@ func (s *server) ReportActionStatus(context context.Context, req *pb.WorkflowAct if err != nil { return &pb.Empty{}, status.Error(codes.Aborted, err.Error()) } - logger.Info(msgCurrentWfContext, wfContext) + logger.Info(fmt.Sprintf(msgCurrentWfContext, wfContext)) return &pb.Empty{}, nil } @@ -218,12 +219,12 @@ func isApplicableToSend(context context.Context, wfContext *pb.WorkflowContext, } if wfContext.GetCurrentActionIndex() == 0 { if actions.ActionList[wfContext.GetCurrentActionIndex()+1].GetWorkerId() == workerID { - logger.Info(msgSendWfContext, wfContext.GetWorkflowId()) + logger.Info(fmt.Sprintf(msgSendWfContext, wfContext.GetWorkflowId())) return true } } } else if actions.ActionList[wfContext.GetCurrentActionIndex()].GetWorkerId() == workerID { - logger.Info(msgSendWfContext, wfContext.GetWorkflowId()) + logger.Info(fmt.Sprintf(msgSendWfContext, wfContext.GetWorkflowId())) return true } From 638dd56ca2820462021dc296c32c2f354f159509 Mon Sep 17 00:00:00 2001 From: Gaurav Gahlot Date: Fri, 21 Aug 2020 12:23:01 +0530 Subject: [PATCH 2/2] adding sensible data to logs Signed-off-by: Gaurav Gahlot --- grpc-server/tinkerbell.go | 18 +++++++++++++++--- grpc-server/workflow.go | 28 +++++++++++++++++++--------- 2 files changed, 34 insertions(+), 12 deletions(-) diff --git a/grpc-server/tinkerbell.go b/grpc-server/tinkerbell.go index 66b621831..168b78147 100644 --- a/grpc-server/tinkerbell.go +++ b/grpc-server/tinkerbell.go @@ -3,6 +3,7 @@ package grpcserver import ( "context" "fmt" + "strconv" "time" "github.com/tinkerbell/tink/db" @@ -22,7 +23,7 @@ const ( errInvalidActionReported = "reported action name does not match the current action details" msgReceivedStatus = "received action status: %s" - msgCurrentWfContext = "current workflow context: %s" + msgCurrentWfContext = "current workflow context" msgSendWfContext = "send workflow context: %s" ) @@ -91,7 +92,8 @@ func (s *server) ReportActionStatus(context context.Context, req *pb.WorkflowAct return nil, status.Errorf(codes.InvalidArgument, errInvalidActionName) } - logger.Info(fmt.Sprintf(msgReceivedStatus, req.GetActionStatus())) + l := logger.With("actionName", req.GetActionName(), "workflowID", req.GetWorkflowId()) + l.Info(fmt.Sprintf(msgReceivedStatus, req.GetActionStatus())) wfContext, err := s.db.GetWorkflowContexts(context, wfID) if err != nil { @@ -131,7 +133,17 @@ func (s *server) ReportActionStatus(context context.Context, req *pb.WorkflowAct if err != nil { return &pb.Empty{}, status.Error(codes.Aborted, err.Error()) } - logger.Info(fmt.Sprintf(msgCurrentWfContext, wfContext)) + + l = logger.With( + "workflowID", wfContext.GetWorkflowId(), + "currentWorker", wfContext.GetCurrentWorker(), + "currentTask", wfContext.GetCurrentTask(), + "currentAction", wfContext.GetCurrentAction(), + "currentActionIndex", strconv.FormatInt(wfContext.GetCurrentActionIndex(), 10), + "currentActionState", wfContext.GetCurrentActionState(), + "totalNumberOfActions", wfContext.GetTotalNumberOfActions(), + ) + l.Info(msgCurrentWfContext) return &pb.Empty{}, nil } diff --git a/grpc-server/workflow.go b/grpc-server/workflow.go index 0ecfc24d7..4b6b7876b 100644 --- a/grpc-server/workflow.go +++ b/grpc-server/workflow.go @@ -4,7 +4,7 @@ import ( "bytes" "context" "encoding/json" - "fmt" + "strconv" "text/template" "github.com/pkg/errors" @@ -34,7 +34,6 @@ func (s *server) CreateWorkflow(ctx context.Context, in *workflow.CreateRequest) labels["op"] = "createworkflow" msg = "creating a new workflow" id := uuid.NewV4() - //var data string fn := func() error { wf := db.Workflow{ ID: id.String(), @@ -59,7 +58,6 @@ func (s *server) CreateWorkflow(ctx context.Context, in *workflow.CreateRequest) logger.Info(msg) err := fn() - logger.Info("done " + msg) if err != nil { metrics.CacheErrors.With(labels).Inc() l := logger @@ -69,6 +67,8 @@ func (s *server) CreateWorkflow(ctx context.Context, in *workflow.CreateRequest) l.Error(err) return &workflow.CreateResponse{}, err } + l := logger.With("workflowID", id.String()) + l.Info("done " + msg) return &workflow.CreateResponse{Id: id.String()}, err } @@ -90,7 +90,6 @@ func (s *server) GetWorkflow(ctx context.Context, in *workflow.GetRequest) (*wor logger.Info(msg) w, err := fn() - logger.Info("done " + msg) if err != nil { metrics.CacheErrors.With(labels).Inc() l := logger @@ -110,6 +109,8 @@ func (s *server) GetWorkflow(ctx context.Context, in *workflow.GetRequest) (*wor State: state[w.State], Data: yamlData, } + l := logger.With("workflowID", w.ID) + l.Info("done " + msg) return wf, err } @@ -122,6 +123,7 @@ func (s *server) DeleteWorkflow(ctx context.Context, in *workflow.GetRequest) (* msg := "" labels["op"] = "delete" + l := logger.With("workflowID", in.GetId()) msg = "deleting a workflow" fn := func() error { // update only if not in running state @@ -132,9 +134,8 @@ func (s *server) DeleteWorkflow(ctx context.Context, in *workflow.GetRequest) (* timer := prometheus.NewTimer(metrics.CacheDuration.With(labels)) defer timer.ObserveDuration() - logger.Info(msg) + l.Info(msg) err := fn() - logger.Info("done " + msg) if err != nil { metrics.CacheErrors.With(labels).Inc() l := logger @@ -143,6 +144,7 @@ func (s *server) DeleteWorkflow(ctx context.Context, in *workflow.GetRequest) (* } l.Error(err) } + l.Info("done " + msg) return &workflow.Empty{}, err } @@ -201,7 +203,6 @@ func (s *server) GetWorkflowContext(ctx context.Context, in *workflow.GetRequest logger.Info(msg) w, err := fn() - logger.Info("done " + msg) if err != nil { metrics.CacheErrors.With(labels).Inc() l := logger @@ -219,6 +220,16 @@ func (s *server) GetWorkflowContext(ctx context.Context, in *workflow.GetRequest CurrentActionState: workflow.ActionState(w.CurrentActionState), TotalNumberOfActions: w.TotalNumberOfActions, } + l := logger.With( + "workflowID", wf.GetWorkflowId(), + "currentWorker", wf.GetCurrentWorker(), + "currentTask", wf.GetCurrentTask(), + "currentAction", wf.GetCurrentAction(), + "currentActionIndex", strconv.FormatInt(wf.GetCurrentActionIndex(), 10), + "currentActionState", wf.GetCurrentActionState(), + "totalNumberOfActions", wf.GetTotalNumberOfActions(), + ) + l.Info("done " + msg) return wf, err } @@ -257,7 +268,7 @@ func (s *server) ShowWorkflowEvents(req *workflow.GetRequest, stream workflow.Wo metrics.CacheErrors.With(labels).Inc() return err } - logger.Info("Done Listing workflows Events") + logger.Info("done listing workflows events") metrics.CacheHits.With(labels).Inc() return nil } @@ -290,6 +301,5 @@ func renderTemplate(tempData string, devices []byte) (string, error) { if err != nil { return "", nil } - fmt.Println(buf.String()) return buf.String(), nil }