Learn how easy it is to sync an existing GitHub or Google Code repo to a SourceForge project! See Demo

Close

#44 Input buffer flooded

closed
nobody
None
5
2014-12-07
2011-03-16
nate
No

Hi,
I am attempting to talk to several lab devices with rs232 ports/usb-serial cables,
and python on OSX. The goal is for my code run a long time, but I randomly come
across a problem(especially with intensive use) where the input buffer gets flooded,
which corrupts any communications from the serial port.

OS: Mac OSX
python: v2.6.1

**********
Here's the script I use to show a proper run and a corrupt run:

#!/usr/bin/python
import serial,time
tm = time.time()
def ct() : return (time.time()-tm)
def dm(txt) : print '%8.6f %s'%(ct(),txt)
dm('Init') # initialize serial port
s = serial.Serial()
s.baudrate = 115200
s.port = '/dev/tty.PL2303-001013FD'
s.timeout = 0.0000001
s.open()

dm('flushInput()') # flush input buffer
s.flushInput()
for i in range (7) : # check that input buffer is clear
dm('afterflush: inWaiting: %i'%s.inWaiting())
dm('Start Transfer')
dm(' pre: inWaiting():%i'%s.inWaiting())
s.write( 'FD\r' ) # tell device to start the data transfer

for i in range(2000) : # read in data bytes
byte = s.read()
if byte != '' :
dm(' (byte,inWaiting) = (%6s,%4i)'%(repr(byte),s.inWaiting()))

dm('Stop Transfer') # send order to stop data transfer
dm(' pre: inWaiting():%i'%s.inWaiting())
s.write( 'LO\r' )
for i in range(20000) :
byte = s.read()
if byte != '':
dm(' byte:%s'% repr(byte))
dm(' post: inWaiting():%i'%s.inWaiting())

s.close()

*************************************************

Here's the output of that script when everything is fine. In this run,
s.inWaiting() generally reports that no bytes ever build up in the
receiving buffer, and the data bytes from the buffer make sense. The
numbers on the left-hand side is the time in seconds since the script
started.
************

[nckelley@HawcMobile01 trunk]$ ./fail_radiometer
0.000003 Init
0.124702 flushInput() <-- flushes receive buffer, for a clean start
0.124791 afterflush: inWaiting: 0 <-- number of bytes waiting in receive buffer
0.124817 afterflush: inWaiting: 0
0.124842 afterflush: inWaiting: 0
0.124866 afterflush: inWaiting: 0
0.124888 afterflush: inWaiting: 0
0.124909 afterflush: inWaiting: 0
0.124933 afterflush: inWaiting: 0
0.124945 Start Transfer <-- sent a command to start data transfer
0.124968 pre: inWaiting():0
0.125748 (byte,inWaiting) = ( '*', 0) <-- '*' = start command acknowledged
0.125845 (byte,inWaiting) = ( '\r', 0) <-- '\r' = termination character
0.131674 (byte,inWaiting) = ( 'a', 0) <-- (data bytes , # bytes waiting in receive buffer)
0.131740 (byte,inWaiting) = ( 'H', 0) |
0.134131 (byte,inWaiting) = ( '`', 0) |
0.134215 (byte,inWaiting) = ( 'H', 0) V
0.136739 (byte,inWaiting) = ( '^', 0)
0.136838 (byte,inWaiting) = ( 'H', 0)
0.139235 (byte,inWaiting) = ( '`', 0)
0.139367 (byte,inWaiting) = ( 'H', 0)
0.141724 (byte,inWaiting) = ( '`', 0)
0.141858 (byte,inWaiting) = ( 'H', 0)
0.144319 (byte,inWaiting) = ( '\\', 0)
0.144480 (byte,inWaiting) = ( 'H', 0)
0.146933 (byte,inWaiting) = ( ']', 0)
0.147006 (byte,inWaiting) = ( 'H', 0)
0.149411 (byte,inWaiting) = ( 'a', 0)
0.149497 (byte,inWaiting) = ( 'H', 0)
0.152036 (byte,inWaiting) = ( '\\', 0)
0.152102 (byte,inWaiting) = ( 'H', 0) <-- keeps going until I tell it to stop
0.152990 Stop Transfer <-- sent command to stop data transfer
0.153043 pre: inWaiting():0
0.153983 byte:'*' <-- stop command acknowledged
0.154082 byte:'\r' <-- term. character
0.329529 post: inWaiting():0 <-- no more characters to read

**************************************************

Now, occasionally, *something* goes wrong, and all communications on the serial port
become corrupted. I've found it very difficult to reliably reproduce this problem.
Below is the output from the same script when this problem occurs.

********
A corrupted run:

[nckelley@HawcMobile01 trunk]$ ./fail_radiometer
0.000004 Init
0.098934 flushInput() <-- just flushed, shouldn't be any chars in receive buffer
0.099045 afterflush: inWaiting: 130 <-- (start_t,start_b) = (0.099045,130)
0.099068 afterflush: inWaiting: 232 <-- this should be 0
0.099087 afterflush: inWaiting: 294
0.099113 afterflush: inWaiting: 380
0.099161 afterflush: inWaiting: 405
0.099187 afterflush: inWaiting: 1020 <-- (end_t,end_b) = (0.099187,1020)
0.099210 afterflush: inWaiting: 1020 <-- tons of stuff in receive buffer?
0.099222 Start Transfer <- sent command to start transfer
0.099245 pre: inWaiting():1020
0.099394 (byte,inWaiting) = ( 'H',1019) <- no acknowledge or term char (!?)
0.099450 (byte,inWaiting) = ( ']',1018) <- receive buffer does decrease after
0.099499 (byte,inWaiting) = ( 'H',1017) each s.read()
0.099554 (byte,inWaiting) = ( '^',1016)
0.099610 (byte,inWaiting) = ( 'H',1015) <- ** the data bytes are not correct **
0.099668 (byte,inWaiting) = ( 'a',1014)
0.099722 (byte,inWaiting) = ( 'H',1013)
0.099778 (byte,inWaiting) = ( 'c',1012)
0.099833 (byte,inWaiting) = ( 'H',1011)
0.099888 (byte,inWaiting) = ( '\\',1010)
0.099905 Stop Transfer <-- sent command to stop transfer
0.099940 pre: inWaiting():1010
0.100000 byte:'H' <-- no acknowledge or term char anywhere (!?)
0.100038 byte:'^' |
0.100072 byte:'H' |
0.100097 byte:'d' V
0.100117 byte:'H'
0.100137 byte:'b'
0.100166 byte:'H'
0.100200 byte:'`'
0.100228 byte:'H'
0.100261 byte:'d'
0.100293 post: inWaiting():1000

*********

From the very beginning, inWaiting() reports lots of bytes have built up
in the receiving buffer, until it stops at 1020. If I look at the
build-up times, I find that bytes are accumulating waaaay too fast to
be from the device:

(byte_diff) / (time_diff):
(end_b - start_b) / ( end_t - start_t )
( 1020 - 130 ) / (0.099187 - 0.099045 ) = 6,267,605 bytes/sec
~ 50,000,000 bits/sec
vs
s.baudrate = 115200 -> -> 115,200 bits/sec

The device can only send 115,000 bits/sec at its current baud setting, but
the buffer is being filled at 50,000,000 bits/sec. I think this indicates
that its a software problem (pyserial, python fcntl, c fnctl, usb?), and
not a problem with the device.

Looking at the 1020 bytes of data in the buffer, only rarely does the
buffer contain the correct data, and even then the correct data is at the
beginning, with gibberish filling it out to 1020 long. Weirdly enough,
some of the data in the buffer looks like code(like the computer keeps
reading memory after the end of the receive buffer). After a short
period of time (<1sec), the receiving buffer gets refilled back to 1020
bytes of gibberish.

On top of this, the only way I'm able to fix this is by unplugging and
replugging the usb-serial cable. Closing and reopening the serial
port has no effect.

Any ideas on whats causing this, or further information I can provide?
Thanks.

Discussion

  • Chris Liechti
    Chris Liechti
    2011-03-19

    You're the first one to report such an issue. Therefore i suspect (hope) that it is a problem with the hardware or it's driver. Did you try different types of USB serial converters? There are different brands that use the same chip, but what would be interesting to test is different chip types.

    One idea. Your device is sending data (maybe the off command was not processed/whatever). flushInput() clears the input buffer of the driver, but maybe not of the chips buffer. The buffer from the chip can be transferred at the USB bus speed, which would explain the high data rate. In this theory, the data you see after sending the start command is old data. that's why you don't see the ack there. if you'd read another 1000 or so bytes the ack would probably follow.

    The ~1000 bytes waiting would also match the time after opening the port (the time stamp indicates ~100ms, 115kBaud ~ 11kB/s).

    If this were the problem, a possible fix would be to send the stop command as first action, then wait e.g. 0.2 seconds (as the data on the serial port needs some time to transfer and until the command is processed) and then flushInput.

     
  • Chris Liechti
    Chris Liechti
    2011-03-19

    • status: open --> pending
     
  • This Tracker item was closed automatically by the system. It was
    previously set to a Pending status, and the original submitter
    did not respond within 14 days (the time period specified by
    the administrator of this Tracker).

     
    • status: pending --> closed