Switching from logrus to packethost/pkg/log in worker #271

gauravgahlot · 2020-08-27T14:27:24Z

Description

Replacing logrus with packethost/pkg/log.

Depends on:

Why is this needed

The PR aims to keep the logging package consistent across the Tink repository.

How Has This Been Tested?

Tested the changes by executing an end-to-end workflow.

Worker Logs

{"log":"{\"level\":\"info\",\"ts\":1598612543.5217416,\"caller\":\"tink-worker/main.go:48\",\"msg\":\"starting version: 6960d5f\",\"service\":\"github.com/tinkerbell/tink\"}\r\n","stream":"stdout","time":"2020-08-28T11:02:23.526199655Z"}
{"log":"{\"level\":\"info\",\"ts\":1598612543.5223653,\"caller\":\"tink-worker/main.go:85\",\"msg\":\"RETRY_INTERVAL not set, using default 3 seconds\",\"service\":\"github.com/tinkerbell/tink\"}\r\n","stream":"stdout","time":"2020-08-28T11:02:23.526229686Z"}
{"log":"{\"level\":\"info\",\"ts\":1598612543.5223973,\"caller\":\"tink-worker/main.go:99\",\"msg\":\"MAX_RETRY not set, using default 3 retries\",\"service\":\"github.com/tinkerbell/tink\"}\r\n","stream":"stdout","time":"2020-08-28T11:02:23.526236012Z"}
{"log":"{\"level\":\"info\",\"ts\":1598612543.5452757,\"caller\":\"tink-worker/worker.go:142\",\"msg\":\"starting with action\",\"service\":\"github.com/tinkerbell/tink\",\"workerId\":\"0eba0bf8-3772-4b4a-ab9f-6ebe93b90a94\",\"workflowId\":\"b3a88595-5bfd-40ed-bd32-766adeab4fa2\",\"actionName\":\"hello_world\",\"taskName\":\"hello world\"}\r\n","stream":"stdout","time":"2020-08-28T11:02:23.545666793Z"}
{"log":"{\"level\":\"info\",\"ts\":1598612543.5510116,\"caller\":\"tink-worker/worker.go:166\",\"msg\":\"sent action status\",\"service\":\"github.com/tinkerbell/tink\",\"workerId\":\"0eba0bf8-3772-4b4a-ab9f-6ebe93b90a94\",\"workflowId\":\"b3a88595-5bfd-40ed-bd32-766adeab4fa2\",\"actionName\":\"hello_world\",\"taskName\":\"hello world\"}\r\n","stream":"stdout","time":"2020-08-28T11:02:23.551388082Z"}
{"log":"{\"status\":\"Pulling from hello-world\",\"id\":\"latest\"}\r\r\n","stream":"stdout","time":"2020-08-28T11:02:23.644575307Z"}
{"log":"{\"status\":\"Pulling fs layer\",\"progressDetail\":{},\"id\":\"0e03bdcc26d7\"}\r\r\n","stream":"stdout","time":"2020-08-28T11:02:23.644659223Z"}
{"log":"{\"status\":\"Downloading\",\"progressDetail\":{\"current\":730,\"total\":2529},\"progress\":\"[==============\\u003e                                    ]     730B/2.529kB\",\"id\":\"0e03bdcc26d7\"}\r\r\n","stream":"stdout","time":"2020-08-28T11:02:23.66942451Z"}
{"log":"{\"status\":\"Downloading\",\"progressDetail\":{\"current\":2529,\"total\":2529},\"progress\":\"[==================================================\\u003e]  2.529kB/2.529kB\",\"id\":\"0e03bdcc26d7\"}\r\r\n","stream":"stdout","time":"2020-08-28T11:02:23.669436361Z"}
{"log":"{\"status\":\"Verifying Checksum\",\"progressDetail\":{},\"id\":\"0e03bdcc26d7\"}\r\r\n","stream":"stdout","time":"2020-08-28T11:02:23.669439988Z"}
{"log":"{\"status\":\"Download complete\",\"progressDetail\":{},\"id\":\"0e03bdcc26d7\"}\r\r\n","stream":"stdout","time":"2020-08-28T11:02:23.66944226Z"}
{"log":"{\"status\":\"Extracting\",\"progressDetail\":{\"current\":2529,\"total\":2529},\"progress\":\"[==================================================\\u003e]  2.529kB/2.529kB\",\"id\":\"0e03bdcc26d7\"}\r\r\n","stream":"stdout","time":"2020-08-28T11:02:23.66944429Z"}
{"log":"{\"status\":\"Extracting\",\"progressDetail\":{\"current\":2529,\"total\":2529},\"progress\":\"[==================================================\\u003e]  2.529kB/2.529kB\",\"id\":\"0e03bdcc26d7\"}\r\r\n","stream":"stdout","time":"2020-08-28T11:02:23.66944685Z"}
{"log":"{\"status\":\"Pull complete\",\"progressDetail\":{},\"id\":\"0e03bdcc26d7\"}\r\r\n","stream":"stdout","time":"2020-08-28T11:02:23.731208642Z"}
{"log":"{\"status\":\"Digest: sha256:90659bf80b44ce6be8234e6ff90a1ac34acbeb826903b02cfa0da11c82cbc042\"}\r\r\n","stream":"stdout","time":"2020-08-28T11:02:23.731223756Z"}
{"log":"{\"status\":\"Status: Downloaded newer image for 192.168.1.1/hello-world:latest\"}\r\r\n","stream":"stdout","time":"2020-08-28T11:02:23.731226604Z"}
{"log":"{\"level\":\"info\",\"ts\":1598612543.6948822,\"caller\":\"tink-worker/action.go:203\",\"msg\":\"starting container with cmd: []\",\"service\":\"github.com/tinkerbell/tink\",\"workflowId\":\"b3a88595-5bfd-40ed-bd32-766adeab4fa2\",\"workerId\":\"0eba0bf8-3772-4b4a-ab9f-6ebe93b90a94\",\"actionName\":\"hello_world\"}\r\n","stream":"stdout","time":"2020-08-28T11:02:23.731228638Z"}
{"log":"\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864270483Z"}
{"log":"Hello from Docker!\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864278931Z"}
{"log":"This message shows that your installation appears to be working correctly.\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864281213Z"}
{"log":"\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864283136Z"}
{"log":"To generate this message, Docker took the following steps:\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864284705Z"}
{"log":" 1. The Docker client contacted the Docker daemon.\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864286483Z"}
{"log":" 2. The Docker daemon pulled the \"hello-world\" image from the Docker Hub.\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864288907Z"}
{"log":"    (amd64)\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864290903Z"}
{"log":" 3. The Docker daemon created a new container from that image which runs the\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864292477Z"}
{"log":"    executable that produces the output you are currently reading.\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864294192Z"}
{"log":" 4. The Docker daemon streamed that output to the Docker client, which sent it\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864295866Z"}
{"log":"    to your terminal.\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864297598Z"}
{"log":"\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864299188Z"}
{"log":"To try something more ambitious, you can run an Ubuntu container with:\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864300687Z"}
{"log":" $ docker run -it ubuntu bash\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864302378Z"}
{"log":"\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864303968Z"}
{"log":"Share images, automate workflows, and more with a free Docker ID:\r\n","stream":"stdout","time":"2020-08-28T11:02:23.86430546Z"}
{"log":" https://hub.docker.com/\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864307212Z"}
{"log":"\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864308793Z"}
{"log":"For more examples and ideas, visit:\r\n","stream":"stdout","time":"2020-08-28T11:02:23.86431029Z"}
{"log":" https://docs.docker.com/get-started/\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864311973Z"}
{"log":"\r\n","stream":"stdout","time":"2020-08-28T11:02:23.864313659Z"}
{"log":"{\"level\":\"info\",\"ts\":1598612543.9096792,\"caller\":\"tink-worker/action.go:266\",\"msg\":\"starting to remove container: eff322d7a5a7bada3d179be6ec927ac2fcac8873c677d2d91d79cfe3fee359f2\",\"service\":\"github.com/tinkerbell/tink\",\"workflowId\":\"b3a88595-5bfd-40ed-bd32-766adeab4fa2\",\"workerId\":\"0eba0bf8-3772-4b4a-ab9f-6ebe93b90a94\",\"actionName\":\"hello_world\"}\r\n","stream":"stdout","time":"2020-08-28T11:02:23.911821295Z"}
{"log":"{\"level\":\"info\",\"ts\":1598612543.9113615,\"caller\":\"tink-worker/action.go:86\",\"msg\":\"container removed with status: ACTION_SUCCESS\",\"service\":\"github.com/tinkerbell/tink\",\"workflowId\":\"b3a88595-5bfd-40ed-bd32-766adeab4fa2\",\"workerId\":\"0eba0bf8-3772-4b4a-ab9f-6ebe93b90a94\",\"actionName\":\"hello_world\"}\r\n","stream":"stdout","time":"2020-08-28T11:02:23.911833548Z"}
{"log":"{\"level\":\"info\",\"ts\":1598612543.9113853,\"caller\":\"tink-worker/action.go:133\",\"msg\":\"action container exit status code: ACTION_SUCCESS\",\"service\":\"github.com/tinkerbell/tink\",\"workflowId\":\"b3a88595-5bfd-40ed-bd32-766adeab4fa2\",\"workerId\":\"0eba0bf8-3772-4b4a-ab9f-6ebe93b90a94\",\"actionName\":\"hello_world\"}\r\n","stream":"stdout","time":"2020-08-28T11:02:23.91183715Z"}
{"log":"{\"level\":\"info\",\"ts\":1598612543.9146202,\"caller\":\"tink-worker/worker.go:211\",\"msg\":\"sent action status\",\"service\":\"github.com/tinkerbell/tink\",\"workerId\":\"0eba0bf8-3772-4b4a-ab9f-6ebe93b90a94\",\"workflowId\":\"b3a88595-5bfd-40ed-bd32-766adeab4fa2\",\"actionName\":\"hello_world\",\"taskName\":\"hello world\"}\r\n","stream":"stdout","time":"2020-08-28T11:02:23.915028437Z"}
{"log":"{\"level\":\"info\",\"ts\":1598612543.916867,\"caller\":\"tink-worker/worker.go:217\",\"msg\":\"reached to end of workflow\",\"service\":\"github.com/tinkerbell/tink\",\"workerId\":\"0eba0bf8-3772-4b4a-ab9f-6ebe93b90a94\",\"workflowId\":\"b3a88595-5bfd-40ed-bd32-766adeab4fa2\"}\r\n","stream":"stdout","time":"2020-08-28T11:02:23.917199393Z"}

codecov · 2020-08-27T14:28:57Z

Codecov Report

Merging #271 into master will not change coverage.
The diff coverage is n/a.

@@           Coverage Diff           @@
##           master     #271   +/-   ##
=======================================
  Coverage   24.24%   24.24%           
=======================================
  Files          15       15           
  Lines        1353     1353           
=======================================
  Hits          328      328           
  Misses       1006     1006           
  Partials       19       19

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 966682b...92b240d. Read the comment docs.

gianarb · 2020-08-27T14:36:30Z

Thank you for taking care of it.
Do you mind to copy/paste here a sample of the new logs?
Thanks

thebsdbox · 2020-08-27T16:41:45Z

Looks like a fantastic start at this 👍

gauravgahlot · 2020-08-28T07:00:11Z

@gianarb @thebsdbox
Added new logs to the description.

mmlb · 2020-09-03T14:47:09Z

@gauravgahlot similar to tinkerbell/osie#107 some of those lines look like they did not come from packethost/pkg/log (the ones missing ts, caller, service keys). I suspect those are from output of docker exec/run -t since it looks like image fetching output and the \r\n is added by docker when -t is passed in I think

mmlb · 2020-09-03T15:47:34Z

@gauravgahlot please rebase

## Description The PR updates Boots to use the latest version of `packethost/pkg/log` package. ## Why is this needed Required for dependent [PR tink #271](tinkerbell/tink#271). ## How Has This Been Tested? Tested by executing an end-to-end workflow.

## Description The PR updates Hegel to use the latest version of `packethost/pkg/log` package. ## Why is this needed Required for dependent [PR tink #271](tinkerbell/tink#271). ## How Has This Been Tested? Tested by executing an end-to-end workflow.

mmlb

Few things need updating wrt the log calls. Also can you change all calls of fmt.Errorf to errors.Wrapf instead.

cmd/tink-worker/action.go

cmd/tink-worker/worker.go

mmlb

Also can you change the calls to errors.Wrapf to just errors.Wrap where there's no fmt'ing done?

cmd/tink-worker/action.go

cmd/tink-worker/main.go

cmd/tink-worker/worker.go

mmlb

2 things should be fixed throughout the whole diff:

Please update the cases where errors.Wrapf was used but errors.Wrap is better.
A bunch of log.With()s are called with context keys that aren't very good keys, should single word for easy lookup. Most of the keys uses actually look like they would be passed to Info() instead.

cmd/tink-worker/action.go

mmlb

allllllllmost there.

cmd/tink-worker/action.go

cmd/tink-worker/main.go

cmd/tink-worker/worker.go

mmlb · 2020-09-15T20:55:06Z

@gauravgahlot can you edit the waitContainer now returns only one 'error' type and explain why its being done please.

The second error type returned by waitContainer was ignored and never logged or used by its only caller executeAction. So, there is no point in returning two error types. Signed-off-by: Gaurav Gahlot <[email protected]>

mmlb

Please squash the review fixes into the replace 'logrus' with 'packethost/pkg/log' commit.

review fixes Signed-off-by: Gaurav Gahlot <[email protected]>

Signed-off-by: Gaurav Gahlot <[email protected]>

mmlb

Finally! Thanks for all the follow through.

gauravgahlot added the kind/feature Categorizes issue or PR as related to a new feature. label Aug 27, 2020

gauravgahlot self-assigned this Aug 27, 2020

gauravgahlot requested review from gianarb and thebsdbox August 27, 2020 14:37

gauravgahlot added the do-not-merge Signal to Mergify to block merging of the PR. label Aug 27, 2020

gauravgahlot force-pushed the worker-logs branch from a48369c to 6960d5f Compare August 28, 2020 05:18

gauravgahlot mentioned this pull request Aug 28, 2020

Adding environment variables required by logger in worker tinkerbell/osie#107

Closed

gauravgahlot removed the do-not-merge Signal to Mergify to block merging of the PR. label Aug 28, 2020

gianarb previously approved these changes Sep 3, 2020

View reviewed changes

gauravgahlot dismissed gianarb’s stale review via ffb5798 September 4, 2020 04:27

gauravgahlot force-pushed the worker-logs branch from 6960d5f to ffb5798 Compare September 4, 2020 04:27

This was referenced Sep 4, 2020

Update packethost/pkg version tinkerbell/hegel#33

Merged

Update packethost/pkg version tinkerbell/smee#77

Merged

gauravgahlot requested a review from gianarb September 4, 2020 06:20

gianarb previously approved these changes Sep 4, 2020

View reviewed changes

mmlb changed the title ~~Switching from logrus to 'packethost/pkg/log' in worker~~ Switching from logrus to packethost/pkg/log in worker Sep 4, 2020

mmlb suggested changes Sep 4, 2020

View reviewed changes

mmlb dismissed gianarb’s stale review via 2fe7ed4 September 4, 2020 13:46

mmlb force-pushed the worker-logs branch from 7ce0d79 to 2fe7ed4 Compare September 4, 2020 13:46

gauravgahlot requested a review from mmlb September 7, 2020 06:53

gauravgahlot force-pushed the worker-logs branch from 0479ed9 to 0e340e7 Compare September 7, 2020 09:33

gianarb previously approved these changes Sep 8, 2020

View reviewed changes

mmlb suggested changes Sep 8, 2020

View reviewed changes

gauravgahlot dismissed gianarb’s stale review via c81380a September 9, 2020 04:21

gauravgahlot force-pushed the worker-logs branch 2 times, most recently from c81380a to 3d934f7 Compare September 10, 2020 12:55

gauravgahlot requested a review from mmlb September 10, 2020 13:01

mmlb suggested changes Sep 10, 2020

View reviewed changes

gauravgahlot force-pushed the worker-logs branch 2 times, most recently from c59f765 to 20b962b Compare September 11, 2020 05:48

gauravgahlot requested a review from mmlb September 11, 2020 06:09

mmlb reviewed Sep 15, 2020

View reviewed changes

gauravgahlot force-pushed the worker-logs branch from 20b962b to 9c1d7b1 Compare September 16, 2020 07:11

gauravgahlot requested a review from mmlb September 16, 2020 07:13

gauravgahlot force-pushed the worker-logs branch from 9c1d7b1 to 266ae83 Compare September 16, 2020 07:31

waitContainer now returns only one 'error' type

9656917

The second error type returned by waitContainer was ignored and never logged or used by its only caller executeAction. So, there is no point in returning two error types. Signed-off-by: Gaurav Gahlot <[email protected]>

gauravgahlot force-pushed the worker-logs branch from 266ae83 to d94afc8 Compare September 16, 2020 14:11

mmlb suggested changes Sep 16, 2020

View reviewed changes

gauravgahlot added 3 commits September 16, 2020 22:20

replace 'logrus' with 'packethost/pkg/log'

9598b29

review fixes Signed-off-by: Gaurav Gahlot <[email protected]>

'pkg/log' version update + go mod tidy

108ca76

Signed-off-by: Gaurav Gahlot <[email protected]>

removed unused env vars

92b240d

Signed-off-by: Gaurav Gahlot <[email protected]>

gauravgahlot force-pushed the worker-logs branch from d94afc8 to 92b240d Compare September 16, 2020 16:53

gauravgahlot requested a review from mmlb September 16, 2020 16:57

mmlb approved these changes Sep 16, 2020

View reviewed changes

mmlb added the ready-to-merge Signal to Mergify to merge the PR. label Sep 16, 2020

mergify bot merged commit 16f8767 into tinkerbell:master Sep 16, 2020

gauravgahlot deleted the worker-logs branch September 16, 2020 17:11

displague mentioned this pull request Sep 21, 2020

tink worker command line args #287

Merged

3 tasks

mmlb removed the ready-to-merge Signal to Mergify to merge the PR. label Jan 25, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Switching from logrus to packethost/pkg/log in worker #271

Switching from logrus to packethost/pkg/log in worker #271

gauravgahlot commented Aug 27, 2020 •

edited

Loading

codecov bot commented Aug 27, 2020 •

edited

Loading

gianarb commented Aug 27, 2020 •

edited

Loading

thebsdbox commented Aug 27, 2020

gauravgahlot commented Aug 28, 2020

mmlb commented Sep 3, 2020

mmlb commented Sep 3, 2020

mmlb left a comment

mmlb left a comment

mmlb left a comment

mmlb left a comment

mmlb commented Sep 15, 2020

mmlb left a comment

mmlb left a comment

Switching from logrus to packethost/pkg/log in worker #271

Switching from logrus to packethost/pkg/log in worker #271

Conversation

gauravgahlot commented Aug 27, 2020 • edited Loading

Description

Why is this needed

How Has This Been Tested?

Worker Logs

codecov bot commented Aug 27, 2020 • edited Loading

Codecov Report

gianarb commented Aug 27, 2020 • edited Loading

thebsdbox commented Aug 27, 2020

gauravgahlot commented Aug 28, 2020

mmlb commented Sep 3, 2020

mmlb commented Sep 3, 2020

mmlb left a comment

Choose a reason for hiding this comment

mmlb left a comment

Choose a reason for hiding this comment

mmlb left a comment

Choose a reason for hiding this comment

mmlb left a comment

Choose a reason for hiding this comment

mmlb commented Sep 15, 2020

mmlb left a comment

Choose a reason for hiding this comment

mmlb left a comment

Choose a reason for hiding this comment

gauravgahlot commented Aug 27, 2020 •

edited

Loading

codecov bot commented Aug 27, 2020 •

edited

Loading

gianarb commented Aug 27, 2020 •

edited

Loading