Document how the new logging system should be used and tested in new code

	@adiroiban reported
Trac ID	trac#8036
Type	enhancement
Created	2015-09-29 07:23:48Z
Branch	https://github.com/twisted/twisted/tree/new-log-usage-8036

I still don't have a clear guideline about how the new logging systems should be used in Twisted to replace the old logging system.

• Do we use namespaces?

• Do we always use the global log publisher?

• Do we document in the docstring/API what is logged by calling a method?

• Is the logging part of the contract/API ?

• How do we test the log text and data?

• Do we want optional or mandatory check of log calls.

• Do we check all structured logs ?

Some info here: [#7897](https://github.com/twisted/twisted/issues/7897)#comment:10

Problems with new name of the new log object [#7983](https://github.com/twisted/twisted/issues/7983)

From #8028#comment:4:

Regarding the logging part I based my choice looking at the only two other instances of the new logging system outside the logger package: defer.py and protocol.py . Looking at those files and these discussions: #7897#comment:10 #7983 it's pretty clear that the "common" accepted way is to use the global publisher, at module level, without a custom namespace. I'll just change the log symbol to _log.

Regarding the coverage of the formatting string I'd like to have some hints about which is the best solution to handle it, since the the "catch all" formatUnformattableEvent makes quite difficult to know if a log_format can't be properly formatted until the log is directed to a textfileobserver, requiring a not so nice "assertIn('expected_formatted_string', logline)". Besides being breakable by an innocuous rephrasing, this obviously requires a logging setup/teardown phase that can easily bloat the test code, e.g.

def test_getUserNonexistentDatabase(self):
    """
    A missing/inaccessible db file should cause a permanent rejection of
    authorization attempts.
    """

    fileHandle = io.StringIO()
    observer = textFileLogObserver(fileHandle)
    globalLogPublisher.addObserver(observer)
    self.addCleanup(lambda: globalLogPublisher.removeObserver(observer))

    self.db = checkers.FilePasswordDB('test_thisbetternoteverexist.db')
    self.failUnlessRaises(error.UnauthorizedLogin, self.db.getUser, 'user')

    self.assertIn("Unable to load credentials db: "
                  "IOError(2, 'No such file or directory')",
                  fileHandle.getvalue())

Maybe a reusable test utility like a context manager could help keeping the overhead code to the minimum; something like this:

class Capture(object):

    def __init__(self, testCase):
        self.testCase = testCase
        self.fileHandle = io.StringIO()
        self.observer = textFileLogObserver(self.fileHandle)

    def __enter__(self):
        globalLogPublisher.addObserver(self.observer)
        return self

    def __exit__(self, type_, value_, tb_):
        self.testCase.addCleanup(
            lambda: globalLogPublisher.removeObserver(self.observer))

    @property
    def logs(self):
        return self.fileHandle.getvalue()


def test_getUserNonexistentDatabase(self):
    """
    A missing/inaccessible db file should cause a permanent rejection of
    authorization attempts.
    """

    with Capture() as capture:

        self.db = checkers.FilePasswordDB('test_thisbetternoteverexist.db')
        self.failUnlessRaises(error.UnauthorizedLogin, self.db.getUser, 'user')

        self.assertIn("Unable to load credentials db: "
                      "IOError(2, 'No such file or directory')",
                      capture.logs)

Honestly I don't really like the string assertion and the fact that it seems that we are testing the logger's formatEvent method among cred tests, so I'd like to hear some advices from twisted devs about it.

Attachments:

• log_capture.patch (2576 bytes) - added by d.vinella on 2015-10-27 22:05:38Z -
• log_capture-2.patch (7222 bytes) - added by d.vinella on 2015-11-08 09:17:32Z -
• logcapture-wsanchez.diff (5578 bytes) - added by wsanchez on 2015-12-03 02:44:12Z - wsanchez suggested edits

trac-id__8036 8036
type__enhancement enhancement
reporter__adiroiban adiroiban
priority__normal normal
milestone__None None
branch__new_log_usage_8036 new-log-usage-8036
branch_author__ 
status__new new
resolution__None None
component__logger logger
keywords__None None
time__1443511428093681 1443511428093681
changetime__1554750884524341 1554750884524341
version__None None
owner__adiroiban adiroiban
cc__d.vinella@... cc__wsanchez@...