98_HTTPMOD: new attribute to set loglevel of error messages

git-svn-id: https://svn.fhem.de/fhem/trunk@23483 2b470e98-0d58-463d-a4d8-8e2adae1ed80

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";
     }
+    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, 3, "$name: Read callback: Error: $err" if ($err);
     Log3 $name, 4, "$name: Read callback: request type was $type" . 
         " retry $request->{retryCount}" .
         ($header ? ",\r\nheader: $header" : ", no headers") . 
@@ -3591,6 +3602,11 @@ sub AddToSendQueue {
         <li><b>preProcessRegex</b></li>
             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.
             
+        <li><b>errorLogLevel</b></li>
+            allows to modify the loglevel used to log errors from HttpUtils. by default level 3 is used.
+        <li><b>errorLogLevelRegex</b></li>
+            restricts the effect of errorLogLevel to such error messages that match this regex.
+
         <li><b>Remarks regarding the automatically created userattr entries</b></li>
             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.
     </ul>

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 " 
+    Log3 $name, 5, "$name: Profiling $key, before $lKey, now is " . FmtTimeMs($now) . 
-        . $hash->{profiler}{start}{$key} . ", $lKey started at " . $hash->{profiler}{start}{$lKey};
+        ", $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";     
+                    " now $pPeriod, total diff for $lKey is $lDiff, " . 
-        Log3 $name, 5, "$name: Profiling add " . ($lDiff - $overP) . " to sum for $key";
+                    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 " .
+        Log3 $name, 5, "$name: Profiling add " . sprintf('%.3f', $lDiff) . " to sum for $lKey " .
-            "(now is $now, start for $lKey was $hash->{profiler}{start}{$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;

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

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;