Arch Linux

fardragon

Member

Registered: 2020-02-26

Posts: 1

Kernel 5.5 weird serial port behaviour

Hi,
I've noticed some bizarre serial port  behaviour on kernel 5.5.5 (issues persist after upgrading to 5.5.6). Basically I have a usb to serial adapter (ch341) with rs-485 and modbus rtu device down the chain, but those shouldn't matter I think. This occurs in a software written in c++ that accesses the serial port directly, but can also be observed using simple pymodbus script:

#!/usr/bin/env python
from pymodbus.client.sync import ModbusSerialClient as ModbusClient

import logging

FORMAT = ('%(asctime)-15s %(threadName)-15s '
          '%(levelname)-8s %(module)-15s:%(lineno)-8s %(message)s')
logging.basicConfig(format=FORMAT)
log = logging.getLogger()
log.setLevel(logging.DEBUG)

UNIT = 0x1


def run_sync_client():
    client = ModbusClient(method='rtu', port='/dev/ttyUSB0', timeout=1,
                          baudrate=9600)
    client.connect()
    rr = client.read_holding_registers(0, 1, unit=UNIT)
    print(rr)

    client.close()


if __name__ == "__main__":
    run_sync_client()

What's happening is that on linux 5.5.* most of the time (like 80%) this script fails and further analysis shows that serial port returns wrong data. After switching to linux-lts everything works as expected.

Test script behaviour on 5.5 kernel:

2020-02-26 13:27:19,158 MainThread      DEBUG    transaction    :114      Current transaction state - IDLE
2020-02-26 13:27:19,158 MainThread      DEBUG    transaction    :119      Running transaction 1
2020-02-26 13:27:19,158 MainThread      DEBUG    transaction    :219      SEND: 0x1 0x3 0x0 0x0 0x0 0x1 0x84 0xa
2020-02-26 13:27:19,158 MainThread      DEBUG    sync           :75       New Transaction state 'SENDING'
2020-02-26 13:27:19,158 MainThread      DEBUG    transaction    :228      Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2020-02-26 13:27:19,204 MainThread      DEBUG    transaction    :304      Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2020-02-26 13:27:19,204 MainThread      DEBUG    transaction    :233      RECV: 0x81 0x3 0x2 0x9 0x88 0xbe 0x72
2020-02-26 13:27:19,204 MainThread      DEBUG    rtu_framer     :97       CRC invalid, discarding header!!
2020-02-26 13:27:19,204 MainThread      DEBUG    rtu_framer     :127      Resetting frame - Current Frame in buffer - 0x81 0x3 0x2 0x9 0x88 0xbe 0x72
2020-02-26 13:27:19,204 MainThread      DEBUG    rtu_framer     :232      Frame check failed, ignoring!!
2020-02-26 13:27:19,204 MainThread      DEBUG    rtu_framer     :127      Resetting frame - Current Frame in buffer - 
2020-02-26 13:27:19,204 MainThread      DEBUG    transaction    :394      Getting transaction 1
2020-02-26 13:27:19,204 MainThread      DEBUG    transaction    :193      Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
Modbus Error: [Input/Output] No Response received from the remote unit/Unable to decode response

Test script behaviour on linux-lts:

2020-02-26 13:22:31,849 MainThread      DEBUG    transaction    :114      Current transaction state - IDLE
2020-02-26 13:22:31,849 MainThread      DEBUG    transaction    :119      Running transaction 1
2020-02-26 13:22:31,849 MainThread      DEBUG    transaction    :219      SEND: 0x1 0x3 0x0 0x0 0x0 0x1 0x84 0xa
2020-02-26 13:22:31,849 MainThread      DEBUG    sync           :75       New Transaction state 'SENDING'
2020-02-26 13:22:31,849 MainThread      DEBUG    transaction    :228      Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2020-02-26 13:22:31,895 MainThread      DEBUG    transaction    :304      Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2020-02-26 13:22:31,895 MainThread      DEBUG    transaction    :233      RECV: 0x1 0x3 0x2 0x9 0x92 0x3f 0xb9
2020-02-26 13:22:31,895 MainThread      DEBUG    rtu_framer     :180      Getting Frame - 0x3 0x2 0x9 0x92
2020-02-26 13:22:31,895 MainThread      DEBUG    factory        :266      Factory Response[ReadHoldingRegistersResponse: 3]
2020-02-26 13:22:31,895 MainThread      DEBUG    rtu_framer     :115      Frame advanced, resetting header!!
2020-02-26 13:22:31,895 MainThread      DEBUG    transaction    :383      Adding transaction 1
2020-02-26 13:22:31,895 MainThread      DEBUG    transaction    :394      Getting transaction 1
2020-02-26 13:22:31,895 MainThread      DEBUG    transaction    :193      Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
ReadRegisterResponse (1)

Serial device in question:

[  425.195052] usb 2-14.1: new full-speed USB device number 6 using xhci_hcd
[  425.326202] usb 2-14.1: New USB device found, idVendor=1a86, idProduct=7523, bcdDevice= 2.54
[  425.326204] usb 2-14.1: New USB device strings: Mfr=0, Product=2, SerialNumber=0
[  425.326205] usb 2-14.1: Product: USB2.0-Serial
[  425.333348] ch341 2-14.1:1.0: ch341-uart converter detected
[  425.333868] usb 2-14.1: ch341-uart converter now attached to ttyUSB0

Any ideas as to what's happening here?

loqs

Member

Registered: 2014-03-06

Posts: 18,928

Re: Kernel 5.5 weird serial port behaviour

https://git.kernel.org/pub/scm/linux/ke … sion.patch queued for 5.5.7