[erledigt] Freeze-Suche rund um echodevice-Modul (viele https-Requests)

[MadMax-FHEM]

Hallo Markus (KölnSolar),

also dann hier weiter...

Allerdings glaube ich sieht das neue Log genauso/ähnlich aus!?

Aber ich bin da (noch lang) kein Fachmann

EDIT: allerdings muss ich mich dann mal um anderes Zeugs kümmern...

Gruß, Joachim

[KölnSolar]

Aber ich bin da (noch lang) kein Fachmann

Wer ist das bei so einem Thema schon ? Außer Rudi, Jörg, Andre,.....

Ja es ist ähnlich. Wie gesagt, echodevice sieht gut aus. Mal länger laufen lassen. Und evtl. global verbose=5 kurz vorher(Ich guck mir dazu immer den letzten timestamp an. Dann den event monitor und kurz vor timestamp + interval setze ich schnell auf verbose 5 und dann wieder zurück)

Ich hab jetzt auch wieder welche "einfangen" können. Sieht auch alles gut aus, außer

Code Auswählen Erweitern

2020.01.20 17:39:43.810 4: [echomaster] [echodevice_SendCommand] [getsettingstraffic] PushToCmdQueue SendURL =https://layla.amazon.de/api/traffic/settings
2020.01.20 17:39:43.810 4: [echomaster] [echodevice_SendCommand] [getsettingstraffic] PushToCmdQueue SendData=
2020.01.20 17:39:43.811 4: [echomaster] [echodevice_GetSettings] Timer INTERVAL = 30
2020.01.20 17:39:44.587 5: HttpUtils request header:
GET /api/bootstrap HTTP/1.1
Host: layla.amazon.de
User-Agent: fhem
Accept-Encoding: gzip,deflate
Connection: Close
Cookie:  Das ist aber glaub ich vom login. Vermutlich ist das noch ohne keep-alive.
Mal sehen ob Michael sich hier meldet. Sonst stups ich ihn später mal an....

[MadMax-FHEM]

Wenn ich global auf 5 setze, dann auch das fhem Log oder weiterhin "nur" das Freeze-Log!?

Aber wie geschrieben, weiß nicht genau wann ich wieder dazu komme...

Wenn heute nicht mehr, dann erst wieder morgen Abend (frühestens)...

Gruß, Joachim

[KölnSolar]

kein Stress. Ich denke wir sind jetzt auf einem guten Weg.

Bei verbose=5 natürlich das FHEM-Log. Das Problem ist, dass das freeze-Log nichts vor dem freeze anzeigt. Ich denke, dass das etwas ganz anderes als das echodevice ist.

Grüße Markus

[KernSani]

Würde es Sinn machen, Freezemon ein Attribut zu verpassen, mehr Zeit zu loggen (es gab mal ein Attribut extraSeconds, das ich aber als unnötig empfunden habe)?


Kurz, weil mobil

[KölnSolar]

Jaaaa. 
Ich hatte im Kopf, dass Du es rausnehmen wolltest. Da dachte ich heute, guck einfach mal. Und siehe da, es war noch da, aber mit dem Hinweis "ohne Funktion". 

In dem Fall wäre es wirklich hilfreich. Freezemon zeigt den freeze an, aber ab der 1. geloggten Zeile ist alles i.O. und der angezeigte freeze-Zeitpunkt lag 2,5 Sek. vorher.

Code Auswählen Erweitern

=========================================================
[Freezemon] FreezeMon: possible freeze starting at 15:35:26, delay is 2.664 possibly caused by: tmr-echodevice_GetSettings(ECHO_XXXXXXXXXXXXXXXX) tmr-echodevice_GetSettings(ECHO_XXXXXXXXXXXXXXXX) tmr-echodevice_GetSettings(ECHO_XXXXXXXXXXXXXXXX) tmr-echodevice_GetSettings(ECHO_XXXXXXXXXXXXXXXX) tmr-echodevice_GetSettings(ECHO_XXXXXXXXXXXXXXXX) tmr-echodevice_GetSettings(ECHO_XXXXXXXXXXXXXXXX) tmr-echodevice_GetSettings(ECHO_XXXXXXXXXXXXXXXX) tmr-echodevice_GetSettings(ECHO_XXXXXXXXXXXXXXXX) tmr-echodevice_GetSettings(ECHO_XXXXXXXXXXXXXXXX) tmr-echodevice_GetSettings(ECHO_XXXXXXXXXXXXXXXX) tmr-echodevice_GetSettings(ECHO_XXXXXXXXXXXXXXXX) tmr-echodevice_GetSettings(ECHO_XXXXXXXXXXXXXXXX) tmr-echodevice_GetSettings(ECHO_XXXXXXXXXXXXXXXX885954773d8605a6) tmr-echodevice_GetSettings(ECHO_XXXXXXXXXXXXXXXX) tmr-echodevice_GetSettings(echoIODev) tmr-RESIDENTStk_DurationTimer(Wohnung_DurationTimer) tmr-RESIDENTStk_DurationTimer(Ich_DurationTimer) tmr-echodevice_LoginStart(echoIODev) tmr-MQTT2_SERVER_keepaliveChecker(MQTT_Server) tmr-HMUARTLGW_CheckCredits(HM_UART) tmr-GOOGLECAST_checkConnection(Google Home Mini) tmr-GOOGLECAST_checkConnection(Google Home)
2020.01.20 15:35:28.527 5: [ECHO_XXXXXXXXXXXXXXXX] [echodevice_GetSettings] start refresh settings
.
.
.


Grüße Markus

[MadMax-FHEM]

Hmm, d.h. wenn das (wieder) mit Funktion versehen wäre, würde ich das aktivieren und dann noch mal loggen lassen...
...bzw. loggen tut FreezeMon auf dem Testsystem ja eh "dauernd" (also jetzt wieder)...

Mal sehen was zuerst kommt...
...hier die Funktion oder ich Zeit für verbose 5 bei global und dann Daten "eindichten"...

Gruß, Joachim

[KernSani]

Ich bin schneller
https://forum.fhem.de/index.php/topic,83909.msg1015390.html#new

[MadMax-FHEM]

Hmmm, bin nicht sicher, ob da mehr drin steht...

Neues Attribut fm_catchHttp auf 5
und fm_logExtraSeconds auch auf 5 (sollte ja bei Freeze 2,5s davor reichen!?)...

Ansonsten mitteilen was ich noch testen kann...

(allerdings noch mal die Anmerkung: es handelt sich um ein Testsystem wo "alles Mögliche" läuft bzw. zumindest mal ausprobiert wurde   )

Ich habe noch ein Testsystem, ebenfalls WLAN und piHole.
Mal sehen, evtl. aktiviere ich dort mal das echodevice und FreezeMon und schaue mal

Gruß, Joachim

[KölnSolar]

stimmt. fm_logExtraSeconds scheint nicht zu fruchten.

Aber was ist das

2020.01.21 00:18:06.731 5: [Freezemon] FreezeMon: Long function call detected ReadyFn:SnipsMQTT - 3.005432 seconds

? Kannst Du das mal disabeln ?

[MadMax-FHEM]

Jep, kein Problem, also disabeln...

Hmmm, stimmt, die "Gegenstelle" läuft (grad) eh nicht (mehr)...

Testsystem halt...

Gruß, Joachim

[MadMax-FHEM]

Also ich hab ma einige Dinge, die auf dem Testsystem eh (schon lange) nicht mehr aktiv sind (Snips, MQTT2_SERVER / MQTT2_DEVICE) gelöscht bzw. deaktiviert...
(alles irgendwie MQTT und die Gegenstelle[n] gibt es nicht mehr   )


Soll ich irgendwas "anders" machen oder einfach noch mal warten und Log hier einstellen!?

Aktuelle Einstellungen bei FreezeMon:

Code Auswählen Erweitern


Internals:
   FUUID      5e259aaa-f33f-55a6-5e4f-c5c709ed6e39d0d2
   NAME       FreezeMon
   NR         453
   NTFY_ORDER 99-FreezeMon
   STATE      s:19:53:16 e:19:53:19 f:3.008 d:fn-ReadyFn(SnipsMQTT) tmr-FW_closeInactiveClients(N/A)
   TYPE       freezemon
   VERSION    0.0.28
   READINGS:
     2020-01-21 19:53:19   fcDay           1137
     2020-01-21 00:00:08   fcDayLast       610
     2020-01-21 19:53:19   freezeDevice    fn-ReadyFn(SnipsMQTT) tmr-FW_closeInactiveClients(N/A)
     2020-01-21 19:53:19   freezeTime      3.008
     2020-01-21 19:53:19   ftDay           2998.82
     2020-01-21 00:00:08   ftDayLast       1597.94
     2020-01-21 19:59:28   perfmon         not active
     2020-01-21 19:53:19   state           s:19:53:16 e:19:53:19 f:3.008 d:fn-ReadyFn(SnipsMQTT) tmr-FW_closeInactiveClients(N/A)
   helper:
     DISABLED   0
     TIMER      1579633183
     apptime   
     fn         
     freeze     3.00863409042358
     intCount   14
     msg        [Freezemon] FreezeMon: possible freeze starting at 19:53:16, delay is 3.008 possibly caused by: fn-ReadyFn(SnipsMQTT) tmr-FW_closeInactiveClients(N/A)
     now        1579632799.00863
     inAt:
       HASH(0x6729450)
...
       HASH(0x5f9af60)
       HASH(0x667f468)
       HASH(0x5f711f0)
       HASH(0x1d8c3b8)
       HASH(0x2cf3ab0)
       HASH(0x5fc2988)
     logfilequeue:
     logqueue:
       ARRAY(0x66ce678)
       ARRAY(0x677ab68)
       ARRAY(0x67c9e88)
...
       ARRAY(0x651a0b8)
       ARRAY(0x6130d08)
       ARRAY(0x60d2e48)
       ARRAY(0x67d0c80)
       ARRAY(0x6831318)
       ARRAY(0x67f4630)
       ARRAY(0x62bfda8)
       ARRAY(0x6683b88)
       ARRAY(0x6130120)
       ARRAY(0x68575a8)
       ARRAY(0x6848a30)
Attributes:
   fm_CatchCmds 5
   fm_CatchFnCalls 5
   fm_CatchHttp 5
   fm_logExtraSeconds 5
   fm_logFile ./log/freeze-%Y%m%d-%H%M%S.log
   fm_logKeep 10
   room       FreezeMon,System


Irgendwann (wenn es Sinn macht) werde ich mal testen ohne piHole aber mit WLAN...
...und ohne piHole und mit LAN...

Gruß, Joachim

[KölnSolar]

da sehe ich aber immer noch dieses Snipselding. 

Soll ich irgendwas "anders" machen oder einfach noch mal warten und Log hier einstellen!?

Letzteres.

Irgendwann (wenn es Sinn macht) werde ich mal testen ohne piHole aber mit WLAN...

Die Mühe nicht mehr wert. Die Änderung von Michael hatte ja den gewünschten Erfolg. Meines Erachtens muss er das nur noch etwas auf weitere requests erweitern.

Aber wir können ja trotzdem etwas weiter gemeinsam analysieren, wo es in Deinem Testsystem hapert. Vielleicht den Titel ändern ?

Grüße Markus
PS: shutdown/restart hattest Du nach dem Download von Olis Testversion gemacht, oder ?

[MadMax-FHEM]

Hallo Markus,

vielen Dank für die Mühen!

Natürlich auch an Michael!

da sehe ich aber immer noch dieses Snipselding. 
Letzteres.Die Mühe nicht mehr wert. Die Änderung von Michael hatte ja den gewünschten Erfolg. Meines Erachtens muss er das nur noch etwas auf weitere requests erweitern.

Ich sag's ungern aber seit ich die (nicht mehr erreichbaren) MQTT-Dinger deaktiviert habe: keine Freezes mehr...

Das in dem List war wahrsch./verm. der letzte VOR dem Deaktivieren...

Aber wir können ja trotzdem etwas weiter gemeinsam analysieren, wo es in Deinem Testsystem hapert. Vielleicht den Titel ändern ?

Hmmm, hat sich wohl erledigt

Bzw.: hätten wir eh lassen können, weil für mich nicht interessant (ist nur ein Testssystem wo vieles mal ausprobiert wird usw. / wäre eher mal an der Zeit das System wieder neu aufzusetzen / aber da ich noch 2 weitere Testsysteme habe war halt immer keine Not   )
Außer es hätte "allgemein" was gebracht bzw. wenn es "allgemein" nützt, können wir auch gerne weiter machen...

PS: shutdown/restart hattest Du nach dem Download von Olis Testversion gemacht, oder ?

Jaja klar, also zumindest reload auf alle Fälle...
...und nach dem Tausch des FreezeMon mit "neuer/alter" Funktion auf jeden Fall...

Gruß, Joachim

[KölnSolar]

Hi Joachim,
das ist ja prima. freezes vom echodevice so gut wie gelöst, Oli hat jetzt doch wieder einen Sinn in seinem attr gesehen und Dein Testsystem ist auch etwas aufgeräumter. 
Und alle was gelernt.

Bis zum nächsten Mal
Markus