Neues Modul: 98_FREEZEMON Freezes monitoren und Verursacher identifizieren

herrmannj · 15 Januar 2020, 13:57:33

der geforkte child prozess ist eine 1 zu 1 Kopie des Elternprozess. timer im parent -> timer im child. Die Frage ist ob im child die codestelle erreicht wird wo der timer ausgewertet wird.

KölnSolar · 15 Januar 2020, 14:12:58

Mir scheint das, was Jörg schreibt, ist plausibel. Ich hab mir den Code noch einmal genau unter dem Aspekt dieses freezes angeguckt

Zitat[Freezemon] freezedetect: possible freeze starting at 13:25:48, delay is 0.558 possibly caused by: no bad guy found
2020.01.15 13:25:47.045 5: Cmd: >{BlockingStart('204241')}<
2020.01.15 13:25:47.049 5: Cmd: >{Nina_Done('NinaTest|durationFetchReadings|1.00|WarnCount|0|WarnCountInArea|0')}<
2020.01.15 13:25:47.049 5: Nina Nina: Done.464 Beginning processing of selected data.
----dies ist ein Insider für Jörg: Nina verwendet also schon BlockingCall
.
.
2020.01.15 13:25:47.052 4: Nina NinaTest: Done.550 3 values captured
2020.01.15 13:25:47.064 5: End notify loop for NinaTest
2020.01.15 13:25:47.233 5: TRX: TRX_Read '0f5c01017ef5e5000000007cb9003260'
.
2
2020.01.15 13:25:47.357 4: https://layla.amazon.de/api/devices-v2/device?cached=true&_=1579091145: HTTP response code 200
2020.01.15 13:25:47.357 5: HttpUtils https://layla.amazon.de/api/devices-v2/device?cached=true&_=1579091145: Got data, length: 1283
2020.01.15 13:25:47.357 5: HttpUtils response header:
HTTP/1.1 200 OK ......
2020.01.15 13:25:47.358 4: [echomaster] [echodevice_Parse] [devicesstate]
2020.01.15 13:25:47.359 5: [echomaster] [echodevice_Parse] [devicesstate] DATA Dumper=$VAR1 = '{"devices": .....[
2020.01.15 13:25:47.363 4: [echomaster] [echodevice_HandleCmdQueue] [getisonline] send command=https://layla.amazon.de/api/devices-v2/device?cached=true&_=1579091145 Data=
2020.01.15 13:25:47.364 5: HttpUtils url=https://layla.amazon.de/api/devices-v2/device?cached=true&_=1579091145
2020.01.15 13:25:47.364 4: IP: layla.amazon.de -> 99.86.111.54
2020.01.15 13:25:47.371 5: TRX: TRX_Read '0f5c010240dae6'
.
.
2020.01.15 13:25:47.406 5: TRX_Read END
2020.01.15 13:25:47.504 5: HttpUtils request header:
GET /api/devices-v2/device?cached=true&_=1579091145 HTTP/1.1
Host: layla.amazon.de
2020.01.15 13:25:47.508 4: Connection accepted from telnetForBlockingFn_1578672571_127.0.0.1_56182
2020.01.15 13:25:47.510 5: Cmd: >{BlockingStart('204242')}<
2020.01.15 13:25:47.514 5: Cmd: >{GPIO4_PollfinishFn('RPi_OW_WWL|28|0317717e8aff|T: 28.312|28.312')}<
2020.01.15 13:25:47.514 5: GPIO4: GPIO4_PollfinishFn(RPi_OW_WWL) Start
2020.01.15 13:25:47.514 5: GPIO4: GPIO4_PollfinishFn(RPi_OW_WWL) EndreadingsBulkUpdate
2020.01.15 13:25:47.515 5: GPIO4: GPIO4_PollfinishFn(RPi_OW_WWL) EndreadingsUpdate
2020.01.15 13:25:47.515 5: GPIO4: GPIO4_PollfinishFn(RPi_OW_WWL) End
2020.01.15 13:25:47.870 4: https://layla.amazon.de/api/devices-v2/device?cached=true&_=1579091145: HTTP response code 200
2020.01.15 13:25:47.871 5: HttpUtils https://layla.amazon.de/api/devices-v2/device?cached=true&_=1579091145: Got data, length: 1283
2020.01.15 13:25:47.871 5: HttpUtils response header:
HTTP/1.1 200 OK
2020.01.15 13:25:47.871 4: [echomaster] [echodevice_Parse] [getisonline]
2020.01.15 13:25:47.872 5: [echomaster] [echodevice_Parse] [getisonline] DATA Dumper=$VAR1 = '{"devices":....
2020.01.15 13:25:47.873 4: [echomaster] [echodevice_HandleCmdQueue] [getdevicesettings] send command=https://layla.amazon.de/api/device-preferences Data=
2020.01.15 13:25:47.873 5: HttpUtils url=https://layla.amazon.de/api/device-preferences
2020.01.15 13:25:47.874 4: IP: layla.amazon.de -> 99.86.111.54
2020.01.15 13:25:48.552 5: HttpUtils request header:
GET /api/device-preferences HTTP/1.1
2020.01.15 13:25:48.558 5: [Freezemon] freezedetect: ----------- Starting Freeze handling at 2020.01.15 13:25:48.558 ---------------------
[Freezemon] freezedetect: possible freeze starting at 13:25:48, delay is 0.558 possibly caused by: no bad guy found

[

hier

Code Auswählen

2020.01.15 13:25:47.364 5: HttpUtils url=https://layla.amazon.de/api/devices-v2/device?cached=true&_=1579091145

war der nonblocking_get request. dann der dns

Code Auswählen

2020.01.15 13:25:47.364 4: IP: layla.amazon.de -> 99.86.111.54

und nun die Antwort

Code Auswählen

2020.01.15 13:25:47.870 4: https://layla.amazon.de/api/devices-v2/device?cached=true&_=1579091145: HTTP response code 200

Also 500 ms, die aber gar nicht wehtun.

Vor der Antwort war ein

Code Auswählen

2020.01.15 13:25:47.515 5: GPIO4: GPIO4_PollfinishFn(RPi_OW_WWL) End

350ms wo nichts passierte. Aber eben kein freeze, sondern nur 2 verschiedene Prozesse(GPIO4_PollfinishFn ist die FinishFN eines BlockingCall).

Was meinst Du, Oli ?

KernSani · 15 Januar 2020, 14:31:49

Klingt auf die Schnell plausibel... Ich spiele heute abend mal ein bisschen rum...

Kurz, weil mobil

schnuddel · 15 Januar 2020, 16:11:32

Hi,

ich habe immer wieder freezes und finde den Verursacher nicht. Hier mal die Ausgabe des logs von freezemon:

Code Auswählen


=========================================================
[Freezemon] myFreezemon: possible freeze starting at 15:46:16, delay is 179.938 possibly caused by: tmr-BOTVAC::GetStatus(Horst) tmr-CUL_HM_procQs(N/A) tmr-perfmon_ProcessTimer(N/A)
2020.01.15 15:46:15.038 5: BOTVAC Horst: called function GetStatus()
2020.01.15 15:46:15.039 4: BOTVAC Horst: Read password from file
2020.01.15 15:46:15.040 5: BOTVAC Horst: called function SendCommand()
2020.01.15 15:46:15.040 4: BOTVAC Horst: REQ messages/getRobotState
2020.01.15 15:46:15.040 4: BOTVAC Horst: successors 0: messages,getSchedule 1: messages,getGeneralInfo 2: messages,getPreferences
2020.01.15 15:46:15.040 5: BOTVAC Horst: POST https://nucleo.neatocloud.com:4443/vendors/neato/robots/XXX/messages ({"reqId":"0","cmd":"getRobotState"})
2020.01.15 15:46:15.040 5: BOTVAC Horst: header Accept: application/vnd.neato.nucleo.v1^M
Content-Type: application/json^M
Date: Wed, 15 Jan 2020 14:46:15 GMT^M
Authorization: NEATOAPP XXX
2020.01.15 15:46:15.040 5: HttpUtils url=https://nucleo.neatocloud.com:4443/vendors/neato/robots/XXX/messages
2020.01.15 15:46:15.054 4: IP: nucleo.neatocloud.com -> 54.90.247.80
2020.01.15 15:46:15.387 5: HttpUtils request header:
POST /vendors/neato/robots/XXX/messages HTTP/1.0^M
Host: nucleo.neatocloud.com:4443^M
User-Agent: fhem^M
Accept-Encoding: gzip,deflate^M
Accept: application/vnd.neato.nucleo.v1^M
Content-Type: application/json^M
Date: Wed, 15 Jan 2020 14:46:15 GMT^M
Authorization: NEATOAPP XXX^M
Content-Length: 35^M

2020.01.15 15:46:15.742 4: https://nucleo.neatocloud.com:4443/vendors/neato/robots/XXX/messages: HTTP response code 200
2020.01.15 15:46:15.742 5: HttpUtils https://nucleo.neatocloud.com:4443/vendors/neato/robots/XXX/messages: Got data, length: 757
2020.01.15 15:46:15.742 5: HttpUtils response header:
HTTP/1.0 200 OK^M
server: Cowboy^M
date: Wed, 15 Jan 2020 14:46:14 GMT^M
content-length: 757^M
Access-Control-Allow-Origin: *^M
Access-Control-Allow-Methods: GET,POST,PUT,DELETE,OPTIONS^M
Access-Control-Allow-Headers: Accept,Date,X-Date,Authorization^M
Content-Type: application/json
2020.01.15 15:46:15.742 5: BOTVAC Horst: called function ReceiveCommand() rc: HASH(0x34d1ee0) err:  data: {"version":1,"reqId":"0","result":"ok","data": {},"error":null,"alert":null,"state":1,"action":0,"cleaning": {"category":0,"mode":1,"modifier":1,"navigationMode":1,"spotWidth":0,"spotHeight":0},"details": {"isCharging":false,"isDocked":true,"isScheduleEnabled":false,"dockHasBeenSeen":false,"charge":98},"availableCommands": {"start":true,"stop":false,"pause":false,"resume":false,"goToBase":false},"availableServices": {"findMe":"basic-1","generalInfo":"basic-1","houseCleaning":"basic-4","IECTest":"advanced-1","logCopy":"basic-1","manualCleaning":"basic-1","maps":"basic-2","preferences":"basic-2","schedule":"basic-2","softwareUpdate":"basic-1","spotCleaning":"basic-3","wifi":"basic-1"},"meta": {"modelName":"BotVacD7Connected","firmware":"4.5.3-189"}}
2020.01.15 15:46:15.742 4: BOTVAC Horst: RCV messages/getRobotState
2020.01.15 15:46:15.742 4: BOTVAC Horst: successors 0: messages,getSchedule 1: messages,getGeneralInfo 2: messages,getPreferences
2020.01.15 15:46:15.742 4: BOTVAC Horst: RES messages/getRobotState - {"version":1,"reqId":"0","result":"ok","data": {},"error":null,"alert":null,"state":1,"action":0,"cleaning": {"category":0,"mode":1,"modifier":1,"navigationMode":1,"spotWidth":0,"spotHeight":0},"details": {"isCharging":false,"isDocked":true,"isScheduleEnabled":false,"dockHasBeenSeen":false,"charge":98},"availableCommands": {"start":true,"stop":false,"pause":false,"resume":false,"goToBase":false},"availableServices": {"findMe":"basic-1","generalInfo":"basic-1","houseCleaning":"basic-4","IECTest":"advanced-1","logCopy":"basic-1","manualCleaning":"basic-1","maps":"basic-2","preferences":"basic-2","schedule":"basic-2","softwareUpdate":"basic-1","spotCleaning":"basic-3","wifi":"basic-1"},"meta": {"modelName":"BotVacD7Connected","firmware":"4.5.3-189"}}
2020.01.15 15:46:15.744 4: BOTVAC Horst: Read password from file
2020.01.15 15:46:15.744 5: BOTVAC Horst: called function SendCommand()
2020.01.15 15:46:15.744 4: BOTVAC Horst: REQ messages/getSchedule
2020.01.15 15:46:15.745 4: BOTVAC Horst: successors 0: messages,getGeneralInfo 1: messages,getPreferences
2020.01.15 15:46:15.745 5: BOTVAC Horst: POST https://nucleo.neatocloud.com:4443/vendors/neato/robots/XXX/messages ({"reqId":"0","cmd":"getScheduleEvents"})
2020.01.15 15:46:15.745 5: BOTVAC Horst: header Accept: application/vnd.neato.nucleo.v1^M
Content-Type: application/json^M
Date: Wed, 15 Jan 2020 14:46:15 GMT^M
Authorization: NEATOAPP XXX
2020.01.15 15:46:15.745 5: HttpUtils url=https://nucleo.neatocloud.com:4443/vendors/neato/robots/XXX/messages
2020.01.15 15:46:15.746 4: IP: nucleo.neatocloud.com -> 54.90.247.80
--- log skips   180.191 secs.
2020.01.15 15:49:15.938 4: HttpUtils: https://nucleo.neatocloud.com:4443/vendors/neato/robots/XXX/messages: Can't connect(2) to https://nucleo.neatocloud.com:4443:  SSL wants a read first
2020.01.15 15:49:15.938 5: BOTVAC Horst: called function ReceiveCommand() rc: HASH(0x341c0a0) err: https://nucleo.neatocloud.com:4443/vendors/neato/robots/XXX/messages: Can't connect(2) to https://nucleo.neatocloud.com:4443:  SSL wants a read first data:
2020.01.15 15:49:15.938 4: BOTVAC Horst:messages/getScheduleEvents RCV https://nucleo.neatocloud.com:4443/vendors/neato/robots/XXX/messages: Can't connect(2) to https://nucleo.neatocloud.com:4443:  SSL wants a read first
2020.01.15 15:49:15.938 4: BOTVAC Horst: drop successors
2020.01.15 15:49:15.938 4: BOTVAC Horst: successors 0: messages,getGeneralInfo 1: messages,getPreferences
2020.01.15 15:49:15.938 1: Perfmon: possible freeze starting at 15:46:16, delay is 179.938
2020.01.15 15:49:15.939 5: [Freezemon] myFreezemon: ----------- Starting Freeze handling at 2020.01.15 15:49:15.939 ---------------------
2020.01.15 15:49:15.939 5: [Freezemon] myFreezemon found something that's not a REF CUL_HM_procQs
2020.01.15 15:49:15.939 5: Freezemon: something went wrong CUL_HM_procQs
[Freezemon] myFreezemon: possible freeze starting at 15:46:16, delay is 179.938 possibly caused by: tmr-BOTVAC::GetStatus(Horst) tmr-CUL_HM_procQs(N/A) tmr-perfmon_ProcessTimer(N/A)

Hat das was mit Homematic zu tun? Wonach könnte ich denn suchen? Welche logs würden helfen?

Danke schon mal!

KölnSolar · 15 Januar 2020, 16:22:59

Nein, mit Deinem Staubsauger(Vermutung)
Respekt 189 Sek.
Du kannst im 1. Schritt mal dnsServer im global-device setzen(wenn Du nichts besseres hast müsste 8.8.8.8 funktionieren).
Wenn es bei den freezes bleibt, müsstest Du den Modulautor fragen, ob er nonblocking_get einsetzt. Wenn nicht, sollte er das tun....

KernSani · 15 Januar 2020, 16:41:03

und bitte nicht perfmon und freezemon parallel laufen lassen

KernSani · 15 Januar 2020, 22:37:57

Zurück zur Blocking Diskussion:
ich habe mir blocking.pm angesehen und ein bisschen über fork gelesen und ein bisschen getestet (einen BlockingCall gebastelt der für ein paar Sekunden sleep macht, Log schreibt, nochmal schläft etc...), folgende Erkenntnis: ich konnte freezemon nicht dazu bringen, den blocking call auszuwerten, obwohl es logisch gesehen eigentlich möglich sein müsste
Zur Sicherheit könnte ich noch im freezemon eine Abfrage einbauen, Rudi ist nämlich so nett und setz im Child $fhemForked, man kann also leicht rausfinden ob man parent oder child ist.

Nun zum eigentlichen Thema HttpUtils_NonblockingGet: Hier sieht das anders aus... Ich bin davon ausgegangen, dass HttpUtils intern blocking nutzt. Ist aber nicht so. HttpUtils_NonblockingGet läuft mit IO::Socket::INET im non-blocking mode... Da bin ich Netzwerk- und perltechnisch leider nicht wirklich in der Lage zu sagen, was da genau passiert. Aber so wie ich das verstehe läuft es im selben Prozess - d.h. m.E. sind Freezes die hier auftreten echte Freezes. Wie genau sich das äußert und warum echodevice da irgendwie auffällig ist muss ich irgendwie noch genauer untersuchen (auch wenn ich gerade nicht weiß wie).

KölnSolar · 15 Januar 2020, 22:50:01

ZitatZur Sicherheit könnte ich noch im freezemon eine Abfrage einbauen,

Und da wollte ich Dir gerade vorschlagen $PID beim define des freezemon-devices in einem Internal abzulegen und dann im Betrieb abzugleichen. Aber es macht sicherlich Sinn, entweder in den childs nicht mehr zu loggen oder die pid mitzuloggen.(zumindest als Testversion)

ZitatIO::Socket::INET im non-blocking mode... Da bin ich Netzwerk- und perltechnisch leider nicht wirklich in der Lage zu sagen, was da genau passiert. Aber so wie ich das verstehe läuft es im selben Prozess

Ich les mal.Vielleicht fällt mir was auf...

herrmannj · 15 Januar 2020, 22:58:20

nach code Durchsicht in blocking.pm: sehe ich auch so. Die einzige Möglichkeit hier wäre wenn jemand innerhalb der blocking fn fhem io benutzt. So etwas wie HttpUtils_NonblockingGet. Sonst ist die select loop wo der timer ausgewertet wird eigentlich unerreichbar.

KölnSolar · 15 Januar 2020, 23:28:53

da war wieder einer schneller... u. der weiß es auch noch viel besser...

ZitatAber so wie ich das verstehe läuft es im selben Prozess

yes. auch hier select das Stichwort.

Ist dann aber auch kein freeze. Und ich glaub beim echodevice sieht das dann im freeze-log so "komisch" aus, weil ja eine ganze Latte requests für die Statusermittlung abgesetzt werden.

KölnSolar · 16 Januar 2020, 18:49:46

oder aber es sind doch freezes. Möglicherweise ist die pauschale Aussage mit global dnsServer gäbe es kein blockierendes Verhalten bei nonblocking_get falsch.
Mein dns u. pi-hole läuft auf dem rpi, wo auch fhem läuft. global dnsServer ist auf dessen IP gesetzt.
Nun hatte ich heute morgen relativ viel lokalen Netzverkehr. Und nun bekam ich ne Menge freezes angezeigt

Code Auswählen

2020.01.16 10:46:44.159 4: [echomaster] [echodevice_HandleCmdQueue] [getnotifications] send command=https://layla.amazon.de/api/notifications Data=
2020.01.16 10:46:44.159 5: HttpUtils url=https://layla.amazon.de/api/notifications
2020.01.16 10:46:44.159 4: IP: layla.amazon.de -> 99.86.111.54
.
nun werden 14 weitere nonblocking_gets vom echodevice abgesetzt
.
2020.01.16 10:46:44.558 5: HttpUtils request header:
GET /api/notifications HTTP/1.1    (das ist dann der request nachdem der dns längst die IP aufgelöst hat

ein (ungekürztes) Beispiel, was sicherlich ein echter bedeutender freeze war

Zitat[Freezemon] freezedetect: possible freeze starting at 10:47:45, delay is 1.346 possibly caused by: tmr-echodevice_GetSettings(echomaster) tmr-Nina_Start(myNina) tmr-at_Exec(check_jammer)
2020.01.16 10:47:44.181 5: [echomaster] [echodevice_GetSettings] start refresh settings
2020.01.16 10:47:44.181 4: [echomaster] [echodevice_SendCommand] [getnotifications] START
2020.01.16 10:47:44.183 4: [echomaster] [echodevice_SendCommand] [getnotifications] PushToCmdQueue SendURL =https://layla.amazon.de/api/notifications
2020.01.16 10:47:44.183 4: [echomaster] [echodevice_SendCommand] [getnotifications] PushToCmdQueue SendData=
2020.01.16 10:47:44.185 4: [echomaster] [echodevice_HandleCmdQueue] [getnotifications] send command=https://layla.amazon.de/api/notifications Data=
2020.01.16 10:47:44.185 5: HttpUtils url=https://layla.amazon.de/api/notifications
2020.01.16 10:47:44.187 5: DNS QUERY 707201000001000000000000056c61796c6106616d617a6f6e0264650000010001
2020.01.16 10:47:44.187 4: [echomaster] [echodevice_SendCommand] [alarmvolume] START
2020.01.16 10:47:44.188 4: [echomaster] [echodevice_SendCommand] [alarmvolume] PushToCmdQueue SendURL =https://layla.amazon.de/api/device-notification-state?_=1579168064
2020.01.16 10:47:44.189 4: [echomaster] [echodevice_SendCommand] [alarmvolume] PushToCmdQueue SendData=
2020.01.16 10:47:44.190 4: [echomaster] [echodevice_SendCommand] [bluetoothstate] START
2020.01.16 10:47:44.191 4: [echomaster] [echodevice_SendCommand] [bluetoothstate] PushToCmdQueue SendURL =https://layla.amazon.de/api/bluetooth?cached=true&_=1579168064
2020.01.16 10:47:44.191 4: [echomaster] [echodevice_SendCommand] [bluetoothstate] PushToCmdQueue SendData=
2020.01.16 10:47:44.192 4: [echomaster] [echodevice_SendCommand] [getdnd] START
2020.01.16 10:47:44.193 4: [echomaster] [echodevice_SendCommand] [getdnd] PushToCmdQueue SendURL =https://layla.amazon.de/api/dnd/device-status-list?_=1579168064
2020.01.16 10:47:44.193 4: [echomaster] [echodevice_SendCommand] [getdnd] PushToCmdQueue SendData=
2020.01.16 10:47:44.193 4: [echomaster] [echodevice_SendCommand] [wakeword] START
2020.01.16 10:47:44.194 4: [echomaster] [echodevice_SendCommand] [wakeword] PushToCmdQueue SendURL =https://layla.amazon.de/api/wake-word?_=1579168064
2020.01.16 10:47:44.194 4: [echomaster] [echodevice_SendCommand] [wakeword] PushToCmdQueue SendData=
2020.01.16 10:47:44.195 4: [echomaster] [echodevice_SendCommand] [listitems_task] START
2020.01.16 10:47:44.196 4: [echomaster] [echodevice_SendCommand] [listitems_task] PushToCmdQueue SendURL =https://layla.amazon.de/api/todos?size=100&startTime=&endTime=&completed=false&type=TASK&deviceSerialNumber=&deviceType=&_=1579168064
2020.01.16 10:47:44.196 4: [echomaster] [echodevice_SendCommand] [listitems_task] PushToCmdQueue SendData=TASK
2020.01.16 10:47:44.197 4: [echomaster] [echodevice_SendCommand] [listitems_shopping] START
2020.01.16 10:47:44.198 4: [echomaster] [echodevice_SendCommand] [listitems_shopping] PushToCmdQueue SendURL =https://layla.amazon.de/api/todos?size=100&startTime=&endTime=&completed=false&type=SHOPPING_ITEM&deviceSerialNumber=&deviceType=&_=1579168064
2020.01.16 10:47:44.198 4: [echomaster] [echodevice_SendCommand] [listitems_shopping] PushToCmdQueue SendData=SHOPPING_ITEM
2020.01.16 10:47:44.199 4: [echomaster] [echodevice_SendCommand] [getdevicesettings] START
2020.01.16 10:47:44.200 4: [echomaster] [echodevice_SendCommand] [getdevicesettings] PushToCmdQueue SendURL =https://layla.amazon.de/api/device-preferences
2020.01.16 10:47:44.200 4: [echomaster] [echodevice_SendCommand] [getdevicesettings] PushToCmdQueue SendData=
2020.01.16 10:47:44.201 4: [echomaster] [echodevice_SendCommand] [getisonline] START
2020.01.16 10:47:44.201 4: [echomaster] [echodevice_SendCommand] [getisonline] PushToCmdQueue SendURL =https://layla.amazon.de/api/devices-v2/device?cached=true&_=1579168064
2020.01.16 10:47:44.202 4: [echomaster] [echodevice_SendCommand] [getisonline] PushToCmdQueue SendData=
2020.01.16 10:47:44.202 4: [echomaster] [echodevice_SendCommand] [devicesstate] START
2020.01.16 10:47:44.203 4: [echomaster] [echodevice_SendCommand] [devicesstate] PushToCmdQueue SendURL =https://layla.amazon.de/api/devices-v2/device?cached=true&_=1579168064
2020.01.16 10:47:44.203 4: [echomaster] [echodevice_SendCommand] [devicesstate] PushToCmdQueue SendData=
2020.01.16 10:47:44.204 4: [echomaster] [echodevice_SendCommand] [account] START
2020.01.16 10:47:44.205 4: [echomaster] [echodevice_SendCommand] [account] PushToCmdQueue SendURL =https://alexa-comms-mobile-service.amazon.com/accounts
2020.01.16 10:47:44.205 4: [echomaster] [echodevice_SendCommand] [account] PushToCmdQueue SendData=
2020.01.16 10:47:44.206 4: [echomaster] [echodevice_SendLoginCommand] [cookielogin6]
2020.01.16 10:47:44.207 5: HttpUtils url=https://layla.amazon.de/api/bootstrap
2020.01.16 10:47:44.208 5: DNS QUERY 707201000001000000000000056c61796c6106616d617a6f6e0264650000010001
2020.01.16 10:47:44.209 5: [echomaster] [echodevice_GetSettings] refresh voice command
2020.01.16 10:47:44.209 4: [echomaster] [echodevice_SendCommand] [activities] START
2020.01.16 10:47:44.210 4: [echomaster] [echodevice_SendCommand] [activities] PushToCmdQueue SendURL =https://layla.amazon.de/api/activities?startTime=&size=50&offset=1&_=1579168064
2020.01.16 10:47:44.210 4: [echomaster] [echodevice_SendCommand] [activities] PushToCmdQueue SendData=
2020.01.16 10:47:44.211 4: [echomaster] [echodevice_SendCommand] [getbehavior] START
2020.01.16 10:47:44.212 4: [echomaster] [echodevice_SendCommand] [getbehavior] PushToCmdQueue SendURL =https://layla.amazon.de/api/behaviors/automations?limit=100
2020.01.16 10:47:44.212 4: [echomaster] [echodevice_SendCommand] [getbehavior] PushToCmdQueue SendData=
2020.01.16 10:47:44.213 4: [echomaster] [echodevice_SendCommand] [getsettingstraffic] START
2020.01.16 10:47:44.214 4: [echomaster] [echodevice_SendCommand] [getsettingstraffic] PushToCmdQueue SendURL =https://layla.amazon.de/api/traffic/settings
2020.01.16 10:47:44.214 4: [echomaster] [echodevice_SendCommand] [getsettingstraffic] PushToCmdQueue SendData=
2020.01.16 10:47:44.215 4: [echomaster] [echodevice_GetSettings] Timer INTERVAL = 60
2020.01.16 10:47:44.238 4: BlockingCall (Nina_Run): created child (30526), uses telnetForBlockingFn_1578672571 to connect back
2020.01.16 10:47:44.274 4: Connection accepted from telnetForBlockingFn_1578672571_127.0.0.1_46010
2020.01.16 10:47:44.283 5: Cmd: >{BlockingRegisterTelnet($cl,241845)}<
2020.01.16 10:47:44.344 5: DNS ANSWER 166:707281800001000400000000056c61796c6106616d617a6f6e0264650000010001c00c00050001000000120012056c61796c6106616d617a6f6e03636f6d00c02d000500010000022f0020056c61796c6106616d617a6f6e03636f6d0866726f6e746965720361327ac03ac04b000500010000003c001f0e64337273717570337463786a31610a636c6f756466726f6e74036e657400c077000100010000003c000463566f36
2020.01.16 10:47:44.344 4: DNS result for layla.amazon.de: 99.86.111.54, ttl:60
2020.01.16 10:47:44.345 4: IP: layla.amazon.de -> 99.86.111.54
2020.01.16 10:47:44.357 5: DNS ANSWER 166:707281800001000400000000056c61796c6106616d617a6f6e0264650000010001c00c000500010000029f0012056c61796c6106616d617a6f6e03636f6d00c02d00050001000005a10020056c61796c6106616d617a6f6e03636f6d0866726f6e746965720361327ac03ac04b000500010000003c001f0e64337273717570337463786a31610a636c6f756466726f6e74036e657400c077000100010000003c000463566f36
2020.01.16 10:47:44.358 4: DNS result for layla.amazon.de: 99.86.111.54, ttl:60
2020.01.16 10:47:44.358 4: IP: layla.amazon.de -> 99.86.111.54
--- log skips 1.944 secs.
2020.01.16 10:47:46.302 5: HttpUtils request header:
GET /api/notifications HTTP/1.1
Host: layla.amazon.de
Accept-Encoding: gzip,deflate
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:62.0) Gecko/20100101 Firefox/62.0
Accept-Language: de,en-US;q=0.7,en;q=0.3
DNT: 1
Connection: keep-alive
Upgrade-Insecure-Requests: 1
csrf: -633661467
Content-Type: application/json; charset=UTF-8

2020.01.16 10:47:46.309 5: exec at command check_jammer
2020.01.16 10:47:46.310 5: Cmd: >{if (ReadingsAge('TRXUSB','state',0) > 40 || ReadingsVal('CULFB','state','opened') ne 'Initialized') {Voicecmd('jammer')}}<
2020.01.16 10:47:46.312 5: redefine at command check_jammer as +*00:00:05 {if (ReadingsAge('TRXUSB','state',0) > 40 || ReadingsVal('CULFB','state','opened') ne 'Initialized') {Voicecmd('jammer')}}
2020.01.16 10:47:46.346 5: End notify loop for check_jammer
2020.01.16 10:47:46.347 5: [Freezemon] freezedetect: ----------- Starting Freeze handling at 2020.01.16 10:47:46.347 ---------------------
[Freezemon] freezedetect: possible freeze starting at 10:47:45, delay is 1.346 possibly caused by: tmr-echodevice_GetSettings(echomaster) tmr-Nina_Start(myNina) tmr-at_Exec(check_jammer)

man sieht den freeze von 1,944 sec. Davor die DNS-Auflösung und danach den http-request

ähnliches Bild

Zitat--- log skips 4.410 secs.
2020.01.16 10:47:53.006 5: HttpUtils request header:
GET /api/traffic/settings HTTP/1.1
Host: layla.amazon.de

2020.01.16 10:47:55.533 4: IP: layla.amazon.de -> 99.86.111.54
2020.01.16 10:47:56.468 5: HttpUtils request header:
GET /api/activities?startTime=&size=50&offset=1&_=1579168064 HTTP/1.1
Host: layla.amazon.de

--- log skips 1.199 secs.
2020.01.16 10:48:46.503 5: HttpUtils request header:
GET /api/bootstrap HTTP/1.1

2020.01.16 10:48:49.831 5: TRX_Read END
2020.01.16 10:48:50.730 5: HttpUtils request header:
GET /api/activities?startTime=&size=50&offset=1&_=1579168124 HTTP/1.1
Host: layla.amazon.de

2020.01.16 10:48:51.705 5: HttpUtils url=https://alexa-comms-mobile-service.amazon.com/accounts
2020.01.16 10:48:51.705 4: IP: alexa-comms-mobile-service.amazon.com -> 99.86.117.220
--- log skips 1.796 secs.
2020.01.16 10:48:53.501 5: HttpUtils request header:
GET /accounts HTTP/1.1

2020.01.16 10:49:44.385 5: Cmd: >{BlockingRegisterTelnet($cl,241910)}<
--- log skips 1.047 secs.
2020.01.16 10:49:45.432 5: HttpUtils request header:
GET /api/notifications HTTP/1.1
Host: layla.amazon.de

2020.01.16 10:49:46.138 5: [Freezemon] freezedetect: Blocking Call with PID 30720 ended
--- log skips 2.465 secs.
2020.01.16 10:49:48.603 5: HttpUtils request header:
GET /api/traffic/settings HTTP/1.1
Host: layla.amazon.de

2020.01.16 10:49:51.103 5: [Freezemon] freezedetect: Blocking Call with PID 30732 ended
--- log skips 2.238 secs.
2020.01.16 10:49:53.341 5: HttpUtils request header:
GET /api/behaviors/automations?limit=100 HTTP/1.1
Host: layla.amazon.de

2020.01.16 10:49:55.744 5: GPIO4: GPIO4_PollfinishFn(RPi_OW_TK) End
--- log skips 2.004 secs.
2020.01.16 10:49:57.748 5: HttpUtils request header:
GET /api/device-preferences HTTP/1.1
Host: layla.amazon.de

2020.01.16 10:50:00.542 4: BlockingCall (GPIO4_Poll): created child (30752), uses telnetForBlockingFn_1578672571 to connect back
--- log skips 1.128 secs.
2020.01.16 10:50:01.669 5: HttpUtils request header:
GET /api/todos?size=100&startTime=&endTime=&completed=false&type=SHOPPING_ITEM&deviceSerialNumber=&deviceType=&_=1579168184 HTTP/1.1
Host: layla.amazon.de

2020.01.16 10:50:02.414 5: End notify loop for PVzaehler
--- log skips 1.664 secs.
2020.01.16 10:50:04.079 5: HttpUtils request header:
GET /api/todos?size=100&startTime=&endTime=&completed=false&type=TASK&deviceSerialNumber=&deviceType=&_=1579168184 HTTP/1.1
Host: layla.amazon.de

Nachdem es im lokalen Netzwerk ruhiger war, blieben auch freeze-Meldungen aus.

Ich ziehe da jetzt mal ein paar Schlüsse draus:
1. es sind die dns-Anfragen die zum freeze führen
2. global dnsServer ist nicht das Allheilmittel nonblocking_get wirklich non-blocking zu machen
3. aufgrund der Vielzahl der dns-Anfragen verschlimmert das echodevice-Modul das Problem
Lösung: Aufruf der nonblocking_get mit IP (ich kenne jetzt keine Funktion, aber dürfte ja nicht so schwierig sein, EINMAL die IP zu ermitteln)

Was meint Ihr ?
@Joachim: Könntest Du Dir mit diesem Ansatz das unterschiedliche Verhalten Deiner beiden Systeme erklären ?

MadMax-FHEM · 16 Januar 2020, 19:12:16

Zitat von: KölnSolar am 16 Januar 2020, 18:49:46
Nachdem es im lokalen Netzwerk ruhiger war, blieben auch freeze-Meldungen aus.

Ich ziehe da jetzt mal ein paar Schlüsse draus:
1. es sind die dns-Anfragen die zum freeze führen
2. global dnsServer ist nicht das Allheilmittel nonblocking_get wirklich non-blocking zu machen
3. aufgrund der Vielzahl der dns-Anfragen verschlimmert das echodevice-Modul das Problem
Lösung: Aufruf der nonblocking_get mit IP (ich kenne jetzt keine Funktion, aber dürfte ja nicht so schwierig sein, EINMAL die IP zu ermitteln)

Was meint Ihr ?
@Joachim: Könntest Du Dir mit diesem Ansatz das unterschiedliche Verhalten Deiner beiden Systeme erklären ?

Äh, hmmm.

Nicht so wirklich.
Wahrscheinlich habe ich nur "nix" verstanden

Weil die beiden Systeme sind sehr ähnlich.
Ähnlicher Stand bzgl. OS und ähnlichr Stand bzgl. fhem.

Es ist nat. auf dem Testsystem schon so einiges mal hin- und weginstalliert worden, Testsytem halt...

Auch dnsServer ist auf beiden Systemen gleicht gesetzt.

Allerdings: das Testsystem ist per WLAN angebunden...

Also kurz: was könnte ich tun um da weiter zu helfen!?

Sorry, Joachim

KölnSolar · 16 Januar 2020, 20:52:28

ZitatWahrscheinlich habe ich nur "nix" verstanden

verstehe ich.

Ich versteh ja selber nicht, wo es wirklich hängt. Ich versteh aber auch nicht, was das setzen des dnsServers konkret bedeutet. Ich dachte, da hättest Du vielleicht mehr Hintergründe...Hab jetzt mal im Code geguckt und weiß nun, dass ohne gesetzten dnsServer blockierende Perl-Standardfunktionen aufgerufen werden, ansonsonsten FHEM-Code, der nicht blockieren sollte, es aber wohl doch stellenweise tut.

ZitatAllerdings: das Testsystem ist per WLAN angebunden...

Zumindest ein Anhaltspunkt. Und wenn Du den mal per LAN einbindest ?

ZitatAuch dnsServer ist auf beiden Systemen gleicht gesetzt.

extern oder auch lokal vorgelagert ?

ich versuch mal verständlicher $:-\$ zu beschreiben, was wir wissen und was meine Bsp. zeigen
- echodevice setzt über zehn nonblocking_get je Statuszyklus ab
- wir haben 3 Aktivitäten beim nonblocking_get: IP-Ermittlung, http-request, http-answer
Timelags zw. request u. answer sind unkritisch, weil über select gesteuert
irgendwo bei der IP-Ermittlung oder in der Schnittstelle zum request hakt es. Warum ? Meine Bsp. zeigen, dass nach einem freeze immer
ein request folgt
- nonblocking_get läuft komplett im Hauptprozess ab. Das lässt den Schluss zu, dass es echte freezes sind, die freezemon zeigt.
In der Zeit ist in FHEM nichts passiert, sonst wäre es gelogged. Der Prozess hat auf etwas von außen gewartet.
- mit IP anstatt hostname sollte es wirklich non-blocking sein

Ich les mal weiter httputils.....

MadMax-FHEM · 16 Januar 2020, 21:02:02

Ah ok klarer...
...etwas

Also genau bzgl. dnsServer hast du ja selbst geklärt

Ich habe aktuell (noch) bei beiden meine FB gesetzt, also lokal.

Obwohl die eigentlich NICHT (mehr) mein DNS sein soll(te) weil ich ja piHole laufen habe...

Aber da aktuell nur meine fhem-Server (noch) über die FB direkt "nach außen" gehen ist mir das nicht so wichtig (gewesen umzustellen)...

Hmmm, wobei: also die WLAN-Installation (Testsystem) hat auf OS-Ebene piHole als DNS. In fhem ist die FB gesetzt... (sollte aber egal sein, beides sollte DNS gut machen

)
Kann ich aber auch mal ändern...
...wenn Zeit ist.

Klar auch das mit LAN statt WLAN kann ich mal machen...

Hmmm, wenn man so drüber nachdenkt sind dann doch so ein paar Unterschiede...

Ich werde das mal angehen und berichten...

Gruß, Joachim

KölnSolar · 16 Januar 2020, 21:40:58

Zitat- nonblocking_get läuft komplett im Hauptprozess ab. Das lässt den Schluss zu, dass es echte freezes sind, die freezemon zeigt.
In der Zeit ist in FHEM nichts passiert, sonst wäre es gelogged. Der Prozess hat auf etwas von außen gewartet.

oder
es gab nicht zu tun in FHEM(außer anstehende requests) ? Es hat nur lange gedauert bis der request von "außen"(von was ?) "getriggered" wurde ? Für diese Annahme, kann nur Oli erklären, was überhaupt der Grund war, dass freezemon einen freeze gemeldet hat....