RFXCom stops sending or receiving any message with error in syslog

pstephan · May 23, 2020, 11:13am

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

bweijenberg · May 24, 2020, 5:58pm

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

pstephan · May 25, 2020, 10:32pm

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.

pstephan · May 31, 2020, 6:54am

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.

pstephan · June 15, 2020, 4:32pm

So i have changed the USB cable connecting the RFXCom to the Raspberry Pi, and all seems to be clockwork since then (now over 10 days)!
Thanks a lot.