Squid won’t store the image

squid

After spending hours configuring squid 3.2.5, I only get TCP_MISS. To narrow the problem, I will focus on one PNG file that I want cached, but note that I get TCP_MISS for every single request, not only PNG files. The PNG file is accessible at this address. Refreshing doesn’t help.

When I try to load it via squid, I get this line in access.log:

1357671721.566 127 127.0.0.1 TCP_MISS/200 618 GET http://flags.tatoeba.org/img/flags/epo.png – HIER_DIRECT/86.65.39.22
image/png

And those in cache.log:

2013/01/08 20:02:59.768 kid1| client_side.cc(2298) parseHttpRequest: HTTP Client local=127.0.0.1:3303 remote=127.0.0.1:42816 FD 19 flags=1
2013/01/08 20:02:59.769 kid1| client_side.cc(2299) parseHttpRequest: HTTP Client REQUEST:
---------
GET http://flags.tatoeba.org/img/flags/epo.png HTTP/1.1
User-Agent: Wget/1.14 (linux-gnu)
Accept: */*
Host: flags.tatoeba.org
Connection: Close
Proxy-Connection: Keep-Alive


----------
2013/01/08 20:02:59.856 kid1| http.cc(2221) httpStart: httpStart: "GET http://flags.tatoeba.org/img/flags/epo.png"
2013/01/08 20:02:59.856 kid1| http.cc(2177) sendRequest: HTTP Server local=192.168.1.13:56866 remote=86.65.39.22:80 FD 22 flags=1
2013/01/08 20:02:59.856 kid1| http.cc(2178) sendRequest: HTTP Server REQUEST:
---------
GET /img/flags/epo.png HTTP/1.1
User-Agent: Wget/1.14 (linux-gnu)
Accept: */*
Host: flags.tatoeba.org
Via: 1.1 nomada (squid/3.2.5)
Cache-Control: max-age=15600540
Connection: keep-alive


----------
2013/01/08 20:02:59.898 kid1| ctx: enter level  0: 'http://flags.tatoeba.org/img/flags/epo.png'
2013/01/08 20:02:59.898 kid1| http.cc(689) processReplyHeader: processReplyHeader: key 'EA06B401749A4C13ED95E8B5788A3010'
2013/01/08 20:02:59.898 kid1| http.cc(732) processReplyHeader: HTTP Server local=192.168.1.13:56866 remote=86.65.39.22:80 FD 22 flags=1
2013/01/08 20:02:59.898 kid1| http.cc(733) processReplyHeader: HTTP Server REPLY:
---------
HTTP/1.1 200 OK
Date: Tue, 08 Jan 2013 19:03:18 GMT
Server: Apache/2.2.16 (Debian)
Accept-Ranges: bytes
Content-Length: 219
Vary: User-Agent
Expires: Fri, 21 Dec 2012 00:00:00 GMT
Cache-Control: public, no-transform
Content-Type: image/png
Via: 1.1 tatoeba.fsffrance.org
Keep-Alive: timeout=15, max=100
Connection: Keep-Alive

�PNG


----------
2013/01/08 20:02:59.898 kid1| ctx: exit level  0
2013/01/08 20:02:59.898 kid1| ctx: enter level  0: 'http://flags.tatoeba.org/img/flags/epo.png'
2013/01/08 20:02:59.898 kid1| http.cc(910) haveParsedReplyHeaders: haveParsedReplyHeaders: HTTP CODE: 200
2013/01/08 20:02:59.898 kid1| http.cc(640) httpMakeVaryMark: httpMakeVaryMark: user-agent="Wget%2F1.14%20(linux-gnu)"
2013/01/08 20:02:59.898 kid1| ctx: exit level  0
2013/01/08 20:02:59.899 kid1| client_side.cc(1362) sendStartOfMessage: HTTP Client local=127.0.0.1:3303 remote=127.0.0.1:42816 FD 19 flags=1
2013/01/08 20:02:59.899 kid1| client_side.cc(1363) sendStartOfMessage: HTTP Client REPLY:
---------
HTTP/1.1 200 OK
Date: Tue, 08 Jan 2013 19:03:18 GMT
Server: Apache/2.2.16 (Debian)
Accept-Ranges: bytes
Content-Length: 219
Vary: User-Agent
Expires: Fri, 21 Dec 2012 00:00:00 GMT
Cache-Control: public, no-transform
Content-Type: image/png
X-Cache: MISS from nomada
X-Cache-Lookup: MISS from nomada:3303
Via: 1.1 tatoeba.fsffrance.org, 1.1 nomada (squid/3.2.5)
Connection: keep-alive


----------
2013/01/08 20:02:59.899 kid1| http.cc(1044) persistentConnStatus: local=192.168.1.13:56866 remote=86.65.39.22:80 FD 22 flags=1 eof=0

My config file looks a lot like the default one, except for a couple changes:

cache_effective_user squid
cache_effective_group squid
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 Safe_ports port 901     # SWAT
acl CONNECT method CONNECT
http_access allow localhost manager
http_access deny manager
http_access deny !Safe_ports
http_access deny CONNECT !SSL_ports
debug_options ALL,1 11,3 31,3 65,3
http_access allow localnet
http_access allow localhost
http_access deny all
http_port 3303
cache_dir ufs /var/cache/squid 600 16 256
cache_mem 256 MB
coredump_dir /var/cache/squid
refresh_pattern ^ftp:       1440    20% 10080
refresh_pattern -i \.(gif|png|jpg|jpeg|ico|bmp)$ 260000 90% 260009 override-expire ignore-no-cache ignore-no-store ignore-private
refresh_pattern ^gopher:    1440    0%  1440
refresh_pattern -i (/cgi-bin/|\?) 0 0%  0
refresh_pattern .       0   20% 4320

My cache directory belongs to squid:squid, so no problem on that side either. And I am stumped for an answer.

Here is a chunk of my access.log:

1357671487.203    212 127.0.0.1 TCP_MISS/200 8263 GET http://i2.ytimg.com/vi/mwKa-gjx14k/mqdefault.jpg - HIER_DIRECT/74.125.230.238 image/jpeg
1357671487.235    134 127.0.0.1 TCP_MISS/200 10762 GET http://i4.ytimg.com/vi/O0bftzEOt9c/mqdefault.jpg - HIER_DIRECT/74.125.230.224 image/jpeg
1357671487.296    253 127.0.0.1 TCP_MISS/200 7415 GET http://i4.ytimg.com/vi/GPUnq0JSqRk/mqdefault.jpg - HIER_DIRECT/74.125.230.224 image/jpeg
1357671488.188    474 127.0.0.1 TCP_MISS/200 294 POST http://serverfault.com/posts/0/editor-heartbeat/ask - HIER_DIRECT/69.59.197.21 application/json
1357671505.309    255 127.0.0.1 TCP_MISS/204 533 GET http://s.youtube.com/s? - HIER_DIRECT/74.125.230.224 text/html
1357671516.404      0 127.0.0.1 TCP_MISS/503 6350 GET http://s.youtube.com/s? - HIER_NONE/- text/html
1357671533.221      0 127.0.0.1 TCP_MISS/503 4106 POST http://serverfault.com/posts/0/editor-heartbeat/ask - HIER_NONE/- text/html
1357671582.022    481 127.0.0.1 TCP_MISS/200 439 POST http://serverfault.com/posts/0/editor-heartbeat/ask - HIER_DIRECT/69.59.197.21 application/json
1357671597.029   1543 127.0.0.1 TCP_MISS/200 9700 GET http://tatoeba.org/eng/sentences/show/673940 - HIER_DIRECT/86.65.39.22 text/html
1357671597.166     47 127.0.0.1 TCP_MISS/200 1426 GET http://tatoeba.org/js/sentences.random.js? - HIER_DIRECT/86.65.39.22 application/javascript
1357671597.205     86 127.0.0.1 TCP_MISS/200 2174 GET http://tatoeba.org/js/sentences_lists.menu.js? - HIER_DIRECT/86.65.39.22 application/javascript
1357671597.254    136 127.0.0.1 TCP_MISS/200 1522 GET http://css.tatoeba.org/css/sentences/show.css? - HIER_DIRECT/86.65.39.22 text/css
1357671597.254    136 127.0.0.1 TCP_MISS/200 1324 GET http://css.tatoeba.org/css/elements/furigana.css - HIER_DIRECT/86.65.39.22 text/css
1357671597.254     48 127.0.0.1 TCP_MISS/200 1809 GET http://tatoeba.org/favicon.ico - HIER_DIRECT/86.65.39.22 image/x-icon
1357671597.258    137 127.0.0.1 TCP_MISS/200 1150 GET http://js.tatoeba.org/js/furigana.js - HIER_DIRECT/86.65.39.22 application/javascript
1357671597.258    139 127.0.0.1 TCP_MISS/200 1339 GET http://js.tatoeba.org/js/generic_functions.js? - HIER_DIRECT/86.65.39.22 application/javascript
1357671597.258     91 127.0.0.1 TCP_MISS/200 2471 GET http://js.tatoeba.org/js/autocompletion.js - HIER_DIRECT/86.65.39.22 application/javascript
1357671597.295    179 127.0.0.1 TCP_MISS/200 3232 GET http://css.tatoeba.org/css/layouts/default.css - HIER_DIRECT/86.65.39.22 text/css
1357671597.332     39 127.0.0.1 TCP_MISS/200 1234 GET http://css.tatoeba.org/css/elements/navigation.css - HIER_DIRECT/86.65.39.22 text/css
1357671597.339     43 127.0.0.1 TCP_MISS/200 1809 GET http://tatoeba.org/favicon.ico - HIER_DIRECT/86.65.39.22 image/x-icon
1357671597.342     49 127.0.0.1 TCP_MISS/200 1774 GET http://css.tatoeba.org/css/elements/sentences_group.css - HIER_DIRECT/86.65.39.22 text/css
1357671597.377     82 127.0.0.1 TCP_MISS/200 1032 GET http://css.tatoeba.org/css/elements/logs_colors.css - HIER_DIRECT/86.65.39.22 text/css
1357671597.384     90 127.0.0.1 TCP_MISS/200 1014 GET http://css.tatoeba.org/css/elements/comment.css - HIER_DIRECT/86.65.39.22 text/css
1357671597.384     89 127.0.0.1 TCP_MISS/200 1124 GET http://css.tatoeba.org/css/elements/autocompletion.css - HIER_DIRECT/86.65.39.22 text/css
1357671597.384     89 127.0.0.1 TCP_MISS/200 1023 GET http://css.tatoeba.org/css/elements/logs_annexe.css - HIER_DIRECT/86.65.39.22 text/css
1357671597.410    292 127.0.0.1 TCP_MISS/200 21703 GET http://js.tatoeba.org/js/jquery-mini.js - HIER_DIRECT/86.65.39.22 application/javascript
1357671597.794    131 127.0.0.1 TCP_MISS/200 1284 GET http://flags.tatoeba.org/img/valid_16x16.png - HIER_DIRECT/86.65.39.22 image/png
1357671597.795    133 127.0.0.1 TCP_MISS/200 595 GET http://flags.tatoeba.org/img/arrow_down.png - HIER_DIRECT/86.65.39.22 image/png
1357671597.800    137 127.0.0.1 TCP_MISS/200 1256 GET http://flags.tatoeba.org/img/add_to_list.png - HIER_DIRECT/86.65.39.22 image/png
1357671597.801    137 127.0.0.1 TCP_MISS/200 618 GET http://flags.tatoeba.org/img/flags/epo.png - HIER_DIRECT/86.65.39.22 image/png
1357671597.846     50 127.0.0.1 TCP_MISS/200 1180 GET http://flags.tatoeba.org/img/direct_translation.png - HIER_DIRECT/86.65.39.22 image/png
1357671597.846     51 127.0.0.1 TCP_MISS/200 3008 GET http://flags.tatoeba.org/img/loading.gif - HIER_DIRECT/86.65.39.22 image/gif
1357671597.846     45 127.0.0.1 TCP_MISS/200 1539 GET http://flags.tatoeba.org/img/flags/eng.png - HIER_DIRECT/86.65.39.22 image/png
1357671597.847     45 127.0.0.1 TCP_MISS/200 532 GET http://flags.tatoeba.org/img/flags/nld.png - HIER_DIRECT/86.65.39.22 image/png
1357671597.860    197 127.0.0.1 TCP_MISS/200 1072 GET http://flags.tatoeba.org/img/loading-small.gif - HIER_DIRECT/86.65.39.22 image/gif
1357671597.887    224 127.0.0.1 TCP_MISS/200 16497 GET http://flags.tatoeba.org/img/TatoebaProjectBeta.png - HIER_DIRECT/86.65.39.22 image/png
1357671597.892     45 127.0.0.1 TCP_MISS/200 1031 GET http://flags.tatoeba.org/img/indirect_translation.png - HIER_DIRECT/86.65.39.22 image/png
1357671597.892     45 127.0.0.1 TCP_MISS/200 520 GET http://flags.tatoeba.org/img/flags/ita.png - HIER_DIRECT/86.65.39.22 image/png
1357671597.892     45 127.0.0.1 TCP_MISS/200 525 GET http://flags.tatoeba.org/img/flags/deu.png - HIER_DIRECT/86.65.39.22 image/png
1357671597.892     44 127.0.0.1 TCP_MISS/200 718 GET http://flags.tatoeba.org/img/flags/jpn.png - HIER_DIRECT/86.65.39.22 image/png
1357671597.908     47 127.0.0.1 TCP_MISS/200 541 GET http://css.tatoeba.org/img/bg_main.png - HIER_DIRECT/86.65.39.22 image/png
1357671597.930     43 127.0.0.1 TCP_MISS/200 694 GET http://css.tatoeba.org/img/search_bar_body.png - HIER_DIRECT/86.65.39.22 image/png
1357671597.933     39 127.0.0.1 TCP_MISS/200 584 GET http://css.tatoeba.org/img/module_background.png - HIER_DIRECT/86.65.39.22 image/png
1357671597.935     42 127.0.0.1 TCP_MISS/200 1572 GET http://css.tatoeba.org/img/search_bar_right.png - HIER_DIRECT/86.65.39.22 image/png
1357671597.936     43 127.0.0.1 TCP_MISS/200 1574 GET http://css.tatoeba.org/img/search_bar_left.png - HIER_DIRECT/86.65.39.22 image/png
1357671597.936     42 127.0.0.1 TCP_MISS/200 1378 GET http://css.tatoeba.org/img/title.png - HIER_DIRECT/86.65.39.22 image/png
1357671597.954     45 127.0.0.1 TCP_MISS/200 1026 GET http://css.tatoeba.org/img/audio_unavailable.png - HIER_DIRECT/86.65.39.22 image/png

Best Answer

The upstream webserver is returning an expiry time in the past, which will cause Squid to immediately consider the object stale.

Expires: Fri, 21 Dec 2012 00:00:00 GMT

That looks like a hardcoded timestamp, you probably want the webserver to return a relative expiry timestamp (e.g. now plus 1 month).