Bug 1224 - refactor logging
Summary: refactor logging
Status: CONFIRMED
Alias: None
Product: Libre-SOC's first SoC
Classification: Unclassified
Component: Source Code (show other bugs)
Version: unspecified
Hardware: PC Windows
: --- major
Assignee: Luke Kenneth Casson Leighton
URL:
Depends on:
Blocks:
 
Reported: 2023-11-29 17:48 GMT by Dmitry Selyutin
Modified: 2023-11-29 19:55 GMT (History)
2 users (show)

See Also:
NLnet milestone: ---
total budget (EUR) for completion of task and all subtasks: 0
budget (EUR) for this task, excluding subtasks' budget: 0
parent task for budget allocation:
child tasks for budget allocation:
The table of payments (in EUR) for this task; TOML format:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Dmitry Selyutin 2023-11-29 17:48:13 GMT
Expectations:
1. No sane logging should write to stdout. This is unconventional. At least choose stderr by default. But preferably choose NOTHING (see item 2).
2. By default there's no need to write so much information unless explicitly told.
3. There must be a possibility to tune the exact logging level per component/subsystem. When debugging insndb, I don't want to see anything related to SelectableInt.
4. There're standard ways of doing this. No, print is not the correct way to do logging; it's good for casual debug. There's no need to reinvent the wheel, Python already has a pretty well established logging.
5. Ideally the users should be able to switch the log destination, be it syslog, file, stderr or anything else. For files we need append mode as well.

Problems with the current implementation:
1. It pollutes stdout for no good reason. Several command-line utilities using stdout already have to deal with this annoying behaviour.
2. It's too verbose. The amount of information distracts the readers.
3. It reinvents the wheel. There are solutions to the same problem in Python. Yes they ARE superior to print() invocation.
4. It leaves no options to have per-subsystem logging by other means than making the underlying implementation aware of the subsystem. It should be up to the subsystem which levels and options it supports.
Comment 1 Luke Kenneth Casson Leighton 2023-11-29 18:15:12 GMT
(In reply to Dmitry Selyutin from comment #0)
> Expectations:
> 1. No sane logging should write to stdout. This is unconventional.

it doesn't matter. this was discussed over 4 years ago and nothing has
changed.

> At least choose stderr by default.

no, definitely not: it interferes with python exceptions

> But preferably choose NOTHING (see item 2).

set the environment variable to switch it off.

> 2. By default there's no need to write so much information unless explicitly
> told.

yes there is.  if you have not been involved directly then it is hard to explain.

> 3. There must be a possibility to tune the exact logging level per
> component/subsystem. When debugging insndb, I don't want to see anything
> related to SelectableInt.

if you have not been involved with the bit-level debugging, given that
ISACaller is now a 4-year EXTREMELY complex Finite State Machine, it
"makes no sense"


> 4. There're standard ways of doing this. No, print is not the correct way to
> do logging; it's good for casual debug. There's no need to reinvent the
> wheel, Python already has a pretty well established logging.

... which is longer and more complex to set up.

> 4. It leaves no options to have per-subsystem logging by other means than
> making the underlying implementation aware of the subsystem. It should be up
> to the subsystem which levels and options it supports.

should... but it needs money being paid to resolve... WITHOUT damaging
my ability to understand one of the most complex Finite State Machines
i have ever written.

this is not a "simple surely it should not be that way no really" task.
making the changes you are proposing is WEEKS if not MONTHS of work
to ensure that no damage occurs.
Comment 2 Jacob Lifshay 2023-11-29 18:22:34 GMT
(In reply to Luke Kenneth Casson Leighton from comment #1)
> (In reply to Dmitry Selyutin from comment #0)
> > Expectations:
> > 1. No sane logging should write to stdout. This is unconventional.
> 
> it doesn't matter. this was discussed over 4 years ago and nothing has
> changed.

actually, writing to stdout is a major problem when we want to start running things like lua or any interactive program...if you can't see the output, how are you supposed to know what to type?

SILENCELOG=1 doesn't remove all output, as more prints have been added.
Comment 3 Dmitry Selyutin 2023-11-29 18:26:34 GMT
(In reply to Luke Kenneth Casson Leighton from comment #1)
> (In reply to Dmitry Selyutin from comment #0)
> > Expectations:
> > 1. No sane logging should write to stdout. This is unconventional.
> 
> it doesn't matter. this was discussed over 4 years ago and nothing has
> changed.

Please quit this habit of "I cannot explain it now" and "it has been discussed but I won't give any context or even the goddamn link". This is unconstructive.

> > At least choose stderr by default.
> 
> no, definitely not: it interferes with python exceptions

Exceptional cases are part of the logging. That's not a disadvantage, quite a contrary. Stdout interferes with anything else but this didn't stop you.

> > But preferably choose NOTHING (see item 2).
> 
> set the environment variable to switch it off.
> 
> > 2. By default there's no need to write so much information unless explicitly
> > told.
> 
> yes there is.  if you have not been involved directly then it is hard to
> explain.

Please try anyway.

> > 3. There must be a possibility to tune the exact logging level per
> > component/subsystem. When debugging insndb, I don't want to see anything
> > related to SelectableInt.
> 
> if you have not been involved with the bit-level debugging, given that
> ISACaller is now a 4-year EXTREMELY complex Finite State Machine, it
> "makes no sense"

There is world besides ISACaller. The whole world is not evolving around it.

> > 4. There're standard ways of doing this. No, print is not the correct way to
> > do logging; it's good for casual debug. There's no need to reinvent the
> > wheel, Python already has a pretty well established logging.
> 
> ... which is longer and more complex to set up.
> 

Setting up a reinvented wheel is sufficiently complex to prefer standard ways of doing the same.

> > 4. It leaves no options to have per-subsystem logging by other means than
> > making the underlying implementation aware of the subsystem. It should be up
> > to the subsystem which levels and options it supports.
> 
> should... but it needs money being paid to resolve... WITHOUT damaging
> my ability to understand one of the most complex Finite State Machines
> i have ever written.

It doesn't. In the end, it'd be the same log() incantation.

> this is not a "simple surely it should not be that way no really" task.
> making the changes you are proposing is WEEKS if not MONTHS of work
> to ensure that no damage occurs.

I think you exaggerating it. And I don't suggest to reserve any budget for this, this is one of the infrastructure tasks meaningful mostly for us.


All in all, if you want to really persuade me, you need a technical rationale. The overall idea I could deduce seems like "you're too young to understand it". :-)
Comment 4 Jacob Lifshay 2023-11-29 18:45:22 GMT
additional conversation:
https://libre-soc.org/irclog/%23libre-soc.2023-11-29.log.html#t2023-11-29T18:33:57

ghostmansd[m]	programmerjake, do you recall the technical rationale about the logging?	18:33
ghostmansd[m]	Luke's reply doesn't clarify anything at all.	18:34
openpowerbot	[irc] <programmerjake> uuh, luke wants print, but will settle for calling log, which acts just like print. he refused to use python's logging library, icr why	18:36
openpowerbot	[irc] <programmerjake> sorry	18:36
openpowerbot	[irc] <programmerjake> one technical reason to use log, instead of python's logging library (though this definitely isn't why luke chose print), is that I designed it to be very fast when logging is disabled, iirc just 2 dict lookups	18:38
Comment 5 Jacob Lifshay 2023-11-29 18:48:18 GMT
(In reply to Jacob Lifshay from comment #4)
> openpowerbot	[irc] <programmerjake> one technical reason to use log, instead
> of python's logging library (though this definitely isn't why luke chose
> print), is that I designed it to be very fast when logging is disabled, iirc
> just 2 dict lookups	18:38

when full logging is enabled, the simulator takes like 2 times as long to run, so log is very hot code.
Comment 6 Luke Kenneth Casson Leighton 2023-11-29 19:51:57 GMT
(In reply to Jacob Lifshay from comment #2)

> actually, writing to stdout is a major problem when we want to start running
> things like lua or any interactive program...if you can't see the output,
> how are you supposed to know what to type?

to be solved later (by getting openpower.util.log to do something different)
 
> SILENCELOG=1 doesn't remove all output, as more prints have been added.

those are bugs that were not authorised, and need to be raised as such.
Comment 7 Luke Kenneth Casson Leighton 2023-11-29 19:55:21 GMT
(In reply to Jacob Lifshay from comment #4)

> ghostmansd[m]	Luke's reply doesn't clarify anything at all.	18:34

dmitry i am LIVING IN A VAN ON BATTERY POWER ONLY, and it is absolutely
freezing cold and i have NO HEATING.

i am GOING to have to be short and curt, you will need to work with that
out of necessity and understanding and tolerance.

i leave it with you to discuss and do the research yourself into
the past IRC logs, bugtracker, and mailing list discussions
i have to shut down for the night now.