Merge lp:~nataliabidart/magicicada-server/no-u1-devtools into lp:magicicada-server

[Natalia Bidart]

- Complete cleanup of logging setup and logging testing.
- Removed dependency on ubuntuone-devtools.

[lp:~nataliabidart/magicicada-server/no-u1-devtools]

80. By Natalia Bidart on 2016-08-06

Less changes against trunk.

81. By Natalia Bidart on 2016-08-06

Merged trunk in.

82. By Natalia Bidart on 2016-08-07

Test fixed

83. By Natalia Bidart on 2016-08-07

No more ubuntu_sso symlink.

84. By Natalia Bidart on 2016-08-08

All tests passing for real :-)

85. By Natalia Bidart on 2016-08-14

Merged trunk into no-u1-devtools.

86. By Natalia Bidart on 2016-08-18

Fixed pending tests.

[Facundo Batista (facundo)]

+1

Couldn't really tested, have a broken env.

I got complains about magicicada/settings/testing.py, though; like "F405 os may be undefined, or defined from star imports: magicicada.settings"; maybe we could avoid that "import *"

Anyway, if you're sure that logs are being produced ok in test and normal server mode, go ahead :)

review: Approve

[lp:~nataliabidart/magicicada-server/no-u1-devtools]

87. By Natalia Bidart on 2016-08-23

Allow for verbosity to be set for tests.

=== modified file 'build/config-manager.txt'
--- build/config-manager.txt	2016-08-06 21:09:45 +0000
+++ build/config-manager.txt	2016-08-23 00:49:23 +0000
@@ -34,5 +34,4 @@
 ./.sourcecode/timeline                    ~canonical-launchpad-branches/python-timeline/trunk;revno=10
 ./.sourcecode/u1sync                      ~facundo/u1sync/opensourcing;revno=10
 ./.sourcecode/ubuntuone-client            ~chicharreros/magicicada-client/trunk
-./.sourcecode/ubuntuone-dev-tools         ~ubuntuone-control-tower/ubuntuone-dev-tools/trunk;revno=78
 ./.sourcecode/ubuntuone-storage-protocol  ~facundo/ubuntuone-storage-protocol/opensourcing;revno=165

=== modified file 'dependencies-devel.txt'
--- dependencies-devel.txt	2016-08-14 20:33:04 +0000
+++ dependencies-devel.txt	2016-08-23 00:49:23 +0000
@@ -8,4 +8,4 @@
 python-pyinotify
 python-testtools
 python-twisted-names
-virtualenv
+python-virtualenv

=== removed symlink 'lib/ubuntuone/devtools'
=== target was u'../../.sourcecode/ubuntuone-dev-tools/ubuntuone/devtools'
=== modified file 'lib/ubuntuone/supervisor/heartbeat_listener.py'
--- lib/ubuntuone/supervisor/heartbeat_listener.py	2016-05-29 21:20:25 +0000
+++ lib/ubuntuone/supervisor/heartbeat_listener.py	2016-08-23 00:49:23 +0000
@@ -35,8 +35,6 @@
 from supervisor import childutils, states
 from supervisor.events import EventTypes, getEventNameByType
 
-from magicicada.server.logger import configure_logger
-
 
 PROCESS_COMMUNICATION_STDOUT = \
     getEventNameByType(EventTypes.PROCESS_COMMUNICATION_STDOUT)
@@ -237,17 +235,6 @@
         parser.print_help()
         sys.exit(2)
 
-    # configure the logger
-    try:
-        level = logging._levelNames[options.log_level]
-    except KeyError:
-        # if level doesn't exist fallback to DEBUG
-        level = logging.DEBUG
-
-    root_logger = logging.getLogger()
-    configure_logger(logger=root_logger, filename=options.log_file,
-                     level=level, log_format=options.log_format)
-
     rpc = childutils.getRPCInterface(os.environ)
     hbl = HeartbeatListener(options.timeout, options.interval, options.groups,
                             options.processes, rpc)

=== modified file 'lib/utilities/testlib.py'
--- lib/utilities/testlib.py	2016-03-09 02:18:43 +0000
+++ lib/utilities/testlib.py	2016-08-23 00:49:23 +0000
@@ -149,12 +149,12 @@
 
 class MagicicadaRunner(DiscoverRunner):
 
-    def __init__(self, factory, filter_test):
+    def __init__(self, factory, filter_test, verbosity=1):
         self.factory = factory
         self.loader = RegexTestLoader(filter_test)
         self.server_suite = TestSuite()
         self.non_server_suite = TestSuite()
-        super(MagicicadaRunner, self).__init__()
+        super(MagicicadaRunner, self).__init__(verbosity=verbosity)
 
     def add_tests_for_dir(self, testdir, testpaths, topdir):
         """Helper for build_suite; searches a particular testdir for tests.
@@ -256,6 +256,7 @@
                 result = False
         return result
 
-    runner = MagicicadaRunner(factory, filter_test)
+    runner = MagicicadaRunner(
+        factory, filter_test, verbosity=options.verbosity)
     result = runner.run_tests(test_labels=(topdir, testdirs, testpaths))
     return not result.wasSuccessful()

=== modified file 'magicicada/metrics/__init__.py'
--- magicicada/metrics/__init__.py	2016-06-03 20:58:22 +0000
+++ magicicada/metrics/__init__.py	2016-08-23 00:49:23 +0000
@@ -27,7 +27,7 @@
 
 from django.conf import settings
 
-from magicicada.server.logger import configure_logger
+logger = logging.getLogger(__name__)
 
 
 class FileBasedMeter(object):
@@ -40,10 +40,6 @@
         self._namespace = namespace
         self._counters = {}
 
-        # configure logs
-        self._logger = logging.getLogger('metrics')
-        configure_logger(logger=self._logger, filename='metrics.log')
-
     def gauge(self, name, value):
         """Record an absolute reading for C{name} with C{value}."""
         self._write('gauge', name, value)
@@ -76,7 +72,7 @@
     def _write(self, kind, name, value):
         record = "%s.%s %s=%s" % (self._namespace, name, kind, value)
         with self._lock:
-            self._logger.info(record)
+            logger.info(record)
 
 
 def _build_namespace(namespace):

=== modified file 'magicicada/metrics/tests/test_base.py'
--- magicicada/metrics/tests/test_base.py	2016-05-31 03:44:10 +0000
+++ magicicada/metrics/tests/test_base.py	2016-08-23 00:49:23 +0000
@@ -24,10 +24,10 @@
 
 import metrics
 
-from ubuntuone.devtools.handlers import MementoHandler
-
-
-class FileBasedMeterTestCase(unittest.TestCase):
+from magicicada.testing.testcase import BaseTestCase
+
+
+class FileBasedMeterTestCase(BaseTestCase):
     """Test the file based meter."""
 
     def setUp(self):
@@ -35,74 +35,56 @@
         self.meter = metrics.FileBasedMeter("test_namespace")
 
         # configure the memento handler to do the testings
-        self.handler = MementoHandler()
-        self.handler.level = logging.INFO
-        self.handler.debug = True
-        self.meter._logger.addHandler(self.handler)
-        self.addCleanup(self.meter._logger.removeHandler, self.handler)
+        self.handler = self.add_memento_handler(
+            metrics.logger, level=logging.INFO)
 
     def test_gauge(self):
         self.meter.gauge("name", "value")
-        self.assertTrue(self.handler.check_info(
-            "test_namespace.name", "gauge=value"))
+        self.handler.assert_info("test_namespace.name", "gauge=value")
 
     def test_increment_first(self):
         self.meter.increment("name")
-        self.assertTrue(self.handler.check_info(
-            "test_namespace.name", "counter=1"))
+        self.handler.assert_info("test_namespace.name", "counter=1")
 
     def test_increment_several(self):
         self.meter.increment("name")
-        self.assertTrue(self.handler.check_info(
-            "test_namespace.name", "counter=1"))
+        self.handler.assert_info("test_namespace.name", "counter=1")
         self.meter.increment("name")
-        self.assertTrue(self.handler.check_info(
-            "test_namespace.name", "counter=2"))
+        self.handler.assert_info("test_namespace.name", "counter=2")
         self.meter.increment("name", 5)
-        self.assertTrue(self.handler.check_info(
-            "test_namespace.name", "counter=7"))
+        self.handler.assert_info("test_namespace.name", "counter=7")
 
     def test_decrement_first(self):
         self.meter.decrement("name")
-        self.assertTrue(self.handler.check_info(
-            "test_namespace.name", "counter=-1"))
+        self.handler.assert_info("test_namespace.name", "counter=-1")
 
     def test_decrement_several(self):
         self.meter.decrement("name")
-        self.assertTrue(self.handler.check_info(
-            "test_namespace.name", "counter=-1"))
+        self.handler.assert_info("test_namespace.name", "counter=-1")
         self.meter.decrement("name")
-        self.assertTrue(self.handler.check_info(
-            "test_namespace.name", "counter=-2"))
+        self.handler.assert_info("test_namespace.name", "counter=-2")
         self.meter.decrement("name", 5)
-        self.assertTrue(self.handler.check_info(
-            "test_namespace.name", "counter=-7"))
+        self.handler.assert_info("test_namespace.name", "counter=-7")
 
     def test_increment_decrement_mixed(self):
         self.meter.increment("name")
-        self.assertTrue(self.handler.check_info(
-            "test_namespace.name", "counter=1"))
+        self.handler.assert_info("test_namespace.name", "counter=1")
         self.meter.decrement("name", 3)
-        self.assertTrue(self.handler.check_info(
-            "test_namespace.name", "counter=-2"))
+        self.handler.assert_info("test_namespace.name", "counter=-2")
         self.meter.increment("name")
-        self.assertTrue(self.handler.check_info(
-            "test_namespace.name", "counter=-1"))
+        self.handler.assert_info("test_namespace.name", "counter=-1")
 
     def test_timing(self):
         self.meter.timing("name", 0.55)
-        self.assertTrue(self.handler.check_info(
-            "test_namespace.name", "timing=0.55"))
+        self.handler.assert_info("test_namespace.name", "timing=0.55")
 
     def test_meter(self):
         self.meter.meter("name", 123)
-        self.assertTrue(self.handler.check_info(
-            "test_namespace.name", "meter=123"))
+        self.handler.assert_info("test_namespace.name", "meter=123")
 
     def test_report(self):
         self.meter.report("name", "whatever")
-        self.assertTrue(self.handler.check_info(
-            "test_namespace.name", "report=whatever"))
+        self.handler.assert_info("test_namespace.name", "report=whatever")
 
 
 class GetMeterTestCase(unittest.TestCase):

=== modified file 'magicicada/monitoring/reactor.py'
--- magicicada/monitoring/reactor.py	2016-06-07 20:10:40 +0000
+++ magicicada/monitoring/reactor.py	2016-08-23 00:49:23 +0000
@@ -20,6 +20,7 @@
 
 from __future__ import unicode_literals
 
+import logging
 import os
 import sys
 import time
@@ -32,11 +33,13 @@
 from magicicada.settings import TRACE
 
 
+logger = logging.getLogger(__name__)
+
+
 class ReactorInspector(threading.Thread):
     """Log message with a time delta from the last call."""
 
-    def __init__(self, logger, reactor_call, loop_time=3):
-        self.logger = logger
+    def __init__(self, reactor_call, loop_time=3):
         self.running = False
         self.stopped = False
         self.queue = Queue.Queue()
@@ -58,7 +61,7 @@
     def stop(self):
         """Stop the thread."""
         self.stopped = True
-        self.logger.info("ReactorInspector: stopped")
+        logger.info("ReactorInspector: stopped")
 
     def dump_frames(self):
         """Dump frames info to log file."""
@@ -74,12 +77,12 @@
                 title = "Dumping Python frame for reactor main thread"
             else:
                 title = "Dumping Python frame"
-            self.logger.debug("%s %s (pid: %d):\n%s",
-                              title, frame_id, os.getpid(), stack)
+            logger.debug(
+                "%s %s (pid: %d):\n%s", title, frame_id, os.getpid(), stack)
 
     def run(self):
         """Start running the thread."""
-        self.logger.info("ReactorInspector: started")
+        logger.info("ReactorInspector: started")
         msg_id = 0
         oldest_pending_request_ts = time.time()
         while not self.stopped:
@@ -94,18 +97,18 @@
                 # Oldest pending request is still out there
                 delay = time.time() - oldest_pending_request_ts
                 self.metrics.gauge("delay", delay)
-                self.logger.critical("ReactorInspector: detected unresponsive!"
-                                     " (current: %d, pid: %d) delay: %.3f",
-                                     msg_id, os.getpid(), delay)
+                logger.critical(
+                    "ReactorInspector: detected unresponsive! (current: %d, "
+                    "pid: %d) delay: %.3f", msg_id, os.getpid(), delay)
                 self.dump_frames()
             else:
                 delay = tsent - tini
                 self.metrics.gauge("delay", delay)
                 if msg_id > id_sent:
-                    self.logger.warning("ReactorInspector: late (current: %d, "
-                                        "got: %d, pid: %d, cleaning queue) "
-                                        "delay: %.3f", msg_id, id_sent,
-                                        os.getpid(), delay)
+                    logger.warning(
+                        "ReactorInspector: late (current: %d, got: %d, pid: "
+                        "%d, cleaning queue) delay: %.3f",
+                        msg_id, id_sent, os.getpid(), delay)
                     while not self.queue.empty():
                         self.queue.get_nowait()
                     # About to start a new request with nothing pending
@@ -115,8 +118,9 @@
                     # About to start a new request with nothing pending
                     self.last_responsive_ts = time.time()
                     oldest_pending_request_ts = self.last_responsive_ts
-                    self.logger.log(TRACE, "ReactorInspector: ok (msg: %d, "
-                                    "pid: %d) delay: %.3f",
-                                    msg_id, os.getpid(), delay)
+                    logger.log(
+                        TRACE,
+                        "ReactorInspector: ok (msg: %d, pid: %d) delay: %.3f",
+                        msg_id, os.getpid(), delay)
             finally:
                 msg_id += 1

=== modified file 'magicicada/monitoring/tests/test_reactor.py'
--- magicicada/monitoring/tests/test_reactor.py	2016-06-07 21:47:46 +0000
+++ magicicada/monitoring/tests/test_reactor.py	2016-08-23 00:49:23 +0000
@@ -21,7 +21,6 @@
 from __future__ import unicode_literals
 
 import time
-import logging
 import threading
 
 from twisted.trial.unittest import TestCase as TwistedTestCase
@@ -29,7 +28,7 @@
 
 import metrics
 
-from magicicada.monitoring.reactor import ReactorInspector
+from magicicada.monitoring.reactor import ReactorInspector, logger
 from magicicada.settings import TRACE
 from magicicada.testing.testcase import BaseTestCase
 
@@ -70,13 +69,12 @@
                 """Record call to gauge()."""
                 self.calls.append(("gauge", name, val))
 
-        logger = logging.getLogger("storage.server")
         self.handler = self.add_memento_handler(logger, level=TRACE)
 
         self.helper = Helper()
         self.fake_metrics = FakeMetrics()
         self.patch(metrics, 'get_meter', lambda n: self.fake_metrics)
-        self.ri = ReactorInspector(logger, self.helper.call, loop_time=.1)
+        self.ri = ReactorInspector(self.helper.call, loop_time=.1)
         self.helper.ri = self.ri
 
     def run_ri(self, call_count=None, join=True):
@@ -175,7 +173,7 @@
         """Reactor resurrects after some loops."""
         self.run_ri(3)
         late_line = self.handler.assert_warning(
-                "ReactorInspector: late", "got: 0")
+            "ReactorInspector: late", "got: 0")
         self.assertTrue(late_line)
         self.assertTrue(late_line.args[-1] >= .2)  # At least 2 cycles of delay
         # Check the metrics

=== modified file 'magicicada/server/auth.py'
--- magicicada/server/auth.py	2016-05-29 20:58:45 +0000
+++ magicicada/server/auth.py	2016-08-23 00:49:23 +0000
@@ -26,7 +26,7 @@
 from magicicada.rpcdb import backend
 
 
-logger = logging.getLogger("storage.server")
+logger = logging.getLogger(__name__)
 
 
 class AuthenticationProvider(object):

=== modified file 'magicicada/server/content.py'
--- magicicada/server/content.py	2016-06-03 20:57:04 +0000
+++ magicicada/server/content.py	2016-08-23 00:49:23 +0000
@@ -40,6 +40,7 @@
 from magicicada.server import errors, upload
 
 ZERO_LENGTH_CONTENT_KEY = ""
+logger = logging.getLogger(__name__)
 
 
 class FalseProducer(object):
@@ -106,7 +107,6 @@
 
         self.last_modified = calendar.timegm(last_modif.timetuple())
         self.node = node
-        self.logger = logging.getLogger('storage.server')
 
     def get_content(self, start=None, previous_hash=None, user=None):
         """Get the content for this node.
@@ -143,7 +143,7 @@
     def _handle_errors(self, failure, user):
         """Transform storage backend errors into something more appropiate."""
         ctx = self._context_msg(user)
-        self.logger.warning("%s - storage backend error: %s", ctx, failure)
+        logger.warning("%s - storage backend error: %s", ctx, failure)
         raise errors.NotAvailable(failure.getErrorMessage())
 
 
@@ -264,7 +264,6 @@
         self._initial_data = True
         self.storage_key = None
         self.canceling = False
-        self.logger = logging.getLogger('storage.server')
 
         self.original_file_hash = node_hash
         self.hash_hint = hash_hint
@@ -393,8 +392,8 @@
                            'sent=%(bytes_sent)s')
             return context_msg % upload_context
 
-        self.logger.warning("%s - storage backend error: %s",
-                            context_msg(), failure)
+        logger.warning(
+            "%s - storage backend error: %s", context_msg(), failure)
         if failure.check(errors.UploadCorrupt):
             return failure
         raise errors.TryAgain(failure.value)
@@ -408,8 +407,8 @@
             try:
                 yield self.uploadjob.delete()
             except Exception as exc:
-                self.logger.warning("%s(%s): while deleting uploadjob",
-                                    exc.__class__.__name__, exc)
+                logger.exception(
+                    "%s while deleting uploadjob:", exc.__class__.__name__)
         defer.returnValue(new_gen)
 
     @defer.inlineCallbacks

=== modified file 'magicicada/server/integtests/test_server_scan.py'
--- magicicada/server/integtests/test_server_scan.py	2016-06-04 19:08:28 +0000
+++ magicicada/server/integtests/test_server_scan.py	2016-08-23 00:49:23 +0000
@@ -18,7 +18,6 @@
 
 """Tests for server rescan."""
 
-import logging
 import zlib
 
 from cStringIO import StringIO
@@ -26,7 +25,6 @@
 from twisted.internet import defer
 from ubuntuone.storageprotocol import request
 from ubuntuone.storageprotocol.content_hash import content_hash_factory, crc32
-from ubuntuone.devtools.handlers import MementoHandler
 
 from magicicada.server.integtests.test_sync import TestServerBase
 from magicicada.server.testing.aq_helpers import NO_CONTENT_HASH
@@ -42,9 +40,6 @@
         yield super(TestServerScan, self).setUp()
         yield self.get_client()
         yield self.do_create_lots_of_files('_pre')
-        self.handler = handler = MementoHandler()
-        handler.setLevel(logging.DEBUG)
-        logging.getLogger('fsyncsrvr.SyncDaemon').addHandler(handler)
 
     @defer.inlineCallbacks
     def do_create_lots_of_files(self, suffix=''):

=== modified file 'magicicada/server/integtests/test_sync.py'
--- magicicada/server/integtests/test_sync.py	2016-06-03 20:57:04 +0000
+++ magicicada/server/integtests/test_sync.py	2016-08-23 00:49:23 +0000
@@ -58,24 +58,12 @@
     FakeGetContent,
 )
 from magicicada.server.testing.caps_helpers import required_caps
+from magicicada.server.testing.testcase import logger
 
 U1SYNC_QUIET = True
 NO_CONTENT_HASH = ""
 
 
-class ErrorHandler(logging.Handler):
-    """A Log Handler to detect exceptions."""
-    def __init__(self):
-        """create it"""
-        logging.Handler.__init__(self)
-        self.errors = []
-
-    def emit(self, record):
-        """Add the record."""
-        if record.levelno >= logging.ERROR:
-            self.errors.append(record)
-
-
 def deferToThread(func, *args, **kwargs):
     """glib reactor doesnt have this."""
     d = defer.Deferred()
@@ -147,14 +135,7 @@
         self.eq.push('SYS_NET_CONNECTED')
         yield d
 
-        self.error_handler = ErrorHandler()
-        logger = logging.getLogger("fsyncsrvr.SyncDaemon.sync")
-        logger.addHandler(self.error_handler)
-        self.addCleanup(logger.removeHandler, self.error_handler)
-
-        logger = logging.getLogger("twisted")
-        logger.addHandler(self.error_handler)
-        self.addCleanup(logger.removeHandler, self.error_handler)
+        self.handler = self.add_memento_handler(logger, level=logging.ERROR)
 
     def _wait_for_dead_nirvana(self):
         """Wait until it's disconnected."""
@@ -182,15 +163,13 @@
         if timer is not None and timer.active():
             timer.cancel()
 
-        try:
-            yield super(TestSync, self).tearDown()
-            yield self._wait_for_dead_nirvana()
-        finally:
-            # make sure no errors were reported
-            if self.error_handler.errors:
-                errs = "\n".join(e.getMessage()
-                                 for e in self.error_handler.errors)
-                raise Exception("Test ended with errors: \n" + errs)
+        yield super(TestSync, self).tearDown()
+        yield self._wait_for_dead_nirvana()
+
+        # make sure no errors were reported
+        if self.handler.records:
+            errs = "\n".join(e.getMessage() for e in self.handler.records)
+            raise Exception("Test ended with errors: \n" + errs)
 
     def compare_dirs(self):
         "run rsync to compare directories, needs some work"
@@ -2024,7 +2003,7 @@
         # Sync will raise an exception, because commit_file is leaving the
         # node in a different state of what the spreadsheet indicated.
         # As this is ok, we're cleaning the error here
-        self.error_handler.errors = []
+        self.handler.reset()
 
         # Now, let LR fix the node, and SD to download it again
         yield self.main.lr.scan_dir("mdid", self.root_dir)

=== removed file 'magicicada/server/logger.py'
--- magicicada/server/logger.py	2016-03-08 00:32:28 +0000
+++ magicicada/server/logger.py	1970-01-01 00:00:00 +0000
@@ -1,204 +0,0 @@
-# Copyright 2008-2015 Canonical
-# Copyright 2015 Chicharreros (https://launchpad.net/~chicharreros)
-#
-# This program is free software: you can redistribute it and/or modify
-# it under the terms of the GNU Affero General Public License as
-# published by the Free Software Foundation, either version 3 of the
-# License, or (at your option) any later version.
-#
-# This program is distributed in the hope that it will be useful,
-# but WITHOUT ANY WARRANTY; without even the implied warranty of
-# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
-# GNU Affero General Public License for more details.
-#
-# You should have received a copy of the GNU Affero General Public License
-# along with this program. If not, see <http://www.gnu.org/licenses/>.
-#
-# For further info, check  http://launchpad.net/magicicada-server
-
-"""Logging utilities."""
-
-from __future__ import absolute_import
-
-import os
-import platform
-import sys
-import time
-import signal
-import socket
-import logging
-
-from functools import partial
-from logging.handlers import TimedRotatingFileHandler, WatchedFileHandler
-
-from django.conf import settings
-from twisted.python import log
-
-
-# define the TRACE level
-TRACE = 5
-logging.addLevelName(TRACE, "TRACE")
-
-
-class SignalAwareFileHandler(WatchedFileHandler):
-    """Close and reopen the stream when signal SIGUSR1 isreceived."""
-
-    def __init__(self, *args, **kwargs):
-        WatchedFileHandler.__init__(self, *args, **kwargs)
-
-        def reopenLog(signal, frame):
-            """the signal handler"""
-            self.reopen_stream()
-        signal.signal(signal.SIGUSR1, reopenLog)
-
-    def reopen_stream(self):
-        """close and open the stream"""
-        if self.stream:
-            self.stream.close()
-        self.stream = self._open()
-
-
-# rotate at midnight
-MidnightRotatingFileHandler = partial(TimedRotatingFileHandler,
-                                      when='midnight')
-
-
-class SysLogHandler(logging.handlers.SysLogHandler):
-
-    def emit(self, record):
-        """
-        Emit a record.
-
-        The record is formatted, and then sent to the syslog server. If the
-        message contains multiple lines, it's split over multiple records.
-        """
-        prio = '<%d>' % self.encodePriority(self.facility,
-                                            self.mapPriority(record.levelname))
-        msg = self.format(record)
-
-        # Message is a string. Convert to bytes as required by RFC 5424
-        if type(msg) is unicode:
-            msg = msg.encode('utf-8')
-
-        # Break the message up into lines and send them.
-        lines = msg.strip().split('\n')
-
-        firstLine = True
-        fmt = self.formatter._fmt
-        data = record.__dict__.copy()
-        for line in lines:
-            if firstLine:
-                firstLine = False
-            else:
-                # Each additional line must be formatted again since only the
-                # first line is formated by format() above.
-                data["message"] = "\t" + line
-                line = fmt % data
-
-            line = prio + line + "\000"
-
-            # Copied from logging/handlers.py in Python stdlib.
-            try:
-                if self.unixsocket:
-                    try:
-                        self.socket.send(line)
-                    except socket.error:
-                        self._connect_unixsocket(self.address)
-                        self.socket.send(line)
-                elif getattr(self, "socktype",
-                             socket.SOCK_DGRAM) == socket.SOCK_DGRAM:
-                    self.socket.sendto(line, self.address)
-                else:
-                    self.socket.sendall(line)
-            except (KeyboardInterrupt, SystemExit):
-                raise
-            except:
-                self.handleError(record)
-
-
-def configure_handler(folder=None, filename=None,
-                      log_format=None, logger_class=None,
-                      log_to_syslog=None, syslog_name=None):
-    """Configure a logging handler."""
-    if folder is None:
-        folder = settings.LOG_FOLDER
-    if log_format is None:
-        log_format = settings.LOG_FORMAT
-    if logger_class is None:
-        logger_class = SignalAwareFileHandler
-    if log_to_syslog is None:
-        log_to_syslog = settings.LOG_TO_SYSLOG
-    if syslog_name is None:
-        syslog_name = settings.APP_NAME
-
-    datefmt = None
-    if log_to_syslog:
-        datefmt = "%Y-%m-%dT%H:%M:%S"
-        log_format = " ".join(["%(asctime)s.%(msecs)03dZ", platform.node(),
-                               syslog_name, settings.SYSLOG_FORMAT])
-        handler = SysLogHandler()
-    else:
-        if filename is not None:
-            if not os.path.isabs(filename):
-                filename = os.path.join(folder, os.path.basename(filename))
-            else:
-                folder = os.path.dirname(filename)
-            if not os.access(folder, os.F_OK):
-                os.makedirs(folder)
-            handler = logger_class(filename)
-        else:
-            handler = logging.StreamHandler(sys.stderr)
-
-    handler.setLevel(TRACE)
-    log_formatter = logging.Formatter(log_format, datefmt=datefmt)
-    log_formatter.converter = time.gmtime
-    handler.setFormatter(log_formatter)
-    return handler
-
-
-def configure_logger(name=None, logger=None, filename=None, folder=None,
-                     level=None, log_format=None, start_observer=False,
-                     propagate=True, logger_class=None, syslog_name=None,
-                     log_to_syslog=None):
-    """Configure the logger."""
-    if level is None:
-        level = settings.LOG_LEVEL
-    if syslog_name is None:
-        syslog_name = name
-
-    if logger is None and name is None:
-        raise ValueError("Must provide one of 'name' or 'logger'")
-
-    if logger is None:
-        logger = logging.getLogger(name)
-    elif name is None:
-        name = logger.name
-
-    # remove StreamHandler from the root logger.
-    root_logger = logging.getLogger()
-    for hdlr in root_logger.handlers:
-        if isinstance(hdlr, logging.StreamHandler):
-            root_logger.removeHandler(hdlr)
-
-    logger.propagate = propagate
-    logger.setLevel(level)
-    handler = configure_handler(folder=folder, filename=filename,
-                                log_format=log_format,
-                                logger_class=logger_class,
-                                syslog_name=syslog_name,
-                                log_to_syslog=log_to_syslog)
-    logger.addHandler(handler)
-
-    if start_observer:
-        log_observer = log.PythonLoggingObserver(
-            name == 'root' and 'twisted' or name + '.twisted')
-        log_observer.start()
-
-    return handler
-
-
-def setup_logging(name, logger=None, start_observer=False):
-    """Setting up logging."""
-    cfg = getattr(settings, name)
-    return configure_logger(name, logger=logger, filename=cfg.log_filename,
-                            propagate=False, start_observer=start_observer)

=== modified file 'magicicada/server/server.py'
--- magicicada/server/server.py	2016-06-07 21:47:46 +0000
+++ magicicada/server/server.py	2016-08-23 00:49:23 +0000
@@ -34,7 +34,7 @@
 import uuid
 import weakref
 
-from functools import wraps
+from functools import partial, wraps
 
 import psycopg2
 import twisted
@@ -62,7 +62,6 @@
 from magicicada.rpcdb import inthread
 from magicicada.server import auth, content, errors, stats
 from magicicada.server.diskstorage import DiskStorage
-from magicicada.server.logger import configure_logger
 
 try:
     from versioninfo import version_info
@@ -90,23 +89,7 @@
 }
 
 MAX_OOPS_LINE = 300
-
-
-def loglevel(lvl):
-    """Make a function that logs at lvl log level."""
-    def level_log(self, message, *args, **kwargs):
-        """inner."""
-        self.log(lvl, message, *args, **kwargs)
-    return level_log
-
-
-def trace_message(function):
-    """A decorator to trace incoming messages."""
-    def decorator(self, message):
-        """inner."""
-        self.log.trace_message('IN: ', message)
-        function(self, message)
-    return decorator
+logger = logging.getLogger(__name__)
 
 
 def _prettify_traceback(report, context):
@@ -149,14 +132,18 @@
     def __init__(self, protocol):
         """Create the logger."""
         self.protocol = protocol
+        self.critical = partial(self.log, logging.CRITICAL)
+        self.error = partial(self.log, logging.ERROR)
+        self.warning = partial(self.log, logging.WARNING)
+        self.info = partial(self.log, logging.INFO)
+        self.debug = partial(self.log, logging.DEBUG)
+        self.trace = partial(self.log, settings.TRACE)
 
     def log(self, lvl, message, *args, **kwargs):
-        """Log."""
-        if self.protocol.logger.isEnabledFor(lvl):
-            self._log(lvl, message, *args, **kwargs)
+        """Log if gloabl logger is enabled for 'lvl'."""
+        if not logger.isEnabledFor(lvl):
+            return
 
-    def _log(self, lvl, message, *args, **kwargs):
-        """Actually do the real log"""
         msg_format = '%(uuid)s %(remote)s %(userid)s %(message)s'
         extra = {'message': message}
         if self.protocol.user is not None:
@@ -175,21 +162,14 @@
         extra['uuid'] = self.protocol.session_id
 
         message = msg_format % extra
-        self.protocol.logger.log(lvl, message, *args, **kwargs)
+        logger.log(lvl, message, *args, **kwargs)
 
     def trace_message(self, text, message):
         """Log a message with some pre processing."""
-        if self.protocol.logger.isEnabledFor(settings.TRACE):
+        if logger.isEnabledFor(settings.TRACE):
             if message.type != protocol_pb2.Message.BYTES:
                 self.trace(text + (str(message).replace('\n', ' ')))
 
-    critical = loglevel(logging.CRITICAL)
-    error = loglevel(logging.ERROR)
-    warning = loglevel(logging.WARNING)
-    info = loglevel(logging.INFO)
-    debug = loglevel(logging.DEBUG)
-    trace = loglevel(settings.TRACE)
-
 
 class StorageServerLogger(StorageLogger):
     """Logger for the server."""
@@ -312,13 +292,12 @@
     PING_TIMEOUT = 480
     PING_INTERVAL = 120
 
-    def __init__(self):
+    def __init__(self, session_id=None):
         """Create a network server. The factory does this."""
         request.RequestHandler.__init__(self)
         self.user = None
         self.factory = None
-        self.session_id = uuid.uuid4()
-        self.logger = logging.getLogger(settings.api_server.LOGGER_NAME)
+        self.session_id = session_id or uuid.uuid4()
         self.log = StorageServerLogger(self)
         self.shutting_down = False
         self.request_locked = False
@@ -338,10 +317,6 @@
     def set_user(self, user):
         """Set user and adjust values that depend on which user it is."""
         self.user = user
-        if user.username in self.factory.trace_users:
-            # set up the logger to use the hackers' one
-            hackers_logger = settings.api_server.LOGGER_NAME + '.hackers'
-            self.logger = logging.getLogger(hackers_logger)
 
     def poison(self, tag):
         """Inject a failure in the server. Works with check_poison."""
@@ -1410,27 +1385,26 @@
     def __init__(self, bytes_producer, request):
         self.producer = bytes_producer
         self.request = request
-        self.logger = request.log
         bytes_producer.startProducing(self)
 
     def resumeProducing(self):
         """IPushProducer interface."""
-        self.logger.trace('BytesMessageProducer resumed, http producer: %s',
-                          self.producer)
+        logger.trace(
+            'BytesMessageProducer resumed, http producer: %s', self.producer)
         if self.producer:
             self.producer.resumeProducing()
 
     def stopProducing(self):
         """IPushProducer interface."""
-        self.logger.trace('BytesMessageProducer stopped, http producer: %s',
-                          self.producer)
+        logger.trace(
+            'BytesMessageProducer stopped, http producer: %s', self.producer)
         if self.producer:
             self.producer.stopProducing()
 
     def pauseProducing(self):
         """IPushProducer interface."""
-        self.logger.trace('BytesMessageProducer paused, http producer: %s',
-                          self.producer)
+        logger.trace(
+            'BytesMessageProducer paused, http producer: %s', self.producer)
         if self.producer:
             self.producer.pauseProducing()
 
@@ -1728,9 +1702,10 @@
         except:
             yield self.internal_error(Failure())
 
-    @trace_message
     def _processMessage(self, message):
         """Receive the content for the upload."""
+        self.log.trace_message('IN: ', message)
+
         if self.state == self.states.uploading:
             try:
                 self._process_while_uploading(message)
@@ -2368,7 +2343,6 @@
         self.auth_provider = auth_provider_class(self)
         self.content = content_class(self)
         self.diskstorage = DiskStorage(settings.api_server.STORAGE_BASEDIR)
-        self.logger = logging.getLogger('storage.server')
 
         self.metrics = metrics.get_meter('root')
         self.user_metrics = metrics.get_meter('user')
@@ -2426,7 +2400,7 @@
             msg = failure.getTraceback()
 
         # log
-        self.logger.error('Unhandled error in deferred! %s', msg)
+        logger.error('Unhandled error in deferred! %s', msg)
 
     def build_notification_oops(self, failure, notif, tl=None):
         """Create an oops entry to log the notification failure."""
@@ -2455,9 +2429,10 @@
                 action.finish()
 
                 oops = self.build_notification_oops(failure, notif, tl)
-                oops_id = self.oops_config.publish(oops)
-                self.logger.error(' %s in notification %r logged in OOPS: %s',
-                                  failure.value, notif, oops_id)
+                self.oops_config.publish(oops)
+                logger.error(
+                    '%s in notification %r while calling %s(**%r)',
+                    failure.value, notif, func.__name__, kwargs)
 
             d = defer.maybeDeferred(func, notif, **kwargs)
             d.addErrback(notification_error_handler)
@@ -2682,10 +2657,9 @@
             heartbeat_interval = float(settings.api_server.HEARTBEAT_INTERVAL)
         self.heartbeat_interval = heartbeat_interval
         self.rpc_dal = None
-        self.logger = logging.getLogger('storage.server')
         self.servername = settings.api_server.SERVERNAME
-        self.logger.info('Starting %s', self.servername)
-        self.logger.info(
+        logger.info('Starting %s', self.servername)
+        logger.info(
             'protocol buffers implementation: %s',
             os.environ.get('PROTOCOL_BUFFERS_PYTHON_IMPLEMENTATION', 'None'))
 
@@ -2695,8 +2669,7 @@
         listeners.setName('Listeners')
         listeners.setServiceParent(self)
 
-        self._reactor_inspector = ReactorInspector(self.logger,
-                                                   reactor.callFromThread)
+        self._reactor_inspector = ReactorInspector(reactor.callFromThread)
 
         self.factory = StorageServerFactory(
             auth_provider_class=auth_provider_class,
@@ -2723,13 +2696,13 @@
 
     def start_rpc_dal(self):
         """Setup the rpc client."""
-        self.logger.info('Starting the RPC clients.')
+        logger.info('Starting the RPC clients.')
         self.rpc_dal = inthread.ThreadedNonRPC()
 
     @inlineCallbacks
     def startService(self):
         """Start listening on two ports."""
-        self.logger.info('- - - - - SERVER STARTING')
+        logger.info('- - - - - SERVER STARTING')
         yield OrderedMultiService.startService(self)
         yield defer.maybeDeferred(self.start_rpc_dal)
         self.factory.content.rpc_dal = self.rpc_dal
@@ -2743,12 +2716,12 @@
         if self.heartbeat_interval > 0:
             self.heartbeat_writer = stdio.StandardIO(
                 supervisor_utils.HeartbeatWriter(self.heartbeat_interval,
-                                                 self.logger))
+                                                 logger))
 
     @inlineCallbacks
     def stopService(self):
         """Stop listening on both ports."""
-        self.logger.info('- - - - - SERVER STOPPING')
+        logger.info('- - - - - SERVER STOPPING')
         yield OrderedMultiService.stopService(self)
         yield self.factory.wait_for_shutdown()
         self.metrics.meter('server_stop')
@@ -2757,26 +2730,13 @@
         if self.heartbeat_writer:
             self.heartbeat_writer.loseConnection()
             self.heartbeat_writer = None
-        self.logger.info('- - - - - SERVER STOPPED')
+        logger.info('- - - - - SERVER STOPPED')
 
 
 def create_service(status_port=None,
                    auth_provider_class=auth.DummyAuthProvider,
                    oops_config=None):
     """Start the StorageServer service."""
-
-    # configure logs
-    logger = logging.getLogger(settings.api_server.LOGGER_NAME)
-    handler = configure_logger(logger=logger, propagate=False,
-                               filename=settings.api_server.LOG_FILENAME,
-                               start_observer=True)
-
-    # set up the hacker's logger always in TRACE
-    h_logger = logging.getLogger(settings.api_server.LOGGER_NAME + '.hackers')
-    h_logger.setLevel(settings.TRACE)
-    h_logger.propagate = False
-    h_logger.addHandler(handler)
-
     # turn on heapy if must to
     if os.getenv('USE_HEAPY'):
         logger.debug('importing heapy')

=== modified file 'magicicada/server/ssl_proxy.py'
--- magicicada/server/ssl_proxy.py	2016-06-03 00:35:53 +0000
+++ magicicada/server/ssl_proxy.py	2016-08-23 00:49:23 +0000
@@ -34,12 +34,12 @@
 import metrics
 
 from magicicada import settings
-from magicicada.server.logger import configure_logger
 from magicicada.server.server import get_service_port
 from magicicada.server.ssl import disable_ssl_compression
 from ubuntuone.supervisor import utils as supervisor_utils
 
-logger = logging.getLogger('ssl_proxy')
+
+logger = logging.getLogger(__name__)
 
 
 def get_transport_info(t):
@@ -283,8 +283,6 @@
 
 def create_service():
     """Create the service instance."""
-    configure_logger(logger=logger, filename=settings.ssl_proxy.LOG_FILENAME,
-                     level=logging.DEBUG, propagate=False, start_observer=True)
     server_key = settings.api_server.KEY
     server_crt = settings.api_server.CRT
     server_crt_chain = settings.api_server.CRT_CHAIN

=== modified file 'magicicada/server/stats.py'
--- magicicada/server/stats.py	2016-06-03 00:35:53 +0000
+++ magicicada/server/stats.py	2016-08-23 00:49:23 +0000
@@ -31,9 +31,7 @@
 
 from magicicada.monitoring import dump
 
-
-logger = logging.getLogger("storage.server.stat")
-status_log = logging.getLogger("storage.server.status")
+logger = logging.getLogger(__name__)
 
 
 def report_reactor_stats(prefix="reactor"):
@@ -65,8 +63,6 @@
 class StatsWorker(object):
     """Execute actions and log the results at the specified interval."""
 
-    logger = logger
-
     def __init__(self, service, interval, servername=None):
         self.service = service
         if servername is None:
@@ -84,7 +80,7 @@
 
     def log(self, msg, *args, **kwargs):
         """Wrap logger.info call to simplify testing."""
-        self.logger.info(msg, *args, **kwargs)
+        logger.info(msg, *args, **kwargs)
 
     def start(self):
         """Start rolling."""
@@ -139,8 +135,8 @@
 
         def on_error(failure):
             """Error callback"""
-            status_log.error("Error while getting status. %s",
-                             failure.getTraceback())
+            logger.error(
+                "Error while getting status. %s", failure.getTraceback())
             request.setResponseCode(500)
             request.write(failure.getErrorMessage() + "\n")
             request.finish()

=== modified file 'magicicada/server/testing/aq_helpers.py'
--- magicicada/server/testing/aq_helpers.py	2016-06-07 21:47:46 +0000
+++ magicicada/server/testing/aq_helpers.py	2016-08-23 00:49:23 +0000
@@ -39,7 +39,12 @@
 from ubuntuone.storageprotocol import request, sharersp, client
 from ubuntuone.storageprotocol.content_hash import content_hash_factory, crc32
 from ubuntuone.syncdaemon.action_queue import ActionQueue, ActionQueueCommand
-from ubuntuone.syncdaemon import main, volume_manager, tritcask, logger
+from ubuntuone.syncdaemon import (
+    main,
+    volume_manager,
+    tritcask,
+    logger as syncdaemon_logger,
+)
 from ubuntuone.syncdaemon.event_queue import EventQueue
 from ubuntuone.syncdaemon.filesystem_manager import FileSystemManager
 from ubuntuone.syncdaemon.sync import Sync
@@ -57,7 +62,7 @@
               os.path.join(SD_CONFIG_DIR, 'syncdaemon-dev.conf')]
 
 _marker = object()
-
+logger = logging.getLogger(__name__)
 NO_CONTENT_HASH = ""
 
 
@@ -171,7 +176,7 @@
         self.hash_q = type('fake hash queue', (),
                            {'empty': staticmethod(lambda: True),
                             '__len__': staticmethod(lambda: 0)})()
-        self.logger = logging.getLogger('fsyncsrvr.SyncDaemon.Main')
+        self.logger = logger
         self.db = tritcask.Tritcask(self.tritcask_dir)
         self.vm = DumbVolumeManager(self)
         self.fs = FileSystemManager(self.fsmdir, self.partials_dir, self.vm,
@@ -362,8 +367,8 @@
 
         # logging can not be configured dinamically, touch the general logger
         # to get one big file and be able to get the logs if failure
-        logger.init()
-        logger.set_max_bytes(0)
+        syncdaemon_logger.init()
+        syncdaemon_logger.set_max_bytes(0)
         yield self.client_setup()
 
     @property

=== modified file 'magicicada/server/testing/testcase.py'
--- magicicada/server/testing/testcase.py	2016-06-04 19:08:28 +0000
+++ magicicada/server/testing/testcase.py	2016-08-23 00:49:23 +0000
@@ -43,7 +43,6 @@
 from magicicada import settings
 from magicicada.filesync import services
 from magicicada.server.auth import DummyAuthProvider
-from magicicada.server.logger import configure_logger
 from magicicada.server.server import (
     PREFERRED_CAP,
     StorageServerService,
@@ -51,28 +50,11 @@
 )
 from magicicada.testing.testcase import BaseTestCase
 
+logger = logging.getLogger(__name__)
 server_key = settings.api_server.KEY
 server_crt = settings.api_server.CRT
 server_crt_chain = settings.api_server.CRT_CHAIN
 
-logger = logging.getLogger("fsyncsrvr.SyncDaemon.TEST")
-
-
-def configure_logging(debug_tests=True):
-    """Configure logging for the tests."""
-    logger = logging.getLogger(settings.api_server.LOGGER_NAME)
-    if debug_tests:
-        level = settings.TRACE
-    else:
-        level = logging.INFO
-
-    configure_logger(logger=logger, filename='filesync-server-tests.log',
-                     level=level, propagate=False,
-                     logger_class=logging.FileHandler)
-
-# configure logging
-configure_logging()
-
 
 class FakeTimestampChecker(object):
     """Fake timestamp checker."""

=== modified file 'magicicada/server/tests/test_auth.py'
--- magicicada/server/tests/test_auth.py	2016-06-03 00:35:53 +0000
+++ magicicada/server/tests/test_auth.py	2016-08-23 00:49:23 +0000
@@ -21,8 +21,6 @@
 import logging
 
 from twisted.internet import defer
-
-from ubuntuone.devtools.handlers import MementoHandler
 from ubuntuone.storageprotocol import errors as protocol_errors, request
 
 from magicicada.filesync.errors import DoesNotExist
@@ -30,7 +28,9 @@
 from magicicada.server.auth import (
     DummyAuthProvider,
     SimpleAuthProvider,
+    logger as auth_logger,
 )
+from magicicada.server.server import logger as server_logger
 from magicicada.server.testing.testcase import TestWithDatabase
 
 
@@ -130,32 +130,27 @@
         yield super(ClientDummyAuthTests, self).setUp()
         self.creds = 'open sesame'
         self.bad_creds = 'not my secret'
-        self.handler = MementoHandler()
-        logger = logging.getLogger('storage.server')
-        logger.addHandler(self.handler)
-        self.addCleanup(logger.removeHandler, self.handler)
-        self.handler.setLevel(logging.DEBUG)
-
-    def assert_auth_ok_logging(self):
-        self.assertTrue(self.handler.check_debug(
-            "authenticated user", "OK", self.usr0.username))
-        self.assertFalse(self.handler.check_warning("missing user"))
-
-    def assert_auth_ok_missing_user(self):
-        self.assertTrue(self.handler.check_debug(
-                        "missing user", "(id=%s)" % self.usr0.id))
-        self.assertFalse(self.handler.check_info("authenticated user"))
+
+    def assert_auth_ok_logging(self, handler):
+        handler.assert_debug("authenticated user", "OK", self.usr0.username)
+        handler.assert_not_logged("missing user")
+
+    def assert_auth_ok_missing_user(self, handler):
+        handler.assert_debug("missing user", "(id=%s)" % self.usr0.id)
+        handler.assert_not_logged("authenticated user")
 
     @defer.inlineCallbacks
     def test_auth_ok_user_ok(self):
         """Correct authentication must succeed."""
+        handler = self.add_memento_handler(auth_logger, level=logging.DEBUG)
         yield self.callback_test(
             self.do_auth, credentials=self.creds, add_default_callbacks=True)
-        self.assert_auth_ok_logging()
+        self.assert_auth_ok_logging(handler)
 
     @defer.inlineCallbacks
     def test_auth_ok_bad_user(self):
         """Non existing user must fail authentication."""
+        handler = self.add_memento_handler(auth_logger, level=logging.DEBUG)
         # make the user getter fail
         self.patch(self.service.factory.content, 'get_user_by_id',
                    lambda *a, **k: defer.fail(DoesNotExist()))
@@ -164,7 +159,7 @@
             self.do_auth, credentials=self.creds, add_default_callbacks=True)
         yield self.assertFailure(d, protocol_errors.AuthenticationFailedError)
 
-        self.assert_auth_ok_missing_user()
+        self.assert_auth_ok_missing_user(handler)
 
     @defer.inlineCallbacks
     def test_auth_ok_with_session_id(self):
@@ -180,14 +175,13 @@
         """Correct authentication must succeed and include metadata."""
         m_called = []
         self.service.factory.metrics.meter = lambda *a: m_called.append(a)
-
+        handler = self.add_memento_handler(server_logger, level=logging.DEBUG)
         metadata = {u"platform": u"linux2", u"version": u"1.0", u"foo": u"bar"}
         yield self.callback_test(
             self.do_auth, credentials=self.creds, metadata=metadata,
             add_default_callbacks=True)
 
-        self.assertTrue(
-            self.handler.check_info("Client metadata: %s" % metadata))
+        handler.assert_info("Client metadata: %s" % metadata)
         self.assertIn(("client.platform.linux2", 1), m_called)
         self.assertIn(("client.version.1_0", 1), m_called)
         self.assertNotIn(("client.foo.bar", 1), m_called)
@@ -270,17 +264,14 @@
             "password": 'invalid',
         }
 
-    def assert_auth_ok_logging(self):
-        self.assertTrue(self.handler.check_info(
+    def assert_auth_ok_logging(self, handler):
+        handler.assert_info(
             "authenticated user", "OK", self.usr0.username,
-            "(id=%s)" % self.usr0.id))
-        self.assertTrue(self.handler.check_info(
-            "valid tokens", "(id=%s)" % self.usr0.id))
-        self.assertFalse(self.handler.check_warning("missing user"))
+            "(id=%s)" % self.usr0.id)
+        handler.assert_info("valid tokens", "(id=%s)" % self.usr0.id)
+        handler.assert_not_logged("missing user")
 
-    def assert_auth_ok_missing_user(self):
-        self.assertTrue(self.handler.check_info(
-                        "valid tokens", "(id=%s)" % self.usr0.id))
-        self.assertTrue(self.handler.check_warning(
-                        "missing user", "(id=%s)" % self.usr0.id))
-        self.assertFalse(self.handler.check_info("authenticated user"))
+    def assert_auth_ok_missing_user(self, handler):
+        handler.assert_info("valid tokens", "(id=%s)" % self.usr0.id)
+        handler.assert_warning("missing user", "(id=%s)" % self.usr0.id)
+        handler.assert_not_logged("authenticated user")

=== modified file 'magicicada/server/tests/test_basic.py'
--- magicicada/server/tests/test_basic.py	2016-06-03 00:35:53 +0000
+++ magicicada/server/tests/test_basic.py	2016-08-23 00:49:23 +0000
@@ -32,14 +32,14 @@
 from twisted.internet import reactor, defer
 from twisted.internet.error import ConnectionDone
 from twisted.web import client, error
+from ubuntuone.storageprotocol import request
+from ubuntuone.supervisor import utils as supervisor_utils
 
 import metrics
 import metrics.services
-from ubuntuone.devtools.handlers import MementoHandler
-from ubuntuone.storageprotocol import request
-from ubuntuone.supervisor import utils as supervisor_utils
 
 from magicicada.filesync.models import StorageUser
+from magicicada.server.server import logger
 from magicicada.server.testing.testcase import TestWithDatabase
 
 
@@ -63,10 +63,7 @@
         # lock the user:
         StorageUser.objects.filter(id=self.usr0.id).update(locked=True)
         # add the log handler
-        logger = logging.getLogger('storage.server')
-        hdlr = MementoHandler()
-        hdlr.setLevel(logging.INFO)
-        logger.addHandler(hdlr)
+        handler = self.add_memento_handler(logger, level=logging.INFO)
         # define a connectionLostHandler to know when the client
         # gets disconnected.
         d = defer.Deferred()
@@ -83,17 +80,14 @@
             client.dummy_authenticate("open sesame")
             yield d
             # check we logged a warning about this.
-            self.assertTrue(hdlr.check_warning(
-                "Shutting down protocol: user locked"))
+            handler.assert_warning("Shutting down protocol: user locked")
+
         return self.callback_test(dummy, add_default_callbacks=True)
 
     def test_disconnect_with_user_locked_after_auth(self):
         """Client gets disconnected if the user is locked after auth."""
         # add the log handler
-        logger = logging.getLogger('storage.server')
-        hdlr = MementoHandler()
-        hdlr.setLevel(logging.INFO)
-        logger.addHandler(hdlr)
+        handler = self.add_memento_handler(logger, level=logging.INFO)
         # define a connectionLostHandler to know when the client
         # gets disconnected.
         d = defer.Deferred()
@@ -114,8 +108,8 @@
             client.make_dir(request.ROOT, root_id, u"open sesame")
             yield d
             # check we logged a warning about this.
-            self.assertTrue(hdlr.check_warning(
-                "Shutting down protocol: user locked"))
+            handler.assert_warning("Shutting down protocol: user locked")
+
         return self.callback_test(dummy, add_default_callbacks=True)
 
     @defer.inlineCallbacks
@@ -359,32 +353,23 @@
     @defer.inlineCallbacks
     def test_disconnect_when_idle(self):
         """Test that the server disconnects idle clients."""
+        # add the log handler
+        handler = self.add_memento_handler(logger, level=logging.INFO)
+
         @defer.inlineCallbacks
         def auth(client):
 
             yield client.dummy_authenticate('open sesame')
             d = defer.Deferred()
             client.connectionLostHandler = d.callback
-            # add the log handler
-            logger = logging.getLogger('storage.server')
-            hdlr = MementoHandler()
-            hdlr.setLevel(logging.INFO)
-            logger.addHandler(hdlr)
             # patch the looping ping values
             server = self.service.factory.protocols[0]
             server.ping_loop.interval = 0.1
             server.ping_loop.idle_timeout = 0.3
             # reschedule the ping loop
             server.ping_loop.reset()
-            try:
-                yield d
-            except ConnectionDone:
-                msg = "Disconnecting - idle timeout"
-                self.assertTrue(hdlr.check_info(msg))
-            else:
-                self.fail("Should get disconnected.")
-            finally:
-                logger.removeHandler(hdlr)
+            yield self.assertFailure(d, ConnectionDone)
+            handler.assert_info("Disconnecting - idle timeout")
 
         yield self.callback_test(auth, add_default_callbacks=True)
 

=== modified file 'magicicada/server/tests/test_content.py'
--- magicicada/server/tests/test_content.py	2016-06-04 19:08:28 +0000
+++ magicicada/server/tests/test_content.py	2016-08-23 00:49:23 +0000
@@ -30,7 +30,6 @@
 from twisted.internet import defer, reactor, threads, task, address
 from twisted.trial.unittest import TestCase
 from twisted.test.proto_helpers import StringTransport
-from ubuntuone.devtools.handlers import MementoHandler
 from ubuntuone.storageprotocol import (
     request,
     client as sp_client,
@@ -46,7 +45,16 @@
 from magicicada import settings
 from magicicada.filesync import errors
 from magicicada.filesync.models import StorageObject, StorageUser
-from magicicada.server import server, content, diskstorage
+from magicicada.server import server, diskstorage
+from magicicada.server.content import (
+    BaseUploadJob,
+    BogusUploadJob,
+    DBUploadJob,
+    ContentManager,
+    UploadJob,
+    User,
+    logger,
+)
 from magicicada.server.testing.testcase import (
     BufferedConsumer,
     FactoryHelper,
@@ -478,17 +486,9 @@
     def setUp(self):
         """Set up."""
         d = super(TestPutContent, self).setUp()
-        self.handler = MementoHandler()
-        self.handler.setLevel(0)
-        self._logger = logging.getLogger('storage.server')
-        self._logger.addHandler(self.handler)
+        self.handler = self.add_memento_handler(server.logger, level=0)
         return d
 
-    def tearDown(self):
-        """Tear down."""
-        self._logger.removeHandler(self.handler)
-        return super(TestPutContent, self).tearDown()
-
     def test_putcontent_cancel(self):
         """Test putting content to a file and cancelling it."""
         data = os.urandom(300000)
@@ -657,8 +657,8 @@
                 # check upload stat and the offset sent
                 self.assertTrue(('UploadJob.upload', 0) in gauge)
                 self.assertTrue(('UploadJob.upload.begin', 1) in meter)
-                self.assertTrue(self.handler.check_debug(
-                                "UploadJob begin content from offset 0"))
+                self.handler.assert_debug(
+                    "UploadJob begin content from offset 0")
 
         yield self.callback_test(auth, add_default_callbacks=True)
 
@@ -1057,9 +1057,8 @@
             try:
                 yield client.put_content(*args)
             except Exception as ex:
-                self.assertTrue(isinstance(ex, protoerrors.UploadCorruptError))
-            self.assertTrue(
-                self.handler.check_debug('UploadCorrupt', str(size)))
+                self.assertIsInstance(ex, protoerrors.UploadCorruptError)
+            self.handler.assert_debug('UploadCorrupt', str(size))
             self.assertTrue(('oops_saved',) not in meter)
         return self.callback_test(test, add_default_callbacks=True)
 
@@ -1137,9 +1136,9 @@
         """Get both storage and content users."""
         s_user = self.make_user(
             max_storage_bytes=max_storage_bytes)
-        c_user = content.User(self.service.factory.content, s_user.id,
-                              s_user.root_volume_id, s_user.username,
-                              s_user.visible_name)
+        c_user = User(
+            self.service.factory.content, s_user.id, s_user.root_volume_id,
+            s_user.username, s_user.visible_name)
         return s_user, c_user
 
     @defer.inlineCallbacks
@@ -1516,7 +1515,7 @@
 
         # overwrite UploadJob method to detect if it
         # uploaded stuff (it shouldn't)
-        self.patch(content.BaseUploadJob, '_start_receiving',
+        self.patch(BaseUploadJob, '_start_receiving',
                    lambda s: defer.fail(Exception("This shouldn't be called")))
 
         @defer.inlineCallbacks
@@ -1596,20 +1595,11 @@
     @defer.inlineCallbacks
     def setUp(self):
         """Set up."""
-        self.handler = MementoHandler()
-        self.handler.setLevel(0)
-        self._logger = logging.getLogger('storage.server')
-        self._logger.addHandler(self.handler)
+        self.handler = self.add_memento_handler(server.logger, level=0)
         yield super(TestMultipartPutContent, self).setUp()
         # override defaults set by TestWithDatabase.setUp.
         self.patch(settings.api_server, 'STORAGE_CHUNK_SIZE', 1024)
 
-    @defer.inlineCallbacks
-    def tearDown(self):
-        """Tear down."""
-        self._logger.removeHandler(self.handler)
-        yield super(TestMultipartPutContent, self).tearDown()
-
     def get_data(self, size):
         """Return random data of the specified size."""
         return os.urandom(size)
@@ -1653,8 +1643,8 @@
                 # check upload stat and log, with the offset sent
                 self.assertIn(('UploadJob.upload', 0), gauge)
                 self.assertIn(('UploadJob.upload.begin', 1), meter)
-                self.assertTrue(self.handler.check_debug(
-                    "UploadJob begin content from offset 0"))
+                self.handler.assert_debug(
+                    "UploadJob begin content from offset 0")
 
         yield self.callback_test(auth, timeout=self.timeout,
                                  add_default_callbacks=True)
@@ -1724,8 +1714,7 @@
             # first time tarts from beginning.
             self.assertTrue(('UploadJob.upload', 0) in gauge)
             self.assertTrue(('UploadJob.upload.begin', 1) in meter)
-            self.assertTrue(self.handler.check_debug(
-                            "UploadJob begin content from offset 0"))
+            self.handler.assert_debug("UploadJob begin content from offset 0")
         else:
             self.fail("Should raise EOFError.")
         yield client.kill()
@@ -1777,8 +1766,8 @@
         # check upload stat and log, with the offset sent, second time it
         # resumes from the first chunk
         self.assertTrue(('UploadJob.upload', offset_sent) in gauge)
-        self.assertTrue(self.handler.check_debug("UploadJob "
-                        "begin content from offset %d" % offset_sent))
+        self.handler.assert_debug(
+            "UploadJob begin content from offset %d" % offset_sent)
 
         yield client.kill()
         yield connector.disconnect()
@@ -1822,8 +1811,8 @@
             yield req.deferred
             self.assertTrue(('UploadJob.upload', 0) in gauge)
             self.assertTrue(('UploadJob.upload.begin', 1) in meter)
-            self.assertTrue(self.handler.check_debug(
-                "UploadJob begin content from offset 0"))
+            self.handler.assert_debug(
+                "UploadJob begin content from offset 0")
             self.assertEqual(len(upload_id), 1)
             self.assertIsInstance(uuid.UUID(upload_id[0]), uuid.UUID)
 
@@ -1888,9 +1877,8 @@
                 putc_req = client.put_content_request(*args)
                 yield putc_req.deferred
             except Exception as ex:
-                self.assertTrue(isinstance(ex, protoerrors.UploadCorruptError))
-            self.assertTrue(self.handler.check_debug('UploadCorrupt',
-                                                     str(size)))
+                self.assertIsInstance(ex, protoerrors.UploadCorruptError)
+            self.handler.assert_debug('UploadCorrupt', str(size))
             # check that the uploadjob was deleted.
             node = self.usr0.volume(None).get_node(make_req.new_id)
             self.assertRaises(errors.DoesNotExist,
@@ -1981,9 +1969,9 @@
         """
         chunk_size = settings.api_server.STORAGE_CHUNK_SIZE
         user = self.make_user(max_storage_bytes=chunk_size ** 2)
-        content_user = content.User(self.service.factory.content, user.id,
-                                    user.root_volume_id, user.username,
-                                    user.visible_name)
+        content_user = User(
+            self.service.factory.content, user.id, user.root_volume_id,
+            user.username, user.visible_name)
         # create the file
         a_file = user.root.make_file(u"A new file")
         # build the upload data
@@ -2030,7 +2018,7 @@
         def crash(*_):
             """Make it crash."""
             raise ValueError("Fail!")
-        self.patch(content.BaseUploadJob, 'add_data', crash)
+        self.patch(BaseUploadJob, 'add_data', crash)
 
         # start uploading
         pc.start()
@@ -2229,8 +2217,9 @@
 
         # user and root to use in the tests
         u = self.suser = self.make_user(max_storage_bytes=64 ** 2)
-        self.user = content.User(self.service.factory.content, u.id,
-                                 u.root_volume_id, u.username, u.visible_name)
+        self.user = User(
+            self.service.factory.content, u.id, u.root_volume_id, u.username,
+            u.visible_name)
 
     @defer.inlineCallbacks
     def test_make_file_node_with_gen(self):
@@ -2287,8 +2276,7 @@
         upload_job = yield self.user.get_upload_job(
             None, node_id, NO_CONTENT_HASH, 'foo', 10, size / 2, size / 4,
             True)
-        self.assertTrue(isinstance(upload_job, content.UploadJob),
-                        upload_job.__class__)
+        self.assertIsInstance(upload_job, UploadJob)
 
     @defer.inlineCallbacks
     def test_get_free_bytes_root(self):
@@ -2329,7 +2317,7 @@
 class TestUploadJob(TestWithDatabase):
     """Tests for UploadJob class."""
 
-    upload_class = content.UploadJob
+    upload_class = UploadJob
 
     @defer.inlineCallbacks
     def setUp(self):
@@ -2339,11 +2327,10 @@
         self.half_size = self.chunk_size / 2
         self.double_size = self.chunk_size * 2
         self.user = self.make_user(max_storage_bytes=self.chunk_size ** 2)
-        self.content_user = content.User(self.service.factory.content,
-                                         self.user.id,
-                                         self.user.root_volume_id,
-                                         self.user.username,
-                                         self.user.visible_name)
+        self.content_user = User(
+            self.service.factory.content, self.user.id,
+            self.user.root_volume_id, self.user.username,
+            self.user.visible_name)
 
         def slowScheduler(x):
             """A slower scheduler for our cooperator."""
@@ -2379,7 +2366,7 @@
         node = yield c_user.get_node(self.user.root_volume_id, node_id, None)
         args = (c_user, self.user.root_volume_id, node_id, node.content_hash,
                 hash_value, crc32_value, size)
-        upload = yield content.DBUploadJob.make(*args)
+        upload = yield DBUploadJob.make(*args)
         upload_job = self.upload_class(c_user, node, node.content_hash,
                                        hash_value, crc32_value, size,
                                        deflated_size, None, False,
@@ -2591,21 +2578,10 @@
         # also delete
         self.patch(upload_job.uploadjob, "delete",
                    lambda: defer.fail(ValueError("delete boom")))
-        logger = logging.getLogger('storage.server')
-        hdlr = MementoHandler()
-        hdlr.setLevel(logging.WARNING)
-        logger.addHandler(hdlr)
-        self.addCleanup(logger.removeHandler, hdlr)
-        hdlr.debug = True
-        try:
-            yield upload_job.commit()
-        except ValueError as e:
-            # twisted bug: even it sees the last exception happened, even if
-            # not the one that exploding one
-            self.assertEqual(str(e), "delete boom")
-            self.assertTrue(hdlr.check_warning("delete boom"))
-        else:
-            self.fail("Should fail and log a warning.")
+        handler = self.add_memento_handler(logger, level=logging.WARNING)
+        failure = yield self.assertFailure(upload_job.commit(), ValueError)
+        self.assertEqual(str(failure), "delete boom")
+        handler.assert_exception("delete boom")
 
     @defer.inlineCallbacks
     def test_delete_after_commit_ok(self):
@@ -2614,19 +2590,12 @@
         deflated_data, _, upload_job = yield self.make_upload(size)
         yield upload_job.connect()
         yield upload_job.add_data(deflated_data)
-        logger = logging.getLogger('storage.server')
-        hdlr = MementoHandler()
-        hdlr.setLevel(logging.WARNING)
-        logger.addHandler(hdlr)
-        self.addCleanup(logger.removeHandler, hdlr)
-        hdlr.debug = True
         yield upload_job.commit()
         node = upload_job.file_node
         # check that the upload is no more
-        d = content.DBUploadJob.get(self.content_user, node.volume_id,
-                                    node.id, upload_job.upload_id,
-                                    upload_job.hash_hint,
-                                    upload_job.crc32_hint)
+        d = DBUploadJob.get(
+            self.content_user, node.volume_id, node.id, upload_job.upload_id,
+            upload_job.hash_hint, upload_job.crc32_hint)
         yield self.assertFailure(d, errors.DoesNotExist)
 
     @defer.inlineCallbacks
@@ -2675,7 +2644,7 @@
 class TestNode(TestWithDatabase):
     """Tests for Node class."""
 
-    upload_class = content.UploadJob
+    upload_class = UploadJob
 
     @defer.inlineCallbacks
     def setUp(self):
@@ -2685,27 +2654,20 @@
         self.half_size = self.chunk_size / 2
         self.double_size = self.chunk_size * 2
         self.user = self.make_user(max_storage_bytes=self.chunk_size ** 2)
-        self.suser = content.User(self.service.factory.content, self.user.id,
-                                  self.user.root_volume_id, self.user.username,
-                                  self.user.visible_name)
+        self.suser = User(
+            self.service.factory.content, self.user.id,
+            self.user.root_volume_id, self.user.username,
+            self.user.visible_name)
 
         # add a memento handler, to check we log ok
-        self.logger = logging.getLogger('storage.server')
-        self.handler = MementoHandler()
-        self.handler.setLevel(logging.WARNING)
-        self.logger.addHandler(self.handler)
-
-    def tearDown(self):
-        """Tear down."""
-        self.logger.removeHandler(self.handler)
-        return super(TestNode, self).tearDown()
+        self.handler = self.add_memento_handler(server.logger)
 
     @defer.inlineCallbacks
     def _upload_a_file(self, user, content_user):
         """Upload a file.
 
         @param user: the storage user
-        @param content: the content.User
+        @param content: the User
         @return: a tuple (upload, deflated_data)
         """
         size = self.chunk_size / 2
@@ -2727,11 +2689,10 @@
         node = yield content_user.get_node(user.root_volume_id, node_id, None)
         args = (content_user, self.user.root_volume_id, node_id,
                 node.content_hash, hash_value, crc32_value, size)
-        upload = yield content.DBUploadJob.make(*args)
-        upload_job = content.UploadJob(content_user, node, node.content_hash,
-                                       hash_value, crc32_value, size,
-                                       deflated_size, None, False,
-                                       magic_hash_value, upload)
+        upload = yield DBUploadJob.make(*args)
+        upload_job = UploadJob(
+            content_user, node, node.content_hash, hash_value, crc32_value,
+            size, deflated_size, None, False, magic_hash_value, upload)
         yield upload_job.connect()
         yield upload_job.add_data(deflated_data)
         yield upload_job.commit()
@@ -2787,8 +2748,9 @@
         """Setup the test."""
         yield super(TestGenerations, self).setUp()
         self.suser = u = self.make_user(max_storage_bytes=64 ** 2)
-        self.user = content.User(self.service.factory.content, u.id,
-                                 u.root_volume_id, u.username, u.visible_name)
+        self.user = User(
+            self.service.factory.content, u.id, u.root_volume_id, u.username,
+            u.visible_name)
 
     @defer.inlineCallbacks
     def test_get_delta_empty(self):
@@ -2871,7 +2833,7 @@
         """Setup the test."""
         yield super(TestContentManagerTests, self).setUp()
         self.suser = self.make_user(max_storage_bytes=64 ** 2)
-        self.cm = content.ContentManager(self.service.factory)
+        self.cm = ContentManager(self.service.factory)
         self.cm.rpc_dal = self.service.rpc_dal
 
     @defer.inlineCallbacks
@@ -2881,12 +2843,12 @@
         u = yield self.cm.get_user_by_id(self.suser.id)
         self.assertEqual(u, None)
         u = yield self.cm.get_user_by_id(self.suser.id, required=True)
-        self.assertTrue(isinstance(u, content.User))
+        self.assertIsInstance(u, User)
         # make sure it's in the cache
         self.assertEqual(u, self.cm.users[self.suser.id])
         # get it from the cache
         u = yield self.cm.get_user_by_id(self.suser.id)
-        self.assertTrue(isinstance(u, content.User))
+        self.assertIsInstance(u, User)
 
     @defer.inlineCallbacks
     def test_get_user_by_id_race_condition(self):
@@ -3028,7 +2990,7 @@
         """Test the getter."""
         args = (self.user, 'volume_id', 'node_id', 'uploadjob_id',
                 'hash_value', 'crc32')
-        dbuj = yield content.DBUploadJob.get(*args)
+        dbuj = yield DBUploadJob.get(*args)
 
         # check it called rpc dal correctly
         method, attribs = self.user.recorded
@@ -3039,7 +3001,7 @@
         self.assertEqual(attribs, should)
 
         # check it built the instance correctly
-        self.assertTrue(isinstance(dbuj, content.DBUploadJob))
+        self.assertIsInstance(dbuj, DBUploadJob)
         self.assertEqual(dbuj.user, self.user)
         self.assertEqual(dbuj.volume_id, 'volume_id')
         self.assertEqual(dbuj.node_id, 'node_id')
@@ -3055,7 +3017,7 @@
         args = (self.user, 'volume_id', 'node_id', 'previous_hash',
                 'hash_value', 'crc32', 'inflated_size')
         self.patch(uuid, 'uuid4', lambda: "test unique id")
-        dbuj = yield content.DBUploadJob.make(*args)
+        dbuj = yield DBUploadJob.make(*args)
 
         # check it called rpc dal correctly
         method, attribs = self.user.recorded
@@ -3068,7 +3030,7 @@
         self.assertEqual(attribs, should)
 
         # check it built the instance correctly
-        self.assertTrue(isinstance(dbuj, content.DBUploadJob))
+        self.assertIsInstance(dbuj, DBUploadJob)
         self.assertEqual(dbuj.user, self.user)
         self.assertEqual(dbuj.volume_id, 'volume_id')
         self.assertEqual(dbuj.node_id, 'node_id')
@@ -3082,7 +3044,7 @@
         """Helper to create the upload job."""
         args = (self.user, 'volume_id', 'node_id', 'previous_hash',
                 'hash_value', 'crc32', 'inflated_size')
-        return content.DBUploadJob.make(*args)
+        return DBUploadJob.make(*args)
 
     @defer.inlineCallbacks
     def test_add_part(self):
@@ -3132,7 +3094,7 @@
     def test_bogus_upload_job(self):
         """Check the not-going-to-db upload job."""
         self.patch(uuid, 'uuid4', lambda: "test unique id")
-        uj = content.BogusUploadJob()
+        uj = BogusUploadJob()
 
         # basic attributes
         self.assertEqual(uj.multipart_key, "test unique id")

=== modified file 'magicicada/server/tests/test_notify_delivery.py'
--- magicicada/server/tests/test_notify_delivery.py	2016-06-04 19:08:28 +0000
+++ magicicada/server/tests/test_notify_delivery.py	2016-08-23 00:49:23 +0000
@@ -46,6 +46,7 @@
     StorageServer,
     StorageServerFactory,
     configure_oops,
+    logger,
 )
 from magicicada.server.testing.testcase import FactoryHelper, TestWithDatabase
 
@@ -343,13 +344,13 @@
     exceptions in themselves, but an exception is created at broadcast.
     """
 
-    induced_error = ValueError
+    induced_error = Failure(ValueError("Test error"))
 
     @defer.inlineCallbacks
     def setUp(self):
         yield super(NotificationErrorsTestCase, self).setUp()
-
-        self.notifier = FakeNotifier()
+        self.event_sent = defer.Deferred()
+        self.notifier = FakeNotifier(event_sent_deferred=self.event_sent)
         self.patch(notifier, 'get_notifier', lambda: self.notifier)
         self.fake_reactor = DummyReactor()
         self.oops_deferred = defer.Deferred()
@@ -369,16 +370,24 @@
         protocol = StorageServer()
         protocol.factory = self.ssfactory
         protocol.working_caps = ["volumes", "generations"]
-        protocol.logger = logging.getLogger("storage.server")
         protocol.session_id = uuid.uuid4()
         self.patch(self.ssfactory.content, 'get_user_by_id',
-                   lambda *a: Failure(self.induced_error("Test error")))
+                   lambda *a: self.induced_error)
+        self.handler = self.add_memento_handler(logger)
 
     @defer.inlineCallbacks
     def check_event(self, event, **kwargs):
         """Test an error in node update."""
         original_event = event
-        self.notifier.send_event(original_event)
+        self.notifier.send_event(event)
+        yield self.event_sent
+
+        actual = self.handler.records_by_level[logging.ERROR]
+        self.assertEqual(len(actual), 1)
+        expected = '%s in notification %r while calling deliver_%s(**%r)' % (
+            self.induced_error.value, event, event.event_type, kwargs)
+        self.assertEqual(actual[0].getMessage(), expected)
+
         oops_data = yield self.oops_deferred
         tl = oops_data["timeline"]
         _, _, category, detail, _ = tl[-1]
@@ -393,36 +402,37 @@
         """Test the share events."""
         event_args = (
             uuid.uuid4(), u"name", uuid.uuid4(), 1, 2, Share.VIEW, False)
-        self.check_event(ShareCreated(*event_args))
+        return self.check_event(ShareCreated(*event_args))
 
     def test_share_deleted(self):
         """Test the share events."""
         event_args = (
             uuid.uuid4(), u"name", uuid.uuid4(), 1, 2, Share.VIEW, False)
-        self.check_event(ShareDeleted(*event_args))
+        return self.check_event(ShareDeleted(*event_args))
 
     def test_share_declined(self):
         """Test the share events."""
         event_args = (
             uuid.uuid4(), u"name", uuid.uuid4(), 1, 2, Share.VIEW, False)
-        self.check_event(ShareDeclined(*event_args))
+        return self.check_event(ShareDeclined(*event_args))
 
     def test_share_accepted(self):
         """Test the share events."""
         event_args = (
             uuid.uuid4(), u"name", uuid.uuid4(), 1, 2, Share.VIEW, True)
-        self.check_event(ShareAccepted(*event_args), recipient_id=u'test')
+        return self.check_event(
+            ShareAccepted(*event_args), recipient_id=u'test')
 
     def test_udf_delete(self):
         """Test UDF Delete."""
-        self.check_event(UDFDelete(1, uuid.uuid4(), uuid.uuid4()))
+        return self.check_event(UDFDelete(1, uuid.uuid4(), uuid.uuid4()))
 
     def test_udf_create(self):
         """Test UDF Create."""
-        self.check_event(UDFCreate(1, uuid.uuid4(), uuid.uuid4(),
-                                   u"suggested path", uuid.uuid4()))
+        return self.check_event(
+            UDFCreate(1, uuid.uuid4(), uuid.uuid4(), u"path", uuid.uuid4()))
 
     def test_new_volume_gen(self):
         """Test the new gen for volume events."""
         event = VolumeNewGeneration(1, uuid.uuid4(), 77, uuid.uuid4())
-        self.check_event(event)
+        return self.check_event(event)

=== modified file 'magicicada/server/tests/test_server.py'
--- magicicada/server/tests/test_server.py	2016-06-07 20:10:40 +0000
+++ magicicada/server/tests/test_server.py	2016-08-23 00:49:23 +0000
@@ -36,14 +36,14 @@
 from twisted.python import log
 from twisted.internet import defer, task, error as txerror
 from twisted.trial.unittest import TestCase as TwistedTestCase
-from ubuntuone.devtools.handlers import MementoHandler
 from ubuntuone.storageprotocol import protocol_pb2, request
 
 from magicicada import settings
 from magicicada.filesync import errors as dataerror
 from magicicada.filesync.models import Share
-from magicicada.server import errors, server
+from magicicada.server import errors
 from magicicada.server.server import (
+    PREFERRED_CAP,
     AccountResponse,
     Action,
     AuthenticateResponse,
@@ -69,9 +69,12 @@
     StorageServerFactory,
     StorageServerRequestResponse,
     Unlink,
+    cancel_filter,
     configure_oops,
+    logger,
 )
 from magicicada.server.testing import testcase
+from magicicada.testing.testcase import BaseTestCase
 
 try:
     from versioninfo import version_info
@@ -132,6 +135,8 @@
 class FakedFactory(object):
     """A faked factory."""
 
+    auth_provider = None
+
     def __init__(self):
         self.oops_config = configure_oops()
         self.oopses = []
@@ -167,35 +172,28 @@
         self.getPeer = lambda *_: FakedPeer()
 
 
-class BaseStorageServerTestCase(TwistedTestCase):
+class BaseStorageServerTestCase(BaseTestCase, TwistedTestCase):
     """Test the StorageServer class.
 
     This is just a base class with a lot of functionality for other TestCases.
     """
 
+    maxDiff = None
+    session_id = '1234-567890'
+
     @defer.inlineCallbacks
     def setUp(self):
         """Init."""
         yield super(BaseStorageServerTestCase, self).setUp()
         self.last_msg = None
         self.restore = {}
-        self.server = StorageServer()
+        self.server = StorageServer(session_id=self.session_id)
         self.patch(self.server, 'sendMessage',
                    lambda msg: setattr(self, 'last_msg', msg))
         self.patch(self.server, 'factory', FakedFactory())
         self.patch(self.server, 'transport', FakedTransport())
 
-        self.handler = MementoHandler()
-        self.handler.setLevel(settings.TRACE)
-        self.server.logger.addHandler(self.handler)
-
-    @defer.inlineCallbacks
-    def tearDown(self):
-        """Clean up."""
-        self.server.logger.removeHandler(self.handler)
-        self.server = None
-        self.last_msg = None
-        yield super(BaseStorageServerTestCase, self).tearDown()
+        self.handler = self.add_memento_handler(logger, level=settings.TRACE)
 
     @property
     def shutdown(self):
@@ -260,8 +258,7 @@
         failure = Failure(Exception(self.msg))
         self.server._log_error_and_oops(failure, req.__class__)
 
-        self.assertTrue(self.handler.check_error(
-                        req.__class__.__name__, str(failure)))
+        self.handler.assert_error(req.__class__.__name__, str(failure))
         self.assert_oopsing(failure)
 
     def test_schedule_request(self):
@@ -285,8 +282,7 @@
         # the logging callback actually works!
         failure = Failure(Exception(self.msg))
         req.error(failure)
-        self.assertTrue(self.handler.check_error(
-                        str(failure), req.__class__.__name__))
+        self.handler.assert_error(str(failure), req.__class__.__name__)
 
     def test_schedule_request_head(self):
         """Test schedule_request to the left of the deque."""
@@ -345,7 +341,7 @@
         failure = Exception(self.msg)
         self.patch(self.server, 'buildMessage', self.fail_please(failure))
         self.server.dataReceived(data=None)
-        self.assertTrue(self.handler.check_exception(failure))
+        self.handler.assert_exception(failure)
         self.assert_oopsing(failure)
 
     def test_execute_next_request(self):
@@ -355,9 +351,7 @@
         self.server.pending_requests = collections.deque([next_req])
         self.server.execute_next_request()
 
-        self.assertTrue(self.handler.check_exception(
-            failure,
-            next_req[0].__class__.__name__))
+        self.handler.assert_exception(failure, next_req[0].__class__.__name__)
         self.assert_oopsing(failure)
 
     def test_process_message_logs_and_oops_on_error(self):
@@ -366,8 +360,8 @@
         self.patch(request.RequestHandler, 'processMessage',
                    self.fail_please(failure))
         self.server.processMessage(protocol_pb2.Message())
-        self.assertTrue(self.handler.check_exception(
-            failure, self.server.processMessage.__name__))
+        self.handler.assert_exception(
+            failure, self.server.processMessage.__name__)
         self.assert_oopsing(failure)
 
     def test_protocol_ref_enabled(self):
@@ -389,7 +383,7 @@
 
     def test_looping_ping_enabled(self):
         """Test that the server instantiates the looping ping."""
-        self.assertTrue(isinstance(self.server.ping_loop, LoopingPing))
+        self.assertIsInstance(self.server.ping_loop, LoopingPing)
 
     def test_looping_ping_interval(self):
         """Test the looping ping interval set from the server."""
@@ -406,31 +400,6 @@
         self.server.set_user(user)
         self.assertEqual(self.server.user, user)
 
-    def test_setuser_fix_logger_yes(self):
-        """If the user is special, fix the logger."""
-        # set up
-        user = FakeUser()
-        assert user.username == 'username'
-        standard_name = settings.api_server.LOGGER_NAME
-        assert self.server.logger.name == standard_name
-        self.server.factory.trace_users = ['username']
-
-        # call and check
-        self.server.set_user(user)
-        self.assertEqual(self.server.logger.name, standard_name + '.hackers')
-
-    def test_setuser_fix_logger_no(self):
-        """If the user is not special, fix the logger."""
-        # set up
-        user = FakeUser()
-        assert user.username == 'username'
-        previous_logger = self.server.logger
-        self.server.factory.trace_users = []
-
-        # call and check
-        self.server.set_user(user)
-        self.assertIdentical(self.server.logger, previous_logger)
-
     def test_handle_PING(self):
         """Handle PING."""
         # get the response
@@ -446,8 +415,7 @@
 
         # check response and logging
         self.assertEqual(response[0].type, protocol_pb2.Message.PONG)
-        self.handler.debug = True
-        self.assertTrue(self.handler.check(settings.TRACE, "ping pong"))
+        self.handler.assert_trace("ping pong")
 
 
 class ActionTestCase(BaseStorageServerTestCase):
@@ -481,10 +449,10 @@
         self.assertTrue(self.action.started)
         self.assertEqual(["action_instances." + Action.__name__],
                          self.increments)
-        self.assertTrue(self.handler.check_debug(
-            "Action being scheduled (%s)" % (self._callable,)))
-        self.assertTrue(self.handler.check_debug(
-            "Action being started, working on: %s" % (self._callable,)))
+        self.handler.assert_debug(
+            "Action being scheduled (%s)" % self._callable)
+        self.handler.assert_debug(
+            "Action being started, working on: %s" % self._callable)
 
     def test_start_tail(self):
         """Test the start method, scheduled in the tail."""
@@ -516,8 +484,8 @@
         self.action.start()
         self.assertEqual(["action_instances." + Action.__name__],
                          self.increments)
-        self.assertTrue(self.handler.check_debug(
-            "Action being scheduled (%s)" % (self._callable,)))
+        self.handler.assert_debug(
+            "Action being scheduled (%s)" % self._callable)
 
     def test__start(self):
         """Test the _start method."""
@@ -544,8 +512,7 @@
         """Test the done method."""
         self.action.start()
         self.callable_deferred.callback(None)
-        self.assertTrue(self.handler.check_debug("Action done (%s)" %
-                                                 (self._callable,)))
+        self.handler.assert_debug("Action done (%s)" % self._callable)
 
     def test_done_fails(self):
         """Test that error is called if done fails."""
@@ -565,8 +532,7 @@
         self.patch(Action, 'error', error)
         self.action.start()
         self.callable_deferred.callback(None)
-        self.assertTrue(self.handler.check_debug("Action done (%s)" %
-                                                 (self._callable,)))
+        self.handler.assert_debug("Action done (%s)" % self._callable)
         # done was called, check if error too.
         self.assertEqual(1, len(called))
         self.assertEqual(exc, called[0].value)
@@ -620,13 +586,6 @@
         self.patch(factory.metrics, 'increment', self.increments.append)
         self.patch(factory.metrics, 'decrement', self.decrements.append)
 
-    @defer.inlineCallbacks
-    def tearDown(self):
-        """Clean up."""
-        self.errors = None
-        self.last_msg = None
-        yield super(StorageServerRequestResponseTestCase, self).tearDown()
-
     @property
     def last_error(self):
         """Return the last error."""
@@ -648,8 +607,7 @@
         failure = Exception(self.msg)
         self.patch(request.RequestResponse, 'error', self.fail_please(failure))
         self.response.error(failure=failure)
-        self.assertTrue(self.handler.check_error(
-                        str(failure), self.response.error.__name__))
+        self.handler.assert_error(str(failure), self.response.error.__name__)
 
     def test_process_message_returns_result_when_started(self):
         """Test response.processMessage erturns the result."""
@@ -714,8 +672,7 @@
         assert not self.response.started
         self.response.stop()
         self.assertTrue(called)
-        self.assertTrue(self.handler.check_debug(
-                        "Request being released before start"))
+        self.handler.assert_debug("Request being released before start")
 
 
 class SSRequestResponseSpecificTestCase(StorageServerRequestResponseTestCase):
@@ -932,11 +889,10 @@
         failure = Exception(self.msg)
         self.patch(request.RequestResponse, 'done', self.fail_please(failure))
         self.response.done()
-        self.assertTrue(self.response.deferred.called,
-                        'request.deferred was fired.')
-        # Commented see Bug LP:890246
-        # self.assertTrue(self.handler.check_exception(
-        #     failure, self.response.__class__.__name__))
+        self.assertTrue(
+            self.response.deferred.called, 'request.deferred was fired.')
+        self.handler.assert_exception(
+            failure, self.response.__class__.__name__)
         self.assert_oopsing(failure)
 
     def test_get_node_info(self):
@@ -949,7 +905,7 @@
         message = protocol_pb2.Message()
         req = self.response_class(self.server, message)
         req.start()
-        self.assertTrue(self.handler.check_debug("Request being started"))
+        self.handler.assert_debug("Request being started")
 
     def test_request_instances_metric(self):
         """request_instances.<request> is updated."""
@@ -967,8 +923,7 @@
         self.patch(self.response_class, '_get_node_info', lambda _: 'FOO')
         req = self.response_class(self.server, message)
         req.start()
-        self.assertTrue(self.handler.check_debug(
-                        "Request being started, working on: FOO"))
+        self.handler.assert_debug("Request being started, working on: FOO")
 
     def test_log_operation_data(self):
         """Log data operation."""
@@ -976,8 +931,7 @@
         req = self.response_class(self.server, message)
         req.operation_data = "some=stuff bar=foo"
         req.done()
-        self.assertTrue(self.handler.check_info(
-            "Request done: some=stuff bar=foo"))
+        self.handler.assert_info("Request done: some=stuff bar=foo")
 
     def test_log_request_process(self):
         """Log correctly the life of a request."""
@@ -989,18 +943,22 @@
         req.start()
 
         # assert log order
-        msgs = [(r.levelno, r.msg) for r in self.handler.records]
+        msgs = [(r.levelname, r.msg) for r in self.handler.records
+                if r.levelno >= logging.DEBUG]
+        prefix = '%s localhost:0 - %s 42 - ' % (
+            self.session_id, self.response_class.__name__)
 
-        def index(level, text):
-            """Return the position of first message where text is included."""
-            for i, (msglevel, msgtext) in enumerate(msgs):
-                if text in msgtext and level == msglevel:
-                    return i
-            raise ValueError("msg not there!")
-        pos_sched = index(logging.INFO, '42 - Request being scheduled')
-        pos_start = index(logging.DEBUG, '42 - Request being started')
-        pos_done = index(logging.INFO, '42 - Request done')
-        self.assertTrue(pos_sched < pos_start < pos_done)
+        node = req._get_node_info()
+        if node is None:
+            working_on = ""
+        else:
+            working_on = ", working on: " + node
+        expected = [
+            ('INFO', prefix + 'Request being scheduled'),
+            ('DEBUG', prefix + "Request being started" + working_on),
+            ('INFO', prefix + 'Request done'),
+        ]
+        self.assertItemsEqual(msgs, expected)
 
     @defer.inlineCallbacks
     def test_internal_error(self):
@@ -1034,8 +992,7 @@
 
     def test_cancel_filter(self):
         """Test the cancel_filter decorator."""
-        self.response_class.fakefunction = \
-            server.cancel_filter(lambda *a: 'hi')
+        self.response_class.fakefunction = cancel_filter(lambda *a: 'hi')
         self.assertEqual(self.response.fakefunction(self.response), "hi")
         self.response.cancelled = True
         self.assertRaises(request.RequestCancelledError,
@@ -1322,8 +1279,7 @@
         self.assertTrue(self.last_error is None)
         self.assertTrue(self.last_msg is None)
 
-        self.assertTrue(self.handler.check_warning(
-                        str(failure), 'cancel_message is None'))
+        self.handler.assert_warning(str(failure), 'cancel_message is None')
 
     def test__init__(self):
         """Test __init__."""
@@ -1642,7 +1598,7 @@
 
         with mocker:
             self.response._cancel()
-        self.assertTrue(self.handler.check_debug("Canceling the upload job"))
+        self.handler.assert_debug("Canceling the upload job")
 
     def test__cancel_uploadjob_cancel_None(self):
         """Test cancel not having an upload_job."""
@@ -1653,7 +1609,8 @@
 
         assert self.response.upload_job is None
         self.response._cancel()
-        self.assertFalse(self.handler.check_debug("Canceling the upload job"))
+
+        self.handler.assert_not_logged("Canceling the upload job")
 
     def test__cancel_uploadjob_stopped(self):
         """Test cancel cancelling the upload_job."""
@@ -1665,16 +1622,15 @@
 
         with mocker:
             self.response._cancel()
-        self.assertTrue(self.handler.check_debug(
-                        "Stoping the upload job after a cancel"))
+        self.handler.assert_debug("Stoping the upload job after a cancel")
 
     def test__cancel_uploadjob_stop_None(self):
         """Test cancel not having an upload_job."""
         assert self.response.state != PutContentResponse.states.canceling
         assert self.response.upload_job is None
         self.response._cancel()
-        self.assertFalse(self.handler.check_debug(
-                         "Stoping the upload job after a cancel"))
+
+        self.handler.assert_not_logged("Stoping the upload job after a cancel")
 
     def test__cancel_answer_client_yes(self):
         """Test answer is sent to the client because canceling."""
@@ -1730,7 +1686,7 @@
         with mocker:
             self.response._cancel()
 
-        self.assertTrue(self.handler.check_debug("Request canceled (in INIT)"))
+        self.handler.assert_debug("Request canceled (in INIT)")
         self.assertEqual(len(called), 2)
         self.assertEqual(called[0], PutContentResponse.states.canceling)
         self.assertEqual(called[1], True)
@@ -1740,15 +1696,13 @@
         """Generic error logs when called with an error."""
         assert self.response.state == PutContentResponse.states.init
         self.response._generic_error(NameError('foo'))
-        self.assertTrue(self.handler.check_warning("Error while in INIT",
-                                                   "NameError", "foo"))
+        self.handler.assert_warning("Error while in INIT", "NameError", "foo")
 
     def test_genericerror_log_failure(self):
         """Generic error logs when called with a failure."""
         assert self.response.state == PutContentResponse.states.init
         self.response._generic_error(Failure(NameError('foo')))
-        self.assertTrue(self.handler.check_warning("Error while in INIT",
-                                                   "NameError", "foo"))
+        self.handler.assert_warning("Error while in INIT", "NameError", "foo")
 
     def test_genericerror_already_in_error(self):
         """Just log if already in error."""
@@ -1757,8 +1711,7 @@
         self.response._send_protocol_error = called.append
         self.response._generic_error(NameError('foo'))
         self.assertFalse(called)
-        self.assertTrue(self.handler.check_warning("Error while in ERROR",
-                                                   "NameError", "foo"))
+        self.handler.assert_warning("Error while in ERROR", "NameError", "foo")
 
     def test_genericerror_already_in_done(self):
         """Just log if already in done."""
@@ -1767,15 +1720,13 @@
         self.response._send_protocol_error = called.append
         self.response._generic_error(NameError('foo'))
         self.assertFalse(called)
-        self.assertTrue(self.handler.check_warning("Error while in DONE",
-                                                   "NameError", "foo"))
+        self.handler.assert_warning("Error while in DONE", "NameError", "foo")
 
     def test_genericerror_no_uploadjob(self):
         """Don't stop the upload job if doesn't have one."""
         assert self.response.upload_job is None
         self.response._generic_error(NameError('foo'))
-        self.assertFalse(self.handler.check_debug(
-                         "Stoping the upload job after an error"))
+        self.handler.assert_not_logged("Stoping the upload job after an error")
 
     def test_genericerror_stop_uploadjob(self):
         """Stop the upload job if has one."""
@@ -1787,8 +1738,7 @@
 
         with mocker:
             self.response._generic_error(NameError('foo'))
-        self.assertTrue(self.handler.check_debug(
-                        "Stoping the upload job after an error"))
+        self.handler.assert_debug("Stoping the upload job after an error")
 
     def test_try_again_handling(self):
         """Test how a TRY_AGAIN error is handled."""
@@ -1803,8 +1753,7 @@
         # call and test
         with mocker:
             self.response._log_exception(errors.TryAgain(NameError('foo')))
-        self.assertTrue(self.handler.check_debug("TryAgain", "NameError",
-                                                 str(size_hint)))
+        self.handler.assert_debug("TryAgain", "NameError", str(size_hint))
 
     def test_genericerror_requestcancelled_canceling(self):
         """Test how a RequestCancelledError error is handled when canceling."""
@@ -1814,7 +1763,7 @@
         self.response.done = called.append
         self.response._generic_error(request.RequestCancelledError('message'))
         self.assertFalse(called)
-        self.assertTrue(self.handler.check_debug("Request cancelled: message"))
+        self.handler.assert_debug("Request cancelled: message")
 
     def test_genericerror_requestcancelled_other(self):
         """Test how a RequestCancelledError error is handled in other state."""
@@ -1830,8 +1779,7 @@
         self.mocker.replay()
         response._generic_error(failure)
         self.assertEqual(response.state, PutContentResponse.states.error)
-        self.assertTrue(self.handler.check_debug("RequestCancelledError",
-                                                 str(1000)))
+        self.handler.assert_debug("RequestCancelledError", str(1000))
 
     def test_genericerror_other_errors_ok(self):
         """Generic error handling."""
@@ -1846,7 +1794,7 @@
         self.mocker.replay()
         response._generic_error(failure)
         self.assertEqual(response.state, PutContentResponse.states.error)
-        self.assertTrue(self.handler.check_debug("NameError", str(1000)))
+        self.handler.assert_debug("NameError", str(1000))
 
     def test_genericerror_other_errors_problem_sendprotocolerror(self):
         """Handle problems in the _send_protocol_error() call."""
@@ -1943,7 +1891,8 @@
         mtyp = protocol_pb2.Message.PUT_CONTENT
         message.type = mtyp
         self.response._processMessage(message)
-        self.assertTrue(self.handler.check_error("unknown message", str(mtyp)))
+        self.handler.assert_error(
+            "unknown message", str(protocol_pb2.Message.PUT_CONTENT))
 
     def test_processmessage_init_cancel_ok(self):
         """Process a cancel request while in init, all ok."""
@@ -1986,8 +1935,8 @@
             all_msgs.append(message.type)
 
         for mtype in all_msgs:
-            self.assertTrue(self.handler.check_warning("Received out-of-order",
-                                                       "INIT", str(mtype)))
+            self.handler.assert_warning(
+                "Received out-of-order", "INIT", str(mtype))
         self.assertFalse(cancel_called)
 
     def test_processmessage_error(self):
@@ -2000,7 +1949,7 @@
             message.type = getattr(protocol_pb2.Message, mtype)
             self.response._processMessage(message)
 
-        self.assertFalse(self.handler.check_warning("Received out-of-order"))
+        self.handler.assert_not_logged("Received out-of-order")
 
     def test_processmessage_otherstates(self):
         """Process all requests while in other states."""
@@ -2011,7 +1960,7 @@
                 message.type = getattr(protocol_pb2.Message, mtype)
                 self.response._processMessage(message)
                 chk = "Received out-of-order", state.upper(), str(message.type)
-                self.assertTrue(self.handler.check_warning(*chk))
+                self.handler.assert_warning(*chk)
 
     def test_processwhileuploading_cancel(self):
         """Got a cancel request while uploading."""
@@ -2086,8 +2035,8 @@
         message = protocol_pb2.Message()
         message.type = protocol_pb2.Message.PUT_CONTENT
         self.response._process_while_uploading(message)
-        self.assertTrue(self.handler.check_error("Received unknown message",
-                                                 str(message.type)))
+        self.handler.assert_error(
+            "Received unknown message", str(message.type))
 
     def test_commituploadjob_not_commiting(self):
         """Assure we're still commiting when we reach this."""
@@ -2179,8 +2128,8 @@
         upload_job = self.FakeUploadJob()
         d.callback(upload_job)
         self.assertEqual(upload_job.called, ['cancel'])   # not connect
-        self.assertTrue(self.handler.check_debug(
-                        "Manually canceling the upload job (in %s)" % state))
+        self.handler.assert_debug(
+            "Manually canceling the upload job (in %s)" % state)
 
     def test_startupload_done(self):
         """State changes to done while getting the upload job."""
@@ -2204,8 +2153,8 @@
         self.assertEqual(self.last_msg.begin_content.upload_id, '12')
 
         upload_type = self.response.upload_job.__class__.__name__
-        self.assertTrue(self.handler.check_debug(
-            upload_type, "begin content", "from offset 10", "fake storagekey"))
+        self.handler.assert_debug(
+            upload_type, "begin content", "from offset 10", "fake storagekey")
 
     def test__send_begin_new_upload_id(self):
         """Test sendbegin when the upload_id received is invalid."""
@@ -2222,8 +2171,8 @@
         self.assertEqual(self.last_msg.begin_content.upload_id, '12')
 
         upload_type = self.response.upload_job.__class__.__name__
-        self.assertTrue(self.handler.check_debug(
-            upload_type, "begin content", "from offset 0", "fake storagekey"))
+        self.handler.assert_debug(
+            upload_type, "begin content", "from offset 0", "fake storagekey")
 
     def test_putcontent_double_done(self):
         """Double call to self.done()."""
@@ -2244,7 +2193,7 @@
         self.assertEqual(called, [])
         msg = ("runWithWarningsSuppressed -> test_method_wrapper -> "
                "test_putcontent_double_done: called done() finished=True")
-        self.assertTrue(self.handler.check_warning(msg))
+        self.handler.assert_warning(msg)
 
     def test_putcontent_done_after_error(self):
         """Double call to self.done()."""
@@ -2265,7 +2214,7 @@
         self.assertEqual(called, [])
         msg = ("runWithWarningsSuppressed -> test_method_wrapper -> "
                "test_putcontent_done_after_error: called done() finished=True")
-        self.assertTrue(self.handler.check_warning(msg))
+        self.handler.assert_warning(msg)
 
 
 class QuerySetCapsResponseTestCase(SimpleRequestResponseTestCase):
@@ -2502,7 +2451,7 @@
             node.last_modified = int(time.mktime(right_now.timetuple()))
             nodes.append(node)
         # set required caps
-        self.response.protocol.working_caps = server.PREFERRED_CAP
+        self.response.protocol.working_caps = PREFERRED_CAP
         mocker = Mocker()
         user = mocker.mock()
         self.patch(self.response, "send_delta_info", lambda *a: None)
@@ -2546,7 +2495,7 @@
         self.assertEqual(self.response.length, 2)
 
 
-class NodeInfoLogsTests(BaseStorageServerTestCase):
+class NodeInfoLogsTestCase(BaseStorageServerTestCase):
     """Check that operations return correct node info."""
 
     def check(self, response, mes_type, klass=None, mes_name=None, **attrs):
@@ -2644,19 +2593,15 @@
         self.assertFalse(self.shutdown)
 
 
-class StorageServerFactoryTests(TwistedTestCase):
+class StorageServerFactoryTestCase(BaseTestCase, TwistedTestCase):
     """Test the StorageServerFactory class."""
 
     @defer.inlineCallbacks
     def setUp(self):
         """Set up."""
-        yield super(StorageServerFactoryTests, self).setUp()
-
+        yield super(StorageServerFactoryTestCase, self).setUp()
         self.factory = StorageServerFactory()
-        self.handler = MementoHandler()
-        self.handler.setLevel(logging.DEBUG)
-        self.factory.logger.addHandler(self.handler)
-        self.addCleanup(self.factory.logger.removeHandler, self.handler)
+        self.handler = self.add_memento_handler(logger, level=logging.DEBUG)
 
     def test_observer_added(self):
         """Test that the observer was added to Twisted logging."""
@@ -2666,22 +2611,20 @@
     def test_noerror(self):
         """No error, no action."""
         self.factory._deferror_handler(dict(isError=False, message=''))
-        self.assertFalse(self.handler.check_error("error"))
+        self.handler.assert_not_logged("error")
 
     def test_message(self):
         """Just a message."""
         self.factory._deferror_handler(dict(isError=True, message="foobar"))
-        self.assertTrue(self.handler.check_error(
-            "Unhandled error in deferred", "foobar"))
+        self.handler.assert_error("Unhandled error in deferred", "foobar")
 
     def test_failure(self):
         """Received a full failure."""
         f = Failure(ValueError('foobar'))
         self.factory._deferror_handler(dict(isError=True,
                                             failure=f, message=''))
-        self.assertTrue(self.handler.check_error(
-                        "Unhandled error in deferred",
-                        "ValueError", "foobar"))
+        self.handler.assert_error(
+            "Unhandled error in deferred", "ValueError", "foobar")
 
     def test_trace_users(self):
         """Check trace users are correctly set."""
@@ -2691,48 +2634,36 @@
         self.assertEqual(factory.trace_users, set(['foo', 'bar', 'baz']))
 
 
-class BytesMessageProducerTests(TwistedTestCase):
+class BytesMessageProducerTestCase(BaseStorageServerTestCase):
     """Test the BytesMessageProducer class."""
 
     @defer.inlineCallbacks
     def setUp(self):
         """Set up."""
-        yield super(BytesMessageProducerTests, self).setUp()
-        server = StorageServer()
-        req = GetContentResponse(protocol=server,
+        yield super(BytesMessageProducerTestCase, self).setUp()
+        req = GetContentResponse(protocol=self.server,
                                  message=protocol_pb2.Message())
         self.patch(GetContentResponse, 'sendMessage', lambda *a: None)
         self.producer = FakeProducer()
         self.bmp = BytesMessageProducer(self.producer, req)
 
-        self.logger = logging.getLogger("storage.server")
-        self.handler = MementoHandler()
-        self.handler.setLevel(settings.TRACE)
-        self.logger.addHandler(self.handler)
-
-    @defer.inlineCallbacks
-    def tearDown(self):
-        """Tear down."""
-        self.logger.removeHandler(self.handler)
-        yield super(BytesMessageProducerTests, self).tearDown()
-
     def test_resume_log(self):
         """Log when resumed."""
         self.bmp.resumeProducing()
-        self.assertTrue(self.handler.check(settings.TRACE,
-                        "BytesMessageProducer resumed", str(self.producer)))
+        self.handler.assert_trace(
+            "BytesMessageProducer resumed", str(self.producer))
 
     def test_stop_log(self):
         """Log when stopped."""
         self.bmp.stopProducing()
-        self.assertTrue(self.handler.check(settings.TRACE,
-                        "BytesMessageProducer stopped", str(self.producer)))
+        self.handler.assert_trace(
+            "BytesMessageProducer stopped", str(self.producer))
 
     def test_pause_log(self):
         """Log when paused."""
         self.bmp.pauseProducing()
-        self.assertTrue(self.handler.check(settings.TRACE,
-                        "BytesMessageProducer paused", str(self.producer)))
+        self.handler.assert_trace(
+            "BytesMessageProducer paused", str(self.producer))
 
     def test_transferred_counting(self):
         """Keep count of transferred data."""
@@ -2741,16 +2672,6 @@
         self.assertEqual(self.bmp.request.transferred, 6)
 
 
-class TestLoggerSetup(testcase.TestWithDatabase):
-    """Tests for the logging setup."""
-
-    def test_server_logger(self):
-        """Test the storage server logger."""
-        self.assertEqual(self.service.logger.name,
-                         "storage.server")
-        self.assertFalse(self.service.logger.propagate)
-
-
 class TestMetricsSetup(testcase.TestWithDatabase):
     """Tests that metrics are setup from configs properly"""
 

=== modified file 'magicicada/server/tests/test_ssl_proxy.py'
--- magicicada/server/tests/test_ssl_proxy.py	2016-08-06 20:20:18 +0000
+++ magicicada/server/tests/test_ssl_proxy.py	2016-08-23 00:49:23 +0000
@@ -30,8 +30,6 @@
 from twisted.python import failure
 from twisted.web import client, error as web_error
 from twisted.trial.unittest import TestCase
-
-from ubuntuone.devtools.handlers import MementoHandler
 from ubuntuone.storageprotocol.client import (
     StorageClientFactory, StorageClient)
 from ubuntuone.supervisor import utils as supervisor_utils
@@ -52,21 +50,13 @@
     @defer.inlineCallbacks
     def setUp(self):
         yield super(SSLProxyServiceTest, self).setUp()
-        self.configure_logging()
+        self.handler = self.add_memento_handler(
+            ssl_proxy.logger, level=logging.DEBUG)
         self.metrics = MetricReceiver()
         self.patch(metrics, 'get_meter', lambda n: self.metrics)
         self.patch(settings.ssl_proxy, 'HEARTBEAT_INTERVAL',
                    self.ssl_proxy_heartbeat_interval)
 
-    def configure_logging(self):
-        """Configure logging for the tests."""
-        logger = logging.getLogger("ssl_proxy")
-        logger.setLevel(logging.DEBUG)
-        logger.propagate = False
-        self.handler = MementoHandler()
-        logger.addHandler(self.handler)
-        self.addCleanup(logger.removeHandler, self.handler)
-
     @defer.inlineCallbacks
     def test_start_stop(self):
         """Test for start/stoService."""
@@ -86,7 +76,8 @@
     @defer.inlineCallbacks
     def setUp(self):
         yield super(SSLProxyTestCase, self).setUp()
-        self.configure_logging()
+        self.handler = self.add_memento_handler(
+            ssl_proxy.logger, level=logging.DEBUG)
         self.ssl_service = ssl_proxy.ProxyService(self.ssl_cert,
                                                   self.ssl_key,
                                                   self.ssl_cert_chain,
@@ -99,20 +90,7 @@
         self.patch(settings.ssl_proxy, 'HEARTBEAT_INTERVAL',
                    self.ssl_proxy_heartbeat_interval)
         yield self.ssl_service.startService()
-
-    def configure_logging(self):
-        """Configure logging for the tests."""
-        logger = logging.getLogger("ssl_proxy")
-        logger.setLevel(logging.DEBUG)
-        logger.propagate = False
-        self.handler = MementoHandler()
-        logger.addHandler(self.handler)
-        self.addCleanup(logger.removeHandler, self.handler)
-
-    @defer.inlineCallbacks
-    def tearDown(self):
-        yield super(SSLProxyTestCase, self).tearDown()
-        yield self.ssl_service.stopService()
+        self.addCleanup(self.ssl_service.stopService)
 
     @property
     def ssl_port(self):
@@ -290,6 +268,9 @@
 class SSLProxyMetricsTestCase(SSLProxyTestCase):
     """Tests for ssl proxy metrics using real connections."""
 
+    from twisted.internet.base import DelayedCall
+    DelayedCall.debug = True
+
     @defer.inlineCallbacks
     def setUp(self):
         yield super(SSLProxyMetricsTestCase, self).setUp()
@@ -321,7 +302,7 @@
 
         yield self.callback_test(dummy, use_ssl=True)
         self.assertIn('frontend_connection_made', self.metrics)
-        self.assertTrue(self.handler.check_debug('Frontend connection made'))
+        self.handler.assert_debug('Frontend connection made')
 
     @defer.inlineCallbacks
     def test_frontend_connection_lost(self):
@@ -344,7 +325,7 @@
         yield self.callback_test(dummy, use_ssl=True)
         yield d
         self.assertIn('frontend_connection_lost', self.metrics)
-        self.assertTrue(self.handler.check_debug('Frontend connection lost'))
+        self.handler.assert_debug('Frontend connection lost')
 
     @defer.inlineCallbacks
     def test_backend_connection_made(self):
@@ -355,7 +336,7 @@
 
         yield self.callback_test(dummy, use_ssl=True)
         self.assertIn('backend_connection_made', self.metrics)
-        self.assertTrue(self.handler.check_debug('Backend connection made'))
+        self.handler.assert_debug('Backend connection made')
 
     @defer.inlineCallbacks
     def test_backend_connection_lost(self):
@@ -378,7 +359,7 @@
         yield self.callback_test(dummy, use_ssl=True)
         yield d
         self.assertIn('backend_connection_lost', self.metrics)
-        self.assertTrue(self.handler.check_debug('Backend connection lost'))
+        self.handler.assert_debug('Backend connection lost')
 
     @defer.inlineCallbacks
     def test_backend_connection_done(self):
@@ -401,4 +382,4 @@
         yield self.callback_test(dummy, use_ssl=True)
         yield d
         self.assertIn('backend_connection_done', self.metrics)
-        self.assertTrue(self.handler.check_debug('Backend connection done'))
+        self.handler.assert_debug('Backend connection done')

=== modified file 'magicicada/settings/__init__.py'
--- magicicada/settings/__init__.py	2016-06-04 19:08:28 +0000
+++ magicicada/settings/__init__.py	2016-08-23 00:49:23 +0000
@@ -136,7 +136,7 @@
 
 # define the TRACE level
 TRACE = 5
-logging.addLevelName(TRACE, "TRACE")
+logging.addLevelName(TRACE, 'TRACE')
 
 # Custom settings
 
@@ -145,8 +145,55 @@
 INSTANCE_ID = 1
 LOG_FOLDER = os.path.join(BASE_DIR, 'tmp')
 LOG_FORMAT = '%(asctime)s %(levelname)-8s %(name)s[%(process)d]: %(message)s'
-LOG_LEVEL = 5
-LOG_TO_SYSLOG = False
+LOGGING = {
+    'version': 1,
+    'disable_existing_loggers': False,
+    'formatters': {
+        'simple': {
+            'format': LOG_FORMAT,
+        },
+    },
+    'handlers': {
+        'console': {
+            'class': 'logging.StreamHandler',
+        },
+        'file': {
+            'level': 'DEBUG',
+            'class': 'logging.FileHandler',
+            'filename': os.path.join(LOG_FOLDER, 'magicicada.log'),
+            'formatter': 'simple',
+        },
+        'server': {
+            'level': 'TRACE',
+            'class': 'logging.handlers.TimedRotatingFileHandler',
+            'filename': os.path.join(LOG_FOLDER, 'filesync-server.log'),
+            'formatter': 'simple',
+        },
+        'metrics': {
+            'level': 'TRACE',
+            'class': 'logging.handlers.TimedRotatingFileHandler',
+            'filename': os.path.join(LOG_FOLDER, 'metrics.log'),
+            'formatter': 'simple',
+        },
+    },
+    'loggers': {
+        'django': {
+            'handlers': ['file'],
+            'level': 'INFO',
+            'propagate': True,
+        },
+        'magicicada.server': {
+            'handlers': ['server'],
+            'level': 'DEBUG',
+            'propagate': False,
+        },
+        'magicicada.metrics': {
+            'handlers': ['metrics'],
+            'level': 'DEBUG',
+            'propagate': False,
+        },
+    },
+}
 OOPS_PATH = os.path.join(BASE_DIR, 'tmp', 'oops')
 PUBLIC_URL_PREFIX = 'http://some_url'
 ROOT_USERVOLUME_NAME = 'Magicicada'

=== modified file 'magicicada/settings/api_server.py'
--- magicicada/settings/api_server.py	2015-10-04 15:14:24 +0000
+++ magicicada/settings/api_server.py	2016-08-23 00:49:23 +0000
@@ -43,8 +43,6 @@
 GRACEFUL_SHUTDOWN = True
 HEARTBEAT_INTERVAL = 5
 IDLE_TIMEOUT = 7200
-LOGGER_NAME = 'storage.server'
-LOG_FILENAME = 'filesync-server.log'
 MAGIC_UPLOAD_ACTIVE = True
 MAX_DELTA_INFO = 20
 METRICS_NAMESPACE = 'development.filesync.server'

=== added file 'magicicada/settings/testing.py'
--- magicicada/settings/testing.py	1970-01-01 00:00:00 +0000
+++ magicicada/settings/testing.py	2016-08-23 00:49:23 +0000
@@ -0,0 +1,4 @@
+from magicicada.settings import *  # noqa
+
+LOGGING['handlers']['server']['filename'] = os.path.join(
+    LOG_FOLDER, 'filesync-server-tests.log')

=== modified file 'test'
--- test	2016-05-29 21:23:33 +0000
+++ test	2016-08-23 00:49:23 +0000
@@ -74,10 +74,12 @@
     parser.add_option("-e", "--logs-on-failure", dest="logs_on_failure",
                       action='store_true',
                       help="Show logs on stdout if error or failure")
+    parser.add_option("-v", "--verbosity", dest="verbosity",
+                      type='int', default=1, help="Verbosity, default is 1")
 
     (options, args) = parser.parse_args()
 
-    setup_environment("magicicada.settings")
+    setup_environment("magicicada.settings.testing")
 
     from utilities.testlib import test_with_trial