Connection occasionally not ending after adapting response with ICAP

classic Classic list List threaded Threaded
7 messages Options
Reply | Threaded
Open this post in threaded view
|

Connection occasionally not ending after adapting response with ICAP

Moti Berger
I have a setup with squid 5.0.4 with ICAP server handling responses. The ICAP server redirects based on some parameters of the response.

To test this setup, I use cURL like this:
curl -k -s --proxy localhost:8000 -o /dev/null -v <URL>

Now, for some URLs, cURL hangs and for others it exits after receiving the 307 response.
When it hangs, I see this as the output of cURL (I removed what seemed to me as non-related logs from the beginning):
} [5 bytes data]
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
} [1 bytes data]
> GET / HTTP/1.1
> Host: www.one.co.il
> User-Agent: curl/7.58.0
> Accept: */*
>
{ [5 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [217 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [217 bytes data]
* TLSv1.3 (IN), TLS Unknown, Unknown (23):
{ [1 bytes data]
< HTTP/1.1 307 Temporary Redirect
< Location: <REDIRECTION-URL>
< Cache-Control: no-cache, no-store, must-revalidate
< Pragma: no-cache
< Date: Wed, 30 Dec 2020 13:58:51 GMT
< X-Cache: MISS from a0e59ea22cf8
< X-Cache-Lookup: MISS from a0e59ea22cf8:3128
< Transfer-Encoding: chunked
< Via: 1.1 a0e59ea22cf8 (squid/5.0.4)
< Connection: keep-alive

Using tcpdump I didn't see squid send any other ICAP requests (besides OPTIONS which the ICAP server replied to properly).
For some of the URLs where it hangs, I saw that running the same cURL command with the --compressed switch, makes cURL exit as expected:
} [5 bytes data]
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
} [1 bytes data]
> GET / HTTP/1.1
> Host: www.one.co.il
> User-Agent: curl/7.58.0
> Accept: */*
> Accept-Encoding: deflate, gzip
>
{ [5 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [217 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [217 bytes data]
* TLSv1.3 (IN), TLS Unknown, Unknown (23):
{ [1 bytes data]
< HTTP/1.1 307 Temporary Redirect
< Location: <REDIRECTION URL>
< Cache-Control: no-cache, no-store, must-revalidate
< Pragma: no-cache
< Date: Wed, 30 Dec 2020 14:00:31 GMT
< X-Cache: MISS from a0e59ea22cf8
< X-Cache-Lookup: MISS from a0e59ea22cf8:3128
< Transfer-Encoding: chunked
< Via: 1.1 a0e59ea22cf8 (squid/5.0.4)
< Connection: keep-alive
<
{ [5 bytes data]
* TLSv1.3 (IN), TLS Unknown, Unknown (23):
{ [1 bytes data]
* Connection #0 to host localhost left intact

When I skip the adaptation in REQMOD, I get the page and the connection is terminated.
When the ICAP works in REQMOD and redirects on the same URLs, everything seems to work properly.

What could make squid not to terminate the connection? Could it be that it still holds connection with the HTTP server?

Thanks

_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Connection occasionally not ending after adapting response with ICAP

Eliezer Croitoru-3
An icap tcpdump pcap file might help to understand something.

Eliezer

On Wed, Dec 30, 2020, 16:10 Moti Berger <[hidden email]> wrote:
I have a setup with squid 5.0.4 with ICAP server handling responses. The ICAP server redirects based on some parameters of the response.

To test this setup, I use cURL like this:
curl -k -s --proxy localhost:8000 -o /dev/null -v <URL>

Now, for some URLs, cURL hangs and for others it exits after receiving the 307 response.
When it hangs, I see this as the output of cURL (I removed what seemed to me as non-related logs from the beginning):
} [5 bytes data]
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
} [1 bytes data]
> GET / HTTP/1.1
> Host: www.one.co.il
> User-Agent: curl/7.58.0
> Accept: */*
>
{ [5 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [217 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [217 bytes data]
* TLSv1.3 (IN), TLS Unknown, Unknown (23):
{ [1 bytes data]
< HTTP/1.1 307 Temporary Redirect
< Location: <REDIRECTION-URL>
< Cache-Control: no-cache, no-store, must-revalidate
< Pragma: no-cache
< Date: Wed, 30 Dec 2020 13:58:51 GMT
< X-Cache: MISS from a0e59ea22cf8
< X-Cache-Lookup: MISS from a0e59ea22cf8:3128
< Transfer-Encoding: chunked
< Via: 1.1 a0e59ea22cf8 (squid/5.0.4)
< Connection: keep-alive

Using tcpdump I didn't see squid send any other ICAP requests (besides OPTIONS which the ICAP server replied to properly).
For some of the URLs where it hangs, I saw that running the same cURL command with the --compressed switch, makes cURL exit as expected:
} [5 bytes data]
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
} [1 bytes data]
> GET / HTTP/1.1
> Host: www.one.co.il
> User-Agent: curl/7.58.0
> Accept: */*
> Accept-Encoding: deflate, gzip
>
{ [5 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [217 bytes data]
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [217 bytes data]
* TLSv1.3 (IN), TLS Unknown, Unknown (23):
{ [1 bytes data]
< HTTP/1.1 307 Temporary Redirect
< Location: <REDIRECTION URL>
< Cache-Control: no-cache, no-store, must-revalidate
< Pragma: no-cache
< Date: Wed, 30 Dec 2020 14:00:31 GMT
< X-Cache: MISS from a0e59ea22cf8
< X-Cache-Lookup: MISS from a0e59ea22cf8:3128
< Transfer-Encoding: chunked
< Via: 1.1 a0e59ea22cf8 (squid/5.0.4)
< Connection: keep-alive
<
{ [5 bytes data]
* TLSv1.3 (IN), TLS Unknown, Unknown (23):
{ [1 bytes data]
* Connection #0 to host localhost left intact

When I skip the adaptation in REQMOD, I get the page and the connection is terminated.
When the ICAP works in REQMOD and redirects on the same URLs, everything seems to work properly.

What could make squid not to terminate the connection? Could it be that it still holds connection with the HTTP server?

Thanks
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users

_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Connection occasionally not ending after adapting response with ICAP

Alex Rousskov
In reply to this post by Moti Berger
On 12/30/20 9:09 AM, Moti Berger wrote:
> I have a setup with squid 5.0.4 with ICAP server handling responses.

FTR: This part seems to be about an ICAP RESPMOD service generating a
307 redirect (AFAICT).


> When it hangs, I see this as the output of cURL

>     > GET / HTTP/1.1
>     > Host: www.one.co.il <http://www.one.co.il>
>     > User-Agent: curl/7.58.0
>     > Accept: */*

>     < HTTP/1.1 307 Temporary Redirect
>     < Location: <REDIRECTION-URL>
>     < Cache-Control: no-cache, no-store, must-revalidate
>     < Pragma: no-cache
>     < Date: Wed, 30 Dec 2020 13:58:51 GMT
>     < X-Cache: MISS from a0e59ea22cf8
>     < X-Cache-Lookup: MISS from a0e59ea22cf8:3128
>     < Transfer-Encoding: chunked
>     < Via: 1.1 a0e59ea22cf8 (squid/5.0.4)
>     < Connection: keep-alive

Did curl receive the last-chunk from Squid? If not, did Squid received
the last-chunk from the ICAP service? See below for more details.


> For some of the URLs where it hangs, I saw that running the same cURL
> command with the --compressed switch, makes cURL exit as expected:

Squid ignores Accept-Encoding so the --compressed switch is not relevant
to Squid. Perhaps the ICAP service or the origin server react to it, but
the headers you have provided do not show any important differences:

>     > GET / HTTP/1.1
>     > Host: www.one.co.il <http://www.one.co.il>
>     > User-Agent: curl/7.58.0
>     > Accept: */*
>     > Accept-Encoding: deflate, gzip

>     < HTTP/1.1 307 Temporary Redirect
>     < Location: <REDIRECTION URL>
>     < Cache-Control: no-cache, no-store, must-revalidate
>     < Pragma: no-cache
>     < Date: Wed, 30 Dec 2020 14:00:31 GMT
>     < X-Cache: MISS from a0e59ea22cf8
>     < X-Cache-Lookup: MISS from a0e59ea22cf8:3128
>     < Transfer-Encoding: chunked
>     < Via: 1.1 a0e59ea22cf8 (squid/5.0.4)
>     < Connection: keep-alive

> When I skip the adaptation in REQMOD, I get the page and the connection
> is terminated.

... but REQMOD does not redirect when you do _not_ skip it, right? That
is, it is RESPMOD that always redirects (until a separate test below)?
If that is what happens, then it is possible that something goes wrong
inside the ICAP service, and turning off REQMOD that does not redirect
fixes the redirect in RESPMOD. However, it is a bit difficult for me to
follow the REQMOD/RESPMOD roles in your email so I may be
misunderstanding something.


> When the ICAP works in REQMOD and redirects on the same URLs, everything
> seems to work properly.

OK. Redirection in REQMOD is quite a different beast -- a lot of things
change, on both Squid and ICAP sides.


> What could make squid not to terminate the connection? Could it be that
> it still holds connection with the HTTP server?

The actual question here is not about the connections but about the
messages inside those connections. It sounds like Squid does not send
the entire redirect response body to curl in some cases. _That_ could be
caused by the ICAP service not sending the entire redirect response body
to Squid.

You can probably confirm or deny the last bit by looking at ICAP traffic
in wireshark. Does the ICAP response contain the last-chunk (which is
usually the "0 CR LF CR LF" sequence in the chunked-encoded message body)?

* If the last-chunk is missing, then Squid is waiting for the ICAP
service. I do not know what the ICAP RESPMOD service is waiting for, but
it could be the last-chunk of the virgin HTTP response that Squid is
supposed to send to the RESPMOD service. Wireshark should show that
exchange as well.

* Otherwise, it could be a Squid bug -- post a link to a compressed
ALL,9 cache.log of the problematic transaction as discussed at
https://wiki.squid-cache.org/SquidFaq/BugReporting#Debugging_a_single_transaction


HTH,

Alex.
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Connection occasionally not ending after adapting response with ICAP

Moti Berger


On Wed, Dec 30, 2020 at 4:54 PM Alex Rousskov <[hidden email]> wrote:
On 12/30/20 9:09 AM, Moti Berger wrote:
> I have a setup with squid 5.0.4 with ICAP server handling responses.

FTR: This part seems to be about an ICAP RESPMOD service generating a
307 redirect (AFAICT).


> When it hangs, I see this as the output of cURL

>     > GET / HTTP/1.1
>     > Host: www.one.co.il <http://www.one.co.il>
>     > User-Agent: curl/7.58.0
>     > Accept: */*

>     < HTTP/1.1 307 Temporary Redirect
>     < Location: <REDIRECTION-URL>
>     < Cache-Control: no-cache, no-store, must-revalidate
>     < Pragma: no-cache
>     < Date: Wed, 30 Dec 2020 13:58:51 GMT
>     < X-Cache: MISS from a0e59ea22cf8
>     < X-Cache-Lookup: MISS from a0e59ea22cf8:3128
>     < Transfer-Encoding: chunked
>     < Via: 1.1 a0e59ea22cf8 (squid/5.0.4)
>     < Connection: keep-alive

Did curl receive the last-chunk from Squid? If not, did Squid received
the last-chunk from the ICAP service? See below for more details.


> For some of the URLs where it hangs, I saw that running the same cURL
> command with the --compressed switch, makes cURL exit as expected:

Squid ignores Accept-Encoding so the --compressed switch is not relevant
to Squid. Perhaps the ICAP service or the origin server react to it, but
the headers you have provided do not show any important differences:

>     > GET / HTTP/1.1
>     > Host: www.one.co.il <http://www.one.co.il>
>     > User-Agent: curl/7.58.0
>     > Accept: */*
>     > Accept-Encoding: deflate, gzip

>     < HTTP/1.1 307 Temporary Redirect
>     < Location: <REDIRECTION URL>
>     < Cache-Control: no-cache, no-store, must-revalidate
>     < Pragma: no-cache
>     < Date: Wed, 30 Dec 2020 14:00:31 GMT
>     < X-Cache: MISS from a0e59ea22cf8
>     < X-Cache-Lookup: MISS from a0e59ea22cf8:3128
>     < Transfer-Encoding: chunked
>     < Via: 1.1 a0e59ea22cf8 (squid/5.0.4)
>     < Connection: keep-alive

> When I skip the adaptation in REQMOD, I get the page and the connection
> is terminated.

... but REQMOD does not redirect when you do _not_ skip it, right? That
is, it is RESPMOD that always redirects (until a separate test below)?
If that is what happens, then it is possible that something goes wrong
inside the ICAP service, and turning off REQMOD that does not redirect
fixes the redirect in RESPMOD. However, it is a bit difficult for me to
follow the REQMOD/RESPMOD roles in your email so I may be
misunderstanding something.

>>> My ICAP server handles both REQMOD and RESPMOD. I can switch on and off
the adaptation in both modes. The adaptation, when take place, is to do redirects.
So, for example, when I turn on the adaptation in REQMOD, meaning, redirecting,
the connection terminates like expected.
When the adaptation in REQMOD is turned off (meaning, the ICAP server still receives
requests to modify, but it doesn't change them), and RESPMOD is turned on and
adaptation occurs (meaning, redirecting) for some URLs, it get stuck and for some it doesn't.
Regarding no adaptation in REQMOD that might affect the RESPMOD, I removed from
squid.conf the related configs and the issue persists.
 

> When the ICAP works in REQMOD and redirects on the same URLs, everything
> seems to work properly.

OK. Redirection in REQMOD is quite a different beast -- a lot of things
change, on both Squid and ICAP sides.


> What could make squid not to terminate the connection? Could it be that
> it still holds connection with the HTTP server?

The actual question here is not about the connections but about the
messages inside those connections. It sounds like Squid does not send
the entire redirect response body to curl in some cases. _That_ could be
caused by the ICAP service not sending the entire redirect response body
to Squid.

You can probably confirm or deny the last bit by looking at ICAP traffic
in wireshark. Does the ICAP response contain the last-chunk (which is
usually the "0 CR LF CR LF" sequence in the chunked-encoded message body)?

>>> I don't see the "0 CR LF CR LF" at all, not only for those URLs that cause the curl to hang.
* If the last-chunk is missing, then Squid is waiting for the ICAP
service. I do not know what the ICAP RESPMOD service is waiting for, but
it could be the last-chunk of the virgin HTTP response that Squid is
supposed to send to the RESPMOD service. Wireshark should show that
exchange as well.

>>> I'm attaching a tcpdump file. 

* Otherwise, it could be a Squid bug -- post a link to a compressed
ALL,9 cache.log of the problematic transaction as discussed at
https://wiki.squid-cache.org/SquidFaq/BugReporting#Debugging_a_single_transaction


HTH,

Alex.

_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users

squid_icap_tcpdump (4K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Connection occasionally not ending after adapting response with ICAP

Alex Rousskov
On 12/30/20 10:40 AM, Moti Berger wrote:

>>>> I don't see the "0 CR LF CR LF" at all, not only for those URLs that
> cause the curl to hang.

I suspect that none of those ICAP responses have HTTP bodies. An ICAP
response without an HTTP body, in itself, is not a bug, but it probably
explains the problem you are having. See below for more details.


> I'm attaching a tcpdump file.

FWIW, my wireshark cannot read your packet capture file: "The capture
file appears to be damaged or corrupt. File has 1852785440-byte packet,
bigger than maximum of 262144". In the future, you should compress such
files before sharing them via email.

However, looking at the ASCII parts of that capture file, I probably see
the likely culprit. The ICAP response below can be considered invalid
or, at least, rather difficult to handle correctly:

> ICAP/1.0 200 OK
> ISTag: "tmrCy72n1Qgsn1mxBipIb4jdEYdce3"
> Date: Wed, 30 Dec 2020 15:07:52 GMT
> Server: BaseICAP/1.0 Python/3.6.12
> Encapsulated: res-hdr=0, null-body=140
>
> HTTP/1.1 307 Temporary Redirect
> location: http://www.redirect.url
> Cache-Control: no-cache, no-store, must-revalidate
> Pragma: no-cache


The HTTP 307 response header sent by the ICAP server promises an HTTP
response body (per HTTP rules), but the ICAP response has no HTTP body
(per the "null-body" value in the Encapsulated header).

I do not remember what Squid does in this problematic case, but I
suspect the outcome is a stuck HTTP transaction.

You should fix the ICAP service to either stop promising an HTTP
response body or provide one. The easiest (but ugly) fix may be to add
Content-Length:0 to the HTTP header returned by the ICAP service. A
better fix would be to include a real body that explains why the request
was redirected or provides some reference to the corresponding decision,
for triage.


HTH,

Alex.
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Connection occasionally not ending after adapting response with ICAP

Moti Berger
I'm sorry for the bad format and for the uncompressed file.
Indeed adding a Content-Length:0 solved the issue.
This is BTW the preferred way for me since the URL I'm redirecting to explains
why the redirection occurred. 

Thanks a lot for your help.

On Wed, Dec 30, 2020 at 6:48 PM Alex Rousskov <[hidden email]> wrote:
On 12/30/20 10:40 AM, Moti Berger wrote:

>>>> I don't see the "0 CR LF CR LF" at all, not only for those URLs that
> cause the curl to hang.

I suspect that none of those ICAP responses have HTTP bodies. An ICAP
response without an HTTP body, in itself, is not a bug, but it probably
explains the problem you are having. See below for more details.


> I'm attaching a tcpdump file.

FWIW, my wireshark cannot read your packet capture file: "The capture
file appears to be damaged or corrupt. File has 1852785440-byte packet,
bigger than maximum of 262144". In the future, you should compress such
files before sharing them via email.

However, looking at the ASCII parts of that capture file, I probably see
the likely culprit. The ICAP response below can be considered invalid
or, at least, rather difficult to handle correctly:

> ICAP/1.0 200 OK
> ISTag: "tmrCy72n1Qgsn1mxBipIb4jdEYdce3"
> Date: Wed, 30 Dec 2020 15:07:52 GMT
> Server: BaseICAP/1.0 Python/3.6.12
> Encapsulated: res-hdr=0, null-body=140
>
> HTTP/1.1 307 Temporary Redirect
> location: http://www.redirect.url
> Cache-Control: no-cache, no-store, must-revalidate
> Pragma: no-cache


The HTTP 307 response header sent by the ICAP server promises an HTTP
response body (per HTTP rules), but the ICAP response has no HTTP body
(per the "null-body" value in the Encapsulated header).

I do not remember what Squid does in this problematic case, but I
suspect the outcome is a stuck HTTP transaction.

You should fix the ICAP service to either stop promising an HTTP
response body or provide one. The easiest (but ugly) fix may be to add
Content-Length:0 to the HTTP header returned by the ICAP service. A
better fix would be to include a real body that explains why the request
was redirected or provides some reference to the corresponding decision,
for triage.


HTH,

Alex.

_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Connection occasionally not ending after adapting response with ICAP

Alex Rousskov
On 12/31/20 7:14 AM, Moti Berger wrote:
> Indeed adding a Content-Length:0 solved the issue.
> This is BTW the preferred way for me since the URL I'm redirecting to
> explains why the redirection occurred.

FYI: You probably assume that the user agent will automatically follow
the redirect URL. That is usually the case, but there are exceptions. It
is best to provide some basic information (like a contact link and
transaction ID) in the response body. It also helps in triage.

Glad you found a solution.

Alex.


> On Wed, Dec 30, 2020 at 6:48 PM Alex Rousskov wrote:
>
>     On 12/30/20 10:40 AM, Moti Berger wrote:
>
>     >>>> I don't see the "0 CR LF CR LF" at all, not only for those URLs
>     that
>     > cause the curl to hang.
>
>     I suspect that none of those ICAP responses have HTTP bodies. An ICAP
>     response without an HTTP body, in itself, is not a bug, but it probably
>     explains the problem you are having. See below for more details.
>
>
>     > I'm attaching a tcpdump file.
>
>     FWIW, my wireshark cannot read your packet capture file: "The capture
>     file appears to be damaged or corrupt. File has 1852785440-byte packet,
>     bigger than maximum of 262144". In the future, you should compress such
>     files before sharing them via email.
>
>     However, looking at the ASCII parts of that capture file, I probably see
>     the likely culprit. The ICAP response below can be considered invalid
>     or, at least, rather difficult to handle correctly:
>
>     > ICAP/1.0 200 OK
>     > ISTag: "tmrCy72n1Qgsn1mxBipIb4jdEYdce3"
>     > Date: Wed, 30 Dec 2020 15:07:52 GMT
>     > Server: BaseICAP/1.0 Python/3.6.12
>     > Encapsulated: res-hdr=0, null-body=140
>     >
>     > HTTP/1.1 307 Temporary Redirect
>     > location: http://www.redirect.url
>     > Cache-Control: no-cache, no-store, must-revalidate
>     > Pragma: no-cache
>
>
>     The HTTP 307 response header sent by the ICAP server promises an HTTP
>     response body (per HTTP rules), but the ICAP response has no HTTP body
>     (per the "null-body" value in the Encapsulated header).
>
>     I do not remember what Squid does in this problematic case, but I
>     suspect the outcome is a stuck HTTP transaction.
>
>     You should fix the ICAP service to either stop promising an HTTP
>     response body or provide one. The easiest (but ugly) fix may be to add
>     Content-Length:0 to the HTTP header returned by the ICAP service. A
>     better fix would be to include a real body that explains why the request
>     was redirected or provides some reference to the corresponding decision,
>     for triage.
>
>
>     HTH,
>
>     Alex.
>

_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users