Endlos-Schleife: CMDs_pending <=> RESPONSE TIMEOUT:RegisterRead

frank · 30 Dezember 2014, 12:44:17

hallo martin,

nach update von 10_cul_hm/98_hminfo/hmconfig (jeweils version 7355) gerade eben aus svn beobachte ich an einem HM-LC-Sw1PBU-FM-CustomFW eine endlosschleife. das fing wohl direkt nach shutdown restart an. der reale schalter kann auch nicht erreicht werden, da er gerade ausgebaut ist.

list device:

Code Auswählen

Internals: 
   .triggerUsed 1 
   DEF        266E75 
   IODev      hmusb1 
   NAME       SwitchPBU02 
   NR         459 
   STATE      RESPONSE TIMEOUT:RegisterRead 
   TYPE       CUL_HM 
   channel_01 SwitchPBU02_Btn_01 
   channel_02 SwitchPBU02_Btn_02 
   channel_03 SwitchPBU02_Sw_01 
   channel_04 SwitchPBU02_Sw_02 
   protCmdDel 389 
   protResnd  132 last_at:2014-12-30 12:10:50 
   protResndFail 44 last_at:2014-12-30 12:10:56 
   protSnd    44 last_at:2014-12-30 12:10:37 
   protState  CMDs_done_Errors:1 
   Readings: 
     2014-11-02 17:42:40   .D-devInfo      410100 
     2014-11-02 17:42:40   .D-stc          10 
     2014-11-03 19:48:46   .protLastRcv    2014-11-03 19:48:46 
     2014-11-03 18:49:39   CommandAccepted no 
     2014-11-02 17:42:40   D-firmware      1.4 
     2014-11-03 18:49:49   D-serialNr      KEQ1109797 
     2014-11-03 16:30:24   PairedTo        0x1ACE1F 
     2014-11-03 16:29:15   R-autoBoot      undef lit:0 
     2014-11-03 16:29:15   R-intKeyVisib   invisib 
     2014-11-03 16:29:15   R-ledMode       off 
     2014-11-03 16:30:02   R-pairCentral   0x1ACE1F 
     2014-11-03 17:50:25   fwUpdate        fail:Block3 
     2014-11-02 17:43:28   sabotageAttack  ErrIoAttack cnt:3 
     2014-12-30 12:10:56   state           RESPONSE TIMEOUT:RegisterRead 
     Regl_00:: 
       VAL 
   Helper: 
     cSnd       011ACE1F266E7500040000000000 
     mId        F0A9 
     rxType     1 
     Bm: 
       Cul_hm_get: 
         cnt        8 
         dmx        0 
         max        1 
         tot        8 
         mAr: 
           HASH(0x143f0b0) 
           SwitchPBU02 
           ? 
       Cul_hm_set: 
         cnt        113 
         dmx        0 
         max        134 
         tot        482 
         mAr: 
           HASH(0x143f0b0) 
           SwitchPBU02 
           getConfig 
     Io: 
       newChn     +266E75,00,01,00 
       rxt        0 
       vccu       ccu 
       p: 
         266E75 
         00 
         01 
         00 
       prefIO: 
         hmusb1 
     Mrssi: 
       mNo 
       Io: 
     Prt: 
       bErr       0 
       sProc      0 
     Q: 
       qReqConf   00 
       qReqStat 
     Role: 
       dev        1 
     Rssi: 
     Shadowreg: 
Attributes: 
   IODev      hmusb1 
   IOgrp      ccu:hmusb1 
   autoReadReg 5_readMissing 
   event-on-change-reading .* 
   expert     2_full 
   firmware   1.4 
   group      Beleuchtung 
   model      HM-LC-Sw1PBU-FM-CustomFW 
   room       20_AZ 
   serialNr   KEQ1109797 
   subType    remoteAndSwitch 
   webCmd     getConfig:clear msgEvents

log:

Code Auswählen

2014.12.30 11:46:27.851 1: Including fhem.cfg
2014.12.30 11:46:30.810 1: HMLAN_Parse: hmusb1 new condition disconnected
2014.12.30 11:46:30.872 1: HMLAN_Parse: hmusb1 new condition init
2014.12.30 11:46:30.902 1: HMLAN_Parse: hmlan1 new condition disconnected
2014.12.30 11:46:30.919 1: HMLAN_Parse: hmlan1 new condition init
2014.12.30 11:46:48.617 1: Including ./log/fhem.save
2014.12.30 11:46:55.210 1: HCS BROETJE monitoring of devices started
2014.12.30 11:46:56.156 1: PERL WARNING: Subroutine HandleTimeout redefined at ./FHEM/98_apptime.pm line 24.
2014.12.30 11:46:56.163 1: PERL WARNING: Subroutine CallFn redefined at ./FHEM/98_apptime.pm line 58.
2014.12.30 11:46:56.484 0: Server started with 326 defined entities (version $Id: fhem.pl 6913 2014-11-08 10:32:44Z rudolfkoenig $, os linux, user root, pid 3695)
2014.12.30 11:46:56.526 1: Perfmon: possible freeze starting at 11:46:28, delay is 28.525
2014.12.30 11:46:57.092 1: PERL WARNING: Use of uninitialized value $nextTimer in concatenation (.) or string at ./FHEM/10_CUL_HM.pm line 4683.
2014.12.30 11:46:57.095 1: PERL WARNING: Use of uninitialized value $nextTimer in addition (+) at ./FHEM/10_CUL_HM.pm line 4685.
2014.12.30 11:46:57.744 1: PERL WARNING: Use of uninitialized value $nextTimer in concatenation (.) or string at ./FHEM/10_CUL_HM.pm line 4683.
2014.12.30 11:46:57.746 1: PERL WARNING: Use of uninitialized value $nextTimer in addition (+) at ./FHEM/10_CUL_HM.pm line 4685.
2014.12.30 11:46:58.960 1: PERL WARNING: Use of uninitialized value $nextTimer in concatenation (.) or string at ./FHEM/10_CUL_HM.pm line 4683.
2014.12.30 11:46:58.962 1: PERL WARNING: Use of uninitialized value $nextTimer in addition (+) at ./FHEM/10_CUL_HM.pm line 4685.
2014.12.30 11:47:09.989 1: Perfmon: possible freeze starting at 11:46:57, delay is 12.987
2014.12.30 11:47:10.751 1: HMLAN_Parse: hmlan1 new condition ok
2014.12.30 11:47:10.989 1: PERL WARNING: Useless use of join or string in void context at (eval 330) line 6.
2014.12.30 11:47:10.996 1: PERL WARNING: Useless use of join or string in void context at (eval 330) line 24.
2014.12.30 11:47:14.190 1: Perfmon: possible freeze starting at 11:47:10, delay is 4.189
2014.12.30 11:47:14.948 1: HMLAN_Parse: hmusb1 new condition ok
2014.12.30 11:47:15.054 1: PERL WARNING: Useless use of join or string in void context at (eval 343) line 6.
2014.12.30 11:47:15.063 1: PERL WARNING: Useless use of join or string in void context at (eval 343) line 24.
2014.12.30 11:47:23.218 0: HMLAN_Parse: hmusb1 R:E1ACE1F   stat:0000 t:030587CC d:FF r:FFD7     m:01 A001 1ACE1F 24AF1D 010E
2014.12.30 11:47:23.797 0: HMLAN_Parse: hmusb1 R:E24AF1D   stat:0000 t:030589DD d:FF r:FFC7     m:01 A410 24AF1D 1ACE1F 0601C8002F
2014.12.30 11:47:39.914 1: Perfmon: possible freeze starting at 11:47:38, delay is 1.914
2014.12.30 11:48:57.604 0: HMLAN_Parse: hmusb1 R:E24AF1D   stat:0000 t:0306F7B6 d:FF r:FFC7     m:D0 845E 24AF1D 000000 8001900000150006095BFE
2014.12.30 11:51:31.038 0: HMLAN_Parse: hmusb1 R:E24AF1D   stat:0000 t:03094E56 d:FF r:FFC7     m:D1 845E 24AF1D 000000 8001900000150006095AFE
2014.12.30 11:53:49.635 0: HMLAN_Parse: hmusb1 R:E24AF1D   stat:0000 t:030B6C56 d:FF r:FFC7     m:D2 845E 24AF1D 000000 80019000001500060959FD
2014.12.30 11:55:53.884 0: HMLAN_Parse: hmusb1 R:E24AF1D   stat:0000 t:030D51AD d:FF r:FFC7     m:D3 845E 24AF1D 000000 8001900000150006095AFE
2014.12.30 11:58:47.855 0: HMLAN_Parse: hmusb1 R:E24AF1D   stat:0000 t:030FF95C d:FF r:FFC7     m:D4 845E 24AF1D 000000 80019000001500090930FE
2014.12.30 11:59:02.795 1: ##### addLog ##### Thermostat.Keller: fan: addLog: invalid reading
2014.12.30 11:59:07.316 1: Perfmon: possible freeze starting at 11:59:00, delay is 7.315
2014.12.30 11:59:45.777 0: HMLAN_Send:  hmusb1 S:S9ADA0139 stat:  00 t:00000000 d:01 r:9ADA0139 m:50 A001 1ACE1F 266E75 00040000000000
2014.12.30 11:59:46.419 0: HMLAN_Parse: hmusb1 R:R9ADA0139 stat:0008 t:00000000 d:FF r:7FFF     m:50 A001 1ACE1F 266E75 00040000000000
2014.12.30 11:59:46.422 0: HMLAN_Parse: hmusb1 no ACK from 266E75
2014.12.30 11:59:55.714 0: HMLAN_Send:  hmusb1 S:S9ADA280A stat:  00 t:00000000 d:01 r:9ADA280A m:51 A001 1ACE1F 266E75 00040000000000
2014.12.30 11:59:56.338 0: HMLAN_Parse: hmusb1 R:R9ADA280A stat:0008 t:00000000 d:FF r:7FFF     m:51 A001 1ACE1F 266E75 00040000000000
2014.12.30 11:59:56.342 0: HMLAN_Parse: hmusb1 no ACK from 266E75
2014.12.30 12:00:01.230 0: HMLAN_Send:  hmusb1 S:S9ADA3D96 stat:  00 t:00000000 d:01 r:9ADA3D96 m:51 A001 1ACE1F 266E75 00040000000000
2014.12.30 12:00:01.875 0: HMLAN_Parse: hmusb1 R:R9ADA3D96 stat:0008 t:00000000 d:FF r:7FFF     m:51 A001 1ACE1F 266E75 00040000000000
2014.12.30 12:00:01.878 0: HMLAN_Parse: hmusb1 no ACK from 266E75
2014.12.30 12:00:06.860 0: HMLAN_Send:  hmusb1 S:S9ADA5393 stat:  00 t:00000000 d:01 r:9ADA5393 m:51 A001 1ACE1F 266E75 00040000000000
2014.12.30 12:00:07.510 0: HMLAN_Parse: hmusb1 R:R9ADA5393 stat:0008 t:00000000 d:FF r:7FFF     m:51 A001 1ACE1F 266E75 00040000000000
2014.12.30 12:00:07.516 0: HMLAN_Parse: hmusb1 no ACK from 266E75
2014.12.30 12:00:12.493 0: HMLAN_Send:  hmusb1 S:S9ADA6995 stat:  00 t:00000000 d:01 r:9ADA6995 m:51 A001 1ACE1F 266E75 00040000000000
2014.12.30 12:00:13.138 0: HMLAN_Parse: hmusb1 R:R9ADA6995 stat:0008 t:00000000 d:FF r:7FFF     m:51 A001 1ACE1F 266E75 00040000000000
2014.12.30 12:00:13.142 0: HMLAN_Parse: hmusb1 no ACK from 266E75

mir ist das erst kurz vor 12:00 aufgefallen. habe dann sofort logids vom hmusb eingeschaltet. das ging dann noch ca 10 min weiter und endete ohne weitere meldungen. der hmusb hat jetzt ein msgloadest von 40%. ein erneutes getconfig hat die schleife nicht wieder gestartet.

aber ein erneutes shutdown restart hat das verhalten erneut gestartet.

update: der spuk endete jetzt ebenfalls nach guten 20 min. msgloadest ebenfalls wieder 40%.
update2: habe gerade unter hminfo protoEvents noch folgendes entdeckt:

Code Auswählen

autoReadTest         : SwitchPBU02 SwitchPBU02_Btn_01 SwitchPBU02_Btn_02 SwitchPBU02_Sw_01 SwitchPBU02_Sw_02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02

gruss frank

martinp876 · 30 Dezember 2014, 16:14:34

zusehen ist dass 266E75 nicht antwortet.
FHEM versucht - wenn eingestellt - nicht vorhandene Register zu lesen . normal sollten die Werte von fhem gespeichert und neu geladen werden. dann wird auch nicht gelesen.
fehlt deinem Device etwas? klappt das schreiben des statefiles nicht?

frank · 30 Dezember 2014, 17:39:37

Zitatfehlt deinem Device etwas?

ja, es liegt seit ein paar wochen auf dem tisch und ist zerlegt.

ZitatFHEM versucht - wenn eingestellt - nicht vorhandene Register zu lesen .

genau. eingestellt ist: autoReadReg 5_readMissing.

bis vor dem update heute gab es dieses verhalten aber nicht. gestern wurde nach shutdown restart ein msgloadest von 1% erreicht. auch die tage davor. meine letzten versionen vor dem update waren bestimmt 4-8 wochen alt.

im augenblick fehlt zumindestens das reading von list0, obwohl die einzelnen register noch alle existieren. das erklärt ja auch, das fhem überhaupt versucht zu lesen. aber ist es denn normal das im abstand von 5 sekunden über einen zeitraum von 20 min ununterbrochen versucht wird zu lesen? sollte es nicht auf zb 3 versuche pro stunde beschränkt werden?

nach den msgnummern haben immer 4 versuche, die selbe nummer. falls das mit msgrepeat korreliert, sollte es stimmen, da das attribut nicht angegeben ist => demnach default 3. aber es geht munter weiter. msgnummer um 1 erhöht und wieder 4 versuche, ... .

wenn das verhalten so sein soll, ok. dann setze ich das device solange auf ignore=1. aber 3 devices mit leerer batterie, etc, könnten dann das system durch overload schnell lahmlegen.

gruss frank

martinp876 · 30 Dezember 2014, 20:14:57

Zitatja, es liegt seit ein paar wochen auf dem tisch und ist zerlegt.

hier stellt sich die Frage, wie oft FHEM wiederholen soll. du kannst overall einmal nachsehen, was in diesem Fall passiert..... In jedem Fall wird hier versucht, die Register zu lesen. Erst wenn aufgegeben wird kommt das nächste dran - immer einer nach dem anderen.

Zitatbis vor dem update heute gab es dieses verhalten aber nicht.

Im Code hat sich m.E. nichts getan. Aber readings sind eine unsichere Sache - daher speichere ich alles wichtige immer anderswo. Es ist möglich, dass aus irgendwelchen Gründen ein teil der Readings - oder auch alle - gelöscht werden. u.a.von deinem OOS device. Dann wird FHEM bei jeden Einschalten versuchen, dies zu lesen - die Readings werden immer fehlen, also bei jeden neustart noch einmal.

Zitataber ist es denn normal das im abstand von 5 sekunden über einen zeitraum von 20 min ununterbrochen versucht wird zu lesen? sollte es nicht auf zb 3 versuche pro stunde beschränkt werden?

kannst du mir sagen, welche devices gelesen werden und welche Readings fehlen? kannst du die logs einmal aufzeichnen?

Zitatdann setze ich das device solange auf ignore=1

würde ich machen. auch wenn es nicht so sein sollte. Wenn ich die logs habe kann ich einmal prüfen, wie oft gesendet wird

Zitataber 3 devices mit leerer batterie, etc, könnten dann das system durch overload schnell lahmlegen.

eigentlich nicht. Das automatische abrufen wird abgeborchen, wenn 40% verbraucht sind. kannst du am IO Einstellen mit hmMsgLowLimit.

frank · 30 Dezember 2014, 22:15:04

Zitatkannst du mir sagen, welche devices gelesen werden und welche Readings fehlen?

nur der eine schalter. laut hminfo fehlen von allen channels die listen. gepeert ist er nicht. soweit ich das überblicke, sind sonst alle readings da. drauf wetten will ich aber nicht.

Code Auswählen

 missing register list 
    SwitchPBU02:	RegL_00: 
    SwitchPBU02_Btn_01:	RegL_01: 
    SwitchPBU02_Btn_02:	RegL_01: 
    SwitchPBU02_Sw_01:	RegL_01: 
    SwitchPBU02_Sw_02:	RegL_01:

Zitatkannst du die logs einmal aufzeichnen?

siehe anhang. seit dem letzten shutdown restart heute mittag, versucht fhem, sofern die 40% msgloadest nicht erreicht sind, die listen zu lesen. siehe grafik.

Code Auswählen

protoEvents done: 
    name                    :State           |CmdPend   |Snd       |Resnd     #CmdDel    |ResndFail |Nack      |IOerr     
    SwitchPBU02             : done_Errors:1  | -        |539:      |1617:     #4844      |539:      | -        | -

Zitatu.a.von deinem OOS device

was genau bedeutet oos?

gruss frank

martinp876 · 31 Dezember 2014, 15:07:05

OOS = OutOfService

mit

Code Auswählen

get hm protoEvents short
kannst du u.a. sehen, wer noch abgefragt werden soll

autoReadReg :
status request :
autoReadReg wakeup : h_s_aussen h_s_az h_s_keller vd
status request wakeup:
autoReadTest : h_s_aussen h_s_az h_s_keller vd

wakeup wird beim aufwachen ausgeführt. autoReadTest wird nach 30min geprüft, ob die daten ok sind (register komplett) Wenn nicht, wird ein getConfig gequeued.

Nach startup wird die Liste recht voll sein. Beachte, dass bei weitem nicht alles zum message-senden führt.

werde einmal untersuchen, warum nicht abgebrochen wird.

martinp876 · 31 Dezember 2014, 16:50:14

ich habe einen "stop" eingecheckt. Nicht optimal - aber wie kann das auch sein.
jetzt wird nach einem timeout beim Lesen der Config das Device in die q der reading-check gesteckt. die kommt alle 30min dran.

evtl mache ich das nur, wenn das Device länger als x min nicht geantwortet hat.
ist nicht einfach zu unterscheiden, ob ein Device tot ist oder blockiert - und wann es wieder aufwacht.
Ich werde evtl noch einen status einbauen, irgendwo in protokol - device antwortet nicht auf Anfragen.... mal sehen.

Könnte jetzt also passieren, dass nach einem fehlerhaften getConfig eine lange pause eintritt beim automatischen update

frank · 31 Dezember 2014, 18:39:29

ich habe noch mal ein test gemacht mit der "non-stop" version. den schalter habe ich zu beginn auf autoreadreg=0_off gestellt und gewartet bis alle anforderungen verschwunden waren. siehe protoEvents:

Code Auswählen

    CUL_HM queue length:0 

    requests pending 
    ---------------- 
    autoReadReg          : 
        recent           : none 
    status request       : 
    autoReadReg wakeup   : 
    status request wakeup: 
    autoReadTest         : 

    IODevs:cul868:Initialized condition:- 
           hmlan1:opened pending=0 condition:ok 
            msgLoadEst: 1hour:9% 10min steps: 0/1/1/1/1/2 
           hmusb1:opened pending=0 condition:ok 
            msgLoadEst: 1hour:0% 10min steps: 0/0/0/0/0/0

jetzt habe ich autoreadreg auf 5_missing gestellt. => der schalter wird in die "test"-queue gesetzt:

Code Auswählen

    CUL_HM queue length:0 

    requests pending 
    ---------------- 
    autoReadReg          : 
        recent           : none 
    status request       : 
    autoReadReg wakeup   : 
    status request wakeup: 
    autoReadTest         : SwitchPBU02 

    IODevs:cul868:Initialized condition:- 
           hmlan1:opened pending=0 condition:ok 
            msgLoadEst: 1hour:8% 10min steps: 0/1/1/1/1/1 
           hmusb1:opened pending=0 condition:ok 
            msgLoadEst: 1hour:0% 10min steps: 0/0/0/0/0/0

wie von dir beschrieben geht es dann nach 30 minuten los. leider habe ich den start etwas verpennt. aber ich konnte noch erkennen, dass nun die "test"-queue permanent, bei jedem neuen sendeversuch, verlängert wird. das scheint mir etwas seltsam. eventuell passiert hier etwas, das nicht so gewollt ist. nach erreichen der 40% msgloadest sind 111 einträge vorhanden.

Code Auswählen

    CUL_HM queue length:1 

    requests pending 
    ---------------- 
    autoReadReg          : 
        recent           : SwitchPBU02 
    status request       : 
    autoReadReg wakeup   : 
    status request wakeup: 
    autoReadTest         : SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 SwitchPBU02 

    IODevs:cul868:Initialized condition:- 
           hmlan1:opened pending=0 condition:ok 
            msgLoadEst: 1hour:10% 10min steps: 2/1/1/1/1/1 
           hmusb1:opened pending=0 condition:ok 
            msgLoadEst: 1hour:9% 10min steps: 9/0/0/0/0/0

die "stop"-version werde ich dann mal probieren. wie könnte ich denn am besten den verlust von daten simulieren. zb einer registerliste, um das verhalten bei einem "normalen"-homematic-device zu testen. nicht, dass das verhalten durch dieses "homebrew-device" verursacht wird. wäre da set clear register das richtige? oder reicht das nicht?

guten rutsch
gruss frank

frank · 01 Januar 2015, 11:47:17

die stop-version scheint gut zu laufen. danke.
nun wird alle 30 min eine anfrage gesendet und mit msgrepeat versuchen wiederholt. nur beim ersten mal nach restart gibt es eine zusätzliche msg, die ich nicht verstehe. was genau bedeutet sie?

Code Auswählen

2014.12.31 22:06:27.203 0: HMLAN_Send:  hmusb1 S:SA22BCE4B stat:  00 t:00000000 d:01 r:A22BCE4B m:09 A001 1ACE1F 266E75 030E

update: auch ein zweiter aktiver schalter bekommt diese message nach restart. dieser reagiert aber nicht darauf.

Code Auswählen

2014.12.31 22:05:15.166 1: Including fhem.cfg
2014.12.31 22:05:19.868 1: HMLAN_Parse: hmusb1 new condition disconnected
2014.12.31 22:05:19.937 1: HMLAN_Parse: hmusb1 new condition init
2014.12.31 22:05:19.964 1: HMLAN_Parse: hmlan1 new condition disconnected
2014.12.31 22:05:19.983 1: HMLAN_Parse: hmlan1 new condition init
2014.12.31 22:05:38.960 1: Including ./log/fhem.save
2014.12.31 22:05:45.731 1: HCS BROETJE monitoring of devices started
2014.12.31 22:05:46.688 1: PERL WARNING: Subroutine HandleTimeout redefined at ./FHEM/98_apptime.pm line 24.
2014.12.31 22:05:46.695 1: PERL WARNING: Subroutine CallFn redefined at ./FHEM/98_apptime.pm line 58.
2014.12.31 22:05:47.014 0: Server started with 325 defined entities (version $Id: fhem.pl 6913 2014-11-08 10:32:44Z rudolfkoenig $, os linux, user root, pid 5276)
2014.12.31 22:05:47.088 1: Perfmon: possible freeze starting at 22:05:16, delay is 31.088
2014.12.31 22:05:48.899 1: PERL WARNING: Use of uninitialized value $nextTimer in concatenation (.) or string at ./FHEM/10_CUL_HM.pm line 4683.
2014.12.31 22:05:48.909 1: PERL WARNING: Use of uninitialized value $nextTimer in addition (+) at ./FHEM/10_CUL_HM.pm line 4685.
2014.12.31 22:05:57.779 1: HMLAN_Parse: hmlan1 new condition ok
2014.12.31 22:05:57.889 1: PERL WARNING: Useless use of join or string in void context at (eval 313) line 6.
2014.12.31 22:05:57.904 1: PERL WARNING: Useless use of join or string in void context at (eval 313) line 24.
2014.12.31 22:05:59.300 1: Perfmon: possible freeze starting at 22:05:48, delay is 11.298
2014.12.31 22:06:03.891 1: HMLAN_Parse: hmusb1 new condition ok
2014.12.31 22:06:04.099 1: PERL WARNING: Useless use of join or string in void context at (eval 331) line 6.
2014.12.31 22:06:04.108 1: PERL WARNING: Useless use of join or string in void context at (eval 331) line 24.
2014.12.31 22:06:04.474 1: Perfmon: possible freeze starting at 22:06:00, delay is 4.473
2014.12.31 22:06:15.596 0: HMLAN_Send:  hmusb1 S:+266E75,00,01,00
2014.12.31 22:06:15.599 0: HMLAN_Send:  hmusb1 S:SA22BA0F3 stat:  00 t:00000000 d:01 r:A22BA0F3 m:09 A001 1ACE1F 266E75 030E
2014.12.31 22:06:16.324 0: HMLAN_Parse: hmusb1 R:RA22BA0F3 stat:0008 t:00000000 d:FF r:7FFF     m:09 A001 1ACE1F 266E75 030E
2014.12.31 22:06:16.327 0: HMLAN_Parse: hmusb1 no ACK from 266E75
2014.12.31 22:06:17.639 0: HMLAN_Send:  hmusb1 S:SA22BA8EF stat:  00 t:00000000 d:01 r:A22BA8EF m:09 A001 1ACE1F 266E75 030E
2014.12.31 22:06:18.289 0: HMLAN_Parse: hmusb1 R:RA22BA8EF stat:0008 t:00000000 d:FF r:7FFF     m:09 A001 1ACE1F 266E75 030E
2014.12.31 22:06:18.293 0: HMLAN_Parse: hmusb1 no ACK from 266E75
2014.12.31 22:06:22.527 0: HMLAN_Send:  hmusb1 S:SA22BBC06 stat:  00 t:00000000 d:01 r:A22BBC06 m:09 A001 1ACE1F 266E75 030E
2014.12.31 22:06:23.185 0: HMLAN_Parse: hmusb1 R:RA22BBC06 stat:0008 t:00000000 d:FF r:7FFF     m:09 A001 1ACE1F 266E75 030E
2014.12.31 22:06:23.188 0: HMLAN_Parse: hmusb1 no ACK from 266E75
2014.12.31 22:06:23.923 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/59_PROPLANTA.pm line 614.
2014.12.31 22:06:23.925 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/59_PROPLANTA.pm line 614.
2014.12.31 22:06:23.927 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/59_PROPLANTA.pm line 614.
2014.12.31 22:06:23.928 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/59_PROPLANTA.pm line 614.
2014.12.31 22:06:25.840 1: Perfmon: possible freeze starting at 22:06:24, delay is 1.84
2014.12.31 22:06:27.110 1: Perfmon: possible freeze starting at 22:06:26, delay is 1.109
2014.12.31 22:06:27.203 0: HMLAN_Send:  hmusb1 S:SA22BCE4B stat:  00 t:00000000 d:01 r:A22BCE4B m:09 A001 1ACE1F 266E75 030E
2014.12.31 22:06:27.826 0: HMLAN_Parse: hmusb1 R:RA22BCE4B stat:0008 t:00000000 d:FF r:7FFF     m:09 A001 1ACE1F 266E75 030E
2014.12.31 22:06:27.829 0: HMLAN_Parse: hmusb1 no ACK from 266E75
2014.12.31 22:06:34.663 0: HMLAN_Send:  hmusb1 S:+266E75,00,01,00
2014.12.31 22:06:34.666 0: HMLAN_Send:  hmusb1 S:SA22BEB6E stat:  00 t:00000000 d:01 r:A22BEB6E m:0D A001 1ACE1F 266E75 00040000000000
2014.12.31 22:06:35.345 0: HMLAN_Parse: hmusb1 R:RA22BEB6E stat:0008 t:00000000 d:FF r:7FFF     m:0D A001 1ACE1F 266E75 00040000000000
2014.12.31 22:06:35.349 0: HMLAN_Parse: hmusb1 no ACK from 266E75
2014.12.31 22:06:40.606 0: HMLAN_Send:  hmusb1 S:SA22C02A3 stat:  00 t:00000000 d:01 r:A22C02A3 m:0D A001 1ACE1F 266E75 00040000000000
2014.12.31 22:06:41.233 0: HMLAN_Parse: hmusb1 R:RA22C02A3 stat:0008 t:00000000 d:FF r:7FFF     m:0D A001 1ACE1F 266E75 00040000000000
2014.12.31 22:06:41.236 0: HMLAN_Parse: hmusb1 no ACK from 266E75
2014.12.31 22:06:46.646 0: HMLAN_Send:  hmusb1 S:SA22C1A3E stat:  00 t:00000000 d:01 r:A22C1A3E m:0D A001 1ACE1F 266E75 00040000000000
2014.12.31 22:06:47.282 0: HMLAN_Parse: hmusb1 R:RA22C1A3E stat:0008 t:00000000 d:FF r:7FFF     m:0D A001 1ACE1F 266E75 00040000000000
2014.12.31 22:06:47.285 0: HMLAN_Parse: hmusb1 no ACK from 266E75
2014.12.31 22:06:51.112 0: HMLAN_Send:  hmusb1 S:SA22C2BB0 stat:  00 t:00000000 d:01 r:A22C2BB0 m:0D A001 1ACE1F 266E75 00040000000000
2014.12.31 22:06:51.729 0: HMLAN_Parse: hmusb1 R:RA22C2BB0 stat:0008 t:00000000 d:FF r:7FFF     m:0D A001 1ACE1F 266E75 00040000000000
2014.12.31 22:06:51.732 0: HMLAN_Parse: hmusb1 no ACK from 266E75
2014.12.31 22:35:27.493 1: PERL WARNING: Argument "" isn't numeric in addition (+) at ./FHEM/59_Weather.pm line 173.
2014.12.31 22:35:32.710 0: HMLAN_Send:  hmusb1 S:SA24670AD stat:  00 t:00000000 d:01 r:A24670AD m:30 A001 1ACE1F 266E75 00040000000000
2014.12.31 22:35:33.332 0: HMLAN_Parse: hmusb1 R:RA24670AD stat:0008 t:00000000 d:FF r:7FFF     m:30 A001 1ACE1F 266E75 00040000000000
2014.12.31 22:35:33.337 0: HMLAN_Parse: hmusb1 no ACK from 266E75
2014.12.31 22:35:38.428 0: HMLAN_Send:  hmusb1 S:SA2468704 stat:  00 t:00000000 d:01 r:A2468704 m:30 A001 1ACE1F 266E75 00040000000000
2014.12.31 22:35:39.060 0: HMLAN_Parse: hmusb1 R:RA2468704 stat:0008 t:00000000 d:FF r:7FFF     m:30 A001 1ACE1F 266E75 00040000000000
2014.12.31 22:35:39.063 0: HMLAN_Parse: hmusb1 no ACK from 266E75
2014.12.31 22:35:44.060 0: HMLAN_Send:  hmusb1 S:SA2469D03 stat:  00 t:00000000 d:01 r:A2469D03 m:30 A001 1ACE1F 266E75 00040000000000
2014.12.31 22:35:44.692 0: HMLAN_Parse: hmusb1 R:RA2469D03 stat:0008 t:00000000 d:FF r:7FFF     m:30 A001 1ACE1F 266E75 00040000000000
2014.12.31 22:35:44.695 0: HMLAN_Parse: hmusb1 no ACK from 266E75
2014.12.31 22:35:48.671 0: HMLAN_Send:  hmusb1 S:SA246AF07 stat:  00 t:00000000 d:01 r:A246AF07 m:30 A001 1ACE1F 266E75 00040000000000
2014.12.31 22:35:49.304 0: HMLAN_Parse: hmusb1 R:RA246AF07 stat:0008 t:00000000 d:FF r:7FFF     m:30 A001 1ACE1F 266E75 00040000000000
2014.12.31 22:35:49.307 0: HMLAN_Parse: hmusb1 no ACK from 266E75

weiterhin gibt es mit hminfo protoevents unter autoreadtest mehrfache einträge vom device. natürlich nicht mehr so krass.

Code Auswählen

    CUL_HM queue length:0 

    requests pending 
    ---------------- 
    autoReadReg          : 
        recent           : SwitchPBU02 
    status request       : 
    autoReadReg wakeup   : 
    status request wakeup: 
    autoReadTest         : SwitchPBU02 SwitchPBU02_Btn_01 SwitchPBU02_Btn_02 SwitchPBU02_Sw_01 SwitchPBU02_Sw_02 SwitchPBU02 SwitchPBU02 

    IODevs:cul868:Initialized condition:- 
           hmlan1:opened pending=0 condition:ok 
            msgLoadEst: 1hour:10% 10min steps: 0/2/1/1/1/2 
           hmusb1:opened pending=0 condition:ok 
            msgLoadEst: 1hour:1% 10min steps: 0/0/0/0/0/0

gruss frank

martinp876 · 01 Januar 2015, 15:44:31

die erste message ist ein status-request.