[Twisted-Python] Serial transport protocol logging on Raspberry Pi

Lucas Taylor ltaylor.volks at gmail.com
Fri Aug 23 11:39:16 MDT 2013


I have written a simple serial-to-serial logging proxy in order to discover and document the protocol used by two hardware devices. The goal is to incrementally replace one of the devices with a Twisted application, but right now I'm just trying to gather data.

A RaspberryPi seemed ideal for this given its cost and ability to run python; however, I seem to be running into some kind of timing or data corruption issue that only occurs on the Pi, and only when I am logging data.  The application works well on my dev laptop (OSX), but falters on the Pi.

I can use socat to do raw data collection for this first stage (it works fine on the Pi as a logging proxy), but I was hoping to use Twisted with custom log observers to format the data in ways that might help illuminate the framing of the protocol. The idea was to have the protocol just log and proxy each byte and then I could experiment with a series of observers to identify the patterns (emphasize STX/ETX as possible delimiters, flag this sequence as an 'INIT' sequence, etc..)


The setup:
--------------

[CON-A]  <---->  [SerialSpy (Twisted)]  <----> [CON-B]

When CON-A is powered-on, it goes through an init sequence to establish communication with CON-B and if there are any issues, CON-A gives up and displays an error message. 

When run from my dev laptop (OSX), the data is logged and proxied between the 2 devices without any problems. 

When run on the Pi (Raspbian), back and forth comm is fine for the first 4-5 framed packets (STX...ETX+CKSUM), but then CON-B begins to NAK every packet after that and CON-A gives up.

The total amount of data transferred during a successful init sequence is < 1k:
CON-A: 537 bytes
CON-B: 290 bytes


The app:
------------

A minimal Protocol subclass logs each byte received and writes to its peer.

class ProxyLoggingProtocol(protocol.Protocol, object):
    peer = None

    def __init__(self, name):
        self.name = name

    def dataReceived(self, data):
        """
        Log data received and proxy to peer
        """
        for b in data:
            log.msg(b, system=self.name)

        # Passthrough data to "other" transport
        if self.peer is not None:
            self.peer.transport.write(data)
        else:
            err = ValueError('Peer protocol not set (nowhere to proxy this data)')
            log.err(err)


... setup the protocols and serial transports:

log.startLogging(sys.stdout)

conA = ProxyLoggingProtocol('CON-A-->')
conB = ProxyLoggingProtocol('<--CON-B')
conA.peer = conB
conB.peer = conA

SerialPort(conA,'/dev/ttyUSB0', reactor, ...)
SerialPort(conB, '/dev/ttyUSB1', reactor, ...)

reactor.run()


The Issue?
--------------
It seems that doing anything in dataReceived beyond just proxying bytes from A to B is enough to cause CON-B to interpret received data as either bad or delayed to the point where it returns a NAK. Oddly, the first few framed packets are logged, proxied, and ACKed successfully.

This occurs if I log.startLogging() to a file or stdout. If I never call startLogging(), the data proxies without error.  That is, CON-B replies with positive ACKs and everything works as expected.

I suppose the obvious answer may be that the Pi is underpowered for this task, but I am hoping to better understand why.  I may be able to defer logging to a queue or find other workarounds, but I'd like to figure out why basic usage of logging could be causing this.  Any thoughts as to what I could be looking at next would be appreciated.


Thanks,

Lucas






More information about the Twisted-Python mailing list