RFXCOM behaves unstable

Add-ons Bindings
1

Hi all,

RFXCOM under OH2 on RPi3 is rather unstable (see log file), at least when I send a few RF commands right after each other.

The rfx-bridge goes ofline and comes then later online again. Commands issued in the mean time seem to be buffered and are issue then later.

I updated OH to the latest stable version 2.2.0-1 and also updated and upgraded openhabian.

Any ideas?

Log file

2018-03-30 17:21:25.614 [ERROR] [g.rfxcom.handler.RFXComBridgeHandler] - Error occurred: Timeout during packet read
2018-03-30 17:22:20.493 [ERROR] [g.rfxcom.handler.RFXComBridgeHandler] - Error occurred: Timeout during packet read
2018-03-30 17:23:23.442 [INFO ] [g.rfxcom.handler.RFXComBridgeHandler] - RFXCOM transceiver/receiver type: _433_92MHZ_TRANSCEIVER, hw version: 0.1, fw version: 24
2018-03-30 17:23:33.945 [ERROR] [g.rfxcom.handler.RFXComBridgeHandler] - Error occurred: Timeout during packet read
2018-03-30 17:24:27.193 [ERROR] [g.rfxcom.handler.RFXComBridgeHandler] - Error occurred: Timeout during packet read
2018-03-30 17:25:30.151 [INFO ] [g.rfxcom.handler.RFXComBridgeHandler] - RFXCOM transceiver/receiver type: _433_92MHZ_TRANSCEIVER, hw version: 0.1, fw version: 24
2018-03-30 17:25:30.838 [ERROR] [g.rfxcom.handler.RFXComBridgeHandler] - Error occurred: Timeout during packet read
2018-03-30 17:26:33.502 [INFO ] [g.rfxcom.handler.RFXComBridgeHandler] - RFXCOM transceiver/receiver type: _433_92MHZ_TRANSCEIVER, hw version: 0.1, fw version: 24
2018-03-30 17:26:34.190 [ERROR] [g.rfxcom.handler.RFXComBridgeHandler] - Error occurred: Timeout during packet read
2018-03-30 17:27:36.853 [INFO ] [g.rfxcom.handler.RFXComBridgeHandler] - RFXCOM transceiver/receiver type: _433_92MHZ_TRANSCEIVER, hw version: 0.1, fw version: 24
2018-03-30 17:29:53.232 [ERROR] [g.rfxcom.handler.RFXComBridgeHandler] - Error occurred: Timeout during packet read
2018-03-30 17:30:40.203 [INFO ] [g.rfxcom.handler.RFXComBridgeHandler] - RFXCOM transceiver/receiver type: _433_92MHZ_TRANSCEIVER, hw version: 0.1, fw version: 24

events log

2018-03-30 17:14:56.152 [hingStatusInfoChangedEvent] - 'rfxcom:bridge:usb1' changed from ONLINE to OFFLINE
2018-03-30 17:14:56.160 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote1_1' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-30 17:14:56.166 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote2_2' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-30 17:14:56.179 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote3_1' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-30 17:14:56.187 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote3_2' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-30 17:14:56.205 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote2_3' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-30 17:14:56.211 [hingStatusInfoChangedEvent] - 'rfxcom:undecoded:usb1:remoteAliA' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-30 17:14:56.215 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliC' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-30 17:14:56.247 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliB' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-30 17:14:56.258 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliD' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-30 17:14:56.284 [me.event.ThingUpdatedEvent] - Thing 'rfxcom:bridge:usb1' has been updated.
2018-03-30 17:14:56.305 [me.event.ThingUpdatedEvent] - Thing 'rfxcom:lighting5:usb1:remote1_1' has been updated.
2018-03-30 17:14:56.329 [me.event.ThingUpdatedEvent] - Thing 'rfxcom:lighting5:usb1:remote2_2' has been updated.
2018-03-30 17:14:56.351 [me.event.ThingUpdatedEvent] - Thing 'rfxcom:lighting5:usb1:remote2_3' has been updated.
2018-03-30 17:14:56.370 [me.event.ThingUpdatedEvent] - Thing 'rfxcom:lighting5:usb1:remote3_1' has been updated.
2018-03-30 17:14:56.391 [me.event.ThingUpdatedEvent] - Thing 'rfxcom:lighting5:usb1:remote3_2' has been updated.
2018-03-30 17:14:56.410 [me.event.ThingUpdatedEvent] - Thing 'rfxcom:undecoded:usb1:remoteAliA' has been updated.
2018-03-30 17:14:56.432 [me.event.ThingUpdatedEvent] - Thing 'rfxcom:lighting5:usb1:remoteAliB' has been updated.
2018-03-30 17:14:56.455 [me.event.ThingUpdatedEvent] - Thing 'rfxcom:lighting5:usb1:remoteAliC' has been updated.
2018-03-30 17:14:56.476 [me.event.ThingUpdatedEvent] - Thing 'rfxcom:lighting5:usb1:remoteAliD' has been updated.
2018-03-30 17:14:57.073 [hingStatusInfoChangedEvent] - 'rfxcom:bridge:usb1' changed from OFFLINE to OFFLINE (COMMUNICATION_ERROR)

2018-03-30 17:21:17.037 [hingStatusInfoChangedEvent] - 'rfxcom:bridge:usb1' changed from OFFLINE (COMMUNICATION_ERROR) to ONLINE
2018-03-30 17:21:17.048 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote1_1' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-30 17:21:17.059 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote2_2' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-30 17:21:17.071 [hingStatusInfoChangedEvent] - 'rfxcom:undecoded:usb1:remoteAliA' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-30 17:21:17.086 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote2_3' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-30 17:21:17.093 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliB' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-30 17:21:17.096 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliD' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-30 17:21:17.104 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote3_1' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-30 17:21:17.109 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote3_2' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-30 17:21:17.115 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliC' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-30 17:21:25.622 [hingStatusInfoChangedEvent] - 'rfxcom:bridge:usb1' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
2018-03-30 17:21:25.663 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote1_1' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-30 17:21:25.666 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote2_2' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-30 17:21:25.669 [hingStatusInfoChangedEvent] - 'rfxcom:undecoded:usb1:remoteAliA' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-30 17:21:25.678 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliB' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-30 17:21:25.685 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote2_3' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-30 17:21:25.689 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote3_1' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-30 17:21:25.693 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote3_2' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-30 17:21:25.697 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliC' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-30 17:21:25.702 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliD' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

Kind regards,
Jan

2

Thinking out of the box…
Is your RFXcom power supply in good health?
It could be teetering on the edge of providing good power to the RFX and not allow bursts of power when decoding for example and sometimes go off-line altogether.
The symptoms match.
Try a beefier/newer one, see if that help.

3

Turn logging up to DEBUG. However you are likely to find that the binding simply times out waiting for a response after sending a command. Commands sent via the binding are queued and sent lock-step - send a command, wait for response, send the next etc. There’s no other flow control or queuing on the RFXCOM so a receive timeout suggests that your RFXCOM has a problem, your pi is dropping serial traffic or you are sending a command which isn’t something the RFXCOM is able to send and that it takes it badly.

4

My RFXtrx433E is powered via the USB cable via RPi3 and I’m using a >2A power adaptor (Ipad). I suppose this is sufficient.

After I’m sending the same two signals (ON & OFF) a few times and the power plug functions well there is a timeout and the bridge restarts (see loggings with DEBUG).

I’m able to send signals repeatedly via RFXMgr under Windows. No problems there, so therefore I assume it is an Openhab or Linux problem.

2018-03-31 14:53:21.742 [vent.ItemStateChangedEvent] - Plug_Spare changed from OFF to ON
2018-03-31 14:53:24.039 [ome.event.ItemCommandEvent] - Item 'Plug_Spare' received command OFF
2018-03-31 14:53:24.052 [vent.ItemStateChangedEvent] - Plug_Spare changed from ON to OFF
2018-03-31 14:53:26.429 [ome.event.ItemCommandEvent] - Item 'Plug_Spare' received command ON
2018-03-31 14:53:26.442 [vent.ItemStateChangedEvent] - Plug_Spare changed from OFF to ON
2018-03-31 14:53:28.307 [ome.event.ItemCommandEvent] - Item 'Plug_Spare' received command OFF
2018-03-31 14:53:28.316 [vent.ItemStateChangedEvent] - Plug_Spare changed from ON to OFF
2018-03-31 14:53:29.763 [ome.event.ItemCommandEvent] - Item 'Plug_Spare' received command ON
2018-03-31 14:53:29.775 [vent.ItemStateChangedEvent] - Plug_Spare changed from OFF to ON
2018-03-31 14:53:31.238 [ome.event.ItemCommandEvent] - Item 'Plug_Spare' received command OFF
2018-03-31 14:53:31.246 [vent.ItemStateChangedEvent] - Plug_Spare changed from ON to OFF
2018-03-31 14:53:32.889 [ome.event.ItemCommandEvent] - Item 'Plug_Spare' received command ON
2018-03-31 14:53:32.900 [vent.ItemStateChangedEvent] - Plug_Spare changed from OFF to ON
2018-03-31 14:53:33.712 [hingStatusInfoChangedEvent] - 'rfxcom:bridge:usb1' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
2018-03-31 14:53:33.740 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote1_1' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-31 14:53:33.754 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote2_3' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-31 14:53:33.764 [hingStatusInfoChangedEvent] - 'rfxcom:undecoded:usb1:remoteAliA' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-31 14:53:33.775 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliC' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-31 14:53:33.788 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote3_1' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-31 14:53:33.794 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote2_2' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-31 14:53:33.802 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliD' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-31 14:53:33.806 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote3_2' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-31 14:53:33.810 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliB' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-31 14:53:36.914 [ome.event.ItemCommandEvent] - Item 'Plug_Spare' received command OFF
2018-03-31 14:53:36.921 [vent.ItemStateChangedEvent] - Plug_Spare changed from ON to OFF
2018-03-31 14:53:38.891 [ome.event.ItemCommandEvent] - Item 'Plug_Spare' received command ON
2018-03-31 14:53:38.907 [vent.ItemStateChangedEvent] - Plug_Spare changed from OFF to ON
2018-03-31 14:53:40.606 [ome.event.ItemCommandEvent] - Item 'Plug_Spare' received command OFF
2018-03-31 14:53:40.616 [vent.ItemStateChangedEvent] - Plug_Spare changed from ON to OFF
2018-03-31 14:53:41.975 [ome.event.ItemCommandEvent] - Item 'Plug_Spare' received command ON
2018-03-31 14:53:41.983 [vent.ItemStateChangedEvent] - Plug_Spare changed from OFF to ON
2018-03-31 14:53:43.232 [ome.event.ItemCommandEvent] - Item 'Plug_Spare' received command OFF
2018-03-31 14:53:43.242 [vent.ItemStateChangedEvent] - Plug_Spare changed from ON to OFF
2018-03-31 14:54:20.267 [hingStatusInfoChangedEvent] - 'rfxcom:bridge:usb1' changed from OFFLINE (COMMUNICATION_ERROR) to ONLINE
2018-03-31 14:54:20.291 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote1_1' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-31 14:54:20.301 [hingStatusInfoChangedEvent] - 'rfxcom:undecoded:usb1:remoteAliA' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-31 14:54:20.309 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote2_3' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-31 14:54:20.316 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliC' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-31 14:54:20.325 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote2_2' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-31 14:54:20.331 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote3_1' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-31 14:54:20.337 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliD' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-31 14:54:20.344 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliB' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-31 14:54:20.347 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote3_2' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-31 14:54:27.278 [hingStatusInfoChangedEvent] - 'rfxcom:bridge:usb1' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
2018-03-31 14:54:27.295 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote1_1' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-31 14:54:27.303 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote3_2' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-31 14:54:27.333 [hingStatusInfoChangedEvent] - 'rfxcom:undecoded:usb1:remoteAliA' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-31 14:54:27.338 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliB' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-31 14:54:27.344 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliD' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-31 14:54:27.348 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliC' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-31 14:54:27.352 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote2_2' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-31 14:54:27.362 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote3_1' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-31 14:54:27.367 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote2_3' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-03-31 14:55:23.665 [hingStatusInfoChangedEvent] - 'rfxcom:bridge:usb1' changed from OFFLINE (COMMUNICATION_ERROR) to ONLINE
2018-03-31 14:55:23.676 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote2_3' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-31 14:55:23.695 [hingStatusInfoChangedEvent] - 'rfxcom:undecoded:usb1:remoteAliA' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-31 14:55:23.699 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote3_2' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-31 14:55:23.702 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote2_2' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-31 14:55:23.709 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote1_1' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-31 14:55:23.713 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliB' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-31 14:55:23.717 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remote3_1' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-31 14:55:23.721 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliD' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-03-31 14:55:23.724 [hingStatusInfoChangedEvent] - 'rfxcom:lighting5:usb1:remoteAliC' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE

2018-03-31 14:50:16.556 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
2018-03-31 14:51:16.559 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
2018-03-31 14:52:16.562 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
2018-03-31 14:53:16.565 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
2018-03-31 14:53:21.721 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - Received channel: rfxcom:lighting5:usb1:remote3_2:command, command: ON
2018-03-31 14:53:21.736 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Transmitting message 'Raw data = unknown, Packet type = LIGHTING5, Seq number = 0, Sub type = KANGTAI, Device Id = 3884.2, Command = ON, Dim level = 0, Signal level = 0'
2018-03-31 14:53:23.365 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Message received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
2018-03-31 14:53:23.369 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Transmitter response received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
2018-03-31 14:53:24.041 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - Received channel: rfxcom:lighting5:usb1:remote3_2:command, command: OFF
2018-03-31 14:53:24.045 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Transmitting message 'Raw data = unknown, Packet type = LIGHTING5, Seq number = 0, Sub type = KANGTAI, Device Id = 3884.2, Command = OFF, Dim level = 0, Signal level = 0'
2018-03-31 14:53:25.683 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Message received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
2018-03-31 14:53:25.689 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Transmitter response received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
2018-03-31 14:53:26.433 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - Received channel: rfxcom:lighting5:usb1:remote3_2:command, command: ON
2018-03-31 14:53:26.438 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Transmitting message 'Raw data = unknown, Packet type = LIGHTING5, Seq number = 0, Sub type = KANGTAI, Device Id = 3884.2, Command = ON, Dim level = 0, Signal level = 0'
2018-03-31 14:53:28.081 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Message received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
2018-03-31 14:53:28.083 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Transmitter response received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
2018-03-31 14:53:28.312 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - Received channel: rfxcom:lighting5:usb1:remote3_2:command, command: OFF
2018-03-31 14:53:28.317 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Transmitting message 'Raw data = unknown, Packet type = LIGHTING5, Seq number = 0, Sub type = KANGTAI, Device Id = 3884.2, Command = OFF, Dim level = 0, Signal level = 0'
2018-03-31 14:53:29.778 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - Received channel: rfxcom:lighting5:usb1:remote3_2:command, command: ON
2018-03-31 14:53:29.951 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Message received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
2018-03-31 14:53:29.953 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Transmitter response received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
2018-03-31 14:53:29.956 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Transmitting message 'Raw data = unknown, Packet type = LIGHTING5, Seq number = 0, Sub type = KANGTAI, Device Id = 3884.2, Command = ON, Dim level = 0, Signal level = 0'
2018-03-31 14:53:31.242 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - Received channel: rfxcom:lighting5:usb1:remote3_2:command, command: OFF
2018-03-31 14:53:31.598 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Message received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
2018-03-31 14:53:31.602 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Transmitter response received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
2018-03-31 14:53:31.605 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Transmitting message 'Raw data = unknown, Packet type = LIGHTING5, Seq number = 0, Sub type = KANGTAI, Device Id = 3884.2, Command = OFF, Dim level = 0, Signal level = 0'
2018-03-31 14:53:32.895 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - Received channel: rfxcom:lighting5:usb1:remote3_2:command, command: ON
2018-03-31 14:53:33.631 [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:87) [226:org.openhab.binding.rfxcom:2.2.0]
	at org.openhab.binding.rfxcom.internal.connector.RFXComStreamReader.run(RFXComStreamReader.java:61) [226:org.openhab.binding.rfxcom:2.2.0]
2018-03-31 14:53:33.689 [ERROR] [g.rfxcom.handler.RFXComBridgeHandler] - Error occurred: Timeout during packet read
2018-03-31 14:53:33.708 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - bridgeStatusChanged OFFLINE (COMMUNICATION_ERROR) for thing rfxcom:lighting5:usb1:remote1_1
2018-03-31 14:53:33.713 [DEBUG] [nternal.connector.RFXComStreamReader] - Data listener stopped
2018-03-31 14:53:33.713 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - initializeBridge OFFLINE for thing rfxcom:lighting5:usb1:remote1_1
2018-03-31 14:53:33.719 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - bridgeStatusChanged OFFLINE (COMMUNICATION_ERROR) for thing rfxcom:lighting5:usb1:remote2_2
2018-03-31 14:53:33.722 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - bridgeStatusChanged OFFLINE (COMMUNICATION_ERROR) for thing rfxcom:lighting5:usb1:remote2_3
2018-03-31 14:53:33.726 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - bridgeStatusChanged OFFLINE (COMMUNICATION_ERROR) for thing rfxcom:undecoded:usb1:remoteAliA
2018-03-31 14:53:33.727 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - initializeBridge OFFLINE for thing rfxcom:lighting5:usb1:remote2_3
2018-03-31 14:53:33.729 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - initializeBridge OFFLINE for thing rfxcom:undecoded:usb1:remoteAliA
2018-03-31 14:53:33.742 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - bridgeStatusChanged OFFLINE (COMMUNICATION_ERROR) for thing rfxcom:lighting5:usb1:remoteAliB
2018-03-31 14:53:33.742 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - bridgeStatusChanged OFFLINE (COMMUNICATION_ERROR) for thing rfxcom:lighting5:usb1:remoteAliC
2018-03-31 14:53:33.724 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - initializeBridge OFFLINE for thing rfxcom:lighting5:usb1:remote2_2
2018-03-31 14:53:33.726 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - bridgeStatusChanged OFFLINE (COMMUNICATION_ERROR) for thing rfxcom:lighting5:usb1:remote3_1
2018-03-31 14:53:33.749 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - initializeBridge OFFLINE for thing rfxcom:lighting5:usb1:remoteAliC
2018-03-31 14:53:33.749 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - initializeBridge OFFLINE for thing rfxcom:lighting5:usb1:remote3_1
2018-03-31 14:53:33.761 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - bridgeStatusChanged OFFLINE (COMMUNICATION_ERROR) for thing rfxcom:lighting5:usb1:remoteAliD
2018-03-31 14:53:33.752 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - bridgeStatusChanged OFFLINE (COMMUNICATION_ERROR) for thing rfxcom:lighting5:usb1:remote3_2
2018-03-31 14:53:33.768 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - initializeBridge OFFLINE for thing rfxcom:lighting5:usb1:remote3_2
2018-03-31 14:53:33.765 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - initializeBridge OFFLINE for thing rfxcom:lighting5:usb1:remoteAliD
2018-03-31 14:53:33.762 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - initializeBridge OFFLINE for thing rfxcom:lighting5:usb1:remoteAliB
2018-03-31 14:53:36.918 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - Received channel: rfxcom:lighting5:usb1:remote3_2:command, command: OFF
2018-03-31 14:53:38.896 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - Received channel: rfxcom:lighting5:usb1:remote3_2:command, command: ON
2018-03-31 14:53:40.607 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - Received channel: rfxcom:lighting5:usb1:remote3_2:command, command: OFF
2018-03-31 14:53:41.979 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - Received channel: rfxcom:lighting5:usb1:remote3_2:command, command: ON
2018-03-31 14:53:43.241 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - Received channel: rfxcom:lighting5:usb1:remote3_2:command, command: OFF
2018-03-31 14:54:16.570 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = OFFLINE
2018-03-31 14:54:16.572 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Connecting to RFXCOM transceiver
2018-03-31 14:54:16.575 [DEBUG] [rnal.connector.RFXComSerialConnector] - Disconnecting
2018-03-31 14:54:19.578 [DEBUG] [rnal.connector.RFXComSerialConnector] - Serial port event listener stopped
2018-03-31 14:54:19.580 [DEBUG] [rnal.connector.RFXComSerialConnector] - Interrupt serial listener
2018-03-31 14:54:19.583 [DEBUG] [rnal.connector.RFXComSerialConnector] - Close serial out stream
2018-03-31 14:54:19.587 [DEBUG] [rnal.connector.RFXComSerialConnector] - Close serial in stream
2018-03-31 14:54:19.591 [DEBUG] [rnal.connector.RFXComSerialConnector] - Close serial port
2018-03-31 14:54:19.597 [DEBUG] [rnal.connector.RFXComSerialConnector] - Closed
2018-03-31 14:54:19.608 [DEBUG] [rnal.connector.RFXComSerialConnector] - Serial port event listener started
2018-03-31 14:54:19.612 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Reset controller
2018-03-31 14:54:19.621 [DEBUG] [nternal.connector.RFXComStreamReader] - Data listener started
2018-03-31 14:54:19.936 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Get status of controller
2018-03-31 14:54:19.954 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Message received: Raw data = 140100010253180800060001031C04524658434F4D, Packet type = INTERFACE_MESSAGE, Seq number = 1, Sub type = RESPONSE, Command = GET_STATUS, Transceiver type = _433_92MHZ_TRANSCEIVER, Hardware version = 0.1, Firmware type = unknown, Firmware version = 24, Output power = 0dBm, 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 = false, 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 = false, Hideki/UPM (433.92) packets = false, AD LightwaveRF (433.92) packets = false, Mertik (433.92) packets = false, Visonic (315/868.95) packets = false, ATI (433.92) packets = false, Oregon Scientific (433.92) packets = false, Meiantech (433.92) packets = false, HomeEasy EU (433.92) packets = false, AC (433.92) packets = true, ARC (433.92) packets = true, X10 (310/433.92) packets = false, HomeConfort (433.92) packets = false, KEELOQ (433.92/868.95) packets = false
2018-03-31 14:54:19.959 [INFO ] [g.rfxcom.handler.RFXComBridgeHandler] - RFXCOM transceiver/receiver type: _433_92MHZ_TRANSCEIVER, hw version: 0.1, fw version: 24
2018-03-31 14:54:19.961 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Ignoring transceiver configuration
2018-03-31 14:54:19.964 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Start receiver
2018-03-31 14:54:20.258 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Message received: Raw data = 1401070307436F7079726967687420524658434F4D, Packet type = INTERFACE_MESSAGE, Seq number = 3, Sub type = START_RECEIVER, Command = START_RECEIVER, Text = Copyright RFXCOM
2018-03-31 14:54:20.263 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - bridgeStatusChanged ONLINE for thing rfxcom:lighting5:usb1:remote1_1
2018-03-31 14:54:20.264 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - bridgeStatusChanged ONLINE for thing rfxcom:lighting5:usb1:remote2_3
2018-03-31 14:54:20.268 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - initializeBridge ONLINE for thing rfxcom:lighting5:usb1:remote1_1
2018-03-31 14:54:20.268 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - initializeBridge ONLINE for thing rfxcom:lighting5:usb1:remote2_3
2018-03-31 14:54:20.263 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - bridgeStatusChanged ONLINE for thing rfxcom:lighting5:usb1:remote2_2
2018-03-31 14:54:20.271 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - initializeBridge ONLINE for thing rfxcom:lighting5:usb1:remote2_2
2018-03-31 14:54:20.273 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - bridgeStatusChanged ONLINE for thing rfxcom:lighting5:usb1:remote3_1
2018-03-31 14:54:20.273 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - bridgeStatusChanged ONLINE for thing rfxcom:lighting5:usb1:remote3_2
2018-03-31 14:54:20.278 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - initializeBridge ONLINE for thing rfxcom:lighting5:usb1:remote3_1
2018-03-31 14:54:20.276 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - initializeBridge ONLINE for thing rfxcom:lighting5:usb1:remote3_2
2018-03-31 14:54:20.283 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - bridgeStatusChanged ONLINE for thing rfxcom:lighting5:usb1:remoteAliD
2018-03-31 14:54:20.282 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - bridgeStatusChanged ONLINE for thing rfxcom:undecoded:usb1:remoteAliA
2018-03-31 14:54:20.273 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Start TX of any queued messages
2018-03-31 14:54:20.283 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - bridgeStatusChanged ONLINE for thing rfxcom:lighting5:usb1:remoteAliB
2018-03-31 14:54:20.286 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - initializeBridge ONLINE for thing rfxcom:undecoded:usb1:remoteAliA
2018-03-31 14:54:20.286 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Transmitting message 'Raw data = unknown, Packet type = LIGHTING5, Seq number = 0, Sub type = KANGTAI, Device Id = 3884.2, Command = OFF, Dim level = 0, Signal level = 0'
2018-03-31 14:54:20.283 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - bridgeStatusChanged ONLINE for thing rfxcom:lighting5:usb1:remoteAliC
2018-03-31 14:54:20.287 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - initializeBridge ONLINE for thing rfxcom:lighting5:usb1:remoteAliB
2018-03-31 14:54:20.288 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - initializeBridge ONLINE for thing rfxcom:lighting5:usb1:remoteAliC
2018-03-31 14:54:20.291 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - initializeBridge ONLINE for thing rfxcom:lighting5:usb1:remoteAliD
2018-03-31 14:54:21.919 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Message received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
2018-03-31 14:54:21.922 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Transmitter response received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
2018-03-31 14:54:21.926 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Transmitting message 'Raw data = unknown, Packet type = LIGHTING5, Seq number = 0, Sub type = KANGTAI, Device Id = 3884.2, Command = ON, Dim level = 0, Signal level = 0'
2018-03-31 14:54:23.565 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Message received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
2018-03-31 14:54:23.569 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Transmitter response received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
2018-03-31 14:54:23.571 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Transmitting message 'Raw data = unknown, Packet type = LIGHTING5, Seq number = 0, Sub type = KANGTAI, Device Id = 3884.2, Command = OFF, Dim level = 0, Signal level = 0'
2018-03-31 14:54:25.213 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Message received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
2018-03-31 14:54:25.217 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Transmitter response received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
2018-03-31 14:54:25.220 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Transmitting message 'Raw data = unknown, Packet type = LIGHTING5, Seq number = 0, Sub type = KANGTAI, Device Id = 3884.2, Command = ON, Dim level = 0, Signal level = 0'
2018-03-31 14:54:27.260 [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:87) [226:org.openhab.binding.rfxcom:2.2.0]
	at org.openhab.binding.rfxcom.internal.connector.RFXComStreamReader.run(RFXComStreamReader.java:61) [226:org.openhab.binding.rfxcom:2.2.0]
2018-03-31 14:54:27.263 [ERROR] [g.rfxcom.handler.RFXComBridgeHandler] - Error occurred: Timeout during packet read
2018-03-31 14:54:27.268 [DEBUG] [nternal.connector.RFXComStreamReader] - Data listener stopped
2018-03-31 14:54:27.268 [DEBUG] [binding.rfxcom.handler.RFXComHandler] - bridgeStatusChanged OFFLINE (COMMUNICATION_ERROR) for thing rfxcom:lighting5:usb1:remote1_1
5

I don’t use the RFX, so I can’t help further, the power idea and just that an idea. Sometimes when we have a problem, it is useful to go back to the hardware and not just think it is a bug.

6

Hi
did you find a solution?
Think I have same issue…

7

Problem still exists?

I bought a second PI and will re-try everything from scratch.

Br,

Jan

8

Yes, if I give just a couple output items signal pretty quick it stops to respond to output signals… Input (Reading) sensors keeps working…

9

Hi again,
have you tried?
regards
Atle

10

Hi Atle,

Yesterday I finished a clean installation on a new Rasberry Pi and until now RFXCOM behaves very stable. Problem seems to be solved.

Br,

Jan

1 Like
11

Hi Jan,

Are you still experiencing problems after 1 month? I’m experiencing similar problems but on a windows 10 install.

12

With me everything works fine now.

13

Hi,

I have just started to get this problem after upgrading to 2.5.8 from 2.4. Almost every minute I get;

2020-08-28 19:17:47.626 [hingStatusInfoChangedEvent] - ‘rfxcom:bridge:eb0f92b4’ changed from ONLINE to UNINITIALIZED
2020-08-28 19:17:50.660 [hingStatusInfoChangedEvent] - ‘rfxcom:bridge:eb0f92b4’ changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
…
2020-08-28 19:17:51.383 [hingStatusInfoChangedEvent] - ‘rfxcom:bridge:eb0f92b4’ changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
2020-08-28 19:17:51.402 [hingStatusInfoChangedEvent] - ‘rfxcom:bridge:eb0f92b4’ changed from INITIALIZING to OFFLINE

Followed by all my things linked to the RFXCOM bridge going to UNINITIALIZED, UNINITIALIZED (HANDLER_MISSING_ERROR)

I have changed the USB cable to the RFXCOM and changed the power supply to the raspberry pi.

I don’t fancy doing a fresh install. I have updated everything, not sure what to do now? Has anyone got any more ideas?

Also just seen this error

> > 2020-08-28 19:35:54.945 [ERROR] [internal.handler.RFXComBridgeHandler] - Connection to RFXCOM transceiver failed
> > org.eclipse.smarthome.io.transport.serial.PortInUseException: null
> > 	at org.eclipse.smarthome.io.transport.serial.internal.SerialPortIdentifierImpl.open(SerialPortIdentifierImpl.java:61) ~[?:?]
> > 	at org.openhab.binding.rfxcom.internal.connector.RFXComSerialConnector.connect(RFXComSerialConnector.java:62) ~[?:?]
> > 	at org.openhab.binding.rfxcom.internal.handler.RFXComBridgeHandler.connect(RFXComBridgeHandler.java:189) ~[?:?]
> > 	at org.openhab.binding.rfxcom.internal.handler.RFXComBridgeHandler.lambda$0(RFXComBridgeHandler.java:162) ~[?:?]
> > 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_265]
> > 	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_265]
> > 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_265]
> > 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_265]
> > 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_265]
> > 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_265]
> > 	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_265]

Cheers

Roscoe

14

It might be early days but i realised i accidentally installed the Mail action binding, which was also doing this every minute

2020-08-28 19:41:48.975 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing ‘openhab-action-mail’

So i removed it from the addon config file and restarted openhab, so far rfxcom is working fine. strange!

15

Old thread, but I recently (in the nightlies) fixed at least one bug that causes this. The binding was dropping the first byte of any message over 127 bytes long and then trying to parse the next byte as the length for the next message. Once out of sync it would eventually reach an unrecoverable state.

This bug has been around for ages, but it’s the raw message support in the more recent pro firmwares that have messages long enough to trigger it.

I wouldn’t be surprised if it was the cause here. The log messages were vague and really just showed messages that didn’t make sense.