Re: [squid-users] squid 3.2.1 proxying but not caching requests made from an origin server when used as an accelerator

From: Amos Jeffries <squid3_at_treenet.co.nz>
Date: Sat, 06 Oct 2012 01:01:00 +1300

On 5/10/2012 4:31 p.m., Dan Moore wrote:
> Hi folks,
>
> I'm running into an issue with a squid setup and wanted to see if
> anyone had any ideas about what I'm doing wrong. I am using squid
> 3.2.1 which I built from source with the default configuration
> options.
>
> We are using squid as an accelerator, to cache queries against several
> different REST APIs on different servers. The issue is that while the
> results are being proxied just fine, they aren't being cached. We
> want squid in the middle for performance and access control.
>
> Here's one request in the access log:
> 67.190.6.171 - - [04/Oct/2012:20:25:15 -0600] "GET
> http://qa-api.8z.com/api/v1/neighborhood/11344 HTTP/1.1" 200 1186 "-"
> "curl/7.24.0 (i686-pc-cygwin) libcurl/7.24.0 OpenSSL/1.0.1c zlib/1.2.7
> libidn/1.22 libssh2/1.4.0" TCP_MISS:FIRSTUP_PARENT
>
> Here's the command I'm using to retrieve the resource: curl
> http://qa-api.8z.com/api/v1/neighborhood/11344
>
> No matter how often I retrieve the resource, I still get that
> TCP_MISS:FIRSTUP_PARENT in the access log.
>
> Here's the relevant section of the config (at least what I think is
> the relevant section, full squid.conf below):
> ------------------
> http_access allow api_sites
> http_access deny all
> http_port 80 accel vhost
> cache_peer 74.86.206.124 parent 80 0 no-query originserver
> name=terabitz8z forceddomain=qa-8z.kwetoo.com
> acl neighborhood_api urlpath_regex ^/api/v1/neighborhood
> cache_peer_access terabitz8z allow neighborhood_api
> cache_peer_access terabitz8z deny all
> ------------------
>
> Below is the cache log for one of the requests, with the debugging set
> to 2. I'd love to hear any suggestions on which sections of source
> code I should set to higher debugging levels (based on this table:
> http://wiki.squid-cache.org/KnowledgeBase/DebugSections ). Nothing
> jumps out at me when I read it.
>
> Nothing bad appears to happen when I bounce squid. Tried playing with
> the cache_peer line: no-digest and it didn't seem to help. Looked at
> http_port options, but nothing seemed to apply.
>
> I confirmed that the squid cache directories are writable by the
> nobody user. I have set it up against another host and the 'Vary:
> Accept-Encoding' header seemed to cause the issue. However, I can't
> see why? It's not like the Vary: header includes user-agent or
> anything like that.
>
> By the way, the API is managed by a third party, so I can request that
> header fields be removed, but am not guaranteed it will be possible.
>
> When I make the request, I see there is a new file in the cache dir:
> /usr/local/squid/var/cache/squid/00/00/00000004 and the contents of
> that file are the requested information. And each time I make the
> request, that same file gets saved again, but has a new timestamp.
> This makes me think that I have something misconfigured?

I can't see anything misconfigured, and the HTTP headers look like they
should be cached for up to 2hrs.
Very strange.

The empty Pragma: header should not be there at all but that should not
affect caching.

Amos

>
> Here's the timestamps of that cache file after I make three separate
> curl requests each one minute apart:
>
> ------------------
> [mooreds_at_proxy-stage1 ~]$ sudo ls -l
> /usr/local/squid/var/cache/squid/00/00/00000004
> -rw-r----- 1 nobody nobody 1287 Oct 4 21:14
> /usr/local/squid/var/cache/squid/00/00/00000004
> [mooreds_at_proxy-stage1 ~]$ sudo ls -l
> /usr/local/squid/var/cache/squid/00/00/00000004
> -rw-r----- 1 nobody nobody 1287 Oct 4 21:15
> /usr/local/squid/var/cache/squid/00/00/00000004
> [mooreds_at_proxy-stage1 ~]$ sudo ls -l
> /usr/local/squid/var/cache/squid/00/00/00000004
> -rw-r----- 1 nobody nobody 1287 Oct 4 21:16
> /usr/local/squid/var/cache/squid/00/00/00000004
> ------------------
>
> Any help would be appreciated. Should I review my configuration file?
> Ask to have headers removed? Play around with the caching setup
> using an origin server control? Resources I should read? I spent
> most of the afternoon looking around on the internet, playing with
> different settings and servers, and seem to have hit a brick wall.
>
> Thanks so much for any help.
>
> Dan Moore
>
> cache.log
> ------------------------------------
>
> 2012/10/04 20:25:15.118 kid1| TcpAcceptor.cc(188) doAccept: New
> connection on FD 16
> 2012/10/04 20:25:15.118 kid1| TcpAcceptor.cc(263) acceptNext:
> connection on local=[::]:80 remote=[::] FD 16 flags=9
> 2012/10/04 20:25:15.844 kid1| HTTP Client local=65.38.188.183:80
> remote=67.190.6.171:61991 FD 12 flags=1
> 2012/10/04 20:25:15.844 kid1| HTTP Client REQUEST:
> ---------
> GET /api/v1/neighborhood/11344 HTTP/1.1
> User-Agent: curl/7.24.0 (i686-pc-cygwin) libcurl/7.24.0 OpenSSL/1.0.1c
> zlib/1.2.7 libidn/1.22 libssh2/1.4.0
> Host: qa-api.8z.com
> Accept: */*
>
>
> ----------
> 2012/10/04 20:25:15.844 kid1| The request GET
> http://qa-api.8z.com/api/v1/neighborhood/11344 is 1, because it
> matched 'api_sites'
> 2012/10/04 20:25:15.844 kid1| client_side_request.cc(734)
> clientAccessCheck2: No adapted_http_access configuration. default:
> ALLOW
> 2012/10/04 20:25:15.844 kid1| The request GET
> http://qa-api.8z.com/api/v1/neighborhood/11344 is 1, because it
> matched 'api_sites'
> 2012/10/04 20:25:15.844 kid1| forward.cc(103) FwdState: Forwarding
> client request local=65.38.188.183:80 remote=67.190.6.171:61991 FD 12
> flags=1, url=http://qa-api.8z.com/api/v1/neighborhood/11344
> 2012/10/04 20:25:15.844 kid1| aclRegexData::match: match
> '(^/api/v1/neighborhood)' found in '/api/v1/neighborhood/11344'
> 2012/10/04 20:25:15.844 kid1| aclRegexData::match: match
> '(^/api/v1/neighborhood)' found in '/api/v1/neighborhood/11344'
> 2012/10/04 20:25:15.844 kid1| Find IP destination for:
> http://qa-api.8z.com/api/v1/neighborhood/11344' via 74.86.206.124
> 2012/10/04 20:25:15.844 kid1| Find IP destination for:
> http://qa-api.8z.com/api/v1/neighborhood/11344' via 74.86.206.124
> 2012/10/04 20:25:15.844 kid1| Found sources for
> 'http://qa-api.8z.com/api/v1/neighborhood/11344'
> 2012/10/04 20:25:15.844 kid1| always_direct = 0
> 2012/10/04 20:25:15.844 kid1| never_direct = 0
> 2012/10/04 20:25:15.844 kid1| cache_peer = local=0.0.0.0
> remote=74.86.206.124:80 flags=1
> 2012/10/04 20:25:15.844 kid1| cache_peer = local=0.0.0.0
> remote=74.86.206.124:80 flags=1
> 2012/10/04 20:25:15.844 kid1| timedout = 0
> 2012/10/04 20:25:15.861 kid1| HTTP Server local=65.38.188.183:37032
> remote=74.86.206.124:80 FD 14 flags=1
> 2012/10/04 20:25:15.861 kid1| HTTP Server REQUEST:
> ---------
> GET /api/v1/neighborhood/11344 HTTP/1.1
> User-Agent: curl/7.24.0 (i686-pc-cygwin) libcurl/7.24.0 OpenSSL/1.0.1c
> zlib/1.2.7 libidn/1.22 libssh2/1.4.0
> Host: qa-8z.kwetoo.com
> Accept: */*
> Via: 1.1 proxy-stage1.chfops.net (squid/3.2.1)
> Surrogate-Capability: proxy-stage1.chfops.net="Surrogate/1.0"
> X-Forwarded-For: 67.190.6.171
> Cache-Control: max-age=259200
> Connection: keep-alive
>
>
> ----------
> 2012/10/04 20:25:15.903 kid1| ctx: enter level 0:
> 'http://qa-api.8z.com/api/v1/neighborhood/11344'
> 2012/10/04 20:25:15.903 kid1| HTTP Server local=65.38.188.183:37032
> remote=74.86.206.124:80 FD 14 flags=1
> 2012/10/04 20:25:15.903 kid1| HTTP Server REPLY:
> ---------
> HTTP/1.1 200 OK
> Date: Fri, 05 Oct 2012 02:33:28 GMT
> Server: Apache/2.2.21 (Unix) DAV/2 mod_ssl/2.2.21 OpenSSL/1.0.0c
> PHP/5.3.8 mod_apreq2-20090110/2.7.1 mod_perl/2.0.5 Perl/v5.10.1
> X-Powered-By: PHP/5.3.8
> Set-Cookie: PHPSESSID=aj7ehqh9rr98uodpq528g3hvs0; path=/
> Expires: Fri, 05 Oct 2012 04:33:28 GMT
> Cache-Control: max-age=7200
> Pragma:
> Vary: Accept-Encoding
> Content-Length: 638
> Keep-Alive: timeout=5, max=100
> Connection: Keep-Alive
> Content-Type: application/x-javascript
>
> {"error":null,"data":[{"id":11344,"name":"rogers-park","displayName":"Rogers
> Park","city":"Fort
> Collins","region":"northern-colorado","state":"CO","assignedRealtor":null,"description":"","extraDescription":"","rssFeed":null,"flickrFeed":"fortcollinsrogerspark","pageTitle":"","pageDescription":"","pageKeywords":"","mapPolygon":[[40.58197000000001,-105.11509],[40.58219,-105.1315],[40.58182,-105.13373],[40.57874,-105.13378],[40.57501000000001,-105.13373],[40.57477,-105.11612],[40.57461,-105.11512],[40.58197000000001,-105.11509]],"url":"\/neighborhoods\/CO\/fort-collins\/rogers-park","latitude":"40.578405","longitude":"-105.124428"}]}
> ----------
> 2012/10/04 20:25:15.903 kid1| ctx: exit level 0
> 2012/10/04 20:25:15.903 kid1| The reply for GET
> http://qa-api.8z.com/api/v1/neighborhood/11344 is 1, because it
> matched 'neighborhood_api'
> 2012/10/04 20:25:15.904 kid1| HTTP Client local=65.38.188.183:80
> remote=67.190.6.171:61991 FD 12 flags=1
> 2012/10/04 20:25:15.904 kid1| HTTP Client REPLY:
> ---------
> HTTP/1.1 200 OK
> Date: Fri, 05 Oct 2012 02:33:28 GMT
> Server: Apache/2.2.21 (Unix) DAV/2 mod_ssl/2.2.21 OpenSSL/1.0.0c
> PHP/5.3.8 mod_apreq2-20090110/2.7.1 mod_perl/2.0.5 Perl/v5.10.1
> X-Powered-By: PHP/5.3.8
> Set-Cookie: PHPSESSID=aj7ehqh9rr98uodpq528g3hvs0; path=/
> Expires: Fri, 05 Oct 2012 04:33:28 GMT
> Cache-Control: max-age=7200
> Pragma:
> Vary: Accept-Encoding
> Content-Length: 638
> Content-Type: application/x-javascript
> X-Cache: MISS from proxy-stage1.chfops.net
> Via: 1.1 proxy-stage1.chfops.net (squid/3.2.1)
> Connection: keep-alive
>
>
> ----------
> 2012/10/04 20:25:15.904 kid1| storeCreate: Selected dir 0 for -1_at_-1=0/2/0/1
> 2012/10/04 20:25:16.024 kid1| client_side.cc(764) swanSong:
> local=65.38.188.183:80 remote=67.190.6.171:61991 flags=1
>
> ------------------------------------
>
>
>
>
> squid.conf
> ------------------------------------
>
> acl localnet src 10.0.0.0/8 # RFC1918 possible internal network
> acl localnet src 172.16.0.0/12 # RFC1918 possible internal network
> acl localnet src 192.168.0.0/16 # RFC1918 possible internal network
> acl localnet src fc00::/7 # RFC 4193 local private network range
> acl localnet src fe80::/10 # RFC 4291 link-local (directly
> plugged) machines
> acl SSL_ports port 443
> acl Safe_ports port 80 # http
> acl Safe_ports port 21 # ftp
> acl Safe_ports port 443 # https
> acl Safe_ports port 70 # gopher
> acl Safe_ports port 210 # wais
> acl Safe_ports port 1025-65535 # unregistered ports
> acl Safe_ports port 280 # http-mgmt
> acl Safe_ports port 488 # gss-http
> acl Safe_ports port 591 # filemaker
> acl Safe_ports port 777 # multiling http
> acl CONNECT method CONNECT
> http_access allow localhost manager
> http_access deny manager
> http_access deny !Safe_ports
> http_access deny CONNECT !SSL_ports
> acl api_sites dstdomain qa-api.8z.com proxy-stage1.chfops.net
> http_access allow api_sites
> http_access deny all
> http_port 80 accel vhost
> cache_dir ufs /usr/local/squid/var/cache/squid 100 16 256
> coredump_dir /usr/local/squid/var/cache/squid
> refresh_pattern ^ftp: 1440 20% 10080
> refresh_pattern ^gopher: 1440 0% 1440
> refresh_pattern -i (/cgi-bin/|\?) 0 0% 0
> refresh_pattern . 20 20% 4320
> cache_peer 74.86.206.124 parent 80 0 no-query originserver
> name=terabitz8z forceddomain=qa-8z.kwetoo.com
> acl neighborhood_api urlpath_regex ^/api/v1/neighborhood
> cache_peer_access terabitz8z allow neighborhood_api
> cache_peer_access terabitz8z deny all
> logformat combined %>a %ui %un [%{%d/%b/%Y:%H:%M:%S %z}tl] "%rm %ru
> HTTP/%rv" %>Hs %<st "%{Referer}>h" "%{User-Agent}>h" %Ss:%Sh
> access_log /usr/local/squid/var/logs/api_access.log combined api_sites
> logfile_rotate 0
> cache_effective_user nobody
> debug_options ALL,2
>
> ------------------------------------
Received on Fri Oct 05 2012 - 12:01:15 MDT

This archive was generated by hypermail 2.2.0 : Mon Oct 08 2012 - 12:00:02 MDT