Ich hab ein seltsames Phänomen bei einem FHEMWEB-Gerät:
Es sind für das FHEMWEB nur Zugriffe auf bestimmte Geräte erlaubt (per allowed). Wenn ich einen Zugriff auf ein solches Gerät durchführe, dann klappt das auch erstmal. Jedoch hab ich von diesem Zeitpunkt an für ca. 60 Sekunden im Log Ausgaben dieser Art:
2018-02-28 15:04:49.578 co2mini sz_co2mini co2: 650
2018.02.28 15:04:49.578 3 : Forbidden device sz_co2mini for WEBApi_127.0.0.1_57308
Also für andere Geräte, die einfach Readings/Events liefern, die mit dem ursprünglichen Request aber gar nichts zu tun haben.
Für mich sieht es so aus, als würden für ca. 60 Sekunden alle weiteren Readings/Events irgendwie im "Kontext" dieses Webrequests passieren und es wird für alle Aktionen diese "allowed"-Prüfung durchgeführt.
Das sieht dann so aus (Eventmonitor + Log):
2018.02.28 15:04:25.870 4 : Connection accepted from WEBApi_127.0.0.1_57308
2018.02.28 15:04:25.871 4 : WEBApi_127.0.0.1_57308 GET /api?cmd=set%20env_presence%20transition%20leaving&fwcsrf=geheim&XHR=1; BUFLEN:0
2018.02.28 15:04:25.871 4 : authorize WEBApi/cmd/set: allowed_WEBApi returned dont care
2018.02.28 15:04:25.872 4 : authorize WEBApi/devicename/env_presence: allowed_WEBApi returned allowed
2018-02-28 15:04:25.877 statistics env_stats Updated stats for: env_presence
2018.02.28 15:04:25.878 3 : Forbidden device env_stats for WEBApi_127.0.0.1_57308
2018.02.28 15:04:25.878 4 : authorize WEBApi/devicename/env_stats: allowed_WEBApi returned prohibited
2018.02.28 15:04:25.882 3 : <EVENT> env_presence - transition: leaving
2018-02-28 15:04:25.885 DOIF sys_di_eventLog cmd_1
2018.02.28 15:04:25.885 3 : Forbidden device sys_di_eventLog for WEBApi_127.0.0.1_57308
2018.02.28 15:04:25.885 4 : authorize WEBApi/devicename/sys_di_eventLog: allowed_WEBApi returned prohibited
2018-02-28 15:04:25.892 dummy env_presence transition: leaving
2018.02.28 15:04:25.892 4 : authorize WEBApi/devicename/env_presence: allowed_WEBApi returned allowed
2018.02.28 15:04:25.893 4 : WEBApi: /api?cmd=set%20env_presence%20transition%20leaving&fwcsrf=EzpT2eKOM3&XHR=1 / RL:20 / text/plain; charset=UTF-8 / Content-Encoding: gzip /
2018.02.28 15:04:25.894 4 : Connection closed for WEBApi_127.0.0.1_57308: EOF
2018-02-28 15:04:32.778 EspLedController ku_lightLedCeil clockCurrentInterval: 19999
2018.02.28 15:04:32.778 3 : Forbidden device ku_lightLedCeil for WEBApi_127.0.0.1_57308
2018.02.28 15:04:32.779 4 : authorize WEBApi/devicename/ku_lightLedCeil: allowed_WEBApi returned prohibited
2018-02-28 15:04:46.073 dummy fl_airSensor airQuality: 476.749963113642
2018.02.28 15:04:46.073 3 : Forbidden device fl_airSensor for WEBApi_127.0.0.1_57308
2018.02.28 15:04:46.074 4 : authorize WEBApi/devicename/fl_airSensor: allowed_WEBApi returned prohibited
2018-02-28 15:04:46.645 SYSSTAT fl_benStats load: 0.13
2018-02-28 15:04:46.645 SYSSTAT fl_benStats numProcesses: 218
2018-02-28 15:04:46.645 SYSSTAT fl_benStats uptime: 14 days, 15:55:22.03
2018-02-28 15:04:46.645 SYSSTAT fl_benStats loadAvg: 3.25
2018.02.28 15:04:46.645 3 : Forbidden device fl_benStats for WEBApi_127.0.0.1_57308
2018.02.28 15:04:46.645 4 : authorize WEBApi/devicename/fl_benStats: allowed_WEBApi returned prohibited
2018-02-28 15:04:49.578 co2mini sz_co2mini co2: 650
2018.02.28 15:04:49.578 3 : Forbidden device sz_co2mini for WEBApi_127.0.0.1_57308
2018.02.28 15:04:49.579 4 : authorize WEBApi/devicename/sz_co2mini: allowed_WEBApi returned prohibited
2018-02-28 15:04:50.632 CUL_HM env_electricMeter_IEC_02 170525.9
2018.02.28 15:04:50.632 3 : Forbidden device env_electricMeter_IEC_02 for WEBApi_127.0.0.1_57308
2018.02.28 15:04:50.632 4 : authorize WEBApi/devicename/env_electricMeter_IEC_02: allowed_WEBApi returned prohibited
2018-02-28 15:04:58.546 FRITZBOX env_fritzbox box_rateDown: 13.124
2018-02-28 15:04:58.546 FRITZBOX env_fritzbox box_rateUp: 2.255
2018.02.28 15:04:58.546 4 : authorize WEBApi/devicename/env_fritzbox: allowed_WEBApi returned allowed
2018.02.28 15:04:58.546 4 : authorize WEBApi/devicename/env_fritzbox: allowed_WEBApi returned allowed
2018-02-28 15:05:02.792 EspLedController ku_lightLedCeil clockCurrentInterval: 19999
2018.02.28 15:05:02.792 3 : Forbidden device ku_lightLedCeil for WEBApi_127.0.0.1_57308
2018.02.28 15:05:02.793 4 : authorize WEBApi/devicename/ku_lightLedCeil: allowed_WEBApi returned prohibited
2018-02-28 15:05:08.874 CUL_HM ku_fridge pressure: 1010.4
2018.02.28 15:05:08.874 3 : Forbidden device ku_fridge for WEBApi_127.0.0.1_57308
2018.02.28 15:05:08.874 4 : authorize WEBApi/devicename/ku_fridge: allowed_WEBApi returned prohibited
2018-02-28 15:05:17.089 TRX_WEATHER wz_co2 co2: 318
2018-02-28 15:05:17.089 TRX_WEATHER wz_co2 CO2: 318
2018.02.28 15:05:17.089 3 : Forbidden device wz_co2 for WEBApi_127.0.0.1_57308
2018.02.28 15:05:17.090 4 : authorize WEBApi/devicename/wz_co2: allowed_WEBApi returned prohibited
<ab hier hören die Meldungen dann wieder auf>
2018-02-28 15:05:32.810 EspLedController ku_lightLedCeil clockCurrentInterval: 19999
2018-02-28 15:05:35.209 CUL_HM bd_hmRt measured-temp: 17.9
2018-02-28 15:05:45.612 statistics env_stats Updated stats for: env_thpl
2018-02-28 15:05:45.629 CUL_HM env_thpl humidity: 69
2018-02-28 15:05:45.629 CUL_HM env_thpl luminosity: 2579
2018-02-28 15:05:45.629 CUL_HM env_thpl pressure: 1014.2
2018-02-28 15:05:45.629 CUL_HM env_thpl temperature: -5.9
2018-02-28 15:05:48.556 statistics env_stats Updated stats for: env_gasMeter_Sen
2018-02-28 15:05:48.564 CUL_HM env_gasMeter_Sen gasCnt: 341.29
2018-02-28 15:05:48.564 CUL_HM env_gasMeter_Sen gasPower: 0.005
2018-02-28 15:05:48.564 CUL_HM env_gasMeter_Sen costPerHour: 0.00
list WEBApi
Internals:
CONNECTS 7
CSRFTOKEN geheim
DEF 8085 global
FD 25
NAME WEBApi
NR 546
NTFY_ORDER 50-WEBApi
PORT 8085
STATE Initialized
TYPE FHEMWEB
Attributes:
csrfToken geheim
group Schnittstellen
room System
verbose 5
webname api
list allowed_WEBApi
Internals:
NAME allowed_WEBApi
NR 547
STATE validFor:WEBApi
TYPE allowed
allowedCommands set
allowedDevices env_fritzbox,env_presence,wz_mode,sys_di_voiceCtrl,wz_lightSpot,env_guestWifi
validFor WEBApi
READINGS:
2018-02-27 18:17:07 state validFor:WEBApi
Attributes:
allowedCommands set
allowedDevices env_fritzbox,env_presence,wz_mode,sys_di_voiceCtrl,wz_lightSpot,env_guestWifi
room System
validFor WEBApi
Ist das ein Bug oder irgendwas was ich nicht verstehe? 8)
Das klingt nach Bug, ich kann es aber nicht nachvollziehen.
Kannst du bitte ein "attr global verbose 5" log zwischen dem "berechtigtem" Befehl und der ersten Falschmeldung hier anhaengen?
Na klar doch:
2018.02.28 22:15:41.113 4 : Connection accepted from WEBApi_127.0.0.1_37866
2018.02.28 22:15:41.114 4 : WEBApi_127.0.0.1_37866 GET /api?cmd=set%20env_presence%20transition%20arriving&fwcsrf=geheim&XHR=1; BUFLEN:0
2018.02.28 22:15:41.114 5 : Cmd: >set env_presence transition arriving<
2018.02.28 22:15:41.115 5 : Starting notify loop for env_presence, 1 event(s), first is transition: arriving
2018.02.28 22:15:41.115 5 : createNotifyHash
2018.02.28 22:15:41.117 5 : statistics env_stats: DoStatistics.432 Assigned reading 'energyCalc' from attribute 'deltaReadings' to statistic type 2.
2018.02.28 22:15:41.117 5 : statistics env_stats: DoStatistics.432 Assigned reading 'gasCntOverallWh' from attribute 'deltaReadings' to statistic type 2.
2018.02.28 22:15:41.117 5 : statistics env_stats: DoStatistics.432 Assigned reading 'homeDuration' from attribute 'deltaReadings' to statistic type 2.
2018.02.28 22:15:41.117 5 : statistics env_stats: DoStatistics.432 Assigned reading 'power' from attribute 'minAvgMaxReadings' to statistic type 5.
2018.02.28 22:15:41.118 5 : statistics env_stats: DoStatistics.432 Assigned reading 'measured-temp' from attribute 'minAvgMaxReadings' to statistic type 5.
2018.02.28 22:15:41.118 5 : statistics env_stats: DoStatistics.432 Assigned reading 'humidity' from attribute 'minAvgMaxReadings' to statistic type 5.
2018.02.28 22:15:41.118 5 : statistics env_stats: DoStatistics.432 Assigned reading 'luminosity' from attribute 'minAvgMaxReadings' to statistic type 5.
2018.02.28 22:15:41.118 5 : statistics env_stats: DoStatistics.432 Assigned reading 'temperature' from attribute 'minAvgMaxReadings' to statistic type 5.
2018.02.28 22:15:41.118 5 : statistics env_stats: DoStatistics.432 Assigned reading 'pressure' from attribute 'minAvgMaxReadings' to statistic type 5.
2018.02.28 22:15:41.118 5 : statistics env_stats: DoStatistics.432 Assigned reading 'gasPowerRealW' from attribute 'minAvgMaxReadings' to statistic type 5.
2018.02.28 22:15:41.118 4 : statistics env_stats: doStatisticDelta.689 Calculating delta statistics for 'env_presence:homeDuration = 806229.177064795'
2018.02.28 22:15:41.118 5 : statistics env_stats: doStatisticDelta.780 Set '.env_presence:homeDuration'='LastValue: 806229.177064795 ShowDate: 1 DecPlaces: 9'
2018.02.28 22:15:41.118 5 : statistics env_stats: doStatisticDelta.786 Set 'statHomeDuration'='Hour: 75.717656870 Day: 695.517755368 Month: 28073.032258196 Year: 59914.964674330'
2018.02.28 22:15:41.118 5 : statistics env_stats: storeSingularReadings.1075 Set statHomeDurationDay = 695.517755368
2018.02.28 22:15:41.119 5 : statistics env_stats: storeSingularReadings.1075 Set statHomeDurationMonth = 28073.032258196
2018.02.28 22:15:41.119 5 : statistics env_stats: storeSingularReadings.1075 Set statHomeDurationYear = 59914.964674330
2018.02.28 22:15:41.119 5 : Starting notify loop for env_stats, 1 event(s), first is Updated stats for: env_presence
2018.02.28 22:15:41.119 5 : statistics env_stats: Notify.259 Notifications of myself received.
2018.02.28 22:15:41.119 4 : DbLog benDbLog -> ################################################################
2018.02.28 22:15:41.119 4 : DbLog benDbLog -> ### start of new Logcycle ###
2018.02.28 22:15:41.119 4 : DbLog benDbLog -> ################################################################
2018.02.28 22:15:41.119 4 : DbLog benDbLog -> number of events received: 1 for device: env_stats
2018.02.28 22:15:41.119 4 : DbLog benDbLog -> check Device: env_stats , Event: state: Updated stats for: env_presence
2018.02.28 22:15:41.120 5 : AUTOREMOTE: Processing target: 'http://192.168.2.42:1817/,fl_tab2'
2018.02.28 22:15:41.120 5 : AUTOREMOTE: Using stateFilter: 'fl_tab2' for event: 'env_stats:Updated stats for: env_presence'
2018.02.28 22:15:41.120 5 : AUTOREMOTE: Event 'env_stats:Updated stats for: env_presence'
2018.02.28 22:15:41.120 5 : AUTOREMOTE: Event 'env_stats:Updated stats for: env_presence' not matching filter 'fl_tab2'
2018.02.28 22:15:41.120 5 : AUTOREMOTE: Processing target: 'http://192.168.2.231:1817/,sz_tabS:.*,sz_tabS_pres'
2018.02.28 22:15:41.120 5 : AUTOREMOTE: Using stateFilter: 'sz_tabS:.*' for event: 'env_stats:Updated stats for: env_presence'
2018.02.28 22:15:41.120 5 : AUTOREMOTE: Event 'env_stats:Updated stats for: env_presence'
2018.02.28 22:15:41.120 5 : AUTOREMOTE: Event 'env_stats:Updated stats for: env_presence' not matching filter 'sz_tabS:.*'
2018.02.28 22:15:41.120 5 : AUTOREMOTE: Processing target: 'http://192.168.2.28:1817/,sz_z1:.*,sz_z1_pres'
2018.02.28 22:15:41.120 5 : AUTOREMOTE: Using stateFilter: 'sz_z1:.*' for event: 'env_stats:Updated stats for: env_presence'
2018.02.28 22:15:41.120 5 : AUTOREMOTE: Event 'env_stats:Updated stats for: env_presence'
2018.02.28 22:15:41.120 5 : AUTOREMOTE: Event 'env_stats:Updated stats for: env_presence' not matching filter 'sz_z1:.*'
2018.02.28 22:15:41.120 5 : AUTOREMOTE: Processing target: zzz,sz_s8:.*,sz_s8_pres'
2018.02.28 22:15:41.120 5 : AUTOREMOTE: Using stateFilter: 'sz_s8:.*' for event: 'env_stats:Updated stats for: env_presence'
2018.02.28 22:15:41.121 5 : AUTOREMOTE: Event 'env_stats:Updated stats for: env_presence'
2018.02.28 22:15:41.121 5 : AUTOREMOTE: Event 'env_stats:Updated stats for: env_presence' not matching filter 'sz_s8:.*'
2018-02-28 22:15:41.122 statistics env_stats Updated stats for: env_presence
2018.02.28 22:15:41.122 3 : Forbidden device env_stats for WEBApi_127.0.0.1_37866
2018.02.28 22:15:41.122 4 : Forbidden device env_stats
2018.02.28 22:15:41.122 5 : End notify loop for env_stats
2018.02.28 22:15:41.122 5 : statistics env_stats: Notify.282 Notification of 'env_presence' received. Update statistics.
Sorry, reicht mir nicht.
Ich habe jetzt in allowed.pm bei (eigenem) verbose=5 ein stacktrace eingebaut, kannst du bitte noch einen Versuch damit machen?
Kein Problem:
2018.03.01 08:56:13.748 4 : Connection accepted from WEBApi_127.0.0.1_37270
2018.03.01 08:56:13.749 4 : WEBApi_127.0.0.1_37270 GET /api?cmd=set%20env_presence%20transition%20leaving&fwcsrf=geheim&XHR=1; BUFLEN:0
2018.03.01 08:56:13.750 5 : Cmd: >set env_presence transition leaving<
2018.03.01 08:56:13.752 5 : Starting notify loop for env_presence, 1 event(s), first is transition: leaving
2018.03.01 08:56:13.752 5 : createNotifyHash
2018.03.01 08:56:13.757 5 : statistics env_stats: DoStatistics.432 Assigned reading 'energyCalc' from attribute 'deltaReadings' to statistic type 2.
2018.03.01 08:56:13.758 5 : statistics env_stats: DoStatistics.432 Assigned reading 'gasCntOverallWh' from attribute 'deltaReadings' to statistic type 2.
2018.03.01 08:56:13.758 5 : statistics env_stats: DoStatistics.432 Assigned reading 'homeDuration' from attribute 'deltaReadings' to statistic type 2.
2018.03.01 08:56:13.758 5 : statistics env_stats: DoStatistics.432 Assigned reading 'power' from attribute 'minAvgMaxReadings' to statistic type 5.
2018.03.01 08:56:13.758 5 : statistics env_stats: DoStatistics.432 Assigned reading 'measured-temp' from attribute 'minAvgMaxReadings' to statistic type 5.
2018.03.01 08:56:13.758 5 : statistics env_stats: DoStatistics.432 Assigned reading 'humidity' from attribute 'minAvgMaxReadings' to statistic type 5.
2018.03.01 08:56:13.758 5 : statistics env_stats: DoStatistics.432 Assigned reading 'luminosity' from attribute 'minAvgMaxReadings' to statistic type 5.
2018.03.01 08:56:13.758 5 : statistics env_stats: DoStatistics.432 Assigned reading 'temperature' from attribute 'minAvgMaxReadings' to statistic type 5.
2018.03.01 08:56:13.758 5 : statistics env_stats: DoStatistics.432 Assigned reading 'pressure' from attribute 'minAvgMaxReadings' to statistic type 5.
2018.03.01 08:56:13.758 5 : statistics env_stats: DoStatistics.432 Assigned reading 'gasPowerRealW' from attribute 'minAvgMaxReadings' to statistic type 5.
2018.03.01 08:56:13.758 4 : statistics env_stats: doStatisticDelta.689 Calculating delta statistics for 'env_presence:homeDuration = 806860.00607829'
2018.03.01 08:56:13.759 5 : statistics env_stats: doStatisticDelta.780 Set '.env_presence:homeDuration'='LastValue: 806860.00607829 ShowDate: 1 DecPlaces: 9'
2018.03.01 08:56:13.759 5 : statistics env_stats: doStatisticDelta.786 Set 'statHomeDuration'='Hour: 50.193551016 Day: 557.385701764 Month: 557.385701764 Year: 60545.793687825'
2018.03.01 08:56:13.759 5 : statistics env_stats: storeSingularReadings.1075 Set statHomeDurationDay = 557.385701764
2018.03.01 08:56:13.759 5 : statistics env_stats: storeSingularReadings.1075 Set statHomeDurationMonth = 557.385701764
2018.03.01 08:56:13.759 5 : statistics env_stats: storeSingularReadings.1075 Set statHomeDurationYear = 60545.793687825
2018.03.01 08:56:13.759 5 : Starting notify loop for env_stats, 1 event(s), first is Updated stats for: env_presence
2018.03.01 08:56:13.760 5 : statistics env_stats: Notify.259 Notifications of myself received.
2018.03.01 08:56:13.760 4 : DbLog benDbLog -> ################################################################
2018.03.01 08:56:13.760 4 : DbLog benDbLog -> ### start of new Logcycle ###
2018.03.01 08:56:13.760 4 : DbLog benDbLog -> ################################################################
2018.03.01 08:56:13.760 4 : DbLog benDbLog -> number of events received: 1 for device: env_stats
2018.03.01 08:56:13.760 4 : DbLog benDbLog -> check Device: env_stats , Event: state: Updated stats for: env_presence
2018.03.01 08:56:13.761 5 : AUTOREMOTE: Processing target: 'http://192.168.2.42:1817/,fl_tab2'
2018.03.01 08:56:13.761 5 : AUTOREMOTE: Using stateFilter: 'fl_tab2' for event: 'env_stats:Updated stats for: env_presence'
2018.03.01 08:56:13.761 5 : AUTOREMOTE: Event 'env_stats:Updated stats for: env_presence'
2018.03.01 08:56:13.761 5 : AUTOREMOTE: Event 'env_stats:Updated stats for: env_presence' not matching filter 'fl_tab2'
2018.03.01 08:56:13.761 5 : AUTOREMOTE: Processing target: 'http://192.168.2.231:1817/,sz_tabS:.*,sz_tabS_pres'
2018.03.01 08:56:13.761 5 : AUTOREMOTE: Using stateFilter: 'sz_tabS:.*' for event: 'env_stats:Updated stats for: env_presence'
2018.03.01 08:56:13.761 5 : AUTOREMOTE: Event 'env_stats:Updated stats for: env_presence'
2018.03.01 08:56:13.761 5 : AUTOREMOTE: Event 'env_stats:Updated stats for: env_presence' not matching filter 'sz_tabS:.*'
2018.03.01 08:56:13.761 5 : AUTOREMOTE: Processing target: 'http://192.168.2.28:1817/,sz_z1:.*,sz_z1_pres'
2018.03.01 08:56:13.761 5 : AUTOREMOTE: Using stateFilter: 'sz_z1:.*' for event: 'env_stats:Updated stats for: env_presence'
2018.03.01 08:56:13.761 5 : AUTOREMOTE: Event 'env_stats:Updated stats for: env_presence'
2018.03.01 08:56:13.761 5 : AUTOREMOTE: Event 'env_stats:Updated stats for: env_presence' not matching filter 'sz_z1:.*'
2018.03.01 08:56:13.761 5 : AUTOREMOTE: Processing target: 'zzz,sz_s8:.*,sz_s8_pres'
2018.03.01 08:56:13.762 5 : AUTOREMOTE: Using stateFilter: 'sz_s8:.*' for event: 'env_stats:Updated stats for: env_presence'
2018.03.01 08:56:13.762 5 : AUTOREMOTE: Event 'env_stats:Updated stats for: env_presence'
2018.03.01 08:56:13.762 5 : AUTOREMOTE: Event 'env_stats:Updated stats for: env_presence' not matching filter 'sz_s8:.*'
2018-03-01 08:56:13.764 statistics env_stats Updated stats for: env_presence
2018.03.01 08:56:13.764 3 : Forbidden device env_stats for WEBApi_127.0.0.1_37270
2018.03.01 08:56:13.764 1 : stacktrace:
2018.03.01 08:56:13.764 1 : main::allowed_Authorize called by fhem.pl (3528)
2018.03.01 08:56:13.764 1 : main::CallFn called by fhem.pl (5097)
2018.03.01 08:56:13.764 1 : main::Authorized called by fhem.pl (1186)
2018.03.01 08:56:13.764 1 : main::devspec2array called by fhem.pl (1788)
2018.03.01 08:56:13.764 1 : main::CommandSet called by fhem.pl (2561)
2018.03.01 08:56:13.764 1 : main::getAllSets called by ./FHEM/01_FHEMWEB.pm (2997)
2018.03.01 08:56:13.764 1 : main::FW_devState called by ./FHEM/01_FHEMWEB.pm (2897)
2018.03.01 08:56:13.764 1 : main::FW_Notify called by fhem.pl (3528)
2018.03.01 08:56:13.764 1 : main::CallFn called by fhem.pl (3448)
2018.03.01 08:56:13.764 1 : main::DoTrigger called by fhem.pl (4438)
2018.03.01 08:56:13.764 1 : main::readingsEndUpdate called by fhem.pl (4620)
2018.03.01 08:56:13.764 1 : main::readingsSingleUpdate called by ./FHEM/98_statistics.pm (471)
2018.03.01 08:56:13.764 1 : main::statistics_DoStatistics called by ./FHEM/98_statistics.pm (281)
2018.03.01 08:56:13.764 1 : main::statistics_Notify called by fhem.pl (3528)
2018.03.01 08:56:13.764 1 : main::CallFn called by fhem.pl (3448)
2018.03.01 08:56:13.765 1 : main::DoTrigger called by fhem.pl (4438)
2018.03.01 08:56:13.765 1 : main::readingsEndUpdate called by fhem.pl (4620)
2018.03.01 08:56:13.765 1 : main::readingsSingleUpdate called by ./FHEM/98_dummy.pm (53)
2018.03.01 08:56:13.766 1 : (eval) called by ./FHEM/98_dummy.pm (50)
2018.03.01 08:56:13.766 1 : main::dummy_Set called by fhem.pl (3523)
2018.03.01 08:56:13.766 1 : main::CallFn called by fhem.pl (1760)
2018.03.01 08:56:13.766 1 : main::DoSet called by fhem.pl (1792)
2018.03.01 08:56:13.766 1 : main::CommandSet called by ./FHEM/98_cmdalias.pm (99)
2018.03.01 08:56:13.766 1 : main::CommandCmdAlias called by fhem.pl (1173)
2018.03.01 08:56:13.766 1 : main::AnalyzeCommand called by fhem.pl (1026)
2018.03.01 08:56:13.766 1 : main::AnalyzeCommandChain called by ./FHEM/01_FHEMWEB.pm (2517)
2018.03.01 08:56:13.766 1 : main::FW_fC called by ./FHEM/01_FHEMWEB.pm (850)
2018.03.01 08:56:13.766 1 : main::FW_answerCall called by ./FHEM/01_FHEMWEB.pm (537)
2018.03.01 08:56:13.766 1 : main::FW_Read called by fhem.pl (3528)
2018.03.01 08:56:13.766 1 : main::CallFn called by fhem.pl (690)
2018.03.01 08:56:13.766 4 : Forbidden device env_stats
2018.03.01 08:56:13.767 5 : End notify loop for env_stats
2018.03.01 08:56:13.767 5 : statistics env_stats: Notify.282 Notification of 'env_presence' received. Update statistics.
2018.03.01 08:56:13.768 4 : DbLog benDbLog -> ################################################################
2018.03.01 08:56:13.768 4 : DbLog benDbLog -> ### start of new Logcycle ###
2018.03.01 08:56:13.768 4 : DbLog benDbLog -> ################################################################
2018.03.01 08:56:13.768 4 : DbLog benDbLog -> number of events received: 1 for device: env_presence
2018.03.01 08:56:13.768 4 : DbLog benDbLog -> check Device: env_presence , Event: transition: leaving
2018.03.01 08:56:13.771 3 : <EVENT> env_presence - transition: leaving
2018.03.01 08:56:13.771 5 : Starting notify loop for sys_di_eventLog, 1 event(s), first is cmd_1
2018.03.01 08:56:13.771 5 : statistics env_stats: Notify.266 Notification of 'sys_di_eventLog' received. Device not monitored.
2018.03.01 08:56:13.771 4 : DbLog benDbLog -> ################################################################
2018.03.01 08:56:13.771 4 : DbLog benDbLog -> ### start of new Logcycle ###
2018.03.01 08:56:13.771 4 : DbLog benDbLog -> ################################################################
2018.03.01 08:56:13.771 4 : DbLog benDbLog -> number of events received: 1 for device: sys_di_eventLog
2018.03.01 08:56:13.771 4 : DbLog benDbLog -> check Device: sys_di_eventLog , Event: state: cmd_1
2018-03-01 08:56:13.773 DOIF sys_di_eventLog cmd_1
2018.03.01 08:56:13.773 3 : Forbidden device sys_di_eventLog for WEBApi_127.0.0.1_37270
2018.03.01 08:56:13.773 1 : stacktrace:
2018.03.01 08:56:13.773 1 : main::allowed_Authorize called by fhem.pl (3528)
2018.03.01 08:56:13.774 1 : main::CallFn called by fhem.pl (5097)
2018.03.01 08:56:13.774 1 : main::Authorized called by fhem.pl (1186)
2018.03.01 08:56:13.774 1 : main::devspec2array called by fhem.pl (1788)
2018.03.01 08:56:13.774 1 : main::CommandSet called by fhem.pl (2561)
2018.03.01 08:56:13.774 1 : main::getAllSets called by ./FHEM/01_FHEMWEB.pm (2997)
2018.03.01 08:56:13.774 1 : main::FW_devState called by ./FHEM/01_FHEMWEB.pm (2897)
2018.03.01 08:56:13.774 1 : main::FW_Notify called by fhem.pl (3528)
2018.03.01 08:56:13.774 1 : main::CallFn called by fhem.pl (3448)
2018.03.01 08:56:13.774 1 : main::DoTrigger called by fhem.pl (4438)
2018.03.01 08:56:13.774 1 : main::readingsEndUpdate called by ./FHEM/98_DOIF.pm (1788)
2018.03.01 08:56:13.774 1 : main::DOIF_SetState called by ./FHEM/98_DOIF.pm (1972)
2018.03.01 08:56:13.774 1 : main::DOIF_cmd called by ./FHEM/98_DOIF.pm (2169)
2018.03.01 08:56:13.774 1 : main::DOIF_Trigger called by ./FHEM/98_DOIF.pm (2301)
2018.03.01 08:56:13.774 1 : main::DOIF_Notify called by fhem.pl (3528)
2018.03.01 08:56:13.774 1 : main::CallFn called by fhem.pl (3448)
2018.03.01 08:56:13.775 1 : main::DoTrigger called by fhem.pl (4438)
2018.03.01 08:56:13.775 1 : main::readingsEndUpdate called by fhem.pl (4620)
2018.03.01 08:56:13.775 1 : main::readingsSingleUpdate called by ./FHEM/98_dummy.pm (53)
2018.03.01 08:56:13.775 1 : (eval) called by ./FHEM/98_dummy.pm (50)
2018.03.01 08:56:13.775 1 : main::dummy_Set called by fhem.pl (3523)
2018.03.01 08:56:13.775 1 : main::CallFn called by fhem.pl (1760)
2018.03.01 08:56:13.775 1 : main::DoSet called by fhem.pl (1792)
2018.03.01 08:56:13.775 1 : main::CommandSet called by ./FHEM/98_cmdalias.pm (99)
2018.03.01 08:56:13.775 1 : main::CommandCmdAlias called by fhem.pl (1173)
2018.03.01 08:56:13.775 1 : main::AnalyzeCommand called by fhem.pl (1026)
2018.03.01 08:56:13.775 1 : main::AnalyzeCommandChain called by ./FHEM/01_FHEMWEB.pm (2517)
2018.03.01 08:56:13.775 1 : main::FW_fC called by ./FHEM/01_FHEMWEB.pm (850)
2018.03.01 08:56:13.775 1 : main::FW_answerCall called by ./FHEM/01_FHEMWEB.pm (537)
2018.03.01 08:56:13.775 1 : main::FW_Read called by fhem.pl (3528)
2018.03.01 08:56:13.775 1 : main::CallFn called by fhem.pl (690)
2018.03.01 08:56:13.775 4 : Forbidden device sys_di_eventLog
2018.03.01 08:56:13.775 5 : End notify loop for sys_di_eventLog
2018-03-01 08:56:13.779 dummy env_presence transition: leaving
2018.03.01 08:56:13.780 5 : End notify loop for env_presence
2018.03.01 08:56:13.780 4 : WEBApi: /api?cmd=set%20env_presence%20transition%20leaving&fwcsrf=geheim&XHR=1 / RL:20 / text/plain; charset=UTF-8 / Content-Encoding: gzip /
2018.03.01 08:56:13.782 4 : Connection closed for WEBApi_127.0.0.1_37270: EOF
Interessante Uebung.
Kurz: set env_presence modifiziert indirekt env_stats, und das hast du untersagt.
Lang:
- set env_presence laeuft "unberuehrt" durch cmdalias (btw, da habe ich jetzt einen Bug gefixt, $cl wurde fuer "abgefangene" Befehle bisher nicht weitergegeben)
- danach wird dumy-set aufgerufen, was wg readingList ein Reading erneuert, was ein trigger ausloest
- darauf reagiert statistics, und generiert Events fuer env_stats (???)
- darauf reagiert FHEMWEB, und versucht den neuen Status fuer env_presence anzuzeigen.
- dafuer braucht er die Liste der moeglichen Befehle, was mit "set env_stats ?" zu kriegen ist, was wiederum verboten ist.
Was ich noch nicht verstehe: wie kommt statistics auf die Idee, ein anderes Geraet zu aktualisieren (env_stats statt env_presence), und wie/warum wird dabei $cl vom env_presence an env_stats weitergegeben. Ich muss es nachstellen, aus dem Code alleine werde ich nicht schlau: Kannst du bitte die Definition+Attribute von env_stats und env_presence mir zeigen?
Ich finde es merkwuerdig, dass "set X ?" von allowed geprueft wird, bin aber noch nicht ganz sicher, ob das falsch ist oder nicht. Tendiere eher zu "nicht pruefen".
Zitat von: rudolfkoenig am 01 März 2018, 10:07:57
Ich finde es merkwuerdig, dass "set X ?" von allowed geprueft wird, bin aber noch nicht ganz sicher, ob das falsch ist oder nicht. Tendiere eher zu "nicht pruefen".
ohne alles verstanden zu haben ;)
aber liegt das nicht an http://commandref.fhem.de/commandref_DE.html#allowedCommands
list von weiter oben
Internals:
NAME allowed_WEBApi
NR 547
STATE validFor:WEBApi
TYPE allowed
allowedCommands set
allowedDevices env_fritzbox,env_presence,wz_mode,sys_di_voiceCtrl,wz_lightSpot,env_guestWifi
validFor WEBApi
READINGS:
2018-02-27 18:17:07 state validFor:WEBApi
Attributes:
allowedCommands set
allowedDevices env_fritzbox,env_presence,wz_mode,sys_di_voiceCtrl,wz_lightSpot,env_guestWifi
room System
validFor WEBApi
@Rudi
Ok, danke dir. Ich hab das jetzt beim ersten Lesen noch nicht in Gänze durchdrungen, muss ich sagen. Das werde ich aber versuchen nachholen.
Nach erstem Verständnis kontrolliert man mit dem allowed-Device also nicht nur die *unmittelbaren* Befehle, die über das Web-Device abgesetzt werden, sondern auch eventuelle nachgeschaltete Abläufe, die über notifies o.ä. ausgelöst werden?
Hier aber erstmal die gewünschten Listing:
Internals:
DEF ^(env_electricMeter_Sen|env_gasMeter_Sen|(wz|sz)_hmTcWeather|(fl|ku|bd)_thgr228n|env_thpl|env_presence)$
DEV_REGEXP ^(env_electricMeter_Sen|env_gasMeter_Sen|(wz|sz)_hmTcWeather|(fl|ku|bd)_thgr228n|env_thpl|env_presence)$
NAME env_stats
NR 386
NTFY_ORDER 10-env_stats
PREFIX stat
STATE Updated stats for: env_thpl
TYPE statistics
READINGS:
2018-02-28 14:58:57 monitoredDevicesCUL_HM env_electricMeter_Sen,env_gasMeter_Sen,env_thpl,sz_hmTcWeather,wz_hmTcWeather
2018-02-28 14:58:57 monitoredDevicesTRX_WEATHER bd_thgr228n,fl_thgr228n,ku_thgr228n
2018-02-28 14:58:46 monitoredDevicesUnknown presence
2018-02-28 14:58:57 monitoredDevicesdummy env_presence
2018-03-01 09:59:58 nextPeriodChangeCalc 2018-03-01 10:59:58
2018-03-01 10:26:19 state Updated stats for: env_thpl
fhem:
modulVersion $Date: 2018-02-26 19:40:38 +0100 (Mon, 26 Feb 2018) $
nextPeriodChangeTime 1519898398
Attributes:
alias Statistiken
deltaReadings energyCalc,gasCntOverallWh,homeDuration
group FHEM
ignoreDefaultAssignments 1
minAvgMaxReadings power,measured-temp,humidity,luminosity,temperature,pressure,gasPowerRealW
periodChangePreset 2
room System
singularReadings (env_presence|env_electricMeter_Sen|env_gasMeter_Sen):(homeDuration|energyCalc|gasCntOverallWh):Delta:(Day|Month|Year)
Internals:
NAME env_presence
NR 39
STATE away
TYPE dummy
Helper:
DBLOG:
statHomeDurationDayLast:
benDbLog:
TIME 1519858798.04973
VALUE 768.961067099
statHomeDurationLast:
benDbLog:
TIME 1519894798.03879
VALUE Hour: 0.000000000 Day: 768.961067099 Month: 28146.475569927 Year: 325227.135678422 (since: 2017-02-16 )
statHomeDurationMonthLast:
benDbLog:
TIME 1519858798.04973
VALUE 28146.475569927
READINGS:
2018-03-01 09:59:58 homeDuration 806860.00607829
2018-03-01 09:59:58 statHomeDuration Hour: 0.000000000 Day: 557.385701764 Month: 557.385701764 Year: 60545.793687825
2018-03-01 09:59:58 statHomeDurationDay 557.385701764
2018-02-28 23:59:58 statHomeDurationDayLast 768.961067099
2018-03-01 09:59:58 statHomeDurationLast Hour: 0.000000000 Day: 768.961067099 Month: 28146.475569927 Year: 325227.135678422 (since: 2017-02-16 )
2018-03-01 09:59:58 statHomeDurationMonth 557.385701764
2018-02-28 23:59:58 statHomeDurationMonthLast 28146.475569927
2018-03-01 09:59:58 statHomeDurationYear 60545.793687825
2017-12-31 23:59:58 statHomeDurationYearLast 325227.135678422
2018-03-01 09:01:13 state away
2018-03-01 08:56:13 transition leaving
helper:
_98_statistics env_stats
Attributes:
alias Anwesenheit
devStateIcon home:status_available away:status_away_1 sleep:scene_sleeping
event-on-change-reading (state|statHomeDuration.*)
event-on-update-reading transition
group Zustände
icon status_away_1
readingList transition
room Wohnung
setList away home sleep
userReadings homeDuration integral { (Value("env_presence") ne "away") /60.0 }
webCmd home:away:sleep
Nochmal ein Nachtrag:
Also mit dem statistics mag ja so sein, dass das wirklich indirekt durch den Web-Request getriggert wird und dadurch mit unter "allowed" fällt. Aber was noch komischer ist, ist dass noch eine ganze Zeit (ca. 60 Sekunden) nach dem Webrequest wirklich ganz normale zyklische Readings von ganz anderen Gerät auch das "forbidden" werfen:
2018-03-01 11:17:04.827 CUL_HM env_thpl luminosity: 2704
2018-03-01 11:17:04.827 CUL_HM env_thpl pressure: 1005.5
2018-03-01 11:17:04.827 CUL_HM env_thpl temperature: -6.5
2018.03.01 11:17:04.828 3 : Forbidden device env_thpl for WEBApi_127.0.0.1_48948
2018.03.01 11:17:04.828 1 : stacktrace:
2018.03.01 11:17:04.828 1 : main::allowed_Authorize called by fhem.pl (3528)
2018.03.01 11:17:04.828 1 : main::CallFn called by fhem.pl (5097)
2018.03.01 11:17:04.828 1 : main::Authorized called by fhem.pl (1186)
2018.03.01 11:17:04.828 1 : main::devspec2array called by fhem.pl (1788)
2018.03.01 11:17:04.828 1 : main::CommandSet called by fhem.pl (2561)
2018.03.01 11:17:04.828 1 : main::getAllSets called by ./FHEM/01_FHEMWEB.pm (2997)
2018.03.01 11:17:04.828 1 : main::FW_devState called by ./FHEM/01_FHEMWEB.pm (2897)
2018.03.01 11:17:04.828 1 : main::FW_Notify called by fhem.pl (3528)
2018.03.01 11:17:04.828 1 : main::CallFn called by fhem.pl (3448)
2018.03.01 11:17:04.828 1 : main::DoTrigger called by fhem.pl (3806)
2018.03.01 11:17:04.828 1 : main::Dispatch called by ./FHEM/00_HMLAN.pm (779)
2018.03.01 11:17:04.828 1 : main::HMLAN_Parse called by ./FHEM/00_HMLAN.pm (604)
2018.03.01 11:17:04.828 1 : main::HMLAN_Read called by fhem.pl (3528)
2018.03.01 11:17:04.829 1 : main::CallFn called by fhem.pl (690)
2018.03.01 11:17:04.829 3 : Forbidden device env_thpl for WEBApi_127.0.0.1_48948
2018.03.01 11:17:04.829 1 : stacktrace:
2018.03.01 11:17:04.829 1 : main::allowed_Authorize called by fhem.pl (3528)
2018.03.01 11:17:04.829 1 : main::CallFn called by fhem.pl (5097)
2018.03.01 11:17:04.829 1 : main::Authorized called by fhem.pl (1186)
2018.03.01 11:17:04.829 1 : main::devspec2array called by fhem.pl (1788)
2018.03.01 11:17:04.829 1 : main::CommandSet called by fhem.pl (2561)
2018.03.01 11:17:04.829 1 : main::getAllSets called by ./FHEM/01_FHEMWEB.pm (2997)
2018.03.01 11:17:04.829 1 : main::FW_devState called by ./FHEM/01_FHEMWEB.pm (2897)
2018.03.01 11:17:04.829 1 : main::FW_Notify called by fhem.pl (3528)
2018.03.01 11:17:04.829 1 : main::CallFn called by fhem.pl (3448)
2018.03.01 11:17:04.829 1 : main::DoTrigger called by fhem.pl (3806)
2018.03.01 11:17:04.829 1 : main::Dispatch called by ./FHEM/00_HMLAN.pm (779)
2018.03.01 11:17:04.829 1 : main::HMLAN_Parse called by ./FHEM/00_HMLAN.pm (604)
2018.03.01 11:17:04.829 1 : main::HMLAN_Read called by fhem.pl (3528)
2018.03.01 11:17:04.830 1 : main::CallFn called by fhem.pl (690)
Das "env_tphl" ist einfach ein THPL-Sensor, der alle 2-3 Minuten seine Readings einliefert. Das ist wirklich nicht angestoßen durch den Webrequest. :o
(Ganz viele solcher Fälle sind auch in dem Log in meinem Eingangspost zu sehen).
Ich verstehe die Ursache nicht. Z.Zt. wird in CommandSet, -Get, -Define, -Modify, -SetReadng $hash->{CL} nur fuer die Dauer des Modulspezifischen Funktionsaufrufs gesetzt, und ich meine kein Modul "restauriert" CL so, dass es in diesem Fall ein Problem waere. Wenn jemand hierfuer eine Idee hat, bitte melden.
Ich habe jetzt den direkten Verursacher (set|get|attr NAME ?) aus der Authorisierungspruefung ausgenommen, da das meiner Ansicht nach auch sonst nicht sinnvoll ist.
Ich verstehe die Ursache natürlich auch nicht. Aber ich kann sagen, dass der Fehler mit deiner Änderung zumindest erstmal weg ist. Also danke!