Need examples of Action.warn etc.

[tompaton]

I'm trying to refactor some code that uses the standard logging.getLogger to use lithoxyl and I'm a bit stuck without some more examples comparing the old style with the new.

In particular, how should I go about converting code that looks like:

logger.info('starting some process')
logger.debug('intermediate result %d', a)
logger.debug('another intermediate result %s', b)
logger.info('complete')

Logging the start/finish is fine, but I'm stuck on the "right" way to log the intermediate results. Should they just be assigned to Action's data:

with app_log.info('process') as act:
    act['intermediate result'] = a
    act.success()

That feels a bit clunky as the resulting repr of the data in the log line is pretty unreadable and out of order.

Or can warn be used? It doesn't seem quite like it does what I want as it has a different level than the Action and it's not outputting how I would expect.

with app_log.info('process') as act:
    act.warn('intermediate result %d', a)
    act.success()

[mahmoud]

Hey Tom, thanks for your interest! You're spot on. For intermediate results, I am generally adding to the Action data map. Otherwise, I create new Actions (nested actions are fine). Actions keep a reference to their parent, though this is contingent on your concurrency model, I have only really leveraged that for indentation.

Warnings have not been fully fleshed out, and I wouldn't recommend them for successful intermediate results anyways. A while back I looked at supporting multiple Action completions, but decided that a single completion had more useful semantics, especially since Actions can be nested.

Have you considered a single-line action? Something like:

log.debug('dbg_action', res='intermediate').success('{res} intermediate result')

Compared to the built-in logging expressions, it's a bit noisier, but it's also a lot more structured.

[tompaton]

Thanks for the extra details @mahmoud.

I agree, you don't want multiple completions, that doesn't really make sense.

Nesting using a single-line action produces clean enough code that I'd be happy with, but I'm using a variant of the SyslogEmitter that only outputs the end_event, so the log entry for the intermediate result looks a bit odd, e.g. before I had output roughly like:

INFO starting some process
DEBUG intermediate result a
DEBUG another intermediate result b
INFO complete

And now I get:

DEBUG "intermediate result a"
DEBUG "another intermediate result b"
INFO "process succeeded"

It would be very instructive to see how you'd refactor some real-world code that has fairly extensive usage of logging.getLogger using lithoxyl.

[mahmoud]

Sure! So, for sure this is one of the most immediate friction points one would hit, especially coming from logging. I've yet to have project that didn't have some long-running task that I wanted some confirmation of having started. Lithoxyl has begin events, the question is when to emit them. There's not really a way where a parent can know it will have a nested event, or that it will be a long-running task, so we have to compromise and be able to mark these ourself.

There are two approaches I use:

1. Emit begin events for transactions marked as verbose.
2. Emit begin events for transactions with above a certain level (e.g., >debug in your case)

You can see the first approach in action in Chert. Note the separate complete format (fmt) and begin format (begin_fmt). This gives an output like:

b+0.277090 --------------    "render site beginning"
F+0.277154 -    0.008ms -       "no pre_render hook defined"
b+0.278630 --------------       "render published entry content beginning"
S+1.213840 -  935.210ms -       "render published entry content succeeded - ({'verbose': True})"
b+1.214119 --------------       "render draft entry content beginning"
S+2.776296 - 1562.177ms -       "render draft entry content succeeded - ({'verbose': True})"
b+2.776552 --------------       "render special entry content beginning"
S+2.787829 -   11.277ms -       "render special entry content succeeded - ({'verbose': True})"
S+2.826007 -   37.902ms -       "render entry html succeeded"
S+2.891567 -   65.425ms -       "render feed and tag lists succeeded"
S+2.892354 - 2615.264ms -    "render site succeeded - ({'verbose': True})"

I'm not super happy about the ({'verbose': True}), but it works pretty well thus far. Enough so that I've made verbose a special part of SensibleFilter.

How's that sounding?

[tompaton]

Yes, that's pretty good, thanks. Real-world example code is always helpful.

Agreed re verbose, maybe there's a way to filter that out of SensibleFormatter/SensibleMessageFormatter?

It seems to me there's room for lithoxyl to get a bit more opinionated about the "sensible" setup too - e.g. with a couple of pre-built sinks for stderr, syslog etc. that can be added to a Logger with a line or two of code to reduce the friction when getting started. I had a question on StackOverflow about creating an emitter that outputs to the logging module, similar to the SyslogEmitter, that may fit into that pre-rolled sink category too.