[PATCH 0/1] Follow-up fix for tinfoil series

[PATCH 0/1] Follow-up fix for tinfoil series

[Paul Eggleton]

This resolves the minor regression that caused a few debug messages
to get printed after recent bitbake commit
824e73e0f3eaa96b4d84da7e31f9a17ce5c5d7ee.


The following changes since commit 921592026c69287cdb40ffd90944d5944f28e2c3:

  main: Improve -v and -D option documentation (2017-03-27 11:11:05 +0100)

are available in the git repository at:

  git://git.yoctoproject.org/poky-contrib paule/codeparser-log
  http://git.yoctoproject.org/cgit.cgi/poky-contrib/log/?h=paule/codeparser-log

Paul Eggleton (1):
  lib/bb/codeparser: ensure BufferedLogger respects target filtering

 lib/bb/codeparser.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

-- 
2.9.3

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

[Paul Eggleton]

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(-)

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():
-- 
2.9.3

Re: [PATCH 1/1] lib/bb/codeparser: ensure BufferedLogger respects target filtering

[Christopher Larson]

[-- Attachment #1: Type: text/plain, Size: 1195 bytes --]

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)
-- 
Christopher Larson
kergoth at gmail dot com
Founder - BitBake, OpenEmbedded, OpenZaurus
Senior Software Engineer, Mentor Graphics

[-- Attachment #2: Type: text/html, Size: 1952 bytes --]

Re: [PATCH 1/1] lib/bb/codeparser: ensure BufferedLogger respects target filtering

[Paul Eggleton]

[-- Attachment #1: Type: text/plain, Size: 1497 bytes --]

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

-- 

Paul Eggleton
Intel Open Source Technology Centre

[-- Attachment #2: testlogging.py --]
[-- Type: text/x-python, Size: 1144 bytes --]

import logging
import sys
import os


def logger_create(name, stream=None):
    logger = logging.getLogger(name)
    loggerhandler = logging.StreamHandler(stream=stream)
    formatter = logging.Formatter("%(levelname)s: %(message)s")
    loggerhandler.setFormatter(formatter)
    logger.addHandler(loggerhandler)
    logger.setLevel(logging.INFO)
    return logger

Logger = logging.getLoggerClass()
class BufferedLogger(Logger):
    def __init__(self, name, level=0, target=None):
        Logger.__init__(self, name)
        self.setLevel(level)
        self.buffer = []
        self.target = target

    def handle(self, record):
        self.buffer.append(record)

    def flush(self):
        for record in self.buffer:
            self.target.handle(record)
        self.buffer = []


logger = logger_create('mylogger')
logger.setLevel(logging.INFO)

buflogger = BufferedLogger('mylogger.Data.PythonParser', logging.DEBUG, logger)
buflogger.debug('buffered debug')

logger.debug('hello debug')
logger.info('hello info')
logger.warn('hello warning')
logger.error('hello error')

buflogger.flush()

Re: [PATCH 1/1] lib/bb/codeparser: ensure BufferedLogger respects target filtering

[Christopher Larson]

[-- Attachment #1: Type: text/plain, Size: 2804 bytes --]

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
kergoth at gmail dot com
Founder - BitBake, OpenEmbedded, OpenZaurus
Senior Software Engineer, Mentor Graphics

[-- Attachment #2: Type: text/html, Size: 4398 bytes --]

Re: [PATCH 1/1] lib/bb/codeparser: ensure BufferedLogger respects target filtering

[Christopher Larson]

[-- Attachment #1: Type: text/plain, Size: 3011 bytes --]

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/


-- 
Christopher Larson
kergoth at gmail dot com
Founder - BitBake, OpenEmbedded, OpenZaurus
Senior Software Engineer, Mentor Graphics

[-- Attachment #2: Type: text/html, Size: 4948 bytes --]