diff --git a/fhem/FHEM/98_HTTPMOD.pm b/fhem/FHEM/98_HTTPMOD.pm index a7c09bfbf..20affec44 100755 --- a/fhem/FHEM/98_HTTPMOD.pm +++ b/fhem/FHEM/98_HTTPMOD.pm @@ -21,6 +21,7 @@ # First version: 25.12.2013 # # Todo: +# Attribute für Regex und LogLevel zum verstecken bestimmter Fehlermedungen von HttpUtils im ReadCallback # setXYHintExpression zum dynamischen Ändern / Erweitern der Hints # extractAllReadings mit Filter / Prefix # get after set um readings zu aktualisieren @@ -141,7 +142,7 @@ BEGIN { )); }; -my $Module_Version = '4.0.16 - 5.12.2020'; +my $Module_Version = '4.0.17 - 31.12.2020'; my $AttrList = join (' ', '(reading|get|set)[0-9]+(-[0-9]+)?Name', @@ -240,6 +241,9 @@ my $AttrList = join (' ', 'clearSIdBeforeAuth:0,1', 'authRetries', + 'errLogLevelRegex', + 'errLogLevel', + 'replacement[0-9]+Regex', 'replacement[0-9]+Mode:reading,internal,text,expression,key', # defaults to text 'replacement[0-9]+Value', # device:reading, device:internal, text, replacement expression @@ -432,6 +436,7 @@ sub AttrFn { my $aVal = shift; # attribute value my $hash = $defs{$name}; # reference to the Fhem device hash + Log3 $name, 5, "$name: attr $name $aName $aVal"; if ($cmd eq 'set') { if ($aName =~ /^regexDecode$/) { delete $hash->{CompiledRegexes}; # recompile everything with the right decoding @@ -1393,7 +1398,7 @@ sub GetRegex { my ($name, $context, $num, $type, $default) = @_; my $hash = $defs{$name}; my $val; - my $regDecode = AttrVal($name, 'regexDecode', ""); # implement this even when not compiled regex + my $regDecode = AttrVal($name, 'regexDecode', ""); # implement this even when not compiled my $regCompile = AttrVal($name, 'regexCompile', 1); #Log3 $name, 5, "$name: Look for Regex $context$num$type"; @@ -1420,7 +1425,7 @@ sub GetRegex { $val = $hash->{CompiledRegexes}{$context . $type}; } } - else { + else { # no attribute defined $val = $default; return if (!$val) # default is not compiled - should only be "" or similar } @@ -2288,8 +2293,14 @@ sub ReadCallback { $body = $2 // ''; Log3 $name, 5, "$name: HTTPMOD ReadCallback split file body / header at $headerSplit"; } - - Log3 $name, 3, "$name: Read callback: Error: $err" if ($err); + if ($err) { + my $lvlRegex = GetRegex($name, '', '', 'errLogLevelRegex', ''); + my $errLvl = AttrVal($name, 'errLogLevel', 3); + Log3 $name, 5, "$name: Read callback Error LogLvl set to $errLvl, regex " . ($lvlRegex // ''); + $errLvl = 3 if ($lvlRegex && $err !~ $lvlRegex); + Log3 $name, $errLvl, "$name: Read callback: Error: $err"; + } + Log3 $name, 4, "$name: Read callback: request type was $type" . " retry $request->{retryCount}" . ($header ? ",\r\nheader: $header" : ", no headers") . @@ -3590,6 +3601,11 @@ sub AddToSendQueue { Please look into the module source to see how it works and don't use them if you are not sure what you are doing.
  • preProcessRegex
  • can be used to fix a broken HTTP response before parsing. The regex should be a replacement regex like s/match/replacement/g and will be applied to the buffer. + +
  • errorLogLevel
  • + allows to modify the loglevel used to log errors from HttpUtils. by default level 3 is used. +
  • errorLogLevelRegex
  • + restricts the effect of errorLogLevel to such error messages that match this regex.
  • Remarks regarding the automatically created userattr entries
  • Fhemweb allows attributes to be edited by clicking on them. However this does not work for attributes that match to a wildcard attribute. To circumvent this restriction HTTPMOD automatically adds an entry for each instance of a defined wildcard attribute to the device userattr list. E.g. if you define a reading[0-9]Name attribute as reading01Name, HTTPMOD will add reading01Name to the device userattr list. These entries only have the purpose of making editing in Fhemweb easier. diff --git a/fhem/lib/FHEM/HTTPMOD/Utils.pm b/fhem/lib/FHEM/HTTPMOD/Utils.pm index 75d2e82ad..e271ec0ea 100644 --- a/fhem/lib/FHEM/HTTPMOD/Utils.pm +++ b/fhem/lib/FHEM/HTTPMOD/Utils.pm @@ -147,7 +147,7 @@ sub UpdateTimer { my $delay = sprintf ("%.1f", $nextUpdate - $now); Log3 $name, 4, "$name: UpdateTimer called from " . FhemCaller() . " with cmd $cmd" . - " sets timer to call update function in $delay sec at " . FmtDateTime($nextUpdate) . ", interval $intvl"; + " sets timer to call update function in $delay sec at " . FmtTimeMs($nextUpdate) . ", interval $intvl"; RemoveInternalTimer("update:$name"); InternalTimer($nextUpdate, $updFn, "update:$name", 0); # now set the timer return; @@ -173,14 +173,13 @@ sub StartQueueTimer { my $pFunc = shift; # e.g. \&Modbus::ProcessRequestQueue my $oRef = shift; # optional hash ref for passing options my $name = $ioHash->{NAME}; - my $pDelay = $oRef->{'delay'} // AttrVal($name, 'queueDelay', 1); # delay until queue processing call + my $delay = $oRef->{'delay'} // AttrVal($name, 'queueDelay', 1); # delay until queue processing call my $silent = $oRef->{'silent'} // 0; my $msg = $oRef->{'log'} // ''; my $qlen = ($ioHash->{QUEUE} ? scalar(@{$ioHash->{QUEUE}}) : 0); if ($qlen) { my $now = gettimeofday(); - my $delay = (defined($pDelay) ? $pDelay : AttrVal($name, 'queueDelay', 1)); return if ($ioHash->{nextQueueRun} && $ioHash->{nextQueueRun} < $now+$delay); Log3 $name, 5, "$name: StartQueueTimer called from " . FhemCaller() . ' sets internal timer to process queue in ' . @@ -407,7 +406,7 @@ sub CheckRange { ##################################################################### -# check that a value is in a defined range +# use sprintf to format a value with a given format string sub FormatVal { my $hash = shift; my $oRef = shift; # optional hash ref for passing options and variables for use in expressions @@ -417,7 +416,8 @@ sub FormatVal { return $val if (!$format); my $newVal = sprintf($format, $val // ''); - Log3 $name, 5, "$name: FormatVal for " . FhemCaller() . " formats $val with $format, result is $newVal"; + Log3 $name, 5, "$name: FormatVal for " . FhemCaller() . " formats " . ($val // 'undef') . + " with format " . ($format // 'undef') . ", result is " . ($newVal // 'undef'); return $newVal; } @@ -832,7 +832,7 @@ sub Profiler { $hash->{profiler}{lastPeriod} = $pPeriod; $hash->{profiler}{start}{$key} = $now; $hash->{profiler}{sums}{$key} = 0 ; - Log3 $name, 5, "$name: Profiling $key initialized, start $now"; + Log3 $name, 5, "$name: Profiling $key initialized, start " . FmtTimeMs($now); return; } my $lKey = $hash->{profiler}{lastKey}; # save last key @@ -843,20 +843,22 @@ sub Profiler { $hash->{profiler}{start}{$key} = $now; # save start time for new key } - Log3 $name, 5, "$name: Profiling $key, before $lKey, now is $now, $key started at " - . $hash->{profiler}{start}{$key} . ", $lKey started at " . $hash->{profiler}{start}{$lKey}; + Log3 $name, 5, "$name: Profiling $key, before $lKey, now is " . FmtTimeMs($now) . + ", $key started at " . FmtTimeMs($hash->{profiler}{start}{$key}) . + ", $lKey started at " . FmtTimeMs($hash->{profiler}{start}{$lKey}); if ($pPeriod != $hash->{profiler}{lastPeriod}) { # new period my $overP = $now - ($pPeriod * $pInterval); # time over the pPeriod start $overP = 0 if ($overP > $lDiff); # if interval was modified things get inconsistant ... Log3 $name, 5, "$name: Profiling pPeriod changed, last pPeriod was " . $hash->{profiler}{lastPeriod} . - " now $pPeriod, total diff for $lKey is $lDiff, over $overP over the pPeriod"; - Log3 $name, 5, "$name: Profiling add " . ($lDiff - $overP) . " to sum for $key"; + " now $pPeriod, total diff for $lKey is $lDiff, " . + sprintf ('%.3f', $overP) . " over the pPeriod"; + Log3 $name, 5, "$name: Profiling add " . sprintf('%.3f', $lDiff - $overP) . " to sum for $key"; $hash->{profiler}{sums}{$lKey} += ($lDiff - $overP); readingsBeginUpdate($hash); foreach my $k (keys %{$hash->{profiler}{sums}}) { - my $val = sprintf('%.2f', $hash->{profiler}{sums}{$k}); + my $val = sprintf('%.3f', $hash->{profiler}{sums}{$k}); Log3 $name, 5, "$name: Profiling set reading for $k to $val"; readingsBulkUpdate($hash, 'Profiler_' . $k . '_sum', $val); $hash->{profiler}{sums}{$k} = 0; @@ -868,12 +870,13 @@ sub Profiler { $hash->{profiler}{sums}{$lKey} = $overP; $hash->{profiler}{lastPeriod} = $pPeriod; $hash->{profiler}{lastKey} = $key; - Log3 $name, 5, "$name: Profiling set new sum for $lKey to $overP"; + Log3 $name, 5, "$name: Profiling set new sum for $lKey to " . sprintf('%.3f', $overP); } else { return if ($key eq $hash->{profiler}{lastKey}); # nothing new - take time when key or pPeriod changes - Log3 $name, 5, "$name: Profiling add $lDiff to sum for $lKey " . - "(now is $now, start for $lKey was $hash->{profiler}{start}{$lKey})"; + Log3 $name, 5, "$name: Profiling add " . sprintf('%.3f', $lDiff) . " to sum for $lKey " . + "(now is " . FmtTimeMs($now) . ", start for $lKey was " . + FmtTimeMs($hash->{profiler}{start}{$lKey}) . ")"; $hash->{profiler}{sums}{$lKey} += $lDiff; $hash->{profiler}{start}{$key} = $now; $hash->{profiler}{lastKey} = $key; diff --git a/fhem/t/FHEM/98_HTTPMOD/91_ErrLogLvl.cfg b/fhem/t/FHEM/98_HTTPMOD/91_ErrLogLvl.cfg new file mode 100644 index 000000000..f8620d51f --- /dev/null +++ b/fhem/t/FHEM/98_HTTPMOD/91_ErrLogLvl.cfg @@ -0,0 +1,3 @@ +define H1 HTTPMOD file://t/FHEM/98_HTTPMOD/NoSuchFile 0 +attr H1 verbose 5 +attr H1 minSendDelay 0 diff --git a/fhem/t/FHEM/98_HTTPMOD/91_ErrLogLvl.t b/fhem/t/FHEM/98_HTTPMOD/91_ErrLogLvl.t new file mode 100644 index 000000000..4c87c82d4 --- /dev/null +++ b/fhem/t/FHEM/98_HTTPMOD/91_ErrLogLvl.t @@ -0,0 +1,66 @@ +############################################## +# test attr errLogLvl +############################################## +package main; + +use strict; +use warnings; +use Test::More; +use Time::HiRes qw( gettimeofday tv_interval); # return time as float, not just full seconds +use FHEM::HTTPMOD::Utils qw(:all); +use FHEM::Modbus::TestUtils qw(:all); + +fhem 'attr global mseclog 1'; +InternalTimer(gettimeofday()+5, "testStepLast", 0); # last resort +NextStep(); + +sub testStep1 { + FhemTestUtils_resetLogs(); + FhemTestUtils_resetEvents(); + is(FhemTestUtils_gotLog('attribute'), 0, "no unknown attributes"); # logs during init are not collected. + LogStep "request without further settings but timeout 0"; + fhem ('set H1 reread'); + return; +} + +sub testStep2 { + # loginform used fot FhemTestUtils inserts a space between the level and : + is(FhemTestUtils_gotLog('3 : H1: Read callback: Error'), 1, "standard log level"); + FhemTestUtils_resetLogs(); + FhemTestUtils_resetEvents(); + LogStep "set level go 4"; + fhem ('attr H1 errLogLevel 4'); + fhem ('set H1 reread'); + return; +} + +sub testStep3 { + is(FhemTestUtils_gotLog('4 : H1: Read callback: Error: t/FHEM/98_HTTPMOD/NoSuchFile'), 1, "log level 4"); + FhemTestUtils_resetLogs(); + FhemTestUtils_resetEvents(); + LogStep "set level regex to timeout only"; + fhem ('attr H1 errLogLevel 4'); + fhem ('attr H1 errLogLevelRegex timeout'); + fhem ('set H1 reread'); + return; +} + +sub testStep4 { + is(FhemTestUtils_gotLog('3 : H1: Read callback: Error: t/FHEM/98_HTTPMOD/NoSuchFile'), 1, "standard log level because regex doesnt match"); + FhemTestUtils_resetLogs(); + FhemTestUtils_resetEvents(); + LogStep "set level regex to no such file"; + fhem ('attr H1 errLogLevel 4'); + fhem ('attr H1 errLogLevelRegex No such file'); + fhem ('set H1 reread'); + return; +} + +sub testStep5 { + is(FhemTestUtils_gotLog('4 : H1: Read callback: Error: t/FHEM/98_HTTPMOD/NoSuchFile'), 1, "log level 4 with match"); + FhemTestUtils_resetLogs(); + FhemTestUtils_resetEvents(); + return; +} + +1; \ No newline at end of file