Ticket #4021: 4021_less_chatty.patch

File 4021_less_chatty.patch, 17.0 KB (added by jasonjwwilliams, 3 years ago)

Implements less chatty logging messages for TCP/UDP protocol start/stop. Logs an event dictionary.

  • twisted/internet/protocol.py

    diff --git a/twisted/internet/protocol.py b/twisted/internet/protocol.py
    index 79b0718..fbeefad 100644
    a b class AbstractDatagramProtocol: 
    624624        This will be called by makeConnection(), users should not call it. 
    625625        """ 
    626626        if not self.numPorts: 
    627             if self.noisy: 
    628                 log.msg("Starting protocol %s" % self) 
     627            log.msg(eventSource=self, 
     628                    eventType="start", 
     629                    protocol=self) 
    629630            self.startProtocol() 
    630631        self.numPorts = self.numPorts + 1 
    631632 
    class AbstractDatagramProtocol: 
    638639        self.numPorts = self.numPorts - 1 
    639640        self.transport = None 
    640641        if not self.numPorts: 
    641             if self.noisy: 
    642                 log.msg("Stopping protocol %s" % self) 
     642            log.msg(eventSource=self, 
     643                    eventType="stop", 
     644                    protocol=self) 
    643645            self.stopProtocol() 
    644646 
    645647    def startProtocol(self): 
  • twisted/internet/tcp.py

    diff --git a/twisted/internet/tcp.py b/twisted/internet/tcp.py
    index 222ae9b..d9602ba 100644
    a b class Port(base.BasePort, _SocketCloser): 
    860860        # reflect what the OS actually assigned us. 
    861861        self._realPortNumber = skt.getsockname()[1] 
    862862 
    863         log.msg("%s starting on %s" % (self.factory.__class__, self._realPortNumber)) 
     863        log.msg(eventSource=self, 
     864                eventType="start", 
     865                protocol=self.factory, 
     866                portNumber=self._realPortNumber) 
    864867 
    865868        # The order of the next 6 lines is kind of bizarre.  If no one 
    866869        # can explain it, perhaps we should re-arrange them. 
    class Port(base.BasePort, _SocketCloser): 
    975978        """ 
    976979        Log message for closing port 
    977980        """ 
    978         log.msg('(TCP Port %s Closed)' % (self._realPortNumber,)) 
     981        log.msg(eventSource=self, 
     982                eventType="stop", 
     983                protocol=self.factory, 
     984                portNumber=self._realPortNumber) 
    979985 
    980986 
    981987    def connectionLost(self, reason): 
  • twisted/internet/test/test_protocol.py

    diff --git a/twisted/internet/test/test_protocol.py b/twisted/internet/test/test_protocol.py
    index 238a6f9..eb5fa22 100644
    a b Tests for L{twisted.internet.protocol}. 
    77 
    88from twisted.python.failure import Failure 
    99from twisted.internet.defer import CancelledError 
    10 from twisted.internet.protocol import Protocol, ClientCreator 
     10from twisted.internet.protocol import Protocol, ClientCreator, AbstractDatagramProtocol 
    1111from twisted.internet.task import Clock 
    1212from twisted.trial.unittest import TestCase 
    1313from twisted.test.proto_helpers import MemoryReactor, StringTransport 
    14  
     14from twisted.python import log 
    1515 
    1616 
    1717class MemoryConnector: 
    class ClientCreatorTests(TestCase): 
    331331            return d, factory 
    332332        return self._cancelConnectFailedTimeoutTest(connect) 
    333333 
     334 
     335class AbstractDatagramProtocolTestCase(TestCase): 
     336     
     337    def setUp(self): 
     338        """ 
     339        Setup L{twisted.internet.protocol.AbstractDatagramProtocol} object. 
     340        """ 
     341        self.proto = AbstractDatagramProtocol() 
     342     
     343    def test_doStartLogMsg(self): 
     344        """ 
     345        Verify that L{twisted.internet.protocol.AbstractDatagramProtocol.doStart} 
     346        logs an event dictionary with the correct parameters. 
     347        """ 
     348         
     349        loggedDicts = [] 
     350         
     351        def logDoStartMsg(eventDict): 
     352            loggedDicts.append(eventDict) 
     353         
     354        log.addObserver(logDoStartMsg) 
     355        self.proto.doStart() 
     356         
     357        self.assertTrue(isinstance(loggedDicts[0]["eventSource"], 
     358                                   AbstractDatagramProtocol)) 
     359        self.assertTrue(isinstance(loggedDicts[0]["protocol"], 
     360                                   AbstractDatagramProtocol)) 
     361        self.assertEquals(loggedDicts[0]["eventType"], "start") 
     362     
     363    def test_doStopLogMsg(self): 
     364        """ 
     365        Verify that L{twisted.internet.protocol.AbstractDatagramProtocol.doStop} 
     366        logs an event dictionary with the correct parameters. 
     367        """ 
     368         
     369        loggedDicts = [] 
     370         
     371        def logDoStopMsg(eventDict): 
     372            loggedDicts.append(eventDict) 
     373         
     374        log.addObserver(logDoStopMsg) 
     375        self.proto.numPorts = 1 
     376        self.proto.doStop() 
     377         
     378        self.assertTrue(isinstance(loggedDicts[0]["eventSource"], 
     379                                   AbstractDatagramProtocol)) 
     380        self.assertTrue(isinstance(loggedDicts[0]["protocol"], 
     381                                   AbstractDatagramProtocol)) 
     382        self.assertEquals(loggedDicts[0]["eventType"], "stop") 
     383 No newline at end of file 
  • twisted/internet/test/test_tcp.py

    diff --git a/twisted/internet/test/test_tcp.py b/twisted/internet/test/test_tcp.py
    index 19f861d..3000889 100644
    a b from twisted.python.runtime import platform 
    2323from twisted.python.failure import Failure 
    2424from twisted.python import log 
    2525from twisted.trial.unittest import SkipTest 
     26from twisted.internet.tcp import Port 
    2627 
    2728from twisted.test.test_tcp import ClosingProtocol 
    2829from twisted.internet.test.test_core import ObjectModelIntegrationMixin 
    class TCPPortTestsBuilder(ReactorBuilder, ObjectModelIntegrationMixin): 
    322323        Get a TCP port from a reactor 
    323324        """ 
    324325        return reactor.listenTCP(0, ServerFactory()) 
    325  
    326  
    327     def getExpectedConnectionLostLogMsg(self, port): 
     326     
     327    def getExpectedConnectionPortNumber(self, port): 
     328        """ 
     329        Get the expected port number for the TCP port that experienced 
     330        the connection event. 
     331        """ 
     332        return port.getHost().port 
     333     
     334    def test_connectionListeningLogMsg(self): 
    328335        """ 
    329         Get the expected connection lost message for a TCP port 
     336        When a connection is made, an informative log dict should be logged 
     337        (see L{getExpectedConnectionLostLogMsg}) containing: the event source, 
     338        event type, protocol, and port number. 
    330339        """ 
    331         return "(TCP Port %s Closed)" % (port.getHost().port,) 
    332340 
     341        loggedDicts = [] 
     342        def logConnectionListeningMsg(eventDict): 
     343            loggedDicts.append(eventDict) 
     344         
     345        log.addObserver(logConnectionListeningMsg) 
     346        reactor = self.buildReactor() 
     347        p = self.getListeningPort(reactor) 
     348        listenPort = self.getExpectedConnectionPortNumber(p) 
     349         
     350 
     351        def stopReactor(ignored): 
     352            log.removeObserver(logConnectionListeningMsg) 
     353            reactor.stop() 
     354 
     355        def doStopListening(): 
     356            maybeDeferred(p.stopListening).addCallback(stopReactor) 
     357 
     358        reactor.callWhenRunning(doStopListening) 
     359        reactor.run() 
     360         
     361        dictHits = 0 
     362        for eventDict in loggedDicts: 
     363            if eventDict.has_key("portNumber") and \ 
     364               eventDict.has_key("eventSource") and \ 
     365               eventDict.has_key("protocol") and \ 
     366               eventDict.has_key("eventType") and \ 
     367               eventDict["portNumber"] == listenPort and \ 
     368               eventDict["eventType"] == "start" and \ 
     369               isinstance(eventDict["eventSource"], Port) and \ 
     370               isinstance(eventDict["protocol"], ServerFactory): 
     371                dictHits = dictHits + 1 
     372         
     373        self.assertTrue(dictHits > 0) 
    333374 
    334375    def test_connectionLostLogMsg(self): 
    335376        """ 
    336         When a connection is lost, an informative message should be logged 
    337         (see L{getExpectedConnectionLostLogMsg}): an address identifying 
    338         the port and the fact that it was closed. 
     377        When a connection is lost, an informative log dict should be logged 
     378        (see L{getExpectedConnectionLostLogMsg}) containing: the event source, 
     379        event type, protocol, and port number. 
    339380        """ 
    340381 
    341         loggedMessages = [] 
     382        loggedDicts = [] 
    342383        def logConnectionLostMsg(eventDict): 
    343             loggedMessages.append(log.textFromEventDict(eventDict)) 
     384            loggedDicts.append(eventDict) 
    344385 
    345386        reactor = self.buildReactor() 
    346387        p = self.getListeningPort(reactor) 
    347         expectedMessage = self.getExpectedConnectionLostLogMsg(p) 
     388        listenPort = self.getExpectedConnectionPortNumber(p) 
    348389        log.addObserver(logConnectionLostMsg) 
    349390 
    350391        def stopReactor(ignored): 
    class TCPPortTestsBuilder(ReactorBuilder, ObjectModelIntegrationMixin): 
    357398 
    358399        reactor.callWhenRunning(doStopListening) 
    359400        reactor.run() 
    360  
    361         self.assertIn(expectedMessage, loggedMessages) 
     401         
     402        dictHits = 0 
     403        for eventDict in loggedDicts: 
     404            if eventDict.has_key("portNumber") and \ 
     405               eventDict.has_key("eventSource") and \ 
     406               eventDict.has_key("protocol") and \ 
     407               eventDict.has_key("eventType") and \ 
     408               eventDict["portNumber"] == listenPort and \ 
     409               eventDict["eventType"] == "stop" and \ 
     410               isinstance(eventDict["eventSource"], Port) and \ 
     411               isinstance(eventDict["protocol"], ServerFactory): 
     412                dictHits = dictHits + 1 
     413         
     414        self.assertTrue(dictHits > 0) 
    362415 
    363416 
    364417    def test_allNewStyle(self): 
  • twisted/internet/test/test_udp.py

    diff --git a/twisted/internet/test/test_udp.py b/twisted/internet/test/test_udp.py
    index 5a6ae53..dc7042e 100644
    a b from zope.interface.verify import verifyObject 
    1212from twisted.internet.test.reactormixins import ReactorBuilder 
    1313from twisted.internet.interfaces import IListeningPort 
    1414from twisted.internet.protocol import DatagramProtocol 
     15from twisted.internet.defer import maybeDeferred 
     16from twisted.internet.udp import Port 
     17from twisted.python import log 
     18 
    1519 
    1620class UDPServerTestsBuilder(ReactorBuilder): 
    1721    """ 
    class UDPServerTestsBuilder(ReactorBuilder): 
    2428        reactor = self.buildReactor() 
    2529        port = reactor.listenUDP(0, DatagramProtocol()) 
    2630        self.assertTrue(verifyObject(IListeningPort, port)) 
     31     
     32    def getListeningPort(self, reactor): 
     33        """ 
     34        Get a TCP port from a reactor 
     35        """ 
     36        return reactor.listenUDP(0, DatagramProtocol()) 
     37     
     38    def getExpectedConnectionPortNumber(self, port): 
     39        """ 
     40        Get the expected port number for the TCP port that experienced 
     41        the connection event. 
     42        """ 
     43        return port.getHost().port 
     44     
     45    def test_connectionListeningLogMsg(self): 
     46        """ 
     47        When a connection is made, an informative log dict should be logged 
     48        (see L{getExpectedConnectionLostLogMsg}) containing: the event source, 
     49        event type, protocol, and port number. 
     50        """ 
     51 
     52        loggedDicts = [] 
     53        def logConnectionListeningMsg(eventDict): 
     54            loggedDicts.append(eventDict) 
     55         
     56        log.addObserver(logConnectionListeningMsg) 
     57        reactor = self.buildReactor() 
     58        p = self.getListeningPort(reactor) 
     59        listenPort = self.getExpectedConnectionPortNumber(p) 
     60 
     61        def stopReactor(*ignored): 
     62            log.removeObserver(logConnectionListeningMsg) 
     63            reactor.stop() 
     64 
     65        reactor.callWhenRunning(stopReactor) 
     66        reactor.run() 
     67         
     68        dictHits = 0 
     69        for eventDict in loggedDicts: 
     70            if eventDict.has_key("portNumber") and \ 
     71               eventDict.has_key("eventSource") and \ 
     72               eventDict.has_key("protocol") and \ 
     73               eventDict.has_key("eventType") and \ 
     74               eventDict["portNumber"] == listenPort and \ 
     75               eventDict["eventType"] == "start" and \ 
     76               isinstance(eventDict["eventSource"], Port) and \ 
     77               isinstance(eventDict["protocol"], DatagramProtocol): 
     78                dictHits = dictHits + 1 
     79         
     80        self.assertTrue(dictHits > 0) 
     81 
     82    def test_connectionLostLogMsg(self): 
     83        """ 
     84        When a connection is made, an informative log dict should be logged 
     85        (see L{getExpectedConnectionLostLogMsg}) containing: the event source, 
     86        event type, protocol, and port number. 
     87        """ 
     88 
     89        loggedDicts = [] 
     90        def logConnectionListeningMsg(eventDict): 
     91            loggedDicts.append(eventDict) 
     92         
     93        log.addObserver(logConnectionListeningMsg) 
     94        reactor = self.buildReactor() 
     95        p = self.getListeningPort(reactor) 
     96        listenPort = self.getExpectedConnectionPortNumber(p) 
     97 
     98        def stopReactor(*ignored): 
     99            p.connectionLost() 
     100            log.removeObserver(logConnectionListeningMsg) 
     101            reactor.stop() 
     102 
     103        reactor.callWhenRunning(stopReactor) 
     104        reactor.run() 
     105         
     106        dictHits = 0 
     107        for eventDict in loggedDicts: 
     108            if eventDict.has_key("portNumber") and \ 
     109               eventDict.has_key("eventSource") and \ 
     110               eventDict.has_key("protocol") and \ 
     111               eventDict.has_key("eventType") and \ 
     112               eventDict["portNumber"] == listenPort and \ 
     113               eventDict["eventType"] == "stop" and \ 
     114               isinstance(eventDict["eventSource"], Port) and \ 
     115               isinstance(eventDict["protocol"], DatagramProtocol): 
     116                dictHits = dictHits + 1 
     117         
     118        self.assertTrue(dictHits > 0) 
    27119 
    28120globals().update(UDPServerTestsBuilder.makeTestCaseClasses()) 
  • twisted/internet/test/test_unix.py

    diff --git a/twisted/internet/test/test_unix.py b/twisted/internet/test/test_unix.py
    index 8485285..356007d 100644
    a b from twisted.internet.address import UNIXAddress 
    2222from twisted.internet import interfaces 
    2323from twisted.internet.protocol import ( 
    2424    ServerFactory, ClientFactory, DatagramProtocol) 
     25from twisted.internet.defer import maybeDeferred 
    2526from twisted.internet.test.reactormixins import ReactorBuilder 
    2627from twisted.internet.test.test_tcp import TCPPortTestsBuilder 
    27  
    28  
     28from twisted.python import log 
     29from twisted.trial import unittest 
    2930 
    3031class UNIXFamilyMixin: 
    3132    """ 
    class UNIXPortTestsBuilder(TCPPortTestsBuilder): 
    152153        Get a UNIX port from a reactor 
    153154        """ 
    154155        return reactor.listenUNIX(self.mktemp(), ServerFactory()) 
    155  
    156  
     156     
    157157    def getExpectedConnectionLostLogMsg(self, port): 
    158158        """ 
    159159        Get the expected connection lost message for a UNIX port 
    160160        """ 
    161161        return "(UNIX Port %s Closed)" % (repr(port.port),) 
     162     
     163    def test_connectionListeningLogMsg(self): 
     164        """ 
     165        When a connection is lost, an informative log dict should be logged 
     166        (see L{getExpectedConnectionLostLogMsg}) containing: the event source, 
     167        event type, protocol, and port number. 
     168         
     169        """ 
     170        raise unittest.SkipTest("SKIPPED until UNIX socket protocol adopts" + \ 
     171                                "the passing of an event dictionary to " + \ 
     172                                "log.msg() on start.") 
     173     
     174    def test_connectionLostLogMsg(self): 
     175        """ 
     176        When a connection is lost, an informative message should be logged 
     177        (see L{getExpectedConnectionLostLogMsg}): an address identifying 
     178        the port and the fact that it was closed. 
     179        """ 
     180 
     181        loggedMessages = [] 
     182        def logConnectionLostMsg(eventDict): 
     183            loggedMessages.append(log.textFromEventDict(eventDict)) 
     184 
     185        reactor = self.buildReactor() 
     186        p = self.getListeningPort(reactor) 
     187        expectedMessage = self.getExpectedConnectionLostLogMsg(p) 
     188        log.addObserver(logConnectionLostMsg) 
     189 
     190        def stopReactor(ignored): 
     191            log.removeObserver(logConnectionLostMsg) 
     192            reactor.stop() 
     193 
     194        def doStopListening(): 
     195            log.addObserver(logConnectionLostMsg) 
     196            maybeDeferred(p.stopListening).addCallback(stopReactor) 
     197 
     198        reactor.callWhenRunning(doStopListening) 
     199        reactor.run() 
     200 
     201        self.assertIn(expectedMessage, loggedMessages) 
    162202 
    163203 
    164204 
  • twisted/internet/udp.py

    diff --git a/twisted/internet/udp.py b/twisted/internet/udp.py
    index 3a21453..c4d4eda 100644
    a b class Port(base.BasePort): 
    9595        # Make sure that if we listened on port 0, we update that to 
    9696        # reflect what the OS actually assigned us. 
    9797        self._realPortNumber = skt.getsockname()[1] 
    98  
    99         log.msg("%s starting on %s"%(self.protocol.__class__, self._realPortNumber)) 
     98         
     99        log.msg(eventSource=self, 
     100                eventType="start", 
     101                protocol=self.protocol, 
     102                portNumber=self._realPortNumber) 
    100103 
    101104        self.connected = 1 
    102105        self.socket = skt 
    class Port(base.BasePort): 
    215218        """ 
    216219        Cleans up my socket. 
    217220        """ 
    218         log.msg('(Port %s Closed)' % self._realPortNumber) 
     221        log.msg(eventSource=self, 
     222                eventType="stop", 
     223                protocol=self.protocol, 
     224                portNumber=self._realPortNumber) 
    219225        self._realPortNumber = None 
    220226        base.BasePort.connectionLost(self, reason) 
    221227        self.protocol.doStop()