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

[Gavin Panella]

Log TFTP requests to the server log.

[Blake Rouse (blake-rouse)]

Looks good.

review: Approve

=== modified file 'src/maastesting/twisted.py'
--- src/maastesting/twisted.py	2016-11-01 16:46:49 +0000
+++ src/maastesting/twisted.py	2016-11-01 16:46:50 +0000
@@ -16,10 +16,12 @@
 
 from fixtures import Fixture
 from testtools.deferredruntest import CaptureTwistedLogs
+from testtools.monkey import patch
 from testtools.twistedsupport._deferred import extract_result
 from twisted.internet import defer
 from twisted.logger import (
     formatEvent,
+    globalLogPublisher,
     LogLevel,
 )
 from twisted.python import log
@@ -106,6 +108,8 @@
         for observer in list(log.theLogPublisher.observers):
             self.addCleanup(log.theLogPublisher.addObserver, observer)
             log.theLogPublisher.removeObserver(observer)
+        # Now remove any remaining modern observers.
+        self.addCleanup(patch(globalLogPublisher, "_observers", []))
         # Now add our observer, again via the legacy API. This ensures that
         # it's wrapped with whatever legacy wrapper we've installed.
         self.addCleanup(log.theLogPublisher.removeObserver, self.events.append)

=== modified file 'src/provisioningserver/rackdservices/tests/test_tftp.py'
--- src/provisioningserver/rackdservices/tests/test_tftp.py	2016-07-30 01:17:54 +0000
+++ src/provisioningserver/rackdservices/tests/test_tftp.py	2016-11-01 16:46:50 +0000
@@ -723,6 +723,17 @@
             mac_address=sentinel.macaddr, description=sentinel.filename,
             event_type=EVENT_TYPES.NODE_TFTP_REQUEST))
 
+    def test__logs_to_server_log(self):
+        self.patch(tftp_module, "send_event_node_mac_address")
+        clock = Clock()
+        mac_address = factory.make_mac_address()
+        file_name = factory.make_name("file")
+        with TwistedLoggerFixture() as logger:
+            log_request(mac_address, file_name, clock)
+            clock.advance(0.0)  # Don't leave anything in the reactor.
+        self.assertThat(logger.output, Equals(
+            "%s requested by %s" % (file_name, mac_address)))
+
     def test__logs_when_sending_event_errors(self):
         send_event = self.patch(tftp_module, "send_event_node_mac_address")
         send_event.side_effect = factory.make_exception()

=== modified file 'src/provisioningserver/rackdservices/tftp.py'
--- src/provisioningserver/rackdservices/tftp.py	2016-11-01 16:46:49 +0000
+++ src/provisioningserver/rackdservices/tftp.py	2016-11-01 16:46:50 +0000
@@ -113,13 +113,19 @@
 def log_request(mac_address, file_name, clock=reactor):
     """Log a TFTP request.
 
-    This will be logged at a later iteration of the `clock` so as to not delay
-    the task currently in progress.
+    This will be logged to the regular log, and also to the node event log at
+    a later iteration of the `clock` so as to not delay the task currently in
+    progress.
     """
     # If the file name is a byte string, decode it as ASCII, replacing
     # non-ASCII characters, so that we have at least something to log.
     if isinstance(file_name, bytes):
         file_name = file_name.decode("ascii", "replace")
+    # Log to the regular log.
+    log.info(
+        "{file_name} requested by {mac_address}", file_name=file_name,
+        mac_address=mac_address)
+    # Log to the node event log.
     d = deferLater(
         clock, 0, send_event_node_mac_address,
         event_type=EVENT_TYPES.NODE_TFTP_REQUEST,