RFXCOM: Error occurred during packet receiving

So I have been using the RFXCOM for several years without any problems. I am using ser2net (similar to socat) and the tcpbridge access method of the RFXCOM binding. My OH 3.4.2 is running in Docker.

So today I updated the my Ubuntu host with a simply “sudo apt-get update” + “apt-get upgrade” + reboot. The OH Docker version remained unchanged. After that everything works fine except the RFXCOM binding.

The OH log file comes with this every minute:

2023-04-10 18:43:11.464 [ERROR] [internal.handler.RFXComBridgeHandler] - Error occurred during packet receiving, data: 207463702C31303031206465766963652073657269616C6465762C202F6465762F

org.openhab.binding.rfxcom.internal.exceptions.RFXComUnsupportedValueException: Unsupported value '116' for PacketType

	at org.openhab.binding.rfxcom.internal.messages.ByteEnumUtil.fromByte(ByteEnumUtil.java:37) ~[bundleFile:?]

	at org.openhab.binding.rfxcom.internal.messages.RFXComMessageFactoryImpl.createMessage(RFXComMessageFactoryImpl.java:125) ~[bundleFile:?]

	at org.openhab.binding.rfxcom.internal.handler.RFXComBridgeHandler$MessageListener.packetReceived(RFXComBridgeHandler.java:259) [bundleFile:?]

	at org.openhab.binding.rfxcom.internal.connector.RFXComBaseConnector.sendMsgToListeners(RFXComBaseConnector.java:49) [bundleFile:?]

	at org.openhab.binding.rfxcom.internal.connector.RFXComStreamReader.run(RFXComStreamReader.java:71) [bundleFile:?]

2023-04-10 18:43:12.169 [ERROR] [internal.handler.RFXComBridgeHandler] - Error occurred: Timeout during packet read

Sometimes I also receive this message:

2023-04-10 18:41:10.853 [ERROR] [internal.handler.RFXComBridgeHandler] - Error occurred during packet receiving, data: 0D0A736572326E657420706F7274

org.openhab.binding.rfxcom.internal.exceptions.RFXComUnsupportedValueException: Unsupported value '10' for PacketType

I could not understand this and tried to to replace ser2net with socat, but that did not work either.
Then I unmounted the RFXtrx433XL device, upgraded to latest firmware #1048 via RFXFlash and tried the hardware using RFXmngr and it works fine. Moving the RFXtrx433XL back to my Ubunto Intel based PC, but still it does not work. I have restarted both ser2net and OH several times.

The UFW firewall in my Ubuntu version 22.04.2 is disabled.

I also added an entry here, because I do not know the root of this problem.

Hope someone can share some light on this. :pray:

EDIT: I added the TRACE option in Karaf console and got this:

2023-04-10 19:10:06.716 [DEBUG] [internal.handler.RFXComBridgeHandler] - Initializing RFXCOM bridge handler

2023-04-10 19:10:06.718 [TRACE] [internal.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = OFFLINE

2023-04-10 19:10:06.722 [DEBUG] [internal.handler.RFXComBridgeHandler] - Connecting to RFXCOM transceiver

2023-04-10 19:10:06.723 [DEBUG] [nternal.connector.RFXComTcpConnector] - Disconnecting

2023-04-10 19:10:06.723 [DEBUG] [nternal.connector.RFXComTcpConnector] - Closed

2023-04-10 19:10:06.724 [INFO ] [nternal.connector.RFXComTcpConnector] - Connecting to RFXCOM at localhost:1001 over TCP/IP

2023-04-10 19:10:06.723 [DEBUG] [fxcom.internal.handler.RFXComHandler] - Initializing thing rfxcom:rfy:rfxcom1:ThRullegardin4ForanHuset

2023-04-10 19:10:06.725 [DEBUG] [fxcom.internal.handler.RFXComHandler] - initializeBridge OFFLINE for thing rfxcom:rfy:rfxcom1:ThRullegardin4ForanHuset

2023-04-10 19:10:06.724 [DEBUG] [fxcom.internal.handler.RFXComHandler] - Initializing thing rfxcom:rfy:rfxcom1:ThRullegardin2Sovevaerlse

2023-04-10 19:10:06.725 [DEBUG] [fxcom.internal.handler.RFXComHandler] - initializeBridge OFFLINE for thing rfxcom:rfy:rfxcom1:ThRullegardin2Sovevaerlse

2023-04-10 19:10:06.724 [DEBUG] [fxcom.internal.handler.RFXComHandler] - Initializing thing rfxcom:rfy:rfxcom1:ThRullegardin1Mellemgang

2023-04-10 19:10:06.726 [DEBUG] [fxcom.internal.handler.RFXComHandler] - initializeBridge OFFLINE for thing rfxcom:rfy:rfxcom1:ThRullegardin1Mellemgang

2023-04-10 19:10:06.727 [DEBUG] [internal.handler.RFXComBridgeHandler] - Reset controller

2023-04-10 19:10:06.727 [TRACE] [nternal.connector.RFXComTcpConnector] - Send data (len=14): 0D00000000000000000000000000

2023-04-10 19:10:06.727 [DEBUG] [nternal.connector.RFXComStreamReader] - Data listener started

2023-04-10 19:10:06.728 [DEBUG] [fxcom.internal.handler.RFXComHandler] - Initializing thing rfxcom:rfy:rfxcom1:ThRullegardin3Sovevaerlse

2023-04-10 19:10:06.728 [DEBUG] [fxcom.internal.handler.RFXComHandler] - initializeBridge OFFLINE for thing rfxcom:rfy:rfxcom1:ThRullegardin3Sovevaerlse

2023-04-10 19:10:06.728 [TRACE] [nternal.connector.RFXComStreamReader] - Message length is 13 bytes

2023-04-10 19:10:06.729 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 13 bytes from the message

2023-04-10 19:10:06.730 [TRACE] [nternal.connector.RFXComStreamReader] - Received 13 bytes from the message

2023-04-10 19:10:06.731 [TRACE] [nternal.connector.RFXComStreamReader] - Message length is 32 bytes

2023-04-10 19:10:06.731 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 32 bytes from the message

2023-04-10 19:10:06.731 [TRACE] [nternal.connector.RFXComStreamReader] - Received 32 bytes from the message

2023-04-10 19:10:06.732 [TRACE] [nternal.connector.RFXComStreamReader] - Message length is 116 bytes

2023-04-10 19:10:06.732 [DEBUG] [fxcom.internal.handler.RFXComHandler] - Initializing thing rfxcom:rfy:rfxcom1:ThRullegardinVindueVest

2023-04-10 19:10:06.732 [DEBUG] [fxcom.internal.handler.RFXComHandler] - initializeBridge OFFLINE for thing rfxcom:rfy:rfxcom1:ThRullegardinVindueVest

2023-04-10 19:10:06.732 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 116 bytes from the message

2023-04-10 19:10:06.732 [DEBUG] [fxcom.internal.handler.RFXComHandler] - Initializing thing rfxcom:rfy:rfxcom1:ThRullegardinAltanVest

2023-04-10 19:10:06.733 [DEBUG] [fxcom.internal.handler.RFXComHandler] - initializeBridge OFFLINE for thing rfxcom:rfy:rfxcom1:ThRullegardinAltanVest

2023-04-10 19:10:06.733 [TRACE] [nternal.connector.RFXComStreamReader] - Received 48 bytes from the message

2023-04-10 19:10:06.734 [DEBUG] [fxcom.internal.handler.RFXComHandler] - Initializing thing rfxcom:rfy:rfxcom1:ThRullegardinAlleVest

2023-04-10 19:10:06.734 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 68 bytes from the message

2023-04-10 19:10:06.734 [DEBUG] [fxcom.internal.handler.RFXComHandler] - initializeBridge OFFLINE for thing rfxcom:rfy:rfxcom1:ThRullegardinAlleVest

2023-04-10 19:10:06.735 [DEBUG] [fxcom.internal.handler.RFXComHandler] - Initializing thing rfxcom:rfy:rfxcom1:ThRullegardinAlle

2023-04-10 19:10:06.735 [DEBUG] [fxcom.internal.handler.RFXComHandler] - initializeBridge OFFLINE for thing rfxcom:rfy:rfxcom1:ThRullegardinAlle

2023-04-10 19:10:06.834 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 68 bytes from the message

2023-04-10 19:10:06.935 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 68 bytes from the message

2023-04-10 19:10:07.028 [DEBUG] [internal.handler.RFXComBridgeHandler] - Get status of controller

2023-04-10 19:10:07.028 [TRACE] [nternal.connector.RFXComTcpConnector] - Send data (len=14): 0D00000102000000000000000000

2023-04-10 19:10:07.036 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 68 bytes from the message

2023-04-10 19:10:07.050 [TRACE] [nternal.connector.RFXComStreamReader] - Received 21 bytes from the message

2023-04-10 19:10:07.051 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 47 bytes from the message

2023-04-10 19:10:07.152 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 47 bytes from the message

2023-04-10 19:10:07.253 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 47 bytes from the message

2023-04-10 19:10:07.354 [TRACE] [nternal.connector.RFXComStreamReader] - Waiting remaining 47 bytes from the message

2023-04-10 19:10:07.455 [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-04-10 19:10:07.456 [ERROR] [internal.handler.RFXComBridgeHandler] - Error occurred: Timeout during packet read

Seems that it is only receiving a part of the message…

Data which binding receive seems to something else than data from rfxcom device. If I convert hex strings from your log to ascii, it seems to be related to ser2net, so I would assume that issue is related to ser2net.

207463702C31303031206465766963652073657269616C6465762C202F6465762F -> "tcp,1001 device serialdev, /dev/"

0D0A736572326E657420706F7274 -> "\r\nser2net port"

Thank you @pauli_anttila for putting focus on the actual contents received. Via that + the help from the creator of ser2net, it was identified that is was my misconfiguration of ser2net. I had added a so called banner in my ser2net config yml config file, which should be removed. After that everything works fine.