Unerwartetes "Forbidden" bei normalen Events?

Begonnen von vbs, 28 Februar 2018, 15:19:42

Vorheriges Thema - Nächstes Thema

vbs

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)

rudolfkoenig

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?

vbs

#2
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.

rudolfkoenig

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?

vbs

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

rudolfkoenig

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

nils_

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
viele Wege in FHEM es gibt!

vbs

@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

vbs

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

rudolfkoenig

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.

vbs

Ich verstehe die Ursache natürlich auch nicht. Aber ich kann sagen, dass der Fehler mit deiner Änderung zumindest erstmal weg ist. Also danke!