Simplify logging by using slog #1572

lalexgap · 2023-08-21T17:53:41Z

This PR updates go-nitro to use slog instead of zerolog with the goal of simplifying our logging. Instead of having to pass loggers or log destinations around we now rely on setting a global DefaultLogger.

How does it work?

A test or CLI sets up a default logger. This can done by calling logging.SetupDefaultFileLogger. This means any log statements will be output to the specified file.
Optionally, components create a sub logger off the default logger that includes additional information. For example in the engine we create a sub-logger that includes the address information. Whenever the engine's logger is used it will include the address as part of the structured log output.
Log things out using by using a components sub logger (IE: e.logger.Info("Engine started")). If there is no sub-logger, you can just use slog which will resolve to the default logger (IE:slog.Info("Hello World"))

What does it look like?

{"time":"2023-08-22T10:36:00.075628-07:00","level":"DEBUG","msg":"Received notification","address":"0x7E5F4552091A69125d5DfCb7b8C2659029395Bdf","method":"ledger_channel_updated"}
{"time":"2023-08-22T10:36:00.075727-07:00","level":"DEBUG","msg":"Received notification","address":"0x2B5AD5c4795c026514f8317c7a215E218DcCD6cF","method":"objective_completed"}
{"time":"2023-08-22T10:36:00.075741-07:00","level":"DEBUG","msg":"Received notification","address":"0x2B5AD5c4795c026514f8317c7a215E218DcCD6cF","method":"ledger_channel_updated"}
{"time":"2023-08-22T10:36:00.075744-07:00","level":"INFO","msg":"Ledger channels created"}
{"time":"2023-08-22T10:36:00.075908-07:00","level":"DEBUG","msg":"sent message","address":"0x7E5F4552091A69125d5DfCb7b8C2659029395Bdf","method":"create_ledger_channel"}
{"time":"2023-08-22T10:36:00.076021-07:00","level":"DEBUG","msg":"Rpc server received request","address":"0x7E5F4552091A69125d5DfCb7b8C2659029395Bdf","requestData":"{\"jsonrpc\":\"2.0\",\"id\":17534221248848771042,\"method\":\"create_ledger_channel\",\"params\":{\"CounterParty\":\"0x2b5ad5c4795c026514f8317c7a215e218dccd6cf\",\"ChallengeDuration\":100,\"Outcome\":[{\"Asset\":\"0x0000000000000000000000000000000000000000\",\"AssetMetadata\":{\"AssetType\":0,\"Metadata\":null},\"Allocations\":[{\"Destination\":\"0x0000000000000000000000007e5f4552091a69125d5dfcb7b8c2659029395bdf\",\"Amount\":100,\"AllocationType\":0,\"Metadata\":null},{\"Destination\":\"0x0000000000000000000000002b5ad5c4795c026514f8317c7a215e218dccd6cf\",\"Amount\":100,\"AllocationType\":0,\"Metadata\":null}]}],\"AppDefinition\":\"0x0000000000000000000000000000000000000000\",\"AppData\":null,\"Nonce\":1818302577464476722}}"}
{"time":"2023-08-22T10:36:00.076091-07:00","level":"ERROR","msg":"directfund: channel already exists","error":"directfund: ledger channel already exists"}
{"time":"2023-08-22T10:36:00.076389-07:00","level":"DEBUG","msg":"sent message","address":"0x7E5F4552091A69125d5DfCb7b8C2659029395Bdf","method":"get_ledger_channel"}
{"time":"2023-08-22T10:36:00.076481-07:00","level":"DEBUG","msg":"Rpc server received request","address":"0x7E5F4552091A69125d5DfCb7b8C2659029395Bdf","requestData":"{\"jsonrpc\":\"2.0\",\"id\":7267307661299658688,\"method\":\"get_ledger_channel\",\"params\":{\"Id\":\"0x1a6e7b5ffdd17823b2b2f3dc68f18b780f826a59c31d61d3dff3ef06e437f28a\"}}"}
{"time":"2023-08-22T10:36:00.076765-07:00","level":"DEBUG","msg":"sent message","address":"0x2B5AD5c4795c026514f8317c7a215E218DcCD6cF","method":"get_ledger_channel"}
{"time":"2023-08-22T10:36:00.076841-07:00","level":"DEBUG","msg":"Rpc server received request","address":"0x2B5AD5c4795c026514f8317c7a215E218DcCD6cF","requestData":"{\"jsonrpc\":\"2.0\",\"id\":2612235265012651114,\"method\":\"get_ledger_channel\",\"params\":{\"Id\":\"0x1a6e7b5ffdd17823b2b2f3dc68f18b780f826a59c31d61d3dff3ef06e437f28a\"}}"}
{"time":"2023-08-22T10:36:00.077152-07:00","level":"DEBUG","msg":"sent message","address":"0x7E5F4552091A69125d5DfCb7b8C2659029395Bdf","method":"create_payment_channel"}
{"time":"2023-08-22T10:36:00.07725-07:00","level":"DEBUG","msg":"Rpc server received request","address":"0x7E5F4552091A69125d5DfCb7b8C2659029395Bdf","requestData":"{\"jsonrpc\":\"2.0\",\"id\":6459807816628571679,\"method\":\"create_payment_channel\",\"params\":{\"Intermediaries\":[],\"CounterParty\":\"0x2b5ad5c4795c026514f8317c7a215e218dccd6cf\",\"ChallengeDuration\":100,\"Outcome\":[{\"Asset\":\"0x0000000000000000000000000000000000000000\",\"AssetMetadata\":{\"AssetType\":0,\"Metadata\":null},\"Allocations\":[{\"Destination\":\"0x0000000000000000000000007e5f4552091a69125d5dfcb7b8c2659029395bdf\",\"Amount\":100,\"AllocationType\":0,\"Metadata\":null},{\"Destination\":\"0x0000000000000000000000002b5ad5c4795c026514f8317c7a215e218dccd6cf\",\"Amount\":0,\"AllocationType\":0,\"Metadata\":null}]}],\"Nonce\":8948917128598512239,\"AppDefinition\":\"0x0000000000000000000000000000000000000000\"}}"}
{"time":"2023-08-22T10:36:00.0773-07:00","level":"INFO","msg":"handling new objective request","address":"0x7E5F4552091A69125d5DfCb7b8C2659029395Bdf","objective-id":"VirtualFund-0x6c939195be84d39af44fe6a9f21cf25a779ac1e0f7b7f477b3429947235ba9a4"}
{"time":"2023-08-22T10:36:00.077605-07:00","level":"INFO","msg":"Objective cranked","address":"0x7E5F4552091A69125d5DfCb7b8C2659029395Bdf","objective-id":"VirtualFund-0x6c939195be84d39af44fe6a9f21cf25a779ac1e0f7b7f477b3429947235ba9a4","waiting-for":"WaitingForCompletePrefund"}
{"time":"2023-08-22T10:36:00.077615-07:00","level":"DEBUG","msg":"Sending notification","address":"0x7E5F4552091A69125d5DfCb7b8C2659029395Bdf","method":"payment_channel_updated","payload":{"ID":"0x6c939195be84d39af44fe6a9f21cf25a779ac1e0f7b7f477b3429947235ba9a4","Status":"Proposed","Balance":{"AssetAddress":"0x0000000000000000000000000000000000000000","Payee":"0x2b5ad5c4795c026514f8317c7a215e218dccd6cf","Payer":"0x7e5f4552091a69125d5dfcb7b8c2659029395bdf","PaidSoFar":"0x0","RemainingFunds":"0x64"}}}
{"time":"2023-08-22T10:36:00.077625-07:00","level":"DEBUG","msg":"Sent message","address":"0x7E5F4552091A69125d5DfCb7b8C2659029395Bdf","msg":{"To":"0x2B5AD5","From":"0x7E5F45","PayloadSummaries":[{"ObjectiveId":"VirtualFund-0x6c939195be84d39af44fe6a9f21cf25a779ac1e0f7b7f477b3429947235ba9a4","Type":"SignedStatePayload","PayloadDataSize":823}],"ProposalSummaries":[],"Payments":[],"RejectedObjectives":[]}}
{"time":"2023-08-22T10:36:00.077726-07:00","level":"DEBUG","msg":"Received notification","address":"0x7E5F4552091A69125d5DfCb7b8C2659029395Bdf","method":"payment_channel_updated"}
{"time":"2023-08-22T10:36:00.077766-07:00","level":"DEBUG","msg":"Received message","address":"0x2B5AD5c4795c026514f8317c7a215E218DcCD6cF","msg":{"To":"0x2B5AD5","From":"0x7E5F45","PayloadSummaries":[{"ObjectiveId":"VirtualFund-0x6c939195be84d39af44fe6a9f21cf25a779ac1e0f7b7f477b3429947235ba9a4","Type":"SignedStatePayload","PayloadDataSize":823}],"ProposalSummaries":[],"Payments":[],"RejectedObjectives":[]}}
{"time":"2023-08-22T10:36:00.077782-07:00","level":"INFO","msg":"Constructing objective from message","address":"0x2B5AD5c4795c026514f8317c7a215E218DcCD6cF","objective-id":"VirtualFund-0x6c939195be84d39af44fe6a9f21cf25a779ac1e0f7b7f477b3429947235ba9a4"}
{"time":"2023-08-22T10:36:00.077771-07:00","level":"DEBUG","msg":"sent message","address":"0x7E5F4552091A69125d5DfCb7b8C2659029395Bdf","method":"get_payment_channel"}
{"time":"2023-08-22T10:36:00.077872-07:00","level":"INFO","msg":"Created new objective from message","address":"0x2B5AD5c4795c026514f8317c7a215E218DcCD6cF","id":"VirtualFund-0x6c939195be84d39af44fe6a9f21cf25a779ac1e0f7b7f477b3429947235ba9a4"}
{"time":"2023-08-22T10:36:00.077878-07:00","level":"INFO","msg":"Policymaker for objective","address":"0x2B5AD5c4795c026514f8317c7a215E218DcCD6cF","policy-maker":{},"objective-id":"VirtualFund-0x6c939195be84d39af44fe6a9f21cf25a779ac1e0f7b7f477b3429947235ba9a4"}
{"time":"2023-08-22T10:36:00.077891-07:00","level":"DEBUG","msg":"Rpc server received request","address":"0x7E5F4552091A69125d5DfCb7b8C2659029395Bdf","requestData":"{\"jsonrpc\":\"2.0\",\"id\":17345848871230467025,\"method\":\"get_payment_channel\",\"params\":{\"Id\":\"0x0000000000000000000000000000000000000000000000000000000000000000\"}}"}
{"time":"2023-08-22T10:36:00.07823-07:00","level":"INFO","msg":"Objective cranked","address":"0x2B5AD5c4795c026514f8317c7a215E218DcCD6cF","objective-id":"VirtualFund-0x6c939195be84d39af44fe6a9f21cf25a779ac1e0f7b7f477b3429947235ba9a4","waiting-for":"WaitingForCompleteFunding"}
{"time":"2023-08-22T10:36:00.07824-07:00","level":"DEBUG","msg":"Sending notification","address":"0x2B5AD5c4795c026514f8317c7a215E218DcCD6cF","method":"payment_channel_updated","payload":{"ID":"0x6c939195be84d39af44fe6a9f21cf25a779ac1e0f7b7f477b3429947235ba9a4","Status":"Proposed","Balance":{"AssetAddress":"0x0000000000000000000000000000000000000000","Payee":"0x2b5ad5c4795c026514f8317c7a215e218dccd6cf","Payer":"0x7e5f4552091a69125d5dfcb7b8c2659029395bdf","PaidSoFar":"0x0","RemainingFunds":"0x64"}}}
{"time":"2023-08-22T10:36:00.07825-07:00","level":"DEBUG","msg":"Sent message","address":"0x2B5AD5c4795c026514f8317c7a215E218DcCD6cF","msg":{"To":"0x7E5F45","From":"0x2B5AD5","PayloadSummaries":[{"ObjectiveId":"VirtualFund-0x6c939195be84d39af44fe6a9f21cf25a779ac1e0f7b7f477b3429947235ba9a4","Type":"SignedStatePayload","PayloadDataSize":823}],"ProposalSummaries":[],"Payments":[],"RejectedObjectives":[]}}
{"time":"2023-08-22T10:36:00.07834-07:00","level":"DEBUG","msg":"Received notification","address":"0x2B5AD5c4795c026514f8317c7a215E218DcCD6cF","method":"payment_channel_updated"}

Performance

Based on the benchmarks maintained by zap it looks like slog is slower than zerolog but relatively close to other logging frameworks.

node/engine/engine.go

internal/logging/logging.go

lalexgap · 2023-08-22T18:06:28Z

cmd/create-channel/main.go

@@ -31,15 +33,15 @@ func main() {
 	if _, err := toml.DecodeFile(CONFIG_FILE, &participantOpts); err != nil {
 		panic(err)
 	}
-	logger, logFile := utils.CreateLogger(LOG_FILE, "alice")
-	defer logFile.Close()


I think we can avoid closing the log file manually, since that should happen anyways when the test/execution halts.

lalexgap · 2023-08-22T18:23:37Z

node_test/rpc_test.go

-		Level(zerolog.TraceLevel).
-		With().
-		Timestamp().
-		Str("rpc", rpcRole), clientName).


Now that the RPC client/server no longer accept a logger, we can't easily add log attribute (like "rpc") in the test, like we did before. Instead the RPC client/server would have to add the "rpc" attribute when it sets up it's own sub-logger off the DefaultLogger. I think this is an OK tradeoff for reducing the complexity of having to pass loggers around.

netlify · 2023-08-22T18:38:54Z

✅ Deploy Preview for nitro-gui canceled.

Name	Link
🔨 Latest commit	`8a87407`
🔍 Latest deploy log	https://app.netlify.com/sites/nitro-gui/deploys/64e655295e897f0008ea59af

netlify · 2023-08-22T18:38:59Z

👷 Deploy Preview for nitrodocs processing.

Name	Link
🔨 Latest commit	`8a87407`
🔍 Latest deploy log	https://app.netlify.com/sites/nitrodocs/deploys/64e655296c93cb00085000d8

netlify · 2023-08-22T18:38:59Z

✅ Deploy Preview for nitro-storybook canceled.

Name	Link
🔨 Latest commit	`8a87407`
🔍 Latest deploy log	https://app.netlify.com/sites/nitro-storybook/deploys/64e655294c78b2000807bfda

lalexgap · 2023-08-22T18:54:01Z

rpc/client.go

@@ -236,6 +244,7 @@ func (rc *rpcClient) subscribeToNotifications(ctx context.Context, notificationC
 			case serde.ObjectiveCompleted:
 				rpcRequest := serde.JsonRpcSpecificRequest[protocols.ObjectiveId]{}
 				err := json.Unmarshal(data, &rpcRequest)
+				rc.logger.Debug("Received notification", "method", method, "data", rpcRequest)


Instead of passing in the raw JSON we pass in a struct that will get serialized automatically for us.

{"time":"2023-08-22T11:43:47.327969-07:00","level":"INFO","msg":"Received notification","client":"aliceLedger","notification":{"time":"2023-08-22T11:55:29.002799-07:00","level":"DEBUG","msg":"Received notification","address":"0x7E5F4552091A69125d5DfCb7b8C2659029395Bdf","method":"objective_completed","data":{"jsonrpc":"2.0","id":1892133135947938969,"method":"objective_completed","params":"DirectDefunding-0xf4e942489cfdf77d22aa589353b9f3ac6d09eceb833a1d8e5a2634140be38aef"}}

Otherwise we'd just get a string:

{"time":"2023-08-22T11:50:48.815977-07:00","level":"DEBUG","msg":"Received notification","address":"0x2B5AD5c4795c026514f8317c7a215E218DcCD6cF","method":"objective_completed","data":"{\"jsonrpc\":\"2.0\",\"id\":11801681279923878936,\"method\":\"objective_completed\",\"params\":\"DirectDefunding-0x5cd0a2e5d660edf0c41cb3902f3350b8346da7be031a7bbf7ec57d3ca775808f\"}"}

a struct will get serialized out properly

geoknee · 2023-08-23T16:49:59Z

We may want to update these instructions

go-nitro/contributing.md

Line 165 in 96c012c

# Logs

geoknee · 2023-08-23T16:57:28Z

@lalexgap I am seeing some log lines like this:

[17:43:45.325] DEBUG: Processing Deposited event
    tx-signer: "!ERROR:json: unsupported type: bind.SignerFn"

Interesting that this is a silent failure -- are we swallowing an error somewhere?

lalexgap · 2023-08-23T17:16:47Z

@lalexgap I am seeing some log lines like this:

[17:43:45.325] DEBUG: Processing Deposited event
    tx-signer: "!ERROR:json: unsupported type: bind.SignerFn"

@geoknee

Ah good catch, that was caused by passing in a function instead of the address into a log attribute. That is fixed in 2139142.

Interesting that this is a silent failure -- are we swallowing an error somewhere?

Right now malformed arguments silently fail. It looks like there is an open issue golang/go#59407 to add this to go vet tool. I think that's the tool that catches malformed print statements like fmt.Printf("This should be a number %d", "But its passed in a string")

lalexgap · 2023-08-23T18:53:23Z

We may want to update these instructions

go-nitro/contributing.md

Line 165 in 96c012c

# Logs

Good point! Updated in 8a87407

lalexgap commented Aug 21, 2023

View reviewed changes

node/engine/engine.go Show resolved Hide resolved

lalexgap commented Aug 21, 2023

View reviewed changes

internal/logging/logging.go Show resolved Hide resolved

lalexgap force-pushed the try-slog branch from 2ea98ec to a6402f4 Compare August 21, 2023 18:26

lalexgap changed the title ~~Use slog in the engine~~ Remove zerolog with slog Aug 21, 2023

lalexgap force-pushed the try-slog branch from 1ecc265 to 3e87c2c Compare August 21, 2023 20:16

lalexgap closed this Aug 22, 2023

lalexgap force-pushed the try-slog branch from 39dd851 to edb5cc8 Compare August 22, 2023 00:46

lalexgap reopened this Aug 22, 2023

lalexgap force-pushed the try-slog branch 3 times, most recently from 5f9eed6 to 5b42985 Compare August 22, 2023 01:00

lalexgap changed the title ~~Remove zerolog with slog~~ Replace zerolog with slog Aug 22, 2023

lalexgap force-pushed the try-slog branch 2 times, most recently from a586156 to 004c58c Compare August 22, 2023 17:35

lalexgap changed the title ~~Replace zerolog with slog~~ Simply logging by using slog DefaultLogger Aug 22, 2023

lalexgap force-pushed the try-slog branch from 004c58c to 2bc5e83 Compare August 22, 2023 17:55

lalexgap changed the title ~~Simply logging by using slog DefaultLogger~~ Simplify logging by using slog Aug 22, 2023

lalexgap commented Aug 22, 2023

View reviewed changes

lalexgap marked this pull request as ready for review August 22, 2023 18:34

lalexgap changed the base branch from upgrade-go to main August 22, 2023 18:34

lalexgap commented Aug 22, 2023

View reviewed changes

lalexgap force-pushed the try-slog branch from ff653fc to 610ee2b Compare August 22, 2023 19:01

lalexgap added 4 commits August 22, 2023 12:10

switch from zerolog to slog

082b649

slightly cleaner cleanup

73c6ee8

remove empty println

f74c85c

log out notif data

97ff216

do not use json string

c588d5f

a struct will get serialized out properly

lalexgap force-pushed the try-slog branch from 610ee2b to c588d5f Compare August 22, 2023 19:11

geoknee approved these changes Aug 23, 2023

View reviewed changes

fix tx-signer

2139142

update logging docs

8a87407

lalexgap merged commit dd7dcf3 into main Aug 23, 2023
2 checks passed

lalexgap deleted the try-slog branch August 23, 2023 19:01

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Simplify logging by using slog #1572

Simplify logging by using slog #1572

lalexgap commented Aug 21, 2023 •

edited

Loading

lalexgap Aug 22, 2023

lalexgap Aug 22, 2023 •

edited

Loading

netlify bot commented Aug 22, 2023 •

edited

Loading

netlify bot commented Aug 22, 2023 •

edited

Loading

netlify bot commented Aug 22, 2023 •

edited

Loading

lalexgap Aug 22, 2023 •

edited

Loading

geoknee commented Aug 23, 2023

geoknee commented Aug 23, 2023

lalexgap commented Aug 23, 2023 •

edited

Loading

lalexgap commented Aug 23, 2023

Simplify logging by using slog #1572

Simplify logging by using slog #1572

Conversation

lalexgap commented Aug 21, 2023 • edited Loading

How does it work?

What does it look like?

Performance

lalexgap Aug 22, 2023

Choose a reason for hiding this comment

lalexgap Aug 22, 2023 • edited Loading

Choose a reason for hiding this comment

netlify bot commented Aug 22, 2023 • edited Loading

✅ Deploy Preview for nitro-gui canceled.

netlify bot commented Aug 22, 2023 • edited Loading

👷 Deploy Preview for nitrodocs processing.

netlify bot commented Aug 22, 2023 • edited Loading

✅ Deploy Preview for nitro-storybook canceled.

lalexgap Aug 22, 2023 • edited Loading

Choose a reason for hiding this comment

geoknee commented Aug 23, 2023

geoknee commented Aug 23, 2023

lalexgap commented Aug 23, 2023 • edited Loading

lalexgap commented Aug 23, 2023

lalexgap commented Aug 21, 2023 •

edited

Loading

lalexgap Aug 22, 2023 •

edited

Loading

netlify bot commented Aug 22, 2023 •

edited

Loading

netlify bot commented Aug 22, 2023 •

edited

Loading

netlify bot commented Aug 22, 2023 •

edited

Loading

lalexgap Aug 22, 2023 •

edited

Loading

lalexgap commented Aug 23, 2023 •

edited

Loading