Autor Thema: Fhem blockiert, langsam zeitweise  (Gelesen 1060 mal)

Offline sven.scherf

  • Full Member
  • ***
  • Beiträge: 180
[gelöst]Fhem blockiert, langsam zeitweise
« Antwort #15 am: 30 Januar 2021, 12:39:31 »
Hallo,

so jetzt hat es geklappt :)

Ich weiß hier nicht mehr so richtig weiter.
Nach der Installation vom freezmon habe ich einige Aktionen gesehen die ausgeführt wurden und nicht nötig waren. Diese Probleme habe ich alle gelöst.

Die freezes sind nach wie vor vorhanden und gestern war der Hammer.
Hier hatte ich einen Ausfall um 23:25 festgestellt. Hier wollte ich mein Licht einschalten und nichts ging.
An der Homesteuerung habe ich eine LED die im 2 Sekunden Takt blinkt und wenn fhem hängt, hängt dieses logischerweise auch.

Bei der heutigen Analyse ist folgendes auffällig.
Die Feezfiles wurden um 22:36 und um 23:36 geschrieben
Laut fhem Log war der Ausfall zwischen 22:58 - 23:36.
Hier sehe ich im Freeze-Log-File von 22:59 das fhem bei regex hängen bleibt.
Aber warum im regex gibt es hier keine Timeouts ?

Zu anderen Zeiten wo fhem hängt konnte ich sowas nicht nicht beobachten.

Es lag auch der Gedanke nahe, dass der Mount von /opt/fhem/log der bei mir auf meine NAS zeigt offline war.
Dann wären ja noch log Files von fhem auf der SD-Card vom Raspi gewesen. Dies kann ich auch ausschliessen.

Heute morgen hängt fhem erneut und wieder in dem Regex von der Bundesliga Abfragen.
Diese werden ich erst einmal aussetzen und und mal schauen was hier im Regex nicht funktioniert.

Es stellt sich für mich die Frage warum fhem im Regex so lange hängt und ob hier nicht noch was anderes die Ursache ist.
Die freezes hatte ich auch wie die Bundesliga Abfrage noch ohne Probleme funktionierte.

Die Freezes in der Bundesliga Abfrage ist so heftig, dass ich hier in der config Datei von fhem die Sache deaktivieren musste.
Dies zeigt mir aber, dass dies nur ein Problem ist da dies ein neues Verhalten ist.

Hier hänge ich mal die Log-Files an. Vielleicht kann mir hier jemand einen Tipp geben wo ich noch ansetzen kann.

Fhem Log-File Ausschnitt
2021.01.29 22:58:44.533 5: in:  PINGREQ: (192)(0)
2021.01.29 22:58:44.536 4:   MQTT2_FHEM_Server_192.168.10.208_53679 Briefkasten PINGREQ
2021.01.29 22:58:44.538 5: out: PINGRESP: (208)(0)
2021.01.29 22:58:53.854 5: CUL_HM set BadK_Thermostat ?
2021.01.29 22:58:53.894 4: CUL_HM BadK_Thermostat dupe: dont process
2021.01.29 22:58:59.560 5: in:  PINGREQ: (192)(0)
2021.01.29 22:58:59.564 4:   MQTT2_FHEM_Server_192.168.10.208_53679 Briefkasten PINGREQ
2021.01.29 22:58:59.568 5: out: PINGRESP: (208)(0)
2021.01.29 23:36:11.339 1: [Freezemon] fhem_freez: possible freeze starting at 22:59:03, delay is 2228.339 possibly caused by: tmr-CODE(0x4173f08)(GetUpdate) tmr-SetExtensionsFn(N/A)
2021.01.29 23:36:11.426 3: MQTT2_FHEM_Server: MQTT2_FHEM_Server_192.168.10.208_53679/Briefkasten left us (keepalive check)
2021.01.29 23:36:23.500 1: /dev/serial/by-id/usb-busware.de_CUL868_868000-if00 disconnected, waiting to reappear (CUL_0)
2021.01.29 23:36:23.506 4: Connection accepted from MQTT2_FHEM_Server_192.168.10.208_62762
[/code]

Erster Freez-Log wo man den Freez zwischen 22:59:02 - 23:07:05 sieht
[Freezemon] fhem_freez: possible freeze starting at 22:59:03, delay is 2228.339 possibly caused by: tmr-CODE(0x4173f08)(GetUpdate) tmr-SetExtensionsFn(N/A)
2021.01.29 22:59:02.051 4: bundesligaSpieltagErgebnisse: GetUpdate called (update)
2021.01.29 22:59:02.052 4: bundesligaSpieltagErgebnisse: UpdateTimer called from GetUpdate with cmd next sets timer to call update function in 3600.0 sec at 23:59:02.051, interval 3600
setuuid
2021.01.29 22:59:02.053 5: bundesligaSpieltagErgebnisse: AddToQueue adds type update to URL https://www.kicker.de/1-bundesliga/spieltag, no data, no headers, retry 0, initial queue len: 0
2021.01.29 22:59:02.053 5: bundesligaSpieltagErgebnisse: HandleSendQueue called from AddToSendQueue, qlen = 1
2021.01.29 22:59:02.054 4: bundesligaSpieltagErgebnisse: HandleSendQueue sends update with timeout 2 to https://www.kicker.de/1-bundesliga/spieltag, No Data, No Header
2021.01.29 22:59:02.054 5: HttpUtils url=https://www.kicker.de/1-bundesliga/spieltag
2021.01.29 22:59:02.092 4: IP: www.kicker.de -> 143.204.215.109
2021.01.29 22:59:02.149 5: HttpUtils request header:
GET /1-bundesliga/spieltag HTTP/1.0
Host: www.kicker.de
User-Agent: fhem
Accept-Encoding: gzip,deflate

2021.01.29 22:59:02.355 4: https://www.kicker.de/1-bundesliga/spieltag: HTTP response code 301
2021.01.29 22:59:02.355 4: HttpUtils https://www.kicker.de/1-bundesliga/spieltag: Redirect to https://www.kicker.de:443/bundesliga/spieltag
2021.01.29 22:59:02.355 5: HttpUtils url=https://www.kicker.de:443/bundesliga/spieltag
2021.01.29 22:59:02.361 4: IP: www.kicker.de -> 143.204.215.126
2021.01.29 22:59:02.458 5: HttpUtils request header:
GET /bundesliga/spieltag HTTP/1.0
Host: www.kicker.de
User-Agent: fhem
Accept-Encoding: gzip,deflate

2021.01.29 22:59:02.642 5: Cmd: >set LED_gelb off<
2021.01.29 22:59:02.643 5: LED_gelb, in fileaccess: value 0
2021.01.29 22:59:02.646 4: DbLog logdb -> ################################################################
2021.01.29 22:59:02.646 4: DbLog logdb -> ###              start of new Logcycle                       ###
2021.01.29 22:59:02.646 4: DbLog logdb -> ################################################################
2021.01.29 22:59:02.646 4: DbLog logdb -> number of events received: 1 for device: LED_gelb
2021.01.29 22:59:02.647 4: DbLog logdb -> check Device: LED_gelb , Event: state: off
2021.01.29 22:59:02.650 5: wird an setextensions gesendet: LED_gelb ?
2021.01.29 22:59:02.654 5: End notify loop for LED_gelb
2021.01.29 22:59:02.946 4: https://www.kicker.de:443/bundesliga/spieltag: HTTP response code 200
2021.01.29 22:59:02.946 5: HttpUtils https://www.kicker.de:443/bundesliga/spieltag: Got data, length: 203536
2021.01.29 22:59:02.946 5: HttpUtils response header:

hier wird die http Site geladen. Habe ich herausgenommen, da es im der Voschau(forum) toll aussah aber nach dem Speichern alles in der Ansicht würfelte

2021.01.29 22:59:02.954 5: bundesligaSpieltagErgebnisse: ExtractReading spiel01 with regex /(?^:(?s)Begegnungen.*?gameRow".*?name">(.*?) <.*?scoreHolder__score">([0-9]?)<.*?score">([0-9]?)<.*?team__name">(.*?) <)/...
2021.01.29 22:59:02.956 5: bundesligaSpieltagErgebnisse: ExtractReading for reading01-1 sets spiel01-1 to VfB Stuttgart
2021.01.29 22:59:02.956 5: bundesligaSpieltagErgebnisse: ExtractReading value as hex is 56664220537475747467617274
2021.01.29 22:59:02.956 5: bundesligaSpieltagErgebnisse: ExtractReading for reading01-2 sets spiel01-2 to 2
2021.01.29 22:59:02.956 5: bundesligaSpieltagErgebnisse: ExtractReading value as hex is 32
2021.01.29 22:59:02.956 5: bundesligaSpieltagErgebnisse: ExtractReading for reading01-3 sets spiel01-3 to 0
2021.01.29 22:59:02.957 5: bundesligaSpieltagErgebnisse: ExtractReading value as hex is 30
2021.01.29 22:59:02.957 5: bundesligaSpieltagErgebnisse: ExtractReading for reading01-4 sets spiel01-4 to 1. FSV Mainz 05
2021.01.29 22:59:02.957 5: bundesligaSpieltagErgebnisse: ExtractReading value as hex is 312e20465356204d61696e7a203035
2021.01.29 22:59:02.957 5: bundesligaSpieltagErgebnisse: ExtractReading spiel02 with regex /(?^:(?s)Begegnungen.*?gameRow".*?gameRow".*?name">(.*?) <.*?scoreHolder__score">([0-9]?)<.*?score">([0-9]?)<.*?team__name">(.*?) <)/...
--- log skips   482.733 secs.
2021.01.29 23:07:05.691 5: bundesligaSpieltagErgebnisse: ExtractReading spiel02 did not match
2021.01.29 23:07:05.691 5: bundesligaSpieltagErgebnisse: ExtractReading spiel03 with regex /(?^:(?s)Begegnungen.*?gameRow".*?gameRow".*?gameRow".*?name">(.*?) <.*?scoreHolder__score">([0-9]?)<.*?score">([0-9]?)<.*?team__name">(.*?) <)/...
--- log skips   806.940 secs.
2021.01.29 23:20:32.631 5: bundesligaSpieltagErgebnisse: ExtractReading spiel03 did not match
2021.01.29 23:20:32.632 5: bundesligaSpieltagErgebnisse: ExtractReading spiel04 with regex /(?^:(?s)Begegnungen.*?gameRow".*?gameRow".*?gameRow".*?gameRow".*?name">(.*?) <.*?scoreHolder__score">([0-9]?)<.*?score">([0-9]?)<.*?team__name">(.*?) <)/...
--- log skips   938.682 secs.
2021.01.29 23:36:11.314 5: bundesligaSpieltagErgebnisse: ExtractReading spiel04 did not match
2021.01.29 23:36:11.314 5: bundesligaSpieltagErgebnisse: ExtractReading spiel05 with regex /(?^:(?s)Begegnungen.*?Analyse.*?Analyse.*?Analyse.*?Analyse.*?name">(.*?) <.*?scoreHolder__score">([0-9]?)<.*?score">([0-9]?)<.*?team__name">(.*?) <)/...
2021.01.29 23:36:11.317 5: bundesligaSpieltagErgebnisse: ExtractReading spiel05 did not match
2021.01.29 23:36:11.317 5: bundesligaSpieltagErgebnisse: ExtractReading spiel06 with regex /(?^:(?s)Begegnungen.*?Analyse.*?Analyse.*?Analyse.*?Analyse.*?Analyse.*?name">(.*?) <.*?scoreHolder__score">([0-9]?)<.*?score">([0-9]?)<.*?team__name">(.*?) <)/...
2021.01.29 23:36:11.320 5: bundesligaSpieltagErgebnisse: ExtractReading spiel06 did not match
2021.01.29 23:36:11.320 5: bundesligaSpieltagErgebnisse: ExtractReading spiel07 with regex /(?^:(?s)Begegnungen.*?Analyse.*?Analyse.*?Analyse.*?Analyse.*?Analyse.*?Analyse.*?name">(.*?) <.*?scoreHolder__score">([0-9]?)<.*?score">([0-9]?)<.*?team__name">(.*?) <)/...
2021.01.29 23:36:11.323 5: bundesligaSpieltagErgebnisse: ExtractReading spiel07 did not match
2021.01.29 23:36:11.323 5: bundesligaSpieltagErgebnisse: ExtractReading spiel08 with regex /(?^:(?s)Begegnungen.*?Analyse.*?Analyse.*?Analyse.*?Analyse.*?Analyse.*?Analyse.*?Analyse.*?name">(.*?) <.*?scoreHolder__score">([0-9]?)<.*?score">([0-9]?)<.*?team__name">(.*?) <)/...
2021.01.29 23:36:11.326 5: bundesligaSpieltagErgebnisse: ExtractReading spiel08 did not match
2021.01.29 23:36:11.326 5: bundesligaSpieltagErgebnisse: ExtractReading spiel09 with regex /(?^:(?s)Begegnungen.*?Analyse.*?Analyse.*?Analyse.*?Analyse.*?Analyse.*?Analyse.*?Analyse.*?Analyse.*?name">(.*?) <.*?scoreHolder__score">([0-9]?)<.*?score">([0-9]?)<.*?team__name">(.*?) <)/...
2021.01.29 23:36:11.329 5: bundesligaSpieltagErgebnisse: ExtractReading spiel09 did not match
2021.01.29 23:36:11.329 4: bundesligaSpieltagErgebnisse: Read response matched 4, unmatch 8 Reading(s)
2021.01.29 23:36:11.329 5: bundesligaSpieltagErgebnisse: Read response to update matched spiel01-1 spiel01-2 spiel01-3 spiel01-4
2021.01.29 23:36:11.329 5: bundesligaSpieltagErgebnisse: Read response to update did not match spiel02 spiel03 spiel04 spiel05 spiel06 spiel07 spiel08 spiel09
2021.01.29 23:36:11.333 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.333 4: DbLog logdb -> ###              start of new Logcycle                       ###
2021.01.29 23:36:11.333 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.333 4: DbLog logdb -> number of events received: 4 for device: bundesligaSpieltagErgebnisse
2021.01.29 23:36:11.333 4: DbLog logdb -> check Device: bundesligaSpieltagErgebnisse , Event: spiel01-1: VfB Stuttgart
2021.01.29 23:36:11.333 4: DbLog logdb -> check Device: bundesligaSpieltagErgebnisse , Event: spiel01-2: 2
2021.01.29 23:36:11.333 4: DbLog logdb -> check Device: bundesligaSpieltagErgebnisse , Event: spiel01-3: 0
2021.01.29 23:36:11.333 4: DbLog logdb -> check Device: bundesligaSpieltagErgebnisse , Event: spiel01-4: 1. FSV Mainz 05
2021.01.29 23:36:11.338 5: End notify loop for bundesligaSpieltagErgebnisse
2021.01.29 23:36:11.339 5: bundesligaSpieltagErgebnisse: HandleSendQueue called from ReadCallback, qlen = 0
2021.01.29 23:36:11.339 5: bundesligaSpieltagErgebnisse: HandleSendQueue found no usable entry in queue
2021.01.29 23:36:11.339 5: [Freezemon] fhem_freez: ----------- Starting Freeze handling at 2021.01.29 23:36:11.339 ---------------------
[Freezemon] fhem_freez: possible freeze starting at 22:59:03, delay is 2228.339 possibly caused by: tmr-CODE(0x4173f08)(GetUpdate) tmr-SetExtensionsFn(N/A)

Nachfolgender Freez-Log File, ein Ausschnitt. Dieser war viel zu lang



[Freezemon] fhem_freez: possible freeze starting at 23:36:12, delay is 11.624 possibly caused by: tmr-LGTV_WebOS_GetForgroundAppInfo(LG_TV) tmr-at_Exec(LED_gelb.blink) tmr-LGTV_WebOS_Get3DStatus(LG_TV) tmr-LGTV_WebOS_GetExternalInputList(LG_TV) tmr-LGTV_WebOS_TimerStatusRequest(LG_TV) tmr-MQTT2_SERVER_keepaliveChecker(MQTT2_FHEM_Server) tmr-PRESENCE_StartLocalScan(Handy_Sven) tmr-FW_closeInactiveClients(N/A) tmr-MQTT::GENERIC_BRIDGE::timerProc(mqttGeneric) tmr-YAMAHA_AVR_GetStatus(Receiver) tmr-HMUARTLGW_CheckCredits(myHmUART) tmr-CODE(0x4689c70)(GetStatus) tmr-ENIGMA2_GetStatus(SATReceiver) tmr-PRESENCE_StartLocalScan(Handy_Andrea) tmr-BlockingKill(N/A) tmr-at_Exec(AT_FSD_Flur_Tuer_off) tmr-at_Exec(AT_Weihnachts_LA_off) tmr-CODE(0x4173f08)(GetUpdate) tmr-CODE(0x4173f08)(GetUpdate) tmr-PRESENCE_StartLocalScan(Cam_Weg_Instar) tmr-PRESENCE_StartLocalScan(Cam_Garten_Lupas) tmr-PRESENCE_StartLocalScan(Briefkasten_aktiv) tmr-CUL_HM_ActCheck(N/A)
2021.01.29 23:36:11.353 4: LGTV_WebOS (LG_TV) - LGTV_WebOS_GetForgroundAppInfo: 0
2021.01.29 23:36:11.353 5: LGTV_WebOS (LG_TV) - Sending command: {"client-key":"4beb29f819bfc2a394265219319b78c7","id":"request_1611959771.3533","type":"request","uri":["ssap://com.webos.applicationManager/getForegroundAppInfo"]}
2021.01.29 23:36:11.353 4: LGTV_WebOS (LG_TV) - WriteFn called
2021.01.29 23:36:11.353 4: LGTV_WebOS (LG_TV) - þ ¤ 2K{;Q'i|\?-rW2"#b|Py9
z9{T(2xr4+~2( x1 P|8zi,;[/"#9ehG.smmz6(r5 |17~3*g"mK;e;ir|C>ejFi,;G9i;"jA*p#dcv_ew|P$s7S;pu[(am[$nTS%a~W9/~W?Fv@.gk]>n}s;pP\-o;o6
2021.01.29 23:36:11.353 5: exec at command LED_gelb.blink
2021.01.29 23:36:11.353 5: Cmd: >set LED_gelb on-for-timer 1<
2021.01.29 23:36:11.353 5: wird an setextensions gesendet: LED_gelb on-for-timer 1
2021.01.29 23:36:11.354 5: Cmd: >set LED_gelb on<
2021.01.29 23:36:11.354 5: LED_gelb, in fileaccess: value 1
2021.01.29 23:36:11.356 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.356 4: DbLog logdb -> ###              start of new Logcycle                       ###
2021.01.29 23:36:11.356 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.356 4: DbLog logdb -> number of events received: 1 for device: LED_gelb
2021.01.29 23:36:11.356 4: DbLog logdb -> check Device: LED_gelb , Event: state: on
2021.01.29 23:36:11.358 5: wird an setextensions gesendet: LED_gelb ?
2021.01.29 23:36:11.360 5: End notify loop for LED_gelb
2021.01.29 23:36:11.360 5: redefine at command LED_gelb.blink as +*00:00:02 set LED_gelb on-for-timer 1
2021.01.29 23:36:11.362 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.362 4: DbLog logdb -> ###              start of new Logcycle                       ###
2021.01.29 23:36:11.362 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.362 4: DbLog logdb -> number of events received: 1 for device: LED_gelb.blink
2021.01.29 23:36:11.362 4: DbLog logdb -> check Device: LED_gelb.blink , Event: state: Next: 22:59:05
2021.01.29 23:36:11.365 5: End notify loop for LED_gelb.blink
2021.01.29 23:36:11.365 4: LGTV_WebOS (LG_TV) - LGTV_WebOS_Get3DStatus: 0
2021.01.29 23:36:11.365 5: LGTV_WebOS (LG_TV) - Sending command: {"uri":["ssap://com.webos.service.tv.display/get3DStatus"],"client-key":"4beb29f819bfc2a394265219319b78c7","id":"request_1611959771.36535","type":"request"}
2021.01.29 23:36:11.365 4: LGTV_WebOS (LG_TV) - WriteFn called
2021.01.29 23:36:11.365 4: LGTV_WebOS (LG_TV) - þ œ 2K{;G9i;"jA*p#dcv_ew|P$s7A.ro[(e7F=.}[8puS2/~W?3]a?amG8"Dicu[.nm e`q"-P.b+ -8( )fz *3 y6, z9*rb.
(7;ii}q"kW:u|A?_(z1 r7.e3/x5;it`B."#9ehG.sm6
2021.01.29 23:36:11.365 5: exec at command LED_gelb.blink
2021.01.29 23:36:11.365 5: Cmd: >set LED_gelb on-for-timer 1<
2021.01.29 23:36:11.365 5: wird an setextensions gesendet: LED_gelb on-for-timer 1
2021.01.29 23:36:11.366 5: Cmd: >set LED_gelb on<
2021.01.29 23:36:11.366 5: LED_gelb, in fileaccess: value 1
2021.01.29 23:36:11.368 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.368 4: DbLog logdb -> ###              start of new Logcycle                       ###
2021.01.29 23:36:11.368 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.368 4: DbLog logdb -> number of events received: 1 for device: LED_gelb
2021.01.29 23:36:11.368 4: DbLog logdb -> check Device: LED_gelb , Event: state: on
2021.01.29 23:36:11.370 5: wird an setextensions gesendet: LED_gelb ?
2021.01.29 23:36:11.372 5: End notify loop for LED_gelb
2021.01.29 23:36:11.372 5: redefine at command LED_gelb.blink as +*00:00:02 set LED_gelb on-for-timer 1
2021.01.29 23:36:11.374 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.374 4: DbLog logdb -> ###              start of new Logcycle                       ###
2021.01.29 23:36:11.374 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.374 4: DbLog logdb -> number of events received: 1 for device: LED_gelb.blink
2021.01.29 23:36:11.374 4: DbLog logdb -> check Device: LED_gelb.blink , Event: state: Next: 22:59:07
2021.01.29 23:36:11.377 5: End notify loop for LED_gelb.blink
2021.01.29 23:36:11.377 4: LGTV_WebOS (LG_TV) - LGTV_WebOS_GetExternalInputList: 0
2021.01.29 23:36:11.377 5: LGTV_WebOS (LG_TV) - Sending command: {"client-key":"4beb29f819bfc2a394265219319b78c7","id":"request_1611959771.37746","type":"request","uri":["ssap://tv/getExternalInputList"]}
2021.01.29 23:36:11.377 4: LGTV_WebOS (LG_TV) - WriteFn called
2021.01.29 23:36:11.377 4: LGTV_WebOS (LG_TV) - þ ‹ 2K{;Q'i|\?-rW2"#b|Py9
z9{T(2xr4+~2( x1 P|8zi,;[/"#9ehG.smmz6(r5 |17|7-i,;F2p|q"kW:u|A?"5>rpq[;A8aid/mDdg|FxmW9nx^niG?LpA?"DO
2021.01.29 23:36:11.377 5: exec at command LED_gelb.blink
2021.01.29 23:36:11.377 5: Cmd: >set LED_gelb on-for-timer 1<
2021.01.29 23:36:11.378 5: wird an setextensions gesendet: LED_gelb on-for-timer 1
2021.01.29 23:36:11.378 5: Cmd: >set LED_gelb on<
2021.01.29 23:36:11.378 5: LED_gelb, in fileaccess: value 1
2021.01.29 23:36:11.380 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.380 4: DbLog logdb -> ###              start of new Logcycle                       ###
2021.01.29 23:36:11.380 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.380 4: DbLog logdb -> number of events received: 1 for device: LED_gelb
2021.01.29 23:36:11.380 4: DbLog logdb -> check Device: LED_gelb , Event: state: on
2021.01.29 23:36:11.382 5: wird an setextensions gesendet: LED_gelb ?
2021.01.29 23:36:11.384 5: End notify loop for LED_gelb
2021.01.29 23:36:11.384 5: redefine at command LED_gelb.blink as +*00:00:02 set LED_gelb on-for-timer 1
2021.01.29 23:36:11.386 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.386 4: DbLog logdb -> ###              start of new Logcycle                       ###
2021.01.29 23:36:11.386 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.386 4: DbLog logdb -> number of events received: 1 for device: LED_gelb.blink
2021.01.29 23:36:11.386 4: DbLog logdb -> check Device: LED_gelb.blink , Event: state: Next: 22:59:09
2021.01.29 23:36:11.389 5: End notify loop for LED_gelb.blink
2021.01.29 23:36:11.389 4: LGTV_WebOS (LG_TV) - run get functions
2021.01.29 23:36:11.398 4: BlockingCall (LGTV_WebOS_PresenceRun): created child (21731), uses telnetPort to connect back
2021.01.29 23:36:11.400 4: LGTV_WebOS (LG_TV) - LGTV_WebOS_GetAudioStatus: 0
2021.01.29 23:36:11.401 5: LGTV_WebOS (LG_TV) - Sending command: {"type":"request","id":"request_1611959771.4011","client-key":"4beb29f819bfc2a394265219319b78c7","uri":["ssap://audio/getStatus"]}
2021.01.29 23:36:11.402 4: LGTV_WebOS (LG_TV) - WriteFn called
2021.01.29 23:36:11.402 4: LGTV_WebOS (LG_TV) - þ ‚ 2K{;F2p|q"kW:u|A?"5"d;ir|C>ejF1/z9, |7(0(i,;Q'i|\?-rW2"#b|Py9
z9{T(2xr4+~2( x1 P|8zi,;G9i;"jA*p#dalV"o6U.tJF*tlAi]d
2021.01.29 23:36:11.417 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.417 4: DbLog logdb -> ###              start of new Logcycle                       ###
2021.01.29 23:36:11.417 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.418 4: DbLog logdb -> number of events received: 1 for device: MQTT2_FHEM_Server
2021.01.29 23:36:11.418 4: DbLog logdb -> check Device: MQTT2_FHEM_Server , Event: nrclients: 1
2021.01.29 23:36:11.426 5: End notify loop for MQTT2_FHEM_Server
2021.01.29 23:36:11.426 3: MQTT2_FHEM_Server: MQTT2_FHEM_Server_192.168.10.208_53679/Briefkasten left us (keepalive check)
2021.01.29 23:36:11.429 5: exec at command LED_gelb.blink
2021.01.29 23:36:11.429 5: Cmd: >set LED_gelb on-for-timer 1<
2021.01.29 23:36:11.430 5: wird an setextensions gesendet: LED_gelb on-for-timer 1
2021.01.29 23:36:11.432 5: Cmd: >set LED_gelb on<
2021.01.29 23:36:11.432 5: LED_gelb, in fileaccess: value 1
2021.01.29 23:36:11.435 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.435 4: DbLog logdb -> ###              start of new Logcycle                       ###
2021.01.29 23:36:11.435 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.435 4: DbLog logdb -> number of events received: 1 for device: LED_gelb
2021.01.29 23:36:11.436 4: DbLog logdb -> check Device: LED_gelb , Event: state: on
2021.01.29 23:36:11.438 5: wird an setextensions gesendet: LED_gelb ?
2021.01.29 23:36:11.443 5: End notify loop for LED_gelb
2021.01.29 23:36:11.443 5: redefine at command LED_gelb.blink as +*00:00:02 set LED_gelb on-for-timer 1
2021.01.29 23:36:11.447 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.447 4: DbLog logdb -> ###              start of new Logcycle                       ###
2021.01.29 23:36:11.447 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.447 4: DbLog logdb -> number of events received: 1 for device: LED_gelb.blink
2021.01.29 23:36:11.447 4: DbLog logdb -> check Device: LED_gelb.blink , Event: state: Next: 22:59:11
2021.01.29 23:36:11.450 5: End notify loop for LED_gelb.blink
2021.01.29 23:36:11.450 5: exec at command LED_gelb.blink
2021.01.29 23:36:11.450 5: Cmd: >set LED_gelb on-for-timer 1<
2021.01.29 23:36:11.450 5: wird an setextensions gesendet: LED_gelb on-for-timer 1
2021.01.29 23:36:11.451 5: Cmd: >set LED_gelb on<
2021.01.29 23:36:11.451 5: LED_gelb, in fileaccess: value 1
2021.01.29 23:36:11.453 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.453 4: DbLog logdb -> ###              start of new Logcycle                       ###
2021.01.29 23:36:11.453 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.453 4: DbLog logdb -> number of events received: 1 for device: LED_gelb
2021.01.29 23:36:11.454 4: DbLog logdb -> check Device: LED_gelb , Event: state: on
2021.01.29 23:36:11.456 5: wird an setextensions gesendet: LED_gelb ?
2021.01.29 23:36:11.458 5: End notify loop for LED_gelb
2021.01.29 23:36:11.458 5: redefine at command LED_gelb.blink as +*00:00:02 set LED_gelb on-for-timer 1
2021.01.29 23:36:11.460 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.460 4: DbLog logdb -> ###              start of new Logcycle                       ###
2021.01.29 23:36:11.460 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.460 4: DbLog logdb -> number of events received: 1 for device: LED_gelb.blink
2021.01.29 23:36:11.461 4: DbLog logdb -> check Device: LED_gelb.blink , Event: state: Next: 22:59:13
2021.01.29 23:36:11.463 5: End notify loop for LED_gelb.blink
2021.01.29 23:36:11.463 5: PRESENCE (Handy_Sven) - stopping timer
2021.01.29 23:36:11.463 5: PRESENCE (Handy_Sven) - starting blocking call for mode lan-ping
2021.01.29 23:36:11.475 4: BlockingCall (PRESENCE_DoLocalPingScan): created child (21732), uses telnetPort to connect back
2021.01.29 23:36:11.488 4: YAMAHA_AVR (Receiver) - append to queue of device Receiver "statusRequest basicStatus": <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Basic_Status>GetParam</Basic_Status></Main_Zone></YAMAHA_AV>
2021.01.29 23:36:11.488 5: YAMAHA_AVR (Receiver) - no commands currently running, but queue has pending commands. preparing new request
2021.01.29 23:36:11.489 5: YAMAHA_AVR (Receiver) - checking cmd queue item: 0 (cmd: statusRequest, arg: basicStatus, data: 1, priority: -, at_first: 0, not_before: 0)
2021.01.29 23:36:11.489 5: YAMAHA_AVR (Receiver) - choosed item 0 as next command
2021.01.29 23:36:11.489 4: YAMAHA_AVR (Receiver) - send command "statusRequest basicStatus": <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Basic_Status>GetParam</Basic_Status></Main_Zone></YAMAHA_AV>
2021.01.29 23:36:11.490 5: HttpUtils url=http://192.168.10.46/YamahaRemoteControl/ctrl
2021.01.29 23:36:11.491 4: IP: 192.168.10.46 -> 192.168.10.46
2021.01.29 23:36:11.494 4: YAMAHA_AVR (Receiver) - append to queue of device Receiver "statusRequest partyModeStatus": <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><System><Party_Mode><Mode>GetParam</Mode></Party_Mode></System></YAMAHA_AV>
2021.01.29 23:36:11.494 4: YAMAHA_AVR (Receiver) - append to queue of device Receiver "statusRequest toneStatus": <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Sound_Video><Tone><Bass>GetParam</Bass></Tone></Sound_Video></Main_Zone></YAMAHA_AV>
2021.01.29 23:36:11.494 4: YAMAHA_AVR (Receiver) - append to queue of device Receiver "statusRequest toneStatus": <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Sound_Video><Tone><Treble>GetParam</Treble></Tone></Sound_Video></Main_Zone></YAMAHA_AV>
2021.01.29 23:36:11.495 5: exec at command LED_gelb.blink
2021.01.29 23:36:11.496 5: Cmd: >set LED_gelb on-for-timer 1<
2021.01.29 23:36:11.497 5: wird an setextensions gesendet: LED_gelb on-for-timer 1
2021.01.29 23:36:11.499 5: Cmd: >set LED_gelb on<
2021.01.29 23:36:11.500 5: LED_gelb, in fileaccess: value 1
2021.01.29 23:36:11.508 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.508 4: DbLog logdb -> ###              start of new Logcycle                       ###
2021.01.29 23:36:11.508 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.508 4: DbLog logdb -> number of events received: 1 for device: LED_gelb
2021.01.29 23:36:11.508 4: DbLog logdb -> check Device: LED_gelb , Event: state: on
2021.01.29 23:36:11.513 5: wird an setextensions gesendet: LED_gelb ?
2021.01.29 23:36:11.519 5: End notify loop for LED_gelb
2021.01.29 23:36:11.519 5: redefine at command LED_gelb.blink as +*00:00:02 set LED_gelb on-for-timer 1
2021.01.29 23:36:11.523 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.523 4: DbLog logdb -> ###              start of new Logcycle                       ###
2021.01.29 23:36:11.523 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.523 4: DbLog logdb -> number of events received: 1 for device: LED_gelb.blink
2021.01.29 23:36:11.523 4: DbLog logdb -> check Device: LED_gelb.blink , Event: state: Next: 22:59:15
2021.01.29 23:36:11.526 5: End notify loop for LED_gelb.blink
2021.01.29 23:36:11.526 5: exec at command LED_gelb.blink
2021.01.29 23:36:11.526 5: Cmd: >set LED_gelb on-for-timer 1<
2021.01.29 23:36:11.526 5: wird an setextensions gesendet: LED_gelb on-for-timer 1
2021.01.29 23:36:11.527 5: Cmd: >set LED_gelb on<
2021.01.29 23:36:11.527 5: LED_gelb, in fileaccess: value 1
2021.01.29 23:36:11.529 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.530 4: DbLog logdb -> ###              start of new Logcycle                       ###
2021.01.29 23:36:11.530 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.530 4: DbLog logdb -> number of events received: 1 for device: LED_gelb
2021.01.29 23:36:11.530 4: DbLog logdb -> check Device: LED_gelb , Event: state: on
2021.01.29 23:36:11.532 5: wird an setextensions gesendet: LED_gelb ?
2021.01.29 23:36:11.534 5: End notify loop for LED_gelb
2021.01.29 23:36:11.535 5: redefine at command LED_gelb.blink as +*00:00:02 set LED_gelb on-for-timer 1
2021.01.29 23:36:11.537 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.537 4: DbLog logdb -> ###              start of new Logcycle                       ###
2021.01.29 23:36:11.537 4: DbLog logdb -> ################################################################
2021.01.29 23:36:11.537 4: DbLog logdb -> number of events received: 1 for device: LED_gelb.blink
2021.01.29 23:36:11.537 4: DbLog logdb -> check Device: LED_gelb.blink , Event: state: Next: 22:59:17
2021.01.29 23:36:11.540 5: End notify loop for LED_gelb.blink
2021.01.29 23:36:11.540 5: HMUARTLGW myHmUART checking credits (from timer)
2021.01.29 23:36:11.540 5: HMUARTLGW myHmUART send: 00 08
2021.01.29 23:36:11.541 5: HMUARTLGW myHmUART send: (8): fd0003001d08d633
2021.01.29 23:36:11.541 5: SW: fd0003001d08d633
2021.01.29 23:36:11.542 5: exec at command LED_gelb.blink
2021.01.29 23:36:11.542 5: Cmd: >set LED_gelb on-for-timer 1<
2021.01.29 23:36:11.543 5: wird an setextensions gesendet: LED_gelb on-for-timer 1
2021.01.29 23:36:11.543 5: Cmd: >set LED_gelb on<
2021.01.29 23:36:11.544 5: LED_gelb, in fileaccess: value 1


Vielen Dank, dass ihr hier drüberschaut.

Sven
« Letzte Änderung: 23 Februar 2021, 11:15:42 von sven.scherf »
Raspi 3 mit CUL Stick 433/868MHZ, Homematic

Offline rudolfkoenig

  • Administrator
  • Hero Member
  • *****
  • Beiträge: 23847
Antw:Fhem blockiert, langsam zeitweise
« Antwort #16 am: 30 Januar 2021, 13:36:36 »
Es schaut so aus, das deine Vermutung mit dem Regex richtig ist, und der Fall eintritt, das in dem vom mir verlinkten Artikel genauer beschrieben wird.
Ich wuerde versuchen die Daten erst mit einer anderen Methode zu extrahieren, oder wenn das nicht geht, die Regexps optimieren, auch mit Hilfe der im verlinkten Artikel beschriebenen Mittel bzw Webseiten.

Offline sven.scherf

  • Full Member
  • ***
  • Beiträge: 180
Antw:Fhem blockiert, langsam zeitweise
« Antwort #17 am: 23 Februar 2021, 11:17:54 »
Hallo,

fhem läuft nun bei mir seit geraumer Zeit wieder stabil nachdem ich die RegEx alle mal auf Eis gelegt habe.

Ich werde nun langsam wieder damit anfangen Stück für Stück zu aktivieren und einige RegEx überarbeiten.

Vielen Dank euch allen für die Hilfe und Grüße


Sven
Raspi 3 mit CUL Stick 433/868MHZ, Homematic

 

decade-submarginal