HMLAN disconnected wenn Web-Oberfläche von "remote" aufgerufen

[Thorsten Pferdekaemper]

Hi,
ich habe (glaube ich) eine neue Version der HMLAN-Disconnects. Es scheint damit zusammenzuhängen, dass ich die Fhem-Web-Oberfläche längere Zeit geöffnet habe und zwar nicht über das lokale Netzwerk. Ich habe zum Teil fehlende Daten über mehrere Minuten.
Hier ist ein typischer Auszug.
Erstmal ein Teil vom Logfile:

Code Auswählen Erweitern

2014.04.23 19:17:54 1: HMLAN_Parse: HMLAN1 new condition ok
2014.04.24 12:40:09 1: 192.168.178.152:1000 disconnected, waiting to reappear
2014.04.24 12:40:09 1: HMLAN_Parse: HMLAN1 new condition disconnected
2014.04.24 12:40:11 1: 192.168.178.152:1000 reappeared (HMLAN1)
2014.04.24 12:40:11 1: HMLAN_Parse: HMLAN1 new condition init
2014.04.24 12:40:14 1: HMLAN_Parse: HMLAN1 new condition ok

...also ein Disconnect heute um 12:40.
Dazu jetzt mal ein FileLog von einem RT zur selben Zeit:

Code Auswählen Erweitern

2014-04-24_12:24:55 eg_ws_HeizungOp T: 17.5 desired: 16.0 valve: 0
2014-04-24_12:27:59 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0
2014-04-24_12:30:48 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0
2014-04-24_12:40:09 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0
2014-04-24_12:40:12 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0
2014-04-24_12:40:13 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0
2014-04-24_12:40:45 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0
2014-04-24_12:43:27 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0
2014-04-24_12:45:53 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0
2014-04-24_12:48:06 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0
2014-04-24_12:51:08 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0

Vor 12:40 ist der letzte Eintrag so ungefähr 12:30, dann kommt erstmal 10 Minuten nichts mehr. Die fehlenden Messages scheinen dann schnell hintereinander einzutrudeln. Das Bild ist dasselbe in allen FileLogs.
Da das oft hilft, habe ich auch mal apptime gestartet. Hier ist das Ergebnis:

Code Auswählen Erweitern

                               name             function    max  count    total  average maxDly
                          HeizParams readingsGroup_Notify   7767   9818   504694    51.40      0 HASH(0xffd5a0); HASH(0xe9b4a0)
                         tmr-at_Exec       HASH(0xfac340)   3462    119    53433   449.02  29431 HASH(0xfac340)
                              HMLAN1           HMLAN_Read   1139   3029   246741    81.46      0 HASH(0xad1a60)
                         tmr-at_Exec      HASH(0x10492f0)    833    594    82376   138.68 117101 HASH(0x10492f0)
                      tmr-PID20_Calc           HeizRegler    518    589    51691    87.76  74661 HeizRegler
                        og_bd_params readingsGroup_Notify    416   9818     2107     0.21      0 HASH(0xf26930); HASH(0xe9b6f0)
                              HMLAN1          HMLAN_Ready    131      6      728   121.33      0 HASH(0xad1a60)
                         tmr-at_Exec       HASH(0xf26730)     84      9      146    16.22    112 HASH(0xf26730)
                         tmr-at_Exec       HASH(0xf23040)     82      9      145    16.11    111 HASH(0xf23040)
                 FileLog_DirksSensor          FileLog_Log     75   9818    16128     1.64      0 HASH(0x10a8ac0); HASH(0x1046da8)
                     eg_ws_HeizungOp           CUL_HM_Set     74      5      125    25.00      0 HASH(0xf21a08); eg_ws_HeizungOp; desired-temp; 17.0
                     dg_so_HeizungOp           CUL_HM_Set     72      1       72    72.00      0 HASH(0xf22950); dg_so_HeizungOp; desired-temp; 17.0
                    FileLog_Heizraum          FileLog_Log     55   9818    28024     2.85      0 HASH(0xf09690); HASH(0xe81b78)
                  FileLog_HeizRegler          FileLog_Set     50     50      698    13.96      0 HASH(0x107f2f8); FileLog_HeizRegler; ?
                    FileLog_Heizraum          FileLog_Set     50     50      656    13.12      0 HASH(0xf09690); FileLog_Heizraum; ?
             FileLog_og_sz_HeizungOp          FileLog_Log     50   9818    14851     1.51      0 HASH(0xe81028); HASH(0xffd5a0)
                     og_ku_HeizungOp           CUL_HM_Set     49    189     2589    13.70      0 HASH(0xe65498); og_ku_HeizungOp; ?
               tmr-HTTPMOD_GetUpdate       HASH(0xe9b4a0)     48    589     4297     7.30  74796 HASH(0xe9b4a0)
                  FileLog_Everything          FileLog_Log     46   9818    19500     1.99      0 HASH(0xe9bb20); HASH(0x1046da8)
                          eventTypes    eventTypes_Notify     46   9818    11696     1.19      0 HASH(0xa87b98); HASH(0xe4fc70)
                  FileLog_HeizRegler          FileLog_Log     43   9818    31399     3.20      0 HASH(0x107f2f8); HASH(0xe80cc8)

Dass das readingsGroup_Notify manchmal etwas lange dauert wundert mich etwas. Ich weiß allerdings nicht, was dahintersteckt. Außerdem ist das kein Grund für einen 10-Minuten Aussetzer, oder?
Der Vollständigkeit halber ist hier mal ein List der readingsGroup:

Code Auswählen Erweitern

Internals:
   DEF        Heizkessel:<Soll Vorlauf>,VLSoll,< >,Hauptschalter Heizkessel:<Vorlauf>,VLTemp,smoothVL,<Rücklauf>,RLTemp,smoothRL Heizkessel:<Außen>,AusTemp,< >,<System>,SysTemp
   NAME       HeizParams
   NR         78
   NTFY_ORDER 50-HeizParams
   STATE      Initialized
   TYPE       readingsGroup
   mayBeVisible 1
   Content:
     Heizkessel 1
   DEVICES:
     ARRAY(0x12193f8)
     ARRAY(0x12df528)
     ARRAY(0x12916b8)
   Fhem:
     last_update 1397462647.16794
   Helper:
     Bm:
       Readingsgroup_get:
         cnt        2
         dmx        0
         mAr       
         max        0
         tot        0
       Readingsgroup_notify:
         cnt        9855
         dmx        0
         mAr        HASH(0xffd5a0); HASH(0xe9b4a0)
         max        7767
         tot        504735
Attributes:
   group      Heizraum
   mapping    { "Heizkessel" => "" }
   noheading  1
   nostate    1
   notime     1
   room       Heizraum
   valueFormat {smoothVL => "(%u °C)", smoothRL => "(%u °C)", VLSoll => "%u °C", AusTemp => "%u °C" , VLTemp => "%u °C", RLTemp => "%u °C", SysTemp => "%u °C" }
   valueIcon  { "Hauptschalter.on" => "Heizung_Hauptschalter.on", "Hauptschalter.off" => "Heizung_Hauptschalter.off" }
   valueStyle style="text-align:right"


Wie gesagt, das ganze scheint nur zu passieren, wenn ich die Web-Oberfläche eine Weile offen lasse und nicht über mein lokales Netzwerk reingehe.
Hat jemand Rat?
Gruß,
    Thorsten

[martinp876]

Hallo Thorsten,

Ich gehe erst einmal davon aus, dass irgend jemand hier "blockiert" - das muss nicht in FHEM intern sein.

Die verzögerten Messages sind interessant. Das Device sendet sicher Zyklich. HMLAN - vermute ich - kann die nicht speichern, also vermute ich, werden die messages in Puffer des OS hinterlegt - und FHEM wartet darauf dran zu kommen. Wenn der 'blockierer' fertig ist, geht es los.
=> wenn du rohmessages aufzeichnest kann ich einiges ablesen

apptime
mit apptime maxDly wird nach der maximalen Verzögerung sortiert. Die max Verarbeitungszeit ist mit 7 sec manchmal kritisch - aber das kann gelegentlich vorkommen. Die maxDly (ein Timer kommt nicht pünktlich, sondern verspätet an den start) ist deutlich schlechter. Da die Werte nicht nach maxDly sortiert sind können noch weitere anstehen. Hier sind Werte von bis zu 2 min zu sehen. Da ich keinen internen Langläufer in dieser Größenordnung sehen ist es wohl ein FHEM externen Prozess, der Ärger macht.

Dass das disconnect so spät gemeldet wird kann den gleichen Grund haben - FHEM kommt nicht dran.

Gruss Martin

ps: was sagt da HMLAN? Da werden auf delays ausgewertet

[Thorsten Pferdekaemper]

Hi,
hier ist das Ergebnis von "apptime maxDly":

Code Auswählen Erweitern

                                name             function    max  count    total  average maxDly
                 tmr-HMLAN_KeepAlive     keepAlive:HMLAN1     11   4261     9664     2.27 120942 keepAlive:HMLAN1
               tmr-HttpUtils_ConnErr       HASH(0xe9b4a0)      3   1779       10     0.01 119095 HASH(0xe9b4a0)
               tmr-HttpUtils_ReadErr       HASH(0xe9b4a0)      1   1779        6     0.00 119092 HASH(0xe9b4a0)
                         tmr-at_Exec      HASH(0x10492f0)    833   1785   204491   114.56 117101 HASH(0x10492f0)
              tmr-FW_closeOldClients                          14   1782     2363     1.33  79862
                tmr-HMLAN_UpdtMsgCnt       UpdtMsg:HMLAN1     10   1069     1118     1.05  79709 UpdtMsg:HMLAN1
                 tmr-CUL_HM_ActCheck       ActionDetector     35    178     2611    14.67  79299 ActionDetector
               tmr-HTTPMOD_GetUpdate       HASH(0xe9b4a0)     75   1779    12769     7.18  74796 HASH(0xe9b4a0)
                      tmr-PID20_Calc           HeizRegler    518   1779   138233    77.70  74661 HeizRegler
                         tmr-at_Exec       HASH(0xfac340)   3462    357    88350   247.48  29431 HASH(0xfac340)
            tmr-HMLAN_KeepAliveCheck   keepAliveCk:HMLAN1      8   4256       36     0.01   1759 keepAliveCk:HMLAN1
                         tmr-at_Exec       HASH(0xf26730)     84     29      387    13.34    112 HASH(0xf26730)
                         tmr-at_Exec       HASH(0xf23040)     82     29      380    13.10    111 HASH(0xf23040)
               tmr-HttpUtils_ConnErr      HASH(0x12a3f20)      0      1        0     0.00    103
               tmr-HttpUtils_ConnErr      HASH(0x135e178)      0      1        0     0.00    103
               tmr-HttpUtils_ReadErr      HASH(0x12a3f20)      0      1        0     0.00     97
               tmr-HttpUtils_ReadErr      HASH(0x135e178)      0      1        0     0.00     97
               tmr-HttpUtils_ConnErr      HASH(0x12915f8)      0      1        0     0.00     71
               tmr-HttpUtils_ReadErr      HASH(0x12915f8)      0      1        0     0.00     66
               tmr-HttpUtils_ConnErr      HASH(0x12a0e68)      0      2        0     0.00     63
               tmr-HttpUtils_ReadErr      HASH(0x12a0e68)      0      2        0     0.00     57
Hilft das weiter?

ps: was sagt da HMLAN? Da werden auf delays ausgewertet

Ich weiß nicht genau, was Du meinst. Vielleicht ein "list HMLAN"? Et voílà:

Code Auswählen Erweitern

Internals:
   DEF        192.168.178.152:1000
   DeviceName 192.168.178.152:1000
   FD         20
   HMLAN1_MSGCNT 45215
   HMLAN1_TIME 2014-04-25 18:32:08
   HM_CMDNR   145
   NAME       HMLAN1
   NR         20
   NTFY_ORDER 50-HMLAN1
   PARTIAL   
   RAWMSG     E6FB75E,0000,47557993,FF,FFC5,C4A2706FB75E21F83300E43703E5000000000943
   RSSI       -59
   STATE      opened
   TYPE       HMLAN
   XmitOpen   1
   assignedIDs 21F923,21FBB2,21FC81,21F833,21F83C
   assignedIDsCnt 5
   assignedIDsReport 5
   firmware   0.961
   msgKeepAlive dlyMax:989.776 bufferMin:-984
   msgLoadEst 1hour:0% 10min steps: 0/0/0/0/0/0
   msgParseDly min:-31 max:462142 last:6 cnt:44812
   owner      23A3F4
   serialNr   KEQ0851839
   uptime     013 332:26:24.019
   Readings:
     2014-04-24 14:25:58   Xmit-Events     ok:1
     2014-04-24 14:25:58   cond            ok
     2014-04-24 14:25:56   prot_disconnected last
     2014-04-24 14:25:56   prot_init       last
     2014-04-24 14:25:58   prot_ok         last
     2014-04-11 22:08:33   prot_timeout    last
   Assids:
     21F833     1
     21F83C     1
     21F923     1
     21FBB2     1
     21FC81     1
   Helper:
     000001:
       flg        0
       msg       
       to         1398342358.55178
     21f833:
       chn        02
       flg        0
       msg       
       name       og_bd_Heizung
       to         1398423727.5534
     21f83c:
       chn        02
       flg        0
       msg       
       name       dg_so_Heizung
       to         1398389814.29172
     21f923:
       chn        02
       flg        0
       msg       
       name       og_sz_Heizung
       to         1398382343.82832
     21fbb2:
       chn        02
       flg        0
       msg       
       name       og_ku_Heizung
       to         1398381302.40932
     21fc81:
       chn        02
       flg        0
       msg       
       name       eg_ws_Heizung
       to         1398382810.3759
     23a3f4:
       flg        0
     6fb75e:
       chn        02
       flg        0
       msg       
       name       DirksSensor
       to         1398283371.02146
     Bm:
       Hmlan_notify:
         cnt        26983
         dmx        0
         mAr        HASH(0xad1a60); HASH(0xe81b78)
         max        33
         tot        154
       Hmlan_read:
         cnt        9199
         dmx        0
         mAr        HASH(0xad1a60)
         max        1139
         tot        684011
       Hmlan_ready:
         cnt        6
         dmx        0
         mAr        HASH(0xad1a60)
         max        131
         tot        728
     Dly:
       cnt        44812
       lst        6
       max        462142
       min        -31
     K:
       BufMin     -984
       DlyMax     989.776
       Next       1398443538.97202
       Start      1398443513.97202
     Log:
       all        0
       sys        0
       ids:
     Q:
       HMcndN     0
       answerPend 0
       hmLanQlen  1
       keepAliveRec 1
       keepAliveRpt 0
       apIDs:
       Cap:
         0          0
         1          0
         2          0
         3          0
         4          0
         5          0
         last       3
         sum        0
     Ref:
       drft       -7.99808046068943e-05
       hmtL       1196769561
       kTs        0
       offL       1397246744418
       sysL       1398443513979
Attributes:
   hmId       23A3F4
   hmLanQlen  1_min
   logIDs     
   wdTimer    25


Rohmessages kann ich momentan nicht liefern, da ich innerhalb meines lokalen Netzes. Ich wollte meinen "Arbeits-Rechner" heute nicht einschalten...
Das werde ich aber noch nachliefern, falls es hilft.
Gruß,
    Thorsten

[martinp876]

hi

hier ist das Ergebnis von "apptime maxDly":

du kannst klar ablesen, dass es eine Verzögerung von 2 min gibt. Auch keepalive ist betroffen (klar). wenn das nicht alle 30sec kommt gibt es einen Disconnect.
Zusammen mit der Auswertung der max zeiten bin ich mir sicher, dass das Problem außerhalb von FHEM liegt. Ich sehen keinen FHEM task, der 2 min verbraucht.

Vielleicht ein "list HMLAN"?

korrekt

msgKeepAlive dlyMax:989.776 bufferMin:-984
   msgParseDly min:-31 max:462142 last:6 cnt:44812

keepalive zeigt das Bild noch dramatischer. Hier ist eine Verzögerung von 989 sekunden eingetragen, das sind 15 minuten!
msgParseDly saget, dass eine Nachricht vom HMLAN nach FHEM zumindest einmal 462 sekunden gebracht hat - das sind auch schon 7 Minuten.

Du musst also besser extern suchen. Rohmessages werden nicht weiter helfen. Während dieser Zeit passiert etwas in deinem System, das du mit OS-mittlen fangen musst. Task-performance untersucht, top und ps nutzen, vielleicht hast du noch sonstige tools.
Macht dein Sytem in dieser Zeit irgend etwas? 15 min sind schon eine Hausnummer!

[Thorsten Pferdekaemper]

Du musst also besser extern suchen. Rohmessages werden nicht weiter helfen. Während dieser Zeit passiert etwas in deinem System, das du mit OS-mittlen fangen musst. Task-performance untersucht, top und ps nutzen, vielleicht hast du noch sonstige tools.
Macht dein Sytem in dieser Zeit irgend etwas? 15 min sind schon eine Hausnummer!

Hi,
vielen Dank soweit erstmal. Das ganze läuft (momentan noch) auf einer FritzBox. Ich werde demnächst wahrscheinlich auf einen RasPi umziehen. Wenn es was FHEM-externes sein sollte, dann ist die Wahrscheinlichkeit groß, dass es dann sowieso verschwindet.
...oder hat noch jemand eine Idee, wie man auf der FritzBox am einfachsten Prozesse mitloggt?
Gruß,
    Thorsten

[frank]

hallo thorsten,

probiere mal dies http://forum.fhem.de/index.php/topic,16347.msg106295.html#msg106295

da in deinen apptime aufzeichnungen häufig "http" auftaucht, kann es mit modulen zusammenhängen die über lan arbeiten. ich hatte ähnliche erfahrungen.

gruss frank

[Thorsten Pferdekaemper]

da in deinen apptime aufzeichnungen häufig "http" auftaucht, kann es mit modulen zusammenhängen die über lan arbeiten. ich hatte ähnliche erfahrungen.

Rein theoretisch müssten doch die Module, die mit http arbeiten, das asynchron tun. D.h. das dürfte eigentlich nichts blockieren. Naja, außer vielleicht es werden mehr Requests abgesetzt als die FritzBox verarbeiten kann (aus welchen Gründen auch immer). Dann muss vielleicht der HMLAN auch mal warten. (Keine Ahnung ob das, was ich da sage, sonderlich sinnvoll ist.)
Gruß,
    Thorsten

[frank]

probier den performance monitor einfach mal aus. ganz einfach.

nur das modul in den FHEM ordner kopieren und fhem neu starten. anscliessend siehst du fhem verzögerungen, die länger als eine sekunde dauern, durch logeinträge in fhem.log.

schon bist du ein schritt weiter.

gruss frank