[Twisted-Python] stdlib logger, loggerFor and filtering events

[Glyph]

> On Jan 14, 2018, at 4:34 PM, Felipe Dau <dau at riseup.net> wrote:
> 
> On Fri, Jan 05, 2018 at 09:00:41PM -0800, Glyph wrote:
>> Just for the record, you don't need to wait for it to be brought up before asking other questions ;-).
> 
> Thanks Glyph, I should have asked these a while ago.
> 
>> It might be cool to add that, but, if you don't want the standard library's log format, why are you using the standard library log observer?  And wouldn't this be a job for a https://docs.python.org/3.6/library/logging.html#logging.Formatter <https://docs.python.org/3.6/library/logging.html#logging.Formatter> object in any case; what Twisted should be doing is sending the logs on in a more structured format that works with that?
> 
> Honestly, I just wanted to display something to stdout (when using the
> GUI) and using stdlib's looked like the right way to do that, but
> using sys.stdout directly like in your example below would work as
> well. And now that I am looking again at what I did, it is probably
> the worst thing to do if you are trying to integrate something: set
> the message text to the actual formatted text and set the format to
> just '%(message)s'. Anything else that used stdlib's would only
> contain the message, losing all the rest of the info.

Yep.

> Considering that I just really wanted to display the logs, is there
> any advantage on using stdlib's? If so, I would then use the Formatter
> as you pointed out, otherwise, I would just pass it to sys.stdout. In
> both cases, there wouldn't be a need to pass an event formatter like I
> wanted to. Thanks!

I don't think so.  Twisted's will do this just fine (and in fact does it automatically if you're using `twist`, or the older `twistd`).

> 
>> I'm honestly not sure why this exists at all.  It seems like a terrible mistake has happened here, since `_loggerFor` is actually exported in __all__, which should never ever happen.
>> 
>> From what I can tell, it should be removed, since rather than creating that fairly noisy attr.ib() definition, you could do this:
>> 
>>    _log = Logger()
>> 
>> which is a lot more succinct, and has exactly the same effect (do `self._log.info <http://log.info/>(...)`) and there you have it.
>> 
>> If you could explain why it's great, then maybe we could remove the underscore and add it to the docs.
> 
> It is indeed a lot more succinct! The reason I used _loggerFor is that
> it creates a logger for any instance it receives. That way, it can
> set the namespace automatically when instantiated inside any method of
> a class - the constructor, for example. I just do not remember why
> creating a separate logger for each instance instead of sharing the
> class'. Would there be a reason for that?

None that I can think of.

> But I do think that if you would like to log something but not keep
> the instance around, _loggerFor may be useful, as Logger would only
> set the namespace based on the module when called from a method.
> 
>> Absolutely!  Super glad you brought this up. This was a major part of the design of the new logging system, both to do this, and to also do as little work as possible with messages that were ultimately caught by such filters.
>> 
>> Here's a quick example program demonstrating the combination of https://twistedmatrix.com/documents/17.9.0/api/twisted.logger.LogLevelFilterPredicate.html <https://twistedmatrix.com/documents/17.9.0/api/twisted.logger.LogLevelFilterPredicate.html> and https://twistedmatrix.com/documents/17.9.0/api/twisted.logger.FilteringLogObserver.html <https://twistedmatrix.com/documents/17.9.0/api/twisted.logger.FilteringLogObserver.html>.
> 
> Thanks for the example! Unfortunately I think that is different from
> what I tried to describe. Here is an example:
> 
>    class ThirdPartyClass:
>        a_log = Logger()
> 
>        def method_a(self):
>            self.a_log.info('Log I want to supress')
> 
>            self.a_log.warn('Log I do not want to supress')
> 
>    class MyClass(ThirdPartyClass):
>        b_log = Logger()
> 
>        def method_b(self):
>            self.method_a()
> 
>            self.b_log.info('Log I do not want to supress')
> 
> 
>    MyClass().method_b()
> 
> Considering that the class definitions would be in separate files,
> they would still have the same namespaces. This would be a case where
> the libraries you are using are a bit noisy and you would just want to
> display warnings+.

Oh, ugh. This is a bug that should be fixed.  a_log really ought to have its namespace set to ThirdPartyClass's namespace, not MyClass.

> I believe that as there is a reference to a_log, it would be possible
> to change the namespace, but if the third party class used
> _loggerFor().info() instead, then that would not be possible, right?

With the example here, it's at least possible to fix the bug, since the logger can identify where in the MRO it lives.  With _loggerFor, it would not be possible.

> This actually happens with Factory.doStart() [0] once that is
> subclassed, you cannot differ its  namespace from your class'.

Yeah, let's fix taht.

> These would be situations where very few people would come across or
> maybe I still have to learn more about the logging system, but I
> thought it would be worth to be discussed.

They absolutely should be discussed!  These types of issues are very important when doing log analysis, which is often a long time after the code is written to emit the messages.

> Thanks,
> -Felipe
> 
> [0]: https://github.com/twisted/twisted/blob/trunk/src/twisted/internet/protocol.py#L75
> 
> _______________________________________________
> Twisted-Python mailing list
> Twisted-Python at twistedmatrix.com
> https://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python