14_CUL_MAX.pm - Crash nach update

bartman121 · 07 Mai 2020, 19:43:09

Hallo,

ich habe heute ein FHEM-UPDATE gemacht, danach startete mein FHEM nicht mehr. Folgendes sagt das Logfile beim Start.

Code Auswählen


2020.05.07 19:35:31 0: Server shutdown
2020.05.07 19:35:32 2: eventTypes: loaded 9127 events from ./log/eventTypes.txt
2020.05.07 19:35:33 1: KU.TEMP: no I/O device
2020.05.07 19:35:35 1: PERL WARNING: main::SIRD_Power() called too early to check prototype at ./FHEM/17_SIRD.pm line 74.
2020.05.07 19:35:35 1: PERL WARNING: main::SIRD_Volume() called too early to check prototype at ./FHEM/17_SIRD.pm line 151.
2020.05.07 19:35:35 1: PERL WARNING: main::SIRD_Mute() called too early to check prototype at ./FHEM/17_SIRD.pm line 247.
2020.05.07 19:35:35 1: PERL WARNING: main::SIRD_Shuffle() called too early to check prototype at ./FHEM/17_SIRD.pm line 307.
2020.05.07 19:35:35 1: PERL WARNING: main::SIRD_Repeat() called too early to check prototype at ./FHEM/17_SIRD.pm line 367.
2020.05.07 19:35:35 1: PERL WARNING: main::SIRD_RemoteState() called too early to check prototype at ./FHEM/17_SIRD.pm line 1038.
2020.05.07 19:35:35 1: PERL WARNING: main::SIRD_Input() called too early to check prototype at ./FHEM/17_SIRD.pm line 1120.
2020.05.07 19:35:35 1: PERL WARNING: main::SIRD_SearchTerm() called too early to check prototype at ./FHEM/17_SIRD.pm line 1716.
2020.05.07 19:35:35 1: PERL WARNING: main::SIRD_DABScan() called too early to check prototype at ./FHEM/17_SIRD.pm line 1766.
2020.05.07 19:35:36 1: WZ.TEMP: no I/O device
2020.05.07 19:35:36 1: EC3000_BCF0: no I/O device
2020.05.07 19:35:36 2: EnOcean Cryptographic functions are not available.
2020.05.07 19:35:36 2: EnOcean XML functions available.
2020.05.07 19:35:36 1: EC3000_C1A8: no I/O device
2020.05.07 19:35:36 0: [echodevice] load ECHO Device ECHO_G090L90964011JQ3
2020.05.07 19:35:36 0: [echodevice] load ECHO Device ECHO_G090L909648611RW
2020.05.07 19:35:36 0: [echodevice] load ECHO Device ECHO_G090QU0674710HHC
2020.05.07 19:35:37 1: PERL WARNING: Use of uninitialized value $model in string eq at ./FHEM/32_YeeLight.pm line 172.
2020.05.07 19:35:37 1: AUSSEN.TEMP: no I/O device
2020.05.07 19:35:37 2: Switched cul_cube rfmode to MAX
2020.05.07 19:35:37 2: Registering GEOFANCY geofancy for URL /geo...
2020.05.07 19:35:37 1: AZ.TEMP: no I/O device
2020.05.07 19:35:37 1: PERL WARNING: given is experimental at ./FHEM/98_PID20.pm line 305.
2020.05.07 19:35:37 1: PERL WARNING: when is experimental at ./FHEM/98_PID20.pm line 307.
2020.05.07 19:35:37 1: PERL WARNING: given is experimental at ./FHEM/98_PID20.pm line 339.
2020.05.07 19:35:37 1: PERL WARNING: when is experimental at ./FHEM/98_PID20.pm line 341.
2020.05.07 19:35:37 1: PERL WARNING: when is experimental at ./FHEM/98_PID20.pm line 345.
2020.05.07 19:35:37 1: PERL WARNING: when is experimental at ./FHEM/98_PID20.pm line 356.
2020.05.07 19:35:37 1: PERL WARNING: when is experimental at ./FHEM/98_PID20.pm line 363.
2020.05.07 19:35:37 1: PERL WARNING: when is experimental at ./FHEM/98_PID20.pm line 370.
2020.05.07 19:35:37 1: PERL WARNING: when is experimental at ./FHEM/98_PID20.pm line 385.
2020.05.07 19:35:38 2: FRITZBOX FritzBox: Define.255 Modul functionality limited because of missing perl modules: Net::Telnet
2020.05.07 19:35:40 1: EC3000_8351: no I/O device
2020.05.07 19:35:40 1: EC3000_F8DC: no I/O device
2020.05.07 19:35:40 1: KeyValueProtocol_LGW_5677390: no I/O device
2020.05.07 19:35:40 1: Messages collected while initializing FHEM:SecurityCheck:
  WEB is not password protected
  MQTT2_FHEM_Server is not password protected
  WEBhook is not password protected
  WEBphone is not password protected

Protect this FHEM installation by configuring the allowed device allowedWEBhook
You can disable this message with attr global motd none

2020.05.07 19:35:40 2: TCM TCM_ESP3_0 RESPONSE: OK
2020.05.07 19:35:41 2: TCM TCM_ESP3_0 RESPONSE: BaseID: FF9D7D80 RemainingWriteCycles: 0A
2020.05.07 19:35:41 2: TCM TCM_ESP3_0 RESPONSE: APIVersion: 02050000 APPVersion: 020A0000 ChipID: 018E3AFB ChipVersion: 454F0103 Desc: GATEWAYCTRL
2020.05.07 19:35:41 2: TCM TCM_ESP3_0 RESPONSE: OK
2020.05.07 19:35:41 2: TCM TCM_ESP3_0 repeater 0000 restored
2020.05.07 19:35:41 2: TCM TCM_ESP3_0 RESPONSE: OK
2020.05.07 19:35:41 2: TCM TCM_ESP3_0 maturity 01 restored
2020.05.07 19:35:41 2: TCM TCM_ESP3_0 RESPONSE: OK
2020.05.07 19:35:41 2: TCM TCM_ESP3_0 smartAckMailboxMax 0 restored
2020.05.07 19:35:41 2: TCM TCM_ESP3_0 RESPONSE: NOT_SUPPORTED
2020.05.07 19:35:41 2: TCM TCM_ESP3_0 initialized
2020.05.07 19:35:41 1: PERL WARNING: Use of uninitialized value in pattern match (m//) at ./FHEM/37_harmony.pm line 1765.
2020.05.07 19:35:41 2: alexa: starting alexa-fhem: /usr/local/bin/alexa-fhem -c ./alexa-fhem.cfg
2020.05.07 19:35:41 0: Featurelevel: 6
2020.05.07 19:35:41 0: Server started with 312 defined entities (fhem.pl:21762/2020-04-23 perl:5.026001 os:linux user:fhem pid:19804)
Can't use an undefined value as a subroutine reference at ./FHEM/10_MAX.pm line 850.
Signal 15 (TERM) caught by ps (3.3.12).
ps:ps/display.c:66: please report this bug
2020.05.07 19:35:42 1: UWZ uwz: UWZ.900 Error: Can't get http://feed.alertspro.meteogroup.com/AlertsPro/AlertsProPollService.php?method=getWarning&language=de&areaID=UWZde01159 -- http://feed.alertspro.meteogroup.com/AlertsPro/AlertsProPollService.php?method=getWarning&language=de&areaID=UWZde01159: Select timeout/error: Interrupted system call

Auffällig ist folgendes:

Code Auswählen


Signal 15 (TERM) caught by ps (3.3.12).
ps:ps/display.c:66: please report this bug

Es wurden folgende Module geupdated:

Code Auswählen


andreas@fhem:/opt/fhem/restoreDir/update/2020-05-07/FHEM$ ls
00_THZ.pm         70_BOTVAC.pm              98_configdb.pm
00_ZWDongle.pm    70_HYDRAWISE.pm           98_DOIF.pm
10_MAX.pm         72_XiaomiDevice.pm        98_RandomTimer.pm
10_SOMFY.pm       73_DoorBird.pm            98_readingsWatcher.pm
14_CUL_MAX.pm     73_GardenaSmartBridge.pm  98_todoist.pm
31_HUEDevice.pm   74_GardenaSmartDevice.pm  98_WeekdayTimer.pm
37_echodevice.pm  77_UWZ.pm                 controls_fhem.txt
42_SMARTMON.pm    93_DbLog.pm               lib
57_Calendar.pm    95_holiday.pm

Der Fehler lässt sich beheben wenn ich die 14_CUL_MAX.pm aus dem restoreDir zurückspiele.

Braucht ihr weitere Infos um das Problem einzugrenzen?

Grüße

Andreas

bartman121 · 07 Mai 2020, 20:14:21

ich verwende einen umgeflashten CUBE angebunden per IP-Adresse

Code Auswählen


Internals:
   CMDS       BbCFiAZNEkGMKLUYRTVWXOefhltxz
   Clients    :CUL_MAX:HMS:CUL_IR:STACKABLE_CC:TSSTACKED:STACKABLE:
   DEF        192.168.2.7:2323 1234
   DeviceName 192.168.2.7:2323
   FD         17
   FHTID      1234
   FUUID      5c49963d-f33f-1dd6-b4e6-57c84697173976f8
   NAME       cul_cube
   NR         178
   NR_CMD_LAST_H 11
   PARTIAL    
   RAWMSG     Z0F0004600703780000000039003D00B91C
   RSSI       -60
   STATE      Status:Initialized || Credits: 1301
   TYPE       CUL
   VERSION    V 1.26.03 a-culfw Build: 300 (2018-04-15_20-15-39) CUBe (F-Band: 868MHz)
   cul_cube_MSGCNT 7
   cul_cube_TIME 2020-05-07 19:54:01
   initString X21
Zr
   Helper:
     DBLOG:
       credit10ms:
         logdb:
           TIME       1588874737.21233
           VALUE      1301
   MatchList:
     1:CUL_MAX  ^Z........................
     8:HMS      ^810e04....(1|5|9).a001
     D:CUL_IR   ^I............
     H:STACKABLE_CC ^\*
     M:TSSTACKED ^\*
     N:STACKABLE ^\*
   READINGS:
     2020-05-07 19:50:38   cmds             B b C F i A Z N E k G M K L U Y R T V W X O e f h l t x z
     2020-05-07 20:05:37   credit          low
     2020-05-07 20:05:37   credit10ms      1301
     2020-05-07 19:54:01   state           Initialized
   XMIT_TIME:
     1588873842.32433
     1588873848.73208
     1588873850.23583
     1588873851.75325
     1588873853.53463
     1588873860.24118
     1588873868.43235
     1588873874.45355
     1588873880.96256
     1588873887.46516
     1588874028.77176
Attributes:
   DbLogExclude 1
   event-min-interval .*:1800
   event-on-change-reading .*
   rfmode     MAX
   room       ZZZ_RXD_TXD
   stateFormat Status:state || Credits: credit10ms
   userReadings credit {cul_credits(ReadingsVal("cul_cube","credit10ms",0));}

hier noch das "cm"-Device

Code Auswählen


Internals:
   DEF        123456
   FUUID      5c49963d-f33f-1dd6-c63f-896522ac331b9c14
   IODev      cul_cube
   LASTInputDev cul_cube
   MSGCNT     7
   NAME       cm
   NR         166
   STATE      Defined
   TYPE       CUL_MAX
   addr       123456
   cnt        0
   cul_cube_MSGCNT 7
   cul_cube_RAWMSG Z0F0004600703780000000039003D00B9
   cul_cube_RSSI -60
   cul_cube_TIME 2020-05-07 19:54:01
   pairmode   0
   retryCount 0
   READINGS:
     2020-05-07 19:51:30   packetsLost     4
   sendQueue:
Attributes:
   DbLogExclude .*
   IODev      cul_cube
   room       ZZZ_RXD_TXD

Sonst wüsste ich nicht was ich noch liefern könnte.

BTW. ich musste auch die 10_MAX.pm zurücksichern, sonst läuft MAX natürlich nicht.

Grüße

Andreas

Wzut · 08 Mai 2020, 07:14:10

und auch die ganzen anderen Fehlermeldungen beim Start verschwinden wenn du die alten Dateien wieder benutzt ?

So einen Absturz wie bei dir habe ich noch nie gesehen und kann daher nur raten. Von der 14_CUL_MAX sehe ich nichts in deinem Log Auszug wohl aber halt von 10_MAX
Ich würde daher darauf tippen das etwas mit deiner 10_MAX.pm nicht stimmt. Mach doch bitte nach 8:00 Uhr nochmal ein Update.
Wichtig : wenn du die Dateien tauschst, zur Vorsicht immer beide.
Alt CUL_MAX und neu MAX sollte gehen, aber die neue CUL_MAX brauch immer die neue MAX.

bartman121 · 08 Mai 2020, 11:10:55

mir ist noch eingegfallen, dass ich meine Thermostate per "PID20" regele. Auf initialized gibt es ein notfiy, dass direkt das maxValveSetting setzt. Scheinbar crashed fhem dabei.

Wenn ich heute update kommt die 14_CUL_MAX.pm gar nicht mit? :/

Mit der neuen 10_MAX.pm stehen meine Thermostate nach dem initialized auf "waiting for Data".

Ich bin etwas ratlos.

Grüße

Wzut · 08 Mai 2020, 13:14:34

sorry, aber jetzt blicke ich nicht durch. Läuft die neue 10_MAX nun doch ? Waiting for Data ist normal bis ein Telegramm von diesem Device empfangen wurde.

bartman121 · 08 Mai 2020, 16:09:02

Die neue 14_CUL_MAX.pm läuft leider nach wie vor nicht. Ich werde am WE das Problem mal mit verbose 5 nachstellen und die neuen Logs hier einstellen, vllt. sieht man dann mehr.

Grüße

Andreas

bartman121 · 09 Mai 2020, 10:41:49

ich habe jetzt erfolglos versucht das Problem nachzustellen, FHEM crasht weiterhin mit der neuen 14_CUL_MAX.pm. Mit verbose 5 kommen derartige viele Meldungen, dass eine Fehlersuche erfolglos erscheint.

Ich bin erstmal nicht gewillt hier weiter zu forschen und habe die Dateien als "exclude from update" gesetzt. Ich bin scheinbar auch der einzige den das betrifft, daher bitte ich um Entschuldigung, dass ich nicht weiter nachforschen will.

Grüße

Andreas

Wzut · 09 Mai 2020, 13:48:17

Zitat von: bartman121 am 09 Mai 2020, 10:41:49
Ich bin erstmal nicht gewillt hier weiter zu forschen

das ist schade, denn nur so lernt man dazu und ich bin natürlich auch neugierig.

bartman121 · 09 Mai 2020, 18:32:26

Zitat von: Wzut am 09 Mai 2020, 13:48:17
das ist schade, denn nur so lernt man dazu und ich bin natürlich auch neugierig.

Angespornt durch deinen Beitrag habe ich mir jetzt ein Testsystem (minimal) aufgebaut. Das Problem tritt auf, sobald der PID20-Regler mit ins Spiel kommt, danach stürzt fhem unvermittelt ab und das System startet fhem neu.

Ich denke das kannst du mit deinem Testsystem auch mal nachstellen nur zur Sicherheit, damit wir vom gleichen Problem reden.
Es reicht den PID20-Regler zu definieren und auch zu parametrieren und fhem neuzustarten. Danach tritt der Fehler auf.

Anbei ein List meines PID20-Reglers:

Code Auswählen


Internals:
   DEF        WZ.TEMP:temperature WZ.HT1:maxValveSetting
   FUUID      5c499640-f33f-1dd6-5a0a-d84196bf9a374cc7
   NAME       PID.WZ.HT1
   NR         209
   NTFY_ORDER 50-PID.WZ.HT1
   STATE      processing
   TYPE       PID20
   VERSION    1.0.0.9
   Helper:
     DBLOG:
       actuation:
         logdb:
           TIME       1589039896.07535
           VALUE      0
       actuationCalc:
         logdb:
           TIME       1589039776.0636
           VALUE      -22.228
       delta:
         logdb:
           TIME       1589039776.0636
           VALUE      -3.7
       desired:
         logdb:
           TIME       1589039896.07535
           VALUE      17
       measured:
         logdb:
           TIME       1589039776.0636
           VALUE      20.7
       p_d:
         logdb:
           TIME       1589039896.07535
           VALUE      0
       p_i:
         logdb:
           TIME       1589039896.07535
           VALUE      -0.028
       p_p:
         logdb:
           TIME       1589039776.0636
           VALUE      -22.2
       state:
         logdb:
           TIME       1589041332.47263
           VALUE      processing
   READINGS:
     2020-05-09 18:22:12   actuation       0
     2020-05-09 18:22:12   actuationCalc   -22.228
     2020-05-09 18:22:12   delta           -3.7
     2020-05-09 18:22:12   desired         17
     2020-05-09 18:22:12   measured        20.7
     2020-05-09 18:22:12   p_d             0
     2020-05-09 18:22:12   p_i             -0.028
     2020-05-09 18:22:12   p_p             -22.2
     2020-05-09 18:22:12   state           processing
   helper:
     actor      WZ.HT1
     actorCommand maxValveSetting
     actorErrorAction freeze
     actorErrorPos 0
     actorInterval 120
     actorKeepAlive 72000
     actorLimitLower 0
     actorLimitUpper 100
     actorThreshold 1
     actorTimestamp 2020-05-09 10:52:09
     actorValueDecPlaces 0
     adjust     
     calcInterval 60
     deltaGradient 0
     deltaOld   -3.7
     deltaOldTS 2020-05-09 18:07:58
     deltaTreshold 0
     desiredName desired
     disable    0
     factor_D   0
     factor_I   0.01
     factor_P   6
     isWindUP   1
     measuredName measured
     reading    temperature
     regexp     ^([\+,\-]?\d+\.?\d*$)
     reverseAction 0
     sensor     WZ.TEMP
     sensorTimeout 3600
     stopped    0
     updateInterval 600
Attributes:
   disable    0
   event-min-interval .*:1800
   event-on-change-reading .*
   pidActorInterval 120
   pidActorKeepAlive 72000
   pidActorValueDecPlaces 0
   pidFactor_I 0.01
   pidFactor_P 6
   room       ZZZ_System->PID

Grüße

Wzut · 09 Mai 2020, 19:59:09

hat etwas gedauert bis ich den PID20 dazu gebracht habe , aber irgendwann :

Code Auswählen

2020.05.09 19:50:32 5: PID20 PID20: Calc.697 actor:Thermo1 actorCommand:maxValveSetting actuation:30
Can't use an undefined value as a subroutine reference at ./FHEM/10_MAX.pm line 850.

Na das ist doch schon mal etwas, beim Versuch das maxValveSetting zu verdrehen kracht es.
Ich denke mal das Problem werd ich finden, nur heute nicht mehr

Wzut · 10 Mai 2020, 08:49:39

das war ne harte Nuß und hat mich einige Stunden gekostet ....
Ursachen bzw Lösungem gibt es zwei :

1. Ich wollte 10_MAX und 14_CUL_MAX robuster machen gegen das Reihenfolge Problem in der fhem.cfg.
D.h. idealerweise ist zurerst die Hardware definiert -> 00_CUL.pm
dann das CULMAX Device -> 14_CUL_MAX.pm
und dann alle MAX Geräte -> 10_MAX.pm
Wie gesagt der Idealfall, durch diverse Hardware Tauschaktionen und Tests kann diese Reihenfolge später aber abweichen, CUL steht hinter CULMAX oder CULMAX nach einem MAX Device. Um das für den User stressfrei zu bekommen habe ich beim FHEM Neustart das eine oder andere etwas verzögert. Und genau diese Verzögerung sorgt nun dafür das beim Einsatz von 98_PID20 FHEM eine Bruchlandung hinlegt sobald PID20 das erste Mal das Ventil verstellen will.
@bartman121, kannst du bitte mal deine fhem.cfg checken wie dort die Reihenfolge der Devices ist ?

2. eine andere Ursache ist wie 98_PID20.pm die Ventilverstellung aufruft :

Code Auswählen

my $cmd = sprintf( "set %s %s %g", $hash->{helper}{actor}, $hash->{helper}{actorCommand}, $actuation );
$ret = fhem $cmd;

Hier werde ich versuchen Kontakt mit John aufzunehmen und ihn bitten die beiden Zeilen leicht zu ändern :

Code Auswählen

my $cmd = sprintf( "%s %s %g", $hash->{helper}{actor}, $hash->{helper}{actorCommand}, $actuation );
$ret = CommandSet(undef, $cmd);

@bartman121, auch das kannst du mal machen wenn du es dir zutraust.

bartman121 · 10 Mai 2020, 10:06:38

du bist Klasse

auf meinem Testsystem stimmt die Reihenfolge und ich konnte das System mit der geänderten 98_PID20.pm erfolgreich wieder in Betrieb nehmen.

Auf meinem Hauptsystem kann ich die Reihenfolge nicht wirklich prüfen, da ich dort configDB nutze, aber das schaue ich mir noch an. Dort war die Änderung der 98_PID20.pm leider nicht erfolgreich. Ich denke hier stimmt die Reihenfolge nicht.

Ich muss das noch genauer untersuchen.

Grüße

Andreas

bartman121 · 10 Mai 2020, 14:17:04

komisch, ich habe jetzt mal die Dateien direkt von hier (https://svn.fhem.de/fhem/trunk/fhem/FHEM/) geholt und die 98_PID20.pm geändert und jetzt funktioniert meine Hauptinstanz auch mit den neuen Dateien.

Allerding erhalte ich bei "version" diese Hinweise:
No Id found for 14_CUL_MAX.pm
das gleiche auch für 10_MAX.pm

Habe ich etwas falsch gemacht?

Grüße

Andreas

Wzut · 10 Mai 2020, 17:06:38

So wie ich das sehe fehlt dort allen Dateien die $Id $ im Kopf. Hat für dich aber keine negativen Auswirkungen.
Wenn du die mit update 10_MAX bzw. update 14_CUL_MAX holst sollte aber eine aktuelle Id drin stehen.

kingmathers · 11 Mai 2020, 22:40:53

Ich habe ein ähnliches Problem (verwende auch PID20, habe die Datei auch schon angepasst, der Fehler besteht aber weiterhin):

Code Auswählen

Can't use an undefined value as a subroutine reference at ./FHEM/10_MAX.pm line 772.