Rethink the logging of BridgeDB

Now that we are playing around with BridgeDB, it's probably a good idea to also improve its logging.

For example, BridgeDB currently doesn't have any debug logs during descriptor parsing (which made it harder to find the root of #9174 (moved)).

Also, we should make sure that BridgeDB can scrub client's IPs from the logs (even for debug logs). Example of offending logs: Valid recaptcha from ... and [DEBUG] getBridgesForIP(, ...)

Also, maybe we should consider using Tor's extended nicknames to improve log greppability. Extended nicknames combine the identity digest and the nickname of a router in the same line. Example: $AAAAAAAA01234AAAAAAAAAAAAAAAAAAAAAAAAAAA=fred .

Check Tor's function node_get_verbose_nickname() and https://gitweb.torproject.org/torspec.git/blob/HEAD:/control-spec.txt#l152

We should also identify other information that the BridgeDB operator would be interested in and log them (maybe even write a heartbeat log with statistics).

added bridgedb-0.1.7 bridgedb-logging component::circumvention/bridgedb owner::isis priority::medium resolution::fixed status::closed type::task labels

This is more general than #3797 (moved), so marking that as dupe. We can lump everything into this.

Nearly finished with an initial branch. some thoughts/questions: a) Should we scrub the bridge's fingerprint when safe logging is not disabled? It can easily be used to retrieve the IP addr via Atlas, etc. Maybe we should hash the fingerprint by default so various aspects of the log file are linkable? b) Using the extended nickname will probably not be in v1 of this patch. It will be a little invasive to retrieve/store all the info we need. c) I think providing a heartbeat is a nice idea. How do you feel about displaying uptime, user GEOIP stats, OS stats (based on user-agent) over the past n hours? This won't be trivial, but it shouldn't be too difficult. I think we should push this to v2 also. d) If we're auditing the logging, do we want to consider switching to twisted.python.log? Isis brought this up a few weeks ago. If we're going to make a decision on it, now is a fine time.0

I'm prioritizing some features/enhancements (mainly adding more debug output and scrubbing) due to the importance of solving #9174 (moved). The faster we are able to fix that, the better.

Trac:
Status: new to needs_information

Replying to sysrqb:

Nearly finished with an initial branch. some thoughts/questions: a) Should we scrub the bridge's fingerprint when safe logging is not disabled? It can easily be used to retrieve the IP addr via Atlas, etc. Maybe we should hash the fingerprint by default so various aspects of the log file are linkable?

Hm, do we even care about scrubbing the IP addresses of bridges? I was mostly worrying about clients IPs.

b) Using the extended nickname will probably not be in v1 of this patch. It will be a little invasive to retrieve/store all the info we need.

Sure. No problem.

c) I think providing a heartbeat is a nice idea. How do you feel about displaying uptime, user GEOIP stats, OS stats (based on user-agent) over the past n hours? This won't be trivial, but it shouldn't be too difficult. I think we should push this to v2 also.

Yeah, I also like heartbeats.

BTW, be aware that if you want a "X unique IPs asked for bridges during the last N hours" dialog, you also need to keep client IPs in memory. We should probably not do that.

d) If we're auditing the logging, do we want to consider switching to twisted.python.log? Isis brought this up a few weeks ago. If we're going to make a decision on it, now is a fine time.0

Hm. How hard would it be to switch to twisted.logging? What are the advantages of using Twisted logging? Do we care about them? If the advantages are not too great, I'd rate this as low-priority and probably do something more important if it takes more than 2 hours of coding/thinking.

It's up to you :)

I'm prioritizing some features/enhancements (mainly adding more debug output and scrubbing) due to the importance of solving #9174 (moved). The faster we are able to fix that, the better.

Sounds good.

Oops. I forgot to mark on #3797 (moved) that I was working on the logger, but a general ticket is better. Also, oops: sysrqb, I don't mean to step on your toes if you're working on this, but I'll post what I've already done.

In reply to [comment:2 asn]:

Hm. How hard would it be to switch to twisted.logging? What are the advantages of using Twisted logging? Do we care about them?

The stdlib logging module, and most of stdlib´s IO utility modules as well, are not compatible with Twisted, due to the default way that Python handles file locks. From what I've understood from discussions on the twisted-dev list, using any of these modules can result in the weird Twisted bugs that pop up one-in-every-thirty-seven-times the program is run, and in general suck to try to debug.

My updates to the logging facilities (using Twisted's logger) and configuration loader so far are in this branch on Github.

As far as asn's ideas at the beginning of this ticket go, setting up a Filter for log emission to remove IP addresses shouldn't be too hard. And if there's any useful info that could safely be collected for metric or something else, that should be doable, though I don't know what info that might be as I am not super familiar with BridgeDB yet.

I was also thinking that it might be a good idea to rewrite the startup() parts of Main.py to be a twisted.application.Application, as then we would nearly-automatically get different logger contexts for different services/servers, daemonisation, resource control, and the like, though I should probably create a separate ticket for this.

Trac:
Cc: N/A to isis@torproject.org

Replying to asn:

Replying to sysrqb:

a) Should we scrub the bridge's fingerprint when safe logging is not disabled? It can easily be used to retrieve the IP addr via Atlas, etc. Maybe we should hash the fingerprint by default so various aspects of the log file are linkable?

Hm, do we even care about scrubbing the IP addresses of bridges? I was mostly worrying about clients IPs.

I don't know, do we? My thought was "what happens if an adversary obtains a log file?", but maybe this isn't something we should worry about. Currently we don't log client IP addresses (only the /24 "area", but that still maybe too much info). We also log email addresses, which I think we should scrub. My current branch scrubs these last two cases.

c) I think providing a heartbeat is a nice idea. How do you feel about displaying uptime, user GEOIP stats, OS stats (based on user-agent) over the past n hours? This won't be trivial, but it shouldn't be too difficult. I think we should push this to v2 also.

Yeah, I also like heartbeats.

It was your idea :)

BTW, be aware that if you want a "X unique IPs asked for bridges during the last N hours" dialog, you also need to keep client IPs in memory. We should probably not do that.

For GEOIP stats, I was thinking we would analyze the information in real-time and only need to keep counters in a dict for the various values, but this would not show unique queries. If we want unique IPs stats, we can hash the IP and store it in the DB only for the time period, very similar to what we do for email addresses. We absolutely should not store IP addresses, agreed.

d) If we're auditing the logging, do we want to consider switching to twisted.python.log? Isis brought this up a few weeks ago. If we're going to make a decision on it, now is a fine time.0

Hm. How hard would it be to switch to twisted.logging? What are the advantages of using Twisted logging? Do we care about them? If the advantages are not too great, I'd rate this as low-priority and probably do something more important if it takes more than 2 hours of coding/thinking.

It's up to you :)

Deferring to Isis' answer above :)

Replying to isis:

Oops. I forgot to mark on #3797 (moved) that I was working on the logger, but a general ticket is better. Also, oops: sysrqb, I don't mean to step on your toes if you're working on this, but I'll post what I've already done.

1. Communication :)
2. No worries, please continue! I'll stay away from rewriting the logger, and I'll concentrate on improving /what/ we log, but not /how/ we log it. It'll be easy to merge the former into any changes you make regarding the latter.

In reply to [comment:2 asn]:

Hm. How hard would it be to switch to twisted.logging? What are the advantages of using Twisted logging? Do we care about them?

The stdlib logging module, and most of stdlib´s IO utility modules as well, are not compatible with Twisted, due to the default way that Python handles file locks. From what I've understood from discussions on the twisted-dev list, using any of these modules can result in the weird Twisted bugs that pop up one-in-every-thirty-seven-times the program is run, and in general suck to try to debug.

My updates to the logging facilities (using Twisted's logger) and configuration loader so far are in this branch on Github.

Very nice! Some initial thoughts:

1. if you rebase your commits, you might want to move the commit with the new log.py (552f12b5fd9a) to be the first commit because many later commits depend on it.
2. If we try to touch/create a file/dir and fail, do we want to exit?
3. I think creating a Util module is fine. We may have some use for it later. We can probably move getkey() there also.
4. In 90628d663030d7cd1cd line 151

+        if os.access(self.file, os.R_OK):
+            log.msg("Loading config file: %s" % self.file)
+            new = execfile(self.file, self.settings)
+            self.settings.update(**new) 

Would it be better to handle the exception than deal with TOCTOU? This isn't really within the threat model of bridgedb, but I'll raise it for awareness.

As far as asn's ideas at the beginning of this ticket go, setting up a Filter for log emission to remove IP addresses shouldn't be too hard. And if there's any useful info that could safely be collected for metric or something else, that should be doable, though I don't know what info that might be as I am not super familiar with BridgeDB yet.

In the past we've simply wrapped any PII with a function that either outputs "[scrubbed]" or outputs the input. I can easily integrate this into your branch.

I was also thinking that it might be a good idea to rewrite the startup() parts of Main.py to be a twisted.application.Application, as then we would nearly-automatically get different logger contexts for different services/servers, daemonisation, resource control, and the like, though I should probably create a separate ticket for this. Yeah, this deserves its own ticket, but this sounds like a wise choice.

I have an initial patch which only adds more logging and sanitizes the info before writing.

Branch bug9199_more_minimal of https://github.com/sysrqb/bridgedb.git

Trac:
Status: needs_information to needs_review

After review from asn, new branch bug9199_more_minimal_rebase

Added some more logging in branch bug9199_2

I rebased my rewrite of bridgedb's logger on top of sysrqb's commits. It is here.

It uses twisted's logger, wraps blocking IO functions in a threadable.synchronize, has support for per-thread context switching, and has all the log level functionality of the stdlib logging module hacked into twisted. The one thing which it currently does not do as well is configurable log rotation, because iirc, twisted usually handles this through the application module. I could look into that more, though if someone else wanted to figure out the best way to do that, that would be great too.

Trac:
Status: needs_review to accepted
Owner: N/A to isis

Trac:
Status: accepted to needs_review

Ah, forgot. This also rewrites the Conf() configuration class (the old one was an old-style class, and would have had serialization problems), and with that #6127 (moved) is fixed too.

hey isis,

your branch contains non-logging-related changes. Can you put these in a different branch and trac ticket, so that we only talk about logging-related changes here. Examples: 03e79f9, 9aaf152, 96a01f2, 7db2fc8, 540dcf2ec02, a811d3a

Replying to isis:

Ah, forgot. This also rewrites the Conf() configuration class (the old one was an old-style class, and would have had serialization problems), and with that #6127 (moved) is fixed too.

Can you put this in another branch and trac ticket?

Trac:
Status: needs_review to needs_revision

Also, can you name your module logging so that you don't need to do the rewriting in 07dc793..44544c8?

Replying to asn:

hey isis,

Hi asn, thanks for the review!

your branch contains non-logging-related changes. Can you put these in a different branch and trac ticket, so that we only talk about logging-related changes here. Examples: 03e79f9, 9aaf152, 96a01f2, 7db2fc8, 540dcf2ec02, a811d3a

Replying to isis:

Ah, forgot. This also rewrites the Conf() configuration class (the old one was an old-style class, and would have had serialization problems), and with that #6127 (moved) is fixed too.

Can you put this in another branch and trac ticket?

The config and extra fixes are now #9277 (moved), which is in this branch: https://github.com/isislovecruft/bridgedb/compare/fix;9277-config

Replying to asn:

Also, can you name your module logging so that you don't need to do the rewriting in 07dc793..44544c8?

Done. :)

Here: https://github.com/isislovecruft/bridgedb/compare/feature;9199-improved-logging-r8

Trac:
Status: needs_revision to needs_review

Replying to isis:

Replying to asn:

hey isis,

Hi asn, thanks for the review!

your branch contains non-logging-related changes. Can you put these in a different branch and trac ticket, so that we only talk about logging-related changes here. Examples: 03e79f9, 9aaf152, 96a01f2, 7db2fc8, 540dcf2ec02, a811d3a

Replying to isis:

Ah, forgot. This also rewrites the Conf() configuration class (the old one was an old-style class, and would have had serialization problems), and with that #6127 (moved) is fixed too.

Can you put this in another branch and trac ticket?

The config and extra fixes are now #9277 (moved), which is in this branch: https://github.com/isislovecruft/bridgedb/compare/fix;9277-config

Replying to asn:

Also, can you name your module logging so that you don't need to do the rewriting in 07dc793..44544c8?

Done. :)

Here: https://github.com/isislovecruft/bridgedb/compare/feature;9199-improved-logging-r8

Quick review of log.py:

• Run your files over pylint. It finds lots of small mistakes. For example, you are using file as a parameter, when it's a python reserved name. Also you have some unused imports.

• I don't like isinstance() use in normal code. It makes dynamic-typed code even more confusing. I would prefer if types were well-defined. For example, I would prefer if setLevel were two functions; one for integers and one for strings; instead of a single function that tries to do both.

• Why are you using isinstance() in the __init__ of BridgeDBFileLogObserver? What else would daily be if it's not bool? Why don't you pass a default value of 10**6 to max_size (it's None now), instead of doing the isinstance() trick to insert a default value?

• _emit_with_level seems to do more things than Prepend basic ISO-8601 timestamps to log messages....

• I don't understand why you have to override LogPublisher with your own class. I'm not even sure what all these methods are. I can't find any public documentation for LogPublisher on the twisted docs. What are functions mute, showwarning etc. used for? Why do you have to override them?

• What's the deal with the except NameError trick in the end of the file? Do you want that block to only execute once? Can't you do this with a is_initialized flag for log.py? It's easier to understand IMO.

• warn() docs reference category, filename, etc. which don't exist. Does this happen elsewhere too?

• 1139de21bb has a wrong commit message. You can fix this with an empty git commit --squash that I can autosquash when I merge your branch. It's fine if you don't fix it too.

Other than that, the patch looks reasonable.

Trac:
Status: needs_review to needs_revision

From the top, first pass, nice job. (sorry, I can be a bit nit-picky)

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

• I think you might as well just reuse safe again (Dist.py:375)

+                raise IgnoreEmail("Client was warned" % Util.logSafely(emailaddress)) 

• Should these be a tuple? (HTTPServer.py:99)

+            logging.info("Valid recaptcha from %s. Parameters were %r"
+                         % Util.logSafely(remote_ip), request.args) 

• 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") 

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

• 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. 

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

• You don't actually return the level in setLevel(): (log.py:153)

+    :rtype: int
+    :returns: An integer from :attr:`log.LOG_LEVEL`. 

• 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

+            self.logfile = logfile.DailyLogFile(filename, self.folder.path)

But this (log.py:248) won't use the updated/correct dir, will it?

• 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.

+    def __init__(self, log_to_stdout=True):
...
+        self.log_to_stdout = log_to_stdout

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

• 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.

Replying to sysrqb:

From the top, first pass, nice job. (sorry, I can be a bit nit-picky)

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.

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').

Just jotting down two more bugs/problems that I've noticed:

1. At L435 (or thereabouts) in lib/bridgedb/EmailServer.py:

$ ack-grep log | ack-grep body
lib/bridgedb/EmailServer.py:435:    logging.debug("Email body:\n%s" % f.read())

This doesn't actually log the body of the email, it logs the body of the email and the full headers, including the original client headers, which include the client's email address and IP address.

2. At L207 (ish) in lib/bridgedb/Main.py:

206                 logging.warn("Parsed bridge that we've already added. Skipping") 
207                 logging.debug("  Bridge: %s" % bridge.getID())

This is borking the logfiles, because getID() returns the raw SHA-1 digest, not the hex representation (the latter is already stored in bridge.fingerprint).

I wasn't sure whether or not to make separate bugs for these, since the fixes are only like +6/-2 changes.

Replying to isis:

Just jotting down two more bugs/problems that I've noticed:

1. At L435 (or thereabouts) in lib/bridgedb/EmailServer.py:

$ ack-grep log | ack-grep body
lib/bridgedb/EmailServer.py:435:    logging.debug("Email body:\n%s" % f.read())
}}}
This doesn't actually log the _body_ of the email, it logs the body of the email _and_ the full headers, including the original client headers, which include the client's email address and IP address.

This is okay because it is at debug, however we must 1) figure out a way to scrub all PII by default, and 2) either adjust the message label to reflect the output or 3) adjust the output to reflect the message label :). If we need to troubleshoot mail issues in the future, I prefer to have the logging already in place. I guess one option for this is to build two copies of the outgoing mail, one we send and the other has PII scrubbed. Another option is that we manually log the headers and scrub them by default, e.g. {{{ w.addheader("To", clientAddr) logging.debug("To: %s" % util.logSafely(clientAddr))

Are you opposed to any/all of these ideas?

>  2) At L207 (ish) in lib/bridgedb/Main.py:
> {{{
> 206                 logging.warn("Parsed bridge that we've already added. Skipping") 
> 207                 logging.debug("  Bridge: %s" % bridge.getID())
> }}}
> This is borking the logfiles, because `getID()` returns the raw SHA-1 digest, not the hex representation (the latter is already stored in `bridge.fingerprint`).
> 

Borked is such a strong word :) But yeah, I noticed this also. It will be best to make this change.

> I wasn't sure whether or not to make separate bugs for these, since the fixes are only like +6/-2 changes.

You can simply make it a separate commit in the patchset, that should be fine.

Replying to 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 BridgeDBFileLogObservers 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 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 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 (moved).

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.

Replying to isis:

Replying to sysrqb:

• 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?

That's fine with me

• 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

Sure, just remind me when I forget.

• 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.

Yup. It looks like trac ate the indentation I added in my suggestion, too.

• 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.

Right, I think my point was only that the docstring says it returns an int, but the method never returns, so the return value will always be None.

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

}}} ... 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") }}} ... 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.

Yup, I understood this (sorry to make you provide an example), I just think it's a bit confusing/kludgey, but I don't immediately see a better way to do this and I'm ok with using this.

• 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?

Sure, that sounds fine. Reading through this now, I wonder if start() is what is bothering me. stop() does, indeed, stop all logging, however start() can start logging (if to stdout) but usually does absolutely nothing. I don't know if begin() is a better name. I don't know, I guess go with stop() -> shutdown(), unless you come up with a better one.

• 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.

Sounds perfect

Replying to 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.

Sounds good!

Replying to 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 (moved).

Ah ha! Cool, that looks fine.

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. :( sounds like a plan

Alright, done, refactored and rebased. It's here.

There are corresponding changes to the other modules, like changing the format strings to work correctly, and also using the safelogger where needed, but I can add these to a separate branch.

Please review!

Trac:
Keywords: N/A deleted, log, bridgedb added
Status: needs_revision to needs_review

Okay, the "correspond changes to the other modules" are in my branch fix/9199-extra-logging-changes-r2, which is based off of feature/9199-improved-logging-2-r3 (the branch linked to in the last comment).

To fully test the new logger, you probably want this changes, since it pulls in the refactored logger into the other modules.

The ticket for the unittests for these changes is #9875 (moved), unless someone thinks it should stay here.

Trac:
Keywords: log, bridgedb deleted, bridgedb-logging added

I added a couple extra commits to the above branches to fix a couple bugs I found while committing the unittests for this branch. I editted the previous comments to point to the correct branches.

Ok, very minor edits in feature/9199-improved-logging-2-r3_sy in my repo. You may actually want to break it apart and squash them in to their respective commits. (please make sure they all make sense and are correct)

Other thoughts:

• All other modules begin with a capital letter, can we keep this consistent?
• Would we gain anything from sticking _emit_with_level in a class and then having all subclasses of FileLogObserver inherit from it?
• Same for _formatTime()?
• Do we really want the default logging at Debug?
• Can we have a :raises: comment in _setPaths?
• In the docstring for getSafeLogger(), you don't show the output of the example use of SafeLogger

It looks really good so far, and the docs are awesome. I haven't tested it yet, nor looked at the unit tests, nor fully grokked some of the twisted features/workarounds. These are next on the list.

All of the Python loggers are messed up and incompatible with each other without resorting to gross hacks and jumping through hoops. Unless we want to switch to a "real" logger which supports asynchronous file IO, i.e. Foolscap's logging module or Twiggy, working with twisted.python.log is hell and the stdlib logging (which we currently use) is possibly worse. This would require major overhauls, and it's not the highest priority thing to deal with right now in BridgeDB.

I pulled the automatic log filters from my old branches, and a pretty formatter which helps with debugging by optionally showing function call traces and thread IDs. The automatic filters, if enabled with the SAFELOGGING config option, will automagically scrub IPv4/6 addresses and email addresses from the logs.

This, as well as the unittests for the changes (which fix #9875 (moved)), are in my fix/9199-safelogging branch. All tests pass, and coverage for the changes is %metrics-lib 3.0.0. Because it doesn't change any functionality (other than removing the need to manually call bridgedb.Util.logSafely() for every variable which might contain sensitive data), I'm going to merge this into bridgedb-0.1.7.

Trac:
Keywords: N/A deleted, bridgedb-0.1.7 added

Trac:
Resolution: N/A to fixed
Status: needs_review to closed

closed

mentioned in issue #9277 (moved)

mentioned in issue #9316 (moved)

mentioned in issue #9317 (moved)

mentioned in issue #9875 (moved)

moved to tpo/anti-censorship/bridgedb#9199 (closed)

mentioned in issue tpo/anti-censorship/bridgedb#9317 (closed)

mentioned in issue tpo/anti-censorship/bridgedb#9875 (closed)