RFXcomm unstable since 3.4.4

flagg · May 23, 2023, 6:52am

This weekend I updated my openhab and since then my rfxcom bridge is very unstable.
It begins with an exception and then a timeout which puts the rfxcom offline.


2023-05-23 08:45:36.289 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 252 bytes from the message
2023-05-23 08:45:36.391 [TRACE] [nternal.connector.RFXComStreamReader] - Received 19 bytes from the message
2023-05-23 08:45:36.395 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 233 bytes from the message
2023-05-23 08:45:36.438 [TRACE] [internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
2023-05-23 08:45:36.497 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 233 bytes from the message
2023-05-23 08:45:36.601 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 233 bytes from the message
2023-05-23 08:45:36.703 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 233 bytes from the message
2023-05-23 08:45:36.807 [DEBUG] [nternal.connector.RFXComStreamReader] - Received exception, will report it to listeners
org.openhab.binding.rfxcom.internal.exceptions.RFXComTimeoutException: Timeout during packet read
	at org.openhab.binding.rfxcom.internal.connector.RFXComStreamReader.processMessage(RFXComStreamReader.java:97) ~[bundleFile:?]
	at org.openhab.binding.rfxcom.internal.connector.RFXComStreamReader.run(RFXComStreamReader.java:70) [bundleFile:?]
2023-05-23 08:45:36.812 [ERROR] [internal.handler.RFXComBridgeHandler] - Error occurred: Timeout during packet read

eventually it comes back:

2023-05-23 08:46:36.441 [TRACE] [internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = OFFLINE
2023-05-23 08:46:36.444 [DEBUG] [internal.handler.RFXComBridgeHandler] - Connecting to RFXCOM transceiver
2023-05-23 08:46:36.447 [DEBUG] [rnal.connector.RFXComSerialConnector] - Disconnecting
2023-05-23 08:46:39.449 [DEBUG] [rnal.connector.RFXComSerialConnector] - Serial port event listener stopped
2023-05-23 08:46:39.451 [DEBUG] [rnal.connector.RFXComSerialConnector] - Interrupt serial listener
2023-05-23 08:46:39.454 [DEBUG] [rnal.connector.RFXComSerialConnector] - Close serial out stream
2023-05-23 08:46:39.457 [DEBUG] [rnal.connector.RFXComSerialConnector] - Close serial in stream
2023-05-23 08:46:39.460 [DEBUG] [rnal.connector.RFXComSerialConnector] - Close serial port
2023-05-23 08:46:39.473 [DEBUG] [rnal.connector.RFXComSerialConnector] - Closed
2023-05-23 08:46:39.491 [DEBUG] [rnal.connector.RFXComSerialConnector] - Serial port event listener started
2023-05-23 08:46:39.494 [DEBUG] [internal.handler.RFXComBridgeHandler] - Reset controller
2023-05-23 08:46:39.495 [DEBUG] [nternal.connector.RFXComStreamReader] - Data listener started
2023-05-23 08:46:39.498 [TRACE] [rnal.connector.RFXComSerialConnector] - Send data (len=14): 0D00000000000000000000000000
2023-05-23 08:46:39.827 [DEBUG] [internal.handler.RFXComBridgeHandler] - Get status of controller
2023-05-23 08:46:39.831 [TRACE] [rnal.connector.RFXComSerialConnector] - Send data (len=14): 0D00000102000000000000000000
2023-05-23 08:46:39.868 [TRACE] [nternal.connector.RFXComStreamReader] - Message length is 20 bytes
2023-05-23 08:46:39.870 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 20 bytes from the message
2023-05-23 08:46:39.873 [TRACE] [nternal.connector.RFXComStreamReader] - Received 20 bytes from the message
2023-05-23 08:46:39.878 [DEBUG] [internal.handler.RFXComBridgeHandler] - Message received: Raw data = 1401000102531C0A0B2F0001031C04524658434F4D, Packet type = INTERFACE_MESSAGE, Seq number = 1, Sub type = RESPONSE, Command = GET_STATUS, Transceiver type = RFXtrx433 operating at 433.92MHz, Hardware version = 1.3, Firmware type = Ext2, Firmware version = 1028, Output power = 10dBm, Undecoded packets = false, RFU6 packets = false, Byron SX packets packets (433.92) = false, RSL packets packets (433.92) = false, Lighting4 packets (433.92) = true, FineOffset / Viking (433.92) packets = false, Rubicson (433.92) packets = true, AE (433.92) packets = false, BlindsT1/T2/T3 (433.92) packets = false, BlindsT0 (433.92) packets = false, ProGuard (868.35 FSK) packets = false, FS20/Legrand CAD (868.35/433.92) packets = false, La Crosse (433.92/868.30) packets = true, Hideki/UPM (433.92) packets = false, AD LightwaveRF (433.92) packets = true, Mertik (433.92) packets = true, Visonic (315/868.95) packets = false, ATI (433.92) packets = false, Oregon Scientific (433.92) packets = true, Meiantech (433.92) packets = false, HomeEasy EU (433.92) packets = true, AC (433.92) packets = true, ARC (433.92) packets = true, X10 (310/433.92) packets = true, HomeConfort (433.92) packets = false, KEELOQ (433.92/868.95) packets = false
2023-05-23 08:46:39.884 [DEBUG] [internal.handler.RFXComBridgeHandler] - RFXCOM transceiver/receiver type: RFXtrx433 operating at 433.92MHz, hw version: 1.3, fw version: 1028
2023-05-23 08:46:39.891 [DEBUG] [internal.handler.RFXComBridgeHandler] - Ignoring transceiver configuration
2023-05-23 08:46:39.894 [DEBUG] [internal.handler.RFXComBridgeHandler] - Start receiver
2023-05-23 08:46:39.897 [TRACE] [rnal.connector.RFXComSerialConnector] - Send data (len=14): 0D00000307000000000000000000
2023-05-23 08:46:40.172 [TRACE] [nternal.connector.RFXComStreamReader] - Message length is 20 bytes
2023-05-23 08:46:40.174 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 20 bytes from the message
2023-05-23 08:46:40.177 [TRACE] [nternal.connector.RFXComStreamReader] - Received 20 bytes from the message
2023-05-23 08:46:40.180 [DEBUG] [internal.handler.RFXComBridgeHandler] - Message received: Raw data = 1401070307436F7079726967687420524658434F4D, Packet type = INTERFACE_MESSAGE, Seq number = 3, Sub type = START_RECEIVER, Command = START_RECEIVER, Text = Copyright RFXCOM
2023-05-23 08:46:40.188 [DEBUG] [fxcom.internal.handler.RFXComHandler] - bridgeStatusChanged ONLINE for thing rfxcom:lighting2:usb0:18204586_9

But this keeps on happening.
I have already put in a powered USB Hub for the rfxcom bridge, since some people said it could be a power issue, but that did not solve it.
Anyone any idea?

flagg · May 23, 2023, 3:58pm

Could it be that there is a bug in the org.openhab.binding.rfxcom-3.4.4.jar?

Larsen · May 24, 2023, 2:14am

The only thing I can report is that it works perfectly fine in my installation with openhab 3.4.4. The transceiver is directly plugged to a raspi4 without additional power supply.
Maybe try creating a new transceiver bridge thing and connecting your rfx-things to it?

flagg · May 24, 2023, 5:13am

Unfortunately, creating a new bridge was something I already tried, but unfortunately that did not help.

Larsen · May 24, 2023, 6:33pm

I guess you were hit by a new debian bug that occurs when updating the system. It has nothing to do with openhab but occurs when updating e.g. with openhabian-config.
The result is that the symbolic links in /dev/serial/by-id are missing. It’s reported here:
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1035094#26
The file with the bug is /usr/lib/udev/rules.d/60-serial.rules. I changed it with udev: fix by-id symlinks by yuwata · Pull Request #25246 · systemd/systemd · GitHub and it worked again.
@mstormi : As the maintainer of openhabian I wanted to inform you about this issue.

flagg · May 27, 2023, 7:34pm

I have tried it for a few days, but it seems that every time an update comes in over rfxcom, the bridge ends up on a timeout and stops and eventually restarts.
The result is that rfxcom devices cannot be operated with openhab anymore…

2023-06-02 11:13:39.165 [TRACE] [nternal.connector.RFXComStreamReader] - Message length is 252 bytes
2023-06-02 11:13:39.169 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 252 bytes from the message
2023-06-02 11:13:39.272 [TRACE] [nternal.connector.RFXComStreamReader] - Received 9 bytes from the message
2023-06-02 11:13:39.274 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 243 bytes from the message
2023-06-02 11:13:39.377 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 243 bytes from the message
2023-06-02 11:13:39.479 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 243 bytes from the message
2023-06-02 11:13:39.582 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 243 bytes from the message
2023-06-02 11:13:39.685 [DEBUG] [nternal.connector.RFXComStreamReader] - Received exception, will report it to listeners
org.openhab.binding.rfxcom.internal.exceptions.RFXComTimeoutException: Timeout during packet read
	at org.openhab.binding.rfxcom.internal.connector.RFXComStreamReader.processMessage(RFXComStreamReader.java:97) ~[bundleFile:?]
	at org.openhab.binding.rfxcom.internal.connector.RFXComStreamReader.run(RFXComStreamReader.java:70) [bundleFile:?]
2023-06-02 11:13:39.689 [ERROR] [internal.handler.RFXComBridgeHandler] - Error occurred: Timeout during packet read
2023-06-02 11:13:39.693 [DEBUG] [fxcom.internal.handler.RFXComHandler] - bridgeStatusChanged OFFLINE (COMMUNICATION_ERROR) for thing rfxcom:lighting2:7367b79e6a:18416978_10

I looked in github, and I am certainly not an expert in coding, but could it be that the refactoring that happened 2 months ago did change something to this stability?

I was trying to get back in versions, but unfortunately I kept the 3.4.4 jar in my add-ons.
How can I safely go back in version (including the bindings)?

Larsen · June 2, 2023, 9:33am

The only experience I can report is that I haven’t had any problems since more than 20 updates (I think since 3.1). So I suspect that it has nothing to do with the binding but rather problems with the usb port or maybe the rfxtrx.

flagg · June 2, 2023, 3:22pm

Larsen,
I tested the rfxtrx on my windows machine again and that worked perfectly fine.
I then reconnected the rfxtrx to the rpi and raised loglevel for rfx to DEBUG.

2023-06-02 17:20:24.473 [DEBUG] [internal.handler.RFXComBridgeHandler] - Connecting to RFXCOM transceiver
2023-06-02 17:20:24.476 [DEBUG] [rnal.connector.RFXComSerialConnector] - Disconnecting
2023-06-02 17:20:24.479 [DEBUG] [rnal.connector.RFXComSerialConnector] - Closed
2023-06-02 17:20:24.486 [DEBUG] [rnal.connector.RFXComSerialConnector] - No serial port /dev/ttyUSB0
2023-06-02 17:20:24.489 [ERROR] [internal.handler.RFXComBridgeHandler] - Connection to RFXCOM transceiver failed
org.openhab.binding.rfxcom.internal.exceptions.RFXComException: No serial port /dev/ttyUSB0
	at org.openhab.binding.rfxcom.internal.connector.RFXComSerialConnector.connect(RFXComSerialConnector.java:61) ~[?:?]
	at org.openhab.binding.rfxcom.internal.handler.RFXComBridgeHandler.connect(RFXComBridgeHandler.java:211) ~[?:?]
	at org.openhab.binding.rfxcom.internal.handler.RFXComBridgeHandler.lambda$0(RFXComBridgeHandler.java:184) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:829) [?:?]

It looks like you are right on the USB part. I don’t know if it is hardware failure or maybe the OS update as you suggested earlier. I will now swap with another RPI to see if it is hardware failure…

Larsen · June 2, 2023, 4:20pm

check your usb-port under /dev/serial/by-id. Where does the rfx-link point to. If you have more than one usb device connected it will not always point to the same ttyUSB. It’s described in the docs of the binding how to assign a static link.

flagg · June 3, 2023, 10:58am

I didn’t change a thing except from updating Openhab through openhabian. the rfxcom worked properly since 2017, so that did not change.
after a fresh restart, it works for a while and I can see the bridge connected and the status of my devices. I can even turn on a light, but then after some time the rfxcom goes in a timeout. I think this also happens when one of my kika sensors send a message, but it also happens at random.
It looks like it cannot get a message translated or something and than waits until it comes in a timeout

flagg · June 10, 2023, 8:53am

Okay, I finally figured it out. I bought a Zigmee usb stick a while ago. That thing conflicted with my rfxcom transceiver, so I deinstalled it. Everything worked fine again…
But not good enough…
When I recently upgraded to 3.4.4 somewhere the remains of the zigbee install started to conflict again.
Just removed it again on all places I could find and my rfxcom is working properly at last…

Julian_Divett · July 5, 2023, 10:44am

Hi I have just had exactly the same problem - I connected up a Sonoff Zigbee Dongle and now my RFXcom has gone off-line. I did not even get as far as installing the Zigbee2Mqtt option in openhabian-config. How did you get rid of the zigbee files? Did you ever find a way to get both devices working together.

Edit: managed to delete it - for anyone else you need to physically disconnect the rfxcom transceiver then run the command below. Reconnect and reboot and it should be back working.

sudo modprobe -r cp210x

flagg · July 5, 2023, 7:23pm

Nice that you managed to get rid of this. I removed the RfXComm transcweiver several times, but that did not help me. I had to remove some more Zigbee files (even after a remove in Openhabian) and then everything started to work properly again…

Julian_Divett · July 6, 2023, 8:16am

I ended up installing the dongle on another raspberry pi running home assistant which I use for some devices that aren’t supported in openhab. It was nice and easy to setup ZigBee2mqtt connecting to the openhab mqtt server. Devices paired with home assistant then in openhab they showed up automatically as mqtt things.