[bitbake-devel] [PATCH 1/1] lib/bb/codeparser: ensure BufferedLogger respects target filtering

[Christopher Larson]

On Tue, Mar 28, 2017 at 12:50 PM, Paul Eggleton <
paul.eggleton at linux.intel.com> wrote:

> On Wednesday, 29 March 2017 5:01:31 AM NZDT Christopher Larson wrote:
> > On Mon, Mar 27, 2017 at 5:51 PM, Paul Eggleton <
> > paul.eggleton at linux.intel.com> wrote:
> > > BufferedLogger was sending log records to the target logger using
> > > handle() - this meant that the filtering (e.g. log level set)
> > > on the target logger was bypassed, leading for example to debug records
> > > getting printed when the log level was set to logging.WARNING.
> > >
> > > Signed-off-by: Paul Eggleton <paul.eggleton at linux.intel.com>
> >
> > The ‘filter’ method of a Logger instance doesn’t log anything, it’s a
> > subclass of Filterer, which just checks whether it should be logged. The
> > ‘handle’ method of a Logger already consults self.filter(), if you check
> > the code:
> >
> >    def handle(self, record):
> >           """
> >           Call the handlers for the specified record.
> >
> >           This method is used for unpickled records received from a
> socket,
> > as
> >           well as those created locally. Logger-level filtering is
> applied.
> >           """
> >           if (not self.disabled) and self.filter(record):
> >               self.callHandlers(record)
>
> Oops, you're right. I'm still confused about why I'm seeing debugging
> messages
> when the target logger is set to INFO then. Do you have any suggestions on
> how
> we fix this?
>
> (I've attached a simplified test script demonstrating the issue.)


handle() obeys filter(), but it seems filter() only checks to see if this
logger is or isn’t responsible for a given message, it doesn’t actually
check to see whether the logger is enabled for a given record given its
level. The level based checking for a logger (as opposed to a handler)
seems to be done in the actual message function, i.e.:

    def debug(self, msg, *args, **kwargs):
          if self.isEnabledFor(DEBUG):
              self._log(DEBUG, msg, args, **kwargs)

The setLevel() for the BufferLogger itself ensures that anything of that
level (logging.DEBUG) or higher severity gets buffered, but then we bypass
the isEnabledFor() on the main logger by calling handle directly rather
than the individual level-based methods. I expect we should use
isEnabledFor rather than filter, and keep the conditional ourselves:

     def flush(self):
         for record in self.buffer:
-            self.target.handle(record)
+            if self.target.isEnabledFor(record.level):
+                self.target.handle(record)
         self.buffer = []
-- 
Christopher Larson
kergoth at gmail dot com
Founder - BitBake, OpenEmbedded, OpenZaurus
Senior Software Engineer, Mentor Graphics
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openembedded.org/pipermail/bitbake-devel/attachments/20170328/d5cfbe9e/attachment-0002.html>