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

Submitted by Paul Eggleton on March 28, 2017, 12:51 a.m. | Patch ID: 138505

Details

Message ID 93968aed34753e90e05945b2bce34ccfb4743a60.1490662146.git.paul.eggleton@linux.intel.com
State New
Headers show

Commit Message

Paul Eggleton March 28, 2017, 12:51 a.m.
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@linux.intel.com>
---
 lib/bb/codeparser.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

Patch hide | download patch | download mbox

diff --git a/lib/bb/codeparser.py b/lib/bb/codeparser.py
index 5d2d440..c36397c 100644
--- a/lib/bb/codeparser.py
+++ b/lib/bb/codeparser.py
@@ -186,7 +186,7 @@  class BufferedLogger(Logger):
 
     def flush(self):
         for record in self.buffer:
-            self.target.handle(record)
+            self.target.filter(record)
         self.buffer = []
 
 class PythonParser():

Comments

Christopher Larson March 28, 2017, 4:01 p.m.
On Mon, Mar 27, 2017 at 5:51 PM, Paul Eggleton <
paul.eggleton@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@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)
Paul Eggleton March 28, 2017, 7:50 p.m.
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@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@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.)

Cheers,
Paul
Christopher Larson March 28, 2017, 8:04 p.m.
On Tue, Mar 28, 2017 at 12:50 PM, Paul Eggleton <
paul.eggleton@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@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@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 March 28, 2017, 8:07 p.m.
On Tue, Mar 28, 2017 at 1:04 PM, Christopher Larson <chris_larson@mentor.com
> wrote:

> On Tue, Mar 28, 2017 at 12:50 PM, Paul Eggleton <
> paul.eggleton@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@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@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 = []
>

s/\.level/.levelno/