Printing to different log file based on connection in Twisted client application

Question

I have the following code for a TCP client in my Twisted application:

from twisted.internet import reactor, protocol
from twisted.python import log
import time

class EchoClient(protocol.Protocol):
    def connectionMade(self):
        if(self.factory.server_name == 'server1'):
          log.startLogging(open('server1.log','w'))
        else:
          log.startLogging(open('server2.log','w'))
        log.msg("Connected to "+self.factory.server_name)

    def connectionLost(self,reason):
        log.msg("Connection is lost " + reason.getErrorMessage())

    def dataReceived(self,data):
        log.msg("Server said: " + data)

class EchoFactory(protocol.ClientFactory):
    def __init__(self,server_name):
        self.server_name = server_name

    def buildProtocol(self, addr):
        client = EchoClient()
        client.factory = self
        return client

    def clientConnectionFailed(self, connector, reason):
        reactor.stop()

    def clientConnectionLost(self, connector, reason):
        time.sleep(10)
        connector.connect()

conn1 = EchoFactory('server1')
conn2 = EchoFactory('server2')

reactor.connectTCP("localhost",8000,conn1)
reactor.connectTCP("localhost",8001,conn2)

reactor.run()

Now when I run the program I see that server1.log has both the Connected to server1 and Connected to server2 lines, whereas server2.log only has Connected to server2.

How can i fix this? Thanks.

Answer 1

The problem that you're having here is that log.startLogging is meant to be called once per process lifetime, to open a single log file. If you think about it, how is Twisted supposed to know what log file a particular log.msg call should go to in your example? You're not passing a log file or any information about which one to use.

There are also a number of things about your example which are using very old-fashioned Twisted idioms, so I'm going to completely overhaul this example to use newer Twisted APIs:

1. Rather than using the old and busted twisted.python.log module, I'm going to use the new logging hotness in twisted.logger.
2. Rather than use the old and busted IReactorTCP.connectTCP, I'm going to use Endpoints which have a number of advantages.
3. Rather than importing the reactor and running it directly, I'm going to use twisted.internet.task.react so that I'm relying on the global reactor (which is bad).

There are also a couple of things that you're doing which were always a bad idea in Twisted:

1. You should never use time.sleep() in any Twisted program, ever. It blocks the entire reactor, which means that all outstanding tasks in your Twisted program (excepting those in threads) are stopped while you wait for it. There are asynchronous APIs, such as deferLater, that you can use to deal with the passage of time.
2. You should never use string formatting to put together log messages. twisted.logger makes this a bit easier and has nicer syntax, but even with twisted.python.log has always had support for structured data in log messages.
3. You have 2-space indents in a couple of places. For shame :).

I'm going to answer your question by using the Twisted logging system, but emitting logs from your connections only to dedicated observers. The reason that I'm doing this is that it's somewhat tricky to intercept log messages destined for the global log and convince the existing global logging infrastructure that it shouldn't write those messages to the main log file. This is by design: once logging is set up, it often serves as catch-all that is necessary to catch the messages leading up to an error. Another potential answer would be to simply open a text file from each connection and not involve Twisted's logging system at all.

Here's an example of how to do this:

import io

from twisted.internet import protocol
from twisted.logger import Logger, jsonFileLogObserver

class EchoClient(protocol.Protocol):
    log = Logger()

    def connectionMade(self):
        log = self.log
        log.observer = jsonFileLogObserver(
            io.open(self.factory.server_name + ".json.log", "tw")
        )
        self.log = log

        self.log.info("Connected to {log_source.factory.server_name}")

    def dataReceived(self, data):
        self.log.info("server said: {data!r}",
                      data=data)

    def connectionLost(self, reason):
        self.log.info("Connection is lost: {reason}",
                      reason=reason)

class EchoFactory(protocol.Factory):
    protocol = EchoClient
    def __init__(self, server_name):
        self.server_name = server_name

from twisted.internet.task import react
from twisted.internet.endpoints import HostnameEndpoint
from twisted.internet.defer import Deferred

def main(reactor):
    for portNumber in 8001, 8002:
        endpoint = HostnameEndpoint(reactor, "localhost", portNumber)
        endpoint.connect(
            EchoFactory("server_" + str(portNumber - 8000))
        )
    return Deferred()

react(main)

Note that in connectionMade, we get the Logger instance with self.log, but since the class attribute EchoClient.log is a descriptor, it's creating a new instance each time. To ensure that our modified observer attribute state is persisted, we re-assign self.log to the resulting object.

This will produce some log files which contain rich structured information, but may be somewhat hard for humans to read. If all you really care about is literal text log files to be read by people, and you don't want to do any log analysis, you can just use textFileLogObserver rather than jsonFileLogObserver; however, with a tiny bit of code, you can get the best of both worlds. Here's a very short program that will read one of the log files produced here and emit classic log text that a person could read or pipe to grep:

import io
from twisted.logger import eventsFromJSONLogFile, formatEventAsClassicLogText

for event in eventsFromJSONLogFile(io.open("server_1.json.log", "rt")):
    print(formatEventAsClassicLogText(event))