CustomGetFileFromURL: leere Antwort wenn hinter einem Proxy

[Dr. Boris Neubert]

So nach und nach wird meine Austauschhardware nach dem Überspannungsschaden wieder einsatzbereit.

Ich habe gerade zwei Stunden an dem Problem geknobelt, warum Weather und Calendar keine Updates mehr bekommen.

Symptom:

Code Auswählen Erweitern

CustomGetFileFromURL <hidden>: empty answer received

Das Verhalten tritt nur auf, wenn Dateien per HTTP abgeholt werden, und dann bei den meisten aber nicht bei allen Aufrufen. Dateien per HTTPS werden sauber abgeholt. Es tritt sowohl auf meinem Raspberry Pi unter Raspian mit linux 3.12.24 als auch auf einen Intel Core2 Duo unter Ubuntu 14.04 auf. Es gibt eine Reihe von Anwenderberichten hier im Forum, die vergleichbares erlebt haben.

Das Problem kann ich reproduzierbar ein- oder ausschalten, indem ich den transparenten WebProxy auf meiner inneren Firewall ein- und ausschalte (Zwangsrouting aller Requests ins Internet auf Port 80 werden durch Squid geleitet).

Es funktioniert immer, die Dateien per Hand (wget, Browser) per HTTP abzuholen.

Die Ursache ist also sehr wahrscheinlich in HttpUtils_BlockingGet() zu suchen.

Reproduzierbarkeit eines Problems ist ja schon die halbe Lösung.

Wie soll ich zur weiteren Problemanalyse vorgehen?

Viele Grüße
Boris

[rudolfkoenig]

Als erstes das Ganze mit global loglevel 5 wiederholen, und die relevanten Meldungen hier posten. Vermutlich muessen wir dann noch mehr Logging in HttpUtils einbauen, um das Problem zu lokalisieren bzw. zu verstehen.

[Dr. Boris Neubert]

Hallo,

Als erstes das Ganze mit global loglevel 5 wiederholen, und die relevanten Meldungen hier posten. Vermutlich muessen wir dann noch mehr Logging in HttpUtils einbauen, um das Problem zu lokalisieren bzw. zu verstehen.

im Log stand gestern schon nichts verwertbares. Ich habe etwas Logging eingebaut (siehe Patch) und bekomme bei eingeschaltetem Proxy damit folgendes Protokoll:

Code Auswählen Erweitern


2014.08.18 20:44:41 4: Calendar C: Wakeup                                                                                                                                       
2014.08.18 20:44:41 4: Calendar C: Updating...                                                                                                                                 
2014.08.18 20:44:41 5: HttpUtils url=<hidden>                                                                                                                                   
2014.08.18 20:44:41 1: DEBUG>HttpUtils_Connect2() $hdr follows:BEGIN                                                                                                           
GET /calendar/ical/neubert.boris%40googlemail.com/private-foobar/basic.ics HTTP/1.0                                                                   
Host: www.google.com


END
2014.08.18 20:44:41 1: DEBUG>HttpUtils_BlockingGet() $err is undefined
2014.08.18 20:44:41 1: DEBUG>HttpUtils_BlockingGet() $nfound= 1
2014.08.18 20:44:41 1: DEBUG>HttpUtils_BlockingGet() $len= 0
2014.08.18 20:44:41 5: CustomGetFileFromURL <hidden>: empty answer received
2014.08.18 20:44:41 1: Calendar C: Could not retrieve file at URL



Viele Grüße
Boris

[rudolfkoenig]

D.h. der transparente Proxy ist nicht transparent genug.

Wenn ich es richtig sehe, macht dein Proxy die Verbindung sofort zu (sysread == 0), ich vermute, weil ihm irgendwelche HTTP-Headerdaten fehlen. Koenntest du von einem funktionierenden Programm einen kompletten Satz an Header abschreiben (curl -v ...) und die fehlenden dem $hash->{header}  oder direkt in HttpUtils_Connect2 zufuegen?

Kannst Du bitte sicherheitshalber pruefen, dass noshutdown nicht auf 0 gesetzt ist?

Falls jemand andere Theorien hat, dann raus damit.

[Dr. Boris Neubert]

Hallo,

das Problem ist gelöst. Calendar_GetUpdate() ruft GetFileFromURLQuiet() so auf, dass noshutdown auf 0 steht. Keine Ahnung, warum ich das damals so gemacht habe. Ich habe jetzt aufgeräumt und den Aufruf durch

Code Auswählen Erweitern


HttpUtils_BlockingGet( { url => $url, hideurl => 1, timeout => 10, } );


ersetzt.Damit funktioniert es dann auch hinter dem Proxy.

Ich habe aber dennoch die Kommunikation mitgeschnitten, falls es mal gebraucht wird:

Code Auswählen Erweitern


wget -d -o debug.txt http://www.schulferien.org/iCal/Ferien/icals/Ferien_Hessen_2014.ics


liefert bei einem Cache MISS folgendes debug.txt:

Code Auswählen Erweitern


DEBUG output created by Wget 1.15 on linux-gnu.

URI encoding = »UTF-8«
--2014-08-19 21:16:29--  http://www.schulferien.org/iCal/Ferien/icals/Ferien_Hessen_2014.ics
Auflösen des Hostnamen »www.schulferien.org (www.schulferien.org)«... 87.106.71.133
Caching www.schulferien.org => 87.106.71.133
Verbindungsaufbau zu www.schulferien.org (www.schulferien.org)|87.106.71.133|:80... verbunden.
Created socket 4.
Releasing 0x00000000019c24f0 (new refcount 1).

---request begin---
GET /iCal/Ferien/icals/Ferien_Hessen_2014.ics HTTP/1.1
User-Agent: Wget/1.15 (linux-gnu)
Accept: */*
Host: www.schulferien.org
Connection: Keep-Alive

---request end---
HTTP-Anforderung gesendet, warte auf Antwort...
---response begin---
HTTP/1.1 200 OK
Date: Tue, 19 Aug 2014 19:16:31 GMT
Server: Apache
Last-Modified: Tue, 19 Aug 2014 13:46:47 GMT
ETag: "80048d8d-575-500fbb7faf99a"
Accept-Ranges: bytes
Content-Length: 1397
Content-Type: text/calendar
X-Cache: MISS from HostnameOfMyProxy
X-Cache-Lookup: MISS from HostnameOfMyProxy:800
Connection: keep-alive

---response end---
200 OK
Registered socket 4 for persistent reuse.
Länge: 1397 (1,4K) [text/calendar]
In »»Ferien_Hessen_2014.ics«« speichern.

     0K .                                                     100%  476K=0,003s

2014-08-19 21:16:29 (476 KB/s) - »»Ferien_Hessen_2014.ics«« gespeichert [1397/1397]



Bei einem Cache HIT kommt dieses dabei heraus:

Code Auswählen Erweitern


DEBUG output created by Wget 1.15 on linux-gnu.

URI encoding = »UTF-8«
--2014-08-19 21:54:20--  http://www.schulferien.org/iCal/Ferien/icals/Ferien_Hessen_2014.ics
Auflösen des Hostnamen »www.schulferien.org (www.schulferien.org)«... 87.106.71.133
Caching www.schulferien.org => 87.106.71.133
Verbindungsaufbau zu www.schulferien.org (www.schulferien.org)|87.106.71.133|:80... verbunden.
Created socket 4.
Releasing 0x00000000014944f0 (new refcount 1).

---request begin---
GET /iCal/Ferien/icals/Ferien_Hessen_2014.ics HTTP/1.1
User-Agent: Wget/1.15 (linux-gnu)
Accept: */*
Host: www.schulferien.org
Connection: Keep-Alive

---request end---
HTTP-Anforderung gesendet, warte auf Antwort...
---response begin---
HTTP/1.1 200 OK
Date: Tue, 19 Aug 2014 19:16:31 GMT
Server: Apache
Last-Modified: Tue, 19 Aug 2014 13:46:47 GMT
ETag: "80048d8d-575-500fbb7faf99a"
Accept-Ranges: bytes
Content-Length: 1397
Content-Type: text/calendar
Age: 2271
X-Cache: HIT from HostnameOfMyProxy
X-Cache-Lookup: HIT from HostnameOfMyProxy:800
Connection: keep-alive

---response end---
200 OK
Registered socket 4 for persistent reuse.
Länge: 1397 (1,4K) [text/calendar]
In »»Ferien_Hessen_2014.ics«« speichern.

     0K .                                                     100%  127M=0s

2014-08-19 21:54:20 (127 MB/s) - »»Ferien_Hessen_2014.ics«« gespeichert [1397/1397]


Und weil's so schön ist, habe ich auch gleich noch 59_Weather.pm gefixt.

Viele Grüße
Boris