decode_packet: too many values to unpack (expected 2)

Question

decode_packet: too many values to unpack (expected 2)

akasma74 opened this issue 5 years ago · 9 comments

I use rflink integration in my HA setup and often get this in HA log:

2020-01-22 07:49:56 ERROR (MainThread) [rflink.protocol] failed to parse packet: None
Traceback (most recent call last):
File "/usr/local/lib/python3.7/site-packages/rflink/protocol.py", line 152, in handle_raw_packet
packet = decode_packet(raw_packet)
File "/usr/local/lib/python3.7/site-packages/rflink/parser.py", line 308, in decode_packet
key, value = attr.lower().split("=")
ValueError: too many values to unpack (expected 2)

Obvoiusly there is no impact on the functionality, but the messages flood the log.
I hope it's possible to rewrite the code so it account for situations like this.

Answer 1 · 2020-01-22T13:04:12.000Z

As a quick fix you can disable error logging for rflink in HA config: https://www.home-assistant.io/integrations/rflink/#debug-logging Just change rflink: debug to rflink: critical.

You could also enable debug logging for a short time to capture the invalid input and paste it here so this problem can be solved.

Answer 2 · 2020-01-22T13:14:07.000Z

Thanks for a quick reply.
I normally have logging level for rflink set as error and it suits my needs.

Do you mean that the error message I've provided is not enough to deal with the issue and you need debug logs?
The problem is this error occures sporadically and I have more than 10 sensors sending their data every 50 seconds. I have no idea how to capture that particular "short time" to enable debug logging as you suggest without having a huge log and trawling through it..

Answer 3 · 2020-01-22T14:22:35.000Z

With the input data that caused this error it's hard to debug it. You mentioned it flooded your logs so I figured it would happen regurarly.

You can capture debug logging for a while and just sent a few (~50) debug lines before this error that would be enough information.

Answer 4 · 2020-01-22T19:37:11.000Z

Here is the debug log:

2020-01-22 16:26:11 DEBUG (MainThread) [rflink.protocol] got packet: 20;93;EV1527;ID=0d4ab2;SWITCH=0e;CMD=ON;
2020-01-22 16:26:11 DEBUG (MainThread) [rflink.protocol] decoded packet: {'node': 'gateway', 'protocol': 'ev1527', 'id': '0d4ab2', 'switch': '0e', 'command': 'on'}
2020-01-22 16:26:11 DEBUG (MainThread) [rflink.protocol] ignoring event with id: {'id': 'ev1527_0d4ab2_0e', 'command': 'on'}
2020-01-22 16:26:25 DEBUG (MainThread) [rflink.protocol] received data: 20;94;Prologue;ID=9100;TEMP=00b8
2020-01-22 16:26:25 DEBUG (MainThread) [rflink.protocol] received data: ;HUM=51;
2020-01-22 16:26:25 DEBUG (MainThread) [rflink.protocol] got packet: 20;94;Prologue;ID=9100;TEMP=00b8;HUM=51;
2020-01-22 16:26:25 DEBUG (MainThread) [rflink.protocol] decoded packet: {'node': 'gateway', 'protocol': 'prologue', 'id': '9100', 'temperature': 18.4, 'temperature_unit': '°C', 'humidity': 51, 'humidity_unit': '%'}
2020-01-22 16:26:25 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'prologue_9100_temp', 'sensor': 'temperature', 'value': 18.4, 'unit': '°C'}
2020-01-22 16:26:25 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'prologue_9100_hum', 'sensor': 'humidity', 'value': 51, 'unit': '%'}
2020-01-22 16:26:25 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'prologue_9100_update_time', 'sensor': 'update_time', 'value': 1579710386, 'unit': 's'}
2020-01-22 16:26:32 DEBUG (MainThread) [rflink.protocol] received data: 20;95;Tunex;ID=AB01;TEMP=00c3;HU
2020-01-22 16:26:32 DEBUG (MainThread) [rflink.protocol] received data: M=75;BAT=OK;
2020-01-22 16:26:32 DEBUG (MainThread) [rflink.protocol] got packet: 20;95;Tunex;ID=AB01;TEMP=00c3;HUM=75;BAT=OK;
2020-01-22 16:26:32 DEBUG (MainThread) [rflink.protocol] decoded packet: {'node': 'gateway', 'protocol': 'tunex', 'id': 'ab01', 'temperature': 19.5, 'temperature_unit': '°C', 'humidity': 75, 'humidity_unit': '%', 'battery': 'ok'}
2020-01-22 16:26:32 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'tunex_ab01_temp', 'sensor': 'temperature', 'value': 19.5, 'unit': '°C'}
2020-01-22 16:26:32 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'tunex_ab01_hum', 'sensor': 'humidity', 'value': 75, 'unit': '%'}
2020-01-22 16:26:32 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'tunex_ab01_bat', 'sensor': 'battery', 'value': 'ok', 'unit': None}
2020-01-22 16:26:32 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'tunex_ab01_update_time', 'sensor': 'update_time', 'value': 1579710392, 'unit': 's'}
2020-01-22 16:26:35 DEBUG (MainThread) [rflink.protocol] received data: 20;96;Tunex;ID=C203;TEMP=00c3;HU
2020-01-22 16:26:35 DEBUG (MainThread) [rflink.protocol] received data: M=53;BAT=OK;
2020-01-22 16:26:35 DEBUG (MainThread) [rflink.protocol] got packet: 20;96;Tunex;ID=C203;TEMP=00c3;HUM=53;BAT=OK;
2020-01-22 16:26:35 DEBUG (MainThread) [rflink.protocol] decoded packet: {'node': 'gateway', 'protocol': 'tunex', 'id': 'c203', 'temperature': 19.5, 'temperature_unit': '°C', 'humidity': 53, 'humidity_unit': '%', 'battery': 'ok'}
2020-01-22 16:26:35 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'tunex_c203_temp', 'sensor': 'temperature', 'value': 19.5, 'unit': '°C'}
2020-01-22 16:26:35 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'tunex_c203_hum', 'sensor': 'humidity', 'value': 53, 'unit': '%'}
2020-01-22 16:26:35 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'tunex_c203_bat', 'sensor': 'battery', 'value': 'ok', 'unit': None}
2020-01-22 16:26:35 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'tunex_c203_update_time', 'sensor': 'update_time', 'value': 1579710395, 'unit': 's'}
2020-01-22 16:26:37 DEBUG (MainThread) [rflink.protocol] received data: 20;97;EV1527;ID=0d4b2d;SWITCH=0e
2020-01-22 16:26:37 DEBUG (MainThread) [rflink.protocol] received data: ;CMD=ON;
2020-01-22 16:26:37 DEBUG (MainThread) [rflink.protocol] got packet: 20;97;EV1527;ID=0d4b2d;SWITCH=0e;CMD=ON;
2020-01-22 16:26:37 DEBUG (MainThread) [rflink.protocol] decoded packet: {'node': 'gateway', 'protocol': 'ev1527', 'id': '0d4b2d', 'switch': '0e', 'command': 'on'}
2020-01-22 16:26:37 DEBUG (MainThread) [rflink.protocol] ignoring event with id: {'id': 'ev1527_0d4b2d_0e', 'command': 'on'}
2020-01-22 16:26:40 DEBUG (MainThread) [rflink.protocol] received data: 20;98;Tunex;ID=8F01;TEMP=0047;HU
2020-01-22 16:26:40 DEBUG (MainThread) [rflink.protocol] received data: M=20;BAT=OK;
2020-01-22 16:26:40 DEBUG (MainThread) [rflink.protocol] got packet: 20;98;Tunex;ID=8F01;TEMP=0047;HUM=20;BAT=OK;
2020-01-22 16:26:40 DEBUG (MainThread) [rflink.protocol] decoded packet: {'node': 'gateway', 'protocol': 'tunex', 'id': '8f01', 'temperature': 7.1, 'temperature_unit': '°C', 'humidity': 20, 'humidity_unit': '%', 'battery': 'ok'}
2020-01-22 16:26:40 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'tunex_8f01_temp', 'sensor': 'temperature', 'value': 7.1, 'unit': '°C'}
2020-01-22 16:26:40 DEBUG (MainThread) [rflink.protocol] ignoring event with id: {'id': 'tunex_8f01_hum', 'sensor': 'humidity', 'value': 20, 'unit': '%'}
2020-01-22 16:26:40 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'tunex_8f01_bat', 'sensor': 'battery', 'value': 'ok', 'unit': None}
2020-01-22 16:26:40 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'tunex_8f01_update_time', 'sensor': 'update_time', 'value': 1579710400, 'unit': 's'}
2020-01-22 16:26:46 DEBUG (MainThread) [rflink.protocol] received data: 20;99;Prologue;ID=9440;TEMP=00b7
2020-01-22 16:26:46 DEBUG (MainThread) [rflink.protocol] received data: ;HUM=51;
2020-01-22 16:26:46 DEBUG (MainThread) [rflink.protocol] got packet: 20;99;Prologue;ID=9440;TEMP=00b7;HUM=51;
2020-01-22 16:26:46 DEBUG (MainThread) [rflink.protocol] decoded packet: {'node': 'gateway', 'protocol': 'prologue', 'id': '9440', 'temperature': 18.3, 'temperature_unit': '°C', 'humidity': 51, 'humidity_unit': '%'}
2020-01-22 16:26:46 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'prologue_9440_temp', 'sensor': 'temperature', 'value': 18.3, 'unit': '°C'}
2020-01-22 16:26:46 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'prologue_9440_hum', 'sensor': 'humidity', 'value': 51, 'unit': '%'}
2020-01-22 16:26:46 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'prologue_9440_update_time', 'sensor': 'update_time', 'value': 1579710407, 'unit': 's'}
2020-01-22 16:26:47 DEBUG (MainThread) [rflink.protocol] received data: 20;9A;FA500;ID=0000db9e;SWITCH=0
2020-01-22 16:26:47 DEBUG (MainThread) [rflink.protocol] received data: 1;CMD=SET_LEVEL=2;
2020-01-22 16:26:47 DEBUG (MainThread) [rflink.protocol] got packet: 20;9A;FA500;ID=0000db9e;SWITCH=01;CMD=SET_LEVEL=2;
2020-01-22 16:26:47 ERROR (MainThread) [rflink.protocol] failed to parse packet: None
Traceback (most recent call last):
File "/usr/local/lib/python3.7/site-packages/rflink/protocol.py", line 152, in handle_raw_packet
packet = decode_packet(raw_packet)
File "/usr/local/lib/python3.7/site-packages/rflink/parser.py", line 308, in decode_packet
key, value = attr.lower().split("=")
ValueError: too many values to unpack (expected 2)
2020-01-22 16:26:47 DEBUG (MainThread) [rflink.protocol] decoded packet: None
2020-01-22 16:26:47 WARNING (MainThread) [rflink.protocol] no valid packet
2020-01-22 16:26:47 DEBUG (MainThread) [rflink.protocol] received data: 20;9B;EV1527;ID=0d2282;SWITCH=0e
2020-01-22 16:26:47 DEBUG (MainThread) [rflink.protocol] received data: ;CMD=ON;
2020-01-22 16:26:47 DEBUG (MainThread) [rflink.protocol] got packet: 20;9B;EV1527;ID=0d2282;SWITCH=0e;CMD=ON;
2020-01-22 16:26:47 DEBUG (MainThread) [rflink.protocol] decoded packet: {'node': 'gateway', 'protocol': 'ev1527', 'id': '0d2282', 'switch': '0e', 'command': 'on'}
2020-01-22 16:26:47 DEBUG (MainThread) [rflink.protocol] ignoring event with id: {'id': 'ev1527_0d2282_0e', 'command': 'on'}
2020-01-22 16:26:57 DEBUG (MainThread) [rflink.protocol] received data: 20;9C;Prologue;ID=97b0;TEMP=00b7
2020-01-22 16:26:57 DEBUG (MainThread) [rflink.protocol] received data: ;HUM=53;
2020-01-22 16:26:57 DEBUG (MainThread) [rflink.protocol] got packet: 20;9C;Prologue;ID=97b0;TEMP=00b7;HUM=53;
2020-01-22 16:26:57 DEBUG (MainThread) [rflink.protocol] decoded packet: {'node': 'gateway', 'protocol': 'prologue', 'id': '97b0', 'temperature': 18.3, 'temperature_unit': '°C', 'humidity': 53, 'humidity_unit': '%'}
2020-01-22 16:26:57 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'prologue_97b0_temp', 'sensor': 'temperature', 'value': 18.3, 'unit': '°C'}
2020-01-22 16:26:57 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'prologue_97b0_hum', 'sensor': 'humidity', 'value': 53, 'unit': '%'}
2020-01-22 16:26:57 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'prologue_97b0_update_time', 'sensor': 'update_time', 'value': 1579710417, 'unit': 's'}
2020-01-22 16:26:58 DEBUG (MainThread) [rflink.protocol] received data: 20;9D;EV1527;ID=0e7e9a;SWITCH=0e
2020-01-22 16:26:58 DEBUG (MainThread) [rflink.protocol] received data: ;CMD=ON;
2020-01-22 16:26:58 DEBUG (MainThread) [rflink.protocol] got packet: 20;9D;EV1527;ID=0e7e9a;SWITCH=0e;CMD=ON;
2020-01-22 16:26:58 DEBUG (MainThread) [rflink.protocol] decoded packet: {'node': 'gateway', 'protocol': 'ev1527', 'id': '0e7e9a', 'switch': '0e', 'command': 'on'}
2020-01-22 16:26:58 DEBUG (MainThread) [rflink.protocol] ignoring event with id: {'id': 'ev1527_0e7e9a_0e', 'command': 'on'}
2020-01-22 16:27:11 DEBUG (MainThread) [rflink.protocol] received data: 20;9E;Tunex;ID=8F01;TEMP=0047;HU
2020-01-22 16:27:11 DEBUG (MainThread) [rflink.protocol] received data: M=20;BAT=OK;
2020-01-22 16:27:11 DEBUG (MainThread) [rflink.protocol] got packet: 20;9E;Tunex;ID=8F01;TEMP=0047;HUM=20;BAT=OK;
2020-01-22 16:27:11 DEBUG (MainThread) [rflink.protocol] decoded packet: {'node': 'gateway', 'protocol': 'tunex', 'id': '8f01', 'temperature': 7.1, 'temperature_unit': '°C', 'humidity': 20, 'humidity_unit': '%', 'battery': 'ok'}
2020-01-22 16:27:11 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'tunex_8f01_temp', 'sensor': 'temperature', 'value': 7.1, 'unit': '°C'}
2020-01-22 16:27:11 DEBUG (MainThread) [rflink.protocol] ignoring event with id: {'id': 'tunex_8f01_hum', 'sensor': 'humidity', 'value': 20, 'unit': '%'}
2020-01-22 16:27:11 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'tunex_8f01_bat', 'sensor': 'battery', 'value': 'ok', 'unit': None}
2020-01-22 16:27:11 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'tunex_8f01_update_time', 'sensor': 'update_time', 'value': 1579710431, 'unit': 's'}
2020-01-22 16:27:15 DEBUG (MainThread) [rflink.protocol] received data: 20;9F;Prologue;ID=9100;TEMP=00b8
2020-01-22 16:27:15 DEBUG (MainThread) [rflink.protocol] received data: ;HUM=51;
2020-01-22 16:27:15 DEBUG (MainThread) [rflink.protocol] got packet: 20;9F;Prologue;ID=9100;TEMP=00b8;HUM=51;
2020-01-22 16:27:15 DEBUG (MainThread) [rflink.protocol] decoded packet: {'node': 'gateway', 'protocol': 'prologue', 'id': '9100', 'temperature': 18.4, 'temperature_unit': '°C', 'humidity': 51, 'humidity_unit': '%'}
2020-01-22 16:27:15 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'prologue_9100_temp', 'sensor': 'temperature', 'value': 18.4, 'unit': '°C'}
2020-01-22 16:27:15 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'prologue_9100_hum', 'sensor': 'humidity', 'value': 51, 'unit': '%'}
2020-01-22 16:27:15 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'prologue_9100_update_time', 'sensor': 'update_time', 'value': 1579710436, 'unit': 's'}
2020-01-22 16:27:22 DEBUG (MainThread) [rflink.protocol] received data: 20;A0;Tunex;ID=9B03;TEMP=00b9;HU
2020-01-22 16:27:22 DEBUG (MainThread) [rflink.protocol] received data: M=57;BAT=OK;
2020-01-22 16:27:22 DEBUG (MainThread) [rflink.protocol] got packet: 20;A0;Tunex;ID=9B03;TEMP=00b9;HUM=57;BAT=OK;
2020-01-22 16:27:22 DEBUG (MainThread) [rflink.protocol] decoded packet: {'node': 'gateway', 'protocol': 'tunex', 'id': '9b03', 'temperature': 18.5, 'temperature_unit': '°C', 'humidity': 57, 'humidity_unit': '%', 'battery': 'ok'}
2020-01-22 16:27:22 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'tunex_9b03_temp', 'sensor': 'temperature', 'value': 18.5, 'unit': '°C'}
2020-01-22 16:27:22 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'tunex_9b03_hum', 'sensor': 'humidity', 'value': 57, 'unit': '%'}
2020-01-22 16:27:22 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'tunex_9b03_bat', 'sensor': 'battery', 'value': 'ok', 'unit': None}
2020-01-22 16:27:22 DEBUG (MainThread) [rflink.protocol] got event: {'id': 'tunex_9b03_update_time', 'sensor': 'update_time', 'value': 1579710442, 'unit': 's'}
2020-01-22 16:27:29 DEBUG (MainThread) [rflink.protocol] received data: 20;A1;Tunex;ID=AB01;TEMP=00c4;HU
2020-01-22 16:27:29 DEBUG (MainThread) [rflink.protocol] received data: M=75;BAT=OK;

Answer 5 · 2020-01-24T12:23:16.000Z

thanks, that should be enough information. I'll get back on this probably in a few days when I find some time to debug.

Answer 6 · 2020-01-25T20:33:14.000Z

release https://github.com/aequitas/python-rflink/releases/tag/0.0.51 should fix this isse

Answer 7 · 2020-01-26T13:36:46.000Z

Thanks for the quick fix.
Could you enlighten me about how it works if a new release of this library comes out in relation to HA development process?
I mean, should I create a new issue on their Github so they include a new release in their one?
Or they know that a new release is available and will include it automatically?

Answer 8 · 2020-01-27T09:03:43.000Z

You'd have to make a pull-request there with the bumped version.

Answer 9 · 2020-01-27T09:40:45.000Z

Got it, thanks!