Nuki Smartlock Plugin - Support Thread

[psilo]

ich habe im aktuellen DEV das Plugin jetzt von der lib.connection auf das services interface des http moduls umgebaut. Tester sind willkommen!

Es geht insbesondere um das Empfangen von callbacks von der Nuki Bridge

[stephan68]

Hallo, ich erwäge aktuell die Anschaffung von zwei Nuki Smart Lock 3.0 Pro, die ja über eine WLAN-Anbindung verfügen. Prinzipiell ist mir vor allem die Steuerung über SmartVisu / SmarthomeNG wichtig, deshalb meine Frage: funktioniert das Plugin auch mit dieser Nuki-Variante ohne Bridge? Hat damit jemand Erfahrung?

[fuxl66]

Hallo, ich erwäge aktuell die Anschaffung von zwei Nuki Smart Lock 3.0 Pro, die ja über eine WLAN-Anbindung verfügen. Prinzipiell ist mir vor allem die Steuerung über SmartVisu / SmarthomeNG wichtig, deshalb meine Frage: funktioniert das Plugin auch mit dieser Nuki-Variante ohne Bridge? Hat damit jemand Erfahrung?

Das würde mich auch interessieren

[beavon]

Hallo,

ich setze seit Anfang des Jahres das Nuki-Plugin v1.6.1 mit SHNG v1.9.3 und einem Nuki Smart Lock 3.0 inkl. Bridge ein.
Funktioniert auch alles soweit gut.

Allerdings habe ich seitdem das Problem, dass in unregelmäßigen Abständen (ein paar Stunden bis max. 10 Tage) SHNG wegen zu vieler worker threads neu startet:

2023-02-21  03:46:29 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 20!  (29 worker threads active)
2023-02-21  03:51:23 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 20!  (30 worker threads active)
2023-02-21  03:51:23 WARNING  lib.scheduler       Worker-Threads: plugins.nuki.plugins.nuki: 25, onewire-io: 1, idle: 4
2023-02-21  03:51:23 NOTICE   lib.smarthome       --------------------   SmartHomeNG restarting, initiated by SmartHomeNG (scheduler started too many worker threads (30))   --------------------

Das Nuki-Log zeigt folgendes:

2023-02-21 01:42:11 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': Lock set.  --  (__init__.py:_api_call:265)
2023-02-21 01:42:11 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': starting API Call to Nuki Bridge at http://192.168.100.81:8080/list with payload {'token': '265897'}.  --  (__init__.py:_api_call:281)
2023-02-21 01:42:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': finishing API Call to Nuki Bridge at http://192.168.100.81:8080/list.  --  (__init__.py:_api_call:285)
2023-02-21 01:42:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': Lock removed.  --  (__init__.py:_api_call:292)
2023-02-21 01:42:12 CET INFO     __init__          plugins.nuki.plugins.nuki Plugin 'nuki': Paired Nuki Lock found: Kueche - 824237816  --  (__init__.py:_get_paired_nukis:201)
2023-02-21 01:42:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki [824237816]  --  (__init__.py:_get_paired_nukis:205)
2023-02-21 01:42:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': Lock set.  --  (__init__.py:_api_call:265)
2023-02-21 01:42:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': starting API Call to Nuki Bridge at http://192.168.100.81:8080/callback/list with payload {'token': '265897'}.  --  (__init__.py:_api_call:281)
2023-02-21 01:42:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': finishing API Call to Nuki Bridge at http://192.168.100.81:8080/callback/list.  --  (__init__.py:_api_call:285)
2023-02-21 01:42:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': Lock removed.  --  (__init__.py:_api_call:292)
2023-02-21 01:42:12 CET INFO     __init__          plugins.nuki.plugins.nuki Plugin 'nuki': Callback URL already registered  --  (__init__.py:_register_callback:240)
2023-02-21 01:42:12 CET INFO     __init__          plugins.nuki.plugins.nuki Plugin 'nuki': Getting Nuki status ...  --  (__init__.py:_get_nuki_status:248)
2023-02-21 01:42:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': Lock set.  --  (__init__.py:_api_call:265)
2023-02-21 01:42:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': noWait is 1  --  (__init__.py:_api_call:275)
2023-02-21 01:42:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': starting API Call to Nuki Bridge at http://192.168.100.81:8080/lockState with payload {'nukiID': 824237816, 'token': '265897', 'noWait': 1}.  --  (__init__.py:_api_call:281)
2023-02-21 01:42:15 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': finishing API Call to Nuki Bridge at http://192.168.100.81:8080/lockState.  --  (__init__.py:_api_call:285)
2023-02-21 01:42:15 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': Lock removed.  --  (__init__.py:_api_call:292)
2023-02-21 01:47:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': Lock set.  --  (__init__.py:_api_call:265)
2023-02-21 01:47:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': starting API Call to Nuki Bridge at http://192.168.100.81:8080/list with payload {'token': '265897'}.  --  (__init__.py:_api_call:281)
2023-02-21 01:47:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': finishing API Call to Nuki Bridge at http://192.168.100.81:8080/list.  --  (__init__.py:_api_call:285)
2023-02-21 01:47:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': Lock removed.  --  (__init__.py:_api_call:292)
2023-02-21 01:47:12 CET INFO     __init__          plugins.nuki.plugins.nuki Plugin 'nuki': Paired Nuki Lock found: Kueche - 824237816  --  (__init__.py:_get_paired_nukis:201)
2023-02-21 01:47:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki [824237816]  --  (__init__.py:_get_paired_nukis:205)
2023-02-21 01:47:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': Lock set.  --  (__init__.py:_api_call:265)
2023-02-21 01:47:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': starting API Call to Nuki Bridge at http://192.168.100.81:8080/callback/list with payload {'token': '265897'}.  --  (__init__.py:_api_call:281)
2023-02-21 01:47:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': finishing API Call to Nuki Bridge at http://192.168.100.81:8080/callback/list.  --  (__init__.py:_api_call:285)
2023-02-21 01:47:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': Lock removed.  --  (__init__.py:_api_call:292)
2023-02-21 01:47:12 CET INFO     __init__          plugins.nuki.plugins.nuki Plugin 'nuki': Callback URL already registered  --  (__init__.py:_register_callback:240)
2023-02-21 01:47:12 CET INFO     __init__          plugins.nuki.plugins.nuki Plugin 'nuki': Getting Nuki status ...  --  (__init__.py:_get_nuki_status:248)
2023-02-21 01:47:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': Lock set.  --  (__init__.py:_api_call:265)
2023-02-21 01:47:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': noWait is 1  --  (__init__.py:_api_call:275)
2023-02-21 01:47:12 CET DEBUG    __init__          plugins.nuki.plugins.nuki Plugin 'nuki': starting API Call to Nuki Bridge at http://192.168.100.81:8080/lockState with payload {'nukiID': 824237816, 'token': '265897', 'noWait': 1}.  --  (__init__.py:_api_call:281)

Der nächste Log-Eintrag stammt dann schon vom Neustart ca. 2 Stunden später.

plugin.yaml:

nuki:
    plugin_name: nuki
    bridge_ip: 192.168.100.81
    bridge_port: '8080'
    bridge_api_token: '265897'
    no_wait: true

Hat jemand eine Idee was die Ursache sein kann?

Gruß
Frank

[bmx]

Also für mich sieht das so aus, als ob ein neuer call zur Abfrage des Nuki bereits gestartet wurde ohne das ein älterer beendet wird. Ohne die Hardware zu besitzen und ein vollständiges Log zu haben wird das eher schwierig das zu debuggen.

Haste noch ein Nuki 3.0 mit Bridge übrig?

[stephan68]

bmx Ich habe aktuell das gleiche Problem (2 Nuki 3.0 Smartlocks mit Bridge). Von Zeit zu Zeit startet das Nuki Plugin immer mehr Threads, bis SHNG irgendwann neu startet:

grafik.png

Das geht dann bis ca. 166 Threads:

2023-10-13  15:42:06 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 60!  (156 worker threads active)
2023-10-13  15:52:52 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 60!  (157 worker threads active)
2023-10-13  15:53:53 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 60!  (158 worker threads active)
2023-10-13  16:00:53 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 60!  (159 worker threads active)
2023-10-13  16:01:55 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 60!  (160 worker threads active)
2023-10-13  16:13:20 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 60!  (161 worker threads active)
2023-10-13  16:14:22 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 60!  (162 worker threads active)
2023-10-13  16:21:41 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 60!  (163 worker threads active)
2023-10-13  16:22:42 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 60!  (164 worker threads active)
2023-10-13  16:32:37 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 60!  (165 worker threads active)
2023-10-13  16:33:38 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 60!  (166 worker threads active)
​

Ein vollständiges Log könnte ich liefern, wenn du mir sagst, was genau du brauchst. Ein Log des Nuki-Plugins mit DEBUG-Level?
Die Hardware habe ich leider nicht übrig...

Viele Grüße
Stephan

[bmx]

Du kannst mal spassehalber ein timeout einbauen in die Datei plugins\nuki\__ini__.py in Zeile 284:

response = requests.get(url=urllib.parse.urljoin(base_url, endpoint), params=payload)

ändern in

response = requests.get(url=urllib.parse.urljoin(base_url, endpoint), params=payload, timeout=1)

@stephan68 ein Feedback ob das schonmal was hilft wäre natürlich gut.

Wenn ich mir den Code des Plugins so anschaue wäre da allerdings sicher auch mal eine Überholung fällig. Evetl. kann sich psilo dessen annehmen?

[stephan68]

@stephan68 ein Feedback ob das schonmal was hilft wäre natürlich gut.

bmx sorry für die späte Antwort, ich aber irgendwie erhalte ich -trotz abonniertem Thread und entsprechender Einstellungen- keine Mailbenachrichtigungen bei einer Antwort...


Aber zum Thema: Ich habe den Timeout eingefügt:

grafik.png

Nach dem Neustart von SHNG wird in smartvisu der Schloß-Status nicht mehr angezeigt:

grafik.png

Im WebIF steht für die Schlösser dann der Wert auf 0 (unkalibriert), im Log finden sich dann einige Meldungen mit Connection errors:

root@smarthome:/usr/local/smarthome/var/log# grep -i nuki smarthome-warnings.log
2023-10-20  11:34:21 ERROR    plugins.nuki        HTTPConnectionPool(host='192.168.2.11', port=8080): Read timed out. (read timeout=1)
2023-10-20  11:36:12 ERROR    plugins.nuki        HTTPConnectionPool(host='192.168.2.11', port=8080): Read timed out. (read timeout=1)
2023-10-20  11:40:32 ERROR    plugins.nuki        HTTPConnectionPool(host='192.168.2.11', port=8080): Read timed out. (read timeout=1)
2023-10-20  11:40:32 ERROR    plugins.nuki        Plugin 'nuki': no response.
2023-10-20  11:52:17 ERROR    plugins.nuki        HTTPConnectionPool(host='192.168.2.11', port=8080): Read timed out. (read timeout=1)

Löse ich dann über das WebIF das öffnen / schließen aus, erscheint immer die folgende Meldung im Log:

2023-10-20 11:57:49 ERROR plugins.nuki HTTPConnectionPool(host='192.168.2.11', port=8080): Read timed out. (read timeout=1)
2023-10-20 11:57:49 ERROR plugins.nuki Plugin 'nuki': no response.

Das Schloß öffnet und schließt dann aber trotzdem und der Status aktualisiert sich auch.

[bmx]

Hm. Das Nuki scheint sehr speziell zu sein. Solange das fährt akzeptiert es wohl keine Abfragen oder sowas. Ich denke dann muss sich das Plugin jemand mit der entsprechenden Hardware mal vornehmen....

Du kannst natürlich den Timeout etwas höher setzen und schauen, ob es eine Änderung gibt. Wie lange dauert es denn eigentlich vom Befehl auf- oder zuschliessen bis das Geräte fertig ist?

[psilo]

Ich habe das Problem auch seit Monaten. These ist, dass die Bridge nicht erreichbar ist, und Requests immer wieder neue hängende Anfragen spawned. Bin aber auch nicht so recht dahinter gekommen.. die Bridge (v2) ist bei mir auch nicht Mesh kompatibel und loggt sich immer in der Garage ins Wifi ein, obwohl der Haupt-Router 2m daneben steht. Wenn sie per Zufall mal auf diesem landet, läuft es wochenlang wieder stabil :-(
Bzgl dem Lock beim Fahren dachte ich, dass das im Plugin sogar schon abgehandelt war.. Muss aber selber mal reinschauen.. Aktuell gibts bei mir mal wieder keine Probleme, daher schwer reproduzierbar.

Aber gut zu wissen, dass das 3er auch zickt, dann macht ein Upgrade wenig Sinn ;-)

[stephan68]

bmx

Wie lange dauert es denn eigentlich vom Befehl auf- oder zuschliessen bis das Geräte fertig ist?

Hab's noch nicht gemessen, aber von auf bis zu dauert es auf jeden Fall 5-10 Sekunden. Die Bridge müsste in dieser Zeit aber auf jeden Fall erreichbar sein und auch nicht blockieren, da ich beide Schlösser (die an der gleichen Bridge hängen) auch kurz nacheinander betätigen kann. An guten Tagen funktioniert das reibungslos.

psilo Das mit dem WLAN müsste ich mal prüfen, denn die Bridge, die beide Schlösser bedient sitzt im Prinzip auch zwischen Fritzbox im Haus und Repeater in der Garage und könnte sich mit beiden verbinden. Vielleicht hängt das ja tatsächlich mit dem Wechsel des Accesspoints zusammen. Aktuell ist sie mit der Fritzbox verbunden und alles läuft prima - ich schau mir mal an, ob die Bridge mit der Garage verbunden ist, wenn die Fehler auftreten...

[psilo]

stephan68 ja wäre cool wenn Du da mal nachforschen kannst.. Hätte gehofft, die 3er ist schlauer im Mesh und fast auf gut Glück für teures Geld geupdated... Wobei ich gerade nachgeschaut habe: obwohl alles ok ist, ist das Ding gerade auch wieder in der Garage eingeloggt.. Sehr seltsam... Aber grundlegend gut, wenn ich nicht der Einzige bin. Gemeinsam kriegen wir den root cause raus...

PS: welche version des requests frameworks verwendest Du? ich bin auf 2.31.0.. Hatte auch überlegt ob das mal nen Bug hatte vielleicht.

[stephan68]

psilo

welche version des requests frameworks verwendest Du? ich bin auf 2.31.0.. Hatte auch überlegt ob das mal nen Bug hatte vielleicht.

Bei mir ist 2.22.0 installiert, scheint also eher nicht an der Version zu liegen.

[bmx]

Nur für die Bücher: In alten Versionen < 2.31.0 gab es Sicherheitslecks daher ist das in develop eigentlich schon auf >= 2.31.0 aktualisiert

[stephan68]

Kurzes Update: den Timeout habe ich wieder entfernt, das hat das Problem leider nicht gelöst und von Zeit zu Zeit gab es Schwierigkeiten mit dem Status beim Neustart von SHNG. Anschließend habe ich nach den Hinweisen von psilo und bmx die requests library auf 2.31.0 aktualisiert und seit dem sind die Probleme verschwunden.

Ich hoffe das bleibt so, erstmal vielen Dank für den Support.