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

Hi Larsen,
I updated the file with the mentioned bug. It seems a bit more stable, but nonetheless it had again timeouts which results in a stopped data listener. 1 or two minutes later, the rfxcomm bridge comes back online…
I’ll try it for a day to see how stable it will be