Nur Text | Text mit Bildern

FHEM Forum

FHEM - Hausautomations-Systeme => Homematic => Thema gestartet von: Andre am 29 Mai 2014, 15:35:57

Titel: Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: Andre am 29 Mai 2014, 15:35:57
Hi,

ich habe seit einigen Tagen Probleme in der HM Kommunikation festgestellt. Bei mir kamen auf der FB und auf den SCs relativ wenige ACKs durch. Beim SC war es nahezu keiner, bei der FB erst nach einigen Wiederholungen. Ich habe mir die letzten Änderungen mal angeschaut, und vermute, dass bei der Umstellung auf CUL_HM_assignIO in CUL_HM_SndCmd ein CUL_HM_assignIO aus dem "if" gerutscht sein könnte.

Vorher:

Code Auswählen

  if(!defined $hash->{IODev} ||!defined $hash->{IODev}{NAME}){
    AssignIoPort($hash);
    if(!defined $hash->{IODev} ||!defined $hash->{IODev}{NAME}){
      CUL_HM_eventP($hash,"IOerr");
      CUL_HM_UpdtReadSingle($hash,"state","ERR_IOdev_undefined",1);
      return;
    }
  };


nachher:

Code Auswählen

  CUL_HM_assignIO($hash) ;
  if(!defined $hash->{IODev} ||!defined $hash->{IODev}{NAME}){
    CUL_HM_eventP($hash,"IOerr");
    CUL_HM_UpdtReadSingle($hash,"state","ERR_IOdev_undefined",1);
    return;
  }


Wenn ich den Aufruf zurück in das if schiebe, funktioniert es (bei mir) wieder.

Edit: Ok, ganz sicher bin ich nicht mehr ob es daran liegt. Es ist auf jeden Fall zwischen den beiden Versionen. Ich teste mal weiter.

Viele Grüße
Andre
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: martinp876 am 29 Mai 2014, 20:06:33
Beim SC gab es  probleme.
Probiere doch einfach mit der aktuellen Version 5989.

ggf. logge einmal

Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: Andre am 29 Mai 2014, 20:35:10
Hi,

Deine neue habe ich noch nicht probiert, ich habe aber auch Probleme mit der FB. Ich hab mal geloggt mit unterschiedlichen Versionen:

Letzte die bei mir geht 5866:

SC Open: Ack kommt (~100ms)
Code Auswählen

2014.05.29 20:16:14.144 4: CUL_Parse: myCUL A 0C 87 A441 1CF75B F11034 0104C81B -60.5
2014.05.29 20:16:14.254 4: CUL_send:  myCULAs 0D 87 8002 F11034 1CF75B 0101C800


SC Close: Ack kommt (~100ms)
Code Auswählen

2014.05.29 20:16:19.145 4: CUL_Parse: myCUL A 0C 88 A441 1CF75B F11034 01050012 -65
2014.05.29 20:16:19.262 4: CUL_send:  myCULAs 0D 88 8002 F11034 1CF75B 0101C800


Version 5966 (Geht nicht, alle davor nach 5866 auch nicht):

SC Open (3 Retries, kein ACK, Timing ~200ms)
Code Auswählen

2014.05.29 20:17:50.150 4: CUL_Parse: myCUL A 0C 89 A441 1CF75B F11034 0106C816 -63
2014.05.29 20:17:50.344 4: CUL_send:  myCULAs 0D 89 8002 F11034 1CF75B 0101C800
2014.05.29 20:17:50.495 4: CUL_Parse: myCUL A 0C 89 A041 1CF75B F11034 0106C817 -62.5
2014.05.29 20:17:50.681 4: CUL_send:  myCULAs 0D 89 8002 F11034 1CF75B 0101C800
2014.05.29 20:17:50.912 4: CUL_Parse: myCUL A 0C 89 A041 1CF75B F11034 0106C816 -63
2014.05.29 20:17:51.096 4: CUL_send:  myCULAs 0D 89 8002 F11034 1CF75B 0101C800


SC Close (3 Retries, kein ACK, Timing ~200ms)
Code Auswählen

2014.05.29 20:17:56.399 4: CUL_Parse: myCUL A 0C 8A A441 1CF75B F11034 0107000D -67.5
2014.05.29 20:17:56.588 4: CUL_send:  myCULAs 0D 8A 8002 F11034 1CF75B 0101C800
2014.05.29 20:17:56.682 4: CUL_Parse: myCUL A 0C 8A A041 1CF75B F11034 01070005 -71.5
2014.05.29 20:17:56.867 4: CUL_send:  myCULAs 0D 8A 8002 F11034 1CF75B 0101C800
2014.05.29 20:17:57.162 4: CUL_Parse: myCUL A 0C 8A A041 1CF75B F11034 010700FD -75.5
2014.05.29 20:17:57.349 4: CUL_send:  myCULAs 0D 8A 8002 F11034 1CF75B 0101C800


Evtl. sind 200ms zu lang? Nun habe ich mal den o.g. "Patch" eingebaut, der erst vielversprechend aussah. Aber der verbessert es nur leicht:

Gefrickelt mit IO Assign im If:

SC Open, kein Ack, (Timing ~200ms)
Code Auswählen

2014.05.29 20:21:49.415 4: CUL_Parse: myCUL A 0C 8F A441 1CF75B F11034 010CC813 -64.5
2014.05.29 20:21:49.608 4: CUL_send:  myCULAs 0D 8F 8002 F11034 1CF75B 0101C800
2014.05.29 20:21:49.762 4: CUL_Parse: myCUL A 0C 8F A041 1CF75B F11034 010CC812 -65
2014.05.29 20:21:50.177 4: CUL_Parse: myCUL A 0C 8F A041 1CF75B F11034 010CC810 -66
2014.05.29 20:21:50.363 4: CUL_send:  myCULAs 0D 8F 8002 F11034 1CF75B 0101C800


SC Close, Ack (Timing beim letzten Retry passt wieder mit ~100ms)
Code Auswählen

2014.05.29 20:21:55.165 4: CUL_Parse: myCUL A 0C 90 A441 1CF75B F11034 010D0010 -66
2014.05.29 20:21:55.362 4: CUL_send:  myCULAs 0D 90 8002 F11034 1CF75B 0101C800
2014.05.29 20:21:55.453 4: CUL_Parse: myCUL A 0C 90 A041 1CF75B F11034 010D000C -68
2014.05.29 20:21:55.928 4: CUL_Parse: myCUL A 0C 90 A041 1CF75B F11034 010D000D -67.5
2014.05.29 20:21:56.031 4: CUL_send:  myCULAs 0D 90 8002 F11034 1CF75B 0101C800


Braucht die Methode CUL_HM_assignIO evtl. zu lang? Ich teste jetzt noch mal die 5989 aus dem trunk.
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: Andre am 29 Mai 2014, 20:39:58
Und hier noch die aktuellste 5988, jeweils auch kein ACK.

SC Open
Code Auswählen

2014.05.29 20:38:08.479 4: CUL_Parse: myCUL A 0C 93 A441 1CF75B F11034 0110C815 -63.5
2014.05.29 20:38:08.670 4: CUL_send:  myCULAs 0D 93 8002 F11034 1CF75B 0101C800
2014.05.29 20:38:08.815 4: CUL_Parse: myCUL A 0C 93 A041 1CF75B F11034 0110C815 -63.5
2014.05.29 20:38:08.996 4: CUL_send:  myCULAs 0D 93 8002 F11034 1CF75B 0101C800
2014.05.29 20:38:09.241 4: CUL_Parse: myCUL A 0C 93 A041 1CF75B F11034 0110C815 -63.5
2014.05.29 20:38:09.453 4: CUL_send:  myCULAs 0D 93 8002 F11034 1CF75B 0101C800


SC Close
Code Auswählen

2014.05.29 20:38:11.978 4: CUL_Parse: myCUL A 0C 94 A441 1CF75B F11034 0111000C -68
2014.05.29 20:38:12.162 4: CUL_send:  myCULAs 0D 94 8002 F11034 1CF75B 0101C800
2014.05.29 20:38:12.254 4: CUL_Parse: myCUL A 0C 94 A041 1CF75B F11034 01110000 -74
2014.05.29 20:38:12.440 4: CUL_send:  myCULAs 0D 94 8002 F11034 1CF75B 0101C800
2014.05.29 20:38:12.740 4: CUL_Parse: myCUL A 0C 94 A041 1CF75B F11034 011100FF -74.5
2014.05.29 20:38:12.922 4: CUL_send:  myCULAs 0D 94 8002 F11034 1CF75B 0101C800


Bei der FB sieht das ähnlich aus, vielleicht ist die toleranter beim Timing?
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: martinp876 am 30 Mai 2014, 09:46:49
Hi,

ganz klar ein timingproblem. statt 100ms wird um 200ms verzögert - das ist grenzwertig - kann manchmal klappen.

Ohne SC habe ich mit einer FB RC12 getestet - mit einem virtuellen Aktor gepeert. Die Antwort der CUL kommt sauber nach 100ms.
Sicherheitshalber: Du bist auf dem neusten Stand - auch bei 00_CUL

Gruss Martin
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: Andre am 30 Mai 2014, 10:08:15
Hi,

ja, alle Files sind aktuell aus dem trunk.

Grüße
André
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: martinp876 am 30 Mai 2014, 10:59:52
schalte einmal verbose 5 ein für das loggen
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: Andre am 30 Mai 2014, 13:37:06
Hi,

hier mit verbose 5, ich bin nicht ganz sicher ob ich die richtigen Open und Close Nachrichten korrekt zusammengebastelt habe. (Beim open ist scheinbar eine raw Message doppelt gekommen?) Kann es später noch mal sauberer aufnehmen wenn notwendig, aber momentan kann ich an der Tür niemanden überreden ;)

SC Open
Code Auswählen

2014.05.30 13:20:42.415 5: CUL/RAW: /A0CA4A4411CF75BF110340120C8E6
A0CA4A0411CF75BF110340120C8EB

2014.05.30 13:20:42.420 4: CUL_Parse: myCUL A 0C A4 A441 1CF75B F11034 0120C8E6 -87
2014.05.30 13:20:42.424 5: myCUL dispatch A0CA4A4411CF75BF110340120C8::-87:myCUL
2014.05.30 13:20:42.628 5: myCUL sending As0DA48002F110341CF75B0101C800
2014.05.30 13:20:42.632 4: CUL_send:  myCULAs 0D A4 8002 F11034 1CF75B 0101C800
2014.05.30 13:20:42.739 4: CUL_Parse: myCUL A 0C A4 A041 1CF75B F11034 0120C8EB -84.5
2014.05.30 13:20:42.743 5: myCUL dispatch A0CA4A0411CF75BF110340120C8::-84.5:myCUL
2014.05.30 13:20:42.940 5: myCUL sending As0DA48002F110341CF75B0101C800
2014.05.30 13:20:42.944 4: CUL_send:  myCULAs 0D A4 8002 F11034 1CF75B 0101C800
2014.05.30 13:20:42.968 5: CUL/RAW: /A0CA4A0411CF75BF110340120C8EF

2014.05.30 13:20:42.973 4: CUL_Parse: myCUL A 0C A4 A041 1CF75B F11034 0120C8EF -82.5
2014.05.30 13:20:42.977 5: myCUL dispatch A0CA4A0411CF75BF110340120C8::-82.5:myCUL


SC Close
Code Auswählen

2014.05.30 13:21:12.641 5: CUL/RAW: /A0CA5A4411CF75BF11034012100F1

2014.05.30 13:21:12.645 4: CUL_Parse: myCUL A 0C A5 A441 1CF75B F11034 012100F1 -81.5
2014.05.30 13:21:12.649 5: myCUL dispatch A0CA5A4411CF75BF11034012100::-81.5:myCUL
2014.05.30 13:21:12.847 5: myCUL sending As0DA58002F110341CF75B0101C800
2014.05.30 13:21:12.851 4: CUL_send:  myCULAs 0D A5 8002 F11034 1CF75B 0101C800
2014.05.30 13:21:13.404 5: CUL/RAW: /A0CA5A0411CF75BF11034012100F1

2014.05.30 13:21:13.410 4: CUL_Parse: myCUL A 0C A5 A041 1CF75B F11034 012100F1 -81.5
2014.05.30 13:21:13.414 5: myCUL dispatch A0CA5A0411CF75BF11034012100::-81.5:myCUL
2014.05.30 13:21:13.611 5: myCUL sending As0DA58002F110341CF75B0101C800
2014.05.30 13:21:13.616 4: CUL_send:  myCULAs 0D A5 8002 F11034 1CF75B 0101C800
2014.05.30 13:21:14.639 5: CUL/RAW: /A0CA6A4411CF75BF110340122C8F1

2014.05.30 13:21:14.643 4: CUL_Parse: myCUL A 0C A6 A441 1CF75B F11034 0122C8F1 -81.5
2014.05.30 13:21:14.647 5: myCUL dispatch A0CA6A4411CF75BF110340122C8::-81.5:myCUL
2014.05.30 13:21:14.844 5: myCUL sending As0DA68002F110341CF75B0101C800
2014.05.30 13:21:14.848 4: CUL_send:  myCULAs 0D A6 8002 F11034 1CF75B 0101C800
2014.05.30 13:21:15.403 5: CUL/RAW: /A0CA6A0411CF75BF110340122C8F1

2014.05.30 13:21:15.407 4: CUL_Parse: myCUL A 0C A6 A041 1CF75B F11034 0122C8F1 -81.5
2014.05.30 13:21:15.411 5: myCUL dispatch A0CA6A0411CF75BF110340122C8::-81.5:myCUL
2014.05.30 13:21:15.610 5: myCUL sending As0DA68002F110341CF75B0101C800
2014.05.30 13:21:15.615 4: CUL_send:  myCULAs 0D A6 8002 F11034 1CF75B 0101C800
2014.05.30 13:21:15.665 5: CUL/RAW: /A0CA7A4411CF75BF11034012300F2

2014.05.30 13:21:15.669 4: CUL_Parse: myCUL A 0C A7 A441 1CF75B F11034 012300F2 -81
2014.05.30 13:21:15.673 5: myCUL dispatch A0CA7A4411CF75BF11034012300::-81:myCUL
2014.05.30 13:21:15.872 5: myCUL sending As0DA78002F110341CF75B0101C800
2014.05.30 13:21:15.877 4: CUL_send:  myCULAs 0D A7 8002 F11034 1CF75B 0101C800
2014.05.30 13:21:16.427 5: CUL/RAW: /A0CA7A0411CF75BF11034012300F0

2014.05.30 13:21:16.431 4: CUL_Parse: myCUL A 0C A7 A041 1CF75B F11034 012300F0 -82
2014.05.30 13:21:16.435 5: myCUL dispatch A0CA7A0411CF75BF11034012300::-82:myCUL
2014.05.30 13:21:16.630 5: myCUL sending As0DA78002F110341CF75B0101C800
2014.05.30 13:21:16.634 4: CUL_send:  myCULAs 0D A7 8002 F11034 1CF75B 0101C800


Nach dem CUL/RAW kommt immer eine Leerzeile, wäre die nicht praktischer vor dem CUL/RAW? Wenn ich es richtig verstehe gehört doch der Block danach zu der CUL/RAW Message, oder?

Gruß
André
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: martinp876 am 30 Mai 2014, 15:52:12
Zitathier mit verbose 5, ich bin nicht ganz sicher ...
alles prima.

13:20:42.420 4: CUL_Parse: myCUL A 0C A4 A441 1CF75B F11034 0120C8
13:20:42.424 5: myCUL dispatch A0CA4A4411CF75BF110340120
warten 200ms
13:20:42.628 5: myCUL sending As0DA48002F110341CF75B0101C800
13:20:42.632 4: CUL_send:  myCULAs 0D A4 8002 F11034 1CF75B 0101C800

Ich habe ein potentielles Delay eingebaut zwischen  myCUL sending und CUL_send - in der Art
15:42:11.124 5: iocu1 sending As0AFD80021743BF18ACF100
15:42:11.126 5: CUL 18ACF1 dly:80ms
15:42:11.209 4: CUL_send:  iocu1As 0A FD 8002 1743BF 18ACF1 00

In deinem Fall ist also klar, dass das Delay nichts mit den 100ms zu tun hat, die ich programmiert habe. CUL_HM habe ich nicht in verdacht.... es muss also ein anderer Programmteil sein. So könnten es z.b. trigger sein. Mache 2 Versuche

1) Alles triggern
attr global verbose 5
=> loggen

2) apptime
attr global verbose 1
apptime clear
=> fenster auf
apptime maxDly all

Gruss Martin

Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: Andre am 30 Mai 2014, 16:23:35
Hi,

hier schon mal der global verbose 5, apptime reiche ich nach:

SC Open
Code Auswählen

2014.05.30 16:15:51.321 5: CUL/RAW: /A0CABA4411CF75BF110340126C804

2014.05.30 16:15:51.324 4: CUL_Parse: myCUL A 0C AB A441 1CF75B F11034 0126C804 -72
2014.05.30 16:15:51.327 5: myCUL dispatch A0CABA4411CF75BF110340126C8::-72:myCUL
2014.05.30 16:15:51.510 5: CUL_HM eg_FensterGarage prep ACK for 01
2014.05.30 16:15:51.514 5: myCUL sending As0DAB8002F110341CF75B0101C800
2014.05.30 16:15:51.518 4: CUL_send:  myCULAs 0D AB 8002 F11034 1CF75B 0101C800
2014.05.30 16:15:51.532 5: CUL_HM eg_FensterGarage protEvent:CMDs_done
2014.05.30 16:15:51.535 5: CUL_HM eg_FensterGarage sent ACK:2
2014.05.30 16:15:51.542 5: Triggering eg_FensterGarage (3 changes)
2014.05.30 16:15:51.545 5: Notify loop for eg_FensterGarage battery: ok
2014.05.30 16:15:51.556 4: eventTypes: CUL_HM eg_FensterGarage battery: ok -> battery: ok
2014.05.30 16:15:51.559 4: eventTypes: CUL_HM eg_FensterGarage open -> open
2014.05.30 16:15:51.562 4: eventTypes: CUL_HM eg_FensterGarage contact: open (to myCUL) -> contact: open (to myCUL)
2014.05.30 16:15:51.565 4: eventTypes: CUL_HM eg_FensterGarage state: open -> state: open
2014.05.30 16:15:51.571 5: Triggering n_on_FensterGarage
2014.05.30 16:15:51.576 4: n_on_FensterGarage exec {
  if (Value("eg_FensterGarage") eq "closed")  {
    fhem("set Aussentuer_Garage zu")
  } else {
    fhem("set Aussentuer_Garage offen")
  }
}
2014.05.30 16:15:51.580 5: Cmd: >{
  if (Value("eg_FensterGarage") eq "closed")  {
    fhem("set Aussentuer_Garage zu")
  } else {
    fhem("set Aussentuer_Garage offen")
  }
}<
2014.05.30 16:15:51.590 5: Cmd: >set Aussentuer_Garage offen<
2014.05.30 16:15:51.594 4: dummy set Aussentuer_Garage offen
2014.05.30 16:15:51.597 5: Triggering Aussentuer_Garage (1 changes)
2014.05.30 16:15:51.600 5: Notify loop for Aussentuer_Garage offen
2014.05.30 16:15:51.609 4: eventTypes: dummy Aussentuer_Garage offen -> offen
2014.05.30 16:15:51.612 4: eventTypes: dummy Aussentuer_Garage state: offen -> state: offen
2014.05.30 16:15:51.616 5: Triggering n_on_Aussentuer
2014.05.30 16:15:51.622 4: n_on_Aussentuer exec {
  if (Value("ANLAGE_STATUS") eq "scharf" || Value("ANLAGE_STATUS") eq "scharf_intern")  {
    fhem("set ALARM_STATUS ALARM")
  }
}
2014.05.30 16:15:51.625 5: Cmd: >{
  if (Value("ANLAGE_STATUS") eq "scharf" || Value("ANLAGE_STATUS") eq "scharf_intern")  {
    fhem("set ALARM_STATUS ALARM")
  }
}<
2014.05.30 16:15:51.649 5: Triggering n_prowl_fenster
2014.05.30 16:15:51.653 4: n_prowl_fenster exec {
  if ("$value{ANLAGE_STATUS}" eq "scharf") {
    prowl("Tuer auf: eg_FensterGarage", "EG", "1")
}
}
2014.05.30 16:15:51.657 5: Cmd: >{
  if ("$value{ANLAGE_STATUS}" eq "scharf") {
    prowl("Tuer auf: eg_FensterGarage", "EG", "1")
}
}<
2014.05.30 16:15:51.669 5: rd_Fenster: not on any display, ignoring notify
2014.05.30 16:15:51.698 5: CUL/RAW: /A0CABA0411CF75BF110340126C8FA

2014.05.30 16:15:51.701 4: CUL_Parse: myCUL A 0C AB A041 1CF75B F11034 0126C8FA -77
2014.05.30 16:15:51.704 5: myCUL dispatch A0CABA0411CF75BF110340126C8::-77:myCUL
2014.05.30 16:15:51.889 5: myCUL sending As0DAB8002F110341CF75B0101C800
2014.05.30 16:15:51.892 4: CUL_send:  myCULAs 0D AB 8002 F11034 1CF75B 0101C800
2014.05.30 16:15:51.906 5: CUL_HM eg_FensterGarage protEvent:CMDs_done
2014.05.30 16:15:51.909 4: CUL_HM eg_FensterGarage dupe: repeat 2 ack, dont process
2014.05.30 16:15:51.932 4: HTTP FHEMWEB:192.168.2.117:61012 GET /fhem/images/default/signal_Fenster_Offen.on.png
2014.05.30 16:15:52.085 5: CUL/RAW: /A0CABA0411CF75BF110340126C8FC

2014.05.30 16:15:52.088 4: CUL_Parse: myCUL A 0C AB A041 1CF75B F11034 0126C8FC -76
2014.05.30 16:15:52.091 5: myCUL dispatch A0CABA0411CF75BF110340126C8::-76:myCUL
2014.05.30 16:15:52.276 5: myCUL sending As0DAB8002F110341CF75B0101C800
2014.05.30 16:15:52.280 4: CUL_send:  myCULAs 0D AB 8002 F11034 1CF75B 0101C800
2014.05.30 16:15:52.294 5: CUL_HM eg_FensterGarage protEvent:CMDs_done
2014.05.30 16:15:52.296 4: CUL_HM eg_FensterGarage dupe: repeat 2 ack, dont process


SC Close
Code Auswählen

2014.05.30 16:16:03.279 5: CUL/RAW: /T630200A
2014.05.30 16:16:03.290 5: CUL/RAW: T630200A/A0010

2014.05.30 16:16:03.291 4: CUL_Parse: myCOC T630200AA0010 -66
2014.05.30 16:16:03.293 5: myCOC dispatch 810c04xx0909a00163020000aa00
2014.05.30 16:16:03.301 4: FHT og_TempStaffelgeschoss actuator: 0%
2014.05.30 16:16:03.305 5: Triggering og_TempStaffelgeschoss (1 changes)
2014.05.30 16:16:03.307 5: Notify loop for og_TempStaffelgeschoss actuator: 0%
2014.05.30 16:16:03.318 4: eventTypes: FHT og_TempStaffelgeschoss actuator: 0% -> actuator: .*%
2014.05.30 16:16:03.822 5: CUL/RAW: /A0CACA4411CF75BF11034012700E1

2014.05.30 16:16:03.825 4: CUL_Parse: myCUL A 0C AC A441 1CF75B F11034 012700E1 -89.5
2014.05.30 16:16:03.828 5: myCUL dispatch A0CACA4411CF75BF11034012700::-89.5:myCUL
2014.05.30 16:16:04.010 5: CUL_HM eg_FensterGarage prep ACK for 01
2014.05.30 16:16:04.014 5: myCUL sending As0DAC8002F110341CF75B0101C800
2014.05.30 16:16:04.017 4: CUL_send:  myCULAs 0D AC 8002 F11034 1CF75B 0101C800
2014.05.30 16:16:04.031 5: CUL_HM eg_FensterGarage protEvent:CMDs_done
2014.05.30 16:16:04.034 5: CUL_HM eg_FensterGarage sent ACK:2
2014.05.30 16:16:04.041 5: Triggering eg_FensterGarage (3 changes)
2014.05.30 16:16:04.043 5: Notify loop for eg_FensterGarage battery: ok
2014.05.30 16:16:04.055 4: eventTypes: CUL_HM eg_FensterGarage battery: ok -> battery: ok
2014.05.30 16:16:04.057 4: eventTypes: CUL_HM eg_FensterGarage closed -> closed
2014.05.30 16:16:04.060 4: eventTypes: CUL_HM eg_FensterGarage contact: closed (to myCUL) -> contact: closed (to myCUL)
2014.05.30 16:16:04.063 4: eventTypes: CUL_HM eg_FensterGarage state: closed -> state: closed
2014.05.30 16:16:04.069 5: Triggering n_on_FensterGarage
2014.05.30 16:16:04.075 4: n_on_FensterGarage exec {
  if (Value("eg_FensterGarage") eq "closed")  {
    fhem("set Aussentuer_Garage zu")
  } else {
    fhem("set Aussentuer_Garage offen")
  }
}
2014.05.30 16:16:04.078 5: Cmd: >{
  if (Value("eg_FensterGarage") eq "closed")  {
    fhem("set Aussentuer_Garage zu")
  } else {
    fhem("set Aussentuer_Garage offen")
  }
}<
2014.05.30 16:16:04.089 5: Cmd: >set Aussentuer_Garage zu<
2014.05.30 16:16:04.092 4: dummy set Aussentuer_Garage zu
2014.05.30 16:16:04.096 5: Triggering Aussentuer_Garage (1 changes)
2014.05.30 16:16:04.099 5: Notify loop for Aussentuer_Garage zu
2014.05.30 16:16:04.108 4: eventTypes: dummy Aussentuer_Garage zu -> zu
2014.05.30 16:16:04.110 4: eventTypes: dummy Aussentuer_Garage state: zu -> state: zu
2014.05.30 16:16:04.131 5: rd_Fenster: not on any display, ignoring notify
2014.05.30 16:16:04.155 5: CUL/RAW: /A0CACA0411CF75BF11034012700E7

2014.05.30 16:16:04.158 4: CUL_Parse: myCUL A 0C AC A041 1CF75B F11034 012700E7 -86.5
2014.05.30 16:16:04.161 5: myCUL dispatch A0CACA0411CF75BF11034012700::-86.5:myCUL
2014.05.30 16:16:04.347 5: myCUL sending As0DAC8002F110341CF75B0101C800
2014.05.30 16:16:04.351 4: CUL_send:  myCULAs 0D AC 8002 F11034 1CF75B 0101C800
2014.05.30 16:16:04.365 5: CUL_HM eg_FensterGarage protEvent:CMDs_done
2014.05.30 16:16:04.368 4: CUL_HM eg_FensterGarage dupe: repeat 2 ack, dont process
2014.05.30 16:16:04.390 4: HTTP FHEMWEB:192.168.2.117:61012 GET /fhem/images/default/signal_Fenster_Offen.off.png
2014.05.30 16:16:04.584 5: CUL/RAW: /A0CACA0411CF75BF11034012700F0

2014.05.30 16:16:04.587 4: CUL_Parse: myCUL A 0C AC A041 1CF75B F11034 012700F0 -82
2014.05.30 16:16:04.590 5: myCUL dispatch A0CACA0411CF75BF11034012700::-82:myCUL
2014.05.30 16:16:04.770 5: myCUL sending As0DAC8002F110341CF75B0101C800
2014.05.30 16:16:04.774 4: CUL_send:  myCULAs 0D AC 8002 F11034 1CF75B 0101C800
2014.05.30 16:16:04.788 5: CUL_HM eg_FensterGarage protEvent:CMDs_done
2014.05.30 16:16:04.791 4: CUL_HM eg_FensterGarage dupe: repeat 2 ack, dont process


Gruß
André
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: Andre am 30 Mai 2014, 16:27:13
Und hier apptime:

Code Auswählen

name             function    max  count    total  average maxDly
                   tmr-CUL_HM_procQs        CUL_HM_procQs      1     21       21     1.00    138 CUL_HM_procQs
                   Aussentuer_Garage            dummy_Set     40      1       40    40.00      0 HASH(0x1996000); Aussentuer_Garage; offen
         FHEMWEB:192.168.2.117:61199            FW_Notify      0      3        0     0.00      0
         FHEMWEB:192.168.2.117:61199              FW_Read     14      6       35     5.83      0 HASH(0x240b1b8)
         FHEMWEB:192.168.2.117:61200              FW_Read      4      4       16     4.00      0 HASH(0x195f688)
         FHEMWEB:192.168.2.117:61201              FW_Read      4      2        8     4.00      0 HASH(0x1968df0)
         FHEMWEB:192.168.2.117:61202              FW_Read      6      3       10     3.33      0 HASH(0x195f508)
         FHEMWEB:192.168.2.117:61203              FW_Read      4      2        8     4.00      0 HASH(0x23e5e90)
         FHEMWEB:192.168.2.117:61204              FW_Read      4      1        4     4.00      0 HASH(0x21918d0)
FileLog_CUL_HM_blindActuator_1B80B3          FileLog_Log      1      3        1     0.33      0 HASH(0x1961b40); HASH(0x181bfc8)
                    FileLog_FHT_6302          FileLog_Log      0      3        0     0.00      0
            FileLog_eg_FensterGarage          FileLog_Log      1      1        1     1.00      0 HASH(0x181c4f0); HASH(0x181bfc8)
          FileLog_og_ActuatorLeandro          FileLog_Log      1      1        1     1.00      0 HASH(0x182cfe8); HASH(0x181e138)
      FileLog_og_TempStaffelgeschoss          FileLog_Log      1      3        2     0.67      0 HASH(0x190d318); HASH(0x181e138)
                             Logfile          FileLog_Log      0      3        0     0.00      0
                            RSSI.log          FileLog_Log      2      3        2     0.67      0 HASH(0x1a98a20); HASH(0x181bfc8)
                                 WEB            FW_Notify      0      3        0     0.00      0
                                 WEB              FW_Read      4      5       13     2.60      0 HASH(0x11dec70)
                            WEBphone            FW_Notify      0      3        0     0.00      0
                           WEBtablet            FW_Notify      0      3        0     0.00      0
                          eventTypes    eventTypes_Notify      1      3        1     0.33      0 HASH(0x206a540); HASH(0x181bfc8)
                               myCOC             CUL_Read     74      2       74    37.00      0 HASH(0xf7c130)
                               myCUL             CUL_Read    305      3      701   233.67      0 HASH(0x1119658)
                       n_battery_chk          notify_Exec      0      3        0     0.00      0
                      n_daylight_off          notify_Exec      0      3        0     0.00      0
                       n_daylight_on          notify_Exec      0      3        0     0.00      0
                 n_hm_virtual_answer          notify_Exec      0      3        0     0.00      0
                      n_mail_fenster          notify_Exec      0      3        0     0.00      0
                     n_on_Aussentuer          notify_Exec     11      3       12     4.00      0 HASH(0x1996b18); HASH(0x1996000)
                  n_on_FensterGarage          notify_Exec     54      1       54    54.00      0 HASH(0x19966c0); HASH(0x181bfc8)
                n_on_FensterTerrasse          notify_Exec      1      3        1     0.33      0 HASH(0x1996558); HASH(0x181bfc8)
                     n_prowl_fenster          notify_Exec     11      3       11     3.67      0 HASH(0x18c7670); HASH(0x181bfc8)
                            n_rc_all          notify_Exec      1      3        1     0.33      0 HASH(0x1904358); HASH(0x181bfc8)
                        n_test_prowl          notify_Exec      0      3        0     0.00      0
                          rd_Fenster readingsGroup_Notify      0      3        0     0.00      0
                             rd_RSSI readingsGroup_Notify      0      3        0     0.00      0
                        rd_Verbrauch readingsGroup_Notify      0      3        0     0.00      0
                    red_Temperaturen readingsGroup_Notify      0      3        0     0.00      0
                        w_FensterBad      watchdog_Notify      1      3        1     0.33      0 HASH(0x2130e28); HASH(0x1996000)
                     w_FensterGarage      watchdog_Notify      2      3        2     0.67      0 HASH(0x2130fb0); HASH(0x181bfc8)
                   w_FensterHaustuer      watchdog_Notify      0      3        0     0.00      0
                     w_FensterKueche      watchdog_Notify      0      3        0     0.00      0
                   w_FensterTerrasse      watchdog_Notify      1      3        1     0.33      0 HASH(0x2131280); HASH(0x181bfc8)


Gruß
André
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: martinp876 am 30 Mai 2014, 16:45:15
da sehe ich erst einmal nicht viel.
Hast du eine recht grosse Datenbank?
Es dauert von Dispatch bis Ende des parsens CUL_HM die fehlenden 180ms - bei mir ist dies kleiner 20ms.

Ach: hmProtocolEvents hast du nicht etwa an? Das ist sowieso ein killer. Level 3 auf keinen Fall...

Ansonsten baue ich eine instrumentierte Version um den Delay einzukreisen

Gruss Martin
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: Andre am 30 Mai 2014, 18:47:13
Hi,

hmProtocolEvents hab ich gar nicht gesetzt, nein. Die config hab ich noch im File (aufgeteilt in 3-4 Files). In Summe aber nicht so super lang, nicht besonders viel Code, ca 180 Entities.

Gruß
André
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: martinp876 am 30 Mai 2014, 19:02:10
jetzt müssen wir einmal in die Tiefe gehen.
Kannst du die Datei im Anhang einmal laden und dann den Test machen?
Mir ist wirklich unklar, wer hier 200ms brauchen soll - und auch nich so präzise

Gruss Martin
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: Andre am 30 Mai 2014, 19:22:55
Klar:

Code Auswählen

2014.05.30 19:21:48.548 4: CUL_Parse: myCUL A 0C AE A441 1CF75B F11034 012900F6 -79
2014.05.30 19:21:48.727 1: ###spy1 enter
2014.05.30 19:21:48.738 1: ###spy2 rssi
2014.05.30 19:21:48.740 1: ###spy3 dump
2014.05.30 19:21:48.743 1: ### spy common 1
2014.05.30 19:21:48.746 1: ###spy4 common
2014.05.30 19:21:48.749 1: ###spy5 examine
2014.05.30 19:21:48.755 4: CUL_send:  myCULAs 0D AE 8002 F11034 1CF75B 0101C800
2014.05.30 19:21:49.311 4: CUL_Parse: myCUL A 0C AE A041 1CF75B F11034 012900E1 -89.5
2014.05.30 19:21:49.485 1: ###spy1 enter
2014.05.30 19:21:49.492 1: ###spy2 rssi
2014.05.30 19:21:49.497 4: CUL_send:  myCULAs 0D AE 8002 F11034 1CF75B 0101C800


Die Zeit ist ja scheinbar schon zwischen CUL_Parse und CUL_HM_Parse weg, oder? Vor Deinem spy1 passiert ja nichts spektakuläres. Weiß nicht ob es weiterhilft, aber nur damit nichts "übersehen wird": Ich habe einen CUL und einen COC, der CUL ist auf Homematic, der andere auf slowRF. Scheinbar sind ja die Änderungen rund um assignIO involviert, vielleicht läuft hier irgend was schief....

Gruß
André
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: martinp876 am 31 Mai 2014, 08:59:02
Hallo Andre,

ZitatDie Zeit ist ja scheinbar schon zwischen CUL_Parse und CUL_HM_Parse weg, oder?
korrekt. Aus den vorigen Logs wissen wir, das CUL an den Kernal "übergeben" hat - genau an "Dispatch" in fhem.pl .
Dieser ruft den CUL_HM parser auf - da sollte nicht viel Zeit vergehen.

Wir müssen also die Dispatch funktion in fhem.pl analysieren. Die probiert, ob jemand die message brauchen kann - und da braucht wohl jemand recht lange. Das könnte dann schon eines der anderen Module sein

Gruß Martin
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: Andre am 02 Juni 2014, 11:00:21
Hi,

ich versuche jetzt das Timing genauer zu untersuchen, nur leider habe ich nicht immer Zugriff auf die Hardware (den Sensor). Es wäre super hilfreich, wenn ich die Message eines Fenstersensors simulieren könnte. Kann ich ein "dummy" Device in FHEM anlegen, welches sich so verhält wie ein Fenstersensor? Per webCmd könnte ich dann open und close simulieren und die Messages loggen. Es müssten natürlich echte Messages gesendet werden. Gibt es sowas? Ist hoffentlich keine komplett sinnlose Frage :)

Grüße
Andre
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: martinp876 am 02 Juni 2014, 11:20:09
perl ist da recht einfach zu stimulieren:

simuliere Close:
{my $in = "myCul";;CUL_Parse($defs{$in},$defs{$in},$in,"A0C89A4411CF75BF110340107000D");;return}

simuliere Open:
{my $in = "myCUL";;CUL_Parse($defs{$in},$defs{$in},$in,"A0C89A4411CF75BF11034010CC813");;return}
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: Andre am 02 Juni 2014, 11:30:58
Cool, das ist der Bringer, Danke! :)
Beim Close bekomme ich allerdings ein Unknown code,...,help me! Muss ich den noch anpassen?

Gruß
André
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: Andre am 02 Juni 2014, 17:38:33
Hi Martin,

ich habe ein paar Vergleiche mit dem Open Dummy angestellt. Für mich sieht es so aus, als wenn das Problem mit der Version 6030 wieder behoben ist. In Version 6008 ist es noch "Buggy". Hast Du da direkt eine Idee?

Da die Zeit ja in Dispatch() in fhem.pl liegenbleibt, habe ich da ein paar Messungen gemacht, und es sieht so aus, als ob die Zeit in der Funktion computeClientArray($$) verloren geht:

Code Auswählen

2014.06.02 17:27:18.058 1: myCUL Before computeClientArray
2014.06.02 17:27:18.227 1: myCUL After computeClientArray


In der Version 6008 von CUL_HM benötigt der Aufruf bei jedem Mal ~175ms, in der Version 6030 nur der erste Aufruf, alle nachfolgenden Aufrufe sind <10ms:

Code Auswählen

2014.06.02 17:28:30.904 1: myCUL Before computeClientArray
2014.06.02 17:28:30.907 1: myCUL After computeClientArray


Erscheint das plausibel oder doch kompletter Unsinn? Ich kann keine entsprechende Änderung in 10_CUL_HM.pm erkennen...

Gruß
André
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: martinp876 am 02 Juni 2014, 19:05:47
Die einzige Timing-änderung die mir bekannt ist, war das handling von "sortRooms". Das ist - je nach länge der Liste der Rooms - um faktor 10-20 beschleunigt worden.

in HM wurde nichts gemacht. War ja auch nicht das Problem.
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: Andre am 03 Juni 2014, 11:47:44
Hallo Martin,

ist ja mittlerweile schon gelöst, aber da ich es mir solange angeschaut hatte, wollte ich es noch verstehen. Die relevante Änderung in 10_CUL_HM.pm (6008 -> 6030), die das Problem mit dem Timing fixt, ist folgende:

Vorher (6008). Hier wird immer AssignIoPort im Kernel aufgerufen, auch wenn sich das IODev nicht ändert:
Code Auswählen

  # not assigned thru CCU - try normal
  my $dIo = AttrVal($hn,"IODev","");
  if ($dIo && $defs{$dIo} && $dIo ne $hash->{IODev}->{NAME}){
    $hash->{IODev} = $defs{$dIo};
  }
  else{
    AssignIoPort($hash);#let kernal decide
  }


Nachher (6030). Hier wird AssignIoPort im Kernel nur aufgerufen, wenn keins (?) definiert ist.
Code Auswählen

  # not assigned thru CCU - try normal
  my $dIo = AttrVal($hash->{NAME},"IODev","");
  if ($defs{$dIo}){
    if($dIo ne $hash->{IODev}->{NAME}){
      $hash->{IODev} = $defs{$dIo};
    }
  }
  else{
    AssignIoPort($hash);#let kernal decide
  }


AssignIoPort wiederum sorgt im Kernel dafür, dass computeClientArray() in Dispatch jedes Mal aufgerufen wird, da .clientArray in AssignIoPort gelöscht wird.

Relevanter Teil in Dispatch():
Code Auswählen

my $clientArray = $hash->{".clientArray"};
$clientArray = computeClientArray($hash, $module) if(!$clientArray);


Der Aufruf von computeClientArray benötigt (zumindest bei mir) immer ~175ms, daher war das Timing jedes Mal off. Ist vielleicht interessant falls es in ähnlicher Form nochmal auftaucht.

Eine offene Frage habe ich noch. Das Simulieren des Öffnens funktioniert ja wunderbar, nur beim Schließen bekomme ich weiterhin "Unknown code,...,help me!". Ich habe auch mal eine andere, echte Message für das Öffnen und Schließen kopiert und getestet, da geht jeweils auch nur "Öffnen". Hast Du da eine Idee woran das liegt?

Vielen (vielen) Dank für Deine Hilfe!

Grüße
Andre
Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: martinp876 am 03 Juni 2014, 12:44:37
Hallo Andre,

habe ich nicht - hat bei mir auch funktioniert.
simuliere Close:
{my $in = "myCul";;CUL_Parse($defs{$in},$defs{$in},$in,"A0C89A4411CF75BF110340107000D");;return}

simuliere Open:
{my $in = "myCUL";;CUL_Parse($defs{$in},$defs{$in},$in,"A0C89A4411CF75BF11034010CC813");;return}

die messages müssen sich eigentlich nur in 00 (0=>0%=>zu)
und C8 (200=>100%=>offen)
underscheiden.
Dass es bei dir nicht funktioniert bedeuted, dass keiner (auch nicht CUL_HM) die message bearbeitet hat. Wichtig ist, dass die Adressen und flags gleich sind

A0CnnA4411CF75BF1103401bbC8xx
nn = message nummer
bb = nummer des Button events
xx = egal, nicht dekodiert

Ich vermute, du hast einen kopierfehler drin

Gruss Martin


Titel: Antw:Probleme beim ACK (Version 5866 -> 5912)
Beitrag von: Andre am 03 Juni 2014, 14:33:14
Hi Martin,

musste lange scharf hinschauen  ;)

Zitat
{my $in = "myCul";;CUL_Parse($defs{$in},$defs{$in},$in,"A0C89A4411CF75BF110340107000D");;return}

Danke für die Erläuterung.

Gruß
Martin
Nur Text | Text mit Bildern