RFXcom binding not responding after few days of operation

hermanvh · May 15, 2021, 4:31pm

I am using the RFXcom binding to control some Somfy sun, which normally are operating fine.
See 1st tracing.

After a few days of operation the binding does not accept any commands and also the binding does not receive anything from the RFXcom any more (normally there is fire alarm from the neighbours popping up every minutes).
See 2nd tracing, the 1st command is still send out, but the other 2 remain queued.

Any help appreciated.

12-mei-2021 16:00:00.044 [DEBUG] [nhab.binding.rfxcom.internal.handler.RFXComHandler] - Received channel: rfxcom:rfy:usb:010100_1:shutter, command: DOWN
12-mei-2021 16:00:00.052 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Transmitting message 'Raw data = unknown, Packet type = RFY, Seq number = 0, Sub type = RFY, Unit Id = 65792.1, Unit Code = 1, Command = DOWN, Signal level = 0'
12-mei-2021 16:00:00.053 [TRACE] [ng.rfxcom.internal.connector.RFXComSerialConnector] - Send data (len=13): 0C1A0000010100010300000000
12-mei-2021 16:00:00.090 [DEBUG] [nhab.binding.rfxcom.internal.handler.RFXComHandler] - Received channel: rfxcom:rfy:usb:010100_2:shutter, command: DOWN
12-mei-2021 16:00:00.094 [DEBUG] [nhab.binding.rfxcom.internal.handler.RFXComHandler] - Received channel: rfxcom:rfy:usb:010100_3:shutter, command: DOWN
12-mei-2021 16:00:00.527 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Message length is 4 bytes
12-mei-2021 16:00:00.528 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 4 bytes from the message
12-mei-2021 16:00:00.529 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:00.529 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 3 bytes from the message
12-mei-2021 16:00:00.530 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:00.531 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 2 bytes from the message
12-mei-2021 16:00:00.532 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:00.533 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 1 bytes from the message
12-mei-2021 16:00:00.534 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:00.535 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Message received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
12-mei-2021 16:00:00.536 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Transmitter response received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
12-mei-2021 16:00:00.537 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Transmitting message 'Raw data = unknown, Packet type = RFY, Seq number = 0, Sub type = RFY, Unit Id = 65792.2, Unit Code = 2, Command = DOWN, Signal level = 0'
12-mei-2021 16:00:00.538 [TRACE] [ng.rfxcom.internal.connector.RFXComSerialConnector] - Send data (len=13): 0C1A0000010100020300000000
12-mei-2021 16:00:01.182 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Message length is 4 bytes
12-mei-2021 16:00:01.184 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 4 bytes from the message
12-mei-2021 16:00:01.187 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:01.188 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 3 bytes from the message
12-mei-2021 16:00:01.189 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:01.190 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 2 bytes from the message
12-mei-2021 16:00:01.191 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:01.192 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 1 bytes from the message
12-mei-2021 16:00:01.193 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:01.194 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Message received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
12-mei-2021 16:00:01.194 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Transmitter response received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
12-mei-2021 16:00:01.195 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Transmitting message 'Raw data = unknown, Packet type = RFY, Seq number = 0, Sub type = RFY, Unit Id = 65792.3, Unit Code = 3, Command = DOWN, Signal level = 0'
12-mei-2021 16:00:01.195 [TRACE] [ng.rfxcom.internal.connector.RFXComSerialConnector] - Send data (len=13): 0C1A0000010100030300000000
12-mei-2021 16:00:01.822 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Message length is 4 bytes
12-mei-2021 16:00:01.823 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 4 bytes from the message
12-mei-2021 16:00:01.824 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:01.825 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 3 bytes from the message
12-mei-2021 16:00:01.826 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:01.827 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 2 bytes from the message
12-mei-2021 16:00:01.828 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:01.829 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 1 bytes from the message
12-mei-2021 16:00:01.830 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:01.832 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Message received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
12-mei-2021 16:00:01.833 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Transmitter response received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
12-mei-2021 16:00:56.750 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:01:56.752 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:02:56.753 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:03:56.755 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:04:56.757 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:05:56.759 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:06:20.282 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Message length is 8 bytes
12-mei-2021 16:06:20.283 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 8 bytes from the message
12-mei-2021 16:06:20.284 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:06:20.285 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 7 bytes from the message
12-mei-2021 16:06:20.285 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:06:20.286 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 6 bytes from the message
12-mei-2021 16:06:20.286 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:06:20.287 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 5 bytes from the message
12-mei-2021 16:06:20.287 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:06:20.288 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 4 bytes from the message
12-mei-2021 16:06:20.288 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:06:20.289 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 3 bytes from the message
12-mei-2021 16:06:20.289 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:06:20.290 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 2 bytes from the message
12-mei-2021 16:06:20.290 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:06:20.291 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 1 bytes from the message
12-mei-2021 16:06:20.291 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:06:20.291 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Message received: Raw data = 08200A91BCF99E0649, Packet type = SECURITY1, Seq number = 145, Sub type = RM174RF, Device Id = 12384670, Status = PANIC, Battery level = 4, Signal level = 9
12-mei-2021 16:06:20.292 [TRACE] [om.internal.discovery.RFXComDeviceDiscoveryService] - Received: bridge: rfxcom:bridge:usb message: Raw data = 08200A91BCF99E0649, Packet type = SECURITY1, Seq number = 145, Sub type = RM174RF, Device Id = 12384670, Status = PANIC, Battery level = 4, Signal level = 9
12-mei-2021 16:06:20.293 [TRACE] [om.internal.discovery.RFXComDeviceDiscoveryService] - Ignoring RFXCOM rfxcom:security1:usb:12384670 with id '12384670' - discovery disabled

12-mei-2021 16:06:51.265 [TRACE] [om.internal.discovery.RFXComDeviceDiscoveryService] - Received: bridge: rfxcom:bridge:usb message: Raw data = 08200A920D2E220649, Packet type = SECURITY1, Seq number = 146, Sub type = RM174RF, Device Id = 863778, Status = PANIC, Battery level = 4, Signal level = 9
12-mei-2021 16:06:51.266 [TRACE] [om.internal.discovery.RFXComDeviceDiscoveryService] - Ignoring RFXCOM rfxcom:security1:usb:863778 with id '863778' - discovery disabled
12-mei-2021 16:06:56.760 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:07:56.762 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:08:56.764 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:09:56.766 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:10:56.767 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:11:56.769 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:12:56.770 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:13:56.772 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:14:56.774 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:15:56.776 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:16:56.778 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:17:56.780 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:18:56.782 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:19:56.783 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:20:00.035 [DEBUG] [nhab.binding.rfxcom.internal.handler.RFXComHandler] - Received channel: rfxcom:rfy:usb:010100_1:shutter, command: DOWN
12-mei-2021 16:20:00.041 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Transmitting message 'Raw data = unknown, Packet type = RFY, Seq number = 0, Sub type = RFY, Unit Id = 65792.1, Unit Code = 1, Command = DOWN, Signal level = 0'
12-mei-2021 16:20:00.042 [TRACE] [ng.rfxcom.internal.connector.RFXComSerialConnector] - Send data (len=13): 0C1A0000010100010300000000
12-mei-2021 16:20:00.054 [DEBUG] [nhab.binding.rfxcom.internal.handler.RFXComHandler] - Received channel: rfxcom:rfy:usb:010100_2:shutter, command: DOWN
12-mei-2021 16:20:00.071 [DEBUG] [nhab.binding.rfxcom.internal.handler.RFXComHandler] - Received channel: rfxcom:rfy:usb:010100_3:shutter, command: DOWN
12-mei-2021 16:20:56.784 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:21:56.786 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:22:56.788 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:23:56.789 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:24:56.791 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:25:56.793 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:26:56.795 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:27:56.797 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:28:56.799 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:29:56.800 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:30:56.801 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:31:56.803 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:32:56.805 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:33:56.807 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:34:56.809 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:35:56.811 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:36:56.813 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:37:56.815 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:38:56.816 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:39:56.818 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:40:56.819 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:41:56.821 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
12-mei-2021 16:42:56.823 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE
1

bweijenberg · May 15, 2021, 8:04pm

This problem is in most cases due to a bad power supply. See the FAQ chapter in the RFXtrx User Guide.

hermanvh · May 16, 2021, 12:37pm

Bert,

Thanks for the reply.
I do have the RFXcom on a usb hub with a seperate supply.
Furthermore when the problem occurs, it does not resolve by unplugging and replugging the RFXcom unit, but after a reboot of the CPU it works again.
So I am not convinced the problem is related to a power glitch.
Question: should the software be able to recover after replugging the RFX unit?

bweijenberg · May 16, 2021, 2:24pm

I agree, this seems to be another problem. A disconnect of the RFXtrx on a Raspberry PI can normally be resolved by unplug the USB and reconnect it.

hermanvh · May 16, 2021, 7:23pm

@martinvw, can you help you to debug this?

Thanks Herman

martinvw · May 17, 2021, 3:37pm

I would expect the binding to at least notice that it is no longer reachable, and report this and bring the connection OFFLINE. After that it should retry when possible. Do you have some more logging demonstrating what happens in such cases?

hermanvh · May 17, 2021, 4:45pm

Martin,

See the the 2nd log at 16:20. The binding continues to report ONLINE, but the 3 received commands are not executed in the same manner as in 1st log. The log level is at TRACE, I do know how to capture more info.

The commands below are not send out.

12-mei-2021 16:20:00.035 [DEBUG] [nhab.binding.rfxcom.internal.handler.RFXComHandler] - Received channel: rfxcom:rfy:usb:010100_1:shutter, command: DOWN
12-mei-2021 16:20:00.041 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Transmitting message 'Raw data = unknown, Packet type = RFY, Seq number = 0, Sub type = RFY, Unit Id = 65792.1, Unit Code = 1, Command = DOWN, Signal level = 0'
12-mei-2021 16:20:00.042 [TRACE] [ng.rfxcom.internal.connector.RFXComSerialConnector] - Send data (len=13): 0C1A0000010100010300000000
12-mei-2021 16:20:00.054 [DEBUG] [nhab.binding.rfxcom.internal.handler.RFXComHandler] - Received channel: rfxcom:rfy:usb:010100_2:shutter, command: DOWN
12-mei-2021 16:20:00.071 [DEBUG] [nhab.binding.rfxcom.internal.handler.RFXComHandler] - Received channel: rfxcom:rfy:usb:010100_3:shutter, command: DOWN

From the 1st log, where the same commands are send out:

12-mei-2021 16:00:00.044 [DEBUG] [nhab.binding.rfxcom.internal.handler.RFXComHandler] - Received channel: rfxcom:rfy:usb:010100_1:shutter, command: DOWN
12-mei-2021 16:00:00.052 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Transmitting message 'Raw data = unknown, Packet type = RFY, Seq number = 0, Sub type = RFY, Unit Id = 65792.1, Unit Code = 1, Command = DOWN, Signal level = 0'
12-mei-2021 16:00:00.053 [TRACE] [ng.rfxcom.internal.connector.RFXComSerialConnector] - Send data (len=13): 0C1A0000010100010300000000
12-mei-2021 16:00:00.090 [DEBUG] [nhab.binding.rfxcom.internal.handler.RFXComHandler] - Received channel: rfxcom:rfy:usb:010100_2:shutter, command: DOWN
12-mei-2021 16:00:00.094 [DEBUG] [nhab.binding.rfxcom.internal.handler.RFXComHandler] - Received channel: rfxcom:rfy:usb:010100_3:shutter, command: DOWN
12-mei-2021 16:00:00.527 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Message length is 4 bytes
12-mei-2021 16:00:00.528 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 4 bytes from the message
12-mei-2021 16:00:00.529 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:00.529 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 3 bytes from the message
12-mei-2021 16:00:00.530 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:00.531 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 2 bytes from the message
12-mei-2021 16:00:00.532 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:00.533 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 1 bytes from the message
12-mei-2021 16:00:00.534 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:00.535 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Message received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
12-mei-2021 16:00:00.536 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Transmitter response received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
12-mei-2021 16:00:00.537 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Transmitting message 'Raw data = unknown, Packet type = RFY, Seq number = 0, Sub type = RFY, Unit Id = 65792.2, Unit Code = 2, Command = DOWN, Signal level = 0'
12-mei-2021 16:00:00.538 [TRACE] [ng.rfxcom.internal.connector.RFXComSerialConnector] - Send data (len=13): 0C1A0000010100020300000000
12-mei-2021 16:00:01.182 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Message length is 4 bytes
12-mei-2021 16:00:01.184 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 4 bytes from the message
12-mei-2021 16:00:01.187 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:01.188 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 3 bytes from the message
12-mei-2021 16:00:01.189 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:01.190 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 2 bytes from the message
12-mei-2021 16:00:01.191 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:01.192 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 1 bytes from the message
12-mei-2021 16:00:01.193 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:01.194 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Message received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
12-mei-2021 16:00:01.194 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Transmitter response received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
12-mei-2021 16:00:01.195 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Transmitting message 'Raw data = unknown, Packet type = RFY, Seq number = 0, Sub type = RFY, Unit Id = 65792.3, Unit Code = 3, Command = DOWN, Signal level = 0'
12-mei-2021 16:00:01.195 [TRACE] [ng.rfxcom.internal.connector.RFXComSerialConnector] - Send data (len=13): 0C1A0000010100030300000000
12-mei-2021 16:00:01.822 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Message length is 4 bytes
12-mei-2021 16:00:01.823 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 4 bytes from the message
12-mei-2021 16:00:01.824 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:01.825 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 3 bytes from the message
12-mei-2021 16:00:01.826 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:01.827 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 2 bytes from the message
12-mei-2021 16:00:01.828 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:01.829 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Waiting remaining 1 bytes from the message
12-mei-2021 16:00:01.830 [TRACE] [nding.rfxcom.internal.connector.RFXComStreamReader] - Received 1 bytes from the message
12-mei-2021 16:00:01.832 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Message received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK
12-mei-2021 16:00:01.833 [DEBUG] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Transmitter response received: Raw data = 0402010000, Packet type = TRANSMITTER_MESSAGE, Seq number = 0, Sub type = RESPONSE, Response = ACK

martinvw · May 17, 2021, 6:05pm

To break out of this method I would expect an error somewhere in your log?

What is the status of your bridge according to the UI?

Do you happen to see any of these logs between the last successful and first problem:

Received exception, will report it to listeners
Data listener stopped
End of stream
Connector died:

hermanvh · May 17, 2021, 6:49pm

Sorry, none of these messages only a few of these lines

12-mei-2021 16:19:56.783 [TRACE] [inding.rfxcom.internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = ONLINE

hermanvh · May 17, 2021, 6:50pm

And status of the bridge is ONLINE.

Herman

martinvw · May 18, 2021, 12:31pm

Would it be possible that you send me (privately?) the complete logging between the successful and the failed attempt?

hermanvh · May 18, 2021, 4:42pm

PM send

Robert234 · May 20, 2021, 6:04am

Right - so I’ve been battling with this, on and off, for months - but it’s got a Following here: RFXCOM Binding stops working after some time - I also I can avoid it - I can always use a new PI, but have no use for 2 RFXComs.

navyarmyccu

martinvw · May 20, 2021, 5:57pm

Sorry, I do not think that I completely understand what you mean. Could you clarify it further? Do you still face this issue have you resolved it by replacing the RFXCOM or Pi?

@hermanvh I think that I will build a binding with some additional logging, it really seems to be that without any error the binding just does not get any response at all, I have some expectations where the code is looping but I need some extra logging to make sure I’m right.

Download the jar at: https://download.martinvw.nl/org.openhab.binding.rfxcom-3.1.0-SNAPSHOT-verbose-reader-logging.jar