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

[Art Mooney]

Hallo zusammen,

derzeit bekomme ich im Log eine Vielzahl von Einträgen "ERROR modules.websocket update_item". Dieses Problem hatte ich zuvor schon einmal, es war aber nicht so schlimm. Das hat sich jetzt geändert, denn SHNG geht nun wegen zu vieler worker threads in den Neustart.

Da ich nicht weiß, was genau wichtig ist, poste ich hier einmal ein paar charakteristische Logeinträge. Der Log ist insgesamt extrem lang, weil immer wieder folgende Meldung kommt (geschätzt Hunderte davon):

2022-09-04  00:43:40 ERROR    modules.websocket   update_item - Error in 'await websocket.send(data)': received 1001 (going away) WebSocket is closed due to suspension.; then sent 1001 (going away) WebSocket is closed due to suspension.
> Traceback (most recent call last):
>   File "/usr/local/smarthome/modules/websocket/__init__.py", line 941, in update_item
>     await websocket.send(msg)
>   File "/home/smarthome/.local/lib/python3.7/site-packages/websockets/legacy/protocol.py", line 619, in send
>     await self.ensure_open()
>   File "/home/smarthome/.local/lib/python3.7/site-packages/websockets/legacy/protocol.py", line 920, in ensure_open
>     raise self.connection_closed_exc()
> websockets.exceptions.ConnectionClosedOK: received 1001 (going away) WebSocket is closed due to suspension.; then sent 1001 (going away) WebSocket is closed due to suspension.
2022-09-04  00:43:41 ERROR    modules.websocket   update_item - Error in 'await websocket.send(data)': received 1001 (going away) WebSocket is closed due to suspension.; then sent 1001 (going away) WebSocket is closed due to suspension.
> Traceback (most recent call last):
>   File "/usr/local/smarthome/modules/websocket/__init__.py", line 941, in update_item
>     await websocket.send(msg)
>   File "/home/smarthome/.local/lib/python3.7/site-packages/websockets/legacy/protocol.py", line 619, in send
>     await self.ensure_open()
>   File "/home/smarthome/.local/lib/python3.7/site-packages/websockets/legacy/protocol.py", line 920, in ensure_open
>     raise self.connection_closed_exc()
> websockets.exceptions.ConnectionClosedOK: received 1001 (going away) WebSocket is closed due to suspension.; then sent 1001 (going away) WebSocket is closed due to suspension.

Dann kommt irgendwann:

2022-09-04  00:44:11 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 20!  (30 worker threads active)
2022-09-04  00:44:11 WARNING  lib.scheduler       Worker-Threads: plugins.database.Remove old: 28, plugins.database.Buffer dump: 2
2022-09-04  00:44:11 WARNING  lib.smarthome.main  --------------------   SmartHomeNG restarting, initiated by SmartHomeNG (scheduler started too many worker threads (30))   --------------------
2022-09-04  00:44:39 WARNING  plugins.database    Skipping dump, since an other database operation running! Data is buffered and dumped later.

Zwischendurch kommt die Meldung vom database-Plugin "skipping dump" auch immer mal. Zudem die Meldung "Needing more worker threads".

Für die Übersichtlichkeit schreibe ich in einem neuen Post weiter.

[Art Mooney]

Es fällt noch auf, dass das Log zwischendurch für viele Stunden ruhig ist. Zum Beispiel war heute Nacht ein Neustart von SHNG um 0:45, dann bis 7:09 alles ruhig. Um 7:09 ging es wieder los, aber nur mit den Meldungen "ERROR modules.websocket update_item".

Das könnte daran liegen, dass "ERROR modules.websocket update_item" mit der Benutzung der VISU zu tun hat, die nachts niemand verwendet hat, richtig? Der Fehler mit den Worker Threads kam seit dem Neustart noch nicht wieder, "Skipping Dump" auch nicht.

Könnte das etwas mit dem database-Plugin zu tun haben? Ich errreiche das WebIF des Plugins komischerweise nicht.

Ich benutze das database-Plugin in der Version 1.5.15. Zudem nutze ich die Plugins avdevice, knx, mpd, russound und smartvisu.

Unter "Schedulers" sehe ich folgende Threads:

grafik.png


Zuletzt noch ein paar Versionsinfos:

SHNG-Version 1.8.2, Python 3.7.3, smartVISU 1.8.2

Danke Euch schon jetzt für Eure Hilfe!

[bmx]

Hm. smartVISU 1.8.2 glaube ich jetzt nicht wirklich...

SHNG 1.8.2 ist auch schon recht alt. Die von Dir beschriebenen Probleme sind IMHO in 1.9.2 bereits gefixt. Hat es einen bestimmten Grund, warum Du das bisher nicht aktualisiert hast?

[wvhn]

Das Thema wurde hier schon mehrfach diskutiert und kann nachgelesen werden. Bisher trat dies vor allem in Verbindung mit der Verwendung des status.log Widgets in smartVISU für eigene Logger in shNG auf.

Die beste Lösung ist sicherlich ein Update von shNG auf v1.9.2. Zusätzlich gibt es im Develop einen Fix für das Websocket-Modul. Das ist hier beschrieben.

Gruß
Wolfram

[Art Mooney]

Danke für die Antworten. Die Themen habe ich wohl gefunden, nur die Lösung war mir nicht klar. Wenn ein Update es tut, umso besser. Ich mache eigentlich nur Updates, wenn ich Probleme habe, denn sonst läuft SHNG bei mir im Hintergrund und tut, was es soll. Da ändere ich lieber nichts ohne Grund.

Ich mache jetzt das Update.

[Art Mooney]

Hallo nochmal,

nun habe ich das Update gemacht und zunächst dachte ich, das Problem sei weg. Jetzt bekomme ich aber wieder das Problem mit den Workerthreads und SHNG geht in den Neustart.

Zudem ist mein Log voll von Meldungen, wonach kein Kontakt zum Russound-Verstärker (192.168.1.107) aufgebaut werden kann. Das ist auch kein Wunder, denn er ist meist ohne Strom und daher offline. In der Vorversion kam diese Meldung auch dann und wann aber nicht wie jetzt ca. alle 8 Sekunden.

Ich post hier mal einen repräsentativen Ausschnitt aus dem Log:

2022-09-08  22:55:43 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 5/5 times, last error was: [Errno 113] No route to host
2022-09-08  22:56:04 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 20!  (29 worker threads active)
2022-09-08  22:56:21 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 1/5 times, last error was: [Errno 113] No route to host
2022-09-08  22:56:29 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 2/5 times, last error was: [Errno 113] No route to host
2022-09-08  22:56:37 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 3/5 times, last error was: [Errno 113] No route to host
2022-09-08  22:56:45 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 4/5 times, last error was: [Errno 113] No route to host
2022-09-08  22:56:53 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 5/5 times, last error was: [Errno 113] No route to host
2022-09-08  22:57:05 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 20!  (30 worker threads active)
2022-09-08  22:57:05 WARNING  lib.scheduler       Worker-Threads: plugins.mpd_zentral.update_status: 30
2022-09-08  22:57:05 NOTICE   lib.smarthome       --------------------   SmartHomeNG restarting, initiated by SmartHomeNG (scheduler started too many worker threads (30))   --------------------
2022-09-08  22:57:25 ERROR    lib.plugin          Plugin 'mpd' exception in stop() method: [Errno 107] Transport endpoint is not connected
> Traceback (most recent call last):
>   File "/usr/local/smarthome/lib/plugin.py", line 685, in stop
>     self.plugin.stop()
>   File "/usr/local/smarthome/plugins/mpd/__init__.py", line 148, in stop
>     self._client.close()
>   File "/usr/local/smarthome/lib/network.py", line 925, in close
>     self._socket.shutdown(socket.SHUT_RD)
> OSError: [Errno 107] Transport endpoint is not connected
2022-09-08  22:57:51 NOTICE   lib.smarthome       --------------------   Init SmartHomeNG v1.9.2-master (cc57a0ad)   --------------------
2022-09-08  22:57:51 NOTICE   lib.smarthome       Running in Python interpreter 'v3.9.2 final', from directory /usr/local/smarthome
2022-09-08  22:57:51 NOTICE   lib.smarthome        - on Linux-5.10.0-17-amd64-x86_64-with-glibc2.31 (pid=40667)
2022-09-08  22:57:51 NOTICE   lib.smarthome        - Loglevel NOTICE is set to value 31 because handler of root logger is set to level WARNING or higher  -  Set level of handler 'shng_warnings_file' to 'NOTICE'!

Können die Workerthreads mit dem Russound-Plugin zu tun haben?

Hier noch eine Auflistung der Threads:

grafik.png

Ideen?

wvhn, ich habe den Link auf den anderen Thread gelesen. Das scheint aber nicht (mehr) das Problem bei mir zu sein, oder?

[bmx]

Diese Worker Thread Problematik hat meist ihren Ursprung in umfangreichen Datenbankabfragen. Schau mal diesen Thread dazu an.

Das Russound Plugin verfügt aktuell über keine Ein/Aus Möglichkeit. Die Warnung kommt auch aus der lib.network diw vom Plugin genutzt wird.

Benutzt Du mpd?

[Art Mooney]

Danke. Ja, ich nutze mpd. Was könnte das Problem damit sein?

database_maxage nutze ich nicht. Trotzdem kann es an Datenbankvorgängen liegen. Verstehe ich richtig, dass also database-Vorgänge worker threads belegen? Wenn ich also ein Ereignis habe, das viele Updates in items bewirkt, die in die Datenbank geschrieben werden, kann das die Ursache sein. Ich habe bei einigen Logiken eine von der Wetterstation gesendete Uhrzeit als Trigger. Das werde ich mir anschauen.

Gibt es eine Möglichkeit, den TCP Connection failed Eintrag aus dem warnings log zu verbannen? So ist es arg unübesichtlich.

[bmx]

Danke. Ja, ich nutze mpd. Was könnte das Problem damit sein?

Nur das das einen Fehler wirft der nicht abgefangen wird. Könnte man mal im Plugin fixen.

Verstehe ich richtig, dass also database-Vorgänge worker threads belegen? Wenn ich also ein Ereignis habe, das viele Updates in items bewirkt, die in die Datenbank geschrieben werden, kann das die Ursache sein.

Eigentlich eher die Konstrukte, wo die Datenbank abgefragt wird, das reine Schreiben ist nicht so zeitaufwändig.
Und es gibt die SmartHomeNG eigenen Items wie z.B. env.core.memory die haben ein database_maxage gesetzt.

Gibt es eine Möglichkeit, den TCP Connection failed Eintrag aus dem warnings log zu verbannen? So ist es arg unübesichtlich.

Eventuell könnte man da einen Filter ins Log einbauen aber damit bin ich überfragt.

Ist das Russound Gerät denn an einer schaltbaren Steckdose? Ich meine das Plugin versucht ja immer wieder die Verbindung aufzubauen und wenn das Gerät nicht antworten kann weil es aus ist, dann ist das ja kontraproduktiv das Gerät immer wieder abzufragen.
Möglicherweise kann man das Plugin aufbohren und mit einem Item koppeln das den Versuch die Verbindung aufzubauen kontrollieren kann.

[Onkelandy]

Zu den logfiltern hab ich einiges in die doku geschrieben, gerne mal angucken

[Art Mooney]

Danke für Eure Beiträge.

Ich habe mir die Logs seit dem Update noch einmal näher angesehen. Es passierte dort fast nichts. Eigentlich kamen nur die Meldungen zum Russound, der über einen Schaltaktor stromlos geschaltet wird, wenn nicht benutzt. Zudem meldet sich mpd mit den zuvor schon gesehenen Logeinträgen. Die Meldung des database-Plugins "skipping dump" kommt nicht mehr.

Hier nochmal ein typischer Ausschnitt kurz vor Neustart:

2022-09-10  11:57:46 WARNING  lib.network         (TCP_Client_192.168.1.112:6600) unhandleded error on sending, cannot send data b'status\n'. Error: [Errno 104] Connection reset by peer
2022-09-10  11:57:46 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
2022-09-10  11:58:08 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 1/5 times, last error was: [Errno 113] No route to host
2022-09-10  11:58:16 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 2/5 times, last error was: [Errno 113] No route to host
2022-09-10  11:58:24 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 3/5 times, last error was: [Errno 113] [...]
No route to host
2022-09-10  12:12:38 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 4/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:12:46 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 5/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:13:20 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 20!  (20 worker threads active)
2022-09-10  12:13:24 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 1/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:13:32 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 2/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:13:40 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 3/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:13:48 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 4/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:13:56 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 5/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:14:21 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 20!  (21 worker threads active)
2022-09-10  12:14:34 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 1/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:14:42 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 2/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:14:50 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 3/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:14:59 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 4/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:15:07 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 5/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:15:22 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 20!  (22 worker threads active)
2022-09-10  12:15:45 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 1/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:15:53 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 2/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:16:01 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 3/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:16:09 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 4/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:16:17 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 5/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:16:24 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 20!  (23 worker threads active)
2022-09-10  12:16:55 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 1/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:17:03 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 2/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:17:11 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 3/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:17:19 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 4/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:17:25 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 20!  (24 worker threads active)
2022-09-10  12:17:28 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 5/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:18:06 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 1/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:18:14 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 2/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:18:22 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 3/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:18:26 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 20!  (25 worker threads active)
2022-09-10  12:18:30 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 4/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:18:38 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 5/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:19:16 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 1/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:19:24 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 2/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:19:27 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 20!  (26 worker threads active)
2022-09-10  12:19:32 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 3/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:19:40 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 4/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:19:49 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 5/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:20:27 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 1/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:20:28 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 20!  (27 worker threads active)
2022-09-10  12:20:35 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 2/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:20:43 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 3/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:20:51 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 4/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:20:59 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 5/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:21:29 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 20!  (28 worker threads active)
2022-09-10  12:21:37 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 1/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:21:45 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 2/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:21:53 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 3/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:22:01 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 4/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:22:10 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 5/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:22:31 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 20!  (29 worker threads active)
2022-09-10  12:22:48 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 1/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:22:56 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 2/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:23:04 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 3/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:23:12 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 4/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:23:20 WARNING  lib.network         (TCP_Client_192.168.1.107:9621) TCP connection failed 5/5 times, last error was: [Errno 113] No route to host
2022-09-10  12:23:32 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 20!  (30 worker threads active)
2022-09-10  12:23:32 WARNING  lib.scheduler       Worker-Threads: plugins.mpd_zentral.update_status: 30
2022-09-10  12:23:32 NOTICE   lib.smarthome       --------------------   SmartHomeNG restarting, initiated by SmartHomeNG (scheduler started too many worker threads (30))   --------------------
2022-09-10  12:23:54 ERROR    lib.plugin          Plugin 'mpd' exception in stop() method: [Errno 107] Transport endpoint is not connected
Traceback (most recent call last):
  File "/usr/local/smarthome/lib/plugin.py", line 685, in stop
    self.plugin.stop()
  File "/usr/local/smarthome/plugins/mpd/__init__.py", line 148, in stop
    self._client.close()
  File "/usr/local/smarthome/lib/network.py", line 925, in close
    self._socket.shutdown(socket.SHUT_RD)
OSError: [Errno 107] Transport endpoint is not connected
2022-09-10  12:24:17 NOTICE   lib.smarthome       --------------------   Init SmartHomeNG v1.9.2-master (cc57a0ad)   --------------------

So ging es mit ca. 1-2 Neustarts pro Tag, bis ich heute Mittag einmal den Russound gestartet habe. Seitdem sind die Russound-bezogenen Logeinträge weg und es gab auch keinen Neustart mehr, obwohl der Russound mittlerweile schon wieder seit ca. 14 Uhr keinen Strom hat. Ich beobachte das weiter.

[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.

[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]

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]

[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?