search

wcbonner / GoveeBTTempLogger

Govee H5072, H5074, H5075, H5100, H5101, H5104, H5105, H5174, H5177, H5179, H5181, H5182, and H5183 Bluetooth Low Energy Temperature and Humidity Logger
MIT License
179 stars 26 forks source link

Incorrect Temperature and Humidity After Running for Some Time #74

Closed alzuno closed 1 month ago

alzuno commented 1 month ago

Hi again @wcbonner,

I’ve encountered a potential issue. After running the script for a few hours or days, it starts to report incorrect temperature and humidity values. When I compare these values with the actual readings on the thermometers, I find that the registered values in the script do not match what's displayed on the thermometer screens.

You can see the images below, which illustrate the "jump" in values that occurs after rebooting the service:

image image image

After reboot, values go back to the real thermometer value. Then after sometime running, i found that the difference is there again.

Let me know if you need any more information.

I'm running GoveeBTTempLogger Version 3.20241001.0 Built on: Oct 2 2024 at 15:29:24

wcbonner commented 1 month ago

@alzuno I've seen this occasionally and haven't figured out what's causing it. There seems to be something happening in BlueZ that I don't understand.

Have you tried restarting the service instead of rebooting the entire device?

sudo systemctl restart goveebttemplogger.service

I'm just wondering if that would be enough to fix it.

Also, if you run bluetoothctl while the govee is getting bad data, is it still receiving data constantly?

wim@WimPi4-Sola:~ $ bluetoothctl
[CHG] Device 25:D8:B3:65:F5:19 RSSI: -74
[CHG] Device 25:D8:B3:65:F5:19 ManufacturerData Key: 0x0006
[CHG] Device 25:D8:B3:65:F5:19 ManufacturerData Value:
  01 09 20 22 06 b7 62 ec 5f e1 68 da 4a 0e aa 1f  .. "..b._.h.J...
  41 76 45 2d 28 73 9c df 8e 1d 14                 AvE-(s.....
Agent registered
[CHG] Controller DC:A6:32:D5:3F:2E Pairable: yes
[CHG] Device D3:D1:90:54:EB:F0 RSSI: -77
[CHG] Device D3:D1:90:54:EB:F0 ManufacturerData Key: 0x02e1
[CHG] Device D3:D1:90:54:EB:F0 ManufacturerData Value:
  10 00 f0 a3 0f 33 b6 4a 12 6e 72 76 70 b0 bf 1d  .....3.J.nrvp...
  fd 66 43 1f d9 59                                .fC..Y
[CHG] Device 73:E1:37:57:4A:0B RSSI: -44
[CHG] Device 73:E1:37:57:4A:0B ManufacturerData Key: 0x004c
[CHG] Device 73:E1:37:57:4A:0B ManufacturerData Value:
  10 07 46 1f 31 4b a6 c1 18                       ..F.1K...
[CHG] Device A4:C1:38:0D:3B:10 RSSI: -74
[CHG] Device A4:C1:38:0D:3B:10 ManufacturerData Key: 0x0001
[CHG] Device A4:C1:38:0D:3B:10 ManufacturerData Value:
  01 01 02 cd 03 3b                                .....;
[CHG] Device A4:C1:38:0D:3B:10 ManufacturerData Key: 0x004c
[CHG] Device A4:C1:38:0D:3B:10 ManufacturerData Value:
  02 15 49 4e 54 45 4c 4c 49 5f 52 4f 43 4b 53 5f  ..INTELLI_ROCKS_
  48 57 51 77 f2 ff c2                             HWQw...
[CHG] Device E3:8E:C8:C1:98:9A RSSI: -67
[CHG] Device E3:8E:C8:C1:98:9A ManufacturerData Key: 0xec88
[CHG] Device E3:8E:C8:C1:98:9A ManufacturerData Value:
  00 b5 07 26 14 5b 02                             ...&.[.
[CHG] Device D3:D1:90:54:EB:F0 RSSI: -82
[CHG] Device D3:D1:90:54:EB:F0 ManufacturerData Key: 0x02e1
[CHG] Device D3:D1:90:54:EB:F0 ManufacturerData Value:
  10 00 f0 a3 0f 33 b6 4a 12 6e 72 76 70 b0 bf 1d  .....3.J.nrvp...
  fd 66 43 1f d9 59                                .fC..Y
alzuno commented 1 month ago

Thanks for the reply, @wcbonner! I'll grab the info you need as soon as the issue pops up again.

wcbonner commented 1 month ago

@alzuno I'm working on a change that will periodically stop Bluetooth discovery, remove known devices from the BlueZ object tree, and restart discovery.

It may take care of the issue, but because I'm not sure what's really causing it, I can't be sure.

I ran across a bug that caused dbus messages in the existing code. It's fixed in my current working branch and will get merged into the main code at the next update.

alzuno commented 1 month ago

Great, @wcbonner! Since I posted yesterday, it's been working like a charm. It might take a while for the issue to show up again, so I won’t have any updates until it does, but I'll send you the info as soon as it happens.

wcbonner commented 1 month ago

@alzuno the updated code will hopefully stop the issues you were seeing. If you can pull the latest code before reporting any more details. Hopefully it doesn't recur.

alzuno commented 1 month ago

Thanks, @wcbonner! I’ve already updated to GoveeBTTempLogger Version 3.20241007.1 and will be monitoring the system over the next few days. If anything fails, I’ll let you know.

alzuno commented 1 month ago

Hi @wcbonner, This morning I checked the system and found that the entire Raspberry Pi had halted. I couldn’t connect via SSH or any other method (it's a headless setup), so I had to reboot.

I’m still investigating what happened, but looking through the GoveeBTTempLogger logs, I noticed that at 01:25:23, the system issued a "StopDiscovery," and there’s nothing logged after that until the reboot this morning.

Oct 10 00:55:23 rasp3 goveebttemplogger[699]: /org/bluez/hci0: org.bluez.Adapter1: RemoveDevice /org/bluez/hci0/dev_A4_C1_38_04_3F_DE
Oct 10 00:55:24 rasp3 goveebttemplogger[699]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Oct 10 01:00:01 rasp3 goveebttemplogger[699]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-day.svg With Title: Room (A4:C1:38:04:3F:DE)
Oct 10 01:00:01 rasp3 goveebttemplogger[699]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-day.svg With Title: Office (A4:C1:38:56:DF:3C)
Oct 10 01:05:01 rasp3 goveebttemplogger[699]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-day.svg With Title: Room (A4:C1:38:04:3F:DE)
Oct 10 01:05:01 rasp3 goveebttemplogger[699]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-week.svg With Title: Room (A4:C1:38:04:3F:DE)
Oct 10 01:05:01 rasp3 goveebttemplogger[699]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-day.svg With Title: Office (A4:C1:38:56:DF:3C)
Oct 10 01:05:01 rasp3 goveebttemplogger[699]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-week.svg With Title: Office (A4:C1:38:56:DF:3C)
Oct 10 01:10:01 rasp3 goveebttemplogger[699]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-day.svg With Title: Room (A4:C1:38:04:3F:DE)
Oct 10 01:10:01 rasp3 goveebttemplogger[699]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-day.svg With Title: Office (A4:C1:38:56:DF:3C)
Oct 10 01:15:01 rasp3 goveebttemplogger[699]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-day.svg With Title: Room (A4:C1:38:04:3F:DE)
Oct 10 01:15:01 rasp3 goveebttemplogger[699]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-day.svg With Title: Office (A4:C1:38:56:DF:3C)
Oct 10 01:20:01 rasp3 goveebttemplogger[699]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-day.svg With Title: Room (A4:C1:38:04:3F:DE)
Oct 10 01:20:01 rasp3 goveebttemplogger[699]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-day.svg With Title: Office (A4:C1:38:56:DF:3C)
Oct 10 01:25:01 rasp3 goveebttemplogger[699]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-day.svg With Title: Room (A4:C1:38:04:3F:DE)
Oct 10 01:25:01 rasp3 goveebttemplogger[699]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-day.svg With Title: Office (A4:C1:38:56:DF:3C)
Oct 10 01:25:23 rasp3 goveebttemplogger[699]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery
-- Boot c75d8b18d137469e846247f74b93037d --
Oct 10 07:18:43 rasp3 systemd[1]: Started goveebttemplogger.service - GoveeBTTempLogger service.
Oct 10 07:18:43 rasp3 goveebttemplogger[697]: GoveeBTTempLogger Version 3.20241007.1 Built on: Oct  8 2024 at 09:38:08 (starting)
Oct 10 07:18:43 rasp3 goveebttemplogger[697]: Reading: /var/www/html/goveebttemplogger/gvh-titlemap.txt
Oct 10 07:18:43 rasp3 goveebttemplogger[697]: Reading: /var/log/goveebttemplogger/gvh-thermometer-types.txt
Oct 10 07:18:43 rasp3 goveebttemplogger[697]: Reading: /var/cache/goveebttemplogger/gvh-A4C138043FDE-cache.txt
Oct 10 07:18:43 rasp3 goveebttemplogger[697]: Reading: /var/cache/goveebttemplogger/gvh-A4C13856DF3C-cache.txt
Oct 10 07:18:43 rasp3 goveebttemplogger[697]: Reading: /var/log/goveebttemplogger/gvh-A4C138043FDE-2024-10.txt
Oct 10 07:18:47 rasp3 goveebttemplogger[697]: Reading: /var/log/goveebttemplogger/gvh-A4C13856DF3C-2024-10.txt
Oct 10 07:18:51 rasp3 goveebttemplogger[697]: Reading LastDownload: /var/log/goveebttemplogger/gvh-lastdownload.txt
Oct 10 07:18:51 rasp3 goveebttemplogger[697]: Connected to D-Bus as ":1.12"
Oct 10 07:18:51 rasp3 goveebttemplogger[697]: Host Controller Address: B8:27:EB:FF:AD:6A BlueZ Adapter Path: /org/bluez/hci0
Oct 10 07:18:51 rasp3 goveebttemplogger[697]: /org/bluez/hci0: org.freedesktop.DBus.Properties: SetPowered: true
Oct 10 07:18:51 rasp3 goveebttemplogger[697]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Oct 10 07:18:51 rasp3 goveebttemplogger[697]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Oct 10 11:35:49 rasp3 goveebttemplogger[697]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-day.svg With Title: Room (A4:C1:38:04:3F:DE)
Oct 10 11:35:49 rasp3 goveebttemplogger[697]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-week.svg With Title: Room (A4:C1:38:04:3F:DE)
Oct 10 11:35:49 rasp3 goveebttemplogger[697]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-month.svg With Title: Room (A4:C1:38:04:3F:DE)
Oct 10 11:35:49 rasp3 goveebttemplogger[697]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-day.svg With Title: Office (A4:C1:38:56:DF:3C)
Oct 10 11:35:49 rasp3 goveebttemplogger[697]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-week.svg With Title: Office (A4:C1:38:56:DF:3C)
Oct 10 11:35:49 rasp3 goveebttemplogger[697]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-month.svg With Title: Office (A4:C1:38:56:DF:3C)
Oct 10 11:35:49 rasp3 goveebttemplogger[697]: Writing: /var/cache/goveebttemplogger/gvh-A4C138043FDE-cache.txt
Oct 10 11:35:50 rasp3 goveebttemplogger[697]: Writing: /var/cache/goveebttemplogger/gvh-A4C13856DF3C-cache.txt
Oct 10 11:35:50 rasp3 goveebttemplogger[697]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery
Oct 10 11:35:50 rasp3 goveebttemplogger[697]: /org/bluez/hci0: org.bluez.Adapter1: RemoveDevice /org/bluez/hci0/dev_A4_C1_38_04_3F_DE
Oct 10 11:35:50 rasp3 goveebttemplogger[697]: /org/bluez/hci0: org.bluez.Adapter1: RemoveDevice /org/bluez/hci0/dev_A4_C1_38_56_DF_3C
Oct 10 11:35:50 rasp3 goveebttemplogger[697]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Oct 10 11:36:50 rasp3 goveebttemplogger[697]: Writing: /var/cache/goveebttemplogger/gvh-A4C138043FDE-cache.txt
Oct 10 11:36:50 rasp3 goveebttemplogger[697]: Writing: /var/cache/goveebttemplogger/gvh-A4C13856DF3C-cache.txt

Of course, there's no info on the logs from 01:25:23 thru 11:35:49

image

Log fragment:

2024-10-09 23:24:04 22.1    61.3    49
2024-10-09 23:24:07 22.2    61.4    49
2024-10-09 23:24:14 22.1    61.3    49
2024-10-09 23:24:16 22.1    61.3    49
2024-10-09 23:24:25 22.1    61.3    49
2024-10-09 23:24:42 22.1    61.3    49
2024-10-09 23:24:48 22.1    61.3    49
2024-10-09 23:24:51 22.2    61.2    49
2024-10-09 23:24:54 22.1    61.3    49
2024-10-10 05:18:55 21  53.7    49
2024-10-10 05:18:57 21  53.6    49
2024-10-10 05:18:59 21  53.6    49
2024-10-10 09:35:54 21  53.6    49
2024-10-10 09:35:59 21  53.7    49
2024-10-10 09:36:01 21  53.6    49
2024-10-10 09:36:03 21  53.6    49
2024-10-10 09:36:07 21  53.6    49
2024-10-10 09:36:15 21  53.6    49
2024-10-10 09:36:17 21  53.6    49
2024-10-10 09:36:19 21  53.6    49
2024-10-10 09:36:21 21  53.6    49
2024-10-10 09:36:23 21  53.7    49
2024-10-10 09:36:28 21  53.7    49
2024-10-10 09:36:29 21  53.7    49
2024-10-10 09:36:31 21  53.7    49

Please let me know if you think it was related to the changes you made on the version. Thanks!

wcbonner commented 1 month ago

Hi @wcbonner, This morning I checked the system and found that the entire Raspberry Pi had halted. I couldn’t connect via SSH or any other method (it's a headless setup), so I had to reboot.

I’m still investigating what happened, but looking through the GoveeBTTempLogger logs, I noticed that at 01:25:23, the system issued a "StopDiscovery," and there’s nothing logged after that until the reboot this morning.

Please let me know if you think it was related to the changes you made on the version. Thanks!

@alzuno I certainly hope that GoveeBTTempLogger isn't able to cause the system to freeze entirely. Running as a non-root user, that would mean that any user on the system would have the ability to crash the system.

Can you confirm that goveebttemplogger is not running as root? (In this example you can see the USER column is truncated to "goveebt+")

wim@WimPi4-Sola:~ $ ps aux
USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root           1  0.0  0.1 170136 12968 ?        Ss   Oct07   0:43 /sbin/init
goveebt+   21368  5.0  0.9  82344 76068 ?        Ss   Oct08 134:54 /usr/local/bin/goveebttemplogger --verbose 0 --log /var/log/goveebttemplogger --time 60 --svg /var/www/html/goveebttemplogger --battery
wim        51745  400  0.0  11148  4224 pts/0    R+   09:06   0:00 ps aux

If you get a list of recent reboots from journalctl:

wim@WimPi5:~ $ journalctl --list-boots
IDX BOOT ID                          FIRST ENTRY                 LAST ENTRY
 -4 cb4e37a5c7aa4e70be30537165b23751 Mon 2024-09-30 08:27:55 PDT Wed 2024-10-02 09:57:00 PDT
 -3 ab9d61c7c2ad4ac9ae487de31ae906dc Wed 2024-10-02 09:57:19 PDT Wed 2024-10-02 09:59:56 PDT
 -2 520084189c03495a8186f714c8ddce3f Wed 2024-10-02 10:00:11 PDT Mon 2024-10-07 09:18:30 PDT
 -1 a18877d521f145eb940c93edd4f4f622 Mon 2024-10-07 09:17:01 PDT Mon 2024-10-07 09:30:13 PDT
  0 ad8768ac951349c0a36f995dc43e7c65 Mon 2024-10-07 09:17:01 PDT Thu 2024-10-10 08:47:18 PDT

And then examine the one that froze up in reverse order, something like this: (the -1 is the previous boot in my example)

wim@WimPi5:~ $ journalctl --reverse --boot -1
Oct 07 09:30:13 WimPi5 CRON[3659]: pam_unix(cron:session): session closed for user root
Oct 07 09:30:06 WimPi5 ddclient[3683]: SUCCESS:  updating wimpi5.wimsworld.com: IPv4 address set to xxx.xx.xxx.x
Oct 07 09:30:01 WimPi5 CRON[3660]: (root) CMD (/usr/bin/rsync --archive --compress --timeout=240 -e 'ssh -p xxxx' --exclude index.html --exclude mrtg-l.png --exclude mrt>
Oct 07 09:30:01 WimPi5 CRON[3659]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Oct 07 09:30:01 WimPi5 victronbtlelogger[1636]: Writing: /var/www/html/victronbtlelogger/victron-D3D19054EBF0-day.svg With Title: S/V Sola Orion XS (D3:D1:90:54:EB:F0)
Oct 07 09:30:01 WimPi5 victronbtlelogger[1636]: Writing: /var/www/html/victronbtlelogger/victron-F948CF185762-day.svg With Title: S/V Sola Battery 2 (F9:48:CF:18:57:62)
Oct 07 09:30:01 WimPi5 victronbtlelogger[1636]: Writing: /var/www/html/victronbtlelogger/victron-E5D1310D9B0F-day.svg With Title: S/V Sola Battery 4 (E5:D1:31:0D:9B:0F)
Oct 07 09:30:01 WimPi5 victronbtlelogger[1636]: Writing: /var/www/html/victronbtlelogger/victron-CEA5D77BCD81-day.svg With Title: S/V Sola Battery 1 (CE:A5:D7:7B:CD:81)
Oct 07 09:30:01 WimPi5 victronbtlelogger[1636]: Writing: /var/www/html/victronbtlelogger/victron-C0FB7EF8BF5D-day.svg With Title: S/V Sola Battery 3 (C0:FB:7E:F8:BF:5D)
Oct 07 09:29:45 WimPi5 snmpd[1633]: systemstats_linux: unexpected header length in /proc/net/snmp. 237 != 224

Is the most recent entry from GoveeBTTempLogger?

These commands are from either bookworm or bullseye. I didn't think to ask what OS you are running.

wim@WimPi5:~ $ lsb_release -a
No LSB modules are available.
Distributor ID: Debian
Description:    Debian GNU/Linux 12 (bookworm)
Release:        12
Codename:       bookworm

wim@WimPi4-Dev:~ $ lsb_release -a
No LSB modules are available.
Distributor ID: Debian
Description:    Debian GNU/Linux 11 (bullseye)
Release:        11
Codename:       bullseye
alzuno commented 1 month ago

Thanks for your help, @wcbonner.

I looked into what you asked, and I’m now confident that the issue wasn’t caused by GoveeBTTempLogger. I’m still investigating the root cause, but I’m fairly certain it was a networking issue.

Also, to confirm, GoveeBTTempLogger is not running as root:

pi@rasp3:~ $ ps aux
USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root           1  0.0  1.2 168436 11316 ?        Ss   Oct10   0:06 /sbin/init
root         449  4.6  0.6  13992  6272 ?        Ss   Oct10  60:39 /usr/libexec/bluetooth/bluetoothd
goveebt+     697 24.5 10.9 108356 102188 ?       Ss   Oct10 321:46 /usr/local/bin/goveebttemplogger --verbose 0 --log /var/log/gov
pi          4718  400  0.4  11152  4352 pts/0    R+   09:24   0:00 ps aux

Is the most recent entry from GoveeBTTempLogger? No, it was another log entry not from GoveeBTTempLogger.

And, i'm using bookworm:

pi@rasp3:~ $ lsb_release -a
No LSB modules are available.
Distributor ID: Debian
Description:    Debian GNU/Linux 12 (bookworm)
Release:    12
Codename:   bookworm

Thanks, i will keep monitoring!