Suppress logging output from StringStream? #36

sjlongland · 2019-01-11T02:37:14Z

Hi,

I just stumbled on your library whilst trying to figure out how to drive gdb from a nosetests test suite. My test suite is intended to test some embedded microcontroller firmware, which it does so by launching it in a QEMU virtual machine (qemu-system-arm -M lm3s9695evb) then setting breakpoints, etc.

One gripe I have though, is the StringStream class directly calls logging.debug, one character at a time. This results in the following in nosetests:

-------------------- >> begin captured logging << --------------------
DEBUG:TestCliUtil.gdb[testlib.py:129]:Sending -target-select extended-remote localhost:1234
DEBUG:root[StringStream.py:72]: i
DEBUG:root[StringStream.py:72]: 1
DEBUG:root[StringStream.py:72]: "
DEBUG:TestCliUtil.gdb[testlib.py:129]:Sending -target-disconnect
DEBUG:root[StringStream.py:72]: i
DEBUG:root[StringStream.py:72]: 1
DEBUG:root[StringStream.py:72]: "
DEBUG:root[StringStream.py:72]: 4
DEBUG:root[StringStream.py:72]: 2
DEBUG:root[StringStream.py:72]: 0
DEBUG:root[StringStream.py:72]: 0
DEBUG:root[StringStream.py:72]: 0
DEBUG:root[StringStream.py:72]: "
DEBUG:root[StringStream.py:72]: 1
DEBUG:root[StringStream.py:72]: "
DEBUG:root[StringStream.py:72]: i
DEBUG:root[StringStream.py:72]: 1
DEBUG:root[StringStream.py:72]: "
DEBUG:root[StringStream.py:72]: 0
DEBUG:root[StringStream.py:72]: x
DEBUG:root[StringStream.py:72]: 0
DEBUG:root[StringStream.py:72]: 0
DEBUG:root[StringStream.py:72]: 0
DEBUG:root[StringStream.py:72]: 0
DEBUG:root[StringStream.py:72]: 0
DEBUG:root[StringStream.py:72]: a
DEBUG:root[StringStream.py:72]: 7
DEBUG:root[StringStream.py:72]: 8
DEBUG:root[StringStream.py:72]: "
DEBUG:root[StringStream.py:72]: R
DEBUG:root[StringStream.py:72]: e
DEBUG:root[StringStream.py:72]: s
DEBUG:root[StringStream.py:72]: e
DEBUG:root[StringStream.py:72]: t
DEBUG:root[StringStream.py:72]: H
DEBUG:root[StringStream.py:72]: a
DEBUG:root[StringStream.py:72]: n
DEBUG:root[StringStream.py:72]: d
DEBUG:root[StringStream.py:72]: l
DEBUG:root[StringStream.py:72]: e
DEBUG:root[StringStream.py:72]: r
DEBUG:root[StringStream.py:72]: "
DEBUG:root[StringStream.py:72]: t
DEBUG:root[StringStream.py:72]: e
DEBUG:root[StringStream.py:72]: s
DEBUG:root[StringStream.py:72]: t
DEBUG:root[StringStream.py:72]: /
DEBUG:root[StringStream.py:72]: l
DEBUG:root[StringStream.py:72]: i
DEBUG:root[StringStream.py:72]: b
DEBUG:root[StringStream.py:72]: /
DEBUG:root[StringStream.py:72]: s
DEBUG:root[StringStream.py:72]: t
DEBUG:root[StringStream.py:72]: a
DEBUG:root[StringStream.py:72]: r
DEBUG:root[StringStream.py:72]: t
DEBUG:root[StringStream.py:72]: u
DEBUG:root[StringStream.py:72]: p
DEBUG:root[StringStream.py:72]: .
DEBUG:root[StringStream.py:72]: c
DEBUG:root[StringStream.py:72]: "
DEBUG:root[StringStream.py:72]: /
DEBUG:root[StringStream.py:72]: h
DEBUG:root[StringStream.py:72]: o
DEBUG:root[StringStream.py:72]: m
DEBUG:root[StringStream.py:72]: e
DEBUG:root[StringStream.py:72]: /
DEBUG:root[StringStream.py:72]: s
DEBUG:root[StringStream.py:72]: t
DEBUG:root[StringStream.py:72]: u
DEBUG:root[StringStream.py:72]: a
DEBUG:root[StringStream.py:72]: r
DEBUG:root[StringStream.py:72]: t
DEBUG:root[StringStream.py:72]: l
DEBUG:root[StringStream.py:72]: /
DEBUG:root[StringStream.py:72]: v
DEBUG:root[StringStream.py:72]: r
DEBUG:root[StringStream.py:72]: t
DEBUG:root[StringStream.py:72]: /
DEBUG:root[StringStream.py:72]: p
DEBUG:root[StringStream.py:72]: r
DEBUG:root[StringStream.py:72]: o
DEBUG:root[StringStream.py:72]: j
DEBUG:root[StringStream.py:72]: e
DEBUG:root[StringStream.py:72]: c
DEBUG:root[StringStream.py:72]: t
DEBUG:root[StringStream.py:72]: s
DEBUG:root[StringStream.py:72]: /
DEBUG:root[StringStream.py:72]: w
DEBUG:root[StringStream.py:72]: i
DEBUG:root[StringStream.py:72]: d
DEBUG:root[StringStream.py:72]: e
DEBUG:root[StringStream.py:72]: s
DEBUG:root[StringStream.py:72]: k
DEBUG:root[StringStream.py:72]: y
DEBUG:root[StringStream.py:72]: /
DEBUG:root[StringStream.py:72]: h
DEBUG:root[StringStream.py:72]: u
DEBUG:root[StringStream.py:72]: b
DEBUG:root[StringStream.py:72]: /
DEBUG:root[StringStream.py:72]: f
DEBUG:root[StringStream.py:72]: i
DEBUG:root[StringStream.py:72]: r
DEBUG:root[StringStream.py:72]: m
DEBUG:root[StringStream.py:72]: w
DEBUG:root[StringStream.py:72]: a
DEBUG:root[StringStream.py:72]: r
DEBUG:root[StringStream.py:72]: e
DEBUG:root[StringStream.py:72]: /
DEBUG:root[StringStream.py:72]: t
DEBUG:root[StringStream.py:72]: e
DEBUG:root[StringStream.py:72]: s
DEBUG:root[StringStream.py:72]: t
DEBUG:root[StringStream.py:72]: /
DEBUG:root[StringStream.py:72]: l
DEBUG:root[StringStream.py:72]: i
DEBUG:root[StringStream.py:72]: b
DEBUG:root[StringStream.py:72]: /
DEBUG:root[StringStream.py:72]: s
DEBUG:root[StringStream.py:72]: t
DEBUG:root[StringStream.py:72]: a
DEBUG:root[StringStream.py:72]: r
DEBUG:root[StringStream.py:72]: t
DEBUG:root[StringStream.py:72]: u
DEBUG:root[StringStream.py:72]: p
DEBUG:root[StringStream.py:72]: .
DEBUG:root[StringStream.py:72]: c
DEBUG:root[StringStream.py:72]: "
DEBUG:root[StringStream.py:72]: 2
DEBUG:root[StringStream.py:72]: 9
DEBUG:root[StringStream.py:72]: 9
DEBUG:root[StringStream.py:72]: "
DEBUG:root[StringStream.py:72]: 1
DEBUG:root[StringStream.py:72]: "
DEBUG:root[StringStream.py:72]: a
DEBUG:root[StringStream.py:72]: l
DEBUG:root[StringStream.py:72]: l
DEBUG:root[StringStream.py:72]: "
DEBUG:root[StringStream.py:72]: i
DEBUG:root[StringStream.py:72]: 1
DEBUG:root[StringStream.py:72]: "

For bonus points, the text is coloured bright blue (cyan). Hitting the logger class with that quantity of log messages is a recipe for a really slow application (I've been there before… Logger.debug() in a tight loop inside OpenERP made things crawl!), and moreover, because it's the root logger, it's impossible to filter it if you have a requirement to see debug information elsewhere.

I'd suggest three things:

StringStream should use logging.getLogger to get a logger instance of its own rather than polluting the root logger with its messages.
StringStream should batch log messages so it's not calling .debug() so frequently as this will really slow down the logger class.
StringStream should not be calling basicConfig.

(1) and (3) is real easy to fix:

    def __init__(self, raw_text, debug=False):
        self.raw_text = raw_text
        self.index = 0
        self.len = len(raw_text)

        self._log = logging.getLogger(self.__class__.__module__)
        if debug:
            self._log.setLevel(logging.DEBUG)
        else:
            self._log.setLevel(logging.ERROR)
        handler = logging.StreamHandler()
        handler.setFormatter(logging.Formatter("%(funcName)20s %(message)s"))
        self._log.addHandler(handler)

Then replace calls to logging.debug with self._log.debug. As it happens, that's just one place. So to take care of that, and suggestion (2) at the same time:

    def advance_past_string_with_gdb_escapes(self, chars_to_remove_gdb_escape=None):
        """characters that gdb escapes that should not be
        escaped by this parser
        """

        if chars_to_remove_gdb_escape is None:
            chars_to_remove_gdb_escape = ['"']

        buf = ""

        if self._log.isEnabledFor(logging.DEBUG):
            read_text = ""

        while True:
            c = self.raw_text[self.index]
            self.index += 1
            if self._log.isEnabledFor(logging.DEBUG):
                read_text += c

            if c == "\\":
                # We are on a backslash and there is another character after the backslash
                # to parse. Handle this case specially since gdb escaped it for us

                # Get the next char that is being escaped
                c2 = self.raw_text[self.index]
                self.index += 1
                # only store the escaped character in the buffer; don't store the backslash
                # (don't leave it escaped)
                buf += c2

            elif c == '"':
                # Quote is closed. Exit (and don't include the end quote).
                break

            else:
                # capture this character, and keep capturing
                buf += c

        if self._log.isEnabledFor(logging.DEBUG):
            self._log.debug("%s", fmt_cyan(read_text))

        return buf

The text was updated successfully, but these errors were encountered:

ChrisMcMStone · 2019-03-14T15:04:34Z

I encountered the same issue. Applying @sjlongland 's changes above resolved it nicely.

cs01 · 2019-03-14T16:13:05Z

@sjlongland Thanks for the detailed issue report! And @ChrisMcMStone thanks for the followup. I somehow missed this issue.

So as for the issue, I used the cyan debug messages when writing the parser itself. If it's causing issues in production it can just be taken out or improved with better practices, I'm all for it.

Would you mind making a pull request?

cs01 mentioned this issue Sep 20, 2019

build updates, remove support for some python versions #39

Merged

cs01 closed this as completed in #39 Sep 21, 2019

hfudev mentioned this issue Oct 8, 2022

[jtag] Add mi mode flag (RDT-290) espressif/pytest-embedded#143

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Suppress logging output from StringStream? #36

Suppress logging output from StringStream? #36

sjlongland commented Jan 11, 2019

ChrisMcMStone commented Mar 14, 2019

cs01 commented Mar 14, 2019

Suppress logging output from StringStream? #36

Suppress logging output from StringStream? #36

Comments

sjlongland commented Jan 11, 2019

ChrisMcMStone commented Mar 14, 2019

cs01 commented Mar 14, 2019