[squid-users] Fail and empty response instead cached resource

Tue Jan 21 09:36:25 UTC 2020

Hello

I run Squid 4.9 in non transparent mode with OPNsense (FreeBSD 
11.2-RELEASE-p16-HBSD FreeBSD 11.2-RELEASE-p16-HBSD 
87a7fc985c3(stable/19.7)  amd64).

Everything works except access to one website.

Squid startup log is clean:

> 2020/01/21 13:56:43 kid1| Startup: Initializing Authentication Schemes ...
> 2020/01/21 13:56:43 kid1| Startup: Initialized Authentication Scheme 
> 'basic'
> 2020/01/21 13:56:43 kid1| Startup: Initialized Authentication Scheme 
> 'digest'
> 2020/01/21 13:56:43 kid1| Startup: Initialized Authentication Scheme 
> 'negotiate'
> 2020/01/21 13:56:43 kid1| Startup: Initialized Authentication Scheme 
> 'ntlm'
> 2020/01/21 13:56:43 kid1| Startup: Initialized Authentication.
> 2020/01/21 13:56:43 kid1| Processing Configuration File: 
> /usr/local/etc/squid/squid.conf (depth 0)
> 2020/01/21 13:56:43 kid1| Processing Configuration File: 
> /usr/local/etc/squid/pre-auth/40-snmp.conf (depth 1)
> 2020/01/21 13:56:43 kid1| Processing Configuration File: 
> /usr/local/etc/squid/pre-auth/dummy.conf (depth 1)
> 2020/01/21 13:56:43 kid1| Processing Configuration File: 
> /usr/local/etc/squid/pre-auth/parentproxy.conf (depth 1)
> 2020/01/21 13:56:43 kid1| Processing Configuration File: 
> /usr/local/etc/squid/auth/ProxyUserACL.conf (depth 1)
> 2020/01/21 13:56:43 kid1| Processing Configuration File: 
> /usr/local/etc/squid/auth/dummy.conf (depth 1)
> 2020/01/21 13:56:43 kid1| Processing Configuration File: 
> /usr/local/etc/squid/post-auth/dummy.conf (depth 1)
> 2020/01/21 13:56:43 kid1| Initializing https:// proxy context
> 2020/01/21 13:56:43 kid1| Logfile: opening log 
> stdio:/var/log/squid/access.log
> 2020/01/21 13:56:43 kid1| Squid plugin modules loaded: 0
> 2020/01/21 13:56:43 kid1| Adaptation support is off.
> 2020/01/21 13:56:43 kid1| Logfile: opening log 
> stdio:/var/log/squid/store.log
> 2020/01/21 13:56:43 kid1| DNS Socket created at [::], FD 9
> 2020/01/21 13:56:43 kid1| DNS Socket created at 0.0.0.0, FD 11
> 2020/01/21 13:56:43 kid1| Adding nameserver 127.0.0.1 from squid.conf
> 2020/01/21 13:56:43 kid1| HTCP Disabled.
> 2020/01/21 13:56:43 kid1| Pinger socket opened on FD 15
> 2020/01/21 13:56:43 kid1| Finished loading MIME types and icons.
> 2020/01/21 13:56:43 kid1| Accepting HTTP Socket connections at 
> local=192.168.0.4:3128 remote=[::] FD 12 flags=9
> 2020/01/21 13:56:43| pinger: Initialising ICMP pinger ...
> 2020/01/21 13:56:43| pinger: ICMP socket opened.
> 2020/01/21 13:56:43| pinger: ICMPv6 socket opened
> 2020/01/21 13:59:54 kid1| Logfile: opening log 
> stdio:/var/squid/cache/netdb.state
> 2020/01/21 13:59:54 kid1| Logfile: closing log 
> stdio:/var/squid/cache/netdb.state
> 2020/01/21 13:59:54 kid1| NETDB state saved; 680 entries, 7 msec

When I make a request for the first time, everything is fine and I get 
correct result.

> curl --proxy 192.168.0.4:3128 -v -O 
> http://tehspb.kodeks.ru/js/jquery-1.4.2.min.js
> * STATE: INIT => CONNECT handle 0x600092d68; line 1491 (connection #-5000)
> * Added connection 0. The cache now contains 1 members
> *   Trying 192.168.0.4:3128...
> * TCP_NODELAY set
> * STATE: CONNECT => WAITCONNECT handle 0x600092d68; line 1547 
> (connection #0)
> * Connected to 192.168.0.4 (192.168.0.4) port 3128 (#0)
> * STATE: WAITCONNECT => SENDPROTOCONNECT handle 0x600092d68; line 1665 
> (connection #0)
> * Marked for [keep alive]: HTTP default
> * STATE: SENDPROTOCONNECT => DO handle 0x600092d68; line 1685 
> (connection #0)
> > GET http://tehspb.kodeks.ru/js/jquery-1.4.2.min.js HTTP/1.1
> > Host: tehspb.kodeks.ru
> > User-Agent: curl/7.67.0
> > Accept: */*
> > Proxy-Connection: Keep-Alive
> >
> * STATE: DO => DO_DONE handle 0x600092d68; line 1756 (connection #0)
> * STATE: DO_DONE => PERFORM handle 0x600092d68; line 1877 (connection #0)
> * Mark bundle as not supporting multiuse
> * HTTP 1.1 or later with persistent connection
> < HTTP/1.1 200 OK
> < Server: nginx/1.4.6 (Ubuntu)
> < Date: Tue, 21 Jan 2020 07:10:43 GMT
> < Content-Type: text/javascript; charset=UTF-8
> < Content-Length: 72175
> < X-PaperRoute: Node
> < ETag: "800439-72175-1534779018000"
> < Last-Modified: Mon, 20 Aug 2018 15:30:18 GMT
> < Access-Control-Allow-Origin: *
> < Cache-Control: no-cache
> < X-Cache: MISS from opnsense.lan
> < X-Cache-Lookup: MISS from opnsense.lan:3128
> < Via: 1.1 opnsense.lan (squid/4.9)
> < Connection: keep-alive
> <
> { [1460 bytes data]
> * STATE: PERFORM => DONE handle 0x600092d68; line 2067 (connection #0)
> * multi_done
> 100 72175  100 72175    0     0   175k      0 --:--:-- --:--:-- 
> --:--:--  176k
> * Connection #0 to host 192.168.0.4 left intact
Squid access log:
> 2020/01/21 12:10:43     184 192.168.0.5 TCP_MISS/200 72647 GET 
> http://tehspb.kodeks.ru/js/jquery-1.4.2.min.js - 
> HIER_DIRECT/5.61.15.55 text/javascript

However, all subsequent requests fail and return an empty response.

> curl --proxy 192.168.0.4:3128 -v -O 
> http://tehspb.kodeks.ru/js/jquery-1.4.2.min.js
> * STATE: INIT => CONNECT handle 0x600092d68; line 1491 (connection #-5000)
> * Added connection 0. The cache now contains 1 members
> *   Trying 192.168.0.4:3128...
> * TCP_NODELAY set
> * STATE: CONNECT => WAITCONNECT handle 0x600092d68; line 1547 
> (connection #0)
> * Connected to 192.168.0.4 (192.168.0.4) port 3128 (#0)
> * STATE: WAITCONNECT => SENDPROTOCONNECT handle 0x600092d68; line 1665 
> (connection #0)
> * Marked for [keep alive]: HTTP default
> * STATE: SENDPROTOCONNECT => DO handle 0x600092d68; line 1685 
> (connection #0)
> > GET http://tehspb.kodeks.ru/js/jquery-1.4.2.min.js HTTP/1.1
> > Host: tehspb.kodeks.ru
> > User-Agent: curl/7.67.0
> > Accept: */*
> > Proxy-Connection: Keep-Alive
> >
> * STATE: DO => DO_DONE handle 0x600092d68; line 1756 (connection #0)
> * STATE: DO_DONE => PERFORM handle 0x600092d68; line 1877 (connection #0)
> * Mark bundle as not supporting multiuse
> * HTTP 1.1 or later with persistent connection
> < HTTP/1.1 200 OK
> < Server: nginx/1.4.6 (Ubuntu)
> < Date: Tue, 21 Jan 2020 07:14:20 GMT
> < Content-Type: text/javascript; charset=UTF-8
> < Content-Length: 0
> < X-PaperRoute: Node
> < ETag: "800439-72175-1534779018000"
> < Last-Modified: Mon, 20 Aug 2018 15:30:18 GMT
> < Access-Control-Allow-Origin: *
> < Cache-Control: no-cache
> < Age: 0
> < X-Cache: HIT from opnsense.lan
> < X-Cache-Lookup: HIT from opnsense.lan:3128
> < Via: 1.1 opnsense.lan (squid/4.9)
> < Connection: keep-alive
> <
> * Excess found: excess = 986 url = /js/jquery-1.4.2.min.js 
> (zero-length body)
> * STATE: PERFORM => DONE handle 0x600092d68; line 2067 (connection #0)
> * multi_done
>   0     0    0     0    0     0      0      0 --:--:-- --:--:-- 
> --:--:--     0
> * Connection #0 to host 192.168.0.4 left intact
> * Expire cleared (transfer 0x600092d68)

Squid access log:

> 2020/01/21 12:14:20     102 192.168.0.5 
> TCP_REFRESH_UNMODIFIED_ABORTED/200 65672 GET 
> http://tehspb.kodeks.ru/js/jquery-1.4.2.min.js - 
> HIER_DIRECT/5.61.15.55 text/javascript

Direct access without proxy works so this is not network issue. I 
thought it was a server setup problem but support guy say they have 
thousands of customers and everything's fine :-) Maybe someone has faced 
similar problems?