search

p2panda / aquadoggo

Node for the p2panda network handling validation, storage, aggregation and replication
GNU Affero General Public License v3.0
70 stars 5 forks source link

Revisit verbosity levels of `log` #197

Closed adzialocha closed 1 year ago

adzialocha commented 2 years ago

Maybe a nice guideline: https://sematext.com/blog/logging-levels/

Related issue in p2panda_rs: https://github.com/p2panda/p2panda/issues/390

adzialocha commented 2 years ago

I find the sqlx logs relatively verbose for info level, maybe there is a way to move them further down?

cafca commented 2 years ago

I always felt that the info level was appropriate. It's emitted every time there a query is executed which is the primary kind of "action" taken by a db library. I would expect a debug level for auxiliary information surrounding the query setup, teardown, etc.

But think it would be nice to have a better tool for monitoring logs that allows configuring different sets of filters, etc! I imagine something that I can keep running in a seperate terminal window independent of the aquadoggo runtime.

adzialocha commented 2 years ago

Hmn, I feel like looking at sql queries for debugging the application, but not for my daily needs to see in what state my application is, otherwise we should also log all graphl and http queries on info etc. but that's not really important information when everything goes well? Also it clutters up the logs a lot, I think it could go a level lower, otherwise there is not much left between noise and errors, probably you even miss them in that noise 😅

cafca commented 2 years ago

It's a limitation of RUST_LOG configuration imho. You can't do something like RUST_LOG=aquadoggo=info,sqlx=warn, which would give a nicer error log like what you probably want. That's why I thought a better tool than RUST_LOG might be a solution.

adzialocha commented 2 years ago

It's a limitation of RUST_LOG configuration imho. You can't do something like RUST_LOG=aquadoggo=info,sqlx=warn, which would give a nicer error log like what you probably want. That's why I thought a better tool than RUST_LOG might be a solution.

Yeah, thats true. I think that could be worth to research this a little. As I understand it log is just a fascade for different frontends. So maybe thats fine, we just need a different one?

Still, I think this is a little bit an offtopic-discussion and I'd still like to discuss log-levels in general. What is our design for them? When do we consider something info or trace or debug etc. - thats independent of how we display and filter stuff?

cafca commented 2 years ago

Yes! Is this also something to go in the style guide? It's a bit on the edge between style and architecture. I like that you opened this issue!

I like the document you linked although I still think it's a bit vague. trace, warn and error don't seem so controversial to me, it's especially the distinction of info and debug that could need some very clear guideline. I agree with you that info logs should be limited.

I don't have a solution but just some thoughts on this:

I think my current approach is that I think about the process I am designing in the application, e.g. the process could be "starting the node" or "publishing an entry". I would then use one info log per process, i.e. "the process started" or "the process ended" but not both (unless I want to track execution time). I would also not use info for individual steps within this process like "the backlink was validated".

Here it gets a bit difficult because you have to make a distinction between something that is just a step inside a process and something that is a whole process of its own. Maybe an indicator for that distinction could also be the structure of the code, if something happens in its own module it's probably a process of its own and if it all happens in one small function it's probably all part of the same thing.

I try to make one-line log lines whenever possible although I don't think that's a good idea per se but a limitation of the log library we use. It would be much better to have a one-line log with additional structured data attached that isn't displayed as part of the logs unless requested.

Another indicator for info logs I use is user intent. I like making an info log whenever the program does something in response to a user request because reading the logs then also means reading the user's journey.

The last thing for info logs is resource cost. If something takes considerable resources (e.g. the db/disk is hit, a network request is sent) I like to log it because evaluating logs then allows reasoning about resource usage.

For debug I am less considerate. I like using debug in particular to be able to trace code execution leading up to a warn or error log. I want to be able to understand what states the program was in before something bad happened.

adzialocha commented 2 years ago

Yes! Is this also something to go in the style guide?

Good question, I had that similar question in other places as well .. maybe we need a "DESIGN.md" where we put design decisions which are neither reflected in software architecture nor style guides?