RFXCom stops sending or receiving any message with error in syslog

Tags: #<Tag:0x00007f5c98759558>

Hello,

My RFXCom 433XL stops receiving and sending messages. It seems that this is happening following a specific error i am seeing in syslog / dmesg. Below are the details.

Enviroment:
I am running OpenHab 2.5.3 on Raspberry Pi 4 (4G Ram version)
with RFXCom RFXtrx433XL running firmware version 1043.
The RFXCom is connected to serial port /dev/ttyUSB0
Log level for org.openhab.binding.rfxcom is TRACE.
Binding “openHAB Add-ons :: Bundles :: Rfxcom Binding” version is 2.5.3

Issue description:
At a point in time after startup (few hours) the RFXCom interface stop sending or receiving any packets.

The below message is still although showing in the openhab logs:

Checking RFXCOM transceiver connection, thing status = ONLINE

The below messages show in syslog:

May 18 14:05:47 openhab kernel: [46989.092008] ftdi_sio ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32

I made a second test but this time rather than connecting the RFXCom immediately to the Raspberry Pi USB port, i connected it to a USB hub that is connected to that same Raspberry Pi.
Same behavior (but more logs). After a while of running correctly, the following show in the logs:

/var/log/syslog

May 23 02:05:47 openhab kernel: [109662.282027] ftdi_sio ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32
[…]
May 23 02:42:44 openhab kernel: [111879.365957] ftdi_sio ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32
May 23 02:42:44 openhab kernel: [111879.497336] usb 1-1.4-port2: disabled by hub (EMI?), re-enabling…
May 23 02:42:44 openhab kernel: [111879.497644] usb 1-1.4.2: USB disconnect, device number 5
May 23 02:42:44 openhab kernel: [111879.498355] ftdi_sio ttyUSB0: FTDI USB Serial Device converter now disconnected from ttyUSB0
May 23 02:42:44 openhab kernel: [111879.498430] ftdi_sio 1-1.4.2:1.0: device disconnected
May 23 02:42:44 openhab kernel: [111879.799392] usb 1-1.4.2: new full-speed USB device number 6 using xhci_hcd
May 23 02:42:44 openhab kernel: [111879.945828] usb 1-1.4.2: New USB device found, idVendor=0403, idProduct=6015, bcdDevice=10.00
May 23 02:42:44 openhab kernel: [111879.945844] usb 1-1.4.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
May 23 02:42:44 openhab kernel: [111879.945857] usb 1-1.4.2: Product: RFXtrx433XL
May 23 02:42:44 openhab kernel: [111879.945869] usb 1-1.4.2: Manufacturer: RFXCOM
May 23 02:42:44 openhab kernel: [111879.945881] usb 1-1.4.2: SerialNumber: DO2Y2WSZ
May 23 02:42:44 openhab kernel: [111879.952497] ftdi_sio 1-1.4.2:1.0: FTDI USB Serial Device converter detected
May 23 02:42:44 openhab kernel: [111879.952640] usb 1-1.4.2: Detected FT-X
May 23 02:42:44 openhab kernel: [111879.955768] usb 1-1.4.2: FTDI USB Serial Device converter now attached to ttyUSB1
May 23 02:42:44 openhab mtp-probe: checking bus 1, device 6: “/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.4/1-1.4.2”
May 23 02:42:44 openhab mtp-probe: bus: 1, device: 6 was not an MTP device
May 23 02:42:44 openhab mtp-probe: checking bus 1, device 6: “/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.4/1-1.4.2”
May 23 02:42:44 openhab mtp-probe: bus: 1, device: 6 was not an MTP device

We see in here that the system tried to re-attach the RFXCom to another port.

/var/log/openhab2/openhab.log

2020-05-23 02:04:12.525 [DEBUG] [internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
2020-05-23 02:05:12.527 [DEBUG] [internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
2020-05-23 02:06:12.531 [DEBUG] [internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
[…]
2020-05-23 02:41:12.619 [DEBUG] [internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
2020-05-23 02:42:12.622 [DEBUG] [internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
2020-05-23 02:43:12.624 [DEBUG] [internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
2020-05-23 02:44:12.626 [DEBUG] [internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE

FYI: when trying to send a message afterwards it will fail as biding is on USB00 and now the RFXCom is on USB01. The status will change to:
Checking RFXCOM transceiver connection, thing status = OFFLINE

Question to community:

  • Is there a way to go around the disconnection happening in the first place (urb stopped) ?
  • Is it possible that the RFXCom is actually shutting down something causing this disconnection ?
  • Where can I look for more help on this?

Any help from the community is much appreciated.

Thanks loads!!
Patrick

see chapter 21.3 in the RFXtrx User Guide, maybe this helps

Thanks for the reply.
The Raspberry Pi uses the manufacturer original power supply. Reconnecting the Rfxcom to the Raspberry Pi 4 USB 3.0 port (used to be on USB 2.0) did not solve it so far. Output now is as follows with no much details:

[43058.551328] ftdi_sio ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32
[43058.551931] ftdi_sio ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32

I’ll be changing the USB cable and retrying. Will share my findings.

Thanks @bweijenberg this actually seems to be a power issue.

Here is what I noticed in the logs over few days:

May 31 02:05:47 openhab kernel: [518266.310198] ftdi_sio ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32
May 30 07:05:47 openhab kernel: [449865.195969] ftdi_sio ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32
May 25 14:05:47 openhab kernel: [43058.551328] ftdi_sio ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32
May 25 14:05:47 openhab kernel: [43058.551931] ftdi_sio ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32
May 24 02:05:47 openhab kernel: [196063.687880] ftdi_sio ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32
May 24 07:05:47 openhab kernel: [214063.982925] ftdi_sio ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32
May 24 07:05:47 openhab kernel: [214064.099322] ftdi_sio ttyUSB0: FTDI USB Serial Device converter now disconnected from ttyUSB0
May 24 07:05:47 openhab kernel: [214064.099398] ftdi_sio 1-1.4.2:1.0: device disconnected
May 24 07:05:47 openhab kernel: [214064.545485] ftdi_sio 1-1.4.2:1.0: FTDI USB Serial Device converter detected
May 24 14:05:47 openhab kernel: [239264.405327] ftdi_sio ttyUSB1: FTDI USB Serial Device converter now disconnected from ttyUSB1
May 24 14:05:47 openhab kernel: [239264.405428] ftdi_sio 1-1.4.2:1.0: device disconnected
May 24 14:05:47 openhab kernel: [239264.868137] ftdi_sio 1-1.4.2:1.0: FTDI USB Serial Device converter detected

Note how all errors are happening at specific time of the day (*:05:47).
Looking deeper into this, the electricity billing system in France uses peak and off-peak hours (in french called: “heures pleines/heures creuses”). The errors are happening when switching from one to another. This is the exact moment when my water heater starts.
I’ll need make sure to have a good isolation here.