Strange call for nonexistent : ReadFn

Begonnen von KernSani, 07 April 2021, 14:20:07

Vorheriges Thema - Nächstes Thema

rudolfkoenig

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.

netwalk

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.
live long and prosper
netwalk
_______________________________________________
INTEL NUC7CJYH, Homematic mit 3x HMLGW, JEELINK mit 18x TX29-DTH-IT, DUOFERNSTICK, FB7590 mit FBDECT, NETATMO, Philips HUE, RFXtrx433, Ubiquiti G3 PRO/FLEX/DOME/MICRO

JudgeDredd

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 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.
Router: Eigenbau (pfSense)
FHEM: Hyper-V | Debian 12 (VM)

KernSani

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

        };



RasPi: RFXTRX, HM, zigbee2mqtt, mySensors, JeeLink, miLight, squeezbox, Alexa, Siri, ...

rudolfkoenig

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

KernSani

#35
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

RasPi: RFXTRX, HM, zigbee2mqtt, mySensors, JeeLink, miLight, squeezbox, Alexa, Siri, ...

rudolfkoenig

Zitatanbei nochmal in ausführlich [...]
... und wegen Uebergroesse abgeschnitten. Kannst Du das bitte als Anhang machen?

KernSani

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
RasPi: RFXTRX, HM, zigbee2mqtt, mySensors, JeeLink, miLight, squeezbox, Alexa, Siri, ...

rudolfkoenig

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.

KernSani

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... 
RasPi: RFXTRX, HM, zigbee2mqtt, mySensors, JeeLink, miLight, squeezbox, Alexa, Siri, ...

rudolfkoenig

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.

KernSani

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?


RasPi: RFXTRX, HM, zigbee2mqtt, mySensors, JeeLink, miLight, squeezbox, Alexa, Siri, ...

KernSani

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)
RasPi: RFXTRX, HM, zigbee2mqtt, mySensors, JeeLink, miLight, squeezbox, Alexa, Siri, ...

rudolfkoenig

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.