Discussion:
[squid-users] URL sometimes reurns empty response
Ralf Hildebrandt
2017-05-02 11:59:38 UTC
Permalink
In some cases, our proxies (got 4 of them) return a empty result when
querying "http://www.msftconnecttest.com/ncsi.txt" (whcih is used by
Microsoft Brwosers to check if they're online).

I'm using this incantation to check the URL:

watch -d curl --silent -v -x "http://proxy-cvk-1.charite.de:8080" http://www.msftconnecttest.com/ncsi.txt

Usually, the URL should just return "Microsoft NCSI".
In some cases I get an empyt response, but curl reports:

< Age: 5
< X-Cache: HIT from proxy-cvk-1
< Via: 1.1 proxy-cvk-1 (squid/5.0.0-20170421-r15126)
< Connection: keep-alive
<
* Excess found in a non pipelined read: excess = 14 url = /ncsi.txt (zero-length body)
* Curl_http_done: called premature == 0
* Connection #0 to host (nil) left intact

As you can see, something is producing an excess of 14 Bytes (which
coincides with the 14 bytes length of "Microsoft NCSI").

< Cache-Control: max-age=30,must-revalidate

Immediatly after revalidating, the problem occurs.

I tried this with 5.0.0-20170421-r15126 as well as 4.0.19 - same result.
--
Ralf Hildebrandt Charite Universitätsmedizin Berlin
***@charite.de Campus Benjamin Franklin
https://www.charite.de Hindenburgdamm 30, 12203 Berlin
Geschäftsbereich IT, Abt. Netzwerk fon: +49-30-450.570.155
Yuri Voinov
2017-05-02 12:05:31 UTC
Permalink
If you add this URL to cache deny rule - problem still exists?
Post by Ralf Hildebrandt
In some cases, our proxies (got 4 of them) return a empty result when
querying "http://www.msftconnecttest.com/ncsi.txt" (whcih is used by
Microsoft Brwosers to check if they're online).
watch -d curl --silent -v -x "http://proxy-cvk-1.charite.de:8080" http://www.msftconnecttest.com/ncsi.txt
Usually, the URL should just return "Microsoft NCSI".
< Age: 5
< X-Cache: HIT from proxy-cvk-1
< Via: 1.1 proxy-cvk-1 (squid/5.0.0-20170421-r15126)
< Connection: keep-alive
<
* Excess found in a non pipelined read: excess = 14 url = /ncsi.txt (zero-length body)
* Curl_http_done: called premature == 0
* Connection #0 to host (nil) left intact
As you can see, something is producing an excess of 14 Bytes (which
coincides with the 14 bytes length of "Microsoft NCSI").
< Cache-Control: max-age=30,must-revalidate
Immediatly after revalidating, the problem occurs.
I tried this with 5.0.0-20170421-r15126 as well as 4.0.19 - same result.
--
Bugs to the Future
Ralf Hildebrandt
2017-05-02 12:59:07 UTC
Permalink
Post by Yuri Voinov
If you add this URL to cache deny rule - problem still exists?
Using this:

# START
acl nocaching url_regex "^http://www\.(msftconnecttest|msftncsi)\.com"
cache deny nocaching
# ENDE

And yes, problem still exists...
--
Ralf Hildebrandt Charite Universitätsmedizin Berlin
***@charite.de Campus Benjamin Franklin
https://www.charite.de Hindenburgdamm 30, 12203 Berlin
Geschäftsbereich IT, Abt. Netzwerk fon: +49-30-450.570.155
Marcus Kool
2017-05-02 13:02:38 UTC
Permalink
Looks like MS uses multiple servers for msftconnecttest.com and that they send different content.
Post by Ralf Hildebrandt
In some cases, our proxies (got 4 of them) return a empty result when
querying "http://www.msftconnecttest.com/ncsi.txt" (whcih is used by
Microsoft Brwosers to check if they're online).
watch -d curl --silent -v -x "http://proxy-cvk-1.charite.de:8080" http://www.msftconnecttest.com/ncsi.txt
Usually, the URL should just return "Microsoft NCSI".
< Age: 5
< X-Cache: HIT from proxy-cvk-1
< Via: 1.1 proxy-cvk-1 (squid/5.0.0-20170421-r15126)
< Connection: keep-alive
<
* Excess found in a non pipelined read: excess = 14 url = /ncsi.txt (zero-length body)
* Curl_http_done: called premature == 0
* Connection #0 to host (nil) left intact
As you can see, something is producing an excess of 14 Bytes (which
coincides with the 14 bytes length of "Microsoft NCSI").
< Cache-Control: max-age=30,must-revalidate
Immediatly after revalidating, the problem occurs.
I tried this with 5.0.0-20170421-r15126 as well as 4.0.19 - same result.
Ralf Hildebrandt
2017-05-02 13:08:43 UTC
Permalink
Post by Marcus Kool
Looks like MS uses multiple servers for msftconnecttest.com and that they send different content.
Nope. I verified the server's responses on the proxy machines itself
using direct connections. It's always correct.
Post by Marcus Kool
Post by Ralf Hildebrandt
* Excess found in a non pipelined read: excess = 14 url = /ncsi.txt (zero-length body)
It seems that squid is returning an incorrect Content-Lenght: header
while the revalidation is still fresh/ongoing.

I haven't yet tried tcpdumping the response to check if the 14 bytes
do indeed contain the correct string.
--
Ralf Hildebrandt Charite Universitätsmedizin Berlin
***@charite.de Campus Benjamin Franklin
https://www.charite.de Hindenburgdamm 30, 12203 Berlin
Geschäftsbereich IT, Abt. Netzwerk fon: +49-30-450.570.155
Ralf Hildebrandt
2017-05-02 13:15:26 UTC
Permalink
Post by Ralf Hildebrandt
It seems that squid is returning an incorrect Content-Lenght: header
while the revalidation is still fresh/ongoing.
I haven't yet tried tcpdumping the response to check if the 14 bytes
do indeed contain the correct string.
And voila - here we go (Content-Length: 0 but squid sends 14 bytes of excess data: "Microsoft NCSI")

15:10:31.741436 IP proxy-cvk-1.charite.de.http-alt > vsw-it-nw-10.54228: Flags [P.], seq 1:952, ack 156, win 235, options [nop,nop,TS val 126939588 ecr 1696144349], length 951: HTTP: HTTP/1.1 200 OK
***@.?....*...*......V?.....5....U......
....e...HTTP/1.1 200 OK
Cache-Control: max-age=30,must-revalidate
Content-Length: 0
Content-Type: text/plain
Last-Modified: Fri, 04 Mar 2016 06:55:23 GMT
ETag: "0x8D343F9F578A7F9"
Server: Microsoft-IIS/7.5
x-ms-request-id: 6508a999-0001-0016-4fbc-c0483a000000
x-ms-version: 2009-09-19
x-ms-meta-CbModifiedTime: Tue, 01 Mar 2016 21:41:22 GMT
x-ms-lease-status: unlocked
x-ms-blob-type: BlockBlob
X-ECN-P: RD0003FF838204
Access-Control-Expose-Headers: X-MSEdge-Ref
Access-Control-Allow-Origin: *
Timing-Allow-Origin: *
X-CID: 7
X-CCC: US
X-MSEdge-Ref: Ref A: 2C6BD6F103A24795AE6784C3DC22E5F5 Ref B: BER30EDGE0115 Ref C: Tue May 2 06:10:31 2017 PST
X-MSEdge-Ref-OriginShield: Ref A: 5A9FC4FE82DC4E2DB26E51E59C50B50A Ref B: AMS04EDGE0506 Ref C: Sat Apr 29 05:30:12 2017 PST
Date: Tue, 02 May 2017 13:10:31 GMT
Age: 0
X-Cache: HIT from proxy-cvk-1
Via: 1.1 proxy-cvk-1 (squid/5.0.0-20170429-r15127)
Connection: keep-alive

Microsoft NCSI
15:10:31.741454 IP vsw-it-nw-10.54228 > proxy-cvk-1.charite.de.http-alt: Flags [.], ack 952, win 243, options [nop,nop,TS val 1696144352 ecr 126939588], length 0
***@.@..=.*...*.........5V?.G.....O.....
e.......
--
Ralf Hildebrandt Charite Universitätsmedizin Berlin
***@charite.de Campus Benjamin Franklin
https://www.charite.de Hindenburgdamm 30, 12203 Berlin
Geschäftsbereich IT, Abt. Netzwerk fon: +49-30-450.570.155
Yuri Voinov
2017-05-02 13:19:16 UTC
Permalink
Hmmmmm. See no issue from my side:

root @ khorne /patch # wget -S http://www.msftconnecttest.com/ncsi.txt
--2017-05-02 19:16:11-- http://www.msftconnecttest.com/ncsi.txt
Connecting to 127.0.0.1:3128... connected.
Proxy request sent, awaiting response...
HTTP/1.1 200 OK
Cache-Control: max-age=30,must-revalidate
Content-Length: 14
Content-Type: text/plain
Last-Modified: Fri, 04 Mar 2016 06:55:23 GMT
ETag: "0x8D343F9F578A7F9"
Server: Microsoft-IIS/7.5
x-ms-request-id: 45e06e80-0001-000b-6f15-be91d0000000
x-ms-version: 2009-09-19
x-ms-meta-CbModifiedTime: Tue, 01 Mar 2016 21:41:22 GMT
x-ms-lease-status: unlocked
x-ms-blob-type: BlockBlob
X-ECN-P: RD0003FF838204
Access-Control-Expose-Headers: X-MSEdge-Ref
Access-Control-Allow-Origin: *
Timing-Allow-Origin: *
X-CID: 7
X-CCC: SE
X-MSEdge-Ref: Ref A: FFF0B969CF5F48DA856B48165D32542E Ref B:
STOEDGE0510 Ref C: Tue May 2 06:16:14 2017 PST
X-MSEdge-Ref-OriginShield: Ref A: 9D033F6C12734D3A839C09F1BAFF798E Ref
B: AMS04EDGE0220 Ref C: Thu Apr 27 07:42:11 2017 PST
Date: Tue, 02 May 2017 13:16:13 GMT
X-Cache: MISS from khorne
X-Cache-Lookup: MISS from khorne:3128
Connection: keep-alive
Length: 14 [text/plain]
Saving to: 'ncsi.txt'

ncsi.txt 100%[===================>] 14 --.-KB/s in
0s

2017-05-02 19:16:14 (2.07 MB/s) - 'ncsi.txt' saved [14/14]

root @ khorne /patch # wget -S http://www.msftconnecttest.com/ncsi.txt
--2017-05-02 19:16:32-- http://www.msftconnecttest.com/ncsi.txt
Connecting to 127.0.0.1:3128... connected.
Proxy request sent, awaiting response...
HTTP/1.1 200 OK
Cache-Control: max-age=30,must-revalidate
Content-Length: 14
Content-Type: text/plain
Last-Modified: Fri, 04 Mar 2016 06:55:23 GMT
ETag: "0x8D343F9F578A7F9"
Server: Microsoft-IIS/7.5
x-ms-request-id: 45e06e80-0001-000b-6f15-be91d0000000
x-ms-version: 2009-09-19
x-ms-meta-CbModifiedTime: Tue, 01 Mar 2016 21:41:22 GMT
x-ms-lease-status: unlocked
x-ms-blob-type: BlockBlob
X-ECN-P: RD0003FF838204
Access-Control-Expose-Headers: X-MSEdge-Ref
Access-Control-Allow-Origin: *
Timing-Allow-Origin: *
X-CID: 7
X-CCC: SE
X-MSEdge-Ref: Ref A: FFF0B969CF5F48DA856B48165D32542E Ref B:
STOEDGE0510 Ref C: Tue May 2 06:16:14 2017 PST
X-MSEdge-Ref-OriginShield: Ref A: 9D033F6C12734D3A839C09F1BAFF798E Ref
B: AMS04EDGE0220 Ref C: Thu Apr 27 07:42:11 2017 PST
X-Origin-Date: Tue, 02 May 2017 13:16:13 GMT
Date: Tue, 02 May 2017 13:16:32 GMT
X-Cache-Age: 19
X-Cache: HIT from khorne
X-Cache-Lookup: HIT from khorne:3128
Connection: keep-alive
Length: 14 [text/plain]
Saving to: 'ncsi.txt.1'

ncsi.txt.1 100%[===================>] 14 --.-KB/s in
0s

2017-05-02 19:16:32 (1.90 MB/s) - 'ncsi.txt.1' saved [14/14]

root @ khorne /patch # wget -S http://www.msftconnecttest.com/ncsi.txt
--2017-05-02 19:18:06-- http://www.msftconnecttest.com/ncsi.txt
Connecting to 127.0.0.1:3128... connected.
Proxy request sent, awaiting response...
HTTP/1.1 200 OK
Content-Length: 14
ETag: "0x8D343F9F578A7F9"
Cache-Control: max-age=30,must-revalidate
Content-Type: text/plain
Last-Modified: Fri, 04 Mar 2016 06:55:23 GMT
Server: Microsoft-IIS/7.5
x-ms-request-id: 45e06e80-0001-000b-6f15-be91d0000000
x-ms-version: 2009-09-19
x-ms-meta-CbModifiedTime: Tue, 01 Mar 2016 21:41:22 GMT
x-ms-lease-status: unlocked
x-ms-blob-type: BlockBlob
X-ECN-P: RD0003FF838204
Access-Control-Expose-Headers: X-MSEdge-Ref
Access-Control-Allow-Origin: *
Timing-Allow-Origin: *
X-CID: 7
X-CCC: SE
X-MSEdge-Ref: Ref A: 1F682D6F87124BF28456EB937B49B208 Ref B:
STOSCHEDGE0116 Ref C: Tue May 2 06:18:06 2017 PST
X-MSEdge-Ref-OriginShield: Ref A: 9D033F6C12734D3A839C09F1BAFF798E Ref
B: AMS04EDGE0220 Ref C: Thu Apr 27 07:42:11 2017 PST
Vary: Accept-Encoding
X-Origin-Date: Tue, 02 May 2017 13:18:05 GMT
Date: Tue, 02 May 2017 13:18:06 GMT
X-Cache-Age: 1
X-Cache: HIT from khorne
X-Cache-Lookup: HIT from khorne:3128
Connection: keep-alive
Length: 14 [text/plain]
Saving to: 'ncsi.txt.2'

ncsi.txt.2 100%[===================>] 14 --.-KB/s in
0s

2017-05-02 19:18:06 (2.03 MB/s) - 'ncsi.txt.2' saved [14/14]

Seems correct. Will dig more.
Post by Ralf Hildebrandt
Post by Ralf Hildebrandt
It seems that squid is returning an incorrect Content-Lenght: header
while the revalidation is still fresh/ongoing.
I haven't yet tried tcpdumping the response to check if the 14 bytes
do indeed contain the correct string.
And voila - here we go (Content-Length: 0 but squid sends 14 bytes of excess data: "Microsoft NCSI")
15:10:31.741436 IP proxy-cvk-1.charite.de.http-alt > vsw-it-nw-10.54228: Flags [P.], seq 1:952, ack 156, win 235, options [nop,nop,TS val 126939588 ecr 1696144349], length 951: HTTP: HTTP/1.1 200 OK
....e...HTTP/1.1 200 OK
Cache-Control: max-age=30,must-revalidate
Content-Length: 0
Content-Type: text/plain
Last-Modified: Fri, 04 Mar 2016 06:55:23 GMT
ETag: "0x8D343F9F578A7F9"
Server: Microsoft-IIS/7.5
x-ms-request-id: 6508a999-0001-0016-4fbc-c0483a000000
x-ms-version: 2009-09-19
x-ms-meta-CbModifiedTime: Tue, 01 Mar 2016 21:41:22 GMT
x-ms-lease-status: unlocked
x-ms-blob-type: BlockBlob
X-ECN-P: RD0003FF838204
Access-Control-Expose-Headers: X-MSEdge-Ref
Access-Control-Allow-Origin: *
Timing-Allow-Origin: *
X-CID: 7
X-CCC: US
X-MSEdge-Ref: Ref A: 2C6BD6F103A24795AE6784C3DC22E5F5 Ref B: BER30EDGE0115 Ref C: Tue May 2 06:10:31 2017 PST
X-MSEdge-Ref-OriginShield: Ref A: 5A9FC4FE82DC4E2DB26E51E59C50B50A Ref B: AMS04EDGE0506 Ref C: Sat Apr 29 05:30:12 2017 PST
Date: Tue, 02 May 2017 13:10:31 GMT
Age: 0
X-Cache: HIT from proxy-cvk-1
Via: 1.1 proxy-cvk-1 (squid/5.0.0-20170429-r15127)
Connection: keep-alive
Microsoft NCSI
15:10:31.741454 IP vsw-it-nw-10.54228 > proxy-cvk-1.charite.de.http-alt: Flags [.], ack 952, win 243, options [nop,nop,TS val 1696144352 ecr 126939588], length 0
e.......
--
Bugs to the Future
Ralf Hildebrandt
2017-05-02 13:29:32 UTC
Permalink
"Content-Length: 0", happens when Age ist either 0 or 1

$ wget -S http://www.msftconnecttest.com/ncsi.txt
--2017-05-02 15:27:28-- http://www.msftconnecttest.com/ncsi.txt
Auflösen des Hostnamens »proxy.charite.de (proxy.charite.de)« …
141.42.1.215
Verbindungsaufbau zu proxy.charite.de
(proxy.charite.de)|141.42.1.215|:8080 … verbunden.
Proxy-Anforderung gesendet, auf Antwort wird gewartet …
HTTP/1.1 200 OK
Cache-Control: max-age=30,must-revalidate
Content-Length: 0
Content-Type: text/plain
Last-Modified: Fri, 04 Mar 2016 06:55:23 GMT
ETag: "0x8D343F9F578A7F9"
Server: Microsoft-IIS/7.5
x-ms-request-id: 6508a999-0001-0016-4fbc-c0483a000000
x-ms-version: 2009-09-19
x-ms-meta-CbModifiedTime: Tue, 01 Mar 2016 21:41:22 GMT
x-ms-lease-status: unlocked
x-ms-blob-type: BlockBlob
X-ECN-P: RD0003FF838204
Access-Control-Expose-Headers: X-MSEdge-Ref
Access-Control-Allow-Origin: *
Timing-Allow-Origin: *
X-CID: 7
X-CCC: US
X-MSEdge-Ref: Ref A: AB76E69442AC44F496DBBD15A2132A90 Ref B: BER30EDGE0206 Ref C: Tue May 2 06:27:28 2017 PST
X-MSEdge-Ref-OriginShield: Ref A: 5A9FC4FE82DC4E2DB26E51E59C50B50A Ref B: AMS04EDGE0506 Ref C: Sat Apr 29 05:30:12 2017 PST
Date: Tue, 02 May 2017 13:27:27 GMT
Age: 1
X-Cache: HIT from proxy-cbf-1
Via: 1.1 proxy-cbf-1 (squid/5.0.0-20170429-r15127)
Connection: keep-alive
Länge: 0 [text/plain]
--
Ralf Hildebrandt Charite Universitätsmedizin Berlin
***@charite.de Campus Benjamin Franklin
https://www.charite.de Hindenburgdamm 30, 12203 Berlin
Geschäftsbereich IT, Abt. Netzwerk fon: +49-30-450.570.155
Loading...