[gelöst] HM-LC-Sw1PBU-FM (FW: jab 1.5) crashed fhem seit v5262 (10_CUL_HM)

frank · 30 April 2014, 00:30:22

hallo martin,

seit v5262 von 10_cul_hm wird bei jeglichem kontakt mit dem schalter fhem sofort gecrashed. mit der vorherigen version v5256 läuft alles normal.

kannst du bitte mal einen blick darauf werfen. ich habe bereits eine detailliertere analyse hier beschrieben http://forum.fhem.de/index.php/topic,18071.msg163852.html#new. in den beiträgen davor sind vielleicht auch noch informationen.

gruss frank

martinp876 · 30 April 2014, 08:55:15

wo habt ihr den 99_Asksin_HM_LC_Sw1PBU_FM_CustomFW.pm rumliegen?
was gibt die subroutine zurück?

ChristianK. · 30 April 2014, 09:49:50

Die gibt es hier:

https://github.com/jabdoa2/Asksin_HM_LC_Sw1PBU_FM

Grüße

Christian K.

frank · 30 April 2014, 11:07:53

hallo martin,

Zitat von: martinp876 am 30 April 2014, 08:55:15
wo habt ihr den 99_Asksin_HM_LC_Sw1PBU_FM_CustomFW.pm rumliegen?

die datei liegt in fhem/FHEM bei 10_cul_hm.

Zitatwas gibt die subroutine zurück?

was meinst du genau? soll ich mal irgend welche variablen loggen?

hier mal einige fhem.log beispiele

randbedingungen:
schalter ist mit 123ABC gepaired und kommuniziert über hmlan. monitor cul hat andere hmid.

3 schaltereignisse über webif mit funktionierender v5256:

Code Auswählen

2014.04.29 18:33:58.128 5: CUL/RAW: /A0E12A011123ABC266EA5020300000055
A0E128002266EA5123ABC01030000001E

2014.04.29 18:33:58.130 4: CUL_Parse: cul868 A 0E 12 A011 123ABC 266EA5 020300000055 -31.5
2014.04.29 18:33:58.133 5: cul868 dispatch A0E12A011123ABC266EA50203000000::-31.5:cul868
2014.04.29 18:33:58.142 4: RCV L:0E N:12 F:A0 CMD:11 SRC:ccu DST:SwitchPBU01 0203000000 (SET CHANNEL:0x03 VALUE:0x00 RAMPTIME:2) (,BIDI,RPTEN)
2014.04.29 18:33:58.192 4: CUL_Parse: cul868 A 0E 12 8002 266EA5 123ABC 01030000001E -59
2014.04.29 18:33:58.194 5: cul868 dispatch A0E128002266EA5123ABC0103000000::-59:cul868

2014.04.29 18:34:08.225 5: CUL/RAW: /A0E13A011123ABC266EA50203C8000055
A0E138002266EA5123ABC0103C8000018

2014.04.29 18:34:08.228 4: CUL_Parse: cul868 A 0E 13 A011 123ABC 266EA5 0203C8000055 -31.5
2014.04.29 18:34:08.230 5: cul868 dispatch A0E13A011123ABC266EA50203C80000::-31.5:cul868
2014.04.29 18:34:08.254 4: RCV L:0E N:13 F:A0 CMD:11 SRC:ccu DST:SwitchPBU01 0203C80000 (SET CHANNEL:0x03 VALUE:0xC8 RAMPTIME:2) (,BIDI,RPTEN)
2014.04.29 18:34:08.301 4: CUL_Parse: cul868 A 0E 13 8002 266EA5 123ABC 0103C8000018 -62
2014.04.29 18:34:08.303 5: cul868 dispatch A0E138002266EA5123ABC0103C80000::-62:cul868

2014.04.29 18:35:12.986 5: CUL/RAW: /A0E18A011123ABC266EA5020300000055
A0E188002266EA5123ABC01030000001E

2014.04.29 18:35:12.989 4: CUL_Parse: cul868 A 0E 18 A011 123ABC 266EA5 020300000055 -31.5
2014.04.29 18:35:12.991 5: cul868 dispatch A0E18A011123ABC266EA50203000000::-31.5:cul868
2014.04.29 18:35:13.000 4: RCV L:0E N:18 F:A0 CMD:11 SRC:ccu DST:SwitchPBU01 0203000000 (SET CHANNEL:0x03 VALUE:0x00 RAMPTIME:2) (,BIDI,RPTEN)
2014.04.29 18:35:13.052 4: CUL_Parse: cul868 A 0E 18 8002 266EA5 123ABC 01030000001E -59
2014.04.29 18:35:13.056 5: cul868 dispatch A0E188002266EA5123ABC0103000000::-59:cul868

bei den absturzversuchen mit v5262 und heute mit v5692 konnte der cul nichts mehr aufzeichnen. auch hmlan hatte keine zeit für logs.

um den schalter trotzdem ohne fhem benutzen zu können, verwende ich ihn mit dem attribut ignore=1. mit dieser einstellung und der neuesten 10_cul_hm gibt es folgende logs:

Code Auswählen

2014.04.29 21:45:07.237 5: CUL/RAW: /A0E1F8002266EA5266EA50103C840001E

2014.04.29 21:45:07.239 4: CUL_Parse: cul868 A 0E 1F 8002 266EA5 266EA5 0103C840001E -59
2014.04.29 21:45:07.241 5: cul868 dispatch A0E1F8002266EA5266EA50103C84000::-59:cul868
2014.04.29 21:45:14.700 5: CUL/RAW: /A0B8EA2581BF81BD4D4D4000014

2014.04.30 10:26:44.529 0: HMLAN_Parse: HMLAN1 R:E266EA5   stat:0000 t:023D5B72 d:FF r:FFCD     m:20 8002 266EA5 266EA5 0103004000
2014.04.30 10:26:51.289 0: HMLAN_Parse: HMLAN1 R:E266EA5   stat:0000 t:023D75DD d:FF r:FFC8     m:21 8002 266EA5 266EA5 0103C84000

zum schluss noch die letzten worte von fhem mit global verbose=5 und ohne ignore. auch hier hat hmlan keine zeit für aufzeichnungen.

Code Auswählen

2014.04.30 10:32:04.476 5: CUL/RAW: /A0E228002266EA5266EA501030040002D

2014.04.30 10:32:04.478 4: CUL_Parse: cul868 A 0E 22 8002 266EA5 266EA5 01030040002D -51.5
2014.04.30 10:32:04.481 5: cul868 dispatch A0E228002266EA5266EA50103004000::-51.5:cul868
2014.04.30 10:32:04.495 4: RCV L:0E N:22 F:80 CMD:02 SRC:SwitchPBU01 DST:SwitchPBU01 0103004000 (ACK_STATUS CHANNEL:0x03 STATUS:0x00 UP:0 DOWN:0 LOWBAT:0 RSSI:0) (,RPTEN)
2014.04.30 10:32:04.496 5: Triggering cul868 (1 changes)
2014.04.30 10:32:04.497 5: Notify loop for cul868 RCV L:0E N:22 F:80 CMD:02 SRC:SwitchPBU01 DST:SwitchPBU01 0103004000 (ACK_STATUS CHANNEL:0x03 STATUS:0x00 UP:0 DOWN:0 LOWBAT:0 RSSI:0) (,RPTEN)

gruss frank

martinp876 · 30 April 2014, 18:44:53

muss noch durchsehen.
Aber die Datei finde ich nicht in SVN.
Ist das in deinem Verzeichnis oder hier irgendwo in einem Thread?

frank · 30 April 2014, 18:57:56

ich habe meine mal angehängt.

gruss frank

martinp876 · 30 April 2014, 20:39:39

Hi,

das Format hat sich geändert... sorry.
Grund war, dass einigen trigger nicht ausgelöst werden - der Kernal sperrt das Triggern währen des Parsens (so weit ok), vergisst aber, dass er noch triggern sollte.
Daher werden die Events jetzt in einem array-of-arrays zurückgegeben.
Ein Eintrag ist dann immer
hash,soll-getriggert-werden-flag,reading-mit-value

CUL_HM übernimmt dann den Rest.
Hoffe der Code ist klar (und ohne typos...)

frank · 30 April 2014, 21:11:11

na dann erstmal schönen dank und guten tanz heute nacht.

die original datei ist übrigens nicht in svn sondern bei jan im git. das hatte christian in post#2 verlinkt. mein angegebener pfad ist von meiner fritzbox.

gruss frank

frank · 30 April 2014, 22:27:18

hallo martin,

die gute nachricht: fhem stürzt nicht mehr ab.

nach restart und dann attr ignore entfernen, war das pairing dann weg. kann ja gut sein. dann hatte ich aber schwierigkeiten neu zu pairen. nach mehrmaligem löschen der register und readings mit getconfig und save config, hat es irgendwann funktioniert.

aber: attr model=unknown und subtype="".

hier ein list vom device

Code Auswählen

Internals: 
   .triggerUsed 1 
   DEF        266EA5 
   HMLAN1_MSGCNT 233 
   HMLAN1_RAWMSG E266EA5,0000,04C3BBD5,FF,FFCC,04A410266EA5123ABC0604000000 
   HMLAN1_RSSI -52 
   HMLAN1_TIME 2014-04-30 22:12:39 
   IODev      HMLAN1 
   LASTInputDev HMLAN1 
   MSGCNT     446 
   NAME       SwitchPBU01 
   NR         374 
   STATE      CMDs_done 
   TYPE       CUL_HM 
   channel_01 SwitchPBU01_Btn_01 
   channel_02 SwitchPBU01_Btn_02 
   channel_03 SwitchPBU01_Sw_01 
   channel_04 SwitchPBU01_Sw_02 
   cul868_MSGCNT 213 
   cul868_RAWMSG A0E04A410266EA5123ABC0604000000::-63.5:cul868 
   cul868_RSSI -63.5 
   cul868_TIME 2014-04-30 22:12:39 
   lastMsg    No:04 - t:10 s:266EA5 d:123ABC 0604000000 
   protLastRcv 2014-04-30 22:12:39 
   protSnd    221 last_at:2014-04-30 22:12:39 
   protState  CMDs_done 
   rssi_at_HMLAN1 avg:-53.33 min:-68 max:-47 lst:-52 cnt:233 
   rssi_at_cul868 avg:-67.84 min:-82.5 max:-57 lst:-63.5 cnt:213 
   Readings: 
     2014-04-30 22:06:33   .D-devInfo      410100 
     2014-04-30 22:06:33   .D-stc          10 
     2014-04-30 22:12:39   .protLastRcv    2014-04-30 22:12:39 
     2014-04-30 22:06:34   CommandAccepted yes 
     2014-04-30 22:06:33   D-firmware      1.5 
     2014-04-30 22:06:33   D-serialNr      PS00000002 
     2014-04-30 22:07:52   PairedTo        0x123ABC 
     2014-04-30 22:06:34   R-pairCentral   0x123ABC 
     2014-04-30 22:07:52   RegL_00:          02:01 05:00 0A:12 0B:3A 0C:BC 12:00 00:00 
     2014-04-30 22:12:39   state           CMDs_done 
   Helper: 
     cSnd       01123ABC266EA500040000000000 
     Io: 
       newChn     +266EA5,00,01,1E 
       nextSend   1398888759.91811 
     Prt: 
       bErr       0 
       sProc      0 
       Rspwait: 
     Q: 
       qReqConf 
       qReqStat 
     Role: 
       dev        1 
     Rpt: 
       IO         cul868 
       flg        A 
       ts         1398888759.87494 
       ack: 
         HASH(0x13290a0) 
         048002123ABC266EA500 
     Rssi: 
       At_hmlan1: 
         avg        -53.3304721030043 
         cnt        233 
         lst        -52 
         max        -47 
         min        -68 
       At_cul868: 
         avg        -67.8427230046948 
         cnt        213 
         lst        -63.5 
         max        -57 
         min        -82.5 
     Shadowreg: 
Attributes: 
   IODev      HMLAN1 
   autoReadReg 5_readMissing 
   event-on-change-reading .* 
   expert     2_full 
   firmware   1.5 
   model      unknown 
   room       10_WZ 
   serialNr   PS00000002 
   subType 
   webCmd     getConfig:clear msgEvents

nach restart in fhem.log:

Code Auswählen

2014.04.30 23:28:44.513 0: Server shutdown
2014.04.30 23:28:50 1: reload: Error:Modul 99_Asksin_HM_LC_Sw1PBU_FM_CustomFW deactivated:
 Did not find leading dereferencer, detected at offset 4596syntax error at ./FHEM/99_Asksin_HM_LC_Sw1PBU_FM_CustomFW.pm line 53, near ""pct:$val";"
syntax error at ./FHEM/99_Asksin_HM_LC_Sw1PBU_FM_CustomFW.pm line 57, near ");"
syntax error at ./FHEM/99_Asksin_HM_LC_Sw1PBU_FM_CustomFW.pm line 107, near ""state:$btnName $state$target";"

2014.04.30 23:28:51 2: Perfmon: ready to watch out for delays greater than one second
2014.04.30 23:28:51.987 1: Including fhem.cfg
2014.04.30 23:28:53.697 1: reload: Error:Modul 99_Asksin_HM_LC_Sw1PBU_FM_CustomFW deactivated:
 Did not find leading dereferencer, detected at offset 4596syntax error at ./FHEM/99_Asksin_HM_LC_Sw1PBU_FM_CustomFW.pm line 53, near ""pct:$val";"
syntax error at ./FHEM/99_Asksin_HM_LC_Sw1PBU_FM_CustomFW.pm line 57, near ");"
syntax error at ./FHEM/99_Asksin_HM_LC_Sw1PBU_FM_CustomFW.pm line 107, near ""state:$btnName $state$target";"

2014.04.30 23:28:57.461 1: HMLAN_Parse: HMLAN1 new condition disconnected
2014.04.30 23:28:57.518 1: HMLAN_Parse: HMLAN1 new condition init
2014.04.30 23:29:08.491 1: Including ./log/fhem.save
2014.04.30 23:29:12.560 1: HCS BROETJE monitoring of devices started
2014.04.30 23:29:12.992 0: Server started with 233 defined entities (version $Id: fhem.pl 5663 2014-04-26 09:13:54Z rudolfkoenig $, os linux, user root, pid 3931)

gruss frank

ChristianK. · 01 Mai 2014, 09:08:48

Guten Morgen Martin, Guten Morgen Frank,

ich habe die askin-pm bei mir ausgetauscht, fhem stürzt nicht mehr ab - danke :-D,
pairing war auch noch da, und schalten konnte ich auch...
Nun habe ich das Verhalten wie Frank es glaube ich schon einmal beschrieben hat...
Wenn kein Strom über die Schaltung fliesst, habe ich im 1-2sek. Rhytmus events im Event-Monitor...
Aber ich glaube das gehört wieder in den Haupt-Thread...
Die LOG-Einträge wie Frank habe ich aber nun auch...

Grüße

Christian

martinp876 · 01 Mai 2014, 11:35:55

die beiden tipfehler könnt ihr sicher entfernen - das semicolon in der Klammer entfernen.
push @evtEt,[$shash,1,"timedOn:".(($err&0x40)?"running":"off")];
push @evtEt,[$shash,1,"state:$btnName $state$target"];

Löst es das Problem?

Ich werden in CUL_HM eine Sicherung einbauen, der fehlerhaftes Readingsetzen unterbindet

ChristianK. · 01 Mai 2014, 12:07:32

Hallo Martin,

nun erscheint nur noch folgendes im Log:

Code Auswählen

Did not find leading dereferencer, detected at offset 4594syntax error at ./FHEM/99_Asksin_HM_LC_Sw1PBU_FM_CustomFW.pm line 53, near ""pct:$val";"

Wenn ich hier aber das Semikolon lösche... was bestimmt falsch ist, läuft das log damit voll:

Code Auswählen

2014.05.01 12:04:48 1: readingsUpdate(,deviceMsg,off (to CUL_1)) missed to call readingsBeginUpdate first.
2014.05.01 12:04:48 1: readingsUpdate(,state,off) missed to call readingsBeginUpdate first.
2014.05.01 12:04:48 1: readingsUpdate(,timedOn,off) missed to call readingsBeginUpdate first.
2014.05.01 12:04:49 1: readingsUpdate(,level,0 %) missed to call readingsBeginUpdate first.
2014.05.01 12:04:49 1: readingsUpdate(,pct,0) missed to call readingsBeginUpdate first.

Grüße Christian

jab · 01 Mai 2014, 15:11:35

Danke fürs korrigieren. Ich checke den Code später ins git ein.

Gruß
Jan

frank · 01 Mai 2014, 22:00:42

ZitatLöst es das Problem?

zusammen mit dem 3. semikolon in zeile 53 ist das problem behoben.
merci vielmals.

gruss frank