Skip to content

Commit

Permalink
Fixed log message format (#263)
Browse files Browse the repository at this point in the history 
## Why is this needed

Fixes: #259 


## How Has This Been Tested?
Tested by executing a workflow on Vagrant setup. 

## Logs
```
tink-server_1  | {"level":"info","ts":1597993697.729267,"caller":"tink-server/main.go:30","msg":"starting version c94241f","service":"github.com/tinkerbell/tink"}
tink-server_1  | {"level":"info","ts":1597993697.7294364,"caller":"metrics/metrics.go:58","msg":"initializing label values","service":"github.com/tinkerbell/tink"}
tink-server_1  | {"level":"info","ts":1597993697.7324421,"caller":"grpc-server/grpc_server.go:77","msg":"serving grpc","service":"github.com/tinkerbell/tink"}
tink-server_1  | {"level":"info","ts":1597993697.7331507,"caller":"http-server/http_server.go:90","msg":"serving http","service":"github.com/tinkerbell/tink"}
tink-server_1  | {"level":"info","ts":1597993707.0710828,"caller":"grpc-server/workflow.go:153","msg":"listworkflows","service":"github.com/tinkerbell/tink"}
tink-server_1  | {"level":"info","ts":1597993714.4313056,"caller":"grpc-server/workflow.go:119","msg":"deleteworkflow","service":"github.com/tinkerbell/tink"}
tink-server_1  | {"level":"info","ts":1597993714.4314113,"caller":"grpc-server/workflow.go:137","msg":"deleting a workflow","service":"github.com/tinkerbell/tink","workflowID":"668efc38-5072-40ed-b575-98cc4f8dc8e7"}
tink-server_1  | {"level":"info","ts":1597993714.4338477,"caller":"grpc-server/workflow.go:147","msg":"done deleting a workflow","service":"github.com/tinkerbell/tink","workflowID":"668efc38-5072-40ed-b575-98cc4f8dc8e7"}
tink-server_1  | {"level":"info","ts":1597993718.7341084,"caller":"grpc-server/workflow.go:29","msg":"createworkflow","service":"github.com/tinkerbell/tink"}
tink-server_1  | {"level":"info","ts":1597993718.7341583,"caller":"grpc-server/workflow.go:59","msg":"creating a new workflow","service":"github.com/tinkerbell/tink"}
tink-server_1  | {"level":"info","ts":1597993718.7396371,"caller":"grpc-server/workflow.go:71","msg":"done creating a new workflow","service":"github.com/tinkerbell/tink","workflowID":"9abf6d93-e117-4ca0-be11-1bb6f31cb371"}
tink-server_1  | {"level":"info","ts":1597993833.5934675,"caller":"grpc-server/tinkerbell.go:239","msg":"send workflow context: 9abf6d93-e117-4ca0-be11-1bb6f31cb371","service":"github.com/tinkerbell/tink"}
tink-server_1  | {"level":"info","ts":1597993833.5954807,"caller":"grpc-server/tinkerbell.go:96","msg":"received action status: ACTION_IN_PROGRESS","service":"github.com/tinkerbell/tink","actionName":"hello_world","workflowID":"9abf6d93-e117-4ca0-be11-1bb6f31cb371"}
tink-server_1  | {"level":"info","ts":1597993833.5994563,"caller":"grpc-server/tinkerbell.go:146","msg":"current workflow context","service":"github.com/tinkerbell/tink","workflowID":"9abf6d93-e117-4ca0-be11-1bb6f31cb371","currentWorker":"0eba0bf8-3772-4b4a-ab9f-6ebe93b90a94","currentTask":"hello world","currentAction":"hello_world","currentActionIndex":"0","currentActionState":"ACTION_IN_PROGRESS","totalNumberOfActions":1}
tink-server_1  | {"level":"info","ts":1597993833.9179895,"caller":"grpc-server/tinkerbell.go:96","msg":"received action status: ACTION_SUCCESS","service":"github.com/tinkerbell/tink","actionName":"hello_world","workflowID":"9abf6d93-e117-4ca0-be11-1bb6f31cb371"}
tink-server_1  | {"level":"info","ts":1597993833.9213414,"caller":"grpc-server/tinkerbell.go:146","msg":"current workflow context","service":"github.com/tinkerbell/tink","workflowID":"9abf6d93-e117-4ca0-be11-1bb6f31cb371","currentWorker":"0eba0bf8-3772-4b4a-ab9f-6ebe93b90a94","currentTask":"hello world","currentAction":"hello_world","currentActionIndex":"0","currentActionState":"ACTION_SUCCESS","totalNumberOfActions":1}
```
  • Loading branch information
@mergify
mergify[bot] authored Aug 21, 2020
2 parents adb49da + 638dd56 commit 7eb10ca
Show file tree
Hide file tree
Showing 2 changed files with 37 additions and 14 deletions.
23 changes: 18 additions & 5 deletions grpc-server/tinkerbell.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,8 @@ package grpcserver

import (
"context"
"fmt"
"strconv"
"time"

"github.com/tinkerbell/tink/db"
Expand All @@ -21,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"
)

Expand Down Expand Up @@ -90,7 +92,8 @@ func (s *server) ReportActionStatus(context context.Context, req *pb.WorkflowAct
return nil, status.Errorf(codes.InvalidArgument, errInvalidActionName)
}

logger.Info(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 {
Expand Down Expand Up @@ -130,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(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
}

Expand Down Expand Up @@ -218,12 +231,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

}
Expand Down
28 changes: 19 additions & 9 deletions grpc-server/workflow.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,7 @@ import (
"bytes"
"context"
"encoding/json"
"fmt"
"strconv"
"text/template"

"github.com/pkg/errors"
Expand Down Expand Up @@ -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(),
Expand All @@ -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
Expand All @@ -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
}

Expand All @@ -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
Expand All @@ -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
}

Expand All @@ -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
Expand All @@ -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
Expand All @@ -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
}

Expand Down Expand Up @@ -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
Expand All @@ -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
}

Expand Down Expand Up @@ -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
}
Expand Down Expand Up @@ -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
}

0 comments on commit 7eb10ca

Please sign in to comment.