98_Modbus: updated tests

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

fhem/lib/FHEM/Modbus/TestUtils.pm

@@ -23,7 +23,6 @@ package FHEM::Modbus::TestUtils;
 
 use strict;
 use warnings;
-
 use GPUtils         qw(:all);
 use Time::HiRes     qw(gettimeofday);    
 
@@ -70,33 +69,37 @@ BEGIN {
 our $testStep = 0;
 our %testOptions;
 our %results;
-our $nextStepMode = 'auto';
 
-sub SimRead {
-    my $name   = shift;
-    my $readFn = shift;
-    my $text   = shift;
-    my $option = shift;
-    my $hash   = $defs{$name};
-    my $data;
-    Log3 undef, 1, "Test simulate reception of $text";
-    if ($option && $option eq 'ASCII') {
-        $data = $text;                      # ascii 
-    } else {
-        $data   = pack ('H*', $text);       # hex coded binary
-    }
-    $hash->{TestInput} = $data;
-    eval { &{$readFn}($hash) };
-    if ($@) {
-        Log3 undef, 1, "Test step $testStep call to readFn created error: $@";
-    } else {
-        Log3 undef, 1, "Test step $testStep readFn done.";
-    }
-    return;
-}
 
+#####################################################################
+#
+#  NextStep
+#       - GetNextStep
+#       - set timer for CallStep or end Testing
+#
+#  InternalTimer -> CallStep 
+#                       - step via eval
+#                       - NextStep -> Timer for CallStep
+#                                       - step via eval
+#                                       - NextStep
+#
+#  LogInform -> ReactOnLogRegex -> 
+#                   - InternalTimer for SimResponseRead
+#
+#  InternalTimer -> SimResponseRead
+#                   - SimResponseRead
+#                   - NextStep -> Timer for CallStep
+#                                   - step via eval
+#                                       - send -> LogInform -> SimResponseRead ...
+#                                   - NextStep?? (don't set timer for next step in this case)
+#
+
+
+##################################################################
+# find the next test step number 
+# internal function, called from NextStep
 sub GetNextStep {
-    #Log3 undef, 1, "Test GetNextStep: look for next step";
+    Log3 undef, 1, "Test GetNextStep: look for next step";
     my $next = $testStep;
     FINDSTEP: 
     while (1) {
@@ -110,43 +113,144 @@ sub GetNextStep {
 }
 
 
+######################################################################
+# set internalTimer to call the next test step after an optional delay
+# normally in tests to have the first step called and 
+# also internally by CallStep and SimResponseRead
 sub NextStep {
     my $delay = shift // 0;
     my $next  = GetNextStep();
-    
+    if (!$next || ($delay && $delay eq 'end')) {        # done if no more steps
-    InternalTimer(gettimeofday() + $delay, \&CallStep, "main::testStep$next");
-    #Log3 undef, 1, "Test NextStep: done.";
-    $testStep = $next;
-    return;
-}
-
-
-sub CallStep {
-    my $func = shift;
-    Log3 undef, 1, "----------------------------------------------------";    
-    Log3 undef, 1, "Test step $testStep";
-    
-    no strict "refs";               ## no critic - function name needs to be string
-    my $delay = eval { &{$func}() };
-    if ($@) {
-        Log3 undef, 1, "Test step $testStep call created error: $@";
-    } else {
-        Log3 undef, 1, "Test step $testStep done.";
-    }
-    
-    my $next  = GetNextStep();      
-    if (!$next) {                       # done if no more steps
         Log3 undef, 1, "Test NextStep: no more steps found - exiting";
         done_testing;
         exit(0);
     }
-    if ($nextStepMode eq 'auto') {
+    if (!$delay || $delay ne 'wait') {                  # set timer to next step unless waiting for reception of data
-        NextStep($delay);               # set timer to go to next step with delay returned by last
+        Log3 undef, 1, "Test NextStep: set timer to call step $next with delay $delay";
+        InternalTimer(gettimeofday() + $delay, \&CallStep, "main::testStep$next");
+        $testStep = $next;
+    }
+    Log3 undef, 1, "Test NextStep: done.";
+    return;
+}
+
+
+#############################################################################
+# Call the Test step and then set the timer for the next one
+# called by internalTimer
+sub CallStep {
+    my $func = shift;
+    $func =~ /^(.*[A-Za-z]+)(\d+)$/;
+    my $step = $2;
+    Log3 undef, 1, "----------------------------------------------------";    
+    Log3 undef, 1, "Test step $step ($func)";
+    
+    no strict "refs";                   ## no critic - function name needs to be string
+    my $delay = eval { &{$func}() };    # call the next step and check for errors
+    if ($@) {
+        Log3 undef, 1, "Test step $step call created error: $@";
+    } else {
+        Log3 undef, 1, "Test step $step ($func) done, delay before next step is $delay";
+    }
+    # if step function returns 'wait' then do not set timer for next step but wait for ReactOnLogRegex or similar
+    NextStep($delay);                   # check for next step and set timer or end testing
+    return;
+}
+
+
+################################################################################
+# check if a regex is found in logs (typically the sending of a request)
+# and call SmResponseRead via timer to simulate the reception of a response
+# called via logInform
+sub ReactOnLogRegex {
+    my $name = shift;
+    my $line = shift;
+    #die "line got: $line";
+    if ($line =~ /$testOptions{RespondTo}/) {
+        my $send = $1;
+        my $id   = substr ($send, 0, 2);
+        my $recv = $testOptions{ResponseHash}{$send};       # simulate broken error response by default
+        if (!$recv) {
+            $recv = ($id . '800041c0');
+            Log3 undef, 1, "Test: request $send is not in Reply hash, respond with default error instead";
+        }
+        my $delay = $testOptions{ResponseDelay} // 0.05;
+        Log3 undef, 1, "------------------------------------------------------------------------";    
+        Log3 undef, 1, "Test saw sending $send, id $id, set timer to simulate receiving $recv in $delay";
+        InternalTimer(gettimeofday() + $delay, \&SimResponseRead, $recv);       # set timer to simulate response and go to next step
     }
     return;
 }
 
 
+#######################################################################################
+# simulate the reception of a response by calling SimRead 
+# and then setting the timer for the next step.
+# todo: delay should be definable
+sub SimResponseRead {
+    my $data = shift;
+    Log3 undef, 1, "Test now simulates reception of response and then checks for next step";
+    SimRead($testOptions{IODevice}, $data);
+    NextStep($testOptions{delayAfterResponse} // 0);
+    return;
+}
+
+
+##########################################################################
+# interface to set options hash
+# used options:
+# - delayAfterResponse : time in seconds to wait after a simualted response before the next step function is called
+# - IODevice : name of the device for sending and receiving
+# - RespondTo : Regex to be used when monitoring the Fhem log and reacting on a "sending" log with a simulated reception
+# - ResponseHash : Hash that maps from data sent (as found in log) to a valid response for the simulation 
+# - ResponseDelay : delay before the reception of a response is sumulated
+# - Time1Regex and Time1Name : name and regex to be searched in log to find the time when it was logged, used by calcDelays
+# - Time2Regex and Time2Name : name and regex to be searched in log to find the time when it was logged, used by calcDelays
+sub SetTestOptions {
+    my $opt = shift;
+    foreach my $k (keys %{$opt}) {
+        $testOptions{$k} = $opt->{$k};
+    }
+    if ($testOptions{RespondTo}) {
+        $logInform{$testOptions{IODevice}} = \&ReactOnLogRegex;
+    }
+    return;
+}
+
+
+##############################################################
+# simulate reading from a device. 
+# the device should be defined with 'none' as interface 
+# and the readFn should take data from $hash->{TestInput}
+# in this case
+sub SimRead {
+    my $name   = shift;             # Name of the io device that should read data
+    my $input  = shift;             # binary input string (coded as hex-string) to be read
+    my $option = shift;             # further otions (so far only 'ASCII' to treat the input string as text instead of hex)
+    my $hash   = $defs{$name};
+    my $data;
+    Log3 undef, 1, "Test simulate reception of $input";
+    if ($option && $option eq 'ASCII') {
+        $data = $input;                      # ascii 
+    } else {
+        $data   = pack ('H*', $input);       # hex coded binary
+    }
+    $hash->{TestInput} = $data;
+    my $type    = $defs{$name}{TYPE};
+    my $modHash = $modules{$type};
+    my $readFn  = $modHash->{ReadFn};
+    eval { &{$readFn}($hash) };
+    if ($@) {
+        Log3 undef, 1, "Test step $testStep call to readFn created error: $@";
+    } else {
+        Log3 undef, 1, "Test step $testStep readFn done.";
+    }
+    return;
+}
+
+
+#############################################################
+# wrapper for Log3 to be used in tests
 sub LogStep {
     my $msg = shift // '';
     Log3 undef, 1, "Test step $testStep: $msg";
@@ -154,43 +258,8 @@ sub LogStep {
 }
 
 
-sub ReactOnSendingLog {
+###########################################################################
-    my $name = shift;
+# find the time of two regexes in the log 
-    my $line = shift;
-    #die "line got: $line";
-    if ($line =~ /$testOptions{RespondTo}/) {
-        my $send = $1;
-        my $id   = substr ($send, 0, 2);
-        my $recv = $testOptions{ReplyHash}{$send} // (($id . '800041c0'));       # simulate broken error response by default
-        my $delay = $testOptions{ResponseDelay} // 0.05;
-        Log3 undef, 1, "------------------------------------------------------------------------";    
-        Log3 undef, 1, "Test saw sending $send, id $id, set timer to simulate receiving $recv in $delay";
-        InternalTimer(gettimeofday() + $delay, \&SimResponseRead, $recv);
-    }
-    return;
-}
-
-
-sub SimResponseRead {
-    my $data = shift;
-    Log3 undef, 1, "Test now simulate reception of response and then call next step";
-    SimRead($testOptions{IODevice}, $testOptions{ReadFn}, $data);
-    NextStep();
-}
-
-
-sub SetTestOptions {
-    my $opt = shift;
-    foreach my $k (keys %{$opt}) {
-        $testOptions{$k} = $opt->{$k};
-    }
-    if ($testOptions{RespondTo}) {
-        $nextStepMode  = 'reception';
-        $logInform{$testOptions{IODevice}} = \&ReactOnSendingLog;
-    }
-}
-
-
 sub findTimesInLog {
     $results{$testOptions{Time1Name}.$testStep} = FhemTestUtils_getLogTime($testOptions{Time1Regex});      
     $results{$testOptions{Time2Name}.$testStep} = FhemTestUtils_getLogTime($testOptions{Time2Regex});
@@ -202,6 +271,8 @@ sub findTimesInLog {
 }
 
 
+################################################################################
+# calculate and log the time differences found by calling findTimesInLog
 sub calcDelays {
     my ($lastDelay, $commDelay, $sendDelay);
     if (defined ($results{$testOptions{Time1Name} . $testStep}) && 

fhem/t/FHEM/98_Modbus/10_Timer.t

@@ -1,6 +1,7 @@
 ##############################################
 # test update timer 
 ##############################################
+package main;
 use strict;
 use warnings;
 use Test::More;

fhem/t/FHEM/98_Modbus/12_Delays.t

@@ -1,5 +1,5 @@
 ##############################################
-# test request parsing
+# test communication delays
 ##############################################
 package main;
 use strict;
@@ -35,20 +35,19 @@ my %rData = (
 fhem 'attr global mseclog 1';
 
 SetTestOptions(
-    {   IODevice    => 'MS',                                    # for loginform
+    {   IODevice      => 'MS',                                    # for loginform
-        RespondTo   => 'MS: Simulate sending to none: (.*)',    # auto reponder / go to next step at reception
+        RespondTo     => 'MS: Simulate sending to none: (.*)',    # auto reponder / go to next step at reception
-        ReadFn      => \&Modbus::ReadFn,                        # call for reception
+        ResponseHash  => \%rData,                                 # to find the right response
-        ReplyHash   => \%rData,                                 # to find the right response
 
-        Time1Name   => 'Sending',
+        Time1Name     => 'Sending',
-        Time1Regex  => qr{MS:\sSimulate\ssending},
+        Time1Regex    => qr{MS:\sSimulate\ssending},
-        Time2Name   => 'Reception',
+        Time2Name     => 'Reception',
-        Time2Regex  => qr{ParseFrameStart\s\(RTU\)\sextracted\sid},
+        Time2Regex    => qr{ParseFrameStart\s\(RTU\)\sextracted\sid},
     }                                
 );                             
 
 
-fhem 'get M1 SolarTemp';
+fhem 'get M1 SolarTemp';        # will cause step 1 to be called when send is detected and response is simulated
 
 sub testStep1 {
     findTimesInLog();
@@ -59,7 +58,7 @@ sub testStep1 {
     fhem 'get M1 HeatOff';
     # read simulation is triggered when sending is seen in the log.
     # next step is called when read simulation is done.
-    return;
+    return 'wait';
 }
 
 
@@ -73,7 +72,7 @@ sub testStep2 {
     
     fhem 'attr M1 dev-timing-sendDelay 0.2';            # send in step2 should be 0.2 after send in step1
     fhem 'get M1 HeatOff';
-    return;
+    return 'wait';
 }
 
 
@@ -84,10 +83,10 @@ sub testStep3 {
     
     # check send delay between read (get HeatOff) after Step 1 and send (get HeatOff) in step 2
     ok($sendDelay >= 0.2, 'defined send delay from read HeatOff to next send get HeatOff big enough');
-    ok($sendDelay < 0.22, 'defined send delay from read HeatOff to next send get HeatOff not too big');
+    ok($sendDelay < 0.25, 'defined send delay from read HeatOff to next send get HeatOff not too big');
     
     fhem 'get M5 TempWasserEin';
-    return;
+    return 'wait';
 }
 
 
@@ -97,11 +96,11 @@ sub testStep4 {
     my ($commDelay, $sendDelay) = calcDelays();
 
     # check no send delay between read (get HeatOff) after Step 2 and send (get TempWasserEin to id 5) in step 3
-    ok($sendDelay < 0.1, 'defined send delay on id 1 from read HeatOff to send get TempWasserEin not used for id 5');
+    ok($sendDelay < 0.15, 'defined send delay on id 1 from read HeatOff to send get TempWasserEin not used for id 5');
     
     fhem 'attr MS busDelay 0.2';
-    fhem 'get M5 TempWasserAus';
+    fhem 'get M5 TempWasserAus';            # new request, go to next step when response is simulated
-    return;
+    return 'wait';
 }
 
 
@@ -117,8 +116,8 @@ sub testStep5 {
     fhem 'attr MS busDelay 0';
     fhem 'attr M1 dev-timing-sendDelay 0';
     fhem 'attr MS clientSwitchDelay 0';
-    fhem 'get M1 SolarTemp';
+    fhem 'get M1 SolarTemp';                # new request, go to next step when response is simulated
-    return;
+    return 'wait';
 }
 
 
@@ -129,8 +128,8 @@ sub testStep6 {
     
     ok($sendDelay < 0.2, 'no delay');
     fhem 'attr MS clientSwitchDelay 0.2';
-    fhem 'get M5 TempWasserEin';
+    fhem 'get M5 TempWasserEin';            # new request, go to next step when response is simulated
-    return;
+    return 'wait';
 }
 
 
@@ -142,8 +141,8 @@ sub testStep7 {
     ok($commDelay >= 0.2, 'defined clsw delay big enough');
     ok($commDelay < 0.3, 'defined clsw delay not too big');
     
-    fhem 'get M5 TempWasserAus';
+    fhem 'get M5 TempWasserAus';            # new request, go to next step when response is simulated
-    return;
+    return 'wait';
 }
 
 
@@ -152,11 +151,11 @@ sub testStep8 {
     FhemTestUtils_resetLogs();
     my ($commDelay, $sendDelay) = calcDelays();
     
-    ok($sendDelay < 0.1, 'no delay for same id');
+    ok($sendDelay < 0.2, 'no delay for same id');
     
     fhem 'attr M5 dev-timing-commDelay 0.2';  
-    fhem 'get M5 TempWasserEin';
+    fhem 'get M5 TempWasserEin';            # new request, go to next step when response is simulated
-    return;
+    return 'wait';
 }
 
 
@@ -169,8 +168,8 @@ sub testStep9 {
     ok($commDelay < 0.22, 'defined comm delay not too big');
 
     fhem 'attr M5 dev-timing-commDelay 0';  
-    fhem 'get M5 TempWasserEin';
+    fhem 'get M5 TempWasserEin';            # new request, go to next step when response is simulated
-    return;
+    return 'wait';  
 }
 
 
@@ -183,8 +182,8 @@ sub testStep10 {
     
     fhem 'attr M5 dev-timing-commDelay 0.2';  
     fhem 'attr M5 verbose 4';  
-    fhem 'set M5 o1 on';
+    fhem 'set M5 o1 on';                    # new request, go to next step when response is simulated
-    return;
+    return 'wait';
 }
 
 

fhem/t/FHEM/98_Modbus/13_OpenDelays.cfg

@@ -4,7 +4,7 @@ define D1 dummy
 
 define Slave ModbusAttr 5 slave global:5501
 attr Slave obj-h256-reading TempWasserEin
-attr Slave obj-h258-reading D1:TempWasserAus
+attr Slave obj-h258-reading TempWasserAus
 
 attr Slave obj-h100-reading Test1
 attr Slave obj-h100-setexpr $val * 4

fhem/t/FHEM/98_Modbus/13_OpenDelays.t

@@ -1,7 +1,5 @@
 ##############################################
-# test master slave end to end
+# test open delays
-# attr disable
-# and set inactive / set active
 ##############################################
 package main;
 use strict;
@@ -9,14 +7,14 @@ 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);
 use Data::Dumper;
 
 my $closeTime;
 my $openTime;
 my $startTime;
 
-InternalTimer(gettimeofday() + 0.1, "testStep1", 0);
+NextStep();
-
 
 sub getLogTime {
     my $regex = shift;
@@ -27,51 +25,42 @@ sub getLogTime {
     return $time;
 }
 
-
 sub testStep1 {     # preparation of slave content, enable devices
-    Log3 undef, 1, "----------------";    
     #is(FhemTestUtils_gotLog('attribute'), 0, "no unknown attributes");     # logs during init are not collected.
-    Log3 undef, 1, "TestStep1: enable Master and set value at Slave";
+    LogStep "TestStep1: enable Master and set value at Slave";
     fhem ('attr Master disable 0');
     fhem ('setreading Slave TempWasserEin 12');
+    fhem ('setreading Slave TempWasserAus 23');
     fhem ('setreading Slave Test1 1');
     fhem ('setreading Slave Test2 2.123');
     fhem ('setreading Slave Test3 abcdefg');
     fhem ('setreading Slave Test4 40');   
-
+    return 0.1;
-    InternalTimer(gettimeofday() + 0.1, "testStep2", 0);
 }
 
 sub testStep2 {     # get holding registers 
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep2: get TempWasserEin";
     fhem ('attr Master verbose 5');
     fhem ('attr Slave verbose 3');
     fhem ('get Master TempWasserEin');
-    InternalTimer(gettimeofday() + 0.1, "testStep3", 0);
+    return 0.1;
 }
 
 sub testStep3 {     # check first result, disable and request again
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep3: check result, disable master and request again";
     is(FhemTestUtils_gotEvent(qr/Master:TempWasserEin:\s12/xms), 1, "Retrieve integer value from local slave");
     FhemTestUtils_resetEvents();
     FhemTestUtils_resetLogs();
     fhem ('attr Master disable 1');
     fhem ('get Master TempWasserEin');
-
+    return;
-    InternalTimer(gettimeofday(), "testStep4", 0);
 }
 
 sub testStep4 {     
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep4: check that master disable worked";
     is(FhemTestUtils_gotEvent(qr/Master:TempWasserEin:\s12/xms), 0, "no Retrieve for disabled");
     is(FhemTestUtils_gotEvent(qr/Master:disabled/xms), 1, "state disabled");
     fhem ('attr Master disable 0');
     FhemTestUtils_resetEvents();
     FhemTestUtils_resetLogs();
-    InternalTimer(gettimeofday() + 0.1, "testStep5", 0);
+    return 0.1;
 }
 
 sub testStep5 {     
@@ -80,44 +69,38 @@ sub testStep5 {
     $startTime = getLogTime ('Master device opened');
     fhem ('attr Master enableSetInactive 1');
     fhem ('set Master inactive');
-    InternalTimer(gettimeofday(), "testStep6", 0);
+    return;
 }
 
 sub testStep6 {    
     Log3 undef, 1, "----------------";     
     Log3 undef, 1, "TestStep6: now try to get reading again";
     fhem ('get Master TempWasserEin');
-    InternalTimer(gettimeofday(), "testStep7a", 0);
+    return;
 }
 
-sub testStep7a {     
+sub testStep7 {     
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep7a: check if reading was not requested and then set master to active again";
     is(FhemTestUtils_gotEvent(qr/Master:TempWasserEin:\s12/xms), 0, "no Retrieve for inactive");
     FhemTestUtils_resetEvents();
     FhemTestUtils_resetLogs();
     fhem ('attr Master nextOpenDelay2 0');              # don't wait with open 
     fhem ('set Master active');
-    InternalTimer(gettimeofday(), "testStep7b", 0);
+    return;
 }
 
-sub testStep7b {     
+sub testStep8 {     
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep7b: try retrieve again";
     $openTime = getLogTime ('Master device opened');
-    Log3 undef, 1, "TestStep7b: Time diff is " . sprintf ('%.3f', $openTime - $startTime);
+    Log3 undef, 1, "Test: Time diff is " . sprintf ('%.3f', $openTime - $startTime);
     ok($openTime - $startTime < 0.25, 'time between two open calls is smaller than 0.25');
     FhemTestUtils_resetEvents();
     FhemTestUtils_resetLogs();
-    fhem ('get Master TempWasserEin');
+    fhem ('get Master TempWasserAus');
-    InternalTimer(gettimeofday() + 0.1, "testStep8", 0);
+    return 0.2;
 }
 
 
-sub testStep8 {     
+sub testStep9 {     
-    Log3 undef, 1, "----------------";    
+    is(FhemTestUtils_gotEvent(qr/Master:TempWasserAus:\s23/xms), 1, "Retrieve integer value again from local slave");
-    Log3 undef, 1, "TestStep8: check result and then set slave to inactive and try again";    
-    is(FhemTestUtils_gotEvent(qr/Master:TempWasserEin:\s12/xms), 1, "Retrieve integer value again from local slave");
     fhem ('set Slave inactive');
     FhemTestUtils_resetEvents();
     FhemTestUtils_resetLogs();
@@ -126,94 +109,53 @@ sub testStep8 {
     fhem ('attr Master nextOpenDelay2 0.1');            # 
     fhem ('attr Master nextOpenDelay 1');               # can not be smaller than 1
     fhem ('get Master TempWasserEin');                  # should run into timeout
-    InternalTimer(gettimeofday()+0.5, "testStep8b", 0);
+    return 0.5;
 }
 
-sub testStep8b {     
+sub testStep10 {     
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep8b: check that request was not answered and get last open time";    
     is(FhemTestUtils_gotEvent(qr/Master:TempWasserEin:\s12/xms), 0, "no Retrieve for inactive Slave");
     #is(FhemTestUtils_gotLog('Master: Timeout waiting for a modbus response'), 1, "saw timeout");
     $startTime = getLogTime ('HttpUtils url=http://localhost:5501');    # time of first try
     fhem ('set Slave active');
-    InternalTimer(gettimeofday()+1, "testStep8c", 0);
+    return 1.0;
 }
 
 
-sub testStep8c {     
+sub testStep11 {     
-    Log3 undef, 1, "----------------";    
+    return 1.0;
-    Log3 undef, 1, "TestStep8c: ";    
-    InternalTimer(gettimeofday()+1, "testStep9a", 0);
 }
 
 
-sub testStep9a {     
+sub testStep12 {     
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep9a: check nextOpenDelay";    
     $openTime = getLogTime ('5501 reappeared');
-    Log3 undef, 1, "TestStep7b: Time diff is " . sprintf ('%.3f', $openTime - $startTime);
+    Log3 undef, 1, "TestStep12: Time diff is " . sprintf ('%.3f', $openTime - $startTime);
     ok($openTime - $startTime >= 1, 'time between two open calls is bigger than 1');
     ok($openTime - $startTime < 2, 'time between two open calls is smaller than 2');
-    InternalTimer(gettimeofday() + 0.1, "testStep9b", 0);
+    return 0.1;
 }
 
-sub testStep9b {     
+sub testStep13 {     
-    Log3 undef, 1, "----------------";    
+    return;
-    Log3 undef, 1, "TestStep9b: ";    
-    InternalTimer(gettimeofday(), "testStep9c", 0);
 }
 
-sub testStep9c {     
+sub testStep14 {     
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep9b: retrieve value and then let Slave close after inactivity timeout";    
     # now open should happen and event should come
     fhem('attr Slave dev-timing-serverTimeout 1');
     fhem('attr Slave dev-timing-serverTimeout 1');
     FhemTestUtils_resetEvents();
     FhemTestUtils_resetLogs();
     fhem ('get Master TempWasserEin');
-    InternalTimer(gettimeofday() + 1.1, "testStep10", 0);
+    return 1.1;
 }
 
-sub testStep10 {    
+sub testStep15 {    
     # check that we now got the value
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep10: check successful retrieve after slave is active again and master did open connection";
     is(FhemTestUtils_gotEvent(qr/Master:TempWasserEin:\s12/xms), 1, "Retrieve integer value again from local slave");
-    InternalTimer(gettimeofday() + 0.5, "testStep11", 0);
+    return 0.5;
 }
 
-sub testStep11 {    
+sub testStep16 {    
-    Log3 undef, 1, "----------------";    
+    return;
-    Log3 undef, 1, "TestStep11:";
-    InternalTimer(gettimeofday() + 1, "testStep12", 0);
 }
 
-sub testStep12 {
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep12:";
-    InternalTimer(gettimeofday() + 1, "testStep13", 0);
-}
-
-sub testStep13 {
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep13:";
-    InternalTimer(gettimeofday(), "testStepEnd", 0);
-}
-
-
-sub testStepX {
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStepX: ";
-    #fhem ('get ');
-    InternalTimer(gettimeofday() + 0.1, "testStepEnd", 0);
-}
-
-
-sub testStepEnd {
-    done_testing;
-    exit(0);
-}
-
-
 1;

fhem/t/FHEM/98_Modbus/14_QDelay.t

@@ -1,5 +1,5 @@
 ##############################################
-# test request parsing
+# test queue delays
 ##############################################
 use strict;
 use warnings;
@@ -13,7 +13,6 @@ fhem 'attr global mseclog 1';
 
 SetTestOptions(
     {   IODevice    => 'MS',                                    # for loginform
-        #RespondTo   => 'MS: Simulate sending to none: (.*)',    # auto reponder / go to next step at reception
         Time1Name   => 'busy',
         Time1Regex  => qr{Fhem is still waiting},
         Time2Name   => 'queue run',

fhem/t/FHEM/98_Modbus/31_Register.t

@@ -1,6 +1,5 @@
 ##############################################
-# test master slave end to end
+# test attr disable
-# attr disable
 # and set inactive / set active
 ##############################################
 use strict;
@@ -8,102 +7,62 @@ 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);
 use Data::Dumper;
 
-InternalTimer(gettimeofday() + 0.1, "testStep1", 0);
+NextStep();
+
 
 sub testStep1 {    
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep1: define Master over MS";
-
     fhem ('define Master ModbusAttr 5 0');
-    InternalTimer(gettimeofday() + 0.1, "testStep2", 0);
+    return 0.1;
 }
 
 sub testStep2 {
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep2: ";
     is(FhemTestUtils_gotLog('registers Master at MS with id 5, MODE master, PROTOCOL RTU'), 1, "Master registered");
     fhem ('define Master2 ModbusAttr 4 0');
-    InternalTimer(gettimeofday() + 0.1, "testStep3", 0);
+    return 0.1;
 }
 
 sub testStep3 {
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep3: ";
     is(FhemTestUtils_gotLog('registers Master2 at MS with id 4, MODE master, PROTOCOL RTU'), 1, "Master2 registered");
     fhem ('define Master3 ModbusAttr 4 0 ASCII');
     fhem ('attr Master3 enableSetInactive 1');
     fhem ('attr Master3 verbose 5');
     fhem ('attr Master3 obj-h100-reading test');
     fhem ('attr Master3 obj-h100-showGet 1');
-    InternalTimer(gettimeofday() + 0.1, "testStep4", 0);
+    return 0.1;
 }
 
 sub testStep4 {
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep4: ";
     is(FhemTestUtils_gotLog('Master3: SetIODev found no usable physical modbus device'), 1, "No IODev for Master3 (MS already locked as RTU)");
     FhemTestUtils_resetLogs();
     fhem ('attr Master disable 1');
     fhem ('get Master3 test');
-    InternalTimer(gettimeofday() + 0.1, "testStep5", 0);
+    return 0.1;
 }
+
 sub testStep5 {
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep5: ";
     is(FhemTestUtils_gotLog('Master3: SetIODev found no usable physical modbus device'), 1, "No IODev for Master3 (MS still locked as RTU)");
     FhemTestUtils_resetLogs();
     fhem ('attr Master2 disable 1');
     fhem ('get Master3 test');
-    InternalTimer(gettimeofday() + 0.1, "testStep6", 0);
+    return 0.1;
 }
+
 sub testStep6 {
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep6: ";
     is(FhemTestUtils_gotLog('registers Master3 at MS with id 4, MODE master, PROTOCOL ASCII'), 1, "Now MS is locked as ASCII");
     FhemTestUtils_resetLogs();
     fhem ('define Slave1 ModbusAttr 10 slave ASCII');
-    InternalTimer(gettimeofday() + 0.1, "testStep7", 0);
+    return 0.1;
 }
+
 sub testStep7 {
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep7: ";
     is(FhemTestUtils_gotLog('Slave1: SetIODev found no usable physical modbus device'), 1, "no io device for slave");
     fhem ('delete Slave1');
     fhem ('attr Master3 disable 1');
     fhem ('define Slave1 ModbusAttr 10 slave ASCII');
-    InternalTimer(gettimeofday() + 0.1, "testStep8", 0);
+    return 0.1;
 }
-sub testStep8 {
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep8: ";
-    is(FhemTestUtils_gotLog('registers Slave1 at MS with id 10, MODE slave, PROTOCOL ASCII'), 1, "now slave can use MS as IO Device");
-    InternalTimer(gettimeofday() + 0.1, "testStep9", 0);
-}
-sub testStep9 {
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep9: ";
-    InternalTimer(gettimeofday() + 0.1, "testStep10", 0);
-}
-sub testStep10 {
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStep10: ";
-    InternalTimer(gettimeofday() + 0.1, "testStepEnd", 0);
-}
-
-sub testStepX {
-    Log3 undef, 1, "----------------";    
-    Log3 undef, 1, "TestStepX: ";
-    #fhem ('get ');
-    InternalTimer(gettimeofday() + 0.1, "testStepEnd", 0);
-}
-
-
-sub testStepEnd {
-    done_testing;
-    exit(0);
-}
-
 
 1;

fhem/t/FHEM/98_Modbus/41_Passive.t

@@ -11,56 +11,28 @@ use Time::HiRes             qw( gettimeofday tv_interval);  # return time as flo
 use FHEM::HTTPMOD::Utils    qw(:all);
 use FHEM::Modbus::TestUtils qw(:all);
 
-#$logInform{'MS'} = \&ReactOnSendingLog;
-
-my @rData = (
-
-    '05030100000585b1',                     # request       h 256 - h 260 (TempWasserEin, TempWasserAus)
-    '05030a0137110001381100010dac7b',       # response
-
-    '0503010600016473',                     # request       h 262
-    '0503020106c816',                       # response
-
-    '050303020001240a',                     # request       h 770
-    '0503020122c80d',                       # response
-
-    '05030309000155c8',                     # request
-    '05030200004984',                       # response
-
-    '0503010000018472',
-    '050302013709c2',                       # response
-
-    '0506030900005808',                     # request   set hyst mode
-    '0506030900005808',                     # response
-
-    '0506030201182850',                     # request   set temp soll 28
-    '0506030201182850'                      # response
-);
-my $dataPtr  = 0;
-
 fhem 'attr global mseclog 1';
-InternalTimer(gettimeofday()+5, "testStepLast", 0);             # last resort
 NextStep();
 
 
 sub testStep1 {
     LogStep "send first request in parts";
     FhemTestUtils_resetLogs();
-    SimRead('MS', \&Modbus::ReadFn, 'fe03');                    # part of a request
+    SimRead('MS', 'fe03');                    # part of a request
     return;
 }
 
 
 sub testStep2 {
     FhemTestUtils_resetLogs();
-    SimRead('MS', \&Modbus::ReadFn, '0164000810');              # part of a request
+    SimRead('MS', '0164000810');              # part of a request
     return;
 }
 
 
 sub testStep3 {
     FhemTestUtils_resetLogs();
-    SimRead('MS', \&Modbus::ReadFn, '20');                      # final part of a request
+    SimRead('MS', '20');                      # final part of a request
     return;
 }
 
@@ -70,18 +42,18 @@ sub testStep4 {
     is(FhemTestUtils_gotLog('received valid request, now wait for the reponse'), 1, "first request reassembled correctly");
     FhemTestUtils_resetLogs();
     FhemTestUtils_resetEvents();
-    SimRead('MS', \&Modbus::ReadFn, 'fe03016400081020');        # another request
+    SimRead('MS', 'fe03016400081020');        # another request
     return;
 }
 
 
 sub testStep5 {
     LogStep "check reception of repeated request and send first reply";
-    is(FhemTestUtils_gotLog('no valid response -> try interpretation as request instead'), 1, "invalid respone and switch to request");
+    is(FhemTestUtils_gotLog('no valid response -> try interpretation as request instead'), 1, "corectly detected invalid respone and switch to request");
     is(FhemTestUtils_gotLog('received valid request, now wait for the reponse'), 1, "second request interpreted");
     FhemTestUtils_resetLogs();
     FhemTestUtils_resetEvents();
-    SimRead('MS', \&Modbus::ReadFn,'fe03100000000b000000400000011a00000167f378');   # the reply
+    SimRead('MS', 'fe03100000000b000000400000011a00000167f378');   # the reply
     return;
 }
 
@@ -91,7 +63,7 @@ sub testStep6 {
     is(FhemTestUtils_gotLog('ParseObj has no information about handling h356'), 1, "try parsing registers");
     FhemTestUtils_resetLogs();
     FhemTestUtils_resetEvents();
-    SimRead('MS', \&Modbus::ReadFn,'fe03100000000b000000400000011a00000167f378');   # the reply repeated
+    SimRead('MS', 'fe03100000000b000000400000011a00000167f378');   # the reply repeated
     return;
 }
 
@@ -102,7 +74,7 @@ sub testStep7 {
     is(FhemTestUtils_gotLog('HandleResponse got data but we don.t have a request'), 1, "next response without a request seen");
     FhemTestUtils_resetLogs();
     FhemTestUtils_resetEvents();    
-    SimRead('MS', \&Modbus::ReadFn, 'fe03064000810209');        # a broken frame
+    SimRead('MS', 'fe03064000810209');        # a broken frame
     return;
 }
 
@@ -110,7 +82,7 @@ sub testStep7 {
 sub testStep8 {
     is(FhemTestUtils_gotLog('HandleRequest Done, error: '), 1, "invalid frame");
     FhemTestUtils_resetLogs();
-    SimRead('MS', \&Modbus::ReadFn, 'fe03016400081020');        # another request
+    SimRead('MS', 'fe03016400081020');        # another request
     return;
 }
 
@@ -125,7 +97,7 @@ sub testStep10 {
     LogStep "check broken frame with illegal fcode";
     FhemTestUtils_resetLogs();
     FhemTestUtils_resetEvents();    
-    SimRead('MS', \&Modbus::ReadFn, 'fe00064000810209');        # a broken frame
+    SimRead('MS', 'fe00064000810209');        # a broken frame
     return;
 }
 
@@ -133,7 +105,7 @@ sub testStep10 {
 sub testStep11 {
     is(FhemTestUtils_gotLog('HandleRequest Done, error:'), 1, "invalid frame");
     FhemTestUtils_resetLogs();
-    SimRead('MS', \&Modbus::ReadFn, 'fe03016400081020');        # another request
+    SimRead('MS', 'fe03016400081020');        # another request
     return;
 }
 

fhem/t/FHEM/98_Modbus/42_MasterRTU.t

@@ -25,7 +25,7 @@ sub testStep1 {
 
 sub testStep2 {
     LogStep('simulate normal reception');
-    SimRead('MS', \&Modbus::ReadFn, '05030a0137110001381100010dac7b');        # normal response 
+    SimRead('MS', '05030a0137110001381100010dac7b');        # normal response 
     return;
 }
 
@@ -44,7 +44,7 @@ sub testStep3 {
 
 sub testStep4 {
     LogStep('simulate short response');
-    SimRead('MS', \&Modbus::ReadFn, '05030a013711000138110091a8');            # short response
+    SimRead('MS', '05030a013711000138110091a8');            # short response
     return 1.1;         # next step after 1.1 seconds
 }
 
@@ -64,7 +64,7 @@ sub testStep5 {
 
 sub testStep6 {
     LogStep('simulate another short response');
-    SimRead('MS', \&Modbus::ReadFn, '05030a013711000138110091a8');            # short response
+    SimRead('MS', '05030a013711000138110091a8');            # short response
     return;
 }
 
@@ -85,7 +85,7 @@ sub testStep7 {
 
 sub testStep8 {
     LogStep('simulate broken fc3 response');
-    SimRead('MS', \&Modbus::ReadFn, '050301000137110001381100010dd04d');      # response type broken FC3
+    SimRead('MS', '050301000137110001381100010dd04d');      # response type broken FC3
     return;
 }
 

fhem/t/FHEM/98_Modbus/50_MasterSlave0.t

@@ -12,7 +12,6 @@ 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 {     # preparation of slave content, enable devices
@@ -219,13 +218,4 @@ sub testStep21 {
     return;
 }
 
-
-# todo: different protocols (RTU, ASCII, TCP)
-#       data type definition
-#       swap bytes and similar
-#       unpack variations
-
-# then relay mode
-
-
 1;

fhem/t/FHEM/98_Modbus/53_Relay.t

@@ -1,5 +1,5 @@
 ##############################################
-# test master slave end to end
+# test relay
 ##############################################
 
 package main;
@@ -12,7 +12,6 @@ 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 {     # preparation of slave content, enable devices
@@ -108,7 +107,7 @@ sub testStep9 {     # check write data
     is(FhemTestUtils_gotLog('0506000a0001698c'), 1, "set o1 on message in log");
     is(FhemTestUtils_gotLog('0506000b0002784d'), 1, "set O2 2 message in log");
     fhem ('attr Master verbose 3');
-    return 0.1;
+    return 0.2;
 }
 
 
@@ -116,7 +115,7 @@ sub testStep10 {    # check combined read of holding registers and coils
     LogStep "getUpdate with combine";
     FhemTestUtils_resetEvents();
     fhem ('set Master reread');
-    return 0.1;
+    return 0.2;
 }
 
 sub testStep11 {    # check results coming from slave and write coils to slave
@@ -129,8 +128,9 @@ sub testStep11 {    # check results coming from slave and write coils to slave
 
     fhem ('attr Slave obj-c402-allowWrite 1');
     fhem ('attr Master verbose 5');
+    #fhem ('attr Slave verbose 5');  # todo: remove
     fhem ('set Master c2 1');
-    return 0.1;
+    return 0.2;
 }
 
 sub testStep12 {
@@ -144,7 +144,7 @@ sub testStep12 {
     fhem ('attr Slave verbose 3');
     fhem ('attr Master dev-h-write 16');
     fhem ('set Master TempWasserAus 29');
-    return 0.1;
+    return 0.2;
 }
 
 sub testStep13 {
@@ -160,7 +160,7 @@ sub testStep14 {
     fhem ('attr Master closeAfterResponse 1');
     fhem ('attr Master verbose 4');
     fhem ('set Master reread');
-    return 0.1;
+    return 0.2;
 }
 
 sub testStep15 {
@@ -219,12 +219,4 @@ sub testStep21 {
 }
 
 
-# todo: different protocols (RTU, ASCII, TCP)
-#       data type definition
-#       swap bytes and similar
-#       unpack variations
-
-# then relay mode
-
-
 1;

fhem/t/FHEM/98_Modbus/54_RelayProto.t

@@ -1,5 +1,5 @@
 ##############################################
-# test master slave end to end
+# test relay with different protocols
 ##############################################
 
 package main;
@@ -12,7 +12,6 @@ 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 {     # preparation of slave content, enable devices
@@ -116,7 +115,7 @@ sub testStep10 {    # check combined read of holding registers and coils
     LogStep "getUpdate with combine";
     FhemTestUtils_resetEvents();
     fhem ('set Master reread');
-    return 0.1;
+    return 0.2;
 }
 
 sub testStep11 {    # check results coming from slave and write coils to slave
@@ -218,13 +217,4 @@ sub testStep21 {
     return;
 }
 
-
-# todo: different protocols (RTU, ASCII, TCP)
-#       data type definition
-#       swap bytes and similar
-#       unpack variations
-
-# then relay mode
-
-
 1;

fhem/t/FHEM/98_Modbus/58_Profiler.t

@@ -1,5 +1,5 @@
 ##############################################
-# test master slave end to end
+# test profiler (to be implemented!)
 ##############################################
 
 package main;
@@ -12,7 +12,6 @@ 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 {     # preparation of slave content, enable devices