no return asyncOutput on screen - attr eventlogging | this normal? #870

HomeAutoUser · 2020-07-15T22:03:47Z

Expected Behavior

return from ccconf

Actual Behavior

no return from ccconf or other async output if attr eventlogging 1

Steps to Reproduce the Problem

attr nano_433Mhz eventlogging 1
get nano_433Mhz ccconf

Specifications

Microcontroller: nano or radino
Version (Firmware): V 3.4.0-dev_20200707 SIGNALduino cc1101 (chip CC1101) - compiled at Jul 10 2020 23:26:18

Versionmodul (FHEM Module): 3.4.0

eventlogging 1

2020.07.15 23:58:52 5: Get ccconf executed
2020.07.15 23:58:52 5: nano_433Mhz: AddSendQueue, nano_433Mhz: C0DnF (1)
2020.07.15 23:58:52 4: HandleWriteQueue, called
2020.07.15 23:58:52 4: SendFromQueue, called
2020.07.15 23:58:52 5: SimpleWrite, C0DnF
2020.07.15 23:58:52 4: Read, msg: C0Dn11=10B07157C43023B900070018146C070091
2020.07.15 23:58:52 5: Parse, noMsg: C0Dn11=10B07157C43023B900070018146C070091
2020.07.15 23:58:52 5: Read, msg: regexp=C0Dn11=[A-F0-9a-f]+ cmd=ccconf msg=C0Dn11=10B07157C43023B900070018146C070091
2020.07.15 23:58:52 4: HandleWriteQueue, called
2020.07.15 23:58:52 4: HandleWriteQueue, nothing to send, stopping timer

eventlogging 0

2020.07.15 23:59:58 5: nano_433Mhz: Get ccconf executed
2020.07.15 23:59:58 5: nano_433Mhz: AddSendQueue, nano_433Mhz: C0DnF (1)
2020.07.15 23:59:58 4: nano_433Mhz: HandleWriteQueue, called
2020.07.15 23:59:58 4: nano_433Mhz: SendFromQueue, called
2020.07.15 23:59:58 5: nano_433Mhz: SimpleWrite, C0DnF
2020.07.15 23:59:58 4: nano_433Mhz: Read, msg: C0Dn11=10B07157C43023B900070018146C070091
2020.07.15 23:59:58 5: nano_433Mhz: Parse, noMsg: C0Dn11=10B07157C43023B900070018146C070091
2020.07.15 23:59:58 5: nano_433Mhz: Read, msg: regexp=C0Dn11=[A-F0-9a-f]+ cmd=ccconf msg=C0Dn11=10B07157C43023B900070018146C070091
2020.07.15 23:59:59 5: nano_433Mhz: Read, try asyncOutput of message Freq: 433.920 MHz, Bandwidth: 325 KHz, rAmpl: 42 dB, sens: 8 dB, DataRate: 5603.79 Baud, Modulation: ASK/OOK, Syncmod: No preamble/sync
2020.07.15 23:59:59 4: nano_433Mhz: HandleWriteQueue, called
2020.07.15 23:59:59 4: nano_433Mhz: HandleWriteQueue, nothing to send, stopping timer

Ist das Verhalten normal?
Verhalten kann rekonstruiert werden, sobald ich auf eventlogging 0 stelle kommt die Ausgabe

The text was updated successfully, but these errors were encountered:

sidey79 · 2020-07-16T04:35:02Z

Das sollte nicht so sein.
Tritt vermutlich auch mit der aktuellen 3.4 auf oder?

HomeAutoUser · 2020-07-16T12:05:34Z

Tritt vermutlich auch mit der aktuellen 3.4 auf oder?

Ja das macht es.

Ich konnte das Ganze soweit eingrenzen.
Diese Zeile

RFFHEM/FHEM/00_SIGNALduino.pm

Line 4415 in f3a4ff2

DoTrigger($dev,"$name $loglevel: $text");

ist dafür zuständig, das KEIN asyncOutput erfolgt.
Wird diese auskommentiert, so funktioniert auch die Abfrage mit gesetzten Attribut 1. (Es erfolgt aber keine DoTriger)

Das ausführen der DoTrigger Funktion führt dazu, das

RFFHEM/FHEM/00_SIGNALduino.pm

Line 1655 in f3a4ff2

if (exists($hash->{ucCmd}->{asyncOut})) {

nicht mehr zutrifft.

HomeAutoUser · 2020-07-16T13:19:37Z

Zusätzlich habe ich dir schonmal eine Zuarbeit geleistet, wo du den Ablauf nachvollziehen kannst.
Ich habe zusätzliche Logausgaben ergänzt um den vollen Ablauf nachvollziehen zu können.

eventlogging 0

2020.07.16 15:16:46.276 5: sduino_USB_SB_Test: Get_Command ccconf executed
2020.07.16 15:16:46.276 5: sduino_USB_SB_Test: AddSendQueue, sduino_USB_SB_Test: C0DnF (1)
2020.07.16 15:16:46.276 5: sduino_USB_SB_Test: AddSendQueue, set InternalTimer 0.1 to SIGNALduino_HandleWriteQueue
2020.07.16 15:16:46.276 5: sduino_USB_SB_Test: Get_Command set timenow
2020.07.16 15:16:46.377 4: sduino_USB_SB_Test: HandleWriteQueue, called
2020.07.16 15:16:46.378 4: sduino_USB_SB_Test: SendFromQueue, called
2020.07.16 15:16:46.378 5: sduino_USB_SB_Test: SimpleWrite, C0DnF
2020.07.16 15:16:46.388 4: sduino_USB_SB_Test: SendFromQueue, set InternalTimer 0.3 to SIGNALduino_HandleWriteQueue
2020.07.16 15:16:46.391 4: sduino_USB_SB_Test: Read, msg: C0Dn11=12494D57C43023B900070018146C070091
2020.07.16 15:16:46.391 5: sduino_USB_SB_Test: Parse, noMsg: C0Dn11=12494D57C43023B900070018146C070091
2020.07.16 15:16:46.391 5: sduino_USB_SB_Test: Read, ucCmd discontinued
2020.07.16 15:16:46.391 5: sduino_USB_SB_Test: Read, msg: regexp=C0Dn11=[A-F0-9a-f]+ cmd=ccconf msg=C0Dn11=12494D57C43023B900070018146C070091
2020.07.16 15:16:46.392 5: sduino_USB_SB_Test: Read, !exists ucCmd || !exists ucCmd[4] || rmsg=~regexp
start to here 116ms
2020.07.16 15:16:46.402 5: sduino_USB_SB_Test: Read, try asyncOutput of message Freq: 475.445 MHz, Bandwidth: 325 KHz, rAmpl: 42 dB, sens: 8 dB, DataRate: 5603.79 Baud, Modulation: ASK/OOK, Syncmod: No preamble/sync
2020.07.16 15:16:46.689 4: sduino_USB_SB_Test: HandleWriteQueue, called
2020.07.16 15:16:46.689 4: sduino_USB_SB_Test: HandleWriteQueue, nothing to send, stopping timer

################################################################################################
eventlogging 1

2020.07.16 15:17:16.904 5: sduino_USB_SB_Test: Get_Command ccconf executed
2020.07.16 15:17:16.904 5: sduino_USB_SB_Test: AddSendQueue, sduino_USB_SB_Test: C0DnF (1)
2020.07.16 15:17:16.904 5: sduino_USB_SB_Test: AddSendQueue, set InternalTimer 0.1 to SIGNALduino_HandleWriteQueue
2020.07.16 15:17:16.909 5: sduino_USB_SB_Test: Get_Command set timenow
2020.07.16 15:17:17.016 4: sduino_USB_SB_Test: HandleWriteQueue, called
2020.07.16 15:17:17.022 4: sduino_USB_SB_Test: SendFromQueue, called
2020.07.16 15:17:17.027 5: sduino_USB_SB_Test: SimpleWrite, C0DnF
2020.07.16 15:17:17.045 4: sduino_USB_SB_Test: SendFromQueue, set InternalTimer 0.3 to SIGNALduino_HandleWriteQueue
2020.07.16 15:17:17.052 4: sduino_USB_SB_Test: Read, msg: C0Dn11=12494D57C43023B900070018146C070091
2020.07.16 15:17:17.056 5: sduino_USB_SB_Test: Parse, noMsg: C0Dn11=12494D57C43023B900070018146C070091
2020.07.16 15:17:17.061 5: sduino_USB_SB_Test: Read, ucCmd discontinued
2020.07.16 15:17:17.066 5: sduino_USB_SB_Test: Read, msg: regexp=C0Dn11=[A-F0-9a-f]+ cmd=ccconf msg=C0Dn11=12494D57C43023B900070018146C070091
2020.07.16 15:17:17.071 5: sduino_USB_SB_Test: Read, !exists ucCmd || !exists ucCmd[4] || rmsg=~regexp
start to here 167ms
2020.07.16 15:17:17.352 4: sduino_USB_SB_Test: HandleWriteQueue, called
2020.07.16 15:17:17.357 4: sduino_USB_SB_Test: HandleWriteQueue, nothing to send, stopping timer

Added test to analyse bug #870

sidey79 · 2020-10-09T12:27:38Z

Ich habe versucht diesem Verhalten auf die Spur zu kommen.
Zunächst mal, kann ich keinen Fehler mit dem Test nachstellen.

In einem Fhemweb kann ich den Fehler dann allerdings doch nachstellen :(

Added test to analyse bug #870

HomeAutoUser · 2020-10-09T15:22:18Z

... das heißt wohl, deine Tests erreichen nicht das Reale FHEMWeb ;)

sidey79 · 2020-10-09T15:26:34Z

Nein, die laufen nicht in FHEMWeb, aber zumindest schmeisst DoTrigger den Teil {ucCmd}->{asyncOut} nicht weg.

sidey79 · 2020-10-10T08:55:25Z

$hash->{CL} ist nicht definiert, wieso weiss ich noch nicht. Es wird in commandGet gesetzt. Zumindest sollte es das :)

sidey79 · 2020-10-11T18:37:00Z

Beim Aufruf von SIGNALduino_Get ist $hash->{CL} noch gesetzt. (Zeile 973)

RFFHEM/FHEM/00_SIGNALduino.pm

Lines 954 to 980 in 7c78550

    
           sub SIGNALduino_Get($@) { 
        
             my ($hash,$name, @a) = @_; 
        
             #my $type = $hash->{TYPE}; 
        
             return "\"get SIGNALduino\" needs at least one parameter" if(@a < 1); 
        
             if (!InternalVal($name,'cc1101_available',0) && $a[0] =~ /^cc/) { 
        
               return 'This command is only available with a cc1101 receiver'; 
        
             } 
        
             if (!exists($gets{$a[0]})) { 
        
               return "Unknown argument $a[0], choose one of supported commands"; 
        
             } 
        
             my $rcode=undef; 
        
             if (exists($hash->{ucCmd}) && $a[0] ne '?' ) { 
        
               SIGNALduino_Get_delayed("SIGNALduino_Get_delayed:$name:".join(':',@a)); 
        
             } elsif ( ($hash->{DevState} eq 'initialized' || $a[0] eq '?' || $a[0] eq 'availableFirmware') && ref @{$gets{$a[0]}}[1] eq 'CODE') { # 
        
           $hash->{logMethod}->($name, 5, '$name: SIGNALduino_Get,1 CL='.Dumper($hash->{CL})); 
        
               $rcode= @{$gets{$a[0]}}[1]->($hash,@a); 
        
             } elsif ($hash->{DevState} ne 'initialized') { 
        
               $rcode= "$name is not active, may firmware is not supported, please flash or reset"; 
        
             } 
        
             return $rcode;    # We will exit here, and give an output only, $rcode has some value 
        
           }

Nach dem Aufruf von Zeile 974, in SIGNALduino_Get_Command fehlt dann allerdings $hash->{CL}.

RFFHEM/FHEM/00_SIGNALduino.pm

Lines 1044 to 1049 in 7c78550

    
           sub SIGNALduino_Get_Command { 
        
             my ($hash, @a) = @_; 
        
             my $name=$hash->{NAME}; 
        
             return 'Unsupported command for the microcontroller' if (!exists(${$gets{$a[0]}}[2])); 
        
             $hash->{logMethod}->($name, 5, "$name: Get_Command $a[0] executed"); 
        
             $hash->{logMethod}->($name, 5, "$name: Get_Command,1 CL=".Dumper($hash->{CL}));

Da werde ich im Moment nicht schlau draus.


2020.10.11 20:29:59.300 5: sduino: Get_Command,1 CL=$VAR1 = undef;
2020.10.11 20:29:59.293 5: sduino: Get_Command freeram executed

        };
          'SNAME' => 'WEB'
          'SSL' => undef,
          'NAME' => 'WEB_172.18.0.1_57286',
          '.attrminint' => [],
          'canAsyncOutput' => 1,
          '.attraggr' => [],
          'STATE' => 'Connected',
          'LASTACCESS' => 1602440999,
          'CD' => bless( \*Symbol::GEN17788, 'IO::Socket::INET' ),
          'NR' => 16223,
          'FW_ID' => '16222',
          'BUF' => '',
          'FD' => 25,
          'Authenticated' => 0,
                        },
                                     }
                                       'VAL' => 'Connected'
                                       'TIME' => '2020-10-11 20:29:08',
                          'state' => {
          'READINGS' => {
          'PORT' => 57286,
          'TYPE' => 'FHEMWEB',
          'PEER' => '172.18.0.1',
          'TEMPORARY' => 1,
2020.10.11 20:29:59.286 5: $name: SIGNALduino_Get,1 CL=$VAR1 = {

HomeAutoUser · 2020-10-11T19:49:21Z

Kann es sein, das dort eine Zuweisung nicht stimmt ?
$rcode= @{$gets{$a[0]}}[1]->($hash,@a);
Muss es nicht Arraywert -> Arraywert werden? ... Wenn ich es richtig interpretiere.

sidey79 · 2020-10-12T20:01:18Z

@HomeAutoUser
Da kann ich dir gerade nicht folgen?

sidey79 · 2020-10-12T20:05:35Z

Die richtige Funktion wird ja auch durchaus aufgerufen.

HomeAutoUser · 2020-10-12T20:06:52Z

Ich war der Annahme, als ich auf die Schnelle drüber schaute vom Handy, das vielleicht
$rcode= @{$gets{$a[0]}}[1] (ein Arraywert ist) und ->($hash,@a); wird doch in ein Array gesetzt.
Es war nur eine Vermutung.

sidey79 · 2020-10-12T20:53:45Z

Das wird in einen array gecasted, da der compiler sonst nicht weiss was es ist:
@{$gets{$a[0]}}[1]
und ->($hash,@a) ruft die Coderef, welche im Array in Wert [1] liegt mit den Parametern $hash und einer Liste @a auf.

HomeAutoUser · 2020-10-12T21:02:41Z

Konntest du verifizieren, das nur $hash->{CL} fehlt oder ist noch mehr was abhanden kommt?

Ich fand hier https://wiki.fhem.de/wiki/DevelopmentModuleAPI#asyncOutput vielleicht ein Hinweis wie man es testen könnte.
Man kann die Unterstützung für eine asynchrone Datenübermittlung vorab mittels einer if-Abfrage auf$client_hash->{canAsyncOutput} prüfen, da es durchaus passieren kann, dass unter bestimmten Umständen keine asynchrone Übertragung möglich ist.

sidey79 · 2020-10-12T21:16:44Z

Soweit ich das feststellen kann, fehlt $hash->{CL}.
Ich habe aber auch nicht jeden Wert explizit verglichen. Mir ist nur nicht so ganz klar, wieso der fehlt

sidey79 added a commit that referenced this issue Oct 9, 2020

t\FHEM\00_SIGNALduino\99_SIGNALduino_AsyncOutput.t

76db076

Added test to analyse bug #870

sidey79 added a commit that referenced this issue Oct 9, 2020

t\FHEM\00_SIGNALduino\99_SIGNALduino_AsyncOutput.t

400fc47

Added test to analyse bug #870

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

no return asyncOutput on screen - attr eventlogging | this normal? #870

no return asyncOutput on screen - attr eventlogging | this normal? #870

HomeAutoUser commented Jul 15, 2020

sidey79 commented Jul 16, 2020

HomeAutoUser commented Jul 16, 2020

HomeAutoUser commented Jul 16, 2020

sidey79 commented Oct 9, 2020

HomeAutoUser commented Oct 9, 2020

sidey79 commented Oct 9, 2020

sidey79 commented Oct 10, 2020

sidey79 commented Oct 11, 2020 •

edited

Loading

HomeAutoUser commented Oct 11, 2020

sidey79 commented Oct 12, 2020

sidey79 commented Oct 12, 2020

HomeAutoUser commented Oct 12, 2020

sidey79 commented Oct 12, 2020

HomeAutoUser commented Oct 12, 2020

sidey79 commented Oct 12, 2020

no return asyncOutput on screen - attr eventlogging | this normal? #870

no return asyncOutput on screen - attr eventlogging | this normal? #870

Comments

HomeAutoUser commented Jul 15, 2020

Expected Behavior

Actual Behavior

Steps to Reproduce the Problem

Specifications

sidey79 commented Jul 16, 2020

HomeAutoUser commented Jul 16, 2020

HomeAutoUser commented Jul 16, 2020

sidey79 commented Oct 9, 2020

HomeAutoUser commented Oct 9, 2020

sidey79 commented Oct 9, 2020

sidey79 commented Oct 10, 2020

sidey79 commented Oct 11, 2020 • edited Loading

HomeAutoUser commented Oct 11, 2020

sidey79 commented Oct 12, 2020

sidey79 commented Oct 12, 2020

HomeAutoUser commented Oct 12, 2020

sidey79 commented Oct 12, 2020

HomeAutoUser commented Oct 12, 2020

sidey79 commented Oct 12, 2020

sidey79 commented Oct 11, 2020 •

edited

Loading