Twisted sample request - grouping data from Factory spawned protocols

[Menyadar]

I'm trying to use Eliot mainly to help me follow stream of requests from Twisted protocols, but can't figure a way to do it. Just to make minimal sample, i've modified basic Echo server from twistedmatrix homepage to include Eliot logging:

from twisted.application import service, strports
from twisted.internet import protocol, reactor

from eliot import log_call
from eliot.logwriter import ThreadedWriter, FileDestination

class Echo(protocol.Protocol):
    @log_call
    def dataReceived(self, data):
        self.transport.write(data)

class EchoFactory(protocol.Factory):
    def buildProtocol(self, addr):
        return Echo()

echo = strports.service("tcp:port=1234", EchoFactory())
logger = ThreadedWriter(FileDestination(file=open("eliot.log", "ab")), reactor)

application = service.Application('app')
svc = service.MultiService()
svc.setServiceParent(application)
echo.setServiceParent(svc)
logger.setServiceParent(svc)

When i run it with twistd -noy sample.py and then connect to it, i get each received message logged as single event, even when they are sent from same connection. This is after opening two client connections, first connection received 2 messages, second got one message:

cc947b94-4c10-4884-b06f-ec318972deaa
└── None.Echo.dataReceived/1 ⇒ started 2020-02-25 13:36:10Z ⧖ 0.000s
    ├── data: 123␍…
    └── None.Echo.dataReceived/2 ⇒ succeeded 2020-02-25 13:36:10Z
        └── result: None

49c4162d-177b-45fd-a8a0-ea8b95dfce89
└── None.Echo.dataReceived/1 ⇒ started 2020-02-25 13:36:12Z ⧖ 0.000s
    ├── data: 321␍…
    └── None.Echo.dataReceived/2 ⇒ succeeded 2020-02-25 13:36:12Z
        └── result: None

be96b5ef-ce90-46b6-8125-aa770fc6adb8
└── None.Echo.dataReceived/1 ⇒ started 2020-02-25 13:36:19Z ⧖ 0.000s
    ├── data: 432␍…
    └── None.Echo.dataReceived/2 ⇒ succeeded 2020-02-25 13:36:19Z
        └── result: None

What is the correct way to get all messages from single connection grouped under one "parent" task_uuid? I plan to use mostly existing Twisted factories / protocols.

[itamarst]

from eliot import start_action, log_call

class LoggingWrapper:
    def __init__(self, protocol):
        self.ctx = start_action("protocol_connection")
        self.protocol = protocol
    def __getattr__(self, attr):
        f = getattr(self.protocol, attr)
        if not callable(f): return f
        f = log_call(f)
        return lambda *args, **kwargs: ctx.run(f, *args, **kwargs)

class EchoFactory(protocol.Factory):
    def buildProtocol(self, addr):
        return LoggingWrapper(Echo())

This is untested, mind you.

[itamarst]

Made a bunch of edits, so make sure you use latest version. Probably also want to finish the action on connectionLost, this is just a sketch.

[itamarst]

And even better would be Protocol-y class that just knew to wrap the Protocol-specific methods.

[itamarst]

(I will try to add working version tomorrow.)

[itamarst]

OK, here's someting that I tested and actually works:

class Echo(protocol.Protocol):
    def connectionMade(self):
        self.action = start_action(action_type="protocol:connection")

    def dataReceived(self, data):
        with self.action.context():
            with start_action(action_type="protocol:datareceived",
                              bytes=len(data)):
                self.transport.write(data)

    def connectionLost(self, reason):
        if isinstance(reason.value, ConnectionDone):
            self.action.finish()
        else:
            self.action.finish(reason.value)

[Menyadar]

Thanks a lot. During the day I've come to mostly the same solution based on your first hint. Right now I'm hijacking transport.write/writeSequence to inject logging into outgoing messages.

I assume there is no (easy) way to mix this approach with standard @log_call decorator without rewriting it to somehow pickup self.action as it's context, right?

[itamarst]

Honestly for dataReceived I wouldn't typically want to use log_call, logging every single byte will get very slow very fast for a high-traffic server.

You could write a custom decorator, something like:

from funcutils import wraps

def log_call_with_self_action(f):
    f = log_call(f)
    @wraps(f)
    def wrap(self, *args, **kwargs):
        with self.action.context():
            return f(self, *args, **kwargs)
    return wrap

Untested...

[itamarst]

What're you working on, by the way?

[Menyadar]

@log_call on dataReceived was just an example. I'm working on IMAP server (using twisted.mail.imap4) with quite complex dependencies (pulling messages from multiple sources / dbs, custom caching, etc.) and debugging it with existing clients in heavy load was quite difficult without context-aware logging - each client holds multiple connections open and it gets messy really fast.