refactor: Replace logging package with corelog #2406

nasdf · 2024-03-13T00:07:24Z

Relevant issue(s)

Resolves #2405

Description

This PR replaces the logging package with the corelog library.

Please review along with sourcenetwork/corelog#2

corelog utilizes the log/slog standard library package to produce structured logs.

The interface is kept mostly the same with some modifications:

Debug and Fatal levels have been removed
context for logging calls has been moved to a context specific variant. For example Info has a InfoContext variant.
Feedback methods have been removed in favor of restricting the output to stderr and stdout.
Supported output formats are text or json. csv is not supported by slog
Support for colored logs is not yet implemented, but can be easily added in a future PR.

Tasks

I made sure the code is well commented, particularly hard-to-understand areas.
I made sure the repository-held documentation is changed accordingly.
I made sure the pull request title adheres to the conventional commit style (the subset used in the project can be found in tools/configs/chglog/config.yml).
I made sure to discuss its limitations such as threats to validity, vulnerability to mistake and misuse, robustness to invalidation of assumptions, resource requirements, ...

How has this been tested?

Manually tested

Specify the platform(s) on which this was tested:

MacOS

codecov · 2024-03-13T00:27:07Z

Codecov Report

Attention: Patch coverage is 58.99281% with 57 lines in your changes are missing coverage. Please review.

Project coverage is 74.90%. Comparing base (c74a6f7) to head (b525ef1).

Additional details and impacted files

@@             Coverage Diff             @@
##           develop    #2406      +/-   ##
===========================================
- Coverage    75.07%   74.90%   -0.17%     
===========================================
  Files          272      268       -4     
  Lines        26332    25856     -476     
===========================================
- Hits         19768    19367     -401     
+ Misses        5225     5162      -63     
+ Partials      1339     1327      -12

Flag	Coverage Δ
all-tests	`74.90% <58.99%> (-0.17%)`	⬇️

Flags with carried forward coverage won't be shown. Click here to find out more.

Files	Coverage Δ
cli/cli.go	`100.00% <ø> (ø)`
cli/config.go	`79.45% <100.00%> (+9.45%)`	⬆️
cli/root.go	`95.73% <100.00%> (+0.23%)`	⬆️
db/subscriptions.go	`83.72% <100.00%> (+6.98%)`	⬆️
http/logger.go	`85.71% <100.00%> (ø)`
merkle/crdt/composite.go	`75.00% <ø> (-1.32%)`	⬇️
merkle/crdt/merklecrdt.go	`87.80% <ø> (ø)`
net/client.go	`100.00% <ø> (ø)`
cli/server_dump.go	`19.23% <0.00%> (ø)`
db/collection.go	`73.23% <0.00%> (ø)`
... and 13 more

... and 8 files with indirect coverage changes

Continue to review full report in Codecov by Sentry.

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

AndrewSisley · 2024-03-13T03:29:58Z

Hi Keenan - could you please summarise the key differences between the corelog lib and the defradb/logging package? I assume the zap logger has been replaced by the std lib logger, but has anything else changed?

And has the corelog lib been reviewed by anyone? Should we also review it in this PR?

nasdf · 2024-03-13T16:43:35Z

And has the corelog lib been reviewed by anyone? Should we also review it in this PR?

I think it'd be nice to have them both reviewed before merging.

AndrewSisley · 2024-03-13T17:13:46Z

Thanks Keenan :)

context for logging calls has been moved to a context specific variant. For example Info has a InfoContext variant.

What is the reasoning behind this change? Is there a Source use-case for calling Info without a ctx?

And did you consider calling it InfoCtx instead? Do you know of other logging packages using this naming?

nasdf · 2024-03-13T17:22:26Z

Thanks Keenan :)

context for logging calls has been moved to a context specific variant. For example Info has a InfoContext variant.

What is the reasoning behind this change? Is there a Source use-case for calling Info without a ctx?

There's a few cases within DefraDB that did not have a proper context and I wanted it to be flexible for the other projects.

And did you consider calling it InfoCtx instead? Do you know of other logging packages using this naming?

This is the same API as the slog package.

AndrewSisley

The code changes in this repo look good, but I want the coreLog lib to be reviewed before this is merged, and there is a design change that I would like the team to chat about and agree upon too (RE log args).

AndrewSisley · 2024-03-13T17:38:25Z

http/logger.go

-		logging.NewKV("Status", status),
-		logging.NewKV("LengthBytes", bytes),
-		logging.NewKV("ElapsedTime", elapsed.String()),
+		"Method", e.req.Method,


todo: These no longer look 'structured' looking at the call "Method": methodValue, "Path": pathValue, etc, instead it looks like they would be logged as equal and independent values "Method", methodValue, "Path", pathValue, ...?

I think that is a loss, and one worth chatting about with the team.

It is possible to use slog.String("key", "val") or any of the other variants here in place of the alternating key value pairs. I have a slight preference for the alternating key values but happy to hear more opinions.

I'm also in favour of using slog.String("key", "val"). Is there a reason for your preference of the alternating key value pairs that could help change our minds?

Is there a reason for your preference of the alternating key value pairs that could help change our minds?

It's easier for me to read, but I don't mind the other option.

It's easier for me to read, but I don't mind the other option.

Might be worth chatting with the protocol (and the rest of the db team) about this - whilst the current interface allows for both to be used, we might want to force slog.Foo("Key", val) like the old logging package used to.

Changing func (l *Logger) Info(msg string, args ...any) into func (l *Logger) Info(msg string, args ...slog.Attr) .

fredcarle

Feedback methods have been removed in favor of restricting the output to stderr and stdout

The Feedback methods allowed sending the logs to a log file but also return useful messages to the terminal. Any plans to support the same functionality? Or is there a more devex appropriate way to do this?

fredcarle · 2024-03-14T03:19:34Z

datastore/blockstore.go

@@ -64,7 +64,7 @@ func (bs *bstore) HashOnRead(enabled bool) {
 // Get returns a block from the blockstore.
 func (bs *bstore) Get(ctx context.Context, k cid.Cid) (blocks.Block, error) {
 	if !k.Defined() {
-		log.Error(ctx, "Undefined CID in blockstore")
+		log.ErrorContext(ctx, "Undefined CID in blockstore")


suggestion: We should remove the error logging here since an error is returned to the caller.

fredcarle · 2024-03-14T03:22:24Z

http/logger.go

-		logging.NewKV("Status", status),
-		logging.NewKV("LengthBytes", bytes),
-		logging.NewKV("ElapsedTime", elapsed.String()),
+		"Method", e.req.Method,


I'm also in favour of using slog.String("key", "val"). Is there a reason for your preference of the alternating key value pairs that could help change our minds?

fredcarle · 2024-03-14T03:25:57Z

net/server.go

 		return nil, err
 	}

 	ctx := grpcpeer.NewContext(s.peer.ctx, &grpcpeer.Peer{
 		Addr: addr{from},
 	})
 	if _, err := s.PushLog(ctx, req); err != nil {
-		log.ErrorE(ctx, "Failed pushing log for doc", err, logging.NewKV("Topic", topic))
+		log.ErrorContextE(ctx, "Failed pushing log for doc", err, "Topic", topic)


todo: This error log should just be removed.

nasdf · 2024-03-14T17:31:55Z

Feedback methods have been removed in favor of restricting the output to stderr and stdout

The Feedback methods allowed sending the logs to a log file but also return useful messages to the terminal. Any plans to support the same functionality? Or is there a more devex appropriate way to do this?

My main concern with logging to a file is that we don't have a log rotation system. Cloud deployments usually come with a way to automatically capture logs, docker has a built in logging driver, and linux deployments can use syslog or systemd / journalctl.

fredcarle · 2024-03-15T18:13:03Z

I just tested out what it looks like in the terminal.

time=2024-03-15T13:55:36.073-04:00 level=INFO msg="Providing HTTP API at http://127.0.0.1:9181." name=node
time=2024-03-15T13:57:05.898-04:00 level=INFO msg=Request name=http Method=POST Path=/api/v0/graphql Status=200 LengthBytes=26 ElapsedTime=4.096792ms

One thing that I would prefer is the have the name field before or after level but definitely before msg since I feel like it's confusing the focus of trying to understand what the logs is trying to tell me. I know it doesn't matter for a log capturing tool that can re organise everything but when looked at raw by devs, in my case anyways, once I hit the msg, I want only msg related information past that point. I hope that makes sense. Does anyone else feel this way?

AndrewSisley · 2024-03-15T18:31:33Z

One thing that I would prefer is the have the name field before or after level but definitely before msg since I feel like it's confusing the focus of trying to understand what the logs is trying to tell me. I know it doesn't matter for a log capturing tool that can re organise everything but when looked at raw by devs, in my case anyways, once I hit the msg, I want only msg related information past that point. I hope that makes sense. Does anyone else feel this way?

Very nice spot :) I think it should be before level too. It is particularly bad in its current location as it now shares the same format as the structured params (this also feels problematic from a collision perspective).

nasdf · 2024-03-15T19:17:07Z

I just tested out what it looks like in the terminal.
time=2024-03-15T13:55:36.073-04:00 level=INFO msg="Providing HTTP API at http://127.0.0.1:9181." name=node
time=2024-03-15T13:57:05.898-04:00 level=INFO msg=Request name=http Method=POST Path=/api/v0/graphql Status=200 LengthBytes=26 ElapsedTime=4.096792ms
One thing that I would prefer is the have the name field before or after level but definitely before msg since I feel like it's confusing the focus of trying to understand what the logs is trying to tell me. I know it doesn't matter for a log capturing tool that can re organise everything but when looked at raw by devs, in my case anyways, once I hit the msg, I want only msg related information past that point. I hope that makes sense. Does anyone else feel this way?

It's possible to change the order but we'll need to rename the variables. This should also help avoid attribute name collisions. Which version does everyone prefer?

_time=2024-03-15T12:12:06.883-07:00 _name=test _level=INFO _msg=message

$time=2024-03-15T12:14:35.429-07:00 $name=test $level=INFO $msg=message

AndrewSisley · 2024-03-15T19:29:34Z

It's possible to change the order but we'll need to rename the variables.

Weirdly I think I prefer the $ prefix, but no strong preference.

fredcarle · 2024-03-15T20:01:04Z

It's possible to change the order but we'll need to rename the variables.

Weirdly I think I prefer the $ prefix, but no strong preference.

Same 👍

AndrewSisley

LGTM, thanks a bunch Keenan :)

fredcarle

LGTM!

nasdf added 4 commits February 15, 2024 16:55

start logging refactor

714eb36

Merge branch 'develop' into nasdf/refactor/logging

bb78df1

remove logging package

e4d1384

Merge branch 'develop' into nasdf/refactor/logging

30c6773

nasdf self-assigned this Mar 13, 2024

nasdf added the area/logging Related to the logging/logger system label Mar 13, 2024

nasdf added this to the DefraDB v0.11 milestone Mar 13, 2024

nasdf requested a review from a team March 13, 2024 00:08

AndrewSisley reviewed Mar 13, 2024

View reviewed changes

add logging config docs

2a1486a

fredcarle reviewed Mar 14, 2024

View reviewed changes

nasdf added 2 commits March 15, 2024 10:40

update to corelog v0.0.5

e7edde7

update log config docs. update config tests.

4d69fc3

nasdf requested review from AndrewSisley and fredcarle March 15, 2024 17:49

nasdf and others added 2 commits March 18, 2024 10:39

update to corelog v0.0.6

ee68bc9

Merge branch 'develop' into nasdf/refactor/logging

b525ef1

AndrewSisley approved these changes Mar 19, 2024

View reviewed changes

fredcarle approved these changes Mar 19, 2024

View reviewed changes

nasdf merged commit d1b1a76 into sourcenetwork:develop Mar 19, 2024
31 of 32 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

refactor: Replace logging package with corelog #2406

refactor: Replace logging package with corelog #2406

nasdf commented Mar 13, 2024 •

edited

Loading

codecov bot commented Mar 13, 2024 •

edited

Loading

AndrewSisley commented Mar 13, 2024 •

edited

Loading

nasdf commented Mar 13, 2024

AndrewSisley commented Mar 13, 2024

nasdf commented Mar 13, 2024

AndrewSisley left a comment

AndrewSisley Mar 13, 2024

nasdf Mar 13, 2024

fredcarle Mar 14, 2024

nasdf Mar 14, 2024

AndrewSisley Mar 14, 2024 •

edited

Loading

fredcarle left a comment

fredcarle Mar 14, 2024

fredcarle Mar 14, 2024

fredcarle Mar 14, 2024

nasdf commented Mar 14, 2024

fredcarle commented Mar 15, 2024

AndrewSisley commented Mar 15, 2024

nasdf commented Mar 15, 2024

AndrewSisley commented Mar 15, 2024

fredcarle commented Mar 15, 2024

AndrewSisley left a comment

fredcarle left a comment

refactor: Replace logging package with corelog #2406

refactor: Replace logging package with corelog #2406

Conversation

nasdf commented Mar 13, 2024 • edited Loading

Relevant issue(s)

Description

Tasks

How has this been tested?

codecov bot commented Mar 13, 2024 • edited Loading

Codecov Report

AndrewSisley commented Mar 13, 2024 • edited Loading

nasdf commented Mar 13, 2024

AndrewSisley commented Mar 13, 2024

nasdf commented Mar 13, 2024

AndrewSisley left a comment

Choose a reason for hiding this comment

AndrewSisley Mar 13, 2024

Choose a reason for hiding this comment

nasdf Mar 13, 2024

Choose a reason for hiding this comment

fredcarle Mar 14, 2024

Choose a reason for hiding this comment

nasdf Mar 14, 2024

Choose a reason for hiding this comment

AndrewSisley Mar 14, 2024 • edited Loading

Choose a reason for hiding this comment

fredcarle left a comment

Choose a reason for hiding this comment

fredcarle Mar 14, 2024

Choose a reason for hiding this comment

fredcarle Mar 14, 2024

Choose a reason for hiding this comment

fredcarle Mar 14, 2024

Choose a reason for hiding this comment

nasdf commented Mar 14, 2024

fredcarle commented Mar 15, 2024

AndrewSisley commented Mar 15, 2024

nasdf commented Mar 15, 2024

AndrewSisley commented Mar 15, 2024

fredcarle commented Mar 15, 2024

AndrewSisley left a comment

Choose a reason for hiding this comment

fredcarle left a comment

Choose a reason for hiding this comment

nasdf commented Mar 13, 2024 •

edited

Loading

codecov bot commented Mar 13, 2024 •

edited

Loading

AndrewSisley commented Mar 13, 2024 •

edited

Loading

AndrewSisley Mar 14, 2024 •

edited

Loading