Hi,
als Fortsetzung dieses Threads (https://forum.fhem.de/index.php/topic,116157.msg1146342.html#msg1146342).
Ich habe sporadisch die Fehlermeldung
Strange call for nonexistent : ReadFn
im Log.
M.E. ist der Auslöser HttpUtils_gethostbyname, konkret der non-blocking DNS Call. Bei mir tritt der Fehler nicht regelmäßig auf, aber nachvollziehbar nur wenn dnsServer in global gesetzt ist (egal, ob ich meinen eigenen pihole oder z.B. 8.8.8.8 eintrage). Im Verdacht habe ich das echodevice Modul, kann aber nicht ausschließen, dass es auch bei anderen Modulen auftritt. Soweit ich das beurteilen kann, macht das echodevice einen ganz normalen HttpUtils_NonblockingGet.
Ich habe verbose mal hochgedreht, um mehr Details zu bekommen... seitdem ist die Meldung natürlich noch nicht aufgetreten :-S Werde aber ergänzen, sobald ich mehr habe...
Grüße,
Oli
Typischer Fall von "in %defs unvorsichtig auf etwas zugreifen", z.Bsp. mit $defs{meingeraet}{NAME}, wenn meingeraet schon entfernt ist.
Waere moeglich, dass echodevice aus $defs was entfernt, bevor der gestartete HttpUtils Aufruf fertig ist oder Fehler meldet?
Zitat von: rudolfkoenig am 07 April 2021, 15:25:41
Typischer Fall von "in %defs unvorsichtig auf etwas zugreifen", z.Bsp. mit $defs{meingeraet}{NAME}, wenn meingeraet schon entfernt ist.
Waere moeglich, dass echodevice aus $defs was entfernt, bevor der gestartete HttpUtils Aufruf fertig ist oder Fehler meldet?
Schau ich mir heute abend nochmal an. Was mich irritiert ist, dass der Fehler tatsächlich nur auftritt, wenn dnsServer in global gesetzt ist. Ich hatte mir das vor längerer Zeit schonmal angesehen und hatte den Eindruck, (kann mich nicht mehr ganz an de Details erinnern) dass ein DNS Call abgesetzt wird und bevor dieser zurück kommt ein weiterer abgesetzt wird. Wenn der erste Call dann zurück kommt findet er sein Device nicht mehr, oder so ähnlich...
Hi Oli,
ich kann nur wenig beitragen. Habe aber die vergleichbare Beobachtung: ab u. zu dieselbe Meldung im Log, echodevice im Einsatz u. globl dnsserver gesetzt.
Ich beobachte mal, ob das mit der täglichen Trennung des Routers zusammenhängt, denn ich meine, ich hätte den Fehler nur nachts beobachtet. ???
Grüße Markus
So, ich habe mal so einen Kollegen "eingefangen":
2021.04.08 00:28:04.096 4: [ECHO_G070L81491352GG7] [echodevice_SendCommand] [media] START
2021.04.08 00:28:04.096 4: [ECHO_G070L81491352GG7] [echodevice_SendCommand] [media] PushToCmdQueue SendURL =https://layla.amazon.de/api/media/state?deviceSerialNumber=SERIAL&deviceType=A2LWARUGJLBYEW&screenWidth=1392&_=1617834484
2021.04.08 00:28:04.096 4: [ECHO_G070L81491352GG7] [echodevice_SendCommand] [media] PushToCmdQueue SendData=
2021.04.08 00:28:04.097 4: [ECHO_G070L81491352GG7] [echodevice_HandleCmdQueue] RUNNING_REQUEST=1 type=player
2021.04.08 00:28:04.098 4: [ECHO_G070L81491352GG7] [echodevice_GetSettings] Timer INTERVAL = 3660
2021.04.08 00:28:04.123 5: HttpUtils url=https://layla.amazon.de/api/np/player?deviceSerialNumber=XXX&deviceType=A2LWARUGJLBYEW&screenWidth=1392&_=1617834484
2021.04.08 00:28:04.126 5: DNS QUERY 707201000001000000000000056c61796c6106616d617a6f6e0264650000010001
2021.04.08 00:28:04.127 4: [ECHO_G070L81491352GG7] [echodevice_Parse] [player] [2504]
2021.04.08 00:28:04.128 5: [ECHO_G070L81491352GG7] [echodevice_Parse] [player] [2504] DATA Dumper=$VAR1 = undef;
2021.04.08 00:28:04.129 4: [ECHO_G070L81491352GG7] [echodevice_HandleCmdQueue] [media] [2506] [0] send command=https://layla.amazon.de/api/media/state?deviceSerialNumber=SERIAL&deviceType=A2LWARUGJLBYEW&screenWidth=1392&_=1617834484 Data=
2021.04.08 00:28:04.129 5: HttpUtils url=https://layla.amazon.de/api/media/state?deviceSerialNumber=XXX&deviceType=A2LWARUGJLBYEW&screenWidth=1392&_=1617834484
2021.04.08 00:28:04.131 5: DNS QUERY 707201000001000000000000056c61796c6106616d617a6f6e0264650000010001
2021.04.08 00:28:04.146 5: DNS ANSWER 292:707281800001000400040000056c61796c6106616d617a6f6e0264650000010001c00c000500010000022c0012056c61796c6106616d617a6f6e03636f6d00c02d000500010000057f0018027470123739396334333333372d66726f6e74696572c033c04b0005000100000013001f0e64337273717570337463786a31610a636c6f756466726f6e74036e657400c06f000100010000001300040de1203bc06f0002000100028ffe0017076e732d3132303709617773646e732d3232036f726700c06f0002000100028ffe0019076e732d3138343909617773646e732d333902636f02756b00c06f0002000100028ffe0013066e732d32373909617773646e732d3334c03ac06f0002000100028ffe0013066e732d39313609617773646e732d3530c089
2021.04.08 00:28:04.146 4: DNS result for layla.amazon.de: 13.225.32.59, ttl:19
2021.04.08 00:28:04.146 4: IP: layla.amazon.de -> 13.225.32.59
2021.04.08 00:28:04.149 5: DNS ANSWER 292:707281800001000400040000056c61796c6106616d617a6f6e0264650000010001c00c000500010000022c0012056c61796c6106616d617a6f6e03636f6d00c02d000500010000057f0018027470123739396334333333372d66726f6e74696572c033c04b0005000100000013001f0e64337273717570337463786a31610a636c6f756466726f6e74036e657400c06f000100010000001300040de1203bc06f0002000100028ffe0017076e732d3132303709617773646e732d3232036f726700c06f0002000100028ffe0019076e732d3138343909617773646e732d333902636f02756b00c06f0002000100028ffe0013066e732d32373909617773646e732d3334c03ac06f0002000100028ffe0013066e732d39313609617773646e732d3530c089
2021.04.08 00:28:04.149 4: DNS result for layla.amazon.de: 13.225.32.59, ttl:19
2021.04.08 00:28:04.149 4: IP: layla.amazon.de -> 13.225.32.59
2021.04.08 00:28:04.149 0: Strange call for nonexistent : ReadFn
Meine laienhafte Interpretation (die völlig danaeben sein kann): Echodevice schickt unmittelbar hintereinander zwei Requests an die selbe Adresse, in ebenso kurzer Folge werden die DNS Queries abgesetzt (weil nichtmehr im Cache). DNS1 kommt zurück und "findet" das Device, DNS2 kommt zurück und das Device ist nicht mehr da, weil DNS1 es schon "konsumiert" hat.
Wenn ich mehr debug-Info bereitstellen kann, lasst mich wissen was/wie... Aktuell habe ich in der CallFn ein Perl-Sleep eingebaut, um einen freeze zu erzwingen (über den ich dann das verbose 5-Log bekomme, ohne global auf verbose 5 zu stellen ;-))
Grüße,
Oli,
Deine Analyse ist vmtl. richtig, der Verursacher ist Echodevice, der sollte nicht mit dem gleichen hash parallel mehrere NonblockingGets starten.
Ich habe HttpUtils.pm erweitert, damit man solche Parallel-Laeufer genauer identifizieren kann, mit Fehlermeldung und zusaetzlichen stacktrace im Log. Bin nicht sicher, ob das ganz ohne Nebeneffekte klappt, aber das werden wir sehen.
Dann lade ich das morgen auch mal.
Ich hab dann mein Log durchforstet:
2021.04.07 03:16:14 0: Strange call for nonexistent : ReadFn
2021.04.07 03:16:14 1: stacktrace:
2021.04.07 03:16:14 1: main::CallFn called by fhem.pl (773)
2021.04.07 04:42:18 0: Strange call for nonexistent : ReadFn
2021.04.07 04:42:18 1: stacktrace:
2021.04.07 04:42:18 1: main::CallFn called by fhem.pl (773)
2021.04.07 04:51:18 0: Strange call for nonexistent : ReadFn
2021.04.07 04:51:18 1: stacktrace:
2021.04.07 04:51:18 1: main::CallFn called by fhem.pl (773)
2021.04.07 06:20:20 0: Strange call for nonexistent : ReadFn
2021.04.07 06:20:20 1: stacktrace:
2021.04.07 06:20:20 1: main::CallFn called by fhem.pl (773)
2021.04.08 03:14:13 0: Strange call for nonexistent : ReadFn
2021.04.08 03:14:13 1: stacktrace:
2021.04.08 03:14:13 1: main::CallFn called by fhem.pl (773)
Wie gesagt, nur nachts, aber eben nicht nur, wenn der Router kurz die Verbindung zum Provider kappt. Nächster Gedanke: nachts hat der echo keine Verbindung ins Inet, weil ich das WLAN abschalte.
Das wäre dann aber etwas anderes, denn den DNS erreicht der echo in meinem Fall ja gar nicht. ???
Grüße Markus
Das unmittelbare Problem scheint zu sein, dass echodevice HttpUtils_NonblockingGet schon wieder aufruft, obwohl der vorherige Aufruf mit dem gleichen $hash noch nicht fertig ist. Womoeglich wird das wiederum ausgeloest, wenn Internet nicht zur Verfuegung steht.
Es ist theoretisch auch moeglich, dass HttpUtils_NonblockingGet den callback aufruft, und danach trotzdem munter weitermacht, aber das haette ich gerne nachgewiesen, bevor ich anfange zu suchen.
Ich kann mit ziemlicher Sicherheit ausschließen, dass es an der Internetverfügbarkeit liegt.
Morgen,
bei mir sieht das nun alle 10' so aus:
Zitat2021.04.09 00:46:05 1: ERROR: Another HttpUtils_NonblockingGet with the same hash is in progress
2021.04.09 00:46:05 1: stacktrace:
2021.04.09 00:46:05 1: main::HttpUtils_NonblockingGet called by FHEM/HttpUtils.pm (889)
2021.04.09 00:46:05 1: main::HttpUtils_ParseAnswer called by FHEM/HttpUtils.pm (642)
2021.04.09 00:46:05 1: main::__ANON__ called by fhem.pl (770)
2021.04.09 00:46:05 1: ERROR: Another HttpUtils_NonblockingGet with the same hash is in progress
2021.04.09 00:46:05 1: stacktrace:
2021.04.09 00:46:05 1: main::HttpUtils_NonblockingGet called by FHEM/HttpUtils.pm (889)
2021.04.09 00:46:05 1: main::HttpUtils_ParseAnswer called by FHEM/HttpUtils.pm (642)
2021.04.09 00:46:05 1: main::__ANON__ called by fhem.pl (770)
Außer der Rythmik sehe ich nichts verwertbares.
Grüße Markus
Ich habe das echodevice Modul erstellt, daher lese ich jetzt mal mit.
Kann mir aber gerade nicht vorstellen wo hier ein Fehler sein soll. Alle HTTP Anfragen werden erst in eine Queue geschrieben, und dann nacheinander abgearbeitet. Eine Parallele Anfrage findet daher nicht statt.
Frage, kann es was damit zu tun haben das man zwei ACCOUNT-Devices (verschiedene Accounts) nutzt ?
Musste letzte Woche bei meinem Account ein NPM_Login new machen und gestern Abend festgestellt dass das bei dem anderen Account (der gar nicht mehr genutzt wird) auch nötig gewesen wäre. Da ich aber gestern Abend keinen Zugriff hatte zum verfizieren des zweiten Account hab ich diese Definition einfach gelöscht (weil disable ja nicht ausreicht) und seitdem (bis jetzt) kam auch nicht mehr die Meldung.
Interessant, kommt bei mir von einem JsonMod-Device, glaube ich zumindest. Fehlermeldung:
2021.04.09 15:14:03 1: ERROR: Another HttpUtils_NonblockingGet with the same hash is in progress
2021.04.09 15:14:03 1: stacktrace:
2021.04.09 15:14:03 1: main::HttpUtils_NonblockingGet called by FHEM/HttpUtils.pm (889)
2021.04.09 15:14:03 1: main::HttpUtils_ParseAnswer called by FHEM/HttpUtils.pm (642)
2021.04.09 15:14:03 1: main::__ANON__ called by fhem.pl (770)
2021.04.09 15:14:03 2: [dnscrypt_proxy_version] http request error: Another HttpUtils_NonblockingGet with the same hash is in progress
Der Block wiederholt sich alle 10 Minuten. Eigentlich hätte das JsonMod Device um 14:04 triggern sollen. Device list:
Internals:
API_LAST_RES 1617978244.62315
API__LAST_MSG Another HttpUtils_NonblockingGet with the same hash is in progress
DEF https://api.github.com/repos/jedisct1/dnscrypt-proxy/releases/latest
FUUID 5eb28e58-f33f-3151-34eb-5666909e42d89e38
NAME dnscrypt_proxy_version
NEXT 2021-04-10 14:04:00
NR 330
SOURCE https://api.github.com/repositories/116739828/releases/latest (301)
STATE <div style="text-align: left;">last <a href="https://github.com/DNSCrypt/dnscrypt-proxy" title="dnscrypt-proxy" rel="noopener noreferrer" target="_blank">dnscrypt-proxy</a> version check => 2021-04-08 14:04:00<br />Online: <a href="https://github.com/DNSCrypt/dnscrypt-proxy/blob/master/ChangeLog" title="ChangeLog" rel="noopener noreferrer" target="_blank" style="color:limegreen;">2.0.45</a> (03.01.21)<br />dnscrypt-proxy: 2.0.45</div>
SVN 22987 2020-10-18 13:26:05 UTC
TYPE JsonMod
CONFIG:
IN_REQUEST 0
SOURCE https://api.github.com/repos/jedisct1/dnscrypt-proxy/releases/latest
SECRET:
READINGS:
2021-04-08 14:04:00 .computedReadings published_at,git_version
2021-04-08 14:04:00 git_version 2.0.45
2021-04-08 14:04:00 published_at 2021-01-03T17:38:20Z
Attributes:
interval 4 14 * * *
readingList single(jsonPath('$.tag_name'), 'git_version', 'none');
single(jsonPath('$.published_at'), 'published_at', 'none');
Andere JsonMod-Devices verursachen keine (derartigen) Log-Einträge.
Zitat von: rudolfkoenig am 08 April 2021, 12:29:46
... der sollte nicht mit dem gleichen hash parallel mehrere NonblockingGets starten.
Ich habe HttpUtils.pm erweitert, damit man solche Parallel-Laeufer genauer identifizieren kann, mit Fehlermeldung und zusaetzlichen stacktrace im Log. Bin nicht sicher, ob das ganz ohne Nebeneffekte klappt, aber das werden wir sehen.
Die Aussage zu "hash" ist missverständlich. Ich vermute dass sich "hash" auf $param bezieht? -> HttpUtils_NonblockingGet($param)
Wenn dem so ist dann liegt die Ursache sowieso woanders denn zumindest für JsonMod kann ich die einzigartigkeit des $param hash bestätigen. Im Fall von JsonMod wird $param als jeweils exklusiver hash mit my erzeugt (line #583).
Da würde ich den Fehler wohl eher in der DNS Implementierung von Http_Utils vermuten
Zitat von: herrmannj am 09 April 2021, 16:54:34Zitat von: rudolfkoenig am 08 April 2021, 12:29:46der sollte nicht mit dem gleichen hash parallel mehrere NonblockingGets starten.
Ich habe HttpUtils.pm erweitert, damit man solche Parallel-Laeufer genauer identifizieren kann, mit Fehlermeldung und zusaetzlichen stacktrace im Log. Bin nicht sicher, ob das ganz ohne Nebeneffekte klappt, aber das werden wir sehen.
Das habe ich gelesen - ich nutze aber weder aktiv noch bewusst ein Echodevice - und die Fehlermeldung ist jetzt neu für mich. Insbesondere im Zusammenhang mit einem JsonMod-Device. Ich wüsste auch auf Anhieb nicht, wie ich die Herkunft der hash-dublette ermitteln soll...
sorry, ich hatte den Beitrag zu früh gesendet, da fehlte die Erklärung dazu welche jetzt oben steht.
https://forum.fhem.de/index.php/topic,120244.msg1147338/topicseen.html#msg1147338 (https://forum.fhem.de/index.php/topic,120244.msg1147338/topicseen.html#msg1147338)
Bei mir löst das Calendar-Modul diesen Fehler reproduzierbar aus.
2021.04.09 17:18:43 4: Calendar avea: Updating...
2021.04.09 17:18:43 5: SSL verify mode set to 0
2021.04.09 17:18:43 4: Calendar avea: Getting data from URL <hidden>
2021.04.09 17:18:43 1: ERROR: Another HttpUtils_NonblockingGet with the same hash is in progress
2021.04.09 17:18:43 1: stacktrace:
2021.04.09 17:18:43 1: main::HttpUtils_NonblockingGet called by /opt/fhem/FHEM/HttpUtils.pm (865)
2021.04.09 17:18:43 1: main::HttpUtils_ParseAnswer called by /opt/fhem/FHEM/HttpUtils.pm (642)
2021.04.09 17:18:43 1: main::__ANON__ called by fhem.pl (770)
2021.04.09 17:18:43 1: Calendar avea: retrieval failed with error message Another HttpUtils_NonblockingGet with the same hash is in progress
2021.04.09 17:18:43 1: Calendar avea: retrieved no or empty data
2021.04.09 17:18:43 4: Calendar avea: Checking times...
Gleicher Fall bei mir im Kalender:
2021.04.09 17:48:34 1: ERROR: Another HttpUtils_NonblockingGet with the same hash is in progress
2021.04.09 17:48:34 1: stacktrace:
2021.04.09 17:48:34 1: main::HttpUtils_NonblockingGet called by FHEM/HttpUtils.pm (889)
2021.04.09 17:48:34 1: main::HttpUtils_ParseAnswer called by FHEM/HttpUtils.pm (642)
2021.04.09 17:48:34 1: main::__ANON__ called by fhem.pl (770)
2021.04.09 17:48:34 1: Calendar cal.Akku: retrieval failed with error message Another HttpUtils_NonblockingGet with the same hash is in progress
2021.04.09 17:48:34 1: Calendar cal.Akku: retrieved no or empty data
2021.04.09 17:48:37 1: ERROR: Another HttpUtils_NonblockingGet with the same hash is in progress
Nach Rückschritt auf eine ältere Version:
$Id: HttpUtils.pm 23979 2021-03-15 14:00:33Z rudolfkoenig $
funktioniert es wieder...
Ich schließe mich dem ganzen an:
ERROR: Another HttpUtils_NonblockingGet with the same hash is in progress
2021.04.10 00:40:28 1: stacktrace:
2021.04.10 00:40:28 1: main::HttpUtils_NonblockingGet called by ./FHEM/98_freezemon.pm (1310)
2021.04.10 00:40:28 1: main::freezemon_http called by ./FHEM/98_freezemon.pm (1357)
2021.04.10 00:40:28 1: main::__ANON__ called by FHEM/HttpUtils.pm (889)
2021.04.10 00:40:28 1: main::HttpUtils_ParseAnswer called by FHEM/HttpUtils.pm (642)
2021.04.10 00:40:28 1: main::__ANON__ called by fhem.pl (770)
2021.04.10 00:40:28 1: Calendar DP_Chrissi: retrieval failed with error message Another HttpUtils_NonblockingGet with the same hash is in progress
2021.04.10 00:40:28 1: Calendar DP_Chrissi: retrieved no or empty data
2021.04.10 00:40:28 1: ERROR: Another HttpUtils_NonblockingGet with the same hash is in progress
2021.04.10 00:40:28 1: stacktrace:
2021.04.10 00:40:28 1: main::HttpUtils_NonblockingGet called by ./FHEM/98_freezemon.pm (1310)
2021.04.10 00:40:28 1: main::freezemon_http called by ./FHEM/98_freezemon.pm (1357)
2021.04.10 00:40:28 1: main::__ANON__ called by FHEM/HttpUtils.pm (889)
2021.04.10 00:40:28 1: main::HttpUtils_ParseAnswer called by FHEM/HttpUtils.pm (642)
2021.04.10 00:40:28 1: main::__ANON__ called by fhem.pl (770)
2021.04.10 00:40:28 1: Calendar DP_Andy: retrieval failed with error message Another HttpUtils_NonblockingGet with the same hash is in progress
2021.04.10 00:40:28 1: Calendar DP_Andy: retrieved no or empty data
Zitat von: netwalk am 09 April 2021, 18:11:50
Gleicher Fall bei mir im Kalender:
2021.04.09 17:48:34 1: ERROR: Another HttpUtils_NonblockingGet with the same hash is in progress
2021.04.09 17:48:34 1: stacktrace:
2021.04.09 17:48:34 1: main::HttpUtils_NonblockingGet called by FHEM/HttpUtils.pm (889)
2021.04.09 17:48:34 1: main::HttpUtils_ParseAnswer called by FHEM/HttpUtils.pm (642)
2021.04.09 17:48:34 1: main::__ANON__ called by fhem.pl (770)
2021.04.09 17:48:34 1: Calendar cal.Akku: retrieval failed with error message Another HttpUtils_NonblockingGet with the same hash is in progress
2021.04.09 17:48:34 1: Calendar cal.Akku: retrieved no or empty data
2021.04.09 17:48:37 1: ERROR: Another HttpUtils_NonblockingGet with the same hash is in progress
Nach Rückschritt auf eine ältere Version:
$Id: HttpUtils.pm 23979 2021-03-15 14:00:33Z rudolfkoenig $
funktioniert es wieder...
Bitte beachten, es ist keine Funktionseinschränkung. Die Aussage mit der alten Version funktioniert es wieder ist nicht korrekt.. Es funktioniert auch mit der neuen.
Denn es wurde lediglich eine erweiterte Ausgabe eingefügt. Siehe Rudis Kommentar.
Zitat von: rudolfkoenig am 08 April 2021, 12:29:46
Deine Analyse ist vmtl. richtig, der Verursacher ist Echodevice, der sollte nicht mit dem gleichen hash parallel mehrere NonblockingGets starten.
Ich habe HttpUtils.pm erweitert, damit man solche Parallel-Laeufer genauer identifizieren kann, mit Fehlermeldung und zusaetzlichen stacktrace im Log. Bin nicht sicher, ob das ganz ohne Nebeneffekte klappt, aber das werden wir sehen.
Zitat von: CoolTux am 10 April 2021, 10:43:36
Es funktioniert auch mit der neuen.
Sicher? Meine Calview Devices zeigen zumindest aktuell keine Termine mehr an. Ich kann jetzt leider nicht ausschließen dass es auch vor dem Update von HttpUtils.pm schon so war, aber da ich darüber die Heizung im Haus steuere denke ich mal dass es schon irgendwann aufgefallen wäre...
Zitat von: Supadone am 10 April 2021, 11:14:04
Sicher? Meine Calview Devices zeigen zumindest aktuell keine Termine mehr an.
Ich kann zwar nix sinnvolles beisteuern, aber meine Kalender haben mit der neuen HttpUtils auch keine Termine mehr angezeigt.
Dann habe ich die Aussage von Rudi falsch verstanden, sorry.
Ich habe mir eben nur kurz den Patch angeschaut, anscheinend wird das ganze als Error ausgegeben. Klingt also nach Abbruch.
Im Log meines des Calendar-Devices:
Calendar avea: retrieved no or empty data
Es funktioniert wirklich nicht und sieht nach Abbruch aus!
Ich stelle fest:
- die eingebaute Fehlermeldung hilft nicht bei der Ursachensuche.
- durch den Abbruch beim vermeintlichen Fehler beim Aufruf gibt es Probleme. Ob sie in HttpUtils oder im aufrufenden Modul zu suchen sind, ist mir noch unklar.
Ich habe in der Duplikats-Erkennung die Fehlermeldung geaendert, und statt Abbruch wird nur auf verbose 4 eine Meldung im Log ausgegeben, um bei der Ursachensuche zu helfen.
Da ich Calender nicht verwende, aber das Problem damit reproduzierbar ist: kann mir jemand eine Anleitung geben, um es ohne viel Installation oder Google/etc Anmeldung nachzustellen?
z.B. so:
define cal_tmp calendar ical url https://www.google.com/calendar/ical/i4aeldvbflqu7u6jpn8uvv9738@group.calendar.google.com/public/basic.ics
Hallo Rudi,
2021.04.11 08:46:28.335 1: ERROR: Another HttpUtils_NonblockingGet with the same hash is in progress
2021.04.11 08:46:28.335 1: stacktrace:
2021.04.11 08:46:28.335 1: main::HttpUtils_NonblockingGet called by FHEM/HttpUtils.pm (889)
2021.04.11 08:46:28.336 1: main::HttpUtils_ParseAnswer called by FHEM/HttpUtils.pm (642)
2021.04.11 08:46:28.336 1: main::__ANON__ called by fhem.pl (770)
2021.04.11 08:46:28.336 1: Radiation: URL error for ODL: Another HttpUtils_NonblockingGet with the same hash is in progress
Das Modul bfs (terrestrische und Höhenstrahlung, bei mir heißt das Device "Radiation") hat anscheinend das gleiche Problem.
Viele Grüße Gisbert
Das ist offensichtlich mit dem veralteten HttpUtils von vorgestern erzeugt.
Bitte FHEM aktualisieren, siehe auch Antwort #24.
define cal_tmp calendar ical url https://www.google.com/calendar/ical/i4aeldvbflqu7u6jpn8uvv9738@group.calendar.google.com/public/basic.ics
Danke!
Ich habe das redirect uebersehen, das ruft die Funktion mit dem gleichen hash und geaenderten URL neu auf.
Das habe ich jetzt gefixt. Wenn man das redirect sparen will, dann ersetzt man www durch calendar
Gehe ich Recht in der Annahme dass innerhalb der Module, konkret jsonmod, nichts verändert werden muss?
Nur wenn Du HttpUtils_NonblockingGet mehrmals mit dem gleichen Hash aufrufst, bevor die Anderen fertig sind.
In diesem Fall gibt HttpUtils eine Warnung auf global verbose 4 aus.
Mit der aktuellen HttpUtils funktioniert der icloud-Kalender wieder. Der Log-Eintrag auf verbose=4 sieht folgendermaßen aus:
2021.04.11 15:48:19 4: Calendar cal.Akku: Updating...
2021.04.11 15:48:19 4: Calendar cal.Akku: Getting data from URL <hidden>
2021.04.11 15:48:20 4: Calendar cal.Akku: parsing data asynchronously (PID= 29356)
2021.04.11 15:48:21 4: Calendar cal.Akku: got result from asynchronous parsing.
2021.04.11 15:48:21 4: Calendar cal.Akku: asynchronous parsing finished.
2021.04.11 15:48:21 4: Calendar cal.Akku: merging data
2021.04.11 15:48:21 4: Calendar cal.Akku: 14 records processed, 14 new, 0 known, 0 modified, 0 changed.
2021.04.11 15:48:21 4: Calendar cal.Akku: creating calendar events
2021.04.11 15:48:21 4: Calendar cal.Akku: events for 0 records cleared, events for 14 records created.
2021.04.11 15:48:21 4: Calendar cal.Akku: Checking times...
2021.04.11 15:48:21 4: Calendar cal.Akku: process ended.
Bei mir lag es tatsächlich auch am Redirect. Mein Exchange-Hoster hat vermutlich mal den Server umgezogen.
Ob die abgefragte Kalender URL einen Redirect macht kann man z.B. hier (https://httpstatus.io/) prüfen.
Die abgefragte URL sollte keinen 302 Status vor dem 200 haben.
Dann sollte sogar die HttpUtils vom 8.4.2021 beim Kalendermodul keinen Abbruch erzeugen.
Hallo Rudi,
ich habe es endlich mal geschafft, mein FHEM upzudaten und einen "Strange Call" eizufangen. Zusätzlich dumpe ich noch den zugehörigen $hash (unnötigen Kram wie meine Einkaufsliste habe ich mal grob gelöscht):
Keine Ahnung ob das hilft...
Grüße,
Oli
2021.04.15 00:04:39.183 4: [ECHO_7094180751761LVH] [echodevice_SendCommand] [media] START
2021.04.15 00:04:39.183 4: [ECHO_7094180751761LVH] [echodevice_SendCommand] [media] PushToCmdQueue SendURL =https://layla.amazon.de/api/media/state?deviceSerialNumber=SERIAL&deviceType=ADVBD696BHNV5&screenWidth=1392&_=1618437879
2021.04.15 00:04:39.183 4: [ECHO_7094180751761LVH] [echodevice_SendCommand] [media] PushToCmdQueue SendData=
2021.04.15 00:04:39.183 4: [ECHO_7094180751761LVH] [echodevice_HandleCmdQueue] RUNNING_REQUEST=1 type=player
2021.04.15 00:04:39.183 4: [ECHO_7094180751761LVH] [echodevice_GetSettings] Timer INTERVAL = 3550
2021.04.15 00:04:39.188 5: HttpUtils url=https://layla.amazon.de/api/np/player?deviceSerialNumber=7094180751761LVH&deviceType=ADVBD696BHNV5&screenWidth=1392&_=1618437879
2021.04.15 00:04:39.189 5: DNS QUERY 707201000001000000000000056c61796c6106616d617a6f6e0264650000010001
2021.04.15 00:04:39.189 4: [ECHO_7094180751761LVH] [echodevice_Parse] [player] [724]
2021.04.15 00:04:39.190 5: [ECHO_7094180751761LVH] [echodevice_Parse] [player] [724] DATA Dumper=$VAR1 = undef;
2021.04.15 00:04:39.190 4: [ECHO_7094180751761LVH] [echodevice_HandleCmdQueue] [media] [726] [0] send command=https://layla.amazon.de/api/media/state?deviceSerialNumber=SERIAL&deviceType=ADVBD696BHNV5&screenWidth=1392&_=1618437879 Data=
2021.04.15 00:04:39.190 5: HttpUtils url=https://layla.amazon.de/api/media/state?deviceSerialNumber=7094180751761LVH&deviceType=ADVBD696BHNV5&screenWidth=1392&_=1618437879
2021.04.15 00:04:39.191 5: DNS QUERY 707201000001000000000000056c61796c6106616d617a6f6e0264650000010001
2021.04.15 00:04:39.208 5: DNS ANSWER 292:707281800001000400040000056c61796c6106616d617a6f6e0264650000010001c00c00050001000003830012056c61796c6106616d617a6f6e03636f6d00c02d00050001000002ad0018027470123739396334333333372d66726f6e74696572c033c04b0005000100000037001f0e64337273717570337463786a31610a636c6f756466726f6e74036e657400c06f000100010000000700046354522cc06f0002000100029aee0017076e732d3132303709617773646e732d3232036f726700c06f0002000100029aee0019076e732d3138343909617773646e732d333902636f02756b00c06f0002000100029aee0013066e732d32373909617773646e732d3334c03ac06f0002000100029aee0013066e732d39313609617773646e732d3530c089
2021.04.15 00:04:39.208 4: DNS result for layla.amazon.de: 99.84.82.44, ttl:7
2021.04.15 00:04:39.208 4: IP: layla.amazon.de -> 99.84.82.44
2021.04.15 00:04:39.210 5: DNS ANSWER 292:707281800001000400040000056c61796c6106616d617a6f6e0264650000010001c00c00050001000003830012056c61796c6106616d617a6f6e03636f6d00c02d00050001000002ad0018027470123739396334333333372d66726f6e74696572c033c04b0005000100000037001f0e64337273717570337463786a31610a636c6f756466726f6e74036e657400c06f000100010000000700046354522cc06f0002000100029aee0017076e732d3132303709617773646e732d3232036f726700c06f0002000100029aee0019076e732d3138343909617773646e732d333902636f02756b00c06f0002000100029aee0013066e732d32373909617773646e732d3334c03ac06f0002000100029aee0013066e732d39313609617773646e732d3530c089
2021.04.15 00:04:39.210 4: DNS result for layla.amazon.de: 99.84.82.44, ttl:7
2021.04.15 00:04:39.210 4: IP: layla.amazon.de -> 99.84.82.44
2021.04.15 00:04:39.216 0: Strange call for nonexistent : ReadFn$VAR1 = {
'displayurl' => 'https://layla.amazon.de/api/media/state?deviceSerialNumber=7094180751761LVH&deviceType=ADVBD696BHNV5&screenWidth=1392&_=1618437879',
'hu_inProgress' => ' freezemon_http:1355 __ANON__:2225 echodevice_HandleCmdQueue:2442 echodevice_Parse:645 __ANON__:770',
'type' => 'media',
'callback' => sub { "DUMMY" },
'conn' => bless( \*Symbol::GEN7041, 'IO::Socket::INET' ),
'httpversion' => '1.1',
'fm_originalCallback' => $VAR1->{'callback'},
'buf' => '',
'loglevel' => 4,
'host' => 'layla.amazon.de',
'CL' => undef,
'hu_port' => 443,
'hu_blocking' => 0,
'protocol' => 'https',
'path' => '/api/media/state?deviceSerialNumber=7094180751761LVH&deviceType=ADVBD696BHNV5&screenWidth=1392&_=1618437879',
'compress' => 1,
'code' => '400',
'keepalive' => 1,
'queuenumber' => 726,
'hu_portSfx' => '',
'url' => 'https://layla.amazon.de/api/media/state?deviceSerialNumber=7094180751761LVH&deviceType=ADVBD696BHNV5&screenWidth=1392&_=1618437879',
'redirects' => 0,
'header' => '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
Cookie:session-id=261-5426251-4039420; session-id-time=2249153244l; ubid-acbde=259-6157451-9340154; x-acbde=vu6k8AkLwQWqvBQSjy3BL@fFALSyfsB6; at-acbde=Atza|IwEBIHJmjpR7eR-
csrf: 1610943944
Content-Type: application/json; charset=UTF-8',
'method' => 'GET',
'FD' => 35,
'NAME' => '',
'sslargs' => {},
'data' => '',
'noshutdown' => 1,
'addr' => 'https://layla.amazon.de:443',
'hash' => {
'.attreocr' => [
'.*'
],
'.attrminint' => [],
'NAME' => 'ECHO_7094180751761LVH',
'.FhemMetaInternals' => 1,
'NR' => 739,
'FVERSION' => '37_echodevice.pm:v5.0.0-s23714/2021-02-10',
'OLDREADINGS' => {},
'READINGS' => {
'model' => 'Fire TV Stick V1',
'.attraggr' => [],
'LOGINMODE' => 'IODEV',
'FUUID' => '5fbcf620-f33f-5926-896a-14b3a03771355a33',
'IODev' => {
'model' => 'ACCOUNT',
'.attraggr' => [],
'LOGINMODE' => 'NPM',
'READINGS' => {
'STATE' => 'connected',
'DEF' => 'xxx@xxx.xx xxx',
'TYPE' => 'echodevice',
'NTFY_ORDER' => '50-echo',
'FUUID' => '5c43b210-f33f-deda-0626-77f013ea56ee5324',
'IODev' => {
'helper' => {}
},
'.HTTP_CONNECTION' => {
'httpversion' => '1.1',
'conn' => bless( \*Symbol::GEN1045, 'IO::Socket::SSL' ),
'type' => 'activities',
'callback' => $VAR1->{'callback'},
'displayurl' => 'https://layla.amazon.de/api/activities?startTime=&size=10&offset=1&_=1618437830',
'protocol' => 'https',
'hu_sslAdded' => 1,
'httpheader' => 'HTTP/1.1 200 OK
Content-Type: application/json
Content-Length: 1429
Connection: keep-alive
Server: Server
Date: Wed, 14 Apr 2021 22:03:51 GMT
x-amz-rid: WMKW6G2REVCQNKNVEMN5
x-amzn-RequestId: 6c410261-c1ed-46cd-aa46-5c1ae9ed9071
Content-Encoding: gzip
Vary: Content-Type,Accept-Encoding,X-Amzn-CDN-Cache,X-Amzn-AX-Treatment,User-Agent
X-Cache: Miss from cloudfront
Via: 1.1 9463f100725b8b17da2d778617835761.cloudfront.net (CloudFront)
X-Amz-Cf-Pop: AMS50-C1
X-Amz-Cf-Id: 5wuxzeQYv2kRz-CzqIpcz1Uj43xG2uDO6RT0NOR4h-7Jm8fm-5hhXw==',
'host' => 'layla.amazon.de',
'loglevel' => 4,
'hu_port' => 443,
'hu_blocking' => 0,
'CL' => undef,
'fm_originalCallback' => $VAR1->{'callback'},
'buf' => '',
'NAME' => '',
'method' => 'GET',
'queuenumber' => 722,
'keepalive' => 1,
'NAME' => 'echo',
'FVERSION' => '37_echodevice.pm:v5.0.0-s23714/2021-02-10',
'OLDREADINGS' => {},
'.FhemMetaInternals' => 1,
'NR' => 415
},
'STATE' => 'connected',
'DEF' => 'ADVBD696BHNV5 7094180751761LVH',
'NTFY_ORDER' => '50-ECHO_7094180751761LVH',
'TYPE' => 'echodevice'
},
'auth' => 0,
'directWriteFn' => sub { "DUMMY" },
'timeout' => 10
};
Ich habe jetzt eine Weile drueber meditiert, ist mir aber nichts Konkretes eingefallen.
Leider sind durch die "grobe Loeschung" einige Klammer verschwunden (in der Summe fehlen 2), was die Zuordnung zu einem Ratespiel macht.
Die stacktrace Ausgabe nach der Fehlermeldung waere auch hilfreich gewesen.
Wenn ich richtig rate, dann liegt das Problem nicht in der DNS-Aufloesung, sondern spaeter, beim Auswerten der HTML Daten. Irgendwer hat vermutlich directReadFn entfernt, ohne selectlist passend zu loeschen. Ich sehe aber die Stelle nicht...
Hallo Rudi,
anbei nochmal in ausführlich (und um es gleich vorweg zu sagen: Der Freezemon ist nicht schuld ;-)). Wenn ich noch irgendwo was zum loggen einbauen soll, sag Bescheid.
Danke,
Oli
Zitatanbei nochmal in ausführlich [...]
... und wegen Uebergroesse abgeschnitten. Kannst Du das bitte als Anhang machen?
Zitat von: rudolfkoenig am 16 April 2021, 09:49:58
... und wegen Uebergroesse abgeschnitten. Kannst Du das bitte als Anhang machen?
hab den vorigen Post abgeändert... Anfängerfehler :-S
ZitatDer Freezemon ist nicht schuld ;-)
Steile These. Jedenfall erschwert es das debuggen.
Kann ich bitte eine Version des Logs ohne obfuscated directWriteFn bekommen?
Da auch noch mindestens ein } fehlt, bin ich unsicher, ob nicht weitere relevante Teile entfernt wurden.
ok... jetzt alle Details ;-)
Zitat von: rudolfkoenig am 17 April 2021, 09:19:40
Steile These. Jedenfall erschwert es das debuggen.
Der Fehler tritt auch ohne Freezemon auf, dann bekomme ich aber das Log nicht (das liefert mir nur der eingebaute "freeze"). Wenn's nicht anders geht, lasse ich aber das System auch mal 12 Stunden auf verbose 5 laufen...
Zitat'directWriteFn' => sub { "DUMMY" },
Hast Du eine Idee, wer "DUMMY" reinschreibt?
Ich bin verunsichert, weil wenn dieser Eintrag modifiziert ist, dann sind andere evtl. auch, und meine Theorien sind dann wenig Wert.
Da buf gesetzt ist, vermute ich es geht um den Abschnitt in HttpUtils_Connect2.
ReadFn wird (nur?) in fhem.pl aufgerufen, falls $hash->{FD} in $rout gesetzt ist.
FD in $rout wird gesetzt, falls FD in $rin gesetzt ist, und select was gefunden hat.
FD in $rin wird nur gesetzt, falls kein directWriteFn gesetzt ist (erst Schreiben, dann Lesen)
=> ReadFn darf mit einem gesetzten dierectWriteFn gar nicht aufgerufen werden.
Ich uebersehe vermutlich was.
Hallo Rudi,
DUMMY wird vom Dumper bei anonymen Funktionen reingeschrieben. Tatsächlich steht da eine Referenz drin, denke ich.
Zitat von: rudolfkoenig am 18 April 2021, 15:04:06
=> ReadFn darf mit einem gesetzten dierectWriteFn gar nicht aufgerufen werden.
Ich kann dem ganzen zwar nicht wirklich folgen, aber CallFn wird ja offensichtlich mit leerem (aber definiertem) $hash->{NAME} aufgerufen, kann das denn sein?
hier:
my $isDev = ($hash && $hash->{NAME} && $defs{$hash->{NAME}});müsste $isDev ja "false" sein. In diesem Fall macht es auch keinen Sinn CallFn überhaupt aufzurufen.
Kann man an der Stelle noch geschickt irgendwas loggen, um vielleicht herauszufinden wo das herkommt?
Kleine Ergänzung noch... Stacktrace ohne Freezemon ;-)
2021.04.19 10:21:58 1: stacktrace:
2021.04.19 10:21:58 1: main::CallFn called by fhem.pl (773)
Zitat... CallFn wird ja offensichtlich mit leerem (aber definiertem) $hash->{NAME} aufgerufen, kann das denn sein?
Naja, es passiert, also es kann sein. Ob es so gewollt ist: vermutlich nicht.
Vermutlich war das Lesen mit directReadFn geplant, die hat aber wohl jemand entfernt.
Das aber ist _eigentlich_ irrelevant, siehe mein Text von vorhin, mit dem Praedikat: "kann dem ganzen zwar nicht wirklich folgen" :)
Ich habe jetzt versucht in HttpUtils etwas besser aufzuraeumen, bevor man die Kontrolle an dem Aufrufer zurueckgibt, es gibt eine geringe Chance, dass das Problem dabei gefixt wird.