Fixed log message format

[gauravgahlot]

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}

[codecov]

Codecov Report

Merging #263 into master will increase coverage by 0.62%.
The diff coverage is 43.75%.

@@            Coverage Diff             @@
##           master     #263      +/-   ##
==========================================
+ Coverage   12.36%   12.98%   +0.62%     
==========================================
  Files           7        7              
  Lines        1165     1186      +21     
==========================================
+ Hits          144      154      +10     
- Misses       1010     1021      +11     
  Partials       11       11              

Impacted Files	Coverage Δ
grpc-server/workflow.go	0.00% <0.00%> (ø)
grpc-server/tinkerbell.go	91.48% <100.00%> (+0.64%)	⬆️

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update adb49da...638dd56. Read the comment docs.

[gianarb]

tink-server_1  | {"level":"info","ts":1597848347.5875487,"caller":"grpc-server/tinkerbell.go:134","msg":"current workflow context: workflow_id:\"5a6a4aef-0f53-421e-9552-80f93b9ca7a4\" current_worker:\"0eba0bf8-3772-4b4a-ab9f-6ebe93b90a94\" current_task:\"hello world\" current_action:\"hello_world\" current_action_state:ACTION_IN_PROGRESS total_number_of_actions:1","service":"github.com/tinkerbell/tink"}

I think this one has to be fixed as well

[gianarb]

Do we have a way to add more information as key=value pair in the log itself?

{"level":"info","ts":1597848234.8412561,"caller":"grpc-server/workflow.go:62","msg":"done creating a new workflow","service":"github.com/tinkerbell/tink"}

I would like this to be:

{"level":"info","ts":1597848234.8412561,"caller":"grpc-server/workflow.go:62","msg":"done creating a new workflow", "service":"github.com/tinkerbell/tink", "workflowID": "5hs4gs454g"}

and:

{"level":"info","ts":1597848347.937874,"caller":"grpc-server/tinkerbell.go:94","msg":"received action status: ACTION_SUCCESS","service":"github.com/tinkerbell/tink"}

to be:

{"level":"info","ts":1597848347.937874,"caller":"grpc-server/tinkerbell.go:94","msg":"received action status: ACTION_SUCCESS","service":"github.com/tinkerbell/tink", "actionID": "asergsergse", "workflowID": "gse5hs45hs4
}

Otherwise those logs sounds useless

[gauravgahlot]

I agree. Without those values, these logs are not useful.

I'm not sure if we have a way to change the behavior. Everything we pass to logger.Info is added to the key msg.
Logger comes from packethost/pkg and internally uses Zap.

[gauravgahlot]

@gianarb I have updated the description with new logs.