RFlink stops working after 30 seconds

Arkest · May 9, 2019, 9:37pm

I used RF link for a long time but now i got a strange error and it is not working any more. I surged the internet for hours but can not find a solution.

If I send something I got a waring acknowledge timeout. If I send something I receive this message:

2019-05-09 23:26:11 ERROR (MainThread) [homeassistant.core] Error doing job: Exception in callback <bound method SerialTransport._read_ready of SerialTransport(<uvloop.Loop running=True closed=False debug=False>, <rflink.protocol.RflinkProtocol object at 0x7293b670>, Serial<id=0x72c819b0, open=True>(port='/dev/ttyACM0', baudrate=57600, bytesize=8, parity='N', stopbits=1, timeout=0, xonxoff=False, rtscts=False, dsrdtr=False))>
        Traceback (most recent call last):
          File "uvloop/cbhandles.pyx", line 66, in uvloop.loop.Handle._run
          File "/usr/local/lib/python3.7/site-packages/serial_asyncio/__init__.py", line 106, in _read_ready
        self._protocol.data_received(data)
          File "/usr/local/lib/python3.7/site-packages/rflink/protocol.py", line 46, in data_received
        data = data.decode()
        UnicodeDecodeError: 'utf-8' codec can't decode byte 0x98 in position 2: invalid start byte
        2019-05-09 23:26:12 ERROR (MainThread) [homeassistant.core] Error doing job: Exception in callback <bound method SerialTransport._read_ready of SerialTransport(<uvloop.Loop running=True closed=False debug=False>, <rflink.protocol.RflinkProtocol object at 0x7293b670>, Serial<id=0x72c819b0, open=True>(port='/dev/ttyACM0', baudrate=57600, bytesize=8, parity='N', stopbits=1, timeout=0, xonxoff=False, rtscts=False, dsrdtr=False))>
        Traceback (most recent call last):
          File "uvloop/cbhandles.pyx", line 66, in uvloop.loop.Handle._run
          File "/usr/local/lib/python3.7/site-packages/serial_asyncio/__init__.py", line 106, in _read_ready
        self._protocol.data_received(data)
          File "/usr/local/lib/python3.7/site-packages/rflink/protocol.py", line 46, in data_received
        data = data.decode()
        UnicodeDecodeError: 'utf-8' codec can't decode byte 0x98 in position 6: invalid start byte

So I do know my configuration is still OK (it receives information) Anny hint where to look for is helpfull (I’m however not a programmer, so please be patient with me)

Arkest · May 12, 2019, 9:05pm

Still no clue where to start. Some additional information. My configuration:

# configure RFlink for 433 devices
rflink:
  port: /dev/ttyACM0

Next my log looks like this:

2019-05-12 23:00:25 INFO (MainThread) [homeassistant.components.rflink] Initiating Rflink connection
2019-05-12 23:00:25 DEBUG (MainThread) [rflink.protocol] ignoring: ['digitech_*', 'rftech_*', 'firstline_*', 'sensor.alectov3_3000_*']
2019-05-12 23:00:25 INFO (MainThread) [homeassistant.components.rflink] Connected to Rflink
2019-05-12 23:00:26 DEBUG (MainThread) [rflink.protocol] connected
2019-05-12 23:00:31 DEBUG (MainThread) [rflink.protocol] received data: 20;00;Nodo RadioFrequencyLink - RFLink Gateway V1.1 - R48;
2019-05-12 23:00:31 DEBUG (MainThread) [rflink.protocol] got packet: 20;00;Nodo RadioFrequencyLink - RFLink Gateway V1.1 - R48;
2019-05-12 23:00:31 DEBUG (MainThread) [rflink.protocol] decoded packet: {'node': 'gateway', 'protocol': 'unknown', 'hardware': 'Nodo RadioFrequencyLink', 'firmware': 'RFLink Gateway', 'version': '1.1', 'revision': '48'}
2019-05-12 23:00:31 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'rflink', 'hardware': 'Nodo RadioFrequencyLink', 'firmware': 'RFLink Gateway', 'version': '1.1', 'revision': '48'}
2019-05-12 23:00:31 DEBUG (MainThread) [homeassistant.components.rflink] event of type unknown: {'id': 'rflink', 'hardware': 'Nodo RadioFrequencyLink', 'firmware': 'RFLink Gateway', 'version': '1.1', 'revision': '48'}
2019-05-12 23:00:31 DEBUG (MainThread) [homeassistant.components.rflink] unhandled event of type: unknown

when a message is received by I got this in my log file:

2019-05-12 23:03:01 ERROR (MainThread) [homeassistant.core] Error doing job: Exception in callback <bound method SerialTransport._read_ready of SerialTransport(<uvloop.Loop running=True closed=False debug=False>, <rflink.protocol.RflinkProtocol object at 0x72bf5890>, Serial<id=0x72bfa270, open=True>(port='/dev/ttyACM0', baudrate=57600, bytesize=8, parity='N', stopbits=1, timeout=0, xonxoff=False, rtscts=False, dsrdtr=False))>
Traceback (most recent call last):
  File "uvloop/cbhandles.pyx", line 66, in uvloop.loop.Handle._run
  File "/usr/local/lib/python3.7/site-packages/serial_asyncio/__init__.py", line 106, in _read_ready
    self._protocol.data_received(data)
  File "/usr/local/lib/python3.7/site-packages/rflink/protocol.py", line 46, in data_received
    data = data.decode()
UnicodeDecodeError: 'utf-8' codec can't decode byte 0x98 in position 2: invalid start byte
2019-05-12 23:03:02 ERROR (MainThread) [homeassistant.core] Error doing job: Exception in callback <bound method SerialTransport._read_ready of SerialTransport(<uvloop.Loop running=True closed=False debug=False>, <rflink.protocol.RflinkProtocol object at 0x72bf5890>, Serial<id=0x72bfa270, open=True>(port='/dev/ttyACM0', baudrate=57600, bytesize=8, parity='N', stopbits=1, timeout=0, xonxoff=False, rtscts=False, dsrdtr=False))>
Traceback (most recent call last):
  File "uvloop/cbhandles.pyx", line 66, in uvloop.loop.Handle._run
  File "/usr/local/lib/python3.7/site-packages/serial_asyncio/__init__.py", line 106, in _read_ready
    self._protocol.data_received(data)
  File "/usr/local/lib/python3.7/site-packages/rflink/protocol.py", line 46, in data_received
    data = data.decode()
UnicodeDecodeError: 'utf-8' codec can't decode byte 0x9e in position 2: invalid start byte

I had my RFlink running for quite some time without issues. Also I tested the device with directly on my windows computer and the sending and receiving works well.
Is there anyone who can give me a hint where to start looking for this? I really have no clue what to do next. Do I need to give my complete configuration file?

Arkest · May 12, 2019, 9:30pm

Well, I managed to find the issue. There where no quotes around the USB port, and for some reason this now corrupted the working of RF link, however it could receive it did not work well.

rflink:
  port: '/dev/ttyACM0'

took me quite some hours, but it works again!

cheered too early, again not working, after a restart of HA. seems like a bug to me.

Arkest · May 13, 2019, 8:25pm

Some more information. It seems that RFlink works for about 30 seconds after I plugged in the USB connector, after that I error messages. See below the first command is send and acknowledged and the second not. Hope that someone can direct me how to continue, although it is pretty silent here, please point me to the right location if I’m wrong here.

2019-05-13 09:02:53 DEBUG (MainThread) [homeassistant.components.rflink] Sending command: on to Rflink device: newkaku_003d8972_1
2019-05-13 09:02:53 DEBUG (MainThread) [rflink.protocol] sending command: {'protocol': 'newkaku', 'id': '003d8972', 'switch': '1', 'command': 'on'}
2019-05-13 09:02:53 DEBUG (MainThread) [rflink.protocol] writing data: '10;newkaku;003d8972;1;on;\r\n'
2019-05-13 09:02:53 DEBUG (MainThread) [rflink.protocol] waiting for acknowledgement
2019-05-13 09:02:54 DEBUG (MainThread) [rflink.protocol] received data: 2
2019-05-13 09:02:54 DEBUG (MainThread) [rflink.protocol] received data: 0;0C;OK;
2019-05-13 09:02:54 DEBUG (MainThread) [rflink.protocol] got packet: 20;0C;OK;
2019-05-13 09:02:54 DEBUG (MainThread) [rflink.protocol] decoded packet: {'node': 'gateway', 'protocol': 'unknown', 'ok': True}
2019-05-13 09:02:54 DEBUG (MainThread) [rflink.protocol] command response: {'node': 'gateway', 'protocol': 'unknown', 'ok': True}
2019-05-13 09:02:54 DEBUG (MainThread) [rflink.protocol] packet acknowledged
2019-05-13 09:02:55 DEBUG (MainThread) [homeassistant.components.rflink] Sending command: off to Rflink device: newkaku_003d8972_1
2019-05-13 09:02:55 DEBUG (MainThread) [rflink.protocol] sending command: {'protocol': 'newkaku', 'id': '003d8972', 'switch': '1', 'command': 'off'}
2019-05-13 09:02:55 DEBUG (MainThread) [rflink.protocol] writing data: '10;newkaku;003d8972;1;off;\r\n'
2019-05-13 09:02:55 DEBUG (MainThread) [rflink.protocol] waiting for acknowledgement
2019-05-13 09:03:00 WARNING (MainThread) [rflink.protocol] acknowledge timeout

olskar · May 17, 2019, 11:49am

Started having this recently as well…

olskar · May 18, 2019, 8:12pm

Added a bug report here

Did you manage to find anything?

Arkest · May 18, 2019, 8:17pm

sins yesterday it is working again, I have no clue what is the cause. However I did change my configuration. I added an additional USB device (for Zigbee) and sins then my RFLINK is not stopping any more after 30 seconds.

mdegraaf · May 25, 2019, 7:14am

I have the same issue in 0.93.1. Rflink just stops working. If i connect to rflink over the network rflink published with socat on another linux machine rflink works fine.

tik83 · July 21, 2019, 8:53pm

Got the same issue here…
After rebooting the whole system (hardware reboot) it seems to be working
for some time… Then after sending commands i got the timeout.

I have changed the “Wait for acknowledgement” from true to false…
This seems to be making it a bit more reliable…

mathewtaylor2007 · July 30, 2019, 7:40pm

same issue here, really annoying as I foolishly base some crucial automations around rflink devices.

tik83 · July 30, 2019, 9:52pm

I also have the breakout for a NodeMCU.
Maybe this works betterr. Keep posted!

tik83 · August 23, 2019, 11:06pm

Anynr configured a node mcu for rflink ???

tik83 · November 12, 2019, 8:49am

everyone… small update from me.

i noticed my RFLink setup became more instable, it got actually more worse after updating
the Ubuntu/Docker (to versionUbuntu 18.04.3 LTS) and HA to latestHome Assistant 0.101.3

My setup:
Arduino Mega + RFLink v. R48+ NodeMCU (easyEsp v. 147, but eventually connected via USBserial connection.

Configuration.yaml

rflink:
#  port: /dev/ttyACM0
  port: '/dev/serial/by-id/usb-Arduino__www.arduino.cc__0042_55834323933351111001-if00'
  wait_for_ack: true
  reconnect_interval: 20`

I got awknowledgement timeouts in the logs (using logviewer for filtering these logs)
[rflink.protocol] acknowledge timeout

Now i have removed the NodeMCU from the Arduino and connected a seperate
powersuppoly 9-12v to the Arduino and voila … it works like a charm…
So it seems a powering issue. So it looks that it is working but eventually when executing the
commands the Voltage drops just below the treshhold.

Nevertheless i still got a [rflink.protocol] acknowledge timeout
When using the NodeMCU conection… anyone experience with that?

mattharrington · November 19, 2019, 5:17pm

Mine has randomly stopped working. Nothing has changed (except maybe I updated HASSIO) and now I get the following in the log. Very frustrating. Anyone else having issues?

[homeassistant.components.rflink] event of type unknown: {‘id’: ‘rflink’, ‘hardware’: ‘Nodo RadioFrequencyLink’, ‘firmware’: ‘RFLink Gateway’, ‘version’: ‘1.1’, ‘revision’: ‘48’}

javicalle · November 20, 2019, 6:57am

This is an RFLink startup message. You should only see it at the start of RFLink.

In my case, after a while, RFLink stopped receiving data, but it could continue to send messages. Shortly after the SD dies and after replacing it with a new one, the problem disappeared until today.

tik83 · November 27, 2019, 3:39pm

so if you see it … the rflink reboots? is the arduino still OK? ? RFLink still working? Maybe hook it up to the Comport to check it?

javicalle · December 1, 2019, 5:40pm

I only see that trace when RFLink starts, so I think so, that you should see it after a restart.
Have you tried to set rflink logs to debug?:

logger:
  default: warn
  logs:
    rflink: debug
    homeassistant.components.rflink: debug

Be careful, it can be very very verbose at debug level.