fhempy: Skoda Connect

staeblvo · 11 November 2021, 20:27:58

hier das log, das wiederholt sich immer wieder so:

2021-11-11 20:24:52,585 - INFO     - websockets.server: server listening on 0.0.0.0:15733
2021-11-11 20:25:02,602 - INFO     - websockets.server: connection open
2021-11-11 20:25:02,606 - INFO     - fhempy.lib.fhem_pythonbinding: Incoming FHEM connection: 127.0.0.1
2021-11-11 20:25:27,388 - INFO     - fhempy.lib.fhem_pythonbinding: Starting fhempy...
2021-11-11 20:25:27,417 - INFO     - fhempy.lib.fhem_pythonbinding: Waiting for FHEM connection
2021-11-11 20:25:27,553 - WARNING  - asyncio: Executing <Task pending coro=<async_main() running at /opt/fhem/.local/lib/python3.7/site-packages/fhempy/lib/fhem_pythonbinding.py:531> wait_for=<_GatheringFuture pending cb=[<TaskWakeupMethWrapper object at 0x751584d0>()] created at /usr/local/lib/python3.7/asyncio/tasks.py:615> cb=[_run_until_complete_cb() at /usr/local/lib/python3.7/asyncio/base_events.py:158] created at /usr/local/lib/python3.7/asyncio/base_events.py:563> took 0.165 seconds
2021-11-11 20:25:27,557 - INFO     - websockets.server: server listening on 0.0.0.0:15733
2021-11-11 20:25:36,309 - INFO     - websockets.server: connection open
2021-11-11 20:25:36,314 - INFO     - fhempy.lib.fhem_pythonbinding: Incoming FHEM connection: 127.0.0.1

dominik · 11 November 2021, 20:34:22

Lösch Mal das Device, dann mach ein restart, warte bis in pybinding auf opened geht und dann mach das define. Poste dann bitte wieder das Log.

staeblvo · 11 November 2021, 20:43:07

Habe das define skodaconnect gelöscht, Fhem gestopt, den Raspi neugestartet und das define skodaconnect neu angelegt.
Das log sieht aber gleich aus:

Code Auswählen

2021-11-11 20:32:19,592 - INFO     - websockets.server: server listening on 0.0.0.0:15733
2021-11-11 20:32:28,624 - INFO     - websockets.server: connection open
2021-11-11 20:32:28,632 - INFO     - fhempy.lib.fhem_pythonbinding: Incoming FHEM connection: 127.0.0.1
2021-11-11 20:38:55,138 - INFO     - fhempy.lib.fhem_pythonbinding: Starting fhempy...
2021-11-11 20:38:55,176 - INFO     - fhempy.lib.fhem_pythonbinding: Waiting for FHEM connection
2021-11-11 20:38:55,362 - WARNING  - asyncio: Executing <Task pending coro=<async_main() running at /opt/fhem/.local/lib/python3.7/site-packages/fhempy/lib/fhem_pythonbinding.py:531> wait_for=<_GatheringFuture pending cb=[<TaskWakeupMethWrapper object at 0x7519c4d0>()] created at /usr/local/lib/python3.7/asyncio/tasks.py:615> cb=[_run_until_complete_cb() at /usr/local/lib/python3.7/asyncio/base_events.py:158] created at /usr/local/lib/python3.7/asyncio/base_events.py:563> took 0.224 seconds
2021-11-11 20:38:55,365 - INFO     - websockets.server: server listening on 0.0.0.0:15733
2021-11-11 20:39:11,501 - INFO     - websockets.server: connection open
2021-11-11 20:39:11,504 - INFO     - fhempy.lib.fhem_pythonbinding: Incoming FHEM connection: 127.0.0.1
2021-11-11 20:40:20,231 - INFO     - fhempy.lib.fhem_pythonbinding: Starting fhempy...
2021-11-11 20:40:20,260 - INFO     - fhempy.lib.fhem_pythonbinding: Waiting for FHEM connection
2021-11-11 20:40:20,396 - WARNING  - asyncio: Executing <Task pending coro=<async_main() running at /opt/fhem/.local/lib/python3.7/site-packages/fhempy/lib/fhem_pythonbinding.py:531> wait_for=<_GatheringFuture pending cb=[<TaskWakeupMethWrapper object at 0x7515d4b0>()] created at /usr/local/lib/python3.7/asyncio/tasks.py:615> cb=[_run_until_complete_cb() at /usr/local/lib/python3.7/asyncio/base_events.py:158] created at /usr/local/lib/python3.7/asyncio/base_events.py:563> took 0.165 seconds
2021-11-11 20:40:20,400 - INFO     - websockets.server: server listening on 0.0.0.0:15733
2021-11-11 20:40:29,846 - INFO     - websockets.server: connection open
2021-11-11 20:40:29,850 - INFO     - fhempy.lib.fhem_pythonbinding: Incoming FHEM connection: 127.0.0.1
2021-11-11 20:40:51,448 - INFO     - fhempy.lib.fhem_pythonbinding: Starting fhempy...
2021-11-11 20:40:51,477 - INFO     - fhempy.lib.fhem_pythonbinding: Waiting for FHEM connection
2021-11-11 20:40:51,612 - WARNING  - asyncio: Executing <Task pending coro=<async_main() running at /opt/fhem/.local/lib/python3.7/site-packages/fhempy/lib/fhem_pythonbinding.py:531> wait_for=<_GatheringFuture pending cb=[<TaskWakeupMethWrapper object at 0x751645b0>()] created at /usr/local/lib/python3.7/asyncio/tasks.py:615> cb=[_run_until_complete_cb() at /usr/local/lib/python3.7/asyncio/base_events.py:158] created at /usr/local/lib/python3.7/asyncio/base_events.py:563> took 0.164 seconds
2021-11-11 20:40:51,616 - INFO     - websockets.server: server listening on 0.0.0.0:15733

dominik · 11 November 2021, 20:45:43

Stell bitte beim Skoda Device auf verbose 5, hoffe dann ist mehr im Log.

staeblvo · 11 November 2021, 20:53:33

den verbose beim Skoda Device auf 5 zusetzen hat nicht gebracht, habe den level auch bei den anderen devices auf 5 gesetzt, vielleicht kannst Du da was erkennen:

Fhem.log

Code Auswählen

2021.11.11 20:48:45 4: http://127.0.0.1:15733/: HTTP response code 101
2021.11.11 20:48:45 5: HttpUtils http://127.0.0.1:15733/: Got data, length: 0
2021.11.11 20:48:45 5: HttpUtils response header:
HTTP/1.1 101 Switching Protocols
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Accept: RfOEdxmBcIk5a+RevnL2/BsC2NI=
Date: Thu, 11 Nov 2021 19:48:45 GMT
Server: Python/3.7 websockets/10.0
2021.11.11 20:48:45 4: BindingsIo (local_pybinding): start fhempyFunction: my_skoda => Define (50535480)
2021.11.11 20:48:45 4: BindingsIo (local_pybinding): <<< WS: {"args":["my_skoda","fhempy","skodaconnect","xxx@x.de","xxx","xxxx"],"defargsh":{},"argsh":{},"id":"50535480","FHEMPYTYPE":"skodaconnect","function":"Define","defargs":["my_skoda","fhempy","skodaconnect","xxx@x.de","xxx","xxxx"],"PYTHONTYPE":"skodaconnect","msgtype":"function","NAME":"my_skoda"}
2021.11.11 20:48:45 5: DevIo_SimpleWrite local_pybinding: 7b2261726773223a5b226d795f736b6f6461222c226668656d7079222c22736b6f6461636f6e6e656374222c22762e73746165626c65696e40676d782e6465222c22736b6175636f323121222c2230353239225d2c226465666172677368223a7b7d2c226172677368223a7b7d2c226964223a223530353335343830222c224648454d505954595045223a22736b6f6461636f6e6e656374222c2266756e6374696f6e223a22446566696e65222c2264656661726773223a5b226d795f736b6f6461222c226668656d7079222c22736b6f6461636f6e6e656374222c22762e73746165626c65696e40676d782e6465222c22736b6175636f323121222c2230353239225d2c22505954484f4e54595045223a22736b6f6461636f6e6e656374222c226d736774797065223a2266756e6374696f6e222c224e414d45223a226d795f736b6f6461227d
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): DevIo_SimpleRead
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): DevIo_SimpleRead WithTimeout
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): QUEUE: start handling - 0
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): QUEUE: finished handling - 0
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): DevIo_SimpleRead
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): DevIo_SimpleRead WithTimeout
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): QUEUE: start handling - 0
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): QUEUE: finished handling - 0
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): DevIo_SimpleRead
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): DevIo_SimpleRead WithTimeout
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): QUEUE: start handling - 0
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): QUEUE: finished handling - 0
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): DevIo_SimpleRead
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): DevIo_SimpleRead WithTimeout
2021.11.11 20:48:45 4: BindingsIo (local_pybinding): >>> WS: {"msgtype": "version", "version": "0.1.172"}
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): QUEUE: start handling - 1
2021.11.11 20:48:45 5: processMessage: {"msgtype": "version", "version": "0.1.172"}
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): QUEUE: finished handling - 0
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): DevIo_SimpleRead
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): DevIo_SimpleRead WithTimeout
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): QUEUE: start handling - 0
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): QUEUE: finished handling - 0
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): DevIo_SimpleRead
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): DevIo_SimpleRead WithTimeout
2021.11.11 20:48:45 4: BindingsIo (local_pybinding): >>> WS: {"args": ["my_skoda", "fhempy", "skodaconnect", "xxx@x.de", "xxx", "xxxx"], "defargsh": {}, "argsh": {}, "id": "50535480", "FHEMPYTYPE": "skodaconnect", "function": "Define", "defargs": ["my_skoda", "fhempy", "skodaconnect", "xxx@x.de", "xxx", "xxxx"], "PYTHONTYPE": "skodaconnect", "msgtype": "function", "NAME": "my_skoda", "finished": 1, "returnval": ""}
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): QUEUE: start handling - 1
2021.11.11 20:48:45 5: processMessage: {"args": ["my_skoda", "fhempy", "skodaconnect", "xxx@x.de", "xxx", "xxxx"], "defargsh": {}, "argsh": {}, "id": "50535480", "FHEMPYTYPE": "skodaconnect", "function": "Define", "defargs": ["my_skoda", "fhempy", "skodaconnect", "xxx@x.de", "xxx", "xxxx"], "PYTHONTYPE": "skodaconnect", "msgtype": "function", "NAME": "my_skoda", "finished": 1, "returnval": ""}
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): QUEUE: finished handling - 0
2021.11.11 20:48:45 4: BindingsIo (local_pybinding): end fhempyFunction: my_skoda => Define (50535480) - result: 
2021.11.11 20:48:45 1: ws:127.0.0.1:15733 reappeared (local_pybinding)
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): DevIo_SimpleRead
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): DevIo_SimpleRead NoTimeout
2021.11.11 20:48:45 5: BindingsIo (local_pybinding): DevIo_SimpleRead WithTimeout - connection seems to be closed
2021.11.11 20:48:45 1: ws:127.0.0.1:15733 disconnected, waiting to reappear (local_pybinding)
2021.11.11 20:48:45 3: fhempyserver_15733: read: end of file reached while sysread
2021.11.11 20:48:45 3: fhempyserver_15733: stopped
2021.11.11 20:48:45 4: fhempyserver_15733: last run duration was only 12 sec, restarting with delay
2021.11.11 20:48:45 5: HttpUtils url=http://127.0.0.1:15733/ NonBlocking via http
2021.11.11 20:48:45 4: IP: 127.0.0.1 -> 127.0.0.1
2021.11.11 20:48:45 4: HttpUtils: 127.0.0.1: Verbindungsaufbau abgelehnt (111)
2021.11.11 20:48:45 1: BindingsIo (local_pybinding): ERROR local_pybinding - error while connecting: 127.0.0.1: Verbindungsaufbau abgelehnt (111)
2021.11.11 20:49:00 5: HttpUtils url=http://127.0.0.1:15733/ NonBlocking via http
2021.11.11 20:49:00 4: IP: 127.0.0.1 -> 127.0.0.1
2021.11.11 20:49:00 4: HttpUtils: 127.0.0.1: Verbindungsaufbau abgelehnt (111)
2021.11.11 20:49:00 1: BindingsIo (local_pybinding): ERROR local_pybinding - error while connecting: 127.0.0.1: Verbindungsaufbau abgelehnt (111)
2021.11.11 20:49:05 5: fhempyserver_15733: using FHEM/bindings/python/bin/fhempy
2021.11.11 20:49:05 3: fhempyserver_15733: starting
2021.11.11 20:49:05 3: fhempyserver_15733: using logfile: ./log/fhempy-2021-11-11.log
2021.11.11 20:49:10 5: HttpUtils url=http://127.0.0.1:15733/ NonBlocking via http
2021.11.11 20:49:10 4: IP: 127.0.0.1 -> 127.0.0.1
2021.11.11 20:49:10 5: HttpUtils request header:
GET / HTTP/1.1
Host: 127.0.0.1:15733
User-Agent: fhem
Accept-Encoding: gzip,deflate
Upgrade: websocket
Sec-WebSocket-Key: xyhkeceJkN4rcC9iJ0dbeA==
Connection: Upgrade
Sec-WebSocket-Version: 13

dominik · 11 November 2021, 20:57:06

Bitte auch das fhempy Log nachdem du alles auf verbose 5 gestellt hast. Achte da bitte auch darauf, dass im Log keine Credentials ersichtlich sind.

staeblvo · 11 November 2021, 21:00:59

da steht leider nicht mehr drin, also ich oben schon gepostet habe.

Ich habe das Gefühl das das Device in fhem nicht "richtig" angelegt/ausgeführt wird.
z.b. beim attr room oder verbose ist keine dropdown Auswahl möglich, wie bei den anderen.

dominik · 11 November 2021, 21:16:33

Probier bitte statt Skodaconnect Mal das helloworld Modul.

staeblvo · 11 November 2021, 21:21:07

mit helloworld ist es das gleiche ... gleiche log Einträge und server offline

Was hat es mit dem Fehler 111 auf sich? Ist das ok?

Code Auswählen


BindingsIo (local_pybinding): ERROR local_pybinding - error while connecting: 127.0.0.1: Verbindungsaufbau abgelehnt (111)

dominik · 11 November 2021, 21:34:31

Naja, da ist fhempy weg, daher die Meldung.

Stoppe den fhempyServer in FHEM und starte fhempy über die Konsole.
sudo -u fhem bash
fhempy --local

Danach mach wieder das Define und schau ob fhempy auf der Console wirklich ohne Fehler stoppt.

staeblvo · 11 November 2021, 21:51:00

Ja dann kommt ein Speicherzugriffsfehler...
Kann man damit erkennen aus welcher Funktion heraus das passiert?

Code Auswählen

2021-11-11 21:48:29,922 - INFO     - websockets.server: server listening on 0.0.0.0:15733
2021-11-11 21:48:43,728 - INFO     - websockets.server: connection open
2021-11-11 21:48:43,733 - INFO     - fhempy.lib.fhem_pythonbinding: Incoming FHEM connection: 127.0.0.1
Speicherzugriffsfehler

dominik · 11 November 2021, 22:00:47

Welche Python Version nutzt du? Auf welchem System? Manuell oder per apt installiert?

staeblvo · 11 November 2021, 22:05:24

Python 3.7.3 manuell installiert und Raspbian stretch

dominik · 11 November 2021, 22:09:20

Ok, dann würde ich empfehlen auf Buster zu wechseln. Ich gehe davon aus, dass bei der manuellen Installation irgendwas schief gelaufen ist bzw. vielleicht eine Library fehlt.
Mach besser ein Buster Upgrade dann hast ein sauberes System, alles andere ist jetzt sonst gebastel und führt wahrscheinlich später zu weiteren Problemen.

staeblvo · 11 November 2021, 22:12:26

ok werde ich am WE machen.

Vielen Dank für Deine Unterstützung. Prima Arbeit.