Possibly false reports of battery level "0"

[elyorkhakimov]

Hi, first of all, this is fantastic work!
Very small, easy on resources but very quick code. Fantastic job!

I noticed in logs that the PIR sensor is producing erratic messages. Battery goes from 100% to 0%.
Please let me know how I could troubleshoot this issue.

Thanks!

INFO[0962] ALARM: time=19 Jun 20 07:33 +0000, mac: 77A17BAB, type: 2, battery: 100, signal: 21, state: 0, data=64000100000815

INFO[0962] ALARM: 77A17BAB, state: 0

INFO[1032] ALARM: time=19 Jun 20 07:34 +0000, mac: 77A17BAB, type: 2, battery: 0, signal: 3, state: 1, data=00000001000003000000001500

INFO[1032] ALARM: 77A17BAB, state: 1

INFO[1043] LOG: time=19 Jun 20 07:34 +0000, data=�77A17BAB��

INFO[1043] ALARM: time=19 Jun 20 07:34 +0000, mac: 77A17BAB, type: 2, battery: 100, signal: 20, state: 1, data=64000101000914

INFO[1043] ALARM: 77A17BAB, state: 1

INFO[1083] LOG: time=19 Jun 20 07:34 +0000, data=�77A17BAB�

INFO[1083] ALARM: time=19 Jun 20 07:34 +0000, mac: 77A17BAB, type: 2, battery: 100, signal: 21, state: 0, data=64000100000a15

INFO[1083] ALARM: 77A17BAB, state: 0

INFO[1098] LOG: time=19 Jun 20 07:35 +0000, data=�77A17BAB���

INFO[1098] ALARM: time=19 Jun 20 07:35 +0000, mac: 77A17BAB, type: 2, battery: 100, signal: 21, state: 1, data=64000101000b15

INFO[1098] ALARM: 77A17BAB, state: 1

INFO[1138] LOG: time=19 Jun 20 07:35 +0000, data=�77A17BAB�

INFO[1138] ALARM: time=19 Jun 20 07:35 +0000, mac: 77A17BAB, type: 2, battery: 100, signal: 21, state: 0, data=64000100000c15

INFO[1138] ALARM: 77A17BAB, state: 0

INFO[1163] ALARM: time=19 Jun 20 07:36 +0000, mac: 77A17BAB, type: 2, battery: 0, signal: 3, state: 0, data=00010000000003000000011500

INFO[1163] ALARM: 77A17BAB, state: 0

INFO[1176] LOG: time=19 Jun 20 07:36 +0000, data=�77A17BAB��

INFO[1176] ALARM: time=19 Jun 20 07:36 +0000, mac: 77A17BAB, type: 2, battery: 100, signal: 21, state: 1, data=64000101000d15

INFO[1176] ALARM: 77A17BAB, state: 1

[elyorkhakimov]

OK, noticed some more nuances, let's look at two cases:

1. Motion is detected, and MQTT message with "state:1" is generated. Then, there is no motion happening anymore and 40 seconds later MQTT message with "state:0" is generated again.
2. Motion is detected, and MQTT message with "state:1" is generated. Then, additional motion is made in front of the sensor. Not instantly, rather few moments later a message with "battery:0" and some strange looking "data" string shows up. Then 30 seconds later a "state:0" message shows up.

It almost seems that when PIR detects additional motion event but before the original event had "expired", sensor generates some data that is being incorrectly parsed by gosense.

Here are logs with timestamps. First you'll see the #1 case, and right after - #2.

2020-06-19T07:41:21.600391811Z INFO[1443] LOG: time=19 Jun 20 07:41 +0000, data=�77A17BAB���

2020-06-19T07:41:21.600485005Z INFO[1443] ALARM: time=19 Jun 20 07:41 +0000, mac: 77A17BAB, type: 2, battery: 100, signal: 21, state: 1, data=64000101000f15

2020-06-19T07:41:21.600505236Z INFO[1443] ALARM: 77A17BAB, state: 1

2020-06-19T07:42:01.594729111Z INFO[1483] LOG: time=19 Jun 20 07:41 +0000, data=�77A17BAB��

2020-06-19T07:42:01.595161311Z INFO[1483] ALARM: time=19 Jun 20 07:41 +0000, mac: 77A17BAB, type: 2, battery: 100, signal: 21, state: 0, data=64000100001015

2020-06-19T07:42:01.595228299Z INFO[1483] ALARM: 77A17BAB, state: 0

2020-06-19T07:42:56.399597312Z INFO[1538] LOG: time=19 Jun 20 07:42 +0000, data=�77A17BAB���

2020-06-19T07:42:56.399679934Z INFO[1538] ALARM: time=19 Jun 20 07:42 +0000, mac: 77A17BAB, type: 2, battery: 100, signal: 21, state: 1, data=64000101001115

2020-06-19T07:42:56.399700377Z INFO[1538] ALARM: 77A17BAB, state: 1

2020-06-19T07:43:21.594282624Z INFO[1563] ALARM: time=19 Jun 20 07:43 +0000, mac: 77A17BAB, type: 2, battery: 0, signal: 0, state: 0, data=00010000010000010000081500

2020-06-19T07:43:21.594384840Z INFO[1563] ALARM: 77A17BAB, state: 0

2020-06-19T07:43:52.815976222Z INFO[1594] LOG: time=19 Jun 20 07:43 +0000, data=�77A17BAB��

2020-06-19T07:43:52.816561626Z INFO[1594] ALARM: time=19 Jun 20 07:43 +0000, mac: 77A17BAB, type: 2, battery: 100, signal: 21, state: 0, data=64000100001215

2020-06-19T07:43:52.816617102Z INFO[1594] ALARM: 77A17BAB, state: 0

[elyorkhakimov]

and more debug level logs:

2020-06-19T19:24:55.501110026Z DEBU[0062] readRawHid: 62 bytes: [ 55aa53193500000172ce0a772f0ea2373741313742414202010051067155aa531d1900000172ce0a7732a2373741313742414202176400010100511706e1 ]

2020-06-19T19:24:55.501220514Z DEBU[0062] Trying to parse: 62 bytes: [ 55aa53193500000172ce0a772f0ea2373741313742414202010051067155aa531d1900000172ce0a7732a2373741313742414202176400010100511706e1 ]

2020-06-19T19:24:55.501246966Z DEBU[0062] ==> Sending ACK packet for cmd 5335

2020-06-19T19:24:55.501264432Z DEBU[0062] ====> sending: [Packet: Cmd:53ff, Payload: ACK[0035]]

2020-06-19T19:24:55.501287402Z DEBU[0062] Sending: aa555335ff0286

2020-06-19T19:24:55.501789179Z INFO[0062] LOG: time=19 Jun 20 19:24 +0000, data=�77A17BAB��Q

2020-06-19T19:24:55.501866457Z DEBU[0062] Trying to parse: 33 bytes: [ 55aa531d1900000172ce0a7732a2373741313742414202176400010100511706e1 ]

2020-06-19T19:24:55.501916999Z DEBU[0062] ==> Sending ACK packet for cmd 5319

2020-06-19T19:24:55.501956320Z DEBU[0062] ====> sending: [Packet: Cmd:53ff, Payload: ACK[0019]]

2020-06-19T19:24:55.501980927Z DEBU[0062] Sending: aa555319ff026a

2020-06-19T19:24:55.502068522Z INFO[0062] ALARM: time=19 Jun 20 19:24 +0000, mac: 77A17BAB, type: 2, battery: 100, signal: 23, state: 1, data=64000101005117

2020-06-19T19:24:55.502162753Z INFO[0062] ALARM: 77A17BAB, state: 1

2020-06-19T19:25:35.493705925Z DEBU[0102] readRawHid: 62 bytes: [ 55aa53193500000172ce0b0c1a0ea237374131374241420200005205f255aa531d1900000172ce0b0c1da237374131374241420217640001000052170662 ]

2020-06-19T19:25:35.493803285Z DEBU[0102] Trying to parse: 62 bytes: [ 55aa53193500000172ce0b0c1a0ea237374131374241420200005205f255aa531d1900000172ce0b0c1da237374131374241420217640001000052170662 ]

2020-06-19T19:25:35.493835865Z DEBU[0102] ==> Sending ACK packet for cmd 5335

2020-06-19T19:25:35.493861900Z DEBU[0102] ====> sending: [Packet: Cmd:53ff, Payload: ACK[0035]]

2020-06-19T19:25:35.493893358Z DEBU[0102] Sending: aa555335ff0286

2020-06-19T19:25:35.494030450Z INFO[0102] LOG: time=19 Jun 20 19:25 +0000, data=�77A17BAB�R

2020-06-19T19:25:35.494089647Z DEBU[0102] Trying to parse: 33 bytes: [ 55aa531d1900000172ce0b0c1da237374131374241420217640001000052170662 ]

2020-06-19T19:25:35.494108240Z DEBU[0102] ==> Sending ACK packet for cmd 5319

2020-06-19T19:25:35.494122570Z DEBU[0102] ====> sending: [Packet: Cmd:53ff, Payload: ACK[0019]]

2020-06-19T19:25:35.494387519Z DEBU[0102] Sending: aa555319ff026a

2020-06-19T19:25:35.494429314Z INFO[0102] ALARM: time=19 Jun 20 19:25 +0000, mac: 77A17BAB, type: 2, battery: 100, signal: 23, state: 0, data=64000100005217

2020-06-19T19:25:35.494628320Z INFO[0102] ALARM: 77A17BAB, state: 0

2020-06-19T19:26:55.496452935Z DEBU[0182] readRawHid: 39 bytes: [ 55aa53231900000172ce0c35f5ab373741313742414202000001000001000001000001170006a9 ]

2020-06-19T19:26:55.496550061Z DEBU[0182] Trying to parse: 39 bytes: [ 55aa53231900000172ce0c35f5ab373741313742414202000001000001000001000001170006a9 ]

2020-06-19T19:26:55.496605672Z DEBU[0182] ==> Sending ACK packet for cmd 5319

2020-06-19T19:26:55.496635430Z DEBU[0182] ====> sending: [Packet: Cmd:53ff, Payload: ACK[0019]]

2020-06-19T19:26:55.496660790Z DEBU[0182] Sending: aa555319ff026a

2020-06-19T19:26:55.496684718Z INFO[0182] ALARM: time=19 Jun 20 19:26 +0000, mac: 77A17BAB, type: 2, battery: 0, signal: 0, state: 0, data=00010000010000010000011700

2020-06-19T19:26:55.496709455Z INFO[0182] ALARM: 77A17BAB, state: 0

[elyorkhakimov]

looks like there is a potential workaround, as stated here : kevinvincent/ha-wyzesense#114 (comment)

At the moment, a dozen of these sensors are working fine for me, but I had to handle malformed MQTT messages in my node-red flow. Not a big problem, just need to account for this nuance.

Either way, Dario, this is fantastic work you've done here!