Stop sending notifications randomly requiring Docker Container restart

[PilotC150]

Normally it works perfectly and sends messages in the format of:

time="2019-10-13T06:13:35Z" level=info msg="LOG: time=13 Oct 19 06:13 +0000, data=\xa2777F2846\x02\x00\x01\xfa"
time="2019-10-13T06:13:35Z" level=info msg="ALARM: time=13 Oct 19 06:13 +0000, mac: 777F2846, type: 2, battery: 100, signal: 79, state: 0, data=6400010001fa4f"
time="2019-10-13T06:13:35Z" level=info msg="ALARM: 777F2846, state: 0"

Then randomly, sometimes multiple times per day it will just stop working. I check the docker logs and all I see is this:

time="2019-10-13T10:52:49Z" level=info msg="LOG: time=01 Jan 70 00:00 +0000, data=\xa2777F2846\x02\x01\x01\xfb"

Only LOG messages, no ALARM messages. Once I restart the docker container (hosted on a Raspberry Pi 3 on Raspbian Stretch) it works perfectly again.

Not sure how to debug this one right now, but I'm going to try tonight, just wanted to see if anybody else had come across it.

As I'm posting this I notice that the "time" for all the LOG messages 01 Jan 70. That's gotta be significant but I'm not sure in what way.

[PilotC150]

Some more feedback:

I turned the log level to "DEBUG" and I'm getting some more info, but not yet anything to help me out. Below is an example of one successful event, and one unsuccessful.

time="2019-10-14T01:04:53Z" level=debug msg="readRawHid: 39 bytes: [ 55aa5323190000016dc7cb70bcab37373746323834360200000601050400000001000051000788 ]"
time="2019-10-14T01:04:53Z" level=debug msg="Trying to parse: 39 bytes: [ 55aa5323190000016dc7cb70bcab37373746323834360200000601050400000001000051000788 ]"
time="2019-10-14T01:04:53Z" level=debug msg=" ==> Sending ACK packet for cmd 5319"
time="2019-10-14T01:04:53Z" level=debug msg="====> sending: [Packet: Cmd:53ff, Payload: ACK[0019]]"
time="2019-10-14T01:04:53Z" level=debug msg="Sending: aa555319ff026a"
time="2019-10-14T01:04:53Z" level=info msg="ALARM: time=14 Oct 19 01:04 +0000, mac: 777F2846, type: 2, battery: 0, signal: 0, state: 5, data=00060105040000000100005100"
time="2019-10-14T01:04:53Z" level=info msg="ALARM: 777F2846, state: 5"

time="2019-10-14T02:02:42Z" level=debug msg="readRawHid: 7 bytes: [ 55aa5303320187 ]"
time="2019-10-14T02:02:42Z" level=debug msg="Trying to parse: 7 bytes: [ 55aa5303320187 ]"
time="2019-10-14T02:02:42Z" level=debug msg=" ==> Sending ACK packet for cmd 5332"
time="2019-10-14T02:02:42Z" level=debug msg="====> sending: [Packet: Cmd:53ff, Payload: ACK[0032]]"
time="2019-10-14T02:02:42Z" level=debug msg="Sending: aa555332ff0283"
time="2019-10-14T02:02:42Z" level=debug msg=" onSyncTime ==> Sending SyncTypeAck packet for cmd 5332"
time="2019-10-14T02:02:42Z" level=debug msg="====> sending: [Packet: Cmd:5333, Payload: [0000016dc800d9d0]]"
time="2019-10-14T02:02:42Z" level=debug msg="Sending: aa55530b330000016dc800d9d0046f"
time="2019-10-14T02:02:42Z" level=debug msg="readRawHid: 7 bytes: [ 55aa5333ff0284 ]"
time="2019-10-14T02:02:42Z" level=debug msg="Trying to parse: 7 bytes: [ 55aa5333ff0284 ]"

[dariopb]

The second message received is fine as well and should not trigger an ALARM since it is a request to sync the time. Only the "alarm" packets will trigger an ALARM.
What I see in your log is "55aa5323190000016dc7cb70bcab" 0xab, this is one of the cases I was mishandling and will lead to wrong Alarm packets (reported as another issue). That issue doesn't explain the wrong time for the log messages or the crashes... That I fix already in the code and I'll produce the docker images soon.
Would you mind setting the tracing to "debug" and see if you catch the issue with the full logs?

[PilotC150]

Thanks for the response!

The second post is what I got when I had the tracing set to "debug". I've had it back on "info" for awhile, but I've just set it back to "debug", so I'll keep an eye on it and see what sort of data I get if/when it crashes again.

I was also confused by the logs, in that the "LOG" message with the wrong datetime doesn't show up when it's in debug mode. But like I said, I'll keep an eye on it, maybe it'll show up this time. I don't think I left it in "debug" very long last time.

Also, to clarify, when it crashes, I see the log message (time="2019-10-13T10:52:49Z" level=info msg="LOG: time=01 Jan 70 00:00 +0000, data=\xa2777F2846\x02\x01\x01\xfb") repeated, not just once. It keeps coming periodically. I don't remember the time interval, but maybe once every few minutes.

[PilotC150]

Finally got the logs in "debug" when it broke!

You can see the first three sections are successful logs. Looks like two that are doing a time sync and the one in the middle is an alarm. After that, at 12:41:09Z is when it breaks. I've included four of the message groups that it sends when it's broken.

{"log":"time=\"2019-10-22T12:26:36Z\" level=debug msg=\"readRawHid: 7 bytes: [ 55aa5303320187 ]\"\n","stream":"stdout","time":"2019-10-22T12:26:36.843190457Z"}
{"log":"time=\"2019-10-22T12:26:36Z\" level=debug msg=\"Trying to parse: 7 bytes: [ 55aa5303320187 ]\"\n","stream":"stdout","time":"2019-10-22T12:26:36.843440249Z"}
{"log":"time=\"2019-10-22T12:26:36Z\" level=debug msg=\"    ==\u003e Sending ACK packet for cmd 5332\"\n","stream":"stdout","time":"2019-10-22T12:26:36.843564937Z"}
{"log":"time=\"2019-10-22T12:26:36Z\" level=debug msg=\"====\u003e sending: [Packet: Cmd:53ff, Payload: ACK[0032]]\"\n","stream":"stdout","time":"2019-10-22T12:26:36.843721239Z"}
{"log":"time=\"2019-10-22T12:26:36Z\" level=debug msg=\"Sending: aa555332ff0283\"\n","stream":"stdout","time":"2019-10-22T12:26:36.843908375Z"}
{"log":"time=\"2019-10-22T12:26:36Z\" level=debug msg=\"    onSyncTime ==\u003e Sending SyncTypeAck packet for cmd 5332\"\n","stream":"stdout","time":"2019-10-22T12:26:36.844031239Z"}
{"log":"time=\"2019-10-22T12:26:36Z\" level=debug msg=\"====\u003e sending: [Packet: Cmd:5333, Payload: [0000016df36eec60]]\"\n","stream":"stdout","time":"2019-10-22T12:26:36.844100146Z"}
{"log":"time=\"2019-10-22T12:26:36Z\" level=debug msg=\"Sending: aa55530b330000016df36eec6004ab\"\n","stream":"stdout","time":"2019-10-22T12:26:36.844166969Z"}
{"log":"time=\"2019-10-22T12:26:36Z\" level=debug msg=\"readRawHid: 7 bytes: [ 55aa5333ff0284 ]\"\n","stream":"stdout","time":"2019-10-22T12:26:36.853419484Z"}
{"log":"time=\"2019-10-22T12:26:36Z\" level=debug msg=\"Trying to parse: 7 bytes: [ 55aa5333ff0284 ]\"\n","stream":"stdout","time":"2019-10-22T12:26:36.853547089Z"}

{"log":"time=\"2019-10-22T12:37:17Z\" level=debug msg=\"readRawHid: 33 bytes: [ 55aa531d190000016df3783e20a13737384137364332011360000100015d42073e ]\"\n","stream":"stdout","time":"2019-10-22T12:37:17.217374068Z"}
{"log":"time=\"2019-10-22T12:37:17Z\" level=debug msg=\"Trying to parse: 33 bytes: [ 55aa531d190000016df3783e20a13737384137364332011360000100015d42073e ]\"\n","stream":"stdout","time":"2019-10-22T12:37:17.217606048Z"}
{"log":"time=\"2019-10-22T12:37:17Z\" level=debug msg=\"    ==\u003e Sending ACK packet for cmd 5319\"\n","stream":"stdout","time":"2019-10-22T12:37:17.217681152Z"}
{"log":"time=\"2019-10-22T12:37:17Z\" level=debug msg=\"====\u003e sending: [Packet: Cmd:53ff, Payload: ACK[0019]]\"\n","stream":"stdout","time":"2019-10-22T12:37:17.217889382Z"}
{"log":"time=\"2019-10-22T12:37:17Z\" level=debug msg=\"Sending: aa555319ff026a\"\n","stream":"stdout","time":"2019-10-22T12:37:17.218100163Z"}
{"log":"time=\"2019-10-22T12:37:17Z\" level=info msg=\"ALARM: time=22 Oct 19 12:36 +0000, mac: 778A76C2, type: 1, battery: 96, signal: 66, state: 0, data=60000100015d42\"\n","stream":"stdout","time":"2019-10-22T12:37:17.218284018Z"}
{"log":"time=\"2019-10-22T12:37:17Z\" level=info msg=\"ALARM: 778A76C2, state: 0\"\n","stream":"stdout","time":"2019-10-22T12:37:17.218454747Z"}

{"log":"time=\"2019-10-22T12:38:08Z\" level=debug msg=\"readRawHid: 7 bytes: [ 55aa5303320187 ]\"\n","stream":"stdout","time":"2019-10-22T12:38:08.84300126Z"}
{"log":"time=\"2019-10-22T12:38:08Z\" level=debug msg=\"Trying to parse: 7 bytes: [ 55aa5303320187 ]\"\n","stream":"stdout","time":"2019-10-22T12:38:08.843223864Z"}
{"log":"time=\"2019-10-22T12:38:08Z\" level=debug msg=\"    ==\u003e Sending ACK packet for cmd 5332\"\n","stream":"stdout","time":"2019-10-22T12:38:08.843299489Z"}
{"log":"time=\"2019-10-22T12:38:08Z\" level=debug msg=\"====\u003e sending: [Packet: Cmd:53ff, Payload: ACK[0032]]\"\n","stream":"stdout","time":"2019-10-22T12:38:08.843365739Z"}
{"log":"time=\"2019-10-22T12:38:08Z\" level=debug msg=\"Sending: aa555332ff0283\"\n","stream":"stdout","time":"2019-10-22T12:38:08.843444958Z"}
{"log":"time=\"2019-10-22T12:38:08Z\" level=debug msg=\"    onSyncTime ==\u003e Sending SyncTypeAck packet for cmd 5332\"\n","stream":"stdout","time":"2019-10-22T12:38:08.843864803Z"}
{"log":"time=\"2019-10-22T12:38:08Z\" level=debug msg=\"====\u003e sending: [Packet: Cmd:5333, Payload: [0000016df3797b80]]\"\n","stream":"stdout","time":"2019-10-22T12:38:08.844066938Z"}
{"log":"time=\"2019-10-22T12:38:08Z\" level=debug msg=\"Sending: aa55530b330000016df3797b800465\"\n","stream":"stdout","time":"2019-10-22T12:38:08.84418897Z"}
{"log":"time=\"2019-10-22T12:38:08Z\" level=debug msg=\"readRawHid: 7 bytes: [ 55aa5333ff0284 ]\"\n","stream":"stdout","time":"2019-10-22T12:38:08.853587212Z"}
{"log":"time=\"2019-10-22T12:38:08Z\" level=debug msg=\"Trying to parse: 7 bytes: [ 55aa5333ff0284 ]\"\n","stream":"stdout","time":"2019-10-22T12:38:08.853698671Z"}

{"log":"time=\"2019-10-22T12:41:09Z\" level=debug msg=\"readRawHid: 29 bytes: [ 55aa53193500000000000000000ea23737374632383436020106f90511 ]\"\n","stream":"stdout","time":"2019-10-22T12:41:09.084356704Z"}
{"log":"time=\"2019-10-22T12:41:09Z\" level=debug msg=\"Trying to parse: 29 bytes: [ 55aa53193500000000000000000ea23737374632383436020106f90511 ]\"\n","stream":"stdout","time":"2019-10-22T12:41:09.084641235Z"}
{"log":"time=\"2019-10-22T12:41:09Z\" level=debug msg=\"    ==\u003e Sending ACK packet for cmd 5335\"\n","stream":"stdout","time":"2019-10-22T12:41:09.084715662Z"}
{"log":"time=\"2019-10-22T12:41:09Z\" level=debug msg=\"====\u003e sending: [Packet: Cmd:53ff, Payload: ACK[0035]]\"\n","stream":"stdout","time":"2019-10-22T12:41:09.084780715Z"}
{"log":"time=\"2019-10-22T12:41:09Z\" level=debug msg=\"Sending: aa555335ff0286\"\n","stream":"stdout","time":"2019-10-22T12:41:09.084847433Z"}
{"log":"time=\"2019-10-22T12:41:09Z\" level=info msg=\"LOG: time=01 Jan 70 00:00 +0000, data=\\xa2777F2846\\x02\\x01\\x06\\xf9\"\n","stream":"stdout","time":"2019-10-22T12:41:09.085059882Z"}

{"log":"time=\"2019-10-22T12:41:59Z\" level=debug msg=\"readRawHid: 29 bytes: [ 55aa53193500000000000000000ea23737374632383436020006fa0511 ]\"\n","stream":"stdout","time":"2019-10-22T12:41:59.375134694Z"}
{"log":"time=\"2019-10-22T12:41:59Z\" level=debug msg=\"Trying to parse: 29 bytes: [ 55aa53193500000000000000000ea23737374632383436020006fa0511 ]\"\n","stream":"stdout","time":"2019-10-22T12:41:59.375393028Z"}
{"log":"time=\"2019-10-22T12:41:59Z\" level=debug msg=\"    ==\u003e Sending ACK packet for cmd 5335\"\n","stream":"stdout","time":"2019-10-22T12:41:59.375675841Z"}
{"log":"time=\"2019-10-22T12:41:59Z\" level=debug msg=\"====\u003e sending: [Packet: Cmd:53ff, Payload: ACK[0035]]\"\n","stream":"stdout","time":"2019-10-22T12:41:59.375788809Z"}
{"log":"time=\"2019-10-22T12:41:59Z\" level=debug msg=\"Sending: aa555335ff0286\"\n","stream":"stdout","time":"2019-10-22T12:41:59.376090997Z"}
{"log":"time=\"2019-10-22T12:41:59Z\" level=info msg=\"LOG: time=01 Jan 70 00:00 +0000, data=\\xa2777F2846\\x02\\x00\\x06\\xfa\"\n","stream":"stdout","time":"2019-10-22T12:41:59.3768598Z"}

{"log":"time=\"2019-10-22T12:49:47Z\" level=debug msg=\"readRawHid: 29 bytes: [ 55aa53193500000000000000000ea23737374632383436020106fb0513 ]\"\n","stream":"stdout","time":"2019-10-22T12:49:47.363890664Z"}
{"log":"time=\"2019-10-22T12:49:47Z\" level=debug msg=\"Trying to parse: 29 bytes: [ 55aa53193500000000000000000ea23737374632383436020106fb0513 ]\"\n","stream":"stdout","time":"2019-10-22T12:49:47.364419311Z"}
{"log":"time=\"2019-10-22T12:49:47Z\" level=debug msg=\"    ==\u003e Sending ACK packet for cmd 5335\"\n","stream":"stdout","time":"2019-10-22T12:49:47.364537072Z"}
{"log":"time=\"2019-10-22T12:49:47Z\" level=debug msg=\"====\u003e sending: [Packet: Cmd:53ff, Payload: ACK[0035]]\"\n","stream":"stdout","time":"2019-10-22T12:49:47.364603426Z"}
{"log":"time=\"2019-10-22T12:49:47Z\" level=debug msg=\"Sending: aa555335ff0286\"\n","stream":"stdout","time":"2019-10-22T12:49:47.364666863Z"}
{"log":"time=\"2019-10-22T12:49:47Z\" level=info msg=\"LOG: time=01 Jan 70 00:00 +0000, data=\\xa2777F2846\\x02\\x01\\x06\\xfb\"\n","stream":"stdout","time":"2019-10-22T12:49:47.364878426Z"}

{"log":"time=\"2019-10-22T12:50:55Z\" level=debug msg=\"readRawHid: 29 bytes: [ 55aa53193500000000000000000ea23737374632383436020006fc0513 ]\"\n","stream":"stdout","time":"2019-10-22T12:50:55.186934211Z"}
{"log":"time=\"2019-10-22T12:50:55Z\" level=debug msg=\"Trying to parse: 29 bytes: [ 55aa53193500000000000000000ea23737374632383436020006fc0513 ]\"\n","stream":"stdout","time":"2019-10-22T12:50:55.187160982Z"}
{"log":"time=\"2019-10-22T12:50:55Z\" level=debug msg=\"    ==\u003e Sending ACK packet for cmd 5335\"\n","stream":"stdout","time":"2019-10-22T12:50:55.18724968Z"}
{"log":"time=\"2019-10-22T12:50:55Z\" level=debug msg=\"====\u003e sending: [Packet: Cmd:53ff, Payload: ACK[0035]]\"\n","stream":"stdout","time":"2019-10-22T12:50:55.187443899Z"}
{"log":"time=\"2019-10-22T12:50:55Z\" level=debug msg=\"Sending: aa555335ff0286\"\n","stream":"stdout","time":"2019-10-22T12:50:55.187926608Z"}
{"log":"time=\"2019-10-22T12:50:55Z\" level=info msg=\"LOG: time=01 Jan 70 00:00 +0000, data=\\xa2777F2846\\x02\\x00\\x06\\xfc\"\n","stream":"stdout","time":"2019-10-22T12:50:55.188592755Z"}

[PilotC150]

Looks like I solved the problem. I started using a different Wyze Bridge.

When I first ordered my Wyze Sense starter kit, Wyze accidentally sent me two kits. (I contacted them to tell them and they told me to keep it.) I decided to try the other bridge instead to see if I was seeing the same behavior. Since I only had two sensors paired with the bridge it was pretty quick and easy to migrate to the new bridge.

It's been ~10 days since I switched over to the new bridge and it hasn't crashed a single time.

It appears there was something wrong with the hardware that was causing it to occasionally start sending bad data.

Glad it's all working now so I can start putting more of the sensors around the house.