Strange call for nonexistent : ReadFn

[KernSani]

Hi,
als Fortsetzung dieses Threads.

Ich habe sporadisch die Fehlermeldung

Code Auswählen Erweitern

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

[rudolfkoenig]

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?

[KernSani]

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...   

[KölnSolar]

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

[KernSani]

So, ich habe mal so einen Kollegen "eingefangen":

Code Auswählen Erweitern


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,   

[rudolfkoenig]

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.

[KölnSolar]

Dann lade ich das morgen auch mal.

Ich hab dann mein Log durchforstet:

Code Auswählen Erweitern

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

[rudolfkoenig]

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.

[KernSani]

Ich kann mit ziemlicher Sicherheit ausschließen, dass es an der Internetverfügbarkeit liegt. 

[KölnSolar]

Morgen,
bei mir sieht das nun alle 10' so aus:

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)
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

[michael.winkler]

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.

[TomLee]

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.

[yersinia]

Interessant, kommt bei mir von einem JsonMod-Device, glaube ich zumindest. Fehlermeldung:

Code Auswählen Erweitern

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:

Code Auswählen Erweitern

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>&nbsp;(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.

[herrmannj]

... 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

[yersinia]

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.

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...