alexa-fhem funktioniert nicht nach Umstellung von FHEM user

reibuehl · 21 Juni 2021, 08:20:55

Hallo,

mein FHEM lief - aus mir unerklärlichen, wahrscheinlich historischen Gründen - bisher unter dem root User. Das ist mir am Wochenende aufgefallen und ich hab dann einen User fhem angelegt, den per chown -R fhem:dialup zum Owner von /opt/fhem gemacht und per systemd service FHEM wieder gestartet.
Nach der Änderung funktioniert jetzt allerdings die Steuerung von Geräten per Alexa nicht mehr. Ich bekomme von Alexa immer nur die Meldung "das Gerät xyz reagiert nicht".

Die Prozesse für die Alexa Anbindung scheinen aber korrekt zu laufen:

Code Auswählen

fhem     31200     1  0 07:11 ?        00:00:01 /usr/bin/node ./cache/alexa-cookie/871refresh-cookie.js
fhem     32472     1  2 Jun19 ?        00:59:27 /usr/bin/perl fhem.pl fhem.cfg
fhem     32501 32472  0 Jun19 ?        00:00:19 node /usr/bin/alexa-fhem -c ./alexa-fhem.cfg
fhem     32502 32472  0 Jun19 ?        00:00:05 SignalMessenger_tx
fhem     32542 32501  0 Jun19 ?        00:00:00 /usr/bin/ssh -R 1234:127.0.0.1:34155 -oServerAliveInterval=90 -i /opt/fhem/.ssh/id_rsa -p 58824 fhem-va.fhem.de

An was könnte das liegen?

Gruß,
Reiner

MadMax-FHEM · 21 Juni 2021, 08:24:46

Was steht denn beim alexa-Device in fhem?

running und ssh connected?

Was steht im alexa-fhem Log?

Nutzt du den alexa-fhem Connector oder eine "alte"/"manuelle" Installation?

Vermutlich wurde alexa-fhem bislang ebenfalls unter root gestartet (selber User wie fhem).
Daher evtl. auch die ssh-Keys unter /root/.ssh die nicht mit denen unter /opt/fhem/.ssh (falls dort überhaupt welche sind) übereinstimmen...

Also etwas mehr Info, sonst wird es schwer...

Gruß, Joachim

reibuehl · 21 Juni 2021, 08:58:21

Hallo Joachim,

Im Alexa Device steht im Reading alexaFHEM.ProxyConnection "running; SSH connected". Im Verzeichnis /opt/fhem/.ssh liegen die Keys.

Ich hatte vor ein paar Jahren mal eine manuelle Installation, hab aber schon vor längerer Zeit auf die m.W.n. neue umgestellt.

Im alexa-fhem.log sehe ich keine Fehler oder Warnings, das sieht die ganze Zeit ungefähr so aus:

Code Auswählen

[21.6.2021, 08:00:17] [FHEM]     caching: CurrentPosition: Sonnenschutz (as string; from 'Sonnenschutz')
[21.6.2021, 08:00:17] [FHEM]     caching: TargetPosition: Sonnenschutz (as string; from 'Sonnenschutz')
  2021-06-21 08:00:18 caching: OG_KU_Rollladen-motor: stop:Sonnenschutz
[21.6.2021, 08:00:18] [FHEM]     caching: PositionState: STOPPED (as string; from 'stop:Sonnenschutz')
  2021-06-21 08:00:18 caching: OG_KU_Rollladen-pct: Sonnenschutz
[21.6.2021, 08:00:18] [FHEM]     caching: CurrentPosition: Sonnenschutz (as string; from 'Sonnenschutz')
[21.6.2021, 08:00:18] [FHEM]     caching: TargetPosition: Sonnenschutz (as string; from 'Sonnenschutz')
  2021-06-21 08:01:09 caching: OG_WZ_ThermostatDisplay_Climate-humidity: 54
[21.6.2021, 08:01:09] [FHEM]     caching: CurrentRelativeHumidity: 54 (as number; from '54')
  2021-06-21 08:01:26 caching: OG_AZ_ThermostatDisplay_Climate-humidity: 48
[21.6.2021, 08:01:26] [FHEM]     caching: CurrentRelativeHumidity: 48 (as number; from '48')
  2021-06-21 08:01:53 caching: OG_BD_ThermostatDisplay_Climate-humidity: 51
[21.6.2021, 08:01:53] [FHEM]     caching: CurrentRelativeHumidity: 51 (as number; from '51')
  2021-06-21 08:02:28 caching: OG_SZ_ThermostatDisplay_Climate-humidity: 52
[21.6.2021, 08:02:28] [FHEM]     caching: CurrentRelativeHumidity: 52 (as number; from '52')
  2021-06-21 08:03:26 caching: OG_WZ_ThermostatDisplay_Climate-measured-temp: 23.7
[21.6.2021, 08:03:26] [FHEM]     caching: CurrentTemperature: 23.7 (as number; from '23.7')
  2021-06-21 08:03:57 caching: OG_BD_ThermostatDisplay_Climate-humidity: 54
[21.6.2021, 08:03:57] [FHEM]     caching: CurrentRelativeHumidity: 54 (as number; from '54')
  2021-06-21 08:03:57 caching: OG_BD_ThermostatDisplay_Climate-measured-temp: 27.5
[21.6.2021, 08:03:57] [FHEM]     caching: CurrentTemperature: 27.5 (as number; from '27.5')
  2021-06-21 08:04:58 caching: OG_SZ_ThermostatDisplay_Climate-measured-temp: 24.8
[21.6.2021, 08:04:58] [FHEM]     caching: CurrentTemperature: 24.8 (as number; from '24.8')
  2021-06-21 08:06:50 caching: OG_BD_ThermostatDisplay_Climate-humidity: 51
[21.6.2021, 08:06:50] [FHEM]     caching: CurrentRelativeHumidity: 51 (as number; from '51')
  2021-06-21 08:06:50 caching: OG_BD_ThermostatDisplay_Climate-measured-temp: 27.4
[21.6.2021, 08:06:50] [FHEM]     caching: CurrentTemperature: 27.4 (as number; from '27.4')
  2021-06-21 08:07:13 caching: OG_SZ_ThermostatDisplay_Climate-humidity: 53
[21.6.2021, 08:07:13] [FHEM]     caching: CurrentRelativeHumidity: 53 (as number; from '53')
  2021-06-21 08:08:21 caching: OG_WZ_ThermostatDisplay_Climate-measured-temp: 23.8
[21.6.2021, 08:08:21] [FHEM]     caching: CurrentTemperature: 23.8 (as number; from '23.8')
  2021-06-21 08:09:28 caching: OG_BD_ThermostatDisplay_Climate-humidity: 50
[21.6.2021, 08:09:28] [FHEM]     caching: CurrentRelativeHumidity: 50 (as number; from '50')
  2021-06-21 08:10:58 caching: OG_WZ_ThermostatDisplay_Climate-humidity: 55
[21.6.2021, 08:10:58] [FHEM]     caching: CurrentRelativeHumidity: 55 (as number; from '55')
  2021-06-21 08:10:58 caching: OG_WZ_ThermostatDisplay_Climate-measured-temp: 23.9
[21.6.2021, 08:10:58] [FHEM]     caching: CurrentTemperature: 23.9 (as number; from '23.9')
  2021-06-21 08:11:20 caching: OG_KU_ThermostatDisplay_Climate-measured-temp: 25.5
[21.6.2021, 08:11:20] [FHEM]     caching: CurrentTemperature: 25.5 (as number; from '25.5')
  2021-06-21 08:11:24 caching: OG_AZ_ThermostatDisplay_Climate-measured-temp: 25.8
[21.6.2021, 08:11:24] [FHEM]     caching: CurrentTemperature: 25.8 (as number; from '25.8')
  2021-06-21 08:11:52 caching: OG_BD_ThermostatDisplay_Climate-measured-temp: 27.3
[21.6.2021, 08:11:52] [FHEM]     caching: CurrentTemperature: 27.3 (as number; from '27.3')
  2021-06-21 08:13:22 caching: OG_WZ_ThermostatDisplay_Climate-humidity: 54
[21.6.2021, 08:13:22] [FHEM]     caching: CurrentRelativeHumidity: 54 (as number; from '54')
  2021-06-21 08:13:33 caching: OG_AZ_ThermostatDisplay_Climate-humidity: 49
[21.6.2021, 08:13:33] [FHEM]     caching: CurrentRelativeHumidity: 49 (as number; from '49')
  2021-06-21 08:13:33 caching: OG_AZ_ThermostatDisplay_Climate-measured-temp: 25.7
[21.6.2021, 08:13:33] [FHEM]     caching: CurrentTemperature: 25.7 (as number; from '25.7')
  2021-06-21 08:14:02 caching: OG_BD_ThermostatDisplay_Climate-humidity: 49
[21.6.2021, 08:14:02] [FHEM]     caching: CurrentRelativeHumidity: 49 (as number; from '49')
  2021-06-21 08:14:04 caching: OG_KU_ThermostatDisplay_Climate-measured-temp: 25.4
[21.6.2021, 08:14:04] [FHEM]     caching: CurrentTemperature: 25.4 (as number; from '25.4')
  2021-06-21 08:14:41 caching: OG_SZ_ThermostatDisplay_Climate-humidity: 52
[21.6.2021, 08:14:41] [FHEM]     caching: CurrentRelativeHumidity: 52 (as number; from '52')
  2021-06-21 08:16:32 caching: OG_AZ_ThermostatDisplay_Climate-measured-temp: 25.8
[21.6.2021, 08:16:32] [FHEM]     caching: CurrentTemperature: 25.8 (as number; from '25.8')
  2021-06-21 08:17:01 caching: OG_BD_ThermostatDisplay_Climate-measured-temp: 27.2
[21.6.2021, 08:17:01] [FHEM]     caching: CurrentTemperature: 27.2 (as number; from '27.2')
  2021-06-21 08:22:07 caching: OG_SZ_ThermostatDisplay_Climate-measured-temp: 24.9
[21.6.2021, 08:22:07] [FHEM]     caching: CurrentTemperature: 24.9 (as number; from '24.9')
  2021-06-21 08:22:16 caching: OG_BD_ThermostatDisplay_Climate-measured-temp: 27.1
[21.6.2021, 08:22:16] [FHEM]     caching: CurrentTemperature: 27.1 (as number; from '27.1')
  2021-06-21 08:23:43 caching: OG_WZ_ThermostatDisplay_Climate-measured-temp: 23.8
[21.6.2021, 08:23:43] [FHEM]     caching: CurrentTemperature: 23.8 (as number; from '23.8')
  2021-06-21 08:24:02 caching: OG_AZ_ThermostatDisplay_Climate-humidity: 48
[21.6.2021, 08:24:02] [FHEM]     caching: CurrentRelativeHumidity: 48 (as number; from '48')
  2021-06-21 08:24:50 caching: OG_SZ_ThermostatDisplay_Climate-measured-temp: 24.8
[21.6.2021, 08:24:50] [FHEM]     caching: CurrentTemperature: 24.8 (as number; from '24.8')
  2021-06-21 08:26:34 caching: OG_BD_ThermostatDisplay_Climate-measured-temp: 27.0
[21.6.2021, 08:26:34] [FHEM]     caching: CurrentTemperature: 27 (as number; from '27.0')
  2021-06-21 08:28:54 caching: OG_AZ_ThermostatDisplay_Climate-humidity: 49
[21.6.2021, 08:28:54] [FHEM]     caching: CurrentRelativeHumidity: 49 (as number; from '49')
  2021-06-21 08:31:30 caching: OG_AZ_ThermostatDisplay_Climate-humidity: 48
[21.6.2021, 08:31:30] [FHEM]     caching: CurrentRelativeHumidity: 48 (as number; from '48')
  2021-06-21 08:33:52 caching: OG_AZ_ThermostatDisplay_Climate-measured-temp: 25.7
[21.6.2021, 08:33:52] [FHEM]     caching: CurrentTemperature: 25.7 (as number; from '25.7')
  2021-06-21 08:33:56 caching: OG_KU_ThermostatDisplay_Climate-measured-temp: 25.3
[21.6.2021, 08:33:56] [FHEM]     caching: CurrentTemperature: 25.3 (as number; from '25.3')
  2021-06-21 08:35:47 caching: OG_WZ_ThermostatDisplay_Climate-humidity: 55
[21.6.2021, 08:35:47] [FHEM]     caching: CurrentRelativeHumidity: 55 (as number; from '55')
  2021-06-21 08:35:59 caching: OG_AZ_ThermostatDisplay_Climate-humidity: 49
[21.6.2021, 08:35:59] [FHEM]     caching: CurrentRelativeHumidity: 49 (as number; from '49')
  2021-06-21 08:36:17 caching: OG_BD_ThermostatDisplay_Climate-measured-temp: 26.9
[21.6.2021, 08:36:17] [FHEM]     caching: CurrentTemperature: 26.9 (as number; from '26.9')
  2021-06-21 08:37:54 caching: OG_WZ_ThermostatDisplay_Climate-measured-temp: 23.7
[21.6.2021, 08:37:54] [FHEM]     caching: CurrentTemperature: 23.7 (as number; from '23.7')
  2021-06-21 08:38:56 caching: OG_AZ_ThermostatDisplay_Climate-humidity: 48
[21.6.2021, 08:38:56] [FHEM]     caching: CurrentRelativeHumidity: 48 (as number; from '48')
  2021-06-21 08:40:51 caching: OG_WZ_ThermostatDisplay_Climate-measured-temp: 23.8
[21.6.2021, 08:40:51] [FHEM]     caching: CurrentTemperature: 23.8 (as number; from '23.8')
  2021-06-21 08:41:39 caching: OG_AZ_ThermostatDisplay_Climate-humidity: 49
[21.6.2021, 08:41:39] [FHEM]     caching: CurrentRelativeHumidity: 49 (as number; from '49')
  2021-06-21 08:43:27 caching: OG_BD_ThermostatDisplay_Climate-measured-temp: 26.8
[21.6.2021, 08:43:27] [FHEM]     caching: CurrentTemperature: 26.8 (as number; from '26.8')
  2021-06-21 08:46:26 caching: OG_BD_ThermostatDisplay_Climate-humidity: 50
[21.6.2021, 08:46:26] [FHEM]     caching: CurrentRelativeHumidity: 50 (as number; from '50')
  2021-06-21 08:46:57 caching: OG_KU_ThermostatDisplay_Climate-humidity: 52

MadMax-FHEM · 21 Juni 2021, 09:03:19

Hm, eigenartig.

Dann muss evtl. mal gvzdus (https://forum.fhem.de/index.php?action=profile;u=23999) im Vereinsserver schauen...

Bzw. das hier schon mal "durchgearbeitet": https://wiki.fhem.de/wiki/FHEM_Connector_f%C3%BCr_Amazon_Alexa#M.C3.B6gliche_Probleme_und_L.C3.B6sungen

Was steht denn im alexa-Log, wenn du alexa-fhem neu startest?

Wäre interessant zu sehen, welche Version läuft und welche config.json verwendet wird etc.

Gruß, Joachim

reibuehl · 21 Juni 2021, 18:16:01

Hier der Logoutput bei einem Stop/Start:

Code Auswählen

[21.6.2021, 10:34:18] BearerToken '...B34E5' read from MyAlexa
[21.6.2021, 10:34:18] [FHEM] got .eventToken
[21.6.2021, 10:34:18] refreshing token
[21.6.2021, 10:34:18] 39_alexa.pm is new version: true
[21.6.2021, 10:34:18] sshautoconf: completed successfully
[21.6.2021, 10:34:18] *** SSH: proxy configuration set up done
[21.6.2021, 10:34:18] Reading alexaFHEM.ProxyConnection set to starting;; starting SSH
[21.6.2021, 10:34:18] [FHEM]   executing: http://127.0.0.1:8083/fhem?cmd=%7B%24defs%7BMyAlexa%7D-%3E%7B%22active%22%7D%20%3D%201%3B%3Bundef%7D%3Bsetreading%20MyAlexa%20alexaFHEM.ProxyConnection%20starting%3B%3B%20starting%20SSH%3B%7B%24defs%7BMyAlexa%7D-%3E%7B%22active%22%7D%20%3D%200%3B%3Bundef%7D&fwcsrf=csrf_154290242086328&XHR=1
[21.6.2021, 10:34:18] Starting SSH with -R 1234:127.0.0.1:42209 -oServerAliveInterval=90 -i /opt/fhem/.ssh/id_rsa -p 58824 fhem-va.fhem.de
[21.6.2021, 10:34:19] got fresh token
[21.6.2021, 10:34:19] Reading alexaFHEM.ProxyConnection set to running;; SSH connected
[21.6.2021, 10:34:19] [FHEM]   executing: http://127.0.0.1:8083/fhem?cmd=%7B%24defs%7BMyAlexa%7D-%3E%7B%22active%22%7D%20%3D%201%3B%3Bundef%7D%3Bsetreading%20MyAlexa%20alexaFHEM.ProxyConnection%20running%3B%3B%20SSH%20connected%3B%7B%24defs%7BMyAlexa%7D-%3E%7B%22active%22%7D%20%3D%200%3B%3Bundef%7D&fwcsrf=csrf_154290242086328&XHR=1
[21.6.2021, 10:34:19] *** SSH: proxy connection established
[21.6.2021, 10:34:19] SSH: Welcome at the reverse proxy!  This pseudoshell does not react to any input - do not get irritated.

Ich habe mal wie in https://wiki.fhem.de/wiki/FHEM_Connector_f%C3%BCr_Amazon_Alexa#M.C3.B6gliche_Probleme_und_L.C3.B6sungen beschrieben ein -D angehängt, sehe aber in alexa-2021-06-21.log keinen unterschied. Laut ps -ef läuft node alexa-fhem mit dem -D.
Logt das in ein anderes logfile?

Gruß,
Reiner

MadMax-FHEM · 21 Juni 2021, 18:29:24

An das Logfile solltest du über das alexa-Device kommen...

Und: es fehlt im Ausschnitt was ich wissen wollte:

alexa-fhem Version und welche config.json verwendet wird...
...das kann nicht der komplette Start sein...

Hast du auch mal deaktiviert und neu verbunden etc. also auch andere Dinge aus dem Link probiert?

Gruß, Joachim

reibuehl · 21 Juni 2021, 20:13:13

Sorry, ich hatte nur ein stop/start des Alexa Devices gemacht. Hab jetzt mal das ganze FHEM neu gestartet, da kommt tatsächlich deutlich mehr und wohl auch die Infos die noch gefehlt haben:

Code Auswählen

[21.6.2021, 20:06:42] using config from ./alexa-fhem.cfg
*** CONFIG: parsed completely
[21.6.2021, 20:06:42] os.homedir()=/opt/fhem
[21.6.2021, 20:06:42] this is alexa-fhem 0.5.55
[21.6.2021, 20:06:42] connecting to FHEM ...
[21.6.2021, 20:06:42] [FHEM] defaults to: will not send proactive events
[21.6.2021, 20:06:42] [FHEM] trying longpoll to listen for fhem events
[21.6.2021, 20:06:42] [FHEM] starting longpoll: http://127.0.0.1:8083/fhem?XHR=1&inform=type=status;addglobal=1;filter=.*;since=null;fmt=JSON&timestamp=1624298802339
[21.6.2021, 20:06:43] [FHEM] got csrfToken: csrf_68641283520554
[21.6.2021, 20:06:43] [FHEM] Checking devices and attributes...
[21.6.2021, 20:06:43] [FHEM]   executing: http://127.0.0.1:8083/fhem?cmd=%7BAttrVal(%22global%22%2C%22userattr%22%2C%22%22)%7D&fwcsrf=csrf_68641283520554&XHR=1
[21.6.2021, 20:06:43] [FHEM]   executing: http://127.0.0.1:8083/fhem?cmd=jsonlist2%20TYPE%3Dalexa&fwcsrf=csrf_68641283520554&XHR=1
[21.6.2021, 20:06:43] [FHEM] waiting for events ...
[21.6.2021, 20:06:43] [FHEM] Fetching FHEM devices...
[21.6.2021, 20:06:43] [FHEM] fetching: http://127.0.0.1:8083/fhem?cmd=jsonlist2%20alexaName=..*&fwcsrf=csrf_68641283520554&XHR=1
[21.6.2021, 20:06:45] [FHEM] alexa device is MyAlexa
[21.6.2021, 20:06:45] [FHEM] MyAlexa will not send proactive events
[21.6.2021, 20:06:45] [FHEM] MyAlexa uses ID: 5c59d121-f33f-3bc6-e9f7-09b5f6622070a078
[21.6.2021, 20:06:45] [FHEM]   executing: http://127.0.0.1:8083/fhem?cmd=%7B%24defs%7BMyAlexa%7D-%3E%7B%22active%22%7D%20%3D%201%3B%3Bundef%7D%3B%7B%24defs%7BMyAlexa%7D-%3E%7B%22alexa-fhem%20version%22%7D%20%3D%20%220.5.55%22%7D%3B%7B%24def
s%7BMyAlexa%7D-%3E%7B%22active%22%7D%20%3D%200%3B%3Bundef%7D&fwcsrf=csrf_68641283520554&XHR=1
[21.6.2021, 20:06:45] [FHEM]   executing: http://127.0.0.1:8083/fhem?cmd=%7B%24defs%7BMyAlexa%7D-%3E%7B%22active%22%7D%20%3D%201%3B%3Bundef%7D%3Bget%20MyAlexa%20proxyToken%3B%7B%24defs%7BMyAlexa%7D-%3E%7B%22active%22%7D%20%3D%200%3B%3Bundef
%7D&fwcsrf=csrf_68641283520554&XHR=1
[21.6.2021, 20:06:45] [FHEM]   executing: http://127.0.0.1:8083/fhem?cmd=%7B%24defs%7BMyAlexa%7D-%3E%7B%22active%22%7D%20%3D%201%3B%3Bundef%7D%3Blist%20MyAlexa%20.eventToken%3B%7B%24defs%7BMyAlexa%7D-%3E%7B%22active%22%7D%20%3D%200%3B%3Bund
ef%7D&fwcsrf=csrf_68641283520554&XHR=1
[21.6.2021, 20:06:45] Server listening on: http://127.0.0.1:40933 for proxy connections
[21.6.2021, 20:06:45] *** SSH: checking proxy configuration
[21.6.2021, 20:06:45] sshautoconf: home=/opt/fhem, spath=/opt/fhem/.alexa, cpath=./alexa-fhem.cfg, sshpath=/opt/fhem/.ssh
[21.6.2021, 20:06:45] Passed config: {"connections":[{"name":"FHEM","filter":"alexaName=..*","port":"8083","server":"127.0.0.1","uid":0,"webname":"fhem"}],"sshproxy":{"ssh":"/usr/bin/ssh","description":"FHEM Connector","options":["-i","/opt
/fhem/.ssh/id_rsa","-p",58824,"fhem-va.fhem.de"],"bind-ip":"127.0.0.1","port":40933}}
[21.6.2021, 20:06:45] sshautoconf: SSH key seems to exist
[21.6.2021, 20:06:45] sshautoconf: Our SSH key is known at the reverse proxy, good!
[21.6.2021, 20:06:45] [FHEM]   executing: http://127.0.0.1:8083/fhem?cmd=%7B%24defs%7BMyAlexa%7D-%3E%7B%22active%22%7D%20%3D%201%3B%3Bundef%7D%3Bjsonlist2%20MyAlexa%3B%7B%24defs%7BMyAlexa%7D-%3E%7B%22active%22%7D%20%3D%200%3B%3Bundef%7D&fwc
srf=csrf_68641283520554&XHR=1
*** FHEM: connected
[21.6.2021, 20:06:45] [FHEM] got: 27 results
[21.6.2021, 20:06:45] [FHEM] OG_AZ_Deckenlicht is light
[21.6.2021, 20:06:45] [FHEM] OG_AZ_Deckenlicht has
[21.6.2021, 20:06:45] [FHEM]   On [pct;on,off]
[21.6.2021, 20:06:45] [FHEM]   Brightness [pct]
[21.6.2021, 20:06:45] [FHEM] OG_AZ_Deckenlicht will not send proactive events
[21.6.2021, 20:06:45] [FHEM] OG_AZ_Deckenlicht uses ID: CUL_HM.526B0501
  2021-06-21 20:06:45 caching: OG_AZ_Deckenlicht-pct: 0
...

Neu Verbinden hab ich mich noch nicht getraut...

MadMax-FHEM · 21 Juni 2021, 20:17:11

Also ich kann nicht sehen woran es liegt...

So wie es aussieht nimmt er (nun) die config unter /opt/fhem

Evtl. wirklich mal gvzdus (https://forum.fhem.de/index.php?action=profile;u=23999) kontaktieren...

Einzig: es gibt schon was Aktuelleres von alexa-fhem

Gruß, Joachim