fhempy: googlecast

[caldir65]

Sehr gut, nach ein paar Sekunden, bis zu einer Minute, sollte das BindungsIo Device auf opened stehen. Dann kannst Googlecast anlegen.

Das wäre zu schön - aber leider passiert nichts ... - erst nach einem Neustart des Raspi bekam ich das "opened"...
Danke

Wenn ich das jetzt richtig verstanden habe, so könnte ich doch jeden Stream an ein Googlecast-fähiges Gerät schicken, oder bin ich an spotify gebunden? Bei uns soll für ein Device z.B. i.d.R. der Livestream von NDR2-Radio laufen ...

[a_quadrat]

Hallo Dominik,

ich habe Probleme mit dem Service fhempy - er lässt sich nicht starten.

Code Auswählen Erweitern



● fhempy.service - FHEM PythonBinding
     Loaded: loaded (/etc/systemd/system/fhempy.service; enabled; vendor preset: enabled)
     Active: failed (Result: exit-code) since Mon 2021-11-08 09:57:43 CET; 1s ago
    Process: 1614 ExecStart=/home/pi/.local/bin/fhempy (code=exited, status=217/USER)
   Main PID: 1614 (code=exited, status=217/USER)

Nov 08 09:57:43 homeserver systemd[1]: fhempy.service: Scheduled restart job, restart counter is at 5.
Nov 08 09:57:43 homeserver systemd[1]: Stopped FHEM PythonBinding.
Nov 08 09:57:43 homeserver systemd[1]: fhempy.service: Start request repeated too quickly.
Nov 08 09:57:43 homeserver systemd[1]: fhempy.service: Failed with result 'exit-code'.
Nov 08 09:57:43 homeserver systemd[1]: Failed to start FHEM PythonBinding.


Ich habe auch zwei LOG-Files, einmal fhempy-Date.log und PythonBinding-Date.log. Der fhempy.log ist leer.

Meine Definition in FHEM war auch anders, und zwar "define pythonbinding BindingsIo Python".

Hat sich hier was geändert? Habe ich was verpasst?


VG Andreas

Edit: ich sehe gerade, dass es für User pi ist, ich habe keinen User Pi. Wo finde ich die Datei, die geladen werden muss?

[caldir65]

Moin,

leider ist der fhempy-Server nur kurz gelaufen, dann hat es ihn leider beendet mit folgenden Logs:

Code Auswählen Erweitern

2021-11-07 20:00:04,400 - INFO     - websockets.server: connection open
2021-11-07 20:00:04,402 - INFO     - fhempy.lib.fhem_pythonbinding: Incoming FHEM connection: 127.0.0.1
2021-11-07 20:01:36,417 - INFO     - fhempy.lib.pkg_installer: Attempting install of pychromecast==9.3.1
2021-11-07 20:01:44,561 - INFO     - fhempy.lib.pkg_installer: Successfully installed pychromecast==9.3.1 update!
2021-11-07 20:01:44,569 - INFO     - fhempy.lib.pkg_installer: Attempting install of youtube_dl>=2021.06.06
2021-11-07 20:01:56,473 - INFO     - fhempy.lib.pkg_installer: Successfully installed youtube_dl>=2021.06.06 update!
2021-11-07 20:01:56,480 - INFO     - fhempy.lib.pkg_installer: Attempting install of spotipy==2.18.0
2021-11-07 20:02:03,921 - INFO     - fhempy.lib.pkg_installer: Successfully installed spotipy==2.18.0 update!
2021-11-07 20:14:37,550 - INFO     - fhempy.lib.pkg_installer: Attempting install of micloud
2021-11-07 20:14:46,701 - INFO     - fhempy.lib.pkg_installer: Successfully installed micloud update!
2021-11-07 20:20:09,282 - INFO     - fhempy.lib.pkg_installer: Attempting install of python-miio==0.5.8
2021-11-07 20:20:25,269 - INFO     - fhempy.lib.pkg_installer: Successfully installed python-miio==0.5.8 update!
2021-11-07 20:20:28,763 - ERROR    - roberta: Annotation is not class: typing.List
2021-11-07 20:20:28,773 - ERROR    - roberta: Annotation is not class: typing.List
2021-11-07 20:27:40,307 - ERROR    - asyncio: Task exception was never retrieved
future: <Task finished coro=<run_blocking() done, defined at /opt/fhem/.local/lib/python3.7/site-packages/fhempy/lib/utils.py:28> exception=RuntimeError("can't start new thread") created at /usr/lib/python3.7/asyncio/tasks.py:325>
source_traceback: Object created at (most recent call last):
  File "FHEM/bindings/python/bin/fhempy", line 113, in <module>
    fpb.run()
  File "/opt/fhem/.local/lib/python3.7/site-packages/fhempy/lib/fhem_pythonbinding.py", line 539, in run
    asyncio.get_event_loop().run_forever()
  File "/usr/lib/python3.7/asyncio/base_events.py", line 539, in run_forever
    self._run_once()
  File "/usr/lib/python3.7/asyncio/base_events.py", line 1767, in _run_once
    handle._run()
  File "/usr/lib/python3.7/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "/opt/fhem/.local/lib/python3.7/site-packages/fhempy/lib/googlecast/googlecast.py", line 150, in Define
    utils.run_blocking_task(functools.partial(self.startDiscovery))
  File "/opt/fhem/.local/lib/python3.7/site-packages/fhempy/lib/utils.py", line 37, in run_blocking_task
    return asyncio.create_task(run_blocking(function))
  File "/usr/lib/python3.7/asyncio/tasks.py", line 325, in create_task
    return loop.create_task(coro)
Traceback (most recent call last):
  File "/opt/fhem/.local/lib/python3.7/site-packages/fhempy/lib/utils.py", line 33, in run_blocking
    return await asyncio.get_event_loop().run_in_executor(pool, function)
  File "/usr/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/opt/fhem/.local/lib/python3.7/site-packages/fhempy/lib/googlecast/googlecast.py", line 580, in startDiscovery
    friendly_names=[self.hash["CASTNAME"]], zeroconf_instance=zc
  File "/opt/fhem/.local/lib/python3.7/site-packages/pychromecast/discovery.py", line 617, in discover_listed_chromecasts
    browser.start_discovery()
  File "/opt/fhem/.local/lib/python3.7/site-packages/pychromecast/discovery.py", line 499, in start_discovery
    self.zeroconf_listener,
  File "/opt/fhem/.local/lib/python3.7/site-packages/zeroconf/_services/browser.py", line 516, in __init__
    self.start()
  File "/opt/fhem/.local/lib/python3.7/site-packages/sentry_sdk/integrations/threading.py", line 54, in sentry_start
    return old_start(self, *a, **kw)  # type: ignore
  File "/usr/lib/python3.7/threading.py", line 847, in start
    _start_new_thread(self._bootstrap, ())
RuntimeError: can't start new thread
2021-11-07 20:27:54,518 - ERROR    - asyncio: Task exception was never retrieved
future: <Task finished coro=<run_blocking() done, defined at /opt/fhem/.local/lib/python3.7/site-packages/fhempy/lib/utils.py:28> exception=RuntimeError("can't start new thread") created at /usr/lib/python3.7/asyncio/tasks.py:325>
source_traceback: Object created at (most recent call last):
  File "FHEM/bindings/python/bin/fhempy", line 113, in <module>
    fpb.run()
  File "/opt/fhem/.local/lib/python3.7/site-packages/fhempy/lib/fhem_pythonbinding.py", line 539, in run
    asyncio.get_event_loop().run_forever()
  File "/usr/lib/python3.7/asyncio/base_events.py", line 539, in run_forever
    self._run_once()
  File "/usr/lib/python3.7/asyncio/base_events.py", line 1767, in _run_once
    handle._run()
  File "/usr/lib/python3.7/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "/opt/fhem/.local/lib/python3.7/site-packages/fhempy/lib/googlecast/googlecast.py", line 150, in Define
    utils.run_blocking_task(functools.partial(self.startDiscovery))
  File "/opt/fhem/.local/lib/python3.7/site-packages/fhempy/lib/utils.py", line 37, in run_blocking_task
    return asyncio.create_task(run_blocking(function))
  File "/usr/lib/python3.7/asyncio/tasks.py", line 325, in create_task
    return loop.create_task(coro)
Traceback (most recent call last):
  File "/opt/fhem/.local/lib/python3.7/site-packages/fhempy/lib/utils.py", line 33, in run_blocking
    return await asyncio.get_event_loop().run_in_executor(pool, function)
  File "/usr/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/opt/fhem/.local/lib/python3.7/site-packages/fhempy/lib/googlecast/googlecast.py", line 580, in startDiscovery
    friendly_names=[self.hash["CASTNAME"]], zeroconf_instance=zc
  File "/opt/fhem/.local/lib/python3.7/site-packages/pychromecast/discovery.py", line 617, in discover_listed_chromecasts
    browser.start_discovery()
  File "/opt/fhem/.local/lib/python3.7/site-packages/pychromecast/discovery.py", line 501, in start_discovery
    self.host_browser.start()
  File "/opt/fhem/.local/lib/python3.7/site-packages/sentry_sdk/integrations/threading.py", line 54, in sentry_start
    return old_start(self, *a, **kw)  # type: ignore
  File "/usr/lib/python3.7/threading.py", line 847, in start
    _start_new_thread(self._bootstrap, ())
RuntimeError: can't start new thread


Für die fragliche Zeit steht im fhemlog nicht wirklich interessantes:

Code Auswählen Erweitern

2021.11.07 20:14:37.276 3: fhempy v1.0.0 (xiaomi_tokens)
2021.11.07 20:20:09.001 3: fhempy v1.0.0 (miio)
2021.11.07 20:20:28.945 3: roberta: Batteriewarnung battery: 100

[dominik]

Hast du irgendein Spezialsystem oder RPi mit Raspbian? Tritt der Fehler nach einem Neustart auch reproduzierbar auf?

[a_quadrat]

Hallo Dominik,

gibt es eine Möglichkeit fhempy unter Ubuntu 20.04 einzurichten?

VG Andreas

[dominik]

Hi,

du musst die Datei mit dem User anpassen:
/etc/systemd/system/fhempy.service
Danach
sudo systemctl reload-daemon

Auf Ubuntu sollte es auch laufen. Einfach wie in der Anleitung Peers installieren.

[a_quadrat]

Danke, aber der Service startet nicht

Code Auswählen Erweitern

● fhempy.service - FHEM PythonBinding
     Loaded: loaded (/etc/systemd/system/fhempy.service; enabl>     Active: failed (Result: exit-code) since Mon 2021-11-08 2>    Process: 5045 ExecStart=/home/ahartmann/.local/bin/fhempy >   Main PID: 5045 (code=exited, status=203/EXEC)

Nov 08 22:52:14 homeserver systemd[1]: fhempy.service: Schedul>Nov 08 22:52:14 homeserver systemd[1]: Stopped FHEM PythonBind>Nov 08 22:52:14 homeserver systemd[1]: fhempy.service: Start r>Nov 08 22:52:14 homeserver systemd[1]: fhempy.service: Failed >Nov 08 22:52:14 homeserver systemd[1]: Failed to start FHEM Py>lines 1-11/11 (END)

der Pfad /home/ahartmann/.local/bin/ ist leer.

VG Andreas

[caldir65]

Hast du irgendein Spezialsystem oder RPi mit Raspbian? Tritt der Fehler nach einem Neustart auch reproduzierbar auf?

Moin,
nein, ist ein RaspiOS-lite, letztes reguläres Image, auf einer SSD, von der auch gebootet wird.. Einzig die dritte Partition, auf der fhem letztlich duch den Symlink residiert, ist abweichend.
---
Nachtrag: ich habe jetzt alles so umgemodelt, daß fhem jetzt regulär im physischen Ordner opt residiert. Nach dem Neustart bekam das Cast-Device direkt automatisch das GCast-Icon verpasst. Ob es jetzt stabil läuft, muß ich noch abwarten, ich bin jetzt erstmal ei e Weile unterwegs ...

[a_quadrat]

Hi,

der Service läuft jetzt, aber fhem verbindet sich noch nicht. Kann es sein, dass ich noch eine alte Version laufen habe? Im Log steht "address already in use"

Code Auswählen Erweitern


2021-11-09 10:36:05,807 - INFO     - fhempy.lib.fhem_pythonbinding: Starting fhempy...
2021-11-09 10:36:05,819 - INFO     - fhempy.lib.fhem_pythonbinding: Waiting for FHEM connection
Traceback (most recent call last):
  File "FHEM/bindings/python/bin/fhempy", line 121, in <module>
    fpb.run()
  File "/usr/local/lib/python3.8/dist-packages/fhempy/lib/fhem_pythonbinding.py", line 538, in run
    asyncio.get_event_loop().run_until_complete(async_main())
  File "/usr/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "/usr/local/lib/python3.8/dist-packages/fhempy/lib/fhem_pythonbinding.py", line 530, in async_main
    await websockets.serve(
  File "/usr/local/lib/python3.8/dist-packages/websockets/legacy/server.py", line 1042, in __await_impl__
    server = await self._create_server()
  File "/usr/lib/python3.8/asyncio/base_events.py", line 1463, in create_server
    raise OSError(err.errno, 'error while attempting '
OSError: [Errno 98] error while attempting to bind on address ('0.0.0.0', 15733): address already in use


VG Andreas

Edit: Es läuft wieder alles, die FHEM Module mussten noch aktualisiert werden.

[a_quadrat]

Hi,

ich habe noch eine Verständnisfrage. Wofür benötige ich den "fhempyserver_15733"? Der ist nämlich "rot" aber spotify und chromecast funktionieren.

VG Andreas

[dominik]

Danke, aber der Service startet nicht

Code Auswählen Erweitern

● fhempy.service - FHEM PythonBinding
     Loaded: loaded (/etc/systemd/system/fhempy.service; enabl>     Active: failed (Result: exit-code) since Mon 2021-11-08 2>    Process: 5045 ExecStart=/home/ahartmann/.local/bin/fhempy >   Main PID: 5045 (code=exited, status=203/EXEC)

Nov 08 22:52:14 homeserver systemd[1]: fhempy.service: Schedul>Nov 08 22:52:14 homeserver systemd[1]: Stopped FHEM PythonBind>Nov 08 22:52:14 homeserver systemd[1]: fhempy.service: Start r>Nov 08 22:52:14 homeserver systemd[1]: fhempy.service: Failed >Nov 08 22:52:14 homeserver systemd[1]: Failed to start FHEM Py>lines 1-11/11 (END)

der Pfad /home/ahartmann/.local/bin/ ist leer.

VG Andreas

Wenn das leer ist, dann hast du fhempy scheinbar nicht installiert. Nur um sicher zu gehen, wir reden von einem Peer und keiner Installation wo FHEM drauf läuft? Wenn dem so ist, dann mach nochmals die Installation wie hier beschrieben:
https://github.com/dominikkarall/fhempy#installation-short

[dominik]

Hi,

ich habe noch eine Verständnisfrage. Wofür benötige ich den "fhempyserver_15733"? Der ist nämlich "rot" aber spotify und chromecast funktionieren.

VG Andreas

Ich hätte noch alle Posts vorher lesen sollen vor meiner vorigen Antwort

Du hast fhempy 2x installierst. Nur dieses Kapitel ist für die Installation notwendig:
https://github.com/dominikkarall/fhempy#installation

NICHT dieses hier:
https://github.com/dominikkarall/fhempy#fhempy-peers-eg-extend-bluetooth-range
Das ist NUR für Peers wo kein FHEM läuft.

Daher mach bei dir mal als User pi:
sudo systemctl stop fhempy
sudo systemctl disable fhempy
sudo rm -f /etc/systemd/system/fhempy.service
sudo systemctl daemon-reload
pip3 uninstall fhempy

Danach wird fhempy durch fhempyserver_15733 gestartet.

[a_quadrat]

Hi,

danke für deine Antwort. Ich habe es korrigiert und jetzt wir der fhempyserver_15733 auch "grün".

Aber ich habe noch ein anderes Problem. Ich habe das PythonBinding Modul seit fast einem Jahr ohne Probleme am Laufen und nutze ausschließlich chromecast und spotify. Seit meinem letzten fhem update - ungefähr vor einer Woche, friert der Fhem Server regelmäßig ein und ist nicht mehr erreichbar.  Im Anhang sind einmal die Log Auszüge vom letzten Einfrieren.

fhem lod:

Code Auswählen Erweitern


2021.11.11 23:39:22 2: SN678X16TD event channel timeout, two keep alive messages missing
2021.11.11 23:39:26 2: TI9558X1DE event channel timeout, two keep alive messages missing
2021.11.11 23:40:42 2: HMCCURPCPROC: [d_rpcBidCos_RF : 1467] Sending data to FHEM failed 100 times. select found no reader
2021.11.11 23:40:54 1: BindingsIo (local_pybinding): ERROR: Timeout while waiting for function to finish (id: 23696355)
2021.11.11 23:40:54 1:   id =>  23696355
2021.11.11 23:40:54 1:   defargs =>  ARRAY(0x55f90f7b1e98)
2021.11.11 23:40:54 1:   function =>  Set
2021.11.11 23:40:54 1:   argsh =>  HASH(0x55f910096918)
2021.11.11 23:40:54 1:   FHEMPYTYPE =>  googlecast
2021.11.11 23:40:54 1:   PYTHONTYPE =>  googlecast
2021.11.11 23:40:54 1:   msgtype =>  function
2021.11.11 23:40:54 1:   args =>  ARRAY(0x55f9108cd530)
2021.11.11 23:40:54 1:   NAME =>  castdevice_Kueche
2021.11.11 23:40:54 1:   defargsh =>  HASH(0x55f90f77c468)
2021.11.11 23:40:54 2: di_schlafen_alles_aus: set castdevice_Kueche volume 40: continue
2021.11.11 23:42:08 1: HMCCU: [d_ccu : 1055] Graceful shutdown in 8 seconds
2021.11.11 23:42:08 1: HMCCURPCPROC: [d_rpcBidCos_Wired : 1055] Stopping RPC server CB2000178045178085
2021.11.11 23:42:08 1: HMCCURPCPROC: [d_rpcBidCos_Wired : 1055] Deregistering RPC server http://192.168.178.45:7410/fh2000 with ID CB2000178045178085 at http://192.168.178.85:2000
2021.11.11 23:42:08 1: HMCCURPCPROC: [d_rpcBidCos_Wired : 1055] Callback for RPC server CB2000178045178085 deregistered
2021.11.11 23:42:08 2: HMCCURPCPROC: [d_rpcBidCos_Wired : 1055] Sending signal INT to RPC server process CB2000178045178085 with PID=1463
2021.11.11 23:42:08 2: HMCCURPCPROC: [d_rpcBidCos_Wired : 1055] Cleaning up immediately
2021.11.11 23:42:08 1: HMCCURPCPROC: [d_rpcBidCos_Wired : 1055] Housekeeping called. Cleaning up RPC environment
2021.11.11 23:42:08 2: HMCCURPCPROC: [d_rpcBidCos_Wired : 1463] CB2000178045178085 received signal INT
2021.11.11 23:42:08 1: HMCCURPCPROC: [d_rpcBidCos_Wired : 1463] RPC server CB2000178045178085 stopped handling connections. PID=1463
2021.11.11 23:42:09 2: HMCCURPCPROC: [d_rpcBidCos_Wired : 1463] Number of I/O errors = 1
2021.11.11 23:42:10 2: HMCCURPCPROC: [d_rpcBidCos_Wired : 1055] RPC server process CB2000178045178085 deleted
2021.11.11 23:42:10 2: HMCCURPCPROC: [d_rpcBidCos_Wired : 1055] Stop I/O handling
2021.11.11 23:42:10 2: HMCCURPCPROC: [d_rpcBidCos_Wired : 1055] RPC server stopped. Cancel delayed shutdown.
2021.11.11 23:42:11 1: HMCCURPCPROC: [d_rpcBidCos_RF : 1055] Stopping RPC server CB2001178045178085
2021.11.11 23:42:11 1: HMCCURPCPROC: [d_rpcBidCos_RF : 1055] Deregistering RPC server http://192.168.178.45:7411/fh2001 with ID CB2001178045178085 at http://192.168.178.85:2001
2021.11.11 23:42:11 1: HMCCURPCPROC: [d_rpcBidCos_RF : 1055] Callback for RPC server CB2001178045178085 deregistered
2021.11.11 23:42:11 2: HMCCURPCPROC: [d_rpcBidCos_RF : 1055] Sending signal INT to RPC server process CB2001178045178085 with PID=1467
2021.11.11 23:42:11 2: HMCCURPCPROC: [d_rpcBidCos_RF : 1055] Cleaning up immediately
2021.11.11 23:42:11 1: HMCCURPCPROC: [d_rpcBidCos_RF : 1055] Housekeeping called. Cleaning up RPC environment
2021.11.11 23:42:11 2: HMCCURPCPROC: [d_rpcBidCos_RF : 1467] CB2001178045178085 received signal INT
2021.11.11 23:42:11 2: HMCCURPCPROC: [d_rpcBidCos_RF : 1467] CB2001178045178085 received signal INT
2021.11.11 23:42:11 1: HMCCURPCPROC: [d_rpcBidCos_RF : 1467] RPC server CB2001178045178085 stopped handling connections. PID=1467
2021.11.11 23:42:12 2: HMCCURPCPROC: [d_rpcBidCos_RF : 1467] Number of I/O errors = 181
2021.11.11 23:42:13 2: HMCCURPCPROC: [d_rpcBidCos_RF : 1055] RPC server process CB2001178045178085 deleted
2021.11.11 23:42:13 2: HMCCURPCPROC: [d_rpcBidCos_RF : 1055] Stop I/O handling
2021.11.11 23:42:13 2: HMCCURPCPROC: [d_rpcBidCos_RF : 1055] RPC server stopped. Cancel delayed shutdown.
2021.11.11 23:42:14 1: HMCCURPCPROC: [d_rpcHmIP_RF : 1055] Stopping RPC server CB2010178045178085
2021.11.11 23:42:14 1: HMCCURPCPROC: [d_rpcHmIP_RF : 1055] Deregistering RPC server http://192.168.178.45:7420/fh2010 with ID CB2010178045178085 at http://192.168.178.85:2010
2021.11.11 23:42:14 1: HMCCURPCPROC: [d_rpcHmIP_RF : 1055] Callback for RPC server CB2010178045178085 deregistered
2021.11.11 23:42:15 2: HMCCURPCPROC: [d_rpcHmIP_RF : 1055] Sending signal INT to RPC server process CB2010178045178085 with PID=1469
2021.11.11 23:42:15 2: HMCCURPCPROC: [d_rpcHmIP_RF : 1055] Cleaning up immediately
2021.11.11 23:42:15 1: HMCCURPCPROC: [d_rpcHmIP_RF : 1055] Housekeeping called. Cleaning up RPC environment
2021.11.11 23:42:15 2: HMCCURPCPROC: [d_rpcHmIP_RF : 1469] CB2010178045178085 received signal INT
2021.11.11 23:42:15 2: HMCCURPCPROC: [d_rpcHmIP_RF : 1469] CB2010178045178085 received signal INT
2021.11.11 23:42:15 1: HMCCURPCPROC: [d_rpcHmIP_RF : 1469] RPC server CB2010178045178085 stopped handling connections. PID=1469
2021.11.11 23:42:15 2: HMCCURPCPROC: [d_rpcHmIP_RF : 1469] Number of I/O errors = 0
2021.11.11 23:42:17 2: HMCCURPCPROC: [d_rpcHmIP_RF : 1055] RPC server process CB2010178045178085 deleted
2021.11.11 23:42:17 1: HMCCU: [d_ccu : 1055] All RPC servers inactive
2021.11.11 23:42:17 2: HMCCURPCPROC: [d_rpcHmIP_RF : 1055] Stop I/O handling
2021.11.11 23:42:17 2: HMCCURPCPROC: [d_rpcHmIP_RF : 1055] RPC server stopped. Cancel delayed shutdown.
2021.11.11 23:42:18 2: DbLog myDbLog - Last database write cycle due to shutdown ...
2021.11.11 23:42:18 2: DbLog myDbLog - no data for last database write cycle
2021.11.11 23:42:18 1: Server shutdown delayed due to d_rpcBidCos_RF,d_rpcBidCos_Wired,d_ccu,gassistant,d_rpcHmIP_RF,myDbLog for max 10 sec
2021.11.11 23:42:22 1: PERL WARNING: Unrecognized escape \d passed through at (eval 347704) line 1.
2021.11.11 23:42:22 1: ws:127.0.0.1:15733 disconnected, waiting to reappear (local_pybinding)
2021.11.11 23:42:22 1: PERL WARNING: Use of uninitialized value $dev1 in concatenation (.) or string at ./FHEM/99_myUtils.pm line 877.
2021.11.11 23:42:22 1: PERL WARNING: Unrecognized escape \d passed through at (eval 347712) line 1.
2021.11.11 23:42:22 2: mqtt2: No PINGRESP for last PINGREQ (at 2021-11-11 23:40:49), disconnecting
2021.11.11 23:42:22 1: 192.168.178.103:1883 disconnected, waiting to reappear (mqtt2)
2021.11.11 23:42:22 2: deCONZ: http request failed: connect to http://192.168.178.98:8080 timed out
2021.11.11 23:42:23 1: 192.168.178.45:1883 disconnected, waiting to reappear (MQTT)
2021.11.11 23:42:24 1: BindingsIo (local_pybinding): ERROR local_pybinding - error while connecting: 127.0.0.1: Connection refused (111)
2021.11.11 23:42:25 1: 192.168.178.45:1883 reappeared (MQTT)
2021.11.11 23:42:25 1: 192.168.178.103:1883 reappeared (mqtt2)
2021.11.11 23:42:36 0: Server shutdown


fhempy log:

Code Auswählen Erweitern


2021-11-11 23:29:26,487 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.104 seconds
2021-11-11 23:29:26,659 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.137 seconds
2021-11-11 23:29:59,080 - WARNING  - asyncio: Executing <Task finished name='Task-86650' coro=<_ServiceBrowserBase._async_start_query_sender() done, defined at /opt/fhem/.local/lib/python3.8/site-packages/zeroconf/_services/browser.py:448> result=None created at /opt/fhem/.local/lib/python3.8/site-packages/zeroconf/_services/browser.py:322> took 0.100 seconds
2021-11-11 23:29:59,184 - WARNING  - asyncio: Executing <Handle run_coroutine_threadsafe.<locals>.callback() at /usr/lib/python3.8/asyncio/tasks.py:920 created at /usr/lib/python3.8/asyncio/tasks.py:930> took 0.104 seconds
2021-11-11 23:30:14,082 - WARNING  - asyncio: Executing <Handle _ServiceBrowserBase._async_start() created at /opt/fhem/.local/lib/python3.8/site-packages/zeroconf/_services/browser.py:517> took 0.120 seconds
2021-11-11 23:30:26,942 - WARNING  - asyncio: Executing <TimerHandle when=16322.41960599111 _ServiceBrowserBase._async_send_ready_queries_schedule_next() created at /opt/fhem/.local/lib/python3.8/site-packages/zeroconf/_services/browser.py:485> took 0.115 seconds
2021-11-11 23:30:36,170 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.160 seconds
2021-11-11 23:30:59,229 - WARNING  - asyncio: Executing <Handle _ServiceBrowserBase._async_start() created at /opt/fhem/.local/lib/python3.8/site-packages/zeroconf/_services/browser.py:517> took 0.105 seconds
2021-11-11 23:30:59,441 - WARNING  - asyncio: Executing <Handle run_coroutine_threadsafe.<locals>.callback() at /usr/lib/python3.8/asyncio/tasks.py:920 created at /usr/lib/python3.8/asyncio/tasks.py:930> took 0.128 seconds
2021-11-11 23:30:59,580 - WARNING  - asyncio: Executing <Task finished name='Task-86682' coro=<_ServiceBrowserBase._async_start_query_sender() done, defined at /opt/fhem/.local/lib/python3.8/site-packages/zeroconf/_services/browser.py:448> result=None created at /opt/fhem/.local/lib/python3.8/site-packages/zeroconf/_services/browser.py:322> took 0.138 seconds
2021-11-11 23:31:09,077 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 1.874 seconds
2021-11-11 23:31:09,247 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.169 seconds
2021-11-11 23:31:09,613 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.298 seconds
2021-11-11 23:31:09,766 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.100 seconds
2021-11-11 23:31:10,120 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.353 seconds
2021-11-11 23:31:10,399 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.211 seconds
2021-11-11 23:31:10,592 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.148 seconds
2021-11-11 23:31:14,552 - WARNING  - asyncio: Executing <Handle _ServiceBrowserBase._async_start() created at /opt/fhem/.local/lib/python3.8/site-packages/zeroconf/_services/browser.py:517> took 0.193 seconds
2021-11-11 23:31:19,071 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.120 seconds
2021-11-11 23:31:26,262 - WARNING  - asyncio: Executing <TimerHandle when=16381.729079020015 _ServiceBrowserBase._async_send_ready_queries_schedule_next() created at /opt/fhem/.local/lib/python3.8/site-packages/zeroconf/_services/browser.py:485> took 0.127 seconds
2021-11-11 23:31:49,573 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.210 seconds
2021-11-11 23:31:59,637 - WARNING  - asyncio: Executing <Handle _ServiceBrowserBase._async_start() created at /opt/fhem/.local/lib/python3.8/site-packages/zeroconf/_services/browser.py:517> took 0.111 seconds
2021-11-11 23:32:03,264 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.127 seconds
2021-11-11 23:32:03,444 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.117 seconds
2021-11-11 23:32:04,478 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.140 seconds
2021-11-11 23:32:43,131 - WARNING  - asyncio: Executing <TimerHandle when=16458.604833483874 _ServiceBrowserBase._async_send_ready_queries_schedule_next() created at /opt/fhem/.local/lib/python3.8/site-packages/zeroconf/_services/browser.py:485> took 0.109 seconds
2021-11-11 23:32:47,917 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 4.767 seconds
2021-11-11 23:32:48,076 - WARNING  - asyncio: Executing <Handle _ServiceBrowserBase._async_start() created at /opt/fhem/.local/lib/python3.8/site-packages/zeroconf/_services/browser.py:517> took 0.157 seconds
2021-11-11 23:32:48,226 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.148 seconds
2021-11-11 23:32:48,612 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.126 seconds
2021-11-11 23:32:48,875 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.208 seconds
2021-11-11 23:32:49,190 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.217 seconds
2021-11-11 23:32:49,817 - WARNING  - asyncio: Executing <Handle run_coroutine_threadsafe.<locals>.callback() at /usr/lib/python3.8/asyncio/tasks.py:920 created at /usr/lib/python3.8/asyncio/tasks.py:930> took 0.144 seconds
2021-11-11 23:32:50,088 - WARNING  - asyncio: Executing <Handle run_coroutine_threadsafe.<locals>.callback() at /usr/lib/python3.8/asyncio/tasks.py:920 created at /usr/lib/python3.8/asyncio/tasks.py:930> took 0.114 seconds
2021-11-11 23:32:50,474 - WARNING  - asyncio: Executing <Handle run_coroutine_threadsafe.<locals>.callback() at /usr/lib/python3.8/asyncio/tasks.py:920 created at /usr/lib/python3.8/asyncio/tasks.py:930> took 0.123 seconds
2021-11-11 23:32:52,692 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.251 seconds
2021-11-11 23:33:04,333 - WARNING  - asyncio: Executing <TimerHandle when=16478.93461729158 _ServiceBrowserBase._async_send_ready_queries_schedule_next() created at /opt/fhem/.local/lib/python3.8/site-packages/zeroconf/_services/browser.py:485> took 0.905 seconds
2021-11-11 23:33:23,238 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 0.123 seconds
2021-11-11 23:34:06,188 - WARNING  - asyncio: Executing <Handle _SelectorDatagramTransport._read_ready() created at /usr/lib/python3.8/asyncio/selector_events.py:259> took 10.401 seconds
2021-11-11 23:42:25,227 - INFO     - fhempy.lib.fhem_pythonbinding: Starting fhempy...
2021-11-11 23:42:25,239 - INFO     - fhempy.lib.fhem_pythonbinding: Waiting for FHEM connection


Kannst du erkennen, woran es liegen kann, dass das System lahm gelegt ist.

VG Andreas

[michaelw]

Ich beobachte bei mir etwas ähnliches wie Andreas. Seit einem Update letzte Woche Samstag hing mein Fhem mehr als er lief. Bin mir nicht sicher, ob es am Python binding liegt, weil ich auch mit HMCCU rumgespielt habe. Ich habe kurz nach dem Fhem Update am letzten Samstag ein "set local_pybinding update" durchgeführt welches dann von 0.1.131 auf 0.1.172 aktualisiert hat. Fhem hing dann große Teile des Samstags und ich habe dann abends manuell über die Kommandozeile die Prozesse abgeschossen, die auf fhempy hindeuteten und dann fing sich Fhem auch wieder. Es war so, dass die Fhemoberfläche ungefähr 5 Minuten relativ flüssig lief und dann hing, wenn ich den kompletten Fhem durchgestartet habe. Ich habe dann kurzerhand mit "pip uninstall fhempy" und "pip3 install -I fhempy==0.1.131" die alte Version wieder hergestellt. Danach lief es wieder etwas besser, wobei ich mir nicht sicher war, dass es wirklich die Lösung war. Heute habe ich dann wieder ein Fhem Update durchgeführt. Wie ich festgestellt habe, hat sich dabei, ohne dass ich das manuell durchgeführt habe, auch das Python Binding wieder aktualisiert. Es war wieder der gleiche Effekt, dass nach dem Fhem Neustart (shutdown restart nach dem Update) erst alles vernünftig lief und es dann plötzlich wieder hing. Im Moment das Downgrade auf 0.1.131 wieder geholfen... (Die Version habe ich gewählt, weil sie vorher problemlos lief und ich bis jetzt noch nicht dazu gekommen war eine neuere, welche nicht die neueste ist, zu testen.) Logs kann ich aber leider keine liefern, weil nichts protokolliert worden ist.

[dominik]

Könnt ihr Mal ein paar Versionen dazwischen probieren um zu sehen wo der Bug entstanden ist?
Wäre super wenn du
0.1.150 (Mitte zwischen 172 und 131) testen könntest
- tritt es dort auch auf, dann 0.1.140 (Mitte zwischen 131 und 150)
- tritt es dort nicht auf, dann 0.1.160 (Mitte zwischen.172 und 150)
Usw.

So sollte sich der Fehler dann gut lokalisieren lassen, danke!