Try to cut down on the crazy verbosity of logging

[zachriggle]

The Travis CI logs are really huge, and literally everything is getting logged to the screen.

Try to cut down on the logging verbosity.

I don't think the change was our fault, I'm pretty sure something with one of the dependencies (or Travis itself) changes something regarding the default logging objects.

[zachriggle]

I've confirmed that this is Sphinx's fault, for adding a new handler to the root logging object.

If you pop an interactive pdb shell in the middle of e.g.:

$ PWNLIB_NOTERM=1 coverage run -m sphinx -b doctest docs/source docs/build/doctest pwnlib/util/web.py

diff --git a/pwnlib/tubes/remote.py b/pwnlib/tubes/remote.py
index 3673a006..6930e33b 100644
--- a/pwnlib/tubes/remote.py
+++ b/pwnlib/tubes/remote.py
@@ -85,6 +85,9 @@ class remote(sock):
         sock    = None
         timeout = self.timeout

+        import pdb
+        pdb.set_trace()
+
         with self.waitfor('Opening connection to %s on port %d' % (self.rhost, self.rport)) as h:
             for res in socket.getaddrinfo(self.rhost, self.rport, fam, typ, 0, socket.AI_PASSIVE):
                 self.family, self.type, self.proto, _canonname, sockaddr = res

We can inspect the logging stack. Pwntool's default handler is not even installed yet, by virtue of the missing [ERROR] message.

(Pdb) import pwnlib
(Pdb) pwnlib.context.context.log_level
40
(Pdb) self.error('asdf')
*** PwnlibException: asdf
(Pdb) pwnlib.log.install_default_handler()
(Pdb) self.error('asdf')
[ERROR] asdf
*** PwnlibException: asdf

Our filtering is working correctly, but Sphinx prints the stuff out:

(Pdb) self.info('asdf')
asdf
(Pdb) pwnlib.context.context.log_level = 'info'
(Pdb) self.info('asdf')
[*] asdf
asdf

So Sphinx has installed some handler, and it's ignoring our log level information. It has actually installed three.

(Pdb) self._logger.root.handlers
[<sphinx.util.logging.NewLineStreamHandlerPY2 object at 0x104800250>, <logging.StreamHandler object at 0x104800550>, <sphinx.util.logging.MemoryHandler object at 0x105acf090>]
(Pdb) self._logger.root.handlers[1].stream
<sphinx.util.logging.LastMessagesWriter object at 0x104800510>

And with this information, we can easily find the source where this happens: https://github.com/sphinx-doc/sphinx/blob/228fdb892af25f4b93f2760f2cd6497f2aabc0be/sphinx/util/logging.py#L464-L493

def setup(app, status, warning):
    # type: (Sphinx, IO, IO) -> None
    """Setup root logger for Sphinx"""
    logger = logging.getLogger()
    logger.setLevel(logging.NOTSET)

    # clear all handlers
    for handler in logger.handlers[:]:
        logger.removeHandler(handler)

    info_handler = NewLineStreamHandler(SafeEncodingWriter(status))  # type: ignore
    info_handler.addFilter(InfoFilter())
    info_handler.setLevel(VERBOSITY_MAP[app.verbosity])
    info_handler.setFormatter(ColorizeFormatter())

It seems that we should be able to override this function entirely in conf.py and kill this stupid shit by overriding the method. However, that turns out to not be the case. It looks like we can just manually remove the first handler object.

(Pdb) import logging
(Pdb) import pwnlib
(Pdb) pwnlib.log.install_default_handler()
(Pdb) pwnlib.context.context.log_level = 'info'
(Pdb) logging.root.handlers
[<sphinx.util.logging.NewLineStreamHandlerPY2 object at 0x10fad2250>, <logging.StreamHandler object at 0x10fad2550>, <sphinx.util.logging.MemoryHandler object at 0x110da1090>]
(Pdb) self.info('asdf')
[*] asdf
asdf
(Pdb) del logging.root.handlers[0]
(Pdb) self.info('asdf')
[*] asdf

[zachriggle]

Unfortunately, removing that specific handler means that all of the normal Sphinx output is broken. Fun!

We can still make it work with a logging filter.

[zachriggle]

@idolf FYI

[TethysSvensson]

Ack

[TethysSvensson]

For context: This PR was submitted to 3.11.0 and then cherry-picked to 3.9.1. The cherry-picked commit was part of #1040.