[Gelöst]Debian 10, Buster: Bluetooth Probleme nach Upgrade von Debian 9, Stretch

Begonnen von dtavb, 01 Oktober 2019, 21:04:27

Vorheriges Thema - Nächstes Thema
Drucken
Nach unten Seiten1
Benutzer-Aktionen

dtavb

01 Oktober 2019, 21:04:27 Letzte Bearbeitung: 26 Oktober 2019, 22:27:58 von dtavb
Hi Ihr,

nachdem ich Heute via Snapshot auf Debian 10 hochgerüstet habe, geht meine Bluetooth Tracking Geschichte nicht mehr so richtig.
Kurz nach dem Reboot ist der Debian 10 Server mit Bluetooth Dongle noch funktional, nach kurzer Zeit aber dann schon nicht mehr.
Telefon via presence und Nuts via lepresence. Beide sind absent sobald der Fehler nach 2 bis 3 Minuten auftritt.
Ich erkenne nur keinen Fehler :/

Grundsätzlich war nach meinem Upgrade folgender Bluetooth Fehler vorhanden:
Sap driver initialization failed.
sap-server: Operation not permitted (1)
Mit Hilfe der Kollegen von https://raspberrypi.stackexchange.com/questions/40839/sap-error-on-bluetooth-service-status konnte ich das dann beseitigen.

Nachdem ich das SAP Modul unter systemd deaktiviert habe, hatte ich keine Fehlermeldung mehr unter journalctl.
Hat leider nicht gebracht, unten die Log-Ausgaben.

Installierte debs:
presenced-1.5.deb
lepresenced-0.83-3.deb
collectord-1.8.1.deb

Nach Reboot
root@fhemlab:~# journalctl -u presenced.service
-- Logs begin at Tue 2019-10-01 20:29:27 CEST, end at Tue 2019-10-01 20:31:18 CEST. --
Okt 01 20:29:29 fhemlab systemd[1]: Started presence daemon to check device presence via bluetooth for FHEM.
Okt 01 20:29:29 fhemlab presenced[515]: [21B blob data]
Okt 01 20:29:29 fhemlab presenced[515]: [31B blob data]
Okt 01 20:30:43 fhemlab presenced[515]: [36B blob data]
Okt 01 20:30:43 fhemlab presenced[515]: [36B blob data]
root@fhemlab:~# journalctl -u lepresenced.service
-- Logs begin at Tue 2019-10-01 20:29:27 CEST, end at Tue 2019-10-01 20:31:21 CEST. --
Okt 01 20:29:28 fhemlab systemd[1]: Starting lepresenced...
Okt 01 20:29:38 fhemlab systemd[1]: Started lepresenced.
Okt 01 20:29:38 fhemlab lepresenced[1173]: [tid:0] main: Version 0.83 started (device: hci0, listen addr: 0.0.0.0, listen port: 5333, daemonize: 0, legacy mode: 0, rssi threshold: 10, log level: 6, debug: 0).
Okt 01 20:29:38 fhemlab lepresenced[1173]: [tid:0] main::sanity_check: md5 digest of '/usr/sbin/lepresenced' is: dc0db6a06b26acce7739b847c3727fad.
Okt 01 20:29:38 fhemlab lepresenced[1173]: [tid:0] main::sanity_check: hciconfig found at '/bin/hciconfig'.
Okt 01 20:29:38 fhemlab lepresenced[1173]: [tid:0] main::sanity_check: hcitool found at '/usr/bin/hcitool'.
Okt 01 20:29:38 fhemlab lepresenced[1173]: [tid:0] main::sanity_check: hcidump found at '/usr/bin/hcidump'.
Okt 01 20:29:38 fhemlab lepresenced[1173]: [tid:1] main::bluetooth_scan_thread: Received 'LE Scan ...'.
Okt 01 20:30:44 fhemlab lepresenced[1173]: [tid:0] main: Connection from 127.0.0.1:53954. Connected clients: 1.
Okt 01 20:30:44 fhemlab lepresenced[1173]: [tid:0] main: Connection from 127.0.0.1:53962. Connected clients: 2.
Okt 01 20:30:44 fhemlab lepresenced[1173]: [tid:0] main::handle_command: Received query for mac address ca:87:d5:57:09:42, interval: 10. Adding client 127.0.0.1:53954 to clients list.
Okt 01 20:30:44 fhemlab lepresenced[1173]: [tid:0] main::handle_command: Received query for mac address 7c:2f:80:90:78:c7, interval: 10. Adding client 127.0.0.1:53962 to clients list.
Okt 01 20:30:45 fhemlab lepresenced[1173]: [tid:0] main::handle_command: Received query update for mac address ca:87:d5:57:09:42, interval: 60 by client 127.0.0.1:53954.
root@fhemlab:~# journalctl -u collectord.service
-- Logs begin at Tue 2019-10-01 20:29:27 CEST, end at Tue 2019-10-01 20:31:27 CEST. --
Okt 01 20:29:29 fhemlab systemd[1]: Started collecting presence state from multiple presenced instances for FHEM.
Okt 01 20:29:29 fhemlab collectord[516]: [21B blob data]
Okt 01 20:29:29 fhemlab collectord[516]: [27B blob data]
Okt 01 20:29:29 fhemlab collectord[516]: [23B blob data]
Okt 01 20:29:29 fhemlab collectord[516]: [41B blob data]

dmesg
[    6.280420] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[    6.280421] Bluetooth: BNEP filters: protocol multicast
[    6.280423] Bluetooth: BNEP socket layer initialized
[    6.291193] Bluetooth: hci0: unexpected event for opcode 0x0000

/var/log/messages
Oct  1 20:29:29 fhemlab NetworkManager[450]: <info>  [1569954569.1802] Loaded device plugin: NMBluezManager (/usr/lib/x86_64-linux-gnu/NetworkManager/1.14.6/libnm-device-plugin-bluetooth.so)
Oct  1 20:29:29 fhemlab NetworkManager[450]: <info>  [1569954569.2632] bluez: use BlueZ version 5
Oct  1 20:29:29 fhemlab NetworkManager[450]: <info>  [1569954569.7274] bluez5: NAP: added interface 00:1A:7D:DA:71:04
Oct  1 20:29:38 fhemlab lepresenced[1173]: [tid:1] main::bluetooth_scan_thread: Received 'LE Scan ...'.

Fehlerfall: nach etwas 2 bis 3 Minuten
root@fhemlab:~# journalctl -u collectord.service
-- Logs begin at Tue 2019-10-01 20:29:27 CEST, end at Tue 2019-10-01 20:34:08 CEST. --
Okt 01 20:29:29 fhemlab systemd[1]: Started collecting presence state from multiple presenced instances for FHEM.
Okt 01 20:29:29 fhemlab collectord[516]: [21B blob data]
Okt 01 20:29:29 fhemlab collectord[516]: [27B blob data]
Okt 01 20:29:29 fhemlab collectord[516]: [23B blob data]
Okt 01 20:29:29 fhemlab collectord[516]: [41B blob data]
root@fhemlab:~# journalctl -u presenced.service
-- Logs begin at Tue 2019-10-01 20:29:27 CEST, end at Tue 2019-10-01 20:34:35 CEST. --
Okt 01 20:29:29 fhemlab systemd[1]: Started presence daemon to check device presence via bluetooth for FHEM.
Okt 01 20:29:29 fhemlab presenced[515]: [21B blob data]
Okt 01 20:29:29 fhemlab presenced[515]: [31B blob data]
Okt 01 20:30:43 fhemlab presenced[515]: [36B blob data]
Okt 01 20:30:43 fhemlab presenced[515]: [36B blob data]
root@fhemlab:~# journalctl -u lepresenced.service
-- Logs begin at Tue 2019-10-01 20:29:27 CEST, end at Tue 2019-10-01 20:34:47 CEST. --
Okt 01 20:29:28 fhemlab systemd[1]: Starting lepresenced...
Okt 01 20:29:38 fhemlab systemd[1]: Started lepresenced.
Okt 01 20:29:38 fhemlab lepresenced[1173]: [tid:0] main: Version 0.83 started (device: hci0, listen addr: 0.0.0.0, listen port: 5333, daemonize: 0, legacy mode: 0, rssi threshold: 10, log level: 6, debug: 0).
Okt 01 20:29:38 fhemlab lepresenced[1173]: [tid:0] main::sanity_check: md5 digest of '/usr/sbin/lepresenced' is: dc0db6a06b26acce7739b847c3727fad.
Okt 01 20:29:38 fhemlab lepresenced[1173]: [tid:0] main::sanity_check: hciconfig found at '/bin/hciconfig'.
Okt 01 20:29:38 fhemlab lepresenced[1173]: [tid:0] main::sanity_check: hcitool found at '/usr/bin/hcitool'.
Okt 01 20:29:38 fhemlab lepresenced[1173]: [tid:0] main::sanity_check: hcidump found at '/usr/bin/hcidump'.
Okt 01 20:29:38 fhemlab lepresenced[1173]: [tid:1] main::bluetooth_scan_thread: Received 'LE Scan ...'.
Okt 01 20:30:44 fhemlab lepresenced[1173]: [tid:0] main: Connection from 127.0.0.1:53954. Connected clients: 1.
Okt 01 20:30:44 fhemlab lepresenced[1173]: [tid:0] main: Connection from 127.0.0.1:53962. Connected clients: 2.
Okt 01 20:30:44 fhemlab lepresenced[1173]: [tid:0] main::handle_command: Received query for mac address ca:87:d5:57:09:42, interval: 10. Adding client 127.0.0.1:53954 to clients list.
Okt 01 20:30:44 fhemlab lepresenced[1173]: [tid:0] main::handle_command: Received query for mac address 7c:2f:80:90:78:c7, interval: 10. Adding client 127.0.0.1:53962 to clients list.
Okt 01 20:30:45 fhemlab lepresenced[1173]: [tid:0] main::handle_command: Received query update for mac address ca:87:d5:57:09:42, interval: 60 by client 127.0.0.1:53954.
Okt 01 20:34:39 fhemlab lepresenced[1173]: [tid:0] main::stats_task: Active clients: 2, known devices: 3 (min/max age: 79/79), received beacons (hcitool/hcidump/difference): 887/887/0
Okt 01 20:34:45 fhemlab lepresenced[1173]: [tid:0] main::handle_command: Received query update for mac address ca:87:d5:57:09:42, interval: 10 by client 127.0.0.1:53954.

Die restlichen Ausgaben wie messages oder dmesg bringen keine Neuigkeiten.

Fhem Log, verbose 5:
2019.10.01 20:37:15 5: PRESENCE (bt_nut_small2) - received data: absence;rssi=unreachable;model=lan-lepresenced;daemon=lepresenced V0.83
2019.10.01 20:37:16 5: PRESENCE (bt_mate_wz) - received data: absence

Folgende Ausgaben auf der CLI, etwas spielen:
[bluetooth]# default-agent
Default agent request successful
[bluetooth]# scan on
Failed to start discovery: org.bluez.Error.InProgress

hcitool -i hci0 lescan --duplicates
Set scan parameters failed: Connection timed out

hcitool dev
Devices:
        hci0    00:1A:7D:DA:71:04
      

Hat jemand von Euch eine Idee?
Unter Debian 9 funktioniert es einwandfrei, allerdings habe ich von Debian 8 auf Debian 9 eine Neuinstallation gemacht.
Bin jetzt übergangsweise wieder zurück auf den Snapshot mit Debian 9

Falls jemand Debian 10, Presence und lan-bluetooth am Laufen hat, wäre ich auch schon froh über Tipps oder Erfahrungen :)

Danke Euch und Grüsse,
dtavb
fhem:pi3&kvm, z-wave, it-funk, milight, zigbee, wifi, bt & presence, geo-tracking, alexa, esp.
Monitoring: ELK(syslog), grafana (grafik), netdata (ermittlung)
Security: haproxy (access), ossec (überall), snort (access), opnsense (fw)
Geplant: KVM-Cluster

dtavb

#1
02 Oktober 2019, 19:42:40
Hi Ihr,
ok, nachdem ich fhem auf Debian 10 neuinstalliert habe, taucht das gleiche Problem auf:

● lepresenced.service - lepresenced
   Loaded: loaded (/lib/systemd/system/lepresenced.service; disabled; vendor preset: enabled)
   Active: active (running) since Wed 2019-10-02 19:37:50 CEST; 25s ago
  Process: 5273 ExecStartPre=/bin/sleep 10 (code=exited, status=0/SUCCESS)
Main PID: 5276 (lepresenced)
    Tasks: 5 (limit: 1149)
   Memory: 14.9M
   CGroup: /system.slice/lepresenced.service
           ├─5276 /usr/bin/perl /usr/sbin/lepresenced --device hci0 --listenaddress 0.0.0.0 --listenport 5333 --loglevel LOG_DEBUG
           ├─5286 hcidump -i hci0
           └─5293 hcitool -i hci0 lescan --duplicates

Okt 02 19:37:50 fhem systemd[1]: Started lepresenced.
Okt 02 19:37:50 fhem lepresenced[5276]: [tid:0] main: Version 0.83 started (device: hci0, listen addr: 0.0.0.0, listen port: 5333, daemonize: 0, legacy mode: 0, rssi thr
Okt 02 19:37:50 fhem lepresenced[5276]: [tid:0] main::sanity_check: md5 digest of '/usr/sbin/lepresenced' is: dc0db6a06b26acce7739b847c3727fad.
Okt 02 19:37:50 fhem lepresenced[5276]: [tid:0] main::sanity_check: hciconfig found at '/usr/bin/hciconfig'.
Okt 02 19:37:50 fhem lepresenced[5276]: [tid:0] main::sanity_check: hcitool found at '/usr/bin/hcitool'.
Okt 02 19:37:50 fhem lepresenced[5276]: [tid:0] main::sanity_check: hcidump found at '/usr/bin/hcidump'.
Okt 02 19:38:00 fhem lepresenced[5276]: [tid:1] main::bluetooth_scan_thread: Received unknown output: 'Set scan parameters failed: Connection timed out'!
Okt 02 19:38:00 fhem lepresenced[5276]: [tid:1] main::bluetooth_scan_thread: hcitool exited, retrying...
Okt 02 19:38:11 fhem lepresenced[5276]: [tid:1] main::bluetooth_scan_thread: Received unknown output: 'Set scan parameters failed: Connection timed out'!
Okt 02 19:38:11 fhem lepresenced[5276]: [tid:1] main::bluetooth_scan_thread: hcitool exited, retrying...

...
Dieser Block wiederholt sich permanent...die le-Devices sind alle absent
Okt 02 19:38:42 fhem lepresenced[5276]: [tid:0] main::handle_command: Received query for mac address 7c:2f:80:90:78:c7, interval: 10. Adding client 127.0.0.1:44558 to cl
Okt 02 19:38:42 fhem lepresenced[5276]: [tid:0] main: Sending update for mac address 7c:2f:80:90:78:c7, max age: 10, result: absence.
Okt 02 19:38:45 fhem lepresenced[5276]: [tid:1] main::bluetooth_scan_thread: Received unknown output: 'Set scan parameters failed: Connection timed out'!
Okt 02 19:38:45 fhem lepresenced[5276]: [tid:1] main::bluetooth_scan_thread: hcitool exited, retrying...
Okt 02 19:38:51 fhem lepresenced[5276]: [tid:0] main: Sending update for mac address ca:87:d5:57:09:42, max age: 10, result: absence.
Okt 02 19:38:52 fhem lepresenced[5276]: [tid:0] main: Sending update for mac address 7c:2f:80:90:78:c7, max age: 10, result: absence.
Okt 02 19:38:56 fhem lepresenced[5276]: [tid:1] main::bluetooth_scan_thread: Received unknown output: 'Set scan parameters failed: Connection timed out'!
Okt 02 19:38:56 fhem lepresenced[5276]: [tid:1] main::bluetooth_scan_thread: hcitool exited, retrying...
Okt 02 19:39:01 fhem lepresenced[5276]: [tid:0] main: Sending update for mac address ca:87:d5:57:09:42, max age: 10, result: absence.
Okt 02 19:39:02 fhem lepresenced[5276]: [tid:0] main: Sending update for mac address 7c:2f:80:90:78:c7, max age: 10, result: absence.
Die beide MACs sind ein Gtag und ein nut

presence schaut so aus:
● presenced.service - presence daemon to check device presence via bluetooth for FHEM
   Loaded: loaded (/lib/systemd/system/presenced.service; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2019-10-02 19:40:12 CEST; 4s ago
     Docs: http://commandref.fhem.de/#PRESENCE
           https://wiki.fhem.de/wiki/PRESENCE#.C3.9Cberwachung_durch_verteilte_Agenten_in_der_Wohnung_.28presenced.2Flepresenced.2Fcollectord.29
Main PID: 5377 (presenced)
    Tasks: 1 (limit: 1149)
   Memory: 6.1M
   CGroup: /system.slice/presenced.service
           └─5377 /usr/bin/perl /usr/bin/presenced -v -n -p 5111

Okt 02 19:40:12 fhem systemd[1]: Started presence daemon to check device presence via bluetooth for FHEM.
Okt 02 19:40:13 fhem presenced[5377]: [22B blob data]
Okt 02 19:40:13 fhem presenced[5377]: [31B blob data]

● presenced.service - presence daemon to check device presence via bluetooth for FHEM
   Loaded: loaded (/lib/systemd/system/presenced.service; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2019-10-02 19:40:12 CEST; 23s ago
     Docs: http://commandref.fhem.de/#PRESENCE
           https://wiki.fhem.de/wiki/PRESENCE#.C3.9Cberwachung_durch_verteilte_Agenten_in_der_Wohnung_.28presenced.2Flepresenced.2Fcollectord.29
Main PID: 5377 (presenced)
    Tasks: 5 (limit: 1149)
   Memory: 12.3M
   CGroup: /system.slice/presenced.service
           ├─5377 /usr/bin/perl /usr/bin/presenced -v -n -p 5111
           ├─5394 sh -c hcitool name 90:2B:D2:CF:FF:9C 2>/dev/null  --> Smartphone via presenced
           └─5395 hcitool name 90:2B:D2:CF:FF:9C

Okt 02 19:40:12 fhem systemd[1]: Started presence daemon to check device presence via bluetooth for FHEM.
Okt 02 19:40:13 fhem presenced[5377]: [22B blob data]
Okt 02 19:40:13 fhem presenced[5377]: [31B blob data]
Okt 02 19:40:34 fhem presenced[5377]: [36B blob data]
Okt 02 19:40:34 fhem presenced[5377]: [36B blob data]

Ich habe das Gefühl, dass die BT-Komponenten von Linux ein Problem mit Debian 10 haben.

Grüsse,
dtavb
fhem:pi3&kvm, z-wave, it-funk, milight, zigbee, wifi, bt & presence, geo-tracking, alexa, esp.
Monitoring: ELK(syslog), grafana (grafik), netdata (ermittlung)
Security: haproxy (access), ossec (überall), snort (access), opnsense (fw)
Geplant: KVM-Cluster

PatrickR

#2
06 Oktober 2019, 17:32:58 Letzte Bearbeitung: 06 Oktober 2019, 17:42:08 von PatrickR
Hi!

Zitat von: dtavb am 01 Oktober 2019, 21:04:27
Okt 01 20:29:28 fhemlab systemd[1]: Starting lepresenced...
Okt 01 20:29:38 fhemlab systemd[1]: Started lepresenced.
Okt 01 20:29:38 fhemlab lepresenced[1173]: [tid:0] main: Version 0.83 started (device: hci0, listen addr: 0.0.0.0, listen port: 5333, daemonize: 0, legacy mode: 0, rssi threshold: 10, log level: 6, debug: 0).
Okt 01 20:29:38 fhemlab lepresenced[1173]: [tid:0] main::sanity_check: md5 digest of '/usr/sbin/lepresenced' is: dc0db6a06b26acce7739b847c3727fad.
Okt 01 20:29:38 fhemlab lepresenced[1173]: [tid:0] main::sanity_check: hciconfig found at '/bin/hciconfig'.
Okt 01 20:29:38 fhemlab lepresenced[1173]: [tid:0] main::sanity_check: hcitool found at '/usr/bin/hcitool'.
Okt 01 20:29:38 fhemlab lepresenced[1173]: [tid:0] main::sanity_check: hcidump found at '/usr/bin/hcidump'.
Okt 01 20:29:38 fhemlab lepresenced[1173]: [tid:1] main::bluetooth_scan_thread: Received 'LE Scan ...'.
[...]
Okt 01 20:34:39 fhemlab lepresenced[1173]: [tid:0] main::stats_task: Active clients: 2, known devices: 3 (min/max age: 79/79), received beacons (hcitool/hcidump/difference): 887/887/0

Das sieht doch schonmal garnicht so schlecht aus. Lepresenced kann scannen und findet zwei Devices. Später wird der Prozess dann beendet. Das passiert üblicherweise, wenn mehrere Dienste auf das Bluetooth-Gerät zugreifen. Sorge doch mal dafür, dass nach dem Systemstart nur lepresenced auf das Bluetooth-Gerät zugreift und starte dann den Rechner durch. D. h. konkret, Kandidaten wie presenced und vor allem NMBluezManager (testweise) deaktivieren/deinstallieren.

Patrick
lepresenced - Tracking von Bluetooth-LE-Tags (Gigaset G-Tag) mittels PRESENCE

"Programming today is a race between software engineers striving to build bigger and better idiot-proof programs, and the universe trying to produce bigger and better idiots. So far, the universe is winning." - Rich Cook

dtavb

#3
26 Oktober 2019, 22:27:32 Letzte Bearbeitung: 26 Oktober 2019, 22:30:27 von dtavb
ich konnte das Problem nicht direkt lösen.
Selbst eine Neuinstallation unter Buster klappt für (le)presenced nicht. Ehrlich gesagt verstehe ich es nicht...

In Ermangelung an Zeit, habe ich mich zu einem Workaround entschieden:
Ich habe einen OrangePi nun mit einem BT-Dongle ausgestattet und dort unter Debian10-Basis (Armbian) alles zum Laufen gebracht.
Das grenzt schon fast an Ironie, dass ich es nicht unter einer 0815 Debian Buster Installation hinbekomme, dafür aber via Debian Buster unter ARM.
Auch dort geht es nicht out-of-the-box, ein grosses Dank an das HowTo für Presence: Hinweis auf die (le)presenced Skripte.
Diese habe ich angepasst und unter supervisor dann zum Laufen gebracht. Nun läuft die BT-Überwachung wieder wunderbar.

Ein Workaround mit kleinem Mehrwert: den süssen OrangePi kann ich via WiFi überall stationieren :)
fhem:pi3&kvm, z-wave, it-funk, milight, zigbee, wifi, bt & presence, geo-tracking, alexa, esp.
Monitoring: ELK(syslog), grafana (grafik), netdata (ermittlung)
Security: haproxy (access), ossec (überall), snort (access), opnsense (fw)
Geplant: KVM-Cluster
Drucken
Nach oben Seiten1
Benutzer-Aktionen