Ticket #4021: 4021_less_chatty.patch

twisted/internet/protocol.py

@@ -624 +624 @@
         This will be called by makeConnection(), users should not call it.
         """
         if not self.numPorts:
-            if self.noisy:
-                log.msg("Starting protocol %s" % self)
+            log.msg(eventSource=self,
+                    eventType="start",
+                    protocol=self)
             self.startProtocol()
         self.numPorts = self.numPorts + 1
 
@@ -638 +639 @@
         self.numPorts = self.numPorts - 1
         self.transport = None
         if not self.numPorts:
-            if self.noisy:
-                log.msg("Stopping protocol %s" % self)
+            log.msg(eventSource=self,
+                    eventType="stop",
+                    protocol=self)
             self.stopProtocol()
 
     def startProtocol(self):

twisted/internet/tcp.py

@@ -860 +860 @@
         # reflect what the OS actually assigned us.
         self._realPortNumber = skt.getsockname()[1]
 
-        log.msg("%s starting on %s" % (self.factory.__class__, self._realPortNumber))
+        log.msg(eventSource=self,
+                eventType="start",
+                protocol=self.factory,
+                portNumber=self._realPortNumber)
 
         # The order of the next 6 lines is kind of bizarre.  If no one
         # can explain it, perhaps we should re-arrange them.
@@ -975 +978 @@
         """
         Log message for closing port
         """
-        log.msg('(TCP Port %s Closed)' % (self._realPortNumber,))
+        log.msg(eventSource=self,
+                eventType="stop",
+                protocol=self.factory,
+                portNumber=self._realPortNumber)
 
 
     def connectionLost(self, reason):

twisted/internet/test/test_protocol.py

@@ -7 +7 @@
 
 from twisted.python.failure import Failure
 from twisted.internet.defer import CancelledError
-from twisted.internet.protocol import Protocol, ClientCreator
+from twisted.internet.protocol import Protocol, ClientCreator, AbstractDatagramProtocol
 from twisted.internet.task import Clock
 from twisted.trial.unittest import TestCase
 from twisted.test.proto_helpers import MemoryReactor, StringTransport
-
+from twisted.python import log
 
 
 class MemoryConnector:
@@ -331 +331 @@
             return d, factory
         return self._cancelConnectFailedTimeoutTest(connect)
 
+
+class AbstractDatagramProtocolTestCase(TestCase):
+    
+    def setUp(self):
+        """
+        Setup L{twisted.internet.protocol.AbstractDatagramProtocol} object.
+        """
+        self.proto = AbstractDatagramProtocol()
+    
+    def test_doStartLogMsg(self):
+        """
+        Verify that L{twisted.internet.protocol.AbstractDatagramProtocol.doStart}
+        logs an event dictionary with the correct parameters.
+        """
+        
+        loggedDicts = []
+        
+        def logDoStartMsg(eventDict):
+            loggedDicts.append(eventDict)
+        
+        log.addObserver(logDoStartMsg)
+        self.proto.doStart()
+        
+        self.assertTrue(isinstance(loggedDicts[0]["eventSource"],
+                                   AbstractDatagramProtocol))
+        self.assertTrue(isinstance(loggedDicts[0]["protocol"],
+                                   AbstractDatagramProtocol))
+        self.assertEquals(loggedDicts[0]["eventType"], "start")
+    
+    def test_doStopLogMsg(self):
+        """
+        Verify that L{twisted.internet.protocol.AbstractDatagramProtocol.doStop}
+        logs an event dictionary with the correct parameters.
+        """
+        
+        loggedDicts = []
+        
+        def logDoStopMsg(eventDict):
+            loggedDicts.append(eventDict)
+        
+        log.addObserver(logDoStopMsg)
+        self.proto.numPorts = 1
+        self.proto.doStop()
+        
+        self.assertTrue(isinstance(loggedDicts[0]["eventSource"],
+                                   AbstractDatagramProtocol))
+        self.assertTrue(isinstance(loggedDicts[0]["protocol"],
+                                   AbstractDatagramProtocol))
+        self.assertEquals(loggedDicts[0]["eventType"], "stop")
+ No newline at end of file

twisted/internet/test/test_tcp.py

@@ -23 +23 @@
 from twisted.python.failure import Failure
 from twisted.python import log
 from twisted.trial.unittest import SkipTest
+from twisted.internet.tcp import Port
 
 from twisted.test.test_tcp import ClosingProtocol
 from twisted.internet.test.test_core import ObjectModelIntegrationMixin
@@ -322 +323 @@
         Get a TCP port from a reactor
         """
         return reactor.listenTCP(0, ServerFactory())
-
-
-    def getExpectedConnectionLostLogMsg(self, port):
+    
+    def getExpectedConnectionPortNumber(self, port):
+        """
+        Get the expected port number for the TCP port that experienced
+        the connection event.
+        """
+        return port.getHost().port
+    
+    def test_connectionListeningLogMsg(self):
         """
-        Get the expected connection lost message for a TCP port
+        When a connection is made, an informative log dict should be logged
+        (see L{getExpectedConnectionLostLogMsg}) containing: the event source,
+        event type, protocol, and port number.
         """
-        return "(TCP Port %s Closed)" % (port.getHost().port,)
 
+        loggedDicts = []
+        def logConnectionListeningMsg(eventDict):
+            loggedDicts.append(eventDict)
+        
+        log.addObserver(logConnectionListeningMsg)
+        reactor = self.buildReactor()
+        p = self.getListeningPort(reactor)
+        listenPort = self.getExpectedConnectionPortNumber(p)
+        
+
+        def stopReactor(ignored):
+            log.removeObserver(logConnectionListeningMsg)
+            reactor.stop()
+
+        def doStopListening():
+            maybeDeferred(p.stopListening).addCallback(stopReactor)
+
+        reactor.callWhenRunning(doStopListening)
+        reactor.run()
+        
+        dictHits = 0
+        for eventDict in loggedDicts:
+            if eventDict.has_key("portNumber") and \
+               eventDict.has_key("eventSource") and \
+               eventDict.has_key("protocol") and \
+               eventDict.has_key("eventType") and \
+               eventDict["portNumber"] == listenPort and \
+               eventDict["eventType"] == "start" and \
+               isinstance(eventDict["eventSource"], Port) and \
+               isinstance(eventDict["protocol"], ServerFactory):
+                dictHits = dictHits + 1
+        
+        self.assertTrue(dictHits > 0)
 
     def test_connectionLostLogMsg(self):
         """
-        When a connection is lost, an informative message should be logged
-        (see L{getExpectedConnectionLostLogMsg}): an address identifying
-        the port and the fact that it was closed.
+        When a connection is lost, an informative log dict should be logged
+        (see L{getExpectedConnectionLostLogMsg}) containing: the event source,
+        event type, protocol, and port number.
         """
 
-        loggedMessages = []
+        loggedDicts = []
         def logConnectionLostMsg(eventDict):
-            loggedMessages.append(log.textFromEventDict(eventDict))
+            loggedDicts.append(eventDict)
 
         reactor = self.buildReactor()
         p = self.getListeningPort(reactor)
-        expectedMessage = self.getExpectedConnectionLostLogMsg(p)
+        listenPort = self.getExpectedConnectionPortNumber(p)
         log.addObserver(logConnectionLostMsg)
 
         def stopReactor(ignored):
@@ -357 +398 @@
 
         reactor.callWhenRunning(doStopListening)
         reactor.run()
-
-        self.assertIn(expectedMessage, loggedMessages)
+        
+        dictHits = 0
+        for eventDict in loggedDicts:
+            if eventDict.has_key("portNumber") and \
+               eventDict.has_key("eventSource") and \
+               eventDict.has_key("protocol") and \
+               eventDict.has_key("eventType") and \
+               eventDict["portNumber"] == listenPort and \
+               eventDict["eventType"] == "stop" and \
+               isinstance(eventDict["eventSource"], Port) and \
+               isinstance(eventDict["protocol"], ServerFactory):
+                dictHits = dictHits + 1
+        
+        self.assertTrue(dictHits > 0)
 
 
     def test_allNewStyle(self):

twisted/internet/test/test_udp.py

@@ -12 +12 @@
 from twisted.internet.test.reactormixins import ReactorBuilder
 from twisted.internet.interfaces import IListeningPort
 from twisted.internet.protocol import DatagramProtocol
+from twisted.internet.defer import maybeDeferred
+from twisted.internet.udp import Port
+from twisted.python import log
+
 
 class UDPServerTestsBuilder(ReactorBuilder):
     """
@@ -24 +28 @@
         reactor = self.buildReactor()
         port = reactor.listenUDP(0, DatagramProtocol())
         self.assertTrue(verifyObject(IListeningPort, port))
+    
+    def getListeningPort(self, reactor):
+        """
+        Get a TCP port from a reactor
+        """
+        return reactor.listenUDP(0, DatagramProtocol())
+    
+    def getExpectedConnectionPortNumber(self, port):
+        """
+        Get the expected port number for the TCP port that experienced
+        the connection event.
+        """
+        return port.getHost().port
+    
+    def test_connectionListeningLogMsg(self):
+        """
+        When a connection is made, an informative log dict should be logged
+        (see L{getExpectedConnectionLostLogMsg}) containing: the event source,
+        event type, protocol, and port number.
+        """
+
+        loggedDicts = []
+        def logConnectionListeningMsg(eventDict):
+            loggedDicts.append(eventDict)
+        
+        log.addObserver(logConnectionListeningMsg)
+        reactor = self.buildReactor()
+        p = self.getListeningPort(reactor)
+        listenPort = self.getExpectedConnectionPortNumber(p)
+
+        def stopReactor(*ignored):
+            log.removeObserver(logConnectionListeningMsg)
+            reactor.stop()
+
+        reactor.callWhenRunning(stopReactor)
+        reactor.run()
+        
+        dictHits = 0
+        for eventDict in loggedDicts:
+            if eventDict.has_key("portNumber") and \
+               eventDict.has_key("eventSource") and \
+               eventDict.has_key("protocol") and \
+               eventDict.has_key("eventType") and \
+               eventDict["portNumber"] == listenPort and \
+               eventDict["eventType"] == "start" and \
+               isinstance(eventDict["eventSource"], Port) and \
+               isinstance(eventDict["protocol"], DatagramProtocol):
+                dictHits = dictHits + 1
+        
+        self.assertTrue(dictHits > 0)
+
+    def test_connectionLostLogMsg(self):
+        """
+        When a connection is made, an informative log dict should be logged
+        (see L{getExpectedConnectionLostLogMsg}) containing: the event source,
+        event type, protocol, and port number.
+        """
+
+        loggedDicts = []
+        def logConnectionListeningMsg(eventDict):
+            loggedDicts.append(eventDict)
+        
+        log.addObserver(logConnectionListeningMsg)
+        reactor = self.buildReactor()
+        p = self.getListeningPort(reactor)
+        listenPort = self.getExpectedConnectionPortNumber(p)
+
+        def stopReactor(*ignored):
+            p.connectionLost()
+            log.removeObserver(logConnectionListeningMsg)
+            reactor.stop()
+
+        reactor.callWhenRunning(stopReactor)
+        reactor.run()
+        
+        dictHits = 0
+        for eventDict in loggedDicts:
+            if eventDict.has_key("portNumber") and \
+               eventDict.has_key("eventSource") and \
+               eventDict.has_key("protocol") and \
+               eventDict.has_key("eventType") and \
+               eventDict["portNumber"] == listenPort and \
+               eventDict["eventType"] == "stop" and \
+               isinstance(eventDict["eventSource"], Port) and \
+               isinstance(eventDict["protocol"], DatagramProtocol):
+                dictHits = dictHits + 1
+        
+        self.assertTrue(dictHits > 0)
 
 globals().update(UDPServerTestsBuilder.makeTestCaseClasses())

twisted/internet/test/test_unix.py

@@ -22 +22 @@
 from twisted.internet import interfaces
 from twisted.internet.protocol import (
     ServerFactory, ClientFactory, DatagramProtocol)
+from twisted.internet.defer import maybeDeferred
 from twisted.internet.test.reactormixins import ReactorBuilder
 from twisted.internet.test.test_tcp import TCPPortTestsBuilder
-
-
+from twisted.python import log
+from twisted.trial import unittest
 
 class UNIXFamilyMixin:
     """
@@ -152 +153 @@
         Get a UNIX port from a reactor
         """
         return reactor.listenUNIX(self.mktemp(), ServerFactory())
-
-
+    
     def getExpectedConnectionLostLogMsg(self, port):
         """
         Get the expected connection lost message for a UNIX port
         """
         return "(UNIX Port %s Closed)" % (repr(port.port),)
+    
+    def test_connectionListeningLogMsg(self):
+        """
+        When a connection is lost, an informative log dict should be logged
+        (see L{getExpectedConnectionLostLogMsg}) containing: the event source,
+        event type, protocol, and port number.
+        
+        """
+        raise unittest.SkipTest("SKIPPED until UNIX socket protocol adopts" + \
+                                "the passing of an event dictionary to " + \
+                                "log.msg() on start.")
+    
+    def test_connectionLostLogMsg(self):
+        """
+        When a connection is lost, an informative message should be logged
+        (see L{getExpectedConnectionLostLogMsg}): an address identifying
+        the port and the fact that it was closed.
+        """
+
+        loggedMessages = []
+        def logConnectionLostMsg(eventDict):
+            loggedMessages.append(log.textFromEventDict(eventDict))
+
+        reactor = self.buildReactor()
+        p = self.getListeningPort(reactor)
+        expectedMessage = self.getExpectedConnectionLostLogMsg(p)
+        log.addObserver(logConnectionLostMsg)
+
+        def stopReactor(ignored):
+            log.removeObserver(logConnectionLostMsg)
+            reactor.stop()
+
+        def doStopListening():
+            log.addObserver(logConnectionLostMsg)
+            maybeDeferred(p.stopListening).addCallback(stopReactor)
+
+        reactor.callWhenRunning(doStopListening)
+        reactor.run()
+
+        self.assertIn(expectedMessage, loggedMessages)
 
 
 

twisted/internet/udp.py

@@ -95 +95 @@
         # Make sure that if we listened on port 0, we update that to
         # reflect what the OS actually assigned us.
         self._realPortNumber = skt.getsockname()[1]
-
-        log.msg("%s starting on %s"%(self.protocol.__class__, self._realPortNumber))
+        
+        log.msg(eventSource=self,
+                eventType="start",
+                protocol=self.protocol,
+                portNumber=self._realPortNumber)
 
         self.connected = 1
         self.socket = skt
@@ -215 +218 @@
         """
         Cleans up my socket.
         """
-        log.msg('(Port %s Closed)' % self._realPortNumber)
+        log.msg(eventSource=self,
+                eventType="stop",
+                protocol=self.protocol,
+                portNumber=self._realPortNumber)
         self._realPortNumber = None
         base.BasePort.connectionLost(self, reason)
         self.protocol.doStop()