[tor-bugs] #9199 [BridgeDB]: Rethink the logging of BridgeDB

[Tor Bug Tracker & Wiki]

#9199: Rethink the logging of BridgeDB
--------------------------+----------------------------
     Reporter:  asn       |      Owner:  isis
         Type:  task      |     Status:  needs_revision
     Priority:  normal    |  Milestone:
    Component:  BridgeDB  |    Version:
   Resolution:            |   Keywords:
Actual Points:            |  Parent ID:
       Points:            |
--------------------------+----------------------------

Comment (by isis):

 Replying to [comment:18 sysrqb]:
 > - Is it necessary to add the string sub twice? (Dist.py:372)
 > {{{
 > +                msg  = "Got a request for bridges from %r; we already"
 % safe
 > +                msg += " sent a warning. Ignoring." % safe
 > +                logging.info(msg)
 > }}}

 Nope, it is not only unnecessary, it's a TypeError. Nice catch. :)

 > - Should these be a tuple? (HTTPServer.py:99)
 > {{{
 > +            logging.info("Valid recaptcha from %s. Parameters were %r"
 > +                         % Util.logSafely(remote_ip), request.args)
 > }}}
 >

 Also nice catch.

 > - Can we keep the indent? It makes the log easier to read, (Main.py:233)
 > {{{
 > -                logging.debug("  Appending transport to running
 bridge")
 > +                logging.debug("Appending transport to running bridge")
 > }}}

 Sure. Can we change these to `'\t'`s instead?

 > - Also the same for this one? (Bridges.py:592)
 > {{{
 > -                logging.warn("  Skipping extra or-address line "\
 > -                             "from Bridge with ID %r" % ID)
 > +                logging.warn(
 > +                    "Skipping extra or-address line from Bridge with ID
 %r"
 > +                    % ID)
 > }}}

 Yep, so long as we don't do string concatenation within calls to the
 logger. See
 {{{% pydoc twisted.python.log.msg}}}

 > - This was confusing to read, can it be reworded? (log.py:133)
 > {{{
 > +    :type _stuff: A :type:None, :class:`t.p.failure.Failure`, or
 > +    :exc:Exception.
 > }}}
 > Maybe something like
 > {{{
 >      :type _stuff: It must be one of :type:None,
 >      :class:`t.p.failure.Failure`, or :exc:Exception.
 > }}}


 Yeah, the indentation was not right either. It should be:

 {{{
       :type _stuff: It must be one of :type:None,
           :class:`twisted.python.failure.Failure`, or :exc:Exception.
 }}}

 > I think the colons were screwing up my parsing of it, so if you can make
 that easier it will be good.

 These get formatted ''much'' nicer when the Sphinx docs are built.

 >
 > - You don't actually return the level in setLevel(): (log.py:153)
 > {{{
 > +    :rtype: int
 > +    :returns: An integer from :attr:`log.LOG_LEVEL`.
 > }}}

 It doesn't need to return. It is like an `@property.setter()`, but on a
 module global variable.

 > - the log folder is a bit confusing :(
 > {{{
 > +        ## this should be set outside this file by doing:
 > +        ## >>> import bridgedb.log as log
 > +        ## >>> log.folder = './putlogshere'
 > +        global folder
 > +        self.folder = filepath.FilePath(folder)
 > }}}
 > That's funky, but that's ok

 Hmm. This is the same as the `level`. Basically, this is telling people to
 do (for example, in `Main.py`):
 {{{
 import os
 from bridgedb import log

 log.level = log.LOG_LEVELS['ERROR']
 log.folder = os.path.expanduser('~/foo-logs')

 log.msg("foo")
 }}}

 and that they should ''not'' do anything like this:

 {{{
 import os
 from bridgedb.log import folder, level, msg, LOG_LEVEL

 level = LOG_LEVEL['ERROR']
 folder = os.path.expanduser('~/foo-logs')

 msg("foo")
 }}}

 Because the `msg()` function would then look ''within its own scope'' for
 `level` (or `folder`, if it were used in that function), and it would find
 the one at the top of the `log.py` file, set to `LOG_LEVEL['WARN']`, and
 use that instead of the one we set in the scope of the parent caller.
 Python scoping is a more than a bit of madness.

 > {{{
 > +            self.logfile = logfile.DailyLogFile(filename,
 self.folder.path)
 > }}}
 > But this (log.py:248) won't use the updated/correct dir, will it?
 >

 It should, because `self.folder =
 twisted.python.filepath.FilePath(folder)` where the `folder` that the
 `FilePath` is being initialised with is the module-level (by module, I
 mean "the log.py file") `global folder` towards the top of the file. As
 long as `folder` is set before the `BridgeDBFileLogObserver`s are
 initialised, it will use the one that is set.

 > - I'm not sure `daily` in BridgeDBFileLogObserver is correct.
 > In Main.py:beginLogging() we have:
 > {{{
 > +    lstdout = getattr(conf, 'LOG_STDOUT', True)
 > +    ldirect = os.path.join(rundir, getattr(conf, 'LOGDIR', 'log'))
 > +
 > +    logging.folder = ldirect
 > +    logging.setLevel(conf.LOGLEVEL)
 > +    logging.startLogging(logfile, lstdout)
 > }}}
 > Then in log.py:startLogging() we have:
 > {{{
 > +def startLogging(file=None, *args, **kwargs):
 > ...
 > +        fileobserver = BridgeDBFileLogObserver(file, *args,
 **kwargs).emit
 > }}}
 > And in BridgeDBFileLogObserver().__init__() we have:
 > {{{
 > +    def __init__(self, filename='bridgedb.log', daily=False,
 > +                 max_size=None, max_files=None):
 > ...
 > +        if not isinstance(daily, bool): daily = True
 > }}}
 > So I may be misreading this, but it seems like we start out stating we
 want to log to stdout and end up defining daily rotation. I guess
 BridgeDBLogPublisher().___init___() is where the value of the LOG_STDOUT
 config option should go.

 Yep, you're right. The `*args, **kwargs` should be part of the
 initialisation arguments for `BridgeDBLogPublisher`.

 > - Hm, BridgeDBLogPublisher().start() and stop() are not complementary, I
 fear this can be confusing.
 >

 Hmm, you're probably right. Maybe the `stop()` should be named
 `shutdown()`, or something else instead?

 > - Similar to what asn mentioned, maybe docing the "try, except
 NameError" block will be helpful. It makes sense, but it's purpose may not
 be obvious to others.

 For sure. It's definitely an unusual bit of code. Perhaps this whole
 "import this ''entire'' module, not functions and classes from it" should
 go in the module docstring, and there should be some sort of inline
 comments or something above the NameError trick.

 Replying to [comment:19 cypherpunks]:
 > One thing that I forgot to add, how do you feel about merging
 Util.logSafely() into log.py? The only reason I created Util.py was
 because there was no other place to put a logging-related function.


 Yes, I assumed this should be done after everything is merged.

 Replying to [comment:20 sysrqb]:
 >also also, I think you also need
 >{{{
 >diff --git a/lib/bridgedb/Main.py b/lib/bridgedb/Main.py
 >index 1f84091..729e4b0 100644
 >--- a/lib/bridgedb/Main.py
 >+++ b/lib/bridgedb/Main.py
 >@@ -293,6 +293,8 @@ def startup(cfg):
 >     :ivar logdir: The directory to store logfiles in. Defaults to
 rundir/log/.
 >     """
 >     rundir = getattr(cfg, 'RUN_IN_DIR', '~/run')
 >+    if rundir.startswith('~'):
 >+        rundir = os.path.expanduser(rundir)
 >     os.chdir(rundir)
 >     beginLogging(cfg, rundir)
 >}}}
 >or similar, else python cries when you use os.chdir('~/run').
 >


 Yeah, I do, you're right. Though I ''think'' that this change went into
 the config branch for #9277.

 I am refactoring. Somewhere though, something happened and my test of the
 next rebase of this failed to log anything. I should probably write some
 unittests to see what's failing.

-- 
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/9199#comment:23>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online