[Twisted-Python] stdlib logger, loggerFor and filtering events
As the logger has been brought up, I'd like to ask a couple things: 1) When I was working on adding logs to an application, I wanted it to use both the `textFileLogObserver` and the `STDLibLogObserver`. As the application could be used either with its CLI or GUI, it seemed interesting to have both these loggers available. I was able to do that but I wanted them to have the same format - specifically, I wanted to use the file's format (which is awesome btw) - and had to override some parts of the `STDLibLogObserver`. It would have made things a lot simpler if that observer accepted a function to format events like the `FileLogObserver`. 2) Why is `_loggerFor` "private/hidden"? That is a great factory which imo should have more visibility - and also works great with attrs!: attr.ib(default=attr.Factory(_loggerFor, takes_self=True)) 3) Is there a way to suppress logs from libs or any other code that is not your own? In my case, I had to manually set which namespaces I wanted to filter but, for example, when you subclass a third-party's class which logs something, that will pass because now it belongs to one of your namespaces. I know it sounds crazy but wanted to know what other people think. If any of these changes sound like they would be useful apart from the specific requirements of that application, I could help implement something based on what I wrote [0]. Thanks, -Felipe [0]: https://github.com/AnemoneLabs/unmessage/blob/develop/unmessage/log.py
On Jan 5, 2018, at 7:11 PM, Felipe Dau <dau@riseup.net> wrote:
As the logger has been brought up, I'd like to ask a couple things:
Just for the record, you don't need to wait for it to be brought up before asking other questions ;-).
1) When I was working on adding logs to an application, I wanted it to use both the `textFileLogObserver` and the `STDLibLogObserver`. As the application could be used either with its CLI or GUI, it seemed interesting to have both these loggers available. I was able to do that but I wanted them to have the same format - specifically, I wanted to use the file's format (which is awesome btw) - and had to override some parts of the `STDLibLogObserver`. It would have made things a lot simpler if that observer accepted a function to format events like the `FileLogObserver`.
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?
2) Why is `_loggerFor` "private/hidden"? That is a great factory which imo should have more visibility - and also works great with attrs!:
attr.ib(default=attr.Factory(_loggerFor, takes_self=True))
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.
3) Is there a way to suppress logs from libs or any other code that is not your own? In my case, I had to manually set which namespaces I wanted to filter but, for example, when you subclass a third-party's class which logs something, that will pass because now it belongs to one of your namespaces. I know it sounds crazy but wanted to know what other people think.
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.LogLevelFilter... <https://twistedmatrix.com/documents/17.9.0/api/twisted.logger.LogLevelFilter...> and https://twistedmatrix.com/documents/17.9.0/api/twisted.logger.FilteringLogOb... <https://twistedmatrix.com/documents/17.9.0/api/twisted.logger.FilteringLogOb...>. import sys from twisted.logger import (Logger, FilteringLogObserver, LogLevelFilterPredicate, globalLogBeginner, LogLevel, textFileLogObserver) alog = Logger(namespace="a") blog = Logger(namespace="b") predicate = LogLevelFilterPredicate() predicate.setLogLevelForNamespace("a", LogLevel.debug) predicate.setLogLevelForNamespace("b", LogLevel.warn) globalLogBeginner.beginLoggingTo( [FilteringLogObserver(textFileLogObserver(sys.stdout), [predicate])] ) alog.info("one") blog.info("two") alog.critical("three") blog.critical("four")
If any of these changes sound like they would be useful apart from the specific requirements of that application, I could help implement something based on what I wrote [0].
We'd certainly be interested in contributions to the logging subsystem! But I'd probably want to hear a little more about how and why you thought these things were useful first. -g
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. 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'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? 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.LogLevelFilter... <https://twistedmatrix.com/documents/17.9.0/api/twisted.logger.LogLevelFilter...> and https://twistedmatrix.com/documents/17.9.0/api/twisted.logger.FilteringLogOb... <https://twistedmatrix.com/documents/17.9.0/api/twisted.logger.FilteringLogOb...>.
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+. 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? This actually happens with Factory.doStart() [0] once that is subclassed, you cannot differ its namespace from your class'. 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. Thanks, -Felipe [0]: https://github.com/twisted/twisted/blob/trunk/src/twisted/internet/protocol....
On Jan 14, 2018, at 4:34 PM, Felipe Dau <dau@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.LogLevelFilter... <https://twistedmatrix.com/documents/17.9.0/api/twisted.logger.LogLevelFilter...> and https://twistedmatrix.com/documents/17.9.0/api/twisted.logger.FilteringLogOb... <https://twistedmatrix.com/documents/17.9.0/api/twisted.logger.FilteringLogOb...>.
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....
_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com https://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
participants (2)
-
Felipe Dau -
Glyph