Merge lp:~robru/friends/refresh-fixup into lp:friends

[Robert Bruce Park]

Workaround for Authentication.login hanging, which was also causing Dispatcher.Refresh to hang thanks to it's use of thread.join(). Authentication.login was using an extraneous GObject MainLoop for the purposes of blocking it's thread synchronously until an async callback got called, but that was a dain bramaged approach because not only does it interfere with the primary mainloop, but Signon.AuthSession.process seems to have a bug where the callback often won't be called, causing the mainloop to block forever.

I've replaced this mainloop with a while loop that calls time.sleep() a limited number of times. The advantage here is that we have direct control over how many times time.sleep() gets called and never have to worry about waiting for a callback that might never come to unblock us.

This commit also makes sweeping changes to the logging infrastructure, which were necessary to track down this bug, and generally beneficial, so they're being included rather than reverted. Logging is now more verbose, and makes extensive use of the "logging.getLogger(__name__)" idiom for finer-grained data on which log is coming from where. debug_live.py also received an overhaul in order to better accomodate testing.

This branch fixes one of the major causes of dispatcher.Refresh hanging, in particular with Authentication.login, in the event that the server did not return any authentication data, it would just hang forever rather than returning properly. This branch converts the incorrect usage of a seconday GObject MainLoop into a much simpler threading.Lock, which serves the same purpose, doesn't interfere with the primary MainLoop, and allows to code to go on to raise existing exceptions when no authentication data is received.

I'm afraid there may be more conditions in which dispatcher.Refresh will hang, but they've been much more intermittent and difficult to pinpoint thus far. But this should still be merged as-is because it's an important fix to a really stupid part of old gwibber code that somehow managed to survive into the friends-service transition.

[Robert Bruce Park (robru)]

This branch also initiates a dispatcher.Refresh on friends-service launch, so that we don't have to wait 15 minutes for the first batch of data to be downloaded ;-)

[lp:~robru/friends/refresh-fixup]

14. By Robert Bruce Park on 2012-10-19

Drop extraneous instance attribute from Authentication class.

This commit also does some minor cleanups, and introduces some new
debugging statements that may prove helpful in tracking down any
future hangs we discover.

Authentication._authenticating turned out to be redundant, I've
dropped it in favor of testing for the presence of self._reply
directly. Authentication.login sees that self._reply isn't populated
yet, so it blocks, and then the callback populates that value and
stops the lock, allowing login() to return that value.

[Robert Bruce Park (robru)]

Ken, I've added a couple log.debug statements at the beginning and ending of our Thread.run subclass, so that now it should be really obvious to us in the debugging output when threads are starting and stopping. I still can no longer reproduce any more hangs in dispatcher.Refresh, I've let it run for quite a while with many iterations and no issues.

Please merge and then we'll just have to keep an eye out for any hangs if they return in the future.

[lp:~robru/friends/refresh-fixup]

15. By Robert Bruce Park on 2012-10-19

Set self._reply sooner, and unconditionally.

16. By Robert Bruce Park on 2012-10-19

Test suite fixups ;-)

17. By Robert Bruce Park on 2012-10-19

Replace threading.Lock() with time.sleep()

Yes, yes, I know time.sleep() is ugly, but this is looking like the
only way I can get this working quite right. The previous attempts
using threading.Lock and GObject.MainLoops both had very subtle hangs
that basically screwed up everything.

18. By Robert Bruce Park on 2012-10-19

Make logging *much* more explicit about what is being logged from where.

19. By Robert Bruce Park on 2012-10-19

Overhaul debug_live.py to make it compatible with Authentication changes.

20. By Robert Bruce Park on 2012-10-19

Update tests to no longer expect HTTPError to be raised.

This brings us much more into line with the Soup way of doing things,
rather than trying to force urllib-like behavior on top of Soup.

21. By Robert Bruce Park on 2012-10-19

Resurrect logging from friends-service.sh

22. By Robert Bruce Park on 2012-10-19

Overhaul a lot of the logging logic.

Logging now works in both friends-service and in debug_live. I found a
workaround for that duplicate-records bug. Tests have been updated.

23. By Robert Bruce Park on 2012-10-19

Fix the last of the test failures.

24. By Robert Bruce Park on 2012-10-20

Greatly simplify the logging logic. Was overthinking it before...

25. By Robert Bruce Park on 2012-10-20

Simplify debug_live.py

26. By Robert Bruce Park on 2012-10-20

debug_live.py doesn't need to be on a loop anymore.

The looping of it was primarily useful before we had the dispatcher
actually running. Now that we have the dispatcher, debug_live is more
just for firing single messages.

[Robert Bruce Park (robru)]

All tests pass, friends-service ran all overnight with no hangs, all good!

review: Approve

=== modified file 'friends-service.sh'
--- friends-service.sh	2012-10-18 17:48:42 +0000
+++ friends-service.sh	2012-10-20 00:36:21 +0000
@@ -1,3 +1,3 @@
 #! /bin/sh
 
-PYTHONPATH=. python3 -m friends.main -do
+PYTHONPATH=. python3 -m friends.main --debug --console

=== modified file 'friends/main.py'
--- friends/main.py	2012-10-15 18:56:26 +0000
+++ friends/main.py	2012-10-20 00:36:21 +0000
@@ -26,7 +26,9 @@
 import logging
 
 from dbus.mainloop.glib import DBusGMainLoop
-from gi.repository import Gio, GLib
+from gi.repository import Gio, GLib, GObject
+
+GObject.threads_init(None)
 
 from friends.service.connection import ConnectionMonitor
 from friends.service.dispatcher import Dispatcher
@@ -56,7 +58,7 @@
     gsettings = Gio.Settings.new('org.gwibber.preferences')
     initialize(console=args.console,
                debug=args.debug or gsettings.get_boolean('debug'))
-    log = logging.getLogger('friends.service')
+    log = logging.getLogger(__name__)
     log.info('Friends backend service starting')
 
     # Set up the DBus main loop.

=== modified file 'friends/protocols/facebook.py'
--- friends/protocols/facebook.py	2012-10-16 04:10:50 +0000
+++ friends/protocols/facebook.py	2012-10-20 00:36:21 +0000
@@ -37,7 +37,7 @@
 ME_URL = API_BASE.format(id='me')
 
 
-log = logging.getLogger('friends.service')
+log = logging.getLogger(__name__)
 
 
 class Facebook(Base):

=== modified file 'friends/protocols/flickr.py'
--- friends/protocols/flickr.py	2012-10-13 01:27:15 +0000
+++ friends/protocols/flickr.py	2012-10-20 00:36:21 +0000
@@ -28,7 +28,7 @@
 from friends.utils.time import iso8601utc, parsetime
 
 
-log = logging.getLogger('friends.service')
+log = logging.getLogger(__name__)
 
 
 # This is contact information for the Flickr REST service.

=== modified file 'friends/protocols/foursquare.py'
--- friends/protocols/foursquare.py	2012-10-13 01:27:15 +0000
+++ friends/protocols/foursquare.py	2012-10-20 00:36:21 +0000
@@ -28,7 +28,7 @@
 from friends.utils.time import iso8601utc
 
 
-log = logging.getLogger('friends.service')
+log = logging.getLogger(__name__)
 
 
 # The '&v=YYYYMMDD' defines the date that the API was last confirmed to be

=== modified file 'friends/protocols/twitter.py'
--- friends/protocols/twitter.py	2012-10-16 04:10:50 +0000
+++ friends/protocols/twitter.py	2012-10-20 00:36:21 +0000
@@ -34,17 +34,16 @@
 from friends.utils.time import parsetime, iso8601utc
 
 
-log = logging.getLogger('friends.service')
+log = logging.getLogger(__name__)
 
 
 # https://dev.twitter.com/docs/api/1.1
 class Twitter(Base):
-    # StatusNet claims to mimick the Twitter API very closely (so closely to
-    # the point that they refer you to the Twitter API reference docs as a
-    # starting point for learning about their API).  So these prefixes are
-    # defined here as class attributes instead of the usual module globals, in
-    # the hopes that the StatusNet class will be able to subclass Twitter and
-    # change only the URLs, with minimal other changes, and magically work.
+    # Identi.ca's API mimicks Twitter's to such a high degree that it
+    # is implemented just as a subclass of this, hence we need these
+    # constants defined as instance attributes, so that the Identica
+    # class can override them. If you make any changes to this class
+    # you must confirm that your changes do not break Identi.ca!
     _api_base = 'https://api.twitter.com/1.1/{endpoint}.json'
 
     _timeline = _api_base.format(endpoint='statuses/{}_timeline')

=== modified file 'friends/service/connection.py'
--- friends/service/connection.py	2012-10-13 01:27:15 +0000
+++ friends/service/connection.py	2012-10-20 00:36:21 +0000
@@ -50,7 +50,7 @@
     DISCONNECTED = 4
 
 
-log = logging.getLogger('friends.service')
+log = logging.getLogger(__name__)
 _State = None
 
 

=== modified file 'friends/service/dispatcher.py'
--- friends/service/dispatcher.py	2012-10-13 01:27:15 +0000
+++ friends/service/dispatcher.py	2012-10-20 00:36:21 +0000
@@ -34,7 +34,7 @@
 from friends.utils.manager import protocol_manager
 from friends.utils.signaler import signaler
 
-log = logging.getLogger('friends.service')
+log = logging.getLogger(__name__)
 
 
 class Dispatcher(dbus.service.Object):
@@ -53,6 +53,7 @@
         signaler.add_signal('ConnectionOnline', self._on_connection_online)
         signaler.add_signal('ConnectionOffline', self._on_connection_offline)
         self._on_connection_online()
+        self.Refresh()
 
     def _on_connection_online(self):
         if not self._timer_id:

=== modified file 'friends/service/shortener.py'
--- friends/service/shortener.py	2012-10-13 01:27:15 +0000
+++ friends/service/shortener.py	2012-10-20 00:36:21 +0000
@@ -27,7 +27,7 @@
 
 from friends.shorteners import lookup
 
-log = logging.getLogger('friends.service')
+log = logging.getLogger(__name__)
 
 
 class URLShorten(dbus.service.Object):

=== modified file 'friends/testing/mocks.py'
--- friends/testing/mocks.py	2012-10-17 18:55:49 +0000
+++ friends/testing/mocks.py	2012-10-20 00:36:21 +0000
@@ -168,7 +168,7 @@
     """
     def __init__(self, *modules):
         self._queue = Queue()
-        self._log = logging.getLogger('friends.test')
+        self._log = logging.getLogger(__name__)
         handler = QueueHandler(self._queue)
         formatter = logging.Formatter(LOG_FORMAT, style='{')
         handler.setFormatter(formatter)
@@ -205,8 +205,8 @@
         self.empty()
         for patcher in self._patchers:
             patcher.stop()
-        # Get rid of the friends.test logger.
-        del logging.Logger.manager.loggerDict['friends.test']
+        # Get rid of the mock logger.
+        del logging.Logger.manager.loggerDict[__name__]
 
     def empty(self, trim=True):
         """Return all the log messages written to this log.

=== modified file 'friends/testing/service.py'
--- friends/testing/service.py	2012-10-13 01:27:15 +0000
+++ friends/testing/service.py	2012-10-20 00:36:21 +0000
@@ -28,7 +28,7 @@
 from friends.utils.signaler import signaler
 
 
-log = logging.getLogger('friends.service')
+log = logging.getLogger(__name__)
 
 
 class TestService(dbus.service.Object):

=== modified file 'friends/tests/test_authentication.py'
--- friends/tests/test_authentication.py	2012-10-13 01:27:15 +0000
+++ friends/tests/test_authentication.py	2012-10-20 00:36:21 +0000
@@ -62,6 +62,11 @@
     def error(self, message, *args):
         self.error_messages.append(message.format(*args))
 
+    reset = __init__
+
+
+logger = Logger()
+
 
 class TestAuthentication(unittest.TestCase):
     """Test authentication."""
@@ -72,28 +77,29 @@
         self.account.auth.method = 'some method'
         self.account.auth.parameters = 'change me'
         self.account.auth.mechanism = ['whatever']
-        self.logger = Logger()
+        logger.reset()
 
+    @mock.patch('friends.utils.authentication.log', logger)
     @mock.patch('friends.utils.authentication.Signon', FakeSignon)
     def test_successful_login(self):
         # Prevent an error in the callback.
         self.account.auth.parameters = False
-        authenticator = Authentication(self.account, self.logger)
+        authenticator = Authentication(self.account)
         reply = authenticator.login()
         self.assertEqual(reply, 'auth reply')
-        self.assertEqual(self.logger.debug_messages,
-                         ['Login completed'])
-        self.assertEqual(self.logger.error_messages, [])
+        self.assertEqual(logger.debug_messages, ['Login completed'])
+        self.assertEqual(logger.error_messages, [])
 
+    @mock.patch('friends.utils.authentication.log', logger)
     @mock.patch('friends.utils.authentication.Signon', FakeSignon)
     def test_failed_login(self):
         # Trigger an error in the callback.
         class Error:
             message = 'who are you?'
         self.account.auth.parameters = Error
-        authenticator = Authentication(self.account, self.logger)
+        authenticator = Authentication(self.account)
         reply = authenticator.login()
-        self.assertIsNone(reply)
-        self.assertEqual(self.logger.debug_messages, ['Login completed'])
-        self.assertEqual(self.logger.error_messages,
+        self.assertEqual(reply, 'auth reply')
+        self.assertEqual(logger.debug_messages, ['Login completed'])
+        self.assertEqual(logger.error_messages,
                          ['Got authentication error: who are you?'])

=== modified file 'friends/tests/test_download.py'
--- friends/tests/test_download.py	2012-10-13 01:27:15 +0000
+++ friends/tests/test_download.py	2012-10-20 00:36:21 +0000
@@ -33,7 +33,7 @@
 from wsgiref.simple_server import WSGIRequestHandler, make_server
 from wsgiref.util import setup_testing_defaults
 
-from friends.testing.mocks import FakeSoupMessage
+from friends.testing.mocks import FakeSoupMessage, LogMock
 from friends.utils.download import Downloader, get_json
 
 try:
@@ -123,6 +123,12 @@
 class TestDownloader(unittest.TestCase):
     """Test the downloading utilities."""
 
+    def setUp(self):
+        self.log_mock = LogMock('friends.utils.download')
+
+    def tearDown(self):
+        self.log_mock.stop()
+
     @classmethod
     def setUpClass(cls):
         cls.server = make_server('', 9180, _app, handler_class=_SilentHandler)
@@ -231,17 +237,17 @@
 
     def test_unauthorized(self):
         # Test a URL that requires authorization.
-        with self.assertRaises(HTTPError) as cm:
-            Downloader('http://localhost:9180/auth').get_string()
-        self.assertEqual(cm.exception.code, 401)
+        Downloader('http://localhost:9180/auth').get_string()
+        self.assertEqual(self.log_mock.empty(),
+                         'http://localhost:9180/auth: 401 Unauthorized\n')
 
     def test_bad_authorization(self):
         # Test a URL that requires authorization, but doesn't have the correct
         # username or password.
-        with self.assertRaises(HTTPError) as cm:
-            Downloader('http://localhost:9180/auth',
-                       username='bob', password='wrong').get_string()
-        self.assertEqual(cm.exception.code, 401)
+        Downloader('http://localhost:9180/auth',
+                   username='bob', password='wrong').get_string()
+        self.assertEqual(self.log_mock.empty(),
+                         'http://localhost:9180/auth: 401 Unauthorized\n')
 
     def test_authorized(self):
         # Test a URL that requires authorization, and has the proper

=== modified file 'friends/tests/test_facebook.py'
--- friends/tests/test_facebook.py	2012-10-17 18:55:49 +0000
+++ friends/tests/test_facebook.py	2012-10-20 00:36:21 +0000
@@ -102,9 +102,11 @@
             self.protocol('receive')
             contents = log_mock.empty(trim=False)
         self.assertEqual(contents, """\
+Facebook.receive is starting in a new thread.
 Logging in to Facebook
 Facebook UID: None
 Facebook error (190 OAuthException): Bad access token
+Facebook.receive has completed, thread exiting.
 """)
 
     @mock.patch('friends.utils.download.Soup.Message',

=== modified file 'friends/tests/test_flickr.py'
--- friends/tests/test_flickr.py	2012-10-17 18:55:49 +0000
+++ friends/tests/test_flickr.py	2012-10-20 00:36:21 +0000
@@ -71,12 +71,14 @@
         with mock.patch.object(self.protocol, '_get_nsid', return_value=None):
             self.protocol('receive')
         self.assertEqual(self.log_mock.empty(), """\
+Flickr.receive is starting in a new thread.
 Flickr: No NSID available
 Friends operation exception:
  Traceback (most recent call last):
  ...
 friends.errors.AuthorizationError:\
  No Flickr user id available (account: faker/than fake)
+Flickr.receive has completed, thread exiting.
 """)
 
     @mock.patch('friends.utils.download.Soup.Message',
@@ -90,7 +92,10 @@
         # AuthorizationError.
         self.protocol('receive')
         # No error messages.
-        self.assertEqual(self.log_mock.empty(), '')
+        self.assertEqual(self.log_mock.empty(), """\
+Flickr.receive is starting in a new thread.
+Flickr.receive has completed, thread exiting.
+""")
         # But also no photos.
         self.assertEqual(TestModel.get_n_rows(), 0)
 
@@ -108,11 +113,13 @@
                                side_effect=side_effect):
             self.protocol('receive')
         self.assertEqual(self.log_mock.empty(), """\
+Flickr.receive is starting in a new thread.
 Friends operation exception:
  Traceback (most recent call last):
  ...
 friends.errors.AuthorizationError:\
  No Flickr user id available (account: faker/than fake)
+Flickr.receive has completed, thread exiting.
 """)
 
     @mock.patch('friends.utils.download.Soup.Message',
@@ -129,7 +136,10 @@
                                side_effect=side_effect):
             self.protocol('receive')
         # No error message.
-        self.assertEqual(self.log_mock.empty(), '')
+        self.assertEqual(self.log_mock.empty(), """\
+Flickr.receive is starting in a new thread.
+Flickr.receive has completed, thread exiting.
+""")
         # But also no photos.
         self.assertEqual(TestModel.get_n_rows(), 0)
 
@@ -145,6 +155,7 @@
         # AccessToken, but this fails.
         self.protocol('receive')
         self.assertEqual(self.log_mock.empty(), """\
+Flickr.receive is starting in a new thread.
 Logging in to Flickr
 No AccessToken in Flickr session:\
  {'TokenSecret': 'abc', 'username': 'Bob Dobbs', 'user_nsid': 'bob'}
@@ -154,6 +165,7 @@
  ...
 friends.errors.AuthorizationError:\
  No Flickr user id available (account: faker/than fake)
+Flickr.receive has completed, thread exiting.
 """)
 
     @mock.patch('friends.utils.download.Soup.Message',
@@ -166,6 +178,7 @@
         # AccessToken, but this fails.
         self.protocol('receive')
         self.assertEqual(self.log_mock.empty(), """\
+Flickr.receive is starting in a new thread.
 Logging in to Flickr
 No Flickr authentication results received.
 Flickr: No NSID available
@@ -174,6 +187,7 @@
  ...
 friends.errors.AuthorizationError:\
  No Flickr user id available (account: faker/than fake)
+Flickr.receive has completed, thread exiting.
 """)
 
     @mock.patch('friends.utils.download.Soup.Message',

=== modified file 'friends/tests/test_logging.py'
--- friends/tests/test_logging.py	2012-10-13 01:27:15 +0000
+++ friends/tests/test_logging.py	2012-10-20 00:36:21 +0000
@@ -35,30 +35,23 @@
     def setUp(self):
         # Preserve the original logger, but restore the global logging system
         # to pre-initialized state.
-        self._logger = logging.getLogger('friends.service')
-        del logging.Logger.manager.loggerDict['friends.service']
+        self._loggers = logging.Logger.manager.loggerDict.copy()
+        logging.Logger.manager.loggerDict.clear()
 
     def tearDown(self):
-        # Restore the original logger.
-        logging.Logger.manager.loggerDict['friends.service'] = self._logger
+        # Restore the original loggers.
+        logging.Logger.manager.loggerDict.update(self._loggers)
 
     def test_logger_has_filehandler(self):
         initialize()
-        # The top level 'friends.service' logger should be available.
-        log = logging.getLogger('friends.service')
+        # The top level logger should be available.
+        log = logging.getLogger()
         # Try to find the file opened by the default file handler.
         filenames = []
         for handler in log.handlers:
             if hasattr(handler, 'baseFilename'):
                 filenames.append(handler.baseFilename)
-        self.assertEqual(len(filenames), 1)
-
-    def _get_log_filename(self, log):
-        filenames = []
-        for handler in log.handlers:
-            if hasattr(handler, 'baseFilename'):
-                filenames.append(handler.baseFilename)
-        return filenames
+        self.assertGreater(len(filenames), 0)
 
     def test_logger_message(self):
         # Write an error message to the log and test that it shows up.
@@ -67,11 +60,7 @@
         logfile = os.path.join(tempdir, 'friends-test.log')
         initialize(filename=logfile)
         # Get another handle on the log file.
-        log = logging.getLogger('friends.service')
-        # Try to find the file opened by the default file handler.
-        filenames = self._get_log_filename(log)
-        self.assertEqual(len(filenames), 1)
-        logfile = filenames[0]
+        log = logging.getLogger()
         self.assertEqual(os.stat(logfile).st_size, 0)
         # Log messages at INFO or higher should be written.
         log.info('friends at your service')
@@ -81,12 +70,11 @@
             contents = fp.read()
         lines = contents.splitlines()
         self.assertEqual(len(lines), 1)
-        # The log message will have a variable timestamp at the front, so
-        # ignore that, but check everything else.
+        # The log message will have a variable timestamp, so ignore
+        # that, but check everything else.
         self.assertRegex(
             lines[0],
-            r'friends.service\s+MainThread\s+:\s+INFO\s+-\s+'
-            r'friends at your service')
+            r'INFO\s+MainThread.*root\s+friends at your service')
 
     def test_console_logger(self):
         # The logger can support an optional console logger.
@@ -94,10 +82,10 @@
         self.addCleanup(shutil.rmtree, tempdir)
         logfile = os.path.join(tempdir, 'friends-test.log')
         initialize(console=True, filename=logfile)
-        log = logging.getLogger('friends.service')
+        log = logging.getLogger()
         # Can we do better than testing that there are now two handlers for
         # the logger?
-        self.assertEqual(2, sum(1 for handler in log.handlers))
+        self.assertEqual(3, sum(1 for handler in log.handlers))
 
     def test_default_logger_level(self):
         # By default, the logger level is INFO.
@@ -106,11 +94,7 @@
         logfile = os.path.join(tempdir, 'friends-test.log')
         initialize(filename=logfile)
         # Get another handle on the log file.
-        log = logging.getLogger('friends.service')
-        # Try to find the file opened by the default file handler.
-        filenames = self._get_log_filename(log)
-        self.assertEqual(len(filenames), 1)
-        logfile = filenames[0]
+        log = logging.getLogger()
         # By default, debug messages won't get written since they are less
         # severe than INFO.
         log.debug('friends is ready')
@@ -123,11 +107,7 @@
         logfile = os.path.join(tempdir, 'friends-test.log')
         initialize(filename=logfile, debug=True)
         # Get another handle on the log file.
-        log = logging.getLogger('friends.service')
-        # Try to find the file opened by the default file handler.
-        filenames = self._get_log_filename(log)
-        self.assertEqual(len(filenames), 1)
-        logfile = filenames[0]
+        log = logging.getLogger()
         log.debug('friends is ready')
         self.assertGreater(os.stat(logfile).st_size, 0)
         # Read the contents, which should be just one line of output.
@@ -139,5 +119,4 @@
         # ignore that, but check everything else.
         self.assertRegex(
             lines[0],
-            r'friends.service\s+MainThread\s+:\s+DEBUG\s+-\s+'
-            r'friends is ready')
+            r'DEBUG\s+MainThread.*root\s+friends is ready')

=== modified file 'friends/utils/account.py'
--- friends/utils/account.py	2012-10-18 18:41:58 +0000
+++ friends/utils/account.py	2012-10-20 00:36:21 +0000
@@ -31,7 +31,7 @@
 from friends.utils.model import COLUMN_INDICES, Model
 
 
-log = logging.getLogger('friends.service')
+log = logging.getLogger(__name__)
 
 
 class AccountManager:

=== modified file 'friends/utils/authentication.py'
--- friends/utils/authentication.py	2012-10-13 01:27:15 +0000
+++ friends/utils/authentication.py	2012-10-20 00:36:21 +0000
@@ -21,37 +21,37 @@
 
 
 import logging
+import time
 
 from gi.repository import GObject, Signon
 GObject.threads_init(None)
 
 
+log = logging.getLogger(__name__)
+
+
 class Authentication:
-    def __init__(self, account, log=None):
+    def __init__(self, account):
         self.account = account
-        self.log = (logging.getLogger('friends.service')
-                    if log is None
-                    else log)
         self._reply = None
-        self._authenticating = False
 
     def login(self):
         auth = self.account.auth
         self.auth_session = Signon.AuthSession.new(auth.id, auth.method)
-        self._authenticating = True
-        self._loop = GObject.MainLoop()
         self.auth_session.process(
             auth.parameters, auth.mechanism,
             self._login_cb, None)
-        if self._authenticating:
-            self._loop.run()
+        timeout = 30
+        while self._reply is None and timeout > 0:
+            # We're building a synchronous API on top of an inherently
+            # async library, so we need to block this thread until the
+            # callback gets called to give us the response to return.
+            time.sleep(0.5)
+            timeout -= 1
         return self._reply
 
     def _login_cb(self, session, reply, error, user_data):
-        self._authenticating = False
+        self._reply = reply
         if error:
-            self.log.error('Got authentication error: {}', error.message)
-        else:
-            self._reply = reply
-        self.log.debug('Login completed')
-        self._loop.quit()
+            log.error('Got authentication error: {}'.format(error.message))
+        log.debug('Login completed')

=== modified file 'friends/utils/avatar.py'
--- friends/utils/avatar.py	2012-10-13 01:27:15 +0000
+++ friends/utils/avatar.py	2012-10-20 00:36:21 +0000
@@ -31,7 +31,7 @@
 from friends.utils.download import Downloader
 
 
-log = logging.getLogger('friends.avatars')
+log = logging.getLogger(__name__)
 CACHE_DIR = os.path.realpath(os.path.join(
     GLib.get_user_cache_dir(), 'friends', 'avatars'))
 CACHE_AGE = timedelta(weeks=4)

=== modified file 'friends/utils/base.py'
--- friends/utils/base.py	2012-10-16 18:58:49 +0000
+++ friends/utils/base.py	2012-10-20 00:36:21 +0000
@@ -52,7 +52,7 @@
 _publish_lock = threading.Lock()
 
 
-log = logging.getLogger('friends.service')
+log = logging.getLogger(__name__)
 
 
 def feature(method):
@@ -105,9 +105,10 @@
 class _OperationThread(threading.Thread):
     """Catch, log, and swallow all exceptions in the sub-thread."""
 
-    def __init__(self, barrier, *args, **kws):
+    def __init__(self, barrier, *args, identifier=None, **kws):
         # The barrier will only be provided when the system is under test.
         self._barrier = barrier
+        self._id = identifier
         super().__init__(*args, **kws)
 
     # Always run these as daemon threads, so they don't block the main thread,
@@ -115,10 +116,12 @@
     daemon = True
 
     def run(self):
+        log.debug('{} is starting in a new thread.'.format(self._id))
         try:
             super().run()
         except Exception:
             log.exception('Friends operation exception:\n')
+        log.debug('{} has completed, thread exiting.'.format(self._id))
         # If the system is under test, indicate that we've reached the
         # barrier, so that the main thread, i.e. the test thread waiting for
         # the results, can then proceed.
@@ -160,6 +163,8 @@
         # thread to assert the results of the sub-thread.
         barrier = (threading.Barrier(parties=2) if Base._SYNCHRONIZE else None)
         _OperationThread(barrier,
+                         identifier='{}.{}'.format(self.__class__.__name__,
+                                                   operation),
                          target=method, args=args, kwargs=kwargs).start()
         # When under synchronous testing, wait until the sub-thread completes
         # before returning.
@@ -299,7 +304,7 @@
         log.debug('{} to {}'.format(
                 'Re-authenticating' if old_token else 'Logging in', protocol))
 
-        result = Authentication(self._account, log).login()
+        result = Authentication(self._account).login()
         if result is None:
             log.error(
                 'No {} authentication results received.'.format(protocol))

=== modified file 'friends/utils/download.py'
--- friends/utils/download.py	2012-10-18 18:41:54 +0000
+++ friends/utils/download.py	2012-10-20 00:36:21 +0000
@@ -31,7 +31,7 @@
 from urllib.error import HTTPError
 from urllib.parse import urlencode
 
-log = logging.getLogger('friends.service')
+log = logging.getLogger(__name__)
 
 
 # Global libsoup session instance.
@@ -139,16 +139,9 @@
         message = self._build_request()
         _soup.send_message(message)
         if message.status_code != 200:
-            # Even though we're using libsoup instead of Python's urllib
-            # libraries, it's helpful for clients to receive an exception when
-            # non-success error codes are received.  This lets the clients do
-            # additional work if they want, and it prevents rate limiting from
-            # occurring.
-            raise HTTPError(self.url,
-                            message.status_code,
-                            message.reason_phrase,
-                            self.headers,
-                            None)
+            log.error('{}: {} {}'.format(self.url,
+                                         message.status_code,
+                                         message.reason_phrase))
         yield message
         self._rate_limiter.update(message)
 

=== modified file 'friends/utils/logging.py'
--- friends/utils/logging.py	2012-10-13 01:27:15 +0000
+++ friends/utils/logging.py	2012-10-20 00:36:21 +0000
@@ -19,15 +19,25 @@
 import errno
 import logging
 import logging.handlers
+import oauthlib.oauth1
 
 from gi.repository import GLib
 
 
+# Set a global default of no logging. This is a workaround for a bug
+# where we were getting duplicated log records.
+logging.basicConfig(filename='/dev/null', level=100)
+
+
+# Disable logging in oauthlib because it is very verbose.
+oauthlib.oauth1.rfc5849.logging.debug = lambda *ignore: None
+
+
 LOG_FILENAME = os.path.join(
     os.path.realpath(os.path.abspath(GLib.get_user_cache_dir())),
     'friends', 'friends.log')
-LOG_FORMAT = '{asctime} - {name:12} {threadName:14}: {levelname:8} - {message}'
-CSL_FORMAT = '{name:12} {threadName:12}: {levelname:8} {message}'
+LOG_FORMAT = '{levelname:5}  {threadName:10}  {asctime}  {name:18}  {message}'
+CSL_FORMAT = LOG_FORMAT.replace('  {asctime}', '')
 
 
 def initialize(console=False, debug=False, filename=None):
@@ -48,11 +58,7 @@
     except OSError as error:
         if error.errno != errno.EEXIST:
             raise
-    log = logging.getLogger('friends.service')
-    if debug:
-        log.setLevel(logging.DEBUG)
-    else:
-        log.setLevel(logging.INFO)
+
     # Install a rotating log file handler.  XXX There should be a
     # configuration file rather than hard-coded values.
     text_handler = logging.handlers.RotatingFileHandler(
@@ -60,9 +66,16 @@
     # Use str.format() style format strings.
     text_formatter = logging.Formatter(LOG_FORMAT, style='{')
     text_handler.setFormatter(text_formatter)
-    log.addHandler(text_handler)
+
+    console_handler = logging.StreamHandler()
+    console_formatter = logging.Formatter(CSL_FORMAT, style='{')
+    console_handler.setFormatter(console_formatter)
+
+    log = logging.getLogger()
+    if debug:
+        log.setLevel(logging.DEBUG)
+    else:
+        log.setLevel(logging.INFO)
     if console:
-        console_handler = logging.StreamHandler()
-        console_formatter = logging.Formatter(CSL_FORMAT, style='{')
-        console_handler.setFormatter(console_formatter)
         log.addHandler(console_handler)
+    log.addHandler(text_handler)

=== modified file 'friends/utils/menus.py'
--- friends/utils/menus.py	2012-10-13 01:27:15 +0000
+++ friends/utils/menus.py	2012-10-20 00:36:21 +0000
@@ -34,7 +34,7 @@
 
 
 DESKTOP_ID = 'friends.desktop'
-log = logging.getLogger('friends.service')
+log = logging.getLogger(__name__)
 
 
 def helper(executable):

=== modified file 'tools/debug_live.py'
--- tools/debug_live.py	2012-10-13 01:27:15 +0000
+++ tools/debug_live.py	2012-10-20 00:36:21 +0000
@@ -20,30 +20,29 @@
 """
 
 import sys
+import time
+import logging
 
 sys.path.insert(0, '.')
 
 from gi.repository import GObject
+from friends.utils.logging import initialize
 from friends.utils.account import AccountManager
 from friends.utils.base import Base
 from friends.utils.model import Model
 
-
-# Ensure synchronous operation of Base.__call__() for easier testing.
-Base._SYNCHRONIZE = True
-
-
-def refresh(account):
+# Print all logs for debugging purposes
+initialize(debug=True, console=True)
+
+
+log = logging.getLogger('friends.debug_live')
+
+
+def row_added(model, itr):
+    row = model.get_row(itr)
+    print(row)
+    log.info('ROWS: {}'.format(len(model)))
     print()
-    print('#' * 80)
-    print('Performing "{}" operation!'.format(args[0]))
-    print('#' * 80)
-
-    account.protocol(*args)
-    for row in Model:
-        print([col for col in row])
-        print()
-    print('ROWS: ', len(Model))
 
 
 if __name__ == '__main__':
@@ -56,14 +55,16 @@
     found = False
     a = AccountManager(None)
 
+    Model.connect('row-added', row_added)
+
     for account_id, account in a._accounts.items():
         if account_id.endswith(protocol):
             found = True
-            refresh(account)
-            GObject.timeout_add_seconds(300, refresh, account)
+            account.protocol(*args)
 
     if not found:
-        print('No {} account found in your Ubuntu Online Accounts!'.format(
-            protocol))
+        log.error('No {} found in Ubuntu Online Accounts!'.format(protocol))
     else:
-        GObject.MainLoop().run()
+        loop = GObject.MainLoop()
+        GObject.timeout_add_seconds(10, loop.quit)
+        loop.run()