SHNG Stürzt ab "worker threads", "ERROR modules.websocket update_item "

[Art Mooney]

Ich melde mich mal wieder, nachdem ich lange Zeit nicht an dem Problem arbeiten konnte.

Oben schrieb ich, dass die Plugin-Funktionen funktionieren. Das war aber leider nicht reproduzierbar. Bisweilen hatte ich den Eindruck, dass es nach einem Neustart von shng einmal funktionierte und danach nicht mehr. Nun habe ich die Plugin-Funktionen erst einmal wieder deaktiviert (Logik per "Pause"-Icon in der Admin-GUI deaktiviert), um zurück zu meinem alten Status zu kommen.

Irgendetwas stimmt hier aber nach wie vor nicht. Funktioneren soll das Abspielen von Musik wie folgt.

1. Am KNX-Tastsensor wird eine Playliste ausgewählt, die einer Szenen-Nummer entspricht. Per Logik wird dann in mpd die Playliste gestartet und ein 1bit-Telegramm zum Einschalten des Russound erzeugt (RUS.ZONE1.BOOLTOV). Das sieht so aus:

#!/usr/bin/env python3
# mpdplaylist.py
if sh.MPD.SZENE() == 0:
    sh.MPD.JAZZ(True)
    sh.RUS.ZONE1.BOOLTOV(True)

2. SHNG prüft bei Änderung des 1bit-Telegramms, ob der Russound Strom hat. Wenn nicht, wird die Steckdose eingeschaltet (K4.STECK.SWIT2) und ein Timer gestartet (RUS.ZONE1.ONTIMER), der 70 Sekunden runterzählt:

if sh.RUS.ZONE1.BOOLTOV() == True and sh.K4.STECK.SWIT2() == True:
    sh.RUS.ZONE1.TURNONVOL(7)
    sh.RUS.ZONE1.SOURCE(2)
elif sh.RUS.ZONE1.BOOLTOV() == True and sh.K4.STECK.SWIT2() == False:
    sh.K4.STECK.SWIT2(True)
    sh.RUS.ZONE1.ONTIMER(True)
elif sh.RUS.ZONE1.BOOLTOV() == False:
    sh.RUS.ZONE1.POWER(False)

3. Der Russound hängt an einem Strommessaktor, der nach 45 Sekunden unter der Last des Russounds ein 1bit-Telegramm schickt (K4.NOTE2). Wenn dieses Telegramm eintrifft, prüft eine Logik, welcher Timer gerade auf "True" steht und sendet noch einmal das Telegramm zum Einschalten der entsprechenden Zone (RUS.ZONE1.BOOLTOV).

#!/usr/bin/env python3
# k4note2return.py
if sh.K4.NOTE2() == True and sh.RUS.ZONE1.ONTIMER() == True:  
    sh.RUS.ZONE1.BOOLTOV(True)
elif sh.K4.NOTE2() == True and sh.RUS.ZONE2.ONTIMER() == True:
    sh.RUS.ZONE2.BOOLTOV(True)    
elif sh.K4.NOTE2() == True and sh.RUS.ZONE4.ONTIMER() == True:
    sh.RUS.ZONE4.BOOLTOV(True)  
elif sh.K4.NOTE2() == True and sh.RUS.ZONE5.ONTIMER() == True:
    sh.RUS.ZONE5.BOOLTOV(True)    
elif sh.K4.NOTE2() == True and sh.RUS.ZONE6.ONTIMER() == True:
    sh.RUS.ZONE6.BOOLTOV(True)

Nun zur Schilderung des Problems:

- Das beschriebene Verfahren funktioniert nach einem Neustart von SHNG einmal. Schalte ich dann wieder ab und will später (nachdem der Russound wieder stromlos ist) noch einmal in der Zone Musik hören, funktioniert der erste Schritt: der Strom für den Russound wird eingeschaltet und auch das Telegramm K4.NOTE2 kommt. Die Musik beginnt aber nicht zu spielen. Sie spielt erst, wenn ich diese (oder eine andere) Playliste noch ein zweites und drittes Mal am Tastsensor auswähle.

- Im Log bekomme ich hinsichtlich des Russound folgende Meldungen, die mir problematisch erscheinen:

TCP_Client_192.168.1.107:9621) receive in terminator mode calling data_received_callback <bound method Russound.found_terminator of <plugins.russound.Russound object at 0x7f6b88223b80>> failed: found_terminator() takes 2 positional arguments but 3 were given -- If stack trace is necessary, enable/check debug log
2023-01-14  19:28:09 ERROR    lib.network         lib.network (TCP_Client_192.168.1.107:9621) receive in terminator mode calling data_received_callback <bound method Russound.found_terminator of <plugins.russound.Russound object at 0x7f6b88223b80>> failed: found_terminator() takes 2 positional arguments but 3 were given -- If stack trace is necessary, enable/check debug log
2023-01-14  19:52:04 WARNING  plugins.mpd         zentral@: currentsong: no items to refresh
2023-01-14  19:52:04 WARNING  plugins.mpd         zentral@: statistic: no items to refresh
2023-01-14  19:53:35 ERROR    modules.admin.api_plugins _test_for_blog_articles: OSError HTTPSConnectionPool(host='www.smarthomeng.de', port=443): Max retries exceeded with url: /tag/knx (Caused by NewConnectionError('<urllib3.connection.HTTPSConnection object at 0x7f6b44727790>: Failed to establish a new connection: [Errno -3] Temporary failure in name resolution'))
2023-01-14  20:13:22 ERROR    lib.network         lib.network (TCP_Client_192.168.1.107:9621) receive thread died with unexpected error: [Errno 104] Connection reset by peer. Go tell... -- If stack trace is necessary, enable/check debug log
2023-01-14  20:26:28 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) detected disconnect, send failed.
2023-01-14  20:26:33 ERROR    lib.network         lib.network (TCP_Client_192.168.1.107:9621) receive in terminator mode calling data_received_callback <bound method Russound.found_terminator of <plugins.russound.Russound object at 0x7f6b88223b80>> failed: found_terminator() takes 2 positional arguments but 3 were given -- If stack trace is necessary, enable/check debug log
2023-01-14  20:26:33 ERROR    lib.network         lib.network (TCP_Client_192.168.1.107:9621) receive in terminator mode calling data_received_callback <bound method Russound.found_terminator of <plugins.russound.Russound object at 0x7f6b88223b80>> failed: found_terminator() takes 2 positional arguments but 3 were given -- If stack trace is necessary, enable/check debug log

Kann jemand etwas damit anfangen?

[Art Mooney]

Das scheint zu funktionieren.

[Art Mooney]

Das geht so nicht. Im Log bekomme ich:

"Hauptroutine der Logik, Exception: name 'activate' is not defined"

Habe hier einen Hinweis gefunden: https://www.smarthomeng.de/user/refe...functions.html

Also:

if sh.K4.STECK.SWIT2() == True:
    sh.plugins.return_plugin("russound").activate()
elif sh.K4.STECK.SWIT2() == False:
    sh.plugins.return_plugin("russound").suspend()

[Art Mooney]

OK, mmh. Ich bin mit der Syntax gar nicht vertraut. Also so? Ich probiere es aus.

if sh.K4.STECK.SWIT2() == True:
    activate()
elif sh.K4.STECK.SWIT2() == False:
    suspend()

[bmx]

Die Funktionen sollten über eine Logik aufgerufen werden können. Die Logik wird sinnigerweise von einem Item getriggert das den Status der Steckdose für das Russound Gerät darstellt. Also wenn Steckdose aus --> suspend() und wenn Steckdose an --> activate().

Ich kann es leider auch nicht so wirklich testen weil ich hier kein russound hat aber einen Versuch ist es Wert.

[Art Mooney]

Heute habe ich versucht, den develop-Branch der Plugins zu ziehen mit "git pull origin develop". Das scheint auch funktioniert zu haben.

bmx, es gibt jetzt die Plugin-Funktionen "suspend" und "activate". Mir ist allerdings nicht klar, wie ich diese Funktionen nutzen kann. Muss ich dafür ein Item anlegen? Wie müsste das aussehen?

Danke!

[Onkelandy]

Sorry, es müssen zwei \\ sein, dann sollte es klappen. Ich versuche es grad mit dem Beispiel von vorhin und aktualisiere den getesteten String in der Doku

[Art Mooney]

Update: den Output-Buffer im mpd hochzusetzen hat nichts genützt. Die Meldung im mpd.log, dass der Output-Buffer voll sei kam dennoch und führte zum Neustart von SHNG.

Ich installiere jetzt mal die develop-Version wie oben angeregt.

[Onkelandy]

Ein Querverweis wäre sicher clever.. Das betrifft aber wohl generell den ganzen Referenz-Teil. Vielleicht hat da Msinn eine Idee, evtl. auch automatisiert?

Ich hab mal kurz den Filter-Code angesehen und soweit ich das sehe, muss es wohl tatsächlich zwingend eine regex sein, ein einfacher Teil des Strings wird nicht gefunden. Ich hab das in der Doku angepasst und einen PR erstellt.

[Art Mooney]

Leider funktioniert der Filter so nicht. Ich bekomme folgende Rückmeldung

smarthome@smarthomeNG:~$ systemctl status smarthome.service
● smarthome.service - SmartHomeNG daemon
     Loaded: loaded (/lib/systemd/system/smarthome.service; enabled; vendor preset: enabled)
     Active: failed (Result: exit-code) since Sun 2022-10-02 22:20:59 CEST; 24s ago
    Process: 275555 ExecStart=/usr/bin/python3 /usr/local/smarthome/bin/smarthome.py (code=exited, status=1/FAILURE)
        CPU: 5.280s

Oct 02 22:20:59 smarthomeNG python3[275555]: while scanning a double-quoted scalar
Oct 02 22:20:59 smarthomeNG python3[275555]:   in "<unicode string>", line 7, column 14:
Oct 02 22:20:59 smarthomeNG python3[275555]:             msg: "(.*)\(TCP_Client_192\.168\.1\.1 ...
Oct 02 22:20:59 smarthomeNG python3[275555]:                  ^ (line: 7)
Oct 02 22:20:59 smarthomeNG python3[275555]: found unknown escape character '('
Oct 02 22:20:59 smarthomeNG python3[275555]:   in "<unicode string>", line 7, column 20:
Oct 02 22:20:59 smarthomeNG python3[275555]:             msg: "(.*)\(TCP_Client_192\.168\.1\.107\:96 ...
Oct 02 22:20:59 smarthomeNG python3[275555]:                        ^ (line: 7)
Oct 02 22:20:59 smarthomeNG python3[275555]: NOTE: Look for the error at the expected <block end>, near the second specified line number
Oct 02 22:20:59 smarthomeNG python3[275555]: ERROR: Invalid logging configuration in file 'logging.yaml'

Offenbar ist die Klammer das Problem?

[Art Mooney]

Onkelandy: danke für den viel besseren Link. Ich bin in der Doku hier gelandet. Dort steht "Diese Strings können Regular Expressions enthalten."

Offenbar gibt es in der Doku einen Bereich "Referenz" und einen zu "Konfiguration". Dein Link zum Bereich "Konfiguration" ist viel besser (da mit Beispielen) als das, was unter "Referenz" steht. Hier wäre ein Querverweis gut. Ich habe nicht mehr in anderen Kapiteln der Doku gesucht, weil ich dachte, die richtige Stelle gefunden zu haben.

[Onkelandy]

Ich behaupte es sollte so heißen..

"(.*)\\(TCP_Client_192\\.168\\.1\\.107:9621\\) TCP connection failed(.*)"

Siehe auch hier: https://www.smarthomeng.de/user/konf...practices.html

Kannst du bitte mal verlinken, wo was von "regex möglich" steht?

[Art Mooney]

bmx, danke für den Hinweis auf den develop branch. Ich schaue mir das an.

Einstweilen habe ich probiert, mir einen Logging-Filter zu schreiben, der mir die Russound-Meldungen aus dem Log nimmt. Leider ist mir die Syntax für den Filter überhaupt nicht klar. In der Doku steht, die Strings können (nicht müssen?) Regular Expressions enthalten. Ich lese mich schon seit einiger Zeit in Regular Expressions ein. Finde das aber recht kompliziert. Ich habe mich vor allem an diesem HOWTO orientiert: Link.

Ich möchte eigentlich nur die Logmeldungen rausfiltern, die vom Russound kommen, also von der richtigen IP. Der Ausdruck, der in den Logmeldungen des Russound immer vorkommt ist "(TCP_Client_192.168.1.107:9621) TCP connection failed".

Also habe ich folgendes in die logging.yaml geschrieben. Es funktioniert allerdings nicht. Metacharaktere außer "" sollten doch in dem Klammerausdruck egal sein, oder?

version: 1
disable_existing_loggers: False
formatters:
    shng_simple:
        format: '%(asctime)s %(levelname)-8s %(name)-19s %(message)s'
        datefmt: '%Y-%m-%d  %H:%M:%S'
    shng_detail:
        format: '%(asctime)s %(levelname)-8s %(module)-17s %(threadName)-12s %(message)s  --  (%(filename)s:%(funcName)s:%(lineno)d)'
        datefmt: '%Y-%m-%d %H:%M:%S %Z'
filters:
    russoundfilter:
        (): lib.logutils.Filter
        msg: [(TCP_Client_192.168.1.107:9621) TCP connection failed]            
handlers:
    console:
        class: logging.StreamHandler
        formatter: shng_detail
        stream: ext://sys.stdout
    shng_warnings_file:
        (): lib.log.ShngTimedRotatingFileHandler
        formatter: shng_simple
        level: WARNING
        when: midnight
        backupCount: 7
        filename: ./var/log/smarthome-warnings.log
        encoding: utf8
        filters: [russoundfilter]
    shng_details_file:
        (): lib.log.ShngTimedRotatingFileHandler
        formatter: shng_detail
        level: DEBUG
        when: midnight
        backupCount: 7
        filename: ./var/log/smarthome-details.log
        encoding: utf8
loggers:
    __main__:
        level: WARNING
        handlers: [shng_details_file]  
    plugins.knx:
        handlers: [shng_details_file]
        level: DEBUG
    
#  lib.scheduler:
#    level: DEBUG
#  plugins.cli:
#    level: DEBUG

root:
    level: WARNING
    handlers: [shng_warnings_file]

[bmx]

Art Mooney Es gibt im develop branch ein aktualisiertes mpd Plugin und auch ein aktualisiertes russound plugin. Beim russound habe ich zwei Funktionen hinzugefügt um den Netzwerkverkehr zur Russound zu unterbinden. Ein Item das z.B. den Netzschalter steuert kann eine Logik triggern und diese Funktionen dann aufrufen. Mangels Rusound kann ich das leider nicht testen aber wenn Du das mal ausprobieren würdest ...

[Art Mooney]

Hallo nochmal,

leider ist mein Problem noch nicht gelöst. Es fällt in der Tat auf, dass mpd einen Fehler meldet, wenn SHNG neu startet. Im mpd-Logfile steht folgendes:

Sep 22 22:11 : exception: error on client 85: Output buffer is full
Sep 22 22:11 : client: [85] closed
Sep 22 22:39 : client: [86] opened from 192.168.1.102:57678
Sep 24 11:51 : exception: error on client 86: Output buffer is full
Sep 24 11:51 : client: [86] closed
Sep 24 12:19 : client: [87] opened from 192.168.1.102:37498

Die Meldung um 11:51 am 24.9. ist zeitgleich mit folgender Meldung im SHNG-Log:

2022-09-24  11:51:56 ERROR    plugins.mpd_zentral.update_status Method plugins.mpd_zentral.update_status exception: [Errno 104] Connection reset by peer
> Traceback (most recent call last):
>   File "/usr/local/smarthome/lib/scheduler.py", line 657, in _task
>     obj()
>   File "/usr/local/smarthome/plugins/mpd/__init__.py", line 193, in update_status
>     self.update_statusitems(warn)
>   File "/usr/local/smarthome/plugins/mpd/__init__.py", line 212, in update_statusitems
>     status = self._send('status')
>   File "/usr/local/smarthome/plugins/mpd/__init__.py", line 522, in _send
>     self._client.send((command + '\n').encode())
>   File "/usr/local/smarthome/lib/network.py", line 687, in send
>     bytes_sent = self._socket.send(message)
> ConnectionResetError: [Errno 104] Connection reset by peer

Kurz danach (ca. 15 Minuten) kommt die bekannte Meldung "Needing more worker threads..."

Das war so am 24.9. - genau das gleiche passierte auch am 22.9. mit demselben zeitlichen Zusammenhang.

Ich setze jetzt mal den Output-Buffer in mpd.conf hoch, denn der soll ja angeblich voll sein.