RFXCOM: Error occurred during packet receiving

AndreH · July 3, 2017, 4:22pm

@martinvw: it is HW 1.3 and firmware 251. I have updated to firmware 1020

After upgrading to the current firmware, the error disappeared.

Thank you!!

rainer300 · July 4, 2017, 5:50am

Hi, I have also upgraded to OH 2.1 and the newest firmware on my RFXCOM (1020).
However, my RFXtrx433 bridge thing does not work – i receive an communication error.
Here ist the log:

17:52:01.426 [ERROR] [g.rfxcom.handler.RFXComBridgeHandler] - Error occurred: Read timed out
17:52:01.628 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'rfxcom:tcpbridge:85d27ccc' changed from OFFLINE to OFFLINE (COMMUNICATION_ERROR)

After reinstall the older version OH 2.0 everything is ok and the RFXtrx433 bridge is online again:

apt-get --reinstall install openhab2=2.0.0-1

Has anyone an idea how to fix this error in HO 2.1?

Kind regards
rainer

martinvw · July 4, 2017, 8:28am

Could you supply some debug logging maybe for both the 2.0.0 version and the 2.1.0 version?

rainer300 · July 4, 2017, 3:47pm

@martinvw,
there are no more entries (rfx or RFX) in the log-file, even if the log-level is set to DEBUG

OH 2.1:

17:38:05.053 [INFO ] [nternal.connector.RFXComTcpConnector] - Connecting to RFXCOM at 192.168.1.112:1001 over TCP/IP
17:38:05.158 [ERROR] [g.rfxcom.handler.RFXComBridgeHandler] - Error occurred: Read timed out

OH 2.0

17:49:13.302 [INFO ] [nternal.connector.RFXComTcpConnector] - Connecting to RFXCOM at 192.168.1.112:1001 over TCP/IP
17:49:13.634 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'rfxcom:tcpbridge:85d27ccc' changed from OFFLINE to ONLINE
17:49:13.635 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'rfxcom:lighting1:9737f707:L_0' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE

martinvw · July 4, 2017, 5:52pm

@mjagdis do you think it is likely that this is related to on of the refactorings we did?

rainer300 · July 4, 2017, 6:11pm

i have no idea

martinvw · July 4, 2017, 8:15pm

I created a pull request: https://github.com/openhab/openhab2-addons/pull/2433

If you uninstall the existing rfxcom binding you should be able to place my jar in your addons directory, some searching (on the community forum) should help you out.

Download: https://github.com/openhab/openhab2-addons/files/1122991/org.openhab.binding.rfxcom-2.2.0-SNAPSHOT.jar.zip

PS it is zipped jar, so first unpack before throwing it in the addons directory.

rainer300 · July 5, 2017, 3:52pm

@martinvw
After uninstall the existing rfxcom binding i have installed the org.openhab.binding.rfxcom-2.2.0-SNAPSHOT.jar as described but the result is the same (error timed out).
This happens in both versions the old one (OH 2.0) and the new version (OH 2.1).

I get the RFXtrx433 bridge only run with a fresh install of OH 2.0 (including the rfxcom binding 2.0).

martinvw · July 5, 2017, 6:21pm

@rainer300

I have added some debug logging, just to be sure can you now, or for the new jar check via the karaf console with bundle:list that the correct bundle is loaded?

I also doubt whether setting debug-ing succeeded, I miss a lot debug message which you must reach. Could you do log:get in karaf and post the result?

You could tail directly from karaf by setting:

log:set TRACE org.openhab.binding.rfxcom
log:tail org.openhab.binding.rfxcom

Download: https://github.com/openhab/openhab2-addons/files/1125679/org.openhab.binding.rfxcom-2.2.0-SNAPSHOT.jar.zip

rainer300 · July 7, 2017, 2:38pm

@martinvw
Now it works

What i have done:

apt-get upgrade (-> OH 2.1)
uninstall the rfxcom-Binding (paperui)
download an place the new .jar (2.2.0.201707051837 - your link above) in my addons directory
restart openhab2

Thanks for your help!!

james_2_roberts · July 9, 2017, 7:28pm

Hi there,

Hope you don’t mind me joining this thread…

I tried your snapshot version of the binding; when I add a new thing manually through paper UI, openhab2 crashes:
openhab.log:

2017-07-09 20:22:52.231 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at http://192.168.1.97:8080
2017-07-09 20:23:07.699 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at https://192.168.1.97:8443
2017-07-09 20:23:07.873 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-07-09 20:23:08.560 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2017-07-09 20:23:08.575 [DEBUG] [org.openhab.binding.rfxcom          ] - BundleEvent STARTING - org.openhab.binding.rfxcom
2017-07-09 20:23:08.577 [DEBUG] [org.openhab.binding.rfxcom          ] - BundleEvent STARTED - org.openhab.binding.rfxcom
2017-07-09 20:23:08.596 [DEBUG] [org.openhab.binding.rfxcom          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={component.name=org.openhab.binding.rfxcom.discovery, component.id=160, service.id=282, service.bundleid=186, service.scope=bundle} - org.openhab.binding.rfxcom
2017-07-09 20:23:08.631 [DEBUG] [org.openhab.binding.rfxcom          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.rfxcom.internal.RFXComHandlerFactory, component.id=161, service.id=283, service.bundleid=186, service.scope=bundle} - org.openhab.binding.rfxcom
2017-07-09 20:24:54.842 [DEBUG] [org.openhab.binding.rfxcom          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=286, service.bundleid=186, service.scope=singleton} - org.openhab.binding.rfxcom
2017-07-09 20:24:54.870 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Initializing RFXCOM bridge handler
2017-07-09 20:24:54.908 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = OFFLINE
2017-07-09 20:24:54.909 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Connecting to RFXCOM transceiver
2017-07-09 20:24:54.933 [DEBUG] [rnal.connector.RFXComSerialConnector] - Disconnecting
2017-07-09 20:24:54.934 [DEBUG] [rnal.connector.RFXComSerialConnector] - Closed

Karaf console:


                          __  _____    ____
  ____  ____  ___  ____  / / / /   |  / __ )
 / __ \/ __ \/ _ \/ __ \/ /_/ / /| | / __  |
/ /_/ / /_/ /  __/ / / / __  / ___ |/ /_/ /
\____/ .___/\___/_/ /_/_/ /_/_/  |_/_____/
    /_/                        2.1.0
                               - release build -

Hit '<tab>' for a list of available commands
and '[cmd] --help' for help on a specific command.
Hit '<ctrl-d>' or type 'system:shutdown' or 'logout' to shutdown openHAB.

openhab> smarthome:items list
No item found for this pattern.
openhab> smarthome:things list
No things found.
openhab> Connection to localhost closed by remote host.
Connection to localhost closed.
pi@openhab /usr/share/openhab2 $

Happy to help debug where I’m able…

Cheers
James

martinvw · July 10, 2017, 5:37am

What hardware / kernel are you running one? Is it maybe similar to the issues described at the bottom of:

james_2_roberts · July 10, 2017, 8:15am

Hi Martin,

I’ll need to check kernel, running wheezy on an rpi3.

That said, the issue you reference mirrors exactly my experiences, when I’m home later I’ll run in debug as suggested and see if I get anything additional.

Thank you - I was beginning to think I was going mad at not being able to solve this!

Cheers
James

james_2_roberts · July 11, 2017, 7:10am

Hi Martin,

Is this the kernel version you require:

pi@openhab /var/log/openhab2 $ cat /proc/version
Linux version 4.4.20-v7+ (dc4@dc4-XPS13-9333) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611) ) #908 SMP Wed Sep 7 14:44:27 BST 2016

I also get the same error from the karaf console:

08:05:43.518 [DEBUG] [org.openhab.binding.rfxcom          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=288, service.bundleid=186, service.scope=singleton} - org.openhab.binding.rfxcom
08:05:43.542 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Initializing RFXCOM bridge handler
08:05:43.548 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = OFFLINE
08:05:43.549 [DEBUG] [g.rfxcom.handler.RFXComBridgeHandler] - Connecting to RFXCOM transceiver
08:05:43.571 [DEBUG] [rnal.connector.RFXComSerialConnector] - Disconnecting
08:05:43.575 [DEBUG] [rnal.connector.RFXComSerialConnector] - Closed
/usr/bin/java: symbol lookup error: /var/lib/openhab2/tmp/libNRJavaSerial_HF_root_0/libNRJavaSerial_HF.so: undefined symbol: __fdelt_chk

Thanks
James

james_2_roberts · July 12, 2017, 7:45am

Hi Martin,

I’ve upgraded my rpi to jessie which includes the libc upgraded version and the RFXcom appears to be working sweetly!

Many thanks
James

metz · February 18, 2019, 10:33am

Hello,

I’ve a similar problem. Tested with Rfxtrx433E batch 1015 and Software Version 1035 / 1026. Could not download / test Version 1020.

The Rfxtrx is connected via USB to a raspberry pi and running socat.
socat tcp-listen:10000,fork,reuseaddr file:/dev/ttyUSB0,raw

After receiving of a signal I get a timeout and the datalistener stopped. Actually only one device sending messages wich are received and encoded correctly when I use RFXmngr.

cat /proc/version
Linux version 4.4.0-142-generic (buildd@lgw01-amd64-033) (gcc version 5.4.0 20160609 (Ubuntu5.4.0-6ubuntu1~16.04.10) ) #168-Ubuntu SMP Wed Jan 16 21:00:45 UTC 2019

lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 16.04.5 LTS
Release:        16.04
Codename:       xenial

ldd --version
ldd (Ubuntu GLIBC 2.23-0ubuntu10) 2.23

openhab> version
4.2.1

openhab> log:set TRACE org.openhab.binding.rfxcom
openhab> log:tail org.openhab.binding.rfxcom
10:32:47.194 [INFO ] [internal.connector.RFXComTcpConnector] - Connecting to RFXCOM at 192.168.1.11:10000 over TCP/IP
10:32:47.196 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Reset controller
10:32:47.198 [TRACE] [internal.connector.RFXComTcpConnector] - Send data (len=14): 0D00000000000000000000000000
10:32:47.199 [DEBUG] [internal.connector.RFXComStreamReader] - Data listener started
10:32:47.498 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Get status of controller
10:32:47.499 [TRACE] [internal.connector.RFXComTcpConnector] - Send data (len=14): 0D00000102000000000000000000
10:33:47.500 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = OFFLINE
10:33:47.502 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Connecting to RFXCOM transceiver
10:33:47.502 [DEBUG] [internal.connector.RFXComTcpConnector] - Disconnecting
10:33:47.503 [DEBUG] [internal.connector.RFXComTcpConnector] - Interrupt stream listener
10:33:47.565 [DEBUG] [internal.connector.RFXComStreamReader] - Data listener stopped
10:33:47.566 [DEBUG] [internal.connector.RFXComTcpConnector] - Close tcp out stream
10:33:47.567 [DEBUG] [internal.connector.RFXComTcpConnector] - Close tcp in stream
10:33:47.573 [DEBUG] [internal.connector.RFXComTcpConnector] - Close socket
10:33:47.574 [DEBUG] [internal.connector.RFXComTcpConnector] - Closed
10:33:47.575 [INFO ] [internal.connector.RFXComTcpConnector] - Connecting to RFXCOM at 192.168.1.11:10000 over TCP/IP
10:33:47.581 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Reset controller
10:33:47.582 [TRACE] [internal.connector.RFXComTcpConnector] - Send data (len=14): 0D00000000000000000000000000
10:33:47.583 [DEBUG] [internal.connector.RFXComStreamReader] - Data listener started
10:33:47.882 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Get status of controller
10:33:47.883 [TRACE] [internal.connector.RFXComTcpConnector] - Send data (len=14): 0D00000102000000000000000000
10:34:08.974 [DEBUG] [internal.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) ~[213:org.openhab.binding.rfxcom:2.4.0]
        at org.openhab.binding.rfxcom.internal.connector.RFXComStreamReader.run(RFXComStreamReader.java:61) [213:org.openhab.binding.rfxcom:2.4.0]
10:34:08.976 [ERROR] [ng.rfxcom.handler.RFXComBridgeHandler] - Error occurred: Timeout during packet read
10:34:08.979 [DEBUG] [internal.connector.RFXComStreamReader] - Data listener stopped
10:34:47.884 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = OFFLINE
10:34:47.885 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Connecting to RFXCOM transceiver
10:34:47.885 [DEBUG] [internal.connector.RFXComTcpConnector] - Disconnecting
10:34:47.885 [DEBUG] [internal.connector.RFXComTcpConnector] - Interrupt stream listener
10:34:47.887 [DEBUG] [internal.connector.RFXComTcpConnector] - Close tcp out stream
10:34:47.887 [DEBUG] [internal.connector.RFXComTcpConnector] - Close tcp in stream
10:34:47.887 [DEBUG] [internal.connector.RFXComTcpConnector] - Close socket
10:34:47.888 [DEBUG] [internal.connector.RFXComTcpConnector] - Closed
10:34:47.891 [INFO ] [internal.connector.RFXComTcpConnector] - Connecting to RFXCOM at 192.168.1.11:10000 over TCP/IP
10:34:47.893 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Reset controller
10:34:47.893 [TRACE] [internal.connector.RFXComTcpConnector] - Send data (len=14): 0D00000000000000000000000000
10:34:47.902 [DEBUG] [internal.connector.RFXComStreamReader] - Data listener started
10:34:48.195 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Get status of controller
10:34:48.195 [TRACE] [internal.connector.RFXComTcpConnector] - Send data (len=14): 0D00000102000000000000000000

10:35:48.196 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = OFFLINE
10:35:48.200 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Connecting to RFXCOM transceiver
10:35:48.201 [DEBUG] [internal.connector.RFXComTcpConnector] - Disconnecting
10:35:48.202 [DEBUG] [internal.connector.RFXComTcpConnector] - Interrupt stream listener
10:35:48.261 [DEBUG] [internal.connector.RFXComStreamReader] - Data listener stopped
10:35:48.263 [DEBUG] [internal.connector.RFXComTcpConnector] - Close tcp out stream
10:35:48.265 [DEBUG] [internal.connector.RFXComTcpConnector] - Close tcp in stream
10:35:48.269 [DEBUG] [internal.connector.RFXComTcpConnector] - Close socket
10:35:48.271 [DEBUG] [internal.connector.RFXComTcpConnector] - Closed
10:35:48.280 [INFO ] [internal.connector.RFXComTcpConnector] - Connecting to RFXCOM at 192.168.1.11:10000 over TCP/IP
10:35:48.286 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Reset controller
10:35:48.288 [TRACE] [internal.connector.RFXComTcpConnector] - Send data (len=14): 0D00000000000000000000000000
10:35:48.294 [DEBUG] [internal.connector.RFXComStreamReader] - Data listener started
10:35:48.591 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Get status of controller
10:35:48.594 [TRACE] [internal.connector.RFXComTcpConnector] - Send data (len=14): 0D00000102000000000000000000
10:36:11.975 [DEBUG] [internal.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) ~[213:org.openhab.binding.rfxcom:2.4.0]
        at org.openhab.binding.rfxcom.internal.connector.RFXComStreamReader.run(RFXComStreamReader.java:61) [213:org.openhab.binding.rfxcom:2.4.0]
10:36:11.986 [ERROR] [ng.rfxcom.handler.RFXComBridgeHandler] - Error occurred: Timeout during packet read
10:36:11.991 [DEBUG] [internal.connector.RFXComStreamReader] - Data listener stopped
10:36:34.115 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Handler disposed.
10:36:34.118 [DEBUG] [internal.connector.RFXComTcpConnector] - Disconnecting
10:36:34.120 [DEBUG] [internal.connector.RFXComTcpConnector] - Interrupt stream listener
10:36:34.121 [DEBUG] [internal.connector.RFXComTcpConnector] - Close tcp out stream
10:36:34.125 [DEBUG] [internal.connector.RFXComTcpConnector] - Close tcp in stream
10:36:34.133 [DEBUG] [internal.connector.RFXComTcpConnector] - Close socket
10:36:34.134 [DEBUG] [internal.connector.RFXComTcpConnector] - Closed

metz · February 18, 2019, 3:17pm

Fixed the issue.

socat tcp-listen:10001,fork,reuseaddr file:/dev/ttyUSB0,b38400,raw

I did also a change from the pro type software to the ext type software and found th 1020 Version. But only adding baud to socat fixed the issue.

Maybe it would be good to mention the minimum software version and the baud in the documentation.

Now I’m wondering why the connection is still offline and the system always reconnect.

16:12:33.671 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = OFFLINE
16:12:33.673 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Connecting to RFXCOM transceiver
16:12:33.674 [DEBUG] [internal.connector.RFXComTcpConnector] - Disconnecting
16:12:33.681 [DEBUG] [internal.connector.RFXComTcpConnector] - Interrupt stream listener
16:12:33.699 [DEBUG] [internal.connector.RFXComStreamReader] - Data listener stopped
16:12:33.701 [DEBUG] [internal.connector.RFXComTcpConnector] - Close tcp out stream
16:12:33.703 [DEBUG] [internal.connector.RFXComTcpConnector] - Close tcp in stream
16:12:33.705 [DEBUG] [internal.connector.RFXComTcpConnector] - Close socket
16:12:33.707 [DEBUG] [internal.connector.RFXComTcpConnector] - Closed
16:12:33.710 [INFO ] [internal.connector.RFXComTcpConnector] - Connecting to RFXCOM at 192.168.1.12:10001 over TCP/IP
16:12:33.724 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Reset controller
16:12:33.726 [TRACE] [internal.connector.RFXComTcpConnector] - Send data (len=14): 0D00000000000000000000000000
16:12:33.732 [DEBUG] [internal.connector.RFXComStreamReader] - Data listener started
16:12:34.028 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Get status of controller
16:12:34.029 [TRACE] [internal.connector.RFXComTcpConnector] - Send data (len=14): 0D00000102000000000000000000
16:13:04.520 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Message received: Raw data = 0A5201007A0200E6240259, Packet type = TEMPERATURE_HUMIDITY, Seq number = 0, Sub type = TH1, Device Id = 31234, Temperature = 23.0, Humidity = 36, Humidity status = DRY, Signal level = 5, Battery level = 9
16:13:04.523 [TRACE] [iscovery.RFXComDeviceDiscoveryService] - Received: bridge: rfxcom:tcpbridge:rp_wohnzimmer message: Raw data = 0A5201007A0200E6240259, Packet type = TEMPERATURE_HUMIDITY, Seq number = 0, Sub type = TH1, Device Id = 31234, Temperature = 23.0, Humidity = 36, Humidity status = DRY, Signal level = 5, Battery level = 9
16:13:04.525 [TRACE] [iscovery.RFXComDeviceDiscoveryService] - Adding new RFXCOM rfxcom:temperaturehumidity:rp_wohnzimmer:31234 with id '31234' to smarthome inbox
16:13:04.526 [DEBUG] [.binding.rfxcom.handler.RFXComHandler] - Received message from bridge: rfxcom:tcpbridge:rp_wohnzimmer message: Raw data = 0A5201007A0200E6240259, Packet type = TEMPERATURE_HUMIDITY, Seq number = 0, Sub type = TH1, Device Id = 31234, Temperature = 23.0, Humidity = 36, Humidity status = DRY, Signal level = 5, Battery level = 9
16:13:25.538 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Message received: Raw data = 0A520101960100AB120240, Packet type = TEMPERATURE_HUMIDITY, Seq number = 1, Sub type = TH1, Device Id = 38401, Temperature = 17.1, Humidity = 18, Humidity status = DRY, Signal level = 4, Battery level = 0
16:13:25.540 [TRACE] [iscovery.RFXComDeviceDiscoveryService] - Received: bridge: rfxcom:tcpbridge:rp_wohnzimmer message: Raw data = 0A520101960100AB120240, Packet type = TEMPERATURE_HUMIDITY, Seq number = 1, Sub type = TH1, Device Id = 38401, Temperature = 17.1, Humidity = 18, Humidity status = DRY, Signal level = 4, Battery level = 0
16:13:25.541 [TRACE] [iscovery.RFXComDeviceDiscoveryService] - Adding new RFXCOM rfxcom:temperaturehumidity:rp_wohnzimmer:38401 with id '38401' to smarthome inbox
16:13:25.543 [DEBUG] [.binding.rfxcom.handler.RFXComHandler] - Received message from bridge: rfxcom:tcpbridge:rp_wohnzimmer message: Raw data = 0A520101960100AB120240, Packet type = TEMPERATURE_HUMIDITY, Seq number = 1, Sub type = TH1, Device Id = 38401, Temperature = 17.1, Humidity = 18, Humidity status = DRY, Signal level = 4, Battery level = 0
16:13:34.031 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Checking RFXCOM transceiver connection, thing status = OFFLINE
16:13:34.033 [DEBUG] [ng.rfxcom.handler.RFXComBridgeHandler] - Connecting to RFXCOM transceiver
16:13:34.035 [DEBUG] [internal.connector.RFXComTcpConnector] - Disconnecting
16:13:34.036 [DEBUG] [internal.connector.RFXComTcpConnector] - Interrupt stream listener
16:13:34.068 [DEBUG] [internal.connector.RFXComStreamReader] - Data listener stopped
16:13:34.070 [DEBUG] [internal.connector.RFXComTcpConnector] - Close tcp out stream
16:13:34.072 [DEBUG] [internal.connector.RFXComTcpConnector] - Close tcp in stream
16:13:34.074 [DEBUG] [internal.connector.RFXComTcpConnector] - Close socket
16:13:34.075 [DEBUG] [internal.connector.RFXComTcpConnector] - Closed

EjvindHald · April 10, 2023, 6:57pm

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.

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…

pauli_anttila · April 11, 2023, 2:30pm

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"

EjvindHald · May 15, 2023, 6:22am

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.