Merge lp:~allenap/maas/overhaul-logging-more-03 into lp:~maas-committers/maas/trunk

[Gavin Panella]

Switch all of MAAS over to LegacyLogger, a transitional shim between the legacy Twisted logging module and the new logging system.

[Blake Rouse (blake-rouse)]

Branch looks good. I think that the web requests logging needs to be improved:

2016-11-01 13:32:46 [twisted.python.log#info] ::ffff:127.0.0.1 - - [01/Nov/2016:13:32:45 +0000] "POST /MAAS/metadata/status/htmada/latest HTTP/1.1" 200 2 "-" "Python-urllib/3.5"

"twisted.python.log" is not helpful in anyway.

review: Approve

[Gavin Panella (allenap)]

> "twisted.python.log" is not helpful in anyway.

I agree but let's fix this in a subsequent branch; there are several other such bits that need cleaning up. Thanks for the review!

[MAAS Lander (maas-lander)]

The attempt to merge lp:~allenap/maas/overhaul-logging-more-03 into lp:maas failed. Below is the output from the failed tests.

Hit:1 http://security.ubuntu.com/ubuntu xenial-security InRelease
Hit:2 http://prodstack-zone-2.clouds.archive.ubuntu.com/ubuntu xenial InRelease
Get:3 http://prodstack-zone-2.clouds.archive.ubuntu.com/ubuntu xenial-updates InRelease [95.7 kB]
Get:4 http://prodstack-zone-2.clouds.archive.ubuntu.com/ubuntu xenial-backports InRelease [92.2 kB]
Get:5 http://prodstack-zone-2.clouds.archive.ubuntu.com/ubuntu xenial-updates/main amd64 Packages [416 kB]
Get:6 http://prodstack-zone-2.clouds.archive.ubuntu.com/ubuntu xenial-updates/universe amd64 Packages [356 kB]
Fetched 960 kB in 0s (986 kB/s)
Reading package lists...
sudo DEBIAN_FRONTEND=noninteractive apt-get -y \
    --no-install-recommends install apache2 archdetect-deb authbind avahi-utils bash bind9 bind9utils build-essential bzr bzr-builddeb chromium-browser chromium-chromedriver curl daemontools debhelper dh-apport dh-systemd distro-info dnsutils firefox freeipmi-tools git gjs ipython isc-dhcp-common isc-dhcp-server libjs-angularjs libjs-jquery libjs-jquery-hotkeys libjs-yui3-full libjs-yui3-min libpq-dev make nodejs-legacy npm postgresql pxelinux python3-all python3-apt python3-attr python3-bson python3-convoy python3-crochet python3-cssselect python3-curtin python3-dev python3-distro-info python3-django python3-django-nose python3-django-piston3 python3-dnspython python3-docutils python3-formencode python3-hivex python3-httplib2 python3-jinja2 python3-jsonschema python3-lxml python3-netaddr python3-netifaces python3-novaclient python3-oauth python3-oauthlib python3-openssl python3-paramiko python3-petname python3-pexpect python3-psycopg2 python3-pyinotify python3-pyparsing python3-pyvmomi python3-requests python3-seamicroclient python3-setuptools python3-simplestreams python3-sphinx python3-tempita python3-twisted python3-txtftp python3-tz python3-yaml python3-zope.interface python-bson python-crochet python-django python-django-piston python-djorm-ext-pgarray python-formencode python-lxml python-netaddr python-netifaces python-pocket-lint python-psycopg2 python-simplejson python-tempita python-twisted python-yaml socat syslinux-common tgt ubuntu-cloudimage-keyring wget xvfb
Reading package lists...
Building dependency tree...
Reading state information...
authbind is already the newest version (2.1.1+nmu1).
avahi-utils is already the newest version (0.6.32~rc+dfsg-1ubuntu2).
build-essential is already the newest version (12.1ubuntu2).
debhelper is already the newest version (9.20160115ubuntu3).
distro-info is already the newest version (0.14build1).
freeipmi-tools is already the newest version (1.4.11-1ubuntu1).
git is already the newest version (1:2.7.4-0ubuntu1).
libjs-angularjs is already the newest version (1.2.28-1ubuntu2).
libjs-jquery is already the newest version (1.11.3+dfsg-4).
libjs-yui3-full is already the newest version (3.5.1-1ubuntu3).
libjs-yui3-min is already the newest version (3.5.1-1ubuntu3).
make is already the newest version (4.1-6).
postgresql is already the newest version (9.5+173).
pxelinux is already the newest version (3:6.03+dfsg-11ubun...

=== modified file 'src/maasserver/bootresources.py'
--- src/maasserver/bootresources.py	2016-10-12 15:26:17 +0000
+++ src/maasserver/bootresources.py	2016-11-01 16:47:02 +0000
@@ -88,7 +88,10 @@
 )
 from provisioningserver.import_images.keyrings import write_all_keyrings
 from provisioningserver.import_images.product_mapping import map_products
-from provisioningserver.logger import get_maas_logger
+from provisioningserver.logger import (
+    get_maas_logger,
+    LegacyLogger,
+)
 from provisioningserver.rpc.cluster import (
     ListBootImages,
     ListBootImagesV2,
@@ -116,11 +119,11 @@
     inlineCallbacks,
 )
 from twisted.protocols.amp import UnhandledCommand
-from twisted.python import log
 from twisted.python.failure import Failure
 
 
 maaslog = get_maas_logger("bootresources")
+log = LegacyLogger()
 
 # Used by maasserver.middleware.AccessMiddleware to allow
 # anonymous access to the simplestreams endpoint.

=== modified file 'src/maasserver/clusterrpc/boot_images.py'
--- src/maasserver/clusterrpc/boot_images.py	2016-05-06 09:28:28 +0000
+++ src/maasserver/clusterrpc/boot_images.py	2016-11-01 16:47:02 +0000
@@ -30,6 +30,7 @@
 from maasserver.utils import async
 from maasserver.utils.orm import transactional
 from maasserver.utils.threads import deferToDatabase
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.rpc.cluster import (
     ImportBootImages,
     IsImportBootImagesRunning,
@@ -48,10 +49,12 @@
     DeferredSemaphore,
 )
 from twisted.protocols.amp import UnhandledCommand
-from twisted.python import log
 from twisted.python.failure import Failure
 
 
+log = LegacyLogger()
+
+
 def suppress_failures(responses):
     """Suppress failures returning from an async/gather operation.
 

=== modified file 'src/maasserver/dhcp.py'
--- src/maasserver/dhcp.py	2016-10-12 15:26:17 +0000
+++ src/maasserver/dhcp.py	2016-11-01 16:47:02 +0000
@@ -53,6 +53,7 @@
     IPNetwork,
 )
 from provisioningserver.dhcp.omshell import generate_omapi_key
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.rpc.cluster import (
     ConfigureDHCPv4,
     ConfigureDHCPv4_V2,
@@ -73,7 +74,9 @@
 )
 from twisted.internet.defer import inlineCallbacks
 from twisted.protocols import amp
-from twisted.python import log
+
+
+log = LegacyLogger()
 
 
 def get_omapi_key():
@@ -562,14 +565,14 @@
                 config = get_dhcp_configure_for(
                     4, rack_controller, vlan, subnets_v4, ntp_servers,
                     default_domain, dhcp_snippets)
-            except DHCPConfigurationError as e:
+            except DHCPConfigurationError:
                 # XXX bug #1602412: this silently breaks DHCPv4, but we cannot
                 # allow it to crash here since DHCPv6 might be able to run.
                 # This error may be irrelevant if there is an IPv4 network in
                 # the MAAS model which is not configured on the rack, and the
                 # user only wants to serve DHCPv6. But it is still something
                 # worth noting, so log it and continue.
-                log.err(e)
+                log.err(None, "Failure configuring DHCPv4.")
             else:
                 failover_peer, subnets, hosts, interface = config
                 if failover_peer is not None:
@@ -586,14 +589,14 @@
                 config = get_dhcp_configure_for(
                     6, rack_controller, vlan, subnets_v6,
                     ntp_servers, default_domain, dhcp_snippets)
-            except DHCPConfigurationError as e:
+            except DHCPConfigurationError:
                 # XXX bug #1602412: this silently breaks DHCPv6, but we cannot
                 # allow it to crash here since DHCPv4 might be able to run.
                 # This error may be irrelevant if there is an IPv6 network in
                 # the MAAS model which is not configured on the rack, and the
                 # user only wants to serve DHCPv4. But it is still something
                 # worth noting, so log it and continue.
-                log.err(e)
+                log.err(None, "Failure configuring DHCPv6.")
             else:
                 failover_peer, subnets, hosts, interface = config
                 if failover_peer is not None:

=== modified file 'src/maasserver/dns/publication.py'
--- src/maasserver/dns/publication.py	2016-04-29 20:16:40 +0000
+++ src/maasserver/dns/publication.py	2016-11-01 16:47:02 +0000
@@ -16,12 +16,15 @@
 from maasserver.models.dnspublication import DNSPublication
 from maasserver.utils.orm import transactional
 from maasserver.utils.threads import deferToDatabase
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.utils.twisted import callOut
 from pytz import UTC
 from twisted.application.service import Service
 from twisted.internet import reactor
 from twisted.internet.task import LoopingCall
-from twisted.python import log
+
+
+log = LegacyLogger()
 
 
 class DNSPublicationGarbageService(Service):

=== modified file 'src/maasserver/models/largefile.py'
--- src/maasserver/models/largefile.py	2016-07-30 01:17:54 +0000
+++ src/maasserver/models/largefile.py	2016-11-01 16:47:02 +0000
@@ -26,12 +26,15 @@
     transactional,
 )
 from maasserver.utils.threads import deferToDatabase
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.utils.twisted import (
     asynchronous,
     FOREVER,
 )
 from twisted.internet import reactor
-from twisted.python import log
+
+
+log = LegacyLogger()
 
 
 class FileStorageManager(Manager):

=== modified file 'src/maasserver/models/signals/power.py'
--- src/maasserver/models/signals/power.py	2016-04-23 08:53:54 +0000
+++ src/maasserver/models/signals/power.py	2016-11-01 16:47:02 +0000
@@ -18,6 +18,7 @@
 )
 from maasserver.utils.signals import SignalsManager
 from maasserver.utils.threads import deferToDatabase
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.rpc.exceptions import UnknownPowerType
 from provisioningserver.utils.twisted import (
     asynchronous,
@@ -26,7 +27,9 @@
     synchronous,
 )
 from twisted.internet import reactor
-from twisted.python import log
+
+
+log = LegacyLogger()
 
 
 signals = SignalsManager()

=== modified file 'src/maasserver/plugin.py'
--- src/maasserver/plugin.py	2016-10-19 17:06:30 +0000
+++ src/maasserver/plugin.py	2016-11-01 16:47:02 +0000
@@ -11,6 +11,7 @@
 
 from maasserver.monkey import add_patches_to_django
 from provisioningserver import logger
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.monkey import add_patches_to_twisted
 from provisioningserver.utils.debug import (
     register_sigusr2_thread_dump_handler,
@@ -18,11 +19,13 @@
 from twisted.application.service import IServiceMaker
 from twisted.internet import reactor
 from twisted.plugin import IPlugin
-from twisted.python import log
 from twisted.python.threadable import isInIOThread
 from zope.interface import implementer
 
 
+log = LegacyLogger()
+
+
 class Options(logger.VerbosityOptions):
     """Command-line options for `regiond`."""
 

=== modified file 'src/maasserver/populate_tags.py'
--- src/maasserver/populate_tags.py	2016-10-12 15:26:17 +0000
+++ src/maasserver/populate_tags.py	2016-11-01 16:47:02 +0000
@@ -31,7 +31,10 @@
 )
 from maasserver.rpc import getAllClients
 from maasserver.utils.orm import transactional
-from provisioningserver.logger import get_maas_logger
+from provisioningserver.logger import (
+    get_maas_logger,
+    LegacyLogger,
+)
 from provisioningserver.rpc.cluster import EvaluateTag
 from provisioningserver.tags import (
     DEFAULT_BATCH_SIZE,
@@ -46,10 +49,10 @@
 )
 from provisioningserver.utils.xpath import try_match_xpath
 from twisted.internet.defer import DeferredList
-from twisted.python import log
 
 
 maaslog = get_maas_logger("tags")
+log = LegacyLogger()
 
 
 # The nsmap that XPath expression must be compiled with. This will

=== modified file 'src/maasserver/rack_controller.py'
--- src/maasserver/rack_controller.py	2016-07-20 20:27:50 +0000
+++ src/maasserver/rack_controller.py	2016-11-01 16:47:02 +0000
@@ -43,6 +43,7 @@
 from maasserver.models.node import RackController
 from maasserver.utils.orm import transactional
 from maasserver.utils.threads import deferToDatabase
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.utils.twisted import (
     asynchronous,
     callOut,
@@ -55,7 +56,9 @@
     maybeDeferred,
 )
 from twisted.internet.task import LoopingCall
-from twisted.python import log
+
+
+log = LegacyLogger()
 
 
 class RackControllerService(Service):

=== modified file 'src/maasserver/region_controller.py'
--- src/maasserver/region_controller.py	2016-03-31 20:41:32 +0000
+++ src/maasserver/region_controller.py	2016-11-01 16:47:02 +0000
@@ -27,6 +27,7 @@
 from maasserver.proxyconfig import proxy_update_config
 from maasserver.utils.orm import transactional
 from maasserver.utils.threads import deferToDatabase
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.utils.twisted import (
     asynchronous,
     FOREVER,
@@ -35,7 +36,9 @@
 from twisted.internet import reactor
 from twisted.internet.defer import DeferredList
 from twisted.internet.task import LoopingCall
-from twisted.python import log
+
+
+log = LegacyLogger()
 
 
 class RegionControllerService(Service):

=== modified file 'src/maasserver/regiondservices/active_discovery.py'
--- src/maasserver/regiondservices/active_discovery.py	2016-09-29 00:15:29 +0000
+++ src/maasserver/regiondservices/active_discovery.py	2016-11-01 16:47:02 +0000
@@ -27,13 +27,17 @@
     with_connection,
 )
 from maasserver.utils.threads import deferToDatabase
+from provisioningserver.logger import LegacyLogger
 from twisted.application.internet import TimerService
 from twisted.internet import reactor
 from twisted.internet.defer import (
     inlineCallbacks,
     maybeDeferred,
 )
-from twisted.python import log
+
+
+log = LegacyLogger()
+
 
 # The check interval serves as somewhat of a throttle; normally, we will
 # not scan more than once every CHECK_INTERVAL seconds (unless the discovery

=== modified file 'src/maasserver/regiondservices/ntp.py'
--- src/maasserver/regiondservices/ntp.py	2016-10-03 20:32:26 +0000
+++ src/maasserver/regiondservices/ntp.py	2016-11-01 16:47:02 +0000
@@ -15,6 +15,7 @@
 from maasserver.service_monitor import service_monitor
 from maasserver.utils.orm import transactional
 from maasserver.utils.threads import deferToDatabase
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.ntp.config import configure_region
 from provisioningserver.utils.twisted import (
     callOut,
@@ -23,7 +24,9 @@
 from twisted.application.internet import TimerService
 from twisted.internet.defer import maybeDeferred
 from twisted.internet.threads import deferToThread
-from twisted.python import log
+
+
+log = LegacyLogger()
 
 
 class RegionNetworkTimeProtocolService(TimerService):

=== modified file 'src/maasserver/regiondservices/reverse_dns.py'
--- src/maasserver/regiondservices/reverse_dns.py	2016-10-20 23:17:48 +0000
+++ src/maasserver/regiondservices/reverse_dns.py	2016-11-01 16:47:02 +0000
@@ -15,10 +15,13 @@
     RegionController,
 )
 from maasserver.utils.threads import deferToDatabase
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.utils.network import reverseResolve
 from twisted.application.service import Service
 from twisted.internet.defer import inlineCallbacks
-from twisted.python import log
+
+
+log = LegacyLogger()
 
 
 class ReverseDNSService(Service):

=== modified file 'src/maasserver/regiondservices/service_monitor_service.py'
--- src/maasserver/regiondservices/service_monitor_service.py	2016-08-19 10:22:29 +0000
+++ src/maasserver/regiondservices/service_monitor_service.py	2016-11-01 16:47:02 +0000
@@ -15,10 +15,13 @@
 from maasserver.utils.orm import transactional
 from maasserver.utils.threads import deferToDatabase
 from provisioningserver.config import is_dev_environment
+from provisioningserver.logger import LegacyLogger
 from twisted.application.internet import TimerService
 from twisted.internet import reactor
 from twisted.internet.defer import inlineCallbacks
-from twisted.python import log
+
+
+log = LegacyLogger()
 
 
 class ServiceMonitorService(TimerService, object):

=== modified file 'src/maasserver/rpc/regionservice.py'
--- src/maasserver/rpc/regionservice.py	2016-10-12 15:26:17 +0000
+++ src/maasserver/rpc/regionservice.py	2016-11-01 16:47:02 +0000
@@ -67,6 +67,7 @@
     AddrConversionError,
     IPAddress,
 )
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.rpc import (
     cluster,
     common,
@@ -116,9 +117,12 @@
 from twisted.internet.task import LoopingCall
 from twisted.internet.threads import deferToThread
 from twisted.protocols import amp
-from twisted.python import log
 from zope.interface import implementer
 
+
+log = LegacyLogger()
+
+
 # Number of regiond processes that should be running for a regiond.
 # XXX blake_r 2016-03-10 bug=1555901: It would be better to determine this
 # value from systemd or other means instead of hard coding the number.
@@ -870,7 +874,8 @@
         super(RegionService, self).startService()
         self.starting = defer.DeferredList(
             (self._bindFirst(endpoint_options, self.factory)
-             for endpoint_options in self.endpoints))
+             for endpoint_options in self.endpoints),
+            consumeErrors=True)
 
         def log_failure(failure):
             if failure.check(defer.CancelledError):
@@ -903,7 +908,7 @@
                 try:
                     yield conn.transport.loseConnection()
                 except:
-                    log.err()
+                    log.err(None, "Failure when closing RPC connection.")
         yield super(RegionService, self).stopService()
 
     @asynchronous(timeout=FOREVER)

=== modified file 'src/maasserver/rpc/tests/test_regionservice.py'
--- src/maasserver/rpc/tests/test_regionservice.py	2016-10-12 15:26:17 +0000
+++ src/maasserver/rpc/tests/test_regionservice.py	2016-11-01 16:47:02 +0000
@@ -124,9 +124,7 @@
 from twisted.internet.interfaces import IStreamServerEndpoint
 from twisted.internet.protocol import Factory
 from twisted.internet.task import LoopingCall
-from twisted.logger import globalLogPublisher
 from twisted.protocols import amp
-from twisted.python import log
 from twisted.python.failure import Failure
 from twisted.python.reflect import fullyQualifiedName
 from zope.interface.verify import verifyObject
@@ -661,19 +659,17 @@
         endpoints = self.patch(service, "endpoints", [[Mock()]])
         endpoints[0][0].listen.return_value = fail(exception)
 
-        logged_failures = []
-        self.patch(log, "msg", (
-            lambda failure, **kw: logged_failures.append(failure)))
-
         logged_failures_expected = [
             AfterPreprocessing(
                 (lambda failure: failure.value),
                 Is(exception)),
         ]
 
-        yield service.startService()
+        with TwistedLoggerFixture() as logger:
+            yield service.startService()
+
         self.assertThat(
-            logged_failures, MatchesListwise(logged_failures_expected))
+            logger.failures, MatchesListwise(logged_failures_expected))
 
     @wait_for_reactor
     @inlineCallbacks
@@ -821,12 +817,12 @@
         # Connection-specific errors are logged.
         self.assertDocTestMatches(
             """\
-            Unhandled Error
+            Failure when closing RPC connection.
             Traceback (most recent call last):
             ...
             builtins.OSError: broken
             ...
-            Unhandled Error
+            Failure when closing RPC connection.
             Traceback (most recent call last):
             ...
             builtins.OSError: broken
@@ -841,8 +837,6 @@
         exception = ValueError("This is a very naughty boy.")
         endpoints = self.patch(service, "endpoints", [[Mock()]])
         endpoints[0][0].listen.return_value = fail(exception)
-        # Suppress logged messages.
-        self.patch(globalLogPublisher, "_observers", [])
 
         service.startService()
         # The test is that stopService() succeeds.

=== modified file 'src/maasserver/start_up.py'
--- src/maasserver/start_up.py	2016-06-21 10:36:38 +0000
+++ src/maasserver/start_up.py	2016-11-01 16:47:02 +0000
@@ -27,7 +27,10 @@
     with_connection,
 )
 from maasserver.utils.threads import deferToDatabase
-from provisioningserver.logger import get_maas_logger
+from provisioningserver.logger import (
+    get_maas_logger,
+    LegacyLogger,
+)
 from provisioningserver.utils.twisted import (
     asynchronous,
     FOREVER,
@@ -35,11 +38,11 @@
 )
 from twisted.internet import reactor
 from twisted.internet.defer import inlineCallbacks
-from twisted.python import log
 
 
 maaslog = get_maas_logger("start-up")
 logger = logging.getLogger(__name__)
+log = LegacyLogger()
 
 
 @asynchronous(timeout=FOREVER)

=== modified file 'src/maasserver/utils/async.py'
--- src/maasserver/utils/async.py	2016-09-21 14:14:38 +0000
+++ src/maasserver/utils/async.py	2016-11-01 16:47:02 +0000
@@ -15,6 +15,7 @@
 import threading
 
 from maasserver.exceptions import IteratorReusedError
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.utils.twisted import (
     asynchronous,
     FOREVER,
@@ -27,7 +28,9 @@
     Deferred,
     maybeDeferred,
 )
-from twisted.python import log
+
+
+log = LegacyLogger()
 
 
 class UseOnceIterator:
@@ -118,7 +121,7 @@
             try:
                 deferred.cancel()
             except:
-                log.err()
+                log.err(None, "Failure gathering results.")
 
     if timeout is None:
         canceller = None
@@ -243,12 +246,12 @@
     @asynchronous
     def _cancel_in_reactor(hook):
         hook.addErrback(suppress, CancelledError)
-        hook.addErrback(log.err)
+        hook.addErrback(log.err, "Failure when cancelling hook.")
         try:
             hook.cancel()
         except:
             # The canceller has failed. We take a hint from DeferredList here,
             # by logging the exception and moving on.
-            log.err(_why="Failure when cancelling hook.")
+            log.err(None, "Failure when cancelling hook.")
         else:
             return hook

=== modified file 'src/maasserver/utils/dbtasks.py'
--- src/maasserver/utils/dbtasks.py	2015-12-01 18:12:59 +0000
+++ src/maasserver/utils/dbtasks.py	2016-11-01 16:47:02 +0000
@@ -14,6 +14,7 @@
 ]
 
 from maasserver.utils.threads import deferToDatabase
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.utils.twisted import (
     asynchronous,
     FOREVER,
@@ -24,7 +25,9 @@
     DeferredQueue,
 )
 from twisted.internet.task import cooperate
-from twisted.python import log
+
+
+log = LegacyLogger()
 
 
 class DatabaseTaskAlreadyRunning(Exception):

=== modified file 'src/maasserver/utils/tests/test_async.py'
--- src/maasserver/utils/tests/test_async.py	2016-09-20 00:55:30 +0000
+++ src/maasserver/utils/tests/test_async.py	2016-11-01 16:47:02 +0000
@@ -299,7 +299,7 @@
         self.assertThat(d, IsFiredDeferred())
         self.assertDocTestMatches(
             dedent("""\
-            Unhandled Error
+            Failure when cancelling hook.
             Traceback (most recent call last):
             ...
             maastesting.factory.TestException#...

=== modified file 'src/maasserver/webapp.py'
--- src/maasserver/webapp.py	2016-03-28 13:54:47 +0000
+++ src/maasserver/webapp.py	2016-11-01 16:47:02 +0000
@@ -19,6 +19,7 @@
     lookupProtocolForFactory,
     WebSocketsResource,
 )
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.utils.twisted import (
     asynchronous,
     ThreadPoolLimiter,
@@ -28,10 +29,7 @@
     defer,
     reactor,
 )
-from twisted.python import (
-    failure,
-    log,
-)
+from twisted.python import failure
 from twisted.web.resource import (
     ErrorPage,
     Resource,
@@ -45,6 +43,9 @@
 from twisted.web.wsgi import WSGIResource
 
 
+log = LegacyLogger()
+
+
 class StartPage(ErrorPage, object):
     def __init__(self):
         super(StartPage, self).__init__(

=== modified file 'src/maasserver/websockets/handlers/bootresource.py'
--- src/maasserver/websockets/handlers/bootresource.py	2016-10-17 20:17:10 +0000
+++ src/maasserver/websockets/handlers/bootresource.py	2016-11-01 16:47:02 +0000
@@ -57,6 +57,7 @@
     image_passes_filter,
 )
 from provisioningserver.import_images.keyrings import write_all_keyrings
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.utils.fs import tempdir
 from provisioningserver.utils.twisted import (
     asynchronous,
@@ -64,7 +65,9 @@
     FOREVER,
 )
 from twisted.internet.defer import Deferred
-from twisted.python import log
+
+
+log = LegacyLogger()
 
 
 def get_distro_series_info_row(series):

=== modified file 'src/maasserver/websockets/handlers/machine.py'
--- src/maasserver/websockets/handlers/machine.py	2016-10-24 17:11:57 +0000
+++ src/maasserver/websockets/handlers/machine.py	2016-11-01 16:47:02 +0000
@@ -79,13 +79,12 @@
     node_prefetch,
     NodeHandler,
 )
-from provisioningserver.logger import get_maas_logger
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.rpc.exceptions import UnknownPowerType
 from provisioningserver.utils.twisted import asynchronous
-from twisted.python import log
-
-
-maaslog = get_maas_logger("websockets.machine")
+
+
+log = LegacyLogger()
 
 
 class MachineHandler(NodeHandler):

=== modified file 'src/maasserver/websockets/protocol.py'
--- src/maasserver/websockets/protocol.py	2016-09-07 15:40:52 +0000
+++ src/maasserver/websockets/protocol.py	2016-11-01 16:47:02 +0000
@@ -4,7 +4,8 @@
 """The MAAS WebSockets protocol."""
 
 __all__ = [
-    ]
+    "WebSocketProtocol",
+]
 
 from collections import deque
 from functools import partial
@@ -29,6 +30,7 @@
 from maasserver.utils.threads import deferToDatabase
 from maasserver.websockets import handlers
 from maasserver.websockets.websockets import STATUSES
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.utils import typed
 from provisioningserver.utils.twisted import (
     deferred,
@@ -42,11 +44,13 @@
     Factory,
     Protocol,
 )
-from twisted.python import log
 from twisted.python.modules import getModule
 from twisted.web.server import NOT_DONE_YET
 
 
+log = LegacyLogger()
+
+
 class MSG_TYPE:
     #: Request made from client.
     REQUEST = 0
@@ -126,8 +130,8 @@
 
     def loseConnection(self, status, reason):
         """Close connection with status and reason."""
-        msgFormat = "Closing connection: %(status)r (%(reason)r)"
-        log.msg(format=msgFormat, status=status, reason=reason)
+        msgFormat = "Closing connection: {status!r} ({reason!r})"
+        log.debug(msgFormat, status=status, reason=reason)
         self.transport._receiver._transport.loseConnection(
             status, reason.encode("utf-8"))
 
@@ -321,7 +325,7 @@
             error = failure.getErrorMessage()
         why = "Error on request (%s) %s.%s: %s" % (
             request_id, handler._meta.handler_name, method, error)
-        log.err(failure, _why=why)
+        log.err(failure, why)
 
         error_msg = {
             "type": MSG_TYPE.RESPONSE,

=== modified file 'src/maasserver/websockets/tests/test_protocol.py'
--- src/maasserver/websockets/tests/test_protocol.py	2016-09-14 19:50:53 +0000
+++ src/maasserver/websockets/tests/test_protocol.py	2016-11-01 16:47:02 +0000
@@ -40,6 +40,7 @@
     MockCalledWith,
 )
 from maastesting.testcase import MAASTestCase
+from maastesting.twisted import TwistedLoggerFixture
 from provisioningserver.refresh.node_info_scripts import LSHW_OUTPUT_NAME
 from provisioningserver.utils.twisted import synchronous
 from testtools.matchers import (
@@ -155,15 +156,15 @@
 
     def test_loseConnection_writes_to_log(self):
         protocol, factory = self.make_protocol()
-        mock_log_msg = self.patch_autospec(protocol_module.log, "msg")
         status = random.randint(1000, 1010)
         reason = maas_factory.make_name("reason")
-        protocol.loseConnection(status, reason)
+        with TwistedLoggerFixture() as logger:
+            protocol.loseConnection(status, reason)
         self.assertThat(
-            mock_log_msg,
-            MockCalledOnceWith(
-                format="Closing connection: %(status)r (%(reason)r)",
-                status=status, reason=reason))
+            logger.messages, Equals([
+                "Closing connection: %(status)r (%(reason)r)"
+                % dict(status=status, reason=reason),
+            ]))
 
     def test_loseConnection_calls_loseConnection_with_status_and_reason(self):
         protocol, factory = self.make_protocol()

=== modified file 'src/maasserver/websockets/tests/test_websockets.py'
--- src/maasserver/websockets/tests/test_websockets.py	2016-09-29 16:30:55 +0000
+++ src/maasserver/websockets/tests/test_websockets.py	2016-11-01 16:47:02 +0000
@@ -28,13 +28,13 @@
     WebSocketsTransport,
 )
 from maastesting.testcase import MAASTestCase
+from maastesting.twisted import TwistedLoggerFixture
 from testtools.matchers import StartsWith
 from twisted.internet.protocol import (
     Factory,
     Protocol,
 )
 from twisted.protocols.tls import TLSMemoryBIOProtocol
-from twisted.python import log
 from twisted.test.proto_helpers import (
     AccumulatingProtocol,
     StringTransportWithDisconnection,
@@ -396,18 +396,13 @@
         When a C{CLOSE} frame is received, the protocol closes the connection
         and logs a message.
         """
-        loggedMessages = []
-
-        def logConnectionLostMsg(eventDict):
-            loggedMessages.append(log.textFromEventDict(eventDict))
-
-        log.addObserver(logConnectionLostMsg)
-
-        self.protocol.dataReceived(
-            _makeFrame(b"", CONTROLS.CLOSE, True, mask=b"abcd"))
+        with TwistedLoggerFixture() as logger:
+            self.protocol.dataReceived(
+                _makeFrame(b"", CONTROLS.CLOSE, True, mask=b"abcd"))
         self.assertFalse(self.transport.connected)
-        self.assertEqual(["Closing connection: <STATUSES=NONE>"],
-                         loggedMessages)
+        self.assertEqual(
+            ["Closing connection: <STATUSES=NONE>"],
+            logger.messages)
 
     def test_invalidFrame(self):
         """

=== modified file 'src/maasserver/websockets/websockets.py'
--- src/maasserver/websockets/websockets.py	2016-09-30 13:23:30 +0000
+++ src/maasserver/websockets/websockets.py	2016-11-01 16:47:02 +0000
@@ -27,10 +27,10 @@
     Sequence,
 )
 
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.utils import typed
 from twisted.internet.protocol import Protocol
 from twisted.protocols.tls import TLSMemoryBIOProtocol
-from twisted.python import log
 from twisted.python.constants import (
     ValueConstant,
     Values,
@@ -45,6 +45,9 @@
 )
 
 
+log = LegacyLogger()
+
+
 class _WSException(Exception):
     """
     Internal exception for control flow inside the WebSockets frame parser.
@@ -392,7 +395,7 @@
         Log the new connection and initialize the buffer list.
         """
         peer = self.transport.getPeer()
-        log.msg(format="Opening connection with %(peer)s", peer=peer)
+        log.debug("Opening connection with {peer}", peer=peer)
         self._buffer = []
         self._receiver.makeConnection(WebSocketsTransport(self.transport))
 
@@ -405,10 +408,10 @@
             if opcode == CONTROLS.CLOSE:
                 # The other side wants us to close.
                 code, reason = data
-                msgFormat = "Closing connection: %(code)r"
+                msgFormat = "Closing connection: {code!r}"
                 if reason:
-                    msgFormat += " (%(reason)r)"
-                log.msg(format=msgFormat, reason=reason, code=code)
+                    msgFormat += " ({reason!r})"
+                log.debug(msgFormat, reason=reason, code=code)
 
                 # Close the connection.
                 self.transport.loseConnection()

=== modified file 'src/maastesting/testcase.py'
--- src/maastesting/testcase.py	2016-09-17 20:11:23 +0000
+++ src/maastesting/testcase.py	2016-11-01 16:47:02 +0000
@@ -28,11 +28,17 @@
     MAASTwistedRunTest,
 )
 from maastesting.scenarios import WithScenarios
+from maastesting.twisted import TwistedLoggerFixture
 from nose.proxy import ResultProxy
 from nose.tools import nottest
 import testresources
 import testtools
+from testtools.content import (
+    Content,
+    UTF8_TEXT,
+)
 import testtools.matchers
+from twisted.logger import formatEventAsClassicLogText
 
 
 @nottest
@@ -139,6 +145,13 @@
             return MAASRunTest
 
     def setUp(self):
+        # Capture Twisted logs and add them as a test detail.
+        twistedLog = self.useFixture(TwistedLoggerFixture())
+        self.addDetail("Twisted logs", Content(
+            UTF8_TEXT, lambda: (
+                formatEventAsClassicLogText(event).encode("utf-8")
+                for event in twistedLog.events)))
+
         self.maybeCheckTableRowCounts()
         self.maybeCloseDatabaseConnections()
         super(MAASTestCase, self).setUp()

=== modified file 'src/maastesting/twisted.py'
--- src/maastesting/twisted.py	2016-10-24 14:01:30 +0000
+++ src/maastesting/twisted.py	2016-11-01 16:47:02 +0000
@@ -18,7 +18,10 @@
 from testtools.deferredruntest import CaptureTwistedLogs
 from testtools.twistedsupport._deferred import extract_result
 from twisted.internet import defer
-from twisted.logger import LogLevel
+from twisted.logger import (
+    formatEvent,
+    LogLevel,
+)
 from twisted.python import log
 
 
@@ -47,17 +50,20 @@
         super(TwistedLoggerFixture, self).__init__()
         self.events = []
 
-    def dump(self):
-        """Return all logs as a string."""
-        return "\n---\n".join(
-            log.textFromEventDict(event) for event in self.events)
+    @property
+    def messages(self):
+        """Return a list of events formatted with `t.logger.formatEvent`.
 
-    # For compatibility with fixtures.FakeLogger.
-    output = property(dump)
+        This returns a list of *strings*, not event dictionaries.
+        """
+        return [formatEvent(event) for event in self.events]
 
     @property
     def errors(self):
-        """Return events that are at `LogLevel.error` or above."""
+        """Return a list of events that are at `LogLevel.error` or above.
+
+        This returns a list of event *dictionaries*, not strings.
+        """
         return [
             event for event in self.events
             if "log_level" in event and
@@ -65,8 +71,34 @@
             event["log_level"] >= LogLevel.error
         ]
 
-    def containsError(self):
-        return any(event["isError"] for event in self.events)
+    @property
+    def failures(self):
+        """Return a list of `Failure` instances from events."""
+
+        def find_failure(event):
+            if "failure" in event:
+                return event["failure"]
+            elif "log_failure" in event:
+                return event["log_failure"]
+            else:
+                return None
+
+        failures = map(find_failure, self.events)
+        return [failure for failure in failures if failure is not None]
+
+    def dump(self):
+        """Return a string of events formatted with `textFromEventDict`.
+
+        This returns a single string, where each log message is separated from
+        the next by a line containing "---". Formatting is done by Twisted's
+        *legacy* log machinery, which may or may not differ from the modern
+        machinery.
+        """
+        return "\n---\n".join(
+            log.textFromEventDict(event) for event in self.events)
+
+    # For compatibility with fixtures.FakeLogger.
+    output = property(dump)
 
     def setUp(self):
         super(TwistedLoggerFixture, self).setUp()

=== modified file 'src/provisioningserver/dhcp/detect.py'
--- src/provisioningserver/dhcp/detect.py	2016-10-05 01:31:22 +0000
+++ src/provisioningserver/dhcp/detect.py	2016-11-01 16:47:02 +0000
@@ -22,7 +22,10 @@
 
 import attr
 from netaddr import IPAddress
-from provisioningserver.logger import get_maas_logger
+from provisioningserver.logger import (
+    get_maas_logger,
+    LegacyLogger,
+)
 from provisioningserver.utils.dhcp import DHCP
 from twisted.internet import reactor
 from twisted.internet.defer import (
@@ -38,17 +41,11 @@
     blockingCallFromThread,
     deferToThread,
 )
-from twisted.python import log
 from twisted.python.failure import Failure
 
 
-_LOG_SYSTEM = "dhcp.detect"
-maaslog = get_maas_logger(_LOG_SYSTEM)
-
-
-def _log_msg(*args, **kwargs):
-    """Log to the Twisted logger using a unique `system` name."""
-    log.msg(*args, system=_LOG_SYSTEM, **kwargs)
+maaslog = get_maas_logger("dhcp.detect")
+log = LegacyLogger()
 
 
 def make_dhcp_transaction_id() -> bytes:
@@ -358,10 +355,10 @@
                 else:
                     offer = DHCP(data)
                     if not offer.is_valid():
-                        _log_msg(
-                            "Invalid DHCP response received from %s on '%s': "
-                            "%s" % (
-                                address, self.ifname, offer.invalid_reason))
+                        log.info(
+                            "Invalid DHCP response received from {address} "
+                            "on '{ifname}': {reason}", address=address,
+                            ifname=self.ifname, reason=offer.invalid_reason)
                     elif offer.packet.xid == xid:
                         # Offer matches our transaction ID, so check if it has
                         # a Server Identifier option.
@@ -390,7 +387,7 @@
             # has already been called.
             return None
         elif failure.check(DHCPProbeException):
-            _log_msg("DHCP probe failed. %s" % failure.getErrorMessage())
+            log.msg("DHCP probe failed. %s" % failure.getErrorMessage())
         elif failure.check(CancelledError):
             # Intentionally cancelled; no need to spam the log.
             pass
@@ -450,9 +447,10 @@
         """
         servers = yield deferToThread(self.send_requests_and_await_replies)
         if len(servers) > 0:
-            _log_msg(
-                "External DHCP server(s) discovered on interface '%s': %s"
-                % (self.ifname, ', '.join(str(server) for server in servers)))
+            log.info(
+                "External DHCP server(s) discovered on interface '{ifname}': "
+                "{servers}", ifname=self.ifname, servers=', '.join(
+                    str(server) for server in servers))
         self.servers = servers
 
     @property

=== modified file 'src/provisioningserver/import_images/download_resources.py'
--- src/provisioningserver/import_images/download_resources.py	2016-10-12 15:26:17 +0000
+++ src/provisioningserver/import_images/download_resources.py	2016-11-01 16:47:02 +0000
@@ -17,6 +17,7 @@
     get_signing_policy,
     maaslog,
 )
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.utils import in_develop_mode
 from provisioningserver.utils.shell import call_and_check
 from simplestreams.contentsource import FdContentSource
@@ -30,7 +31,9 @@
     path_from_mirror_url,
     products_exdata,
 )
-from twisted.python import log
+
+
+log = LegacyLogger()
 
 
 DEFAULT_KEYRING_PATH = "/usr/share/keyrings"

=== modified file 'src/provisioningserver/logger/__init__.py'
--- src/provisioningserver/logger/__init__.py	2016-10-25 14:00:30 +0000
+++ src/provisioningserver/logger/__init__.py	2016-11-01 16:47:02 +0000
@@ -51,6 +51,7 @@
 __all__ = [
     "configure",
     "get_maas_logger",
+    "LegacyLogger",
     "LoggingMode",
     "VerbosityOptions",
 ]
@@ -63,6 +64,7 @@
 from provisioningserver.logger._tftp import configure_tftp_logging
 from provisioningserver.logger._twisted import (
     configure_twisted_logging,
+    LegacyLogger,
     VerbosityOptions,
 )
 from provisioningserver.utils import typed

=== modified file 'src/provisioningserver/logger/_common.py'
--- src/provisioningserver/logger/_common.py	2016-10-25 13:30:27 +0000
+++ src/provisioningserver/logger/_common.py	2016-11-01 16:47:02 +0000
@@ -100,3 +100,12 @@
             asctime=time.strftime(DEFAULT_LOG_FORMAT_DATE, time.localtime()),
             name="global", levelname="warn", message=message)
         print(message, file=sys.__stdout__, flush=True)
+
+
+def is_dev_environment():
+    """Is this the development environment, or production?
+
+    Lazy import to avoid circular import issues.
+    """
+    from provisioningserver.config import is_dev_environment
+    return is_dev_environment()

=== modified file 'src/provisioningserver/logger/_django.py'
--- src/provisioningserver/logger/_django.py	2016-10-25 13:30:27 +0000
+++ src/provisioningserver/logger/_django.py	2016-11-01 16:47:02 +0000
@@ -9,8 +9,8 @@
 
 import warnings
 
-from provisioningserver.config import is_dev_environment
 from provisioningserver.logger._common import (
+    is_dev_environment,
     LoggingMode,
     warn_unless,
 )

=== modified file 'src/provisioningserver/logger/_logging.py'
--- src/provisioningserver/logger/_logging.py	2016-10-25 13:36:56 +0000
+++ src/provisioningserver/logger/_logging.py	2016-11-01 16:47:02 +0000
@@ -12,11 +12,11 @@
 import logging.handlers
 import sys
 
-from provisioningserver.config import is_dev_environment
 from provisioningserver.logger._common import (
     DEFAULT_LOG_FORMAT,
     DEFAULT_LOG_FORMAT_DATE,
     DEFAULT_LOG_VERBOSITY_LEVELS,
+    is_dev_environment,
     LoggingMode,
 )
 from provisioningserver.utils import typed

=== modified file 'src/provisioningserver/logger/_twisted.py'
--- src/provisioningserver/logger/_twisted.py	2016-10-26 08:54:13 +0000
+++ src/provisioningserver/logger/_twisted.py	2016-11-01 16:47:02 +0000
@@ -185,7 +185,7 @@
         return super().__call__(event)
 
 
-class LegacyLogger:
+class LegacyLogger(twistedModern.Logger):
     """Looks like a stripped-down `t.p.log` module, logs to a `Logger`.
 
     Use this with code that cannot easily be changed to use `twisted.logger`
@@ -193,7 +193,7 @@
     """
 
     @classmethod
-    def install(cls, module, attribute="log", *, observer=None):
+    def install(cls, module, attribute="log", *, source=None, observer=None):
         """Install a `LegacyLogger` at `module.attribute`.
 
         Warns if `module.attribute` does not exist, but carries on anyway.
@@ -201,8 +201,8 @@
         :param module: A module (or any other object with assignable
             attributes and a `__name__`).
         :param attribute: The name of the attribute on `module` to replace.
-        :param observer: A (modern) logging observer to use. If not specified
-            the global log publisher will be used.
+        :param source: See `Logger.__init__`.
+        :param observer: See `Logger.__init__`.
         :return: The newly created `LegacyLogger`.
         """
         replacing = getattr(module, attribute, "<not-found>")
@@ -210,14 +210,9 @@
             "Legacy logger being installed to replace %r but expected a "
             "reference to twisted.python.log module; please investigate!"
             % (replacing,)))
-        modernLogger = twistedModern.Logger(module.__name__, observer=observer)
-        legacyLogger = cls(modernLogger)
-        setattr(module, attribute, legacyLogger)
-        return legacyLogger
-
-    def __init__(self, logger: twistedModern.Logger):
-        super(LegacyLogger, self).__init__()
-        self.logger = logger
+        logger = cls(module.__name__, source=source, observer=observer)
+        setattr(module, attribute, logger)
+        return logger
 
     def msg(self, *message, **kwargs):
         """Write a message to the log.
@@ -228,14 +223,14 @@
         """
         fmt = " ".join("{_message_%d}" % i for i, _ in enumerate(message))
         kwargs.update({"_message_%d" % i: m for i, m in enumerate(message)})
-        self.logger.info(fmt, **kwargs)
+        self.info(fmt, **kwargs)
 
     def err(self, _stuff=None, _why=None, **kwargs):
         """Write a failure to the log.
 
         See `twisted.python.log.err`.
         """
-        self.logger.failure("{_why}", _stuff, _why=_why, **kwargs)
+        self.failure("{_why}", _stuff, _why=_why, **kwargs)
 
 
 class VerbosityOptions(usage.Options):

=== modified file 'src/provisioningserver/logger/tests/test__twisted.py'
--- src/provisioningserver/logger/tests/test__twisted.py	2016-10-26 09:12:47 +0000
+++ src/provisioningserver/logger/tests/test__twisted.py	2016-11-01 16:47:02 +0000
@@ -261,8 +261,7 @@
     def test__logs_messages(self):
         events = []
         namespace = factory.make_name("namespace")
-        modern_logger = logger.Logger(namespace, self, events.append)
-        legacy_logger = LegacyLogger(modern_logger)
+        legacy_logger = LegacyLogger(namespace, self, events.append)
         message = factory.make_name("message")
         keywords = {
             factory.make_name("key"): factory.make_name("value")
@@ -274,7 +273,7 @@
         expected = {
             'log_format': Equals('{_message_0}'),
             'log_level': Equals(logger.LogLevel.info),
-            'log_logger': Is(modern_logger),
+            'log_logger': Is(legacy_logger),
             'log_namespace': Equals(namespace),
             'log_source': Is(self),
             'log_time': IsInstance(float),
@@ -292,8 +291,7 @@
 
     def test__logs_multiple_messages(self):
         events = []
-        modern_logger = logger.Logger(observer=events.append)
-        legacy_logger = LegacyLogger(modern_logger)
+        legacy_logger = LegacyLogger(observer=events.append)
         messages = [
             factory.make_name("message"),
             factory.make_name("message"),
@@ -317,8 +315,7 @@
     def test__logs_errors(self):
         events = []
         namespace = factory.make_name("namespace")
-        modern_logger = logger.Logger(namespace, self, events.append)
-        legacy_logger = LegacyLogger(modern_logger)
+        legacy_logger = LegacyLogger(namespace, self, events.append)
         message = factory.make_name("message")
         exception_type = factory.make_exception_type()
         keywords = {
@@ -341,7 +338,7 @@
             ),
             'log_format': Equals('{_why}'),
             'log_level': Equals(logger.LogLevel.critical),
-            'log_logger': Is(modern_logger),
+            'log_logger': Is(legacy_logger),
             'log_namespace': Equals(namespace),
             'log_source': Is(self),
             'log_time': IsInstance(float),

=== modified file 'src/provisioningserver/power/change.py'
--- src/provisioningserver/power/change.py	2016-10-25 13:57:02 +0000
+++ src/provisioningserver/power/change.py	2016-11-01 16:47:02 +0000
@@ -19,7 +19,10 @@
     EVENT_TYPES,
     send_event_node,
 )
-from provisioningserver.logger import get_maas_logger
+from provisioningserver.logger import (
+    get_maas_logger,
+    LegacyLogger,
+)
 from provisioningserver.power import query
 from provisioningserver.rpc import getRegionClient
 from provisioningserver.rpc.exceptions import (
@@ -40,10 +43,10 @@
     returnValue,
 )
 from twisted.internet.task import deferLater
-from twisted.python import log
 
 
 maaslog = get_maas_logger("power")
+log = LegacyLogger()
 
 
 # Timeout for change_power_state(). We set it to 5 minutes by default,

=== modified file 'src/provisioningserver/rackdservices/dhcp_probe_service.py'
--- src/provisioningserver/rackdservices/dhcp_probe_service.py	2016-10-25 19:10:55 +0000
+++ src/provisioningserver/rackdservices/dhcp_probe_service.py	2016-11-01 16:47:02 +0000
@@ -12,7 +12,10 @@
 
 from provisioningserver.config import is_dev_environment
 from provisioningserver.dhcp.detect import probe_interface
-from provisioningserver.logger import get_maas_logger
+from provisioningserver.logger import (
+    get_maas_logger,
+    LegacyLogger,
+)
 from provisioningserver.rpc.exceptions import NoConnectionsAvailable
 from provisioningserver.rpc.region import ReportForeignDHCPServer
 from provisioningserver.utils.network import (
@@ -30,10 +33,10 @@
 )
 from twisted.internet.threads import deferToThread
 from twisted.protocols.amp import UnhandledCommand
-from twisted.python import log
 
 
 maaslog = get_maas_logger("dhcp.probe")
+log = LegacyLogger()
 
 
 class DHCPProbeService(TimerService):

=== modified file 'src/provisioningserver/rackdservices/image_download_service.py'
--- src/provisioningserver/rackdservices/image_download_service.py	2016-03-28 13:54:47 +0000
+++ src/provisioningserver/rackdservices/image_download_service.py	2016-11-01 16:47:02 +0000
@@ -11,7 +11,10 @@
 from datetime import timedelta
 
 from provisioningserver.boot import tftppath
-from provisioningserver.logger import get_maas_logger
+from provisioningserver.logger import (
+    get_maas_logger,
+    LegacyLogger,
+)
 from provisioningserver.rpc.boot_images import import_boot_images
 from provisioningserver.rpc.exceptions import NoConnectionsAvailable
 from provisioningserver.rpc.region import (
@@ -29,10 +32,10 @@
     returnValue,
 )
 from twisted.protocols.amp import UnhandledCommand
-from twisted.python import log
 
 
 maaslog = get_maas_logger("boot_image_download_service")
+log = LegacyLogger()
 
 
 class ImageDownloadService(TimerService, object):

=== modified file 'src/provisioningserver/rackdservices/node_power_monitor_service.py'
--- src/provisioningserver/rackdservices/node_power_monitor_service.py	2016-10-25 13:57:02 +0000
+++ src/provisioningserver/rackdservices/node_power_monitor_service.py	2016-11-01 16:47:02 +0000
@@ -10,7 +10,10 @@
 
 from datetime import timedelta
 
-from provisioningserver.logger import get_maas_logger
+from provisioningserver.logger import (
+    get_maas_logger,
+    LegacyLogger,
+)
 from provisioningserver.power.query import query_all_nodes
 from provisioningserver.rpc import getRegionClient
 from provisioningserver.rpc.exceptions import (
@@ -21,10 +24,10 @@
 from twisted.application.internet import TimerService
 from twisted.internet.defer import inlineCallbacks
 from twisted.internet.error import ConnectionDone
-from twisted.python import log
 
 
 maaslog = get_maas_logger("power_monitor_service")
+log = LegacyLogger()
 
 
 class NodePowerMonitorService(TimerService, object):

=== modified file 'src/provisioningserver/rackdservices/ntp.py'
--- src/provisioningserver/rackdservices/ntp.py	2016-10-04 11:50:27 +0000
+++ src/provisioningserver/rackdservices/ntp.py	2016-11-01 16:47:02 +0000
@@ -10,6 +10,7 @@
 from datetime import timedelta
 
 import attr
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.ntp.config import configure_rack
 from provisioningserver.rpc import exceptions
 from provisioningserver.rpc.region import (
@@ -24,7 +25,9 @@
     maybeDeferred,
 )
 from twisted.internet.threads import deferToThread
-from twisted.python import log
+
+
+log = LegacyLogger()
 
 
 class RackNetworkTimeProtocolService(TimerService):

=== modified file 'src/provisioningserver/rackdservices/service_monitor_service.py'
--- src/provisioningserver/rackdservices/service_monitor_service.py	2016-08-19 10:22:29 +0000
+++ src/provisioningserver/rackdservices/service_monitor_service.py	2016-11-01 16:47:02 +0000
@@ -12,7 +12,10 @@
 from datetime import timedelta
 
 from provisioningserver.config import is_dev_environment
-from provisioningserver.logger import get_maas_logger
+from provisioningserver.logger import (
+    get_maas_logger,
+    LegacyLogger,
+)
 from provisioningserver.rpc.exceptions import NoConnectionsAvailable
 from provisioningserver.rpc.region import UpdateServices
 from provisioningserver.service_monitor import service_monitor
@@ -22,10 +25,10 @@
 )
 from twisted.application.internet import TimerService
 from twisted.internet.defer import inlineCallbacks
-from twisted.python import log
 
 
 maaslog = get_maas_logger("service_monitor_service")
+log = LegacyLogger()
 
 
 class ServiceMonitorService(TimerService, object):

=== modified file 'src/provisioningserver/rackdservices/tftp.py'
--- src/provisioningserver/rackdservices/tftp.py	2016-10-25 13:57:02 +0000
+++ src/provisioningserver/rackdservices/tftp.py	2016-11-01 16:47:02 +0000
@@ -25,7 +25,10 @@
     send_event_node_mac_address,
 )
 from provisioningserver.kernel_opts import KernelParameters
-from provisioningserver.logger import get_maas_logger
+from provisioningserver.logger import (
+    get_maas_logger,
+    LegacyLogger,
+)
 from provisioningserver.rpc.boot_images import list_boot_images
 from provisioningserver.rpc.exceptions import BootConfigNoResponse
 from provisioningserver.rpc.region import (
@@ -65,11 +68,11 @@
     returnValue,
 )
 from twisted.internet.task import deferLater
-from twisted.python import log
 from twisted.python.filepath import FilePath
 
 
 maaslog = get_maas_logger("tftp")
+log = LegacyLogger()
 
 
 def get_boot_image(params):

=== modified file 'src/provisioningserver/rpc/boot_images.py'
--- src/provisioningserver/rpc/boot_images.py	2016-07-28 16:42:04 +0000
+++ src/provisioningserver/rpc/boot_images.py	2016-11-01 16:47:02 +0000
@@ -16,6 +16,7 @@
 from provisioningserver.boot import tftppath
 from provisioningserver.config import ClusterConfiguration
 from provisioningserver.import_images import boot_resources
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.rpc import getRegionClient
 from provisioningserver.rpc.region import UpdateLastImageSync
 from provisioningserver.utils.env import (
@@ -28,7 +29,9 @@
     inlineCallbacks,
 )
 from twisted.internet.threads import deferToThread
-from twisted.python import log
+
+
+log = LegacyLogger()
 
 
 CACHED_BOOT_IMAGES = None

=== modified file 'src/provisioningserver/rpc/clusterservice.py'
--- src/provisioningserver/rpc/clusterservice.py	2016-10-25 13:57:02 +0000
+++ src/provisioningserver/rpc/clusterservice.py	2016-11-01 16:47:02 +0000
@@ -40,7 +40,10 @@
 from provisioningserver.drivers.power import power_drivers_by_name
 from provisioningserver.drivers.power.mscm import probe_and_enlist_mscm
 from provisioningserver.drivers.power.msftocs import probe_and_enlist_msftocs
-from provisioningserver.logger import get_maas_logger
+from provisioningserver.logger import (
+    get_maas_logger,
+    LegacyLogger,
+)
 from provisioningserver.power.change import maybe_change_power_state
 from provisioningserver.power.query import get_power_state
 from provisioningserver.refresh import (
@@ -115,22 +118,19 @@
 )
 from twisted.internet.threads import deferToThread
 from twisted.protocols import amp
-from twisted.python import log
 from twisted.python.failure import Failure
 from twisted.python.reflect import fullyQualifiedName
 from twisted.web import http
 import twisted.web.client
-from twisted.web.client import getPage
+from twisted.web.client import (
+    getPage,
+    URI,
+)
 from zope.interface import implementer
 
-# From python-twisted 15+ changes the name of _URI to URI.
-try:
-    from twisted.web.client import _URI as URI
-except ImportError:
-    from twisted.web.client import URI
-
 
 maaslog = get_maas_logger("rpc.cluster")
+log = LegacyLogger()
 
 
 def catch_probe_and_enlist_error(name, failure):
@@ -1132,7 +1132,7 @@
                         log.msg("Event-loop %s (%s:%d): %s" % (
                             eventloop, host, port, error))
                     except:
-                        log.err()
+                        log.err(None, "Failure making new RPC connection.")
                     else:
                         break
         # Remove connections to event-loops that are no longer

=== modified file 'src/provisioningserver/rpc/common.py'
--- src/provisioningserver/rpc/common.py	2016-08-19 10:22:29 +0000
+++ src/provisioningserver/rpc/common.py	2016-11-01 16:47:02 +0000
@@ -13,6 +13,7 @@
 from os import getpid
 from socket import gethostname
 
+from provisioningserver.logger import LegacyLogger
 from provisioningserver.rpc.interfaces import (
     IConnection,
     IConnectionToRegion,
@@ -20,10 +21,12 @@
 from provisioningserver.utils.twisted import asynchronous
 from twisted.internet.defer import Deferred
 from twisted.protocols import amp
-from twisted.python import log
 from twisted.python.failure import Failure
 
 
+log = LegacyLogger()
+
+
 class Identify(amp.Command):
     """Request the identity of the remote side, e.g. its UUID.
 

=== modified file 'src/provisioningserver/rpc/tests/test_clusterservice.py'
--- src/provisioningserver/rpc/tests/test_clusterservice.py	2016-10-20 15:34:08 +0000
+++ src/provisioningserver/rpc/tests/test_clusterservice.py	2016-11-01 16:47:02 +0000
@@ -650,7 +650,7 @@
 
         self.assertDocTestMatches(
             """\
-            Unhandled Error
+            Failure making new RPC connection.
             Traceback (most recent call last):
             ...
             builtins.RuntimeError: Something went wrong.

=== modified file 'src/provisioningserver/utils/services.py'
--- src/provisioningserver/utils/services.py	2016-10-25 13:57:02 +0000
+++ src/provisioningserver/utils/services.py	2016-11-01 16:47:02 +0000
@@ -18,7 +18,10 @@
 import re
 
 from provisioningserver.config import is_dev_environment
-from provisioningserver.logger import get_maas_logger
+from provisioningserver.logger import (
+    get_maas_logger,
+    LegacyLogger,
+)
 from provisioningserver.rpc.exceptions import NoConnectionsAvailable
 from provisioningserver.utils.fs import (
     get_maas_provision_command,
@@ -46,11 +49,11 @@
 )
 from twisted.internet.protocol import ProcessProtocol
 from twisted.internet.threads import deferToThread
-from twisted.python import log
 from twisted.python.failure import Failure
 
 
 maaslog = get_maas_logger("networks.monitor")
+log = LegacyLogger()
 
 
 class JSONPerLineProtocol(ProcessProtocol):

=== modified file 'src/provisioningserver/utils/twisted.py'
--- src/provisioningserver/utils/twisted.py	2016-10-24 14:36:30 +0000
+++ src/provisioningserver/utils/twisted.py	2016-11-01 16:47:02 +0000
@@ -52,6 +52,7 @@
 import threading
 
 from crochet import run_in_reactor
+from provisioningserver.logger import LegacyLogger
 from twisted.internet import reactor
 from twisted.internet.defer import (
     AlreadyCalledError,
@@ -66,7 +67,6 @@
 from twisted.logger import Logger
 from twisted.python import (
     context,
-    log,
     threadable,
     threadpool,
 )
@@ -75,6 +75,9 @@
 from zope import interface
 
 
+log = LegacyLogger()
+
+
 undefined = object()
 FOREVER = object()
 LONGTIME = 60 * 60 * 24 * 7 * 4  # 4 weeks.