HTTP 405 Response Nach 200. Logfile: unsupported HTTP method

Begonnen von Qowy, 15 Mai 2020, 13:39:47

Vorheriges Thema - Nächstes Thema

Qowy

Hi,
ich reverse proxy mein FHEM Setup hinter einer eigenen Webanwendung welche authentication authorization usw macht.

An sich funktioniert auch alles, bis darauf das FHEM auf fast alle Anfragen erst mit einem 200 OK antwortet und dann aber sofort ein 405 Method Not Allowed hinterherschickt.

Das Logfile loggt unmengen "unsupported HTTP method , rejecting it."

Die Browser scheinen diese 2. Antwort glücklicherweise zu ignorieren, nachdem das 200 OK kam, deswegen scheint auch alles zu funktionieren.

Es folgt mal ein (gekürztes) gespräch mit FHEM mitgeschnitten mit Wireshark.


GET /fhem/?cmd=get%20logdb%20-%20-%202020-05-14_13%3A00%3A00%202020-05-15_14%3A00%3A00%20DimplexWP%3Adimhp_temperature_outdoor%3A%3A&fwcsrf=csrf_338762756054057&XHR=1&_=1589268089556 HTTP/1.1
Accept: text/plain, */*; q=0.01
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US, de-DE; q=0.8, de; q=0.5, en; q=0.3
Cookie: .AspNetCore.Antiforgery.1JLQcGR_8qw=CfDJ8O8OQ7yFdotMi5OKDndHvmmFgdMrHD6UUA69LE7T25I-TdbFkRknKwV8aTuwmdpZENSIERTmaXWBGd5xdxLIV1SQQThfvuFvCzWOLJ4Mk80, .AspNetCore.Cookies=CfDJ8O8OQ7yFdotMi5OKDZENSIERTpvkiOWPxDeccC1Bw1OGMxLYi7BWBnHlvqNjV2hWztipojpQBIkNJt-7_8PCaDUY8NxIDu4vbHEPBQsLPDyqERS8wXvFNcvOh04Qcbe093cF6kxq7bhL_Wnp3nfTqRCK3lbJmZENSIERTw_zvoaeWfGtIsMj5J60uNfLdh0yjeSzGWMofd0bTDlizY8wKy7dvpwj9ueMvIdO2FYME4FOEbauRE44MLdm6BsDDY0UNqNeaX3VtQWsz2U5RUOSZEwYhlXZENSIERTQPbU4Kk48-ymiOhA9TO66bu4RHwytuvJhEhL4w8E9wKaG3KzkT7tAu-Ste8fr2yJ47k-6Q_cNYsjqlPowKiTcUL2IWPb01Dw6RK3fTEr73GZENSIERT8xc4xl4EfXB8TTrxt2RSG-NCbmlLH60Hg
Host: localhost:8083
Referer: https://ZENSIERT/fhem/tablet/index.html
TE: trailers
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:76.0) Gecko/20100101 Firefox/76.0
DNT: 1
x-requested-with: XMLHttpRequest
X-Forwarded-For: "[::ffff:192.168.103.94]"
X-Forwarded-Host: ZENSIERT.de
X-Forwarded-Proto: https
Request-Id: |83523e10-4888a4bd8b533161.1.
Transfer-Encoding: chunked



HTTP/1.1 200 OK
Content-Length: 908
Cache-Control: no-cache, no-store, must-revalidate
Content-Encoding: gzip
Content-Type: text/plain; charset=UTF-8

2020-05-14_13:01:49 13.9
2020-05-14_13:12:22 14.6
2020-05-14_13:22:55 15.0
2020-05-14_13:33:17 15.0
2020-05-14_13:43:45 15.0
2020-05-14_13:54:17 15.0
usw..
#DimplexWP:dimhp_temperature_outdoor:::



HTTP/1.1 405 Method Not Allowed
Content-Length: 0


Das ganze passiert bei fast alles GET requests, z.B. auch wenn eine .js datei angefordert wird, wird mit 301 und 405 geantwortet.

Irgendetwas im request header was FHEM nicht schmeckt und zu diesem (meiner meinung nach) abstrußen verhalten führt?

Edit: Nach einem schnellen blick in den code taucht diese Meldung ja nur in Zeile 488 in 01_FHEMWEB.pm auf Und die Tatsache dass keine method gelogged wird heißt dass $method in zeile 478 auf "" gesetzt wird, da if(!$method) true ergibt.

D.h. irgendwo zwischen der richtigen Antwort, und dieser Code Zeile geht $method verloren? Da muss doch irgendwo ein bug sein. Selbsts wenn ich schmarn als request schicken sollte, sollten doch nie 2 Antworten geschickt werden.

Otto123

Wozu ist der Teil am Ende?
Zitat&_=1589268089556 HTTP/1.1

Ich habe da nicht viel Ahnung von, aber wenn ich sowas mache ist bei &XHR=1 Schluß :)

Gruß Otto
Viele Grüße aus Leipzig  ⇉  nächster Stammtisch an der Lindennaundorfer Mühle
RaspberryPi B B+ B2 B3 B3+ ZeroW,HMLAN,HMUART,Homematic,Fritz!Box 7590,WRT3200ACS-OpenWrt,Sonos,VU+,Arduino nano,ESP8266,MQTT,Zigbee,deconz

Qowy

Keine ahnung, die Urls sind ja auch nicht von mir, die kommen entweder ganz normal von FHEM oder FHEM tablet ui (und wie gesagt es passiert auch bei sowas wie GET /script.js)

rudolfkoenig

Ich sehe mit einem Apache-Proxy keine Probleme, ich habe es aber auch nicht mit dblog getestet.

405 liefert FHEM zurueck, wenn die Anfrage nicht HTTP GET/POST/OPTIONS ist.
Vermutlich koennte hier ein "attr WEB verbose 5" weiterhlefen, ich frage mich, wieso man nicht mit sowas anfaengt.

@Otto123: das ist eine uebliche Methode irgendwelche Caches zu umgehen.

Otto123

Viele Grüße aus Leipzig  ⇉  nächster Stammtisch an der Lindennaundorfer Mühle
RaspberryPi B B+ B2 B3 B3+ ZeroW,HMLAN,HMUART,Homematic,Fritz!Box 7590,WRT3200ACS-OpenWrt,Sonos,VU+,Arduino nano,ESP8266,MQTT,Zigbee,deconz

Qowy

Zitat von: rudolfkoenig am 16 Mai 2020, 14:53:04
Ich sehe mit einem Apache-Proxy keine Probleme, ich habe es aber auch nicht mit dblog getestet.

405 liefert FHEM zurueck, wenn die Anfrage nicht HTTP GET/POST/OPTIONS ist.
Vermutlich koennte hier ein "attr WEB verbose 5" weiterhlefen, ich frage mich, wieso man nicht mit sowas anfaengt.

@Otto123: das ist eine uebliche Methode irgendwelche Caches zu umgehen.

Ok ich wiederhole es nochmal.

Wie in den Wireshark Mitschnitten zu sehen Ist die Anfrage GET von daher hilft mir die Aussage "405 liefert FHEM zurück, wenn die Anfrage nicht HTTP GET/POST/OPTIONS ist." nicht weiter.

"attr WEB verbose 5" hab ich auch schon gemacht und siehe da es ist eine GET Anfrage auf die geantwortet wird; ich bin halt schon eine Stufe weiter und habe direkt wireshark angeschaut ;) .

FHEM bekommt GET anfrage. -> FHEM antwortet mit HTTP 200 OK -> Gleichzeitig antwortet FHEM mit 405 Not Allowed.

Völlig egal was/ob ich falsch mache das darf schonmal nicht sein. HTTP ist ja nur mit einer Antwort definiert, da darf der Server nicht 2 (auch noch unterschiedliche schicken).
Dass die Fehlermeldung  garnicht das meldet, was sie soll sie man schon daran, dass sie  nicht lautet "unsupported HTTP method HEAD" oder ähnliches, sondern der request method string der Fehlermeldung leer ist.

Hier nochmal fürs protokoll verbose 5:


2020.05.17 13:03:07 4: Connection accepted from WEB_127.0.0.1_44418
2020.05.17 13:03:07 4: WEB_127.0.0.1_44418 GET /fhem/pgm2/images/ui-icons_222222_256x240.png; BUFLEN:5
2020.05.17 13:03:07 3: WEB_127.0.0.1_44418: unsupported HTTP method , rejecting it.
2020.05.17 13:03:07 4: Connection accepted from WEB_127.0.0.1_44422
2020.05.17 13:03:07 4: Connection accepted from WEB_127.0.0.1_44426
2020.05.17 13:03:07 4: WEB_127.0.0.1_44422 GET /fhem/pgm2/images/ui-bg_diagonals-thick_20_666666_40x40.png; BUFLEN:5
2020.05.17 13:03:07 3: WEB_127.0.0.1_44422: unsupported HTTP method , rejecting it.
2020.05.17 13:03:07 4: Connection accepted from WEB_127.0.0.1_44430
2020.05.17 13:03:07 4: WEB_127.0.0.1_44426 GET /fhem/?cmd=get%20logdb%20-%20-%202020-05-16_13%3A00%3A00%202020-05-17_14%3A00%3A00%20DimplexWP%3Adimhp_temperature_outdoor%3A%3A&fwcsrf=&XHR=1&_=1589558942734; BUFLEN:5
2020.05.17 13:03:07 4: authorize WEB/cmd/get: allowed_MQTT_TH10_pool returned dont care
2020.05.17 13:03:07 4: authorize WEB/devicename/logdb: allowed_MQTT_TH10_pool returned dont care
2020.05.17 13:03:07 4: WEB: /fhem/?cmd=get%20logdb%20-%20-%202020-05-16_13%3A00%3A00%202020-05-17_14%3A00%3A00%20DimplexWP%3Adimhp_temperature_outdoor%3A%3A&fwcsrf=&XHR=1&_=1589558942734 / RL:899 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/ Cache-Control: no-cache, no-store, must-revalidate

2020.05.17 13:03:07 3: WEB_127.0.0.1_44426: unsupported HTTP method , rejecting it.
2020.05.17 13:03:07 4: WEB_127.0.0.1_44430 GET /fhem/?cmd=get%20logdb%20-%20-%202020-05-16_13%3A00%3A00%202020-05-17_14%3A00%3A00%20DimplexWP%3Adimhp_temperature_outdoor%3A%3A&fwcsrf=&XHR=1&_=1589558942735; BUFLEN:5
2020.05.17 13:03:07 4: authorize WEB/cmd/get: allowed_MQTT_TH10_pool returned dont care
2020.05.17 13:03:07 4: authorize WEB/devicename/logdb: allowed_MQTT_TH10_pool returned dont care
2020.05.17 13:03:08 4: WEB: /fhem/?cmd=get%20logdb%20-%20-%202020-05-16_13%3A00%3A00%202020-05-17_14%3A00%3A00%20DimplexWP%3Adimhp_temperature_outdoor%3A%3A&fwcsrf=&XHR=1&_=1589558942735 / RL:899 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/ Cache-Control: no-cache, no-store, must-revalidate

2020.05.17 13:03:08 3: WEB_127.0.0.1_44430: unsupported HTTP method , rejecting it.


Ich denke wir sind uns einig, das ist merkwürdig :) Man achte auch nochmal auf das Leerzeichen vor dem Komma in der Fehlermeldung. Hier sollte die rejected HTTP method stehen, tut sie aber nicht.

Qowy

Ok ich bin mit dem debuggen etwas weiter:

Mit Proxy landet FW_closeConn($hash) in  FW_read() wo $hash->{HDR} dann aber leer ist weswegen $method leer ist und der rest ist klar.
Ohne Proxy passiert das nicht, und FW_closeConn returned einfach.

Jetzt muss ich noch rausfinden warum FW_closeConn mit proxy der Meinung ist nochmal FW_read() aufrufen zu müssen.
Etwas input vom Programmierer warum diese Funktion, doch nochmal zu lesen, gebraucht wird wäre vermutlich hilfreich :D :

Chunked transfers?


POSIX::exit(0) if($hash->{isChild});
FW_Read($hash, 1) if($hash->{BUF});


EDIT:

Ok wir kommen der sache näher:
FW_closeConn ruft nocheinmal FW_Read auf, da $hash->{BUF} tatsächlich nicht leer ist.

{BUF} hat aber keinen sinnvollen Wert, sondern  ist "0\cM\cJ\cM\cJ" weswegen natürlich alles spätere nicht mehr funktioniert.

Warum hat {BUF} nun diesen Wert?

=> gesetzt wird er durch dieses RegEx


    return if($hash->{BUF} !~ m/^(.*?)(\n\n|\r\n\r\n)(.*)$/s);
    $hash->{HDR} = $1;
    $hash->{BUF} = $3;


Hierbei enthält $1 den korrekten Teil und $3 ist aber leider nicht leer sondern "0\cM\cJ\cM\cJ" (Was aber soweit ich weiß stimmen sollte, da das ende eines Chunked HTTP ja 0\r\n\r\n sein müsste)

Allerdings wird anscheinend nirgends überprüft ob der rest der noch in BUF ist nur die "Chunked Transfer zu Ende" Zeichenfolge ist.

=> quickfix FW_closeConn($) in der 01_FHEMWEB.pm anpassen auf:


sub
FW_closeConn($)
{
  my ($hash) = @_;
  # Forum #41125, 88470
  if(!$hash->{inform} && !$hash->{BUF} && !defined($hash->{".WRITEBUFFER"})) {
    my $cc = AttrVal($hash->{SNAME}, "closeConn",
                     $FW_userAgent =~ m/(iPhone|iPad|iPod)/);
    if(!$FW_httpheader{Connection} || $cc) {
      TcpServer_Close($hash, 1);
    }
  }

  POSIX::exit(0) if($hash->{isChild});

#NEUER CHECK
if($hash->{BUF} eq "0\cM\cJ\cM\cJ") {
   #Notwendig da viele aufrufe immer nur {BUF} .= machen
   $hash->{BUF} = "";
   return;
}

  FW_Read($hash, 1) if($hash->{BUF});
}




und siehe da es funktioniert.
Eine entsprechende überprüfung kann villeicht anderswo sinvoller sein und schöner durchgeführt werden, aber das überlasse jemandem, der den Code besser kennt.




Christian72D

#7
Ich muß den beitrag mal "kapern", ich habe eben auf meiner Synology RP eingerichtet, ich komme auch perfekt auf fhem drauf, ABER ich bekomme pausenlos die Meldung, daß die Verbindung verloren wurde und in 5 Sekunden eine Neu Verbindung versucht wird.

An wem liegt es?

NACHTRAG: das passiert nur, wenn ich das zuhause Teste, von unterwegs kommt die Meldung nicht.