Follow-up fix for tinfoil series

PATCH Superseded Paul Eggleton 2 participants 6 messages Mar 28, 2017

Share & tools

Paul Eggleton

author

2017-03-28 00:51 UTC #0 lore raw

cover Follow-up fix for tinfoil series

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

Signature · 1 line

2.9.3

Paul Eggleton

author

2017-03-28 00:51 UTC #1 lore raw

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

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 <[email protected]>

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

lib/bb/codeparser.py +1 -1

index 5d2d440..c36397c 100644
@@ -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():

Signature · 1 line

2.9.3

Christopher Larson

2017-03-28 16:01 UTC #2 lore raw

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

Quoted 6 lines · 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 <[email protected]>

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)

Signature · 4 lines

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

Paul Eggleton

author

2017-03-28 19:50 UTC #3 lore raw

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

Quoted 18 lines · NZDT Christopher Larson

Quoted 6 lines · 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 <[email protected]>
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.

Quoted 6 lines

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

Signature · 2 lines

Paul Eggleton
Intel Open Source Technology Centre

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

Christopher Larson

2017-03-28 20:05 UTC #4 lore raw

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

Quoted 28 lines · Paul Eggleton

Quoted 14 lines · NZDT Christopher Larson
Quoted 6 lines · 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 <[email protected]>
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:
Quoted 5 lines
def handle(self, record):
"""
Call the handlers for the specified record.
This method is used for unpickled records received from a
socket,
Quoted 2 lines
as
well as those created locally. Logger-level filtering is
applied.
Quoted 3 lines
"""
if (not self.disabled) and self.filter(record):
self.callHandlers(record)

Quoted 7 lines

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 = []

Signature · 4 lines

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

Christopher Larson

2017-03-28 20:07 UTC #5 lore raw

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

On Tue, Mar 28, 2017 at 1:04 PM, Christopher Larson <[email protected]

Quoted 62 lines

wrote:
Quoted 29 lines · Paul Eggleton
Quoted 5 lines · NZDT Christopher Larson
Quoted 3 lines · 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
Quoted 9 lines
Quoted 3 lines
getting printed when the log level was set to logging.WARNING.
Signed-off-by Paul Eggleton <[email protected]>
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:
Quoted 5 lines
def handle(self, record):
"""
Call the handlers for the specified record.
This method is used for unpickled records received from a
socket,
Quoted 2 lines
as
well as those created locally. Logger-level filtering is
applied.
Quoted 3 lines
"""
if (not self.disabled) and self.filter(record):
self.callHandlers(record)
Quoted 7 lines
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:

lib/bb/codeparser.py class BufferedLogger(Logger): · line 190

Quoted 4 lines

lib/bb/codeparser.py +2 -1

-            self.target.handle(record)
+            if self.target.isEnabledFor(record.level):
+                self.target.handle(record)
         self.buffer = []

s/\.level/.levelno/

Signature · 4 lines

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