From 9d7ad56f2c36b2a035ce595e92a0846b1a2fbbdd Mon Sep 17 00:00:00 2001
From: StefanStrobel <>
Date: Thu, 7 Jan 2021 12:55:17 +0000
Subject: [PATCH] 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 | 26 ++++++++--
fhem/lib/FHEM/HTTPMOD/Utils.pm | 31 ++++++------
fhem/t/FHEM/98_HTTPMOD/91_ErrLogLvl.cfg | 3 ++
fhem/t/FHEM/98_HTTPMOD/91_ErrLogLvl.t | 66 +++++++++++++++++++++++++
4 files changed, 107 insertions(+), 19 deletions(-)
create mode 100644 fhem/t/FHEM/98_HTTPMOD/91_ErrLogLvl.cfg
create mode 100644 fhem/t/FHEM/98_HTTPMOD/91_ErrLogLvl.t
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