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

org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress #80

Open alzuno opened 11 hours ago

alzuno commented 11 hours ago

Hi @wcbonner,

I've been experiencing recurring service interruptions. Over the past month, the system hasn't remained up for more than 24 hours. Previously, it would sometimes run for a month without any issues.

From the logs, I noticed this recurring error:

/org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)

After this error appears, the logging stops entirely. The only way to get the system working again is to reboot the Raspberry Pi.

Here a piece of logs from the system:

Nov 14 09:39:41 rasp3 goveebttemplogger[33743]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 09:39:41 rasp3 goveebttemplogger[33743]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 09:39:41 rasp3 goveebttemplogger[33743]: /org/bluez/hci0: org.freedesktop.DBus.Properties: SetPowered: true
Nov 14 09:39:41 rasp3 goveebttemplogger[33743]: Host Controller Address: B8:27:EB:FF:AD:6A BlueZ Adapter Path: /org/bluez/hci0
Nov 14 09:39:41 rasp3 goveebttemplogger[33743]: Connected to D-Bus as ":1.21"
Nov 14 09:39:41 rasp3 goveebttemplogger[33743]: Reading LastDownload: /var/log/goveebttemplogger/gvh-lastdownload.txt
Nov 14 09:39:40 rasp3 goveebttemplogger[33743]: Reading: /var/log/goveebttemplogger/gvh-A4C13856DF3C-2024-11.txt
Nov 14 09:39:40 rasp3 goveebttemplogger[33743]: Reading: /var/log/goveebttemplogger/gvh-A4C138043FDE-2024-11.txt
Nov 14 09:39:40 rasp3 goveebttemplogger[33743]: Reading: /var/cache/goveebttemplogger/gvh-A4C13856DF3C-cache.txt
Nov 14 09:39:40 rasp3 goveebttemplogger[33743]: Reading: /var/cache/goveebttemplogger/gvh-A4C138043FDE-cache.txt
Nov 14 09:39:40 rasp3 goveebttemplogger[33743]: Reading: /var/log/goveebttemplogger/gvh-thermometer-types.txt
Nov 14 09:39:40 rasp3 goveebttemplogger[33743]: Reading: /var/www/html/goveebttemplogger/gvh-titlemap.txt
Nov 14 09:39:40 rasp3 goveebttemplogger[33743]: GoveeBTTempLogger Version 3.20241023.1 Built on: Nov 13 2024 at 09:24:30 (starting)
Nov 14 09:39:40 rasp3 systemd[1]: Started GoveeBTTempLogger service.
Nov 14 09:39:33 rasp3 systemd[1]: goveebttemplogger.service: Consumed 17min 4.071s CPU time.
Nov 14 09:39:33 rasp3 systemd[1]: Stopped GoveeBTTempLogger service.
Nov 14 09:39:33 rasp3 systemd[1]: goveebttemplogger.service: Succeeded.
Nov 14 09:39:33 rasp3 goveebttemplogger[674]: GoveeBTTempLogger Version 3.20241023.1 Built on: Nov 13 2024 at 09:24:30 (exiting)
Nov 14 09:39:33 rasp3 goveebttemplogger[674]: Writing: /var/log/goveebttemplogger/gvh-thermometer-types.txt
Nov 14 09:39:33 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 09:39:32 rasp3 systemd[1]: Stopping GoveeBTTempLogger service...
Nov 14 09:39:32 rasp3 goveebttemplogger[674]: ***************** SIGINT: Caught Ctrl-C, finishing loop and quitting. *****************
Nov 14 09:30:56 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 09:30:56 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 09:30:56 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 09:00:55 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 09:00:55 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 09:00:55 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 08:30:54 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 08:30:54 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 08:30:54 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 08:00:53 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 08:00:53 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 08:00:53 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 07:30:52 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 07:30:52 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 07:30:52 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 07:00:51 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 07:00:51 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 07:00:51 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 06:30:50 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 06:30:50 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 06:30:50 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 06:00:49 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 06:00:49 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 06:00:49 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 05:30:48 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 05:30:48 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 05:30:48 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 05:00:47 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 05:00:47 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 05:00:47 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 04:30:46 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 04:30:46 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 04:30:46 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 04:00:45 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 04:00:45 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 04:00:45 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 03:30:44 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 03:30:44 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 03:30:44 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 03:00:43 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 03:00:43 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 03:00:43 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 02:30:42 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 02:30:42 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 02:30:42 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 02:00:41 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 02:00:41 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 02:00:41 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 01:30:40 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 01:30:40 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 01:30:40 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 01:00:39 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 01:00:39 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 01:00:39 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 00:40:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-day.svg With Title: Office (A4:C1:38:56:DF:3C)
Nov 14 00:40:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-day.svg With Title: Room (A4:C1:38:04:3F:DE)
Nov 14 00:35:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-week.svg With Title: Office (A4:C1:38:56:DF:3C)
Nov 14 00:35:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-day.svg With Title: Office (A4:C1:38:56:DF:3C)
Nov 14 00:35:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-week.svg With Title: Room (A4:C1:38:04:3F:DE)
Nov 14 00:35:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-day.svg With Title: Room (A4:C1:38:04:3F:DE)
Nov 14 00:30:39 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 00:30:39 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 00:30:39 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
Nov 14 00:30:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-day.svg With Title: Office (A4:C1:38:56:DF:3C)
Nov 14 00:30:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-day.svg With Title: Room (A4:C1:38:04:3F:DE)
Nov 14 00:25:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-day.svg With Title: Office (A4:C1:38:56:DF:3C)
Nov 14 00:25:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-day.svg With Title: Room (A4:C1:38:04:3F:DE)
Nov 14 00:20:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-day.svg With Title: Office (A4:C1:38:56:DF:3C)
Nov 14 00:20:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-day.svg With Title: Room (A4:C1:38:04:3F:DE)
Nov 14 00:15:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-day.svg With Title: Office (A4:C1:38:56:DF:3C)
Nov 14 00:15:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-day.svg With Title: Room (A4:C1:38:04:3F:DE)
Nov 14 00:10:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-day.svg With Title: Office (A4:C1:38:56:DF:3C)
Nov 14 00:10:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-day.svg With Title: Room (A4:C1:38:04:3F:DE)
Nov 14 00:05:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-year.svg With Title: Office (A4:C1:38:56:DF:3C)
Nov 14 00:05:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-month.svg With Title: Office (A4:C1:38:56:DF:3C)
Nov 14 00:05:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-week.svg With Title: Office (A4:C1:38:56:DF:3C)
Nov 14 00:05:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-day.svg With Title: Office (A4:C1:38:56:DF:3C)
Nov 14 00:05:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-year.svg With Title: Room (A4:C1:38:04:3F:DE)
Nov 14 00:05:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-month.svg With Title: Room (A4:C1:38:04:3F:DE)
Nov 14 00:05:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-week.svg With Title: Room (A4:C1:38:04:3F:DE)
Nov 14 00:05:01 rasp3 goveebttemplogger[674]: Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-day.svg With Title: Room (A4:C1:38:04:3F:DE)
Nov 14 00:00:37 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
Nov 14 00:00:37 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
Nov 14 00:00:37 rasp3 goveebttemplogger[674]: /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)

I ran the system on the console and observed the same issue:

[2024-11-15T13:53:55] [A4:C1:38:56:DF:3C] (Temp) 21.9°C (Humidity)  58.2% (Battery)  85% (GVH5075)
[2024-11-15T13:53:55] [A4:C1:38:04:3F:DE] (Temp) 21.2°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[2024-11-15T13:53:57] [A4:C1:38:56:DF:3C] (Temp) 21.9°C (Humidity)  58.2% (Battery)  85% (GVH5075)
[2024-11-15T13:53:57] [A4:C1:38:04:3F:DE] (Temp) 21.2°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[2024-11-15T13:53:59] [A4:C1:38:56:DF:3C] (Temp) 21.9°C (Humidity)  58.2% (Battery)  85% (GVH5075)
[2024-11-15T13:53:59] [A4:C1:38:04:3F:DE] (Temp) 21.2°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[2024-11-15T13:54:11] [A4:C1:38:56:DF:3C] (Temp) 21.9°C (Humidity)  58.2% (Battery)  86% (GVH5075)
[2024-11-15T13:54:11] [A4:C1:38:04:3F:DE] (Temp) 21.1°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[2024-11-15T13:54:14] [A4:C1:38:56:DF:3C] (Temp) 21.9°C (Humidity)  58.2% (Battery)  86% (GVH5075)
[2024-11-15T13:54:14] [A4:C1:38:04:3F:DE] (Temp) 21.2°C (Humidity)  60.7% (Battery)  47% (GVH5075)
[2024-11-15T13:54:17] [A4:C1:38:04:3F:DE] (Temp) 21.1°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[2024-11-15T13:54:18] [A4:C1:38:56:DF:3C] (Temp) 21.9°C (Humidity)  58.2% (Battery)  86% (GVH5075)
[2024-11-15T13:54:22] [A4:C1:38:04:3F:DE] (Temp) 21.1°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[-------------------] [A4:C1:38:04:3F:DE] 00:00:00
[-------------------] [A4:C1:38:56:DF:3C] 00:00:00
[2024-11-15T13:54:26] [A4:C1:38:04:3F:DE] (Temp) 21.1°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[2024-11-15T13:54:29] [A4:C1:38:56:DF:3C] (Temp) 21.9°C (Humidity)  58.2% (Battery)  86% (GVH5075)
[2024-11-15T13:54:32] [A4:C1:38:04:3F:DE] (Temp) 21.2°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[2024-11-15T13:54:33] [A4:C1:38:56:DF:3C] (Temp) 21.9°C (Humidity)  58.2% (Battery)  86% (GVH5075)
[2024-11-15T13:54:35] [A4:C1:38:04:3F:DE] (Temp) 21.2°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[2024-11-15T13:54:40] [A4:C1:38:04:3F:DE] (Temp) 21.1°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[2024-11-15T13:54:43] [A4:C1:38:04:3F:DE] (Temp) 21.2°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[2024-11-15T13:54:45] [A4:C1:38:56:DF:3C] (Temp) 22.0°C (Humidity)  58.2% (Battery)  85% (GVH5075)
[2024-11-15T13:54:45] [A4:C1:38:04:3F:DE] (Temp) 21.2°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[2024-11-15T13:54:53] [A4:C1:38:04:3F:DE] (Temp) 21.1°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[2024-11-15T13:54:58] [A4:C1:38:04:3F:DE] (Temp) 21.2°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[2024-11-15T13:54:59] [A4:C1:38:56:DF:3C] (Temp) 21.9°C (Humidity)  58.2% (Battery)  85% (GVH5075)
[2024-11-15T13:55:00] [A4:C1:38:56:DF:3C] (Temp) 21.9°C (Humidity)  58.2% (Battery)  85% (GVH5075)
[2024-11-15T13:55:00] [A4:C1:38:04:3F:DE] (Temp) 21.1°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[2024-11-15T13:55:01] 300 seconds or more have passed. Writing SVG Files
[2024-11-15T13:55:01] Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-day.svg With Title: Room (A4:C1:38:04:3F:DE)
[2024-11-15T13:55:01] Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-day.svg With Title: Office (A4:C1:38:56:DF:3C)
[2024-11-15T13:55:06] [A4:C1:38:56:DF:3C] (Temp) 21.9°C (Humidity)  58.2% (Battery)  85% (GVH5075)
[2024-11-15T13:55:18] [A4:C1:38:56:DF:3C] (Temp) 21.9°C (Humidity)  58.2% (Battery)  85% (GVH5075)
[2024-11-15T13:55:18] [A4:C1:38:04:3F:DE] (Temp) 21.1°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[2024-11-15T13:55:23] [A4:C1:38:56:DF:3C] (Temp) 21.9°C (Humidity)  58.2% (Battery)  85% (GVH5075)
[2024-11-15T13:55:23] [A4:C1:38:04:3F:DE] (Temp) 21.2°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[-------------------] [A4:C1:38:04:3F:DE] 00:00:00
[-------------------] [A4:C1:38:56:DF:3C] 00:00:00
[2024-11-15T13:55:25] [A4:C1:38:04:3F:DE] (Temp) 21.2°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[2024-11-15T13:55:26] [A4:C1:38:56:DF:3C] (Temp) 22.0°C (Humidity)  58.2% (Battery)  85% (GVH5075)
[2024-11-15T13:55:28] [A4:C1:38:56:DF:3C] (Temp) 21.9°C (Humidity)  58.2% (Battery)  85% (GVH5075)
[2024-11-15T13:55:37] [A4:C1:38:04:3F:DE] (Temp) 21.2°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[2024-11-15T13:55:41] [A4:C1:38:56:DF:3C] (Temp) 21.9°C (Humidity)  58.2% (Battery)  85% (GVH5075)
[2024-11-15T13:55:45] [A4:C1:38:04:3F:DE] (Temp) 21.1°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[-------------------] [A4:C1:38:04:3F:DE] 00:00:00
[-------------------] [A4:C1:38:56:DF:3C] 00:00:00
[-------------------] [A4:C1:38:04:3F:DE] 00:00:00
[-------------------] [A4:C1:38:56:DF:3C] 00:00:00
[2024-11-15T13:57:35] [A4:C1:38:56:DF:3C] (Temp) 21.9°C (Humidity)  58.2% (Battery)  85% (GVH5075)
[                   ] /org/bluez/hci0: org.bluez.Adapter1: StopDiscovery: Error: Operation already in progress /home/pi/GoveeBTTempLogger/goveebttemplogger.cpp(3918)
[                   ] /org/bluez/hci0: org.bluez.Adapter1: SetDiscoveryFilter
[                   ] /org/bluez/hci0: org.bluez.Adapter1: StartDiscovery
[-------------------] [A4:C1:38:04:3F:DE] 00:00:00
[-------------------] [A4:C1:38:56:DF:3C] 00:00:00
[-------------------] [A4:C1:38:04:3F:DE] 00:00:00
[-------------------] [A4:C1:38:56:DF:3C] 00:00:00
[2024-11-15T14:00:01] 300 seconds or more have passed. Writing SVG Files
[2024-11-15T14:00:01] Writing: /var/www/html/goveebttemplogger/gvh-A4C138043FDE-day.svg With Title: Room (A4:C1:38:04:3F:DE)
[2024-11-15T14:00:01] Writing: /var/www/html/goveebttemplogger/gvh-A4C13856DF3C-day.svg With Title: Office (A4:C1:38:56:DF:3C)
[2024-11-15T14:00:17] [A4:C1:38:04:3F:DE] (Temp) 21.1°C (Humidity)  60.8% (Battery)  47% (GVH5075)
[-------------------] [A4:C1:38:04:3F:DE] 00:00:00
[-------------------] [A4:C1:38:56:DF:3C] 00:00:00
[-------------------] [A4:C1:38:04:3F:DE] 00:00:00
[-------------------] [A4:C1:38:56:DF:3C] 00:00:00
[-------------------] [A4:C1:38:04:3F:DE] 00:00:00
[-------------------] [A4:C1:38:56:DF:3C] 00:00:00

Additional Information:

Distributor ID: Debian
Description:    Debian GNU/Linux 11 (bullseye)
Release:    11
Codename:   bullseye

Thanks for your help!

wcbonner commented 6 hours ago

@alzuno I'd seen some problems like this but was hoping that I'd fixed it.

Are you running on a Raspberry Pi or another platform? (I'm guessing by your machine name in the logs that it's a Raspberry Pi3.)

Is the software running as the user goveebttemplogger instead of root? (one of my recent changes was to avoid running as root)

Are you running anything else that uses Bluetooth? (Keyboard, Mouse, or any other program?)

Am I correct that the Bluetooth appears to not work at all after this problem occurs, and the only way to recover it is to reboot the entire machine?

I've seen this issue and am not sure what's happening. There may be something I'm not cleaning up in the DBus communication that is causing BlueZ to leak memory and stop responding. It seems wrong that a user mode program can crash a piece of system software..

You should be able to revert to the old hardware Bluetooth Hardware Control Interface by adding the --HCI option to the end of the command line, but that probably won't recover the Bluetooth after it's locked up. Using HCI took exclusive control of the Bluetooth interface and has been deprecated for several years.

wcbonner commented 21 minutes ago

@alzuno Commits I made today https://github.com/wcbonner/GoveeBTTempLogger/commit/c8e2cd16bce06fd4db5d36624addba28b6471faa and then https://github.com/wcbonner/GoveeBTTempLogger/commit/6b895c515abb1a28d4ec0a7aba391b6e14c7bcb8 bring the version up to 3.20241115.1 and I'm hoping will squash the issue you have for good.

I'm going to run this on my primary machines for a couple of days before creating a new release, but I'm interested if this fixes the issue on your platform.