Amos Jeffries wrote:
Angelo Hongens wrote:
Sorry, sent this mail directly to Hendrik.. Here it is to the list. I'm
still pulling my hear out :(
Henrik Nordstrom wrote:
On ons, 2008-07-09 at 14:32 +0200, Angelo Höngens wrote:
Is there any way I can force caching if the control headers are
missing??
refresh_pattern with a min age does this.
I expect this line in my squid.conf should take care of that?
refresh_pattern . 3600 100% 3600 ignore-no-cache ignore-reload
override-expire override-lastmod
Here's two records from access.log:
1215606505.637 1678 10.94.206.73 TCP_MISS/200 3262 GET
http://10.94.206.77:8001/bin?id=ACC83639Zoover-NL&irversion=510
- FIRST_UP_PARENT/10.94.206.34 text/html 1215606506.990 1352
10.94.206.73 TCP_MISS/200 3262 GET
http://10.94.206.77:8001/bin?id=ACC83639Zoover-NL&irversion=510
- FIRST_UP_PARENT/10.94.206.34 text/html
Make sure you are not denying caching of query URLs (cache
directive), and that there is a refresh_pattern with a min age.
I expect these lines in my squid.conf to take care of that:
acl all src 0.0.0.0/0.0.0.0
cache allow all
The best way to test is to use squidclient, both to Squid and the web
server. This will show you exactly what is going on with no mangling
of the HTTP headers what so ever.
Exactly the same..
source server:
-------------------------------------------------
[angelo@zvr-web-04 ~]$ squidclient -h 10.94.206.34 -p 8001
"/admin?op=ping"
HTTP/1.0 200 OK
Content-Type: text/html
Content-Length: 63
dgraph zvr-end-04:8001 responding at Wed Jul 09 16:13:18 2008
-------------------------------------------------
local squid:
-------------------------------------------------
[angelo@zvr-web-04 ~]$ squidclient -h localhost -p 8001 "/admin?op=ping"
HTTP/1.0 200 OK
Content-Type: text/html
Content-Length: 63
X-Cache: MISS from zvr-web-04.zoovercolo.local
Via: 1.0 zvr-web-04.zoovercolo.local:8001 (squid/2.6.STABLE16)
Connection: close
dgraph zvr-end-04:8001 responding at Wed Jul 09 16:13:53 2008
-------------------------------------------------
Any more ideas? Thanks in advance :)
The first request through cache is usually expected to MISS, its the
second which tells you whether or not the caching was success/failure.
Try:
squidclient -h 10.94.206.34 -p 8001 "/admin?op=ping"
squidclient -h localhost -p 8001 "/admin?op=ping"
squidclient -h localhost -p 8001 "/admin?op=ping"
and see what the third response is.
If it still fails, configure "debug_options 22,9 20,5", purge the
cache.log and try the above three again. Hopefully the cache.log will be
left with a trace of what happend to non-cache the reply.
Amos
--
Please use Squid 2.7.STABLE3 or 3.0.STABLE7
I added the line "debug_options 22,9 20,5" somewhere in my config, and
restarted squid.
The ran the three squidclient commands.
access.log shows the same:
1215758508.849 2 127.0.0.1 TCP_MISS/200 258 GET
http://127.0.0.1:8001/admin?op=ping - FIRST_UP_PARENT/zvr-end-04 text/html
1215758508.855 2 127.0.0.1 TCP_MISS/200 258 GET
http://127.0.0.1:8001/admin?op=ping - FIRST_UP_PARENT/zvr-end-04 text/html
store.log as well:
1215758508.849 RELEASE -1 FFFFFFFF 36ADE22820C2FDE4586036DE72714B3A 200
-1 -1 -1 text/html 63/63 GET
http://127.0.0.1:8001/admin?op=ping
1215758508.855 RELEASE -1 FFFFFFFF B8B52D283D5FC8A54EA6E12A1D1EAED4 200
-1 -1 -1 text/html 63/63 GET
http://127.0.0.1:8001/admin?op=ping
But now the cache.log has some more info, which I do not fully understand:
Any ideas?:
2008/07/11 08:41:48| storeGet: looking up 9101138CFFBF419A08EFBB418D8264D7
2008/07/11 08:41:48| storeCreateEntry: 'http://127.0.0.1:8001/admin?op=ping'
2008/07/11 08:41:48| new_MemObject: returning 0x28336100
2008/07/11 08:41:48| new_StoreEntry: returning 0x2914f580
2008/07/11 08:41:48| storeKeyPrivate: GET
http://127.0.0.1:8001/admin?op=ping
2008/07/11 08:41:48| storeHashInsert: Inserting Entry 0x2914f580 key
'36ADE22820C2FDE4586036DE72714B3A'
2008/07/11 08:41:48| storeLockObject: key
'36ADE22820C2FDE4586036DE72714B3A' count=2
2008/07/11 08:41:48| storeClientCopy: 36ADE22820C2FDE4586036DE72714B3A,
seen 0, want 0, size 4096, cb 0x8065f20, cbdata 0x29155010
2008/07/11 08:41:48| storeClientCopy2: 36ADE22820C2FDE4586036DE72714B3A
2008/07/11 08:41:48| storeClientCopy3: Waiting for more
2008/07/11 08:41:48| storeLockObject: key
'36ADE22820C2FDE4586036DE72714B3A' count=3
2008/07/11 08:41:48| storeLockObject: key
'36ADE22820C2FDE4586036DE72714B3A' count=4
2008/07/11 08:41:48| storeUnlockObject: key
'36ADE22820C2FDE4586036DE72714B3A' count=3
2008/07/11 08:41:48| storeLockObject: key
'36ADE22820C2FDE4586036DE72714B3A' count=4
2008/07/11 08:41:48| getMaxAge: 'http://127.0.0.1:8001/admin?op=ping'
2008/07/11 08:41:48| ctx: enter level 0:
'http://127.0.0.1:8001/admin?op=ping'
2008/07/11 08:41:48| storeAppend: appending 64 bytes for
'36ADE22820C2FDE4586036DE72714B3A'
2008/07/11 08:41:48| refreshCheck: 'http://127.0.0.1:8001/admin?op=ping'
2008/07/11 08:41:48| FRESH: age 3600 < min 216000
2008/07/11 08:41:48| Staleness = -1
2008/07/11 08:41:48| refreshCheck: Matched '. 216000 100% 216000'
2008/07/11 08:41:48| refreshCheck: age = 3600
2008/07/11 08:41:48| check_time: Fri, 11 Jul 2008 07:41:48 GMT
2008/07/11 08:41:48| entry->timestamp: Fri, 11 Jul 2008 06:41:48 GMT
2008/07/11 08:41:48| storeExpireNow: '36ADE22820C2FDE4586036DE72714B3A'
2008/07/11 08:41:48| storeReleaseRequest: '36ADE22820C2FDE4586036DE72714B3A'
2008/07/11 08:41:48| storeGet: looking up 9101138CFFBF419A08EFBB418D8264D7
2008/07/11 08:41:48| storeGet: looking up 5C590DE8852729BB7654D5EFFBB29519
2008/07/11 08:41:48| ctx: exit level 0
2008/07/11 08:41:48| storeAppend: appending 63 bytes for
'36ADE22820C2FDE4586036DE72714B3A'
2008/07/11 08:41:48| InvokeHandlers: 36ADE22820C2FDE4586036DE72714B3A
2008/07/11 08:41:48| InvokeHandlers: checking client #0
2008/07/11 08:41:48| storeClientCopy2: 36ADE22820C2FDE4586036DE72714B3A
2008/07/11 08:41:48| storeClientCopy3: Copying from memory
2008/07/11 08:41:48| storeComplete: '36ADE22820C2FDE4586036DE72714B3A'
2008/07/11 08:41:48| storeEntryValidLength: Checking
'36ADE22820C2FDE4586036DE72714B3A'
2008/07/11 08:41:48| storeEntryValidLength: object_len = 127
2008/07/11 08:41:48| storeEntryValidLength: hdr_sz = 64
2008/07/11 08:41:48| storeEntryValidLength: content_length = 63
2008/07/11 08:41:48| InvokeHandlers: 36ADE22820C2FDE4586036DE72714B3A
2008/07/11 08:41:48| InvokeHandlers: checking client #0
2008/07/11 08:41:48| storeUnlockObject: key
'36ADE22820C2FDE4586036DE72714B3A' count=3
2008/07/11 08:41:48| storePendingNClients: returning 1
2008/07/11 08:41:48| storeUnlockObject: key
'36ADE22820C2FDE4586036DE72714B3A' count=2
2008/07/11 08:41:48| storeClientUnregister: called for
'36ADE22820C2FDE4586036DE72714B3A'
2008/07/11 08:41:48| storePendingNClients: returning 0
2008/07/11 08:41:48| storeUnlockObject: key
'36ADE22820C2FDE4586036DE72714B3A' count=1
2008/07/11 08:41:48| storeUnlockObject: key
'36ADE22820C2FDE4586036DE72714B3A' count=0
2008/07/11 08:41:48| storePendingNClients: returning 0
2008/07/11 08:41:48| storeRelease: Releasing:
'36ADE22820C2FDE4586036DE72714B3A'
2008/07/11 08:41:48| destroy_StoreEntry: destroying 0x2914f580
2008/07/11 08:41:48| ctx: enter level 0:
'http://127.0.0.1:8001/admin?op=ping'
2008/07/11 08:41:48| destroy_MemObject: destroying 0x28336100
2008/07/11 08:41:48| ctx: exit level 0
2008/07/11 08:41:48| storeGet: looking up 9101138CFFBF419A08EFBB418D8264D7
2008/07/11 08:41:48| storeCreateEntry: 'http://127.0.0.1:8001/admin?op=ping'
2008/07/11 08:41:48| new_MemObject: returning 0x28336100
2008/07/11 08:41:48| new_StoreEntry: returning 0x2914f580
2008/07/11 08:41:48| storeKeyPrivate: GET
http://127.0.0.1:8001/admin?op=ping
2008/07/11 08:41:48| storeHashInsert: Inserting Entry 0x2914f580 key
'B8B52D283D5FC8A54EA6E12A1D1EAED4'
2008/07/11 08:41:48| storeLockObject: key
'B8B52D283D5FC8A54EA6E12A1D1EAED4' count=2
2008/07/11 08:41:48| storeClientCopy: B8B52D283D5FC8A54EA6E12A1D1EAED4,
seen 0, want 0, size 4096, cb 0x8065f20, cbdata 0x29155010
2008/07/11 08:41:48| storeClientCopy2: B8B52D283D5FC8A54EA6E12A1D1EAED4
2008/07/11 08:41:48| storeClientCopy3: Waiting for more
2008/07/11 08:41:48| storeLockObject: key
'B8B52D283D5FC8A54EA6E12A1D1EAED4' count=3
2008/07/11 08:41:48| storeLockObject: key
'B8B52D283D5FC8A54EA6E12A1D1EAED4' count=4
2008/07/11 08:41:48| storeUnlockObject: key
'B8B52D283D5FC8A54EA6E12A1D1EAED4' count=3
2008/07/11 08:41:48| storeLockObject: key
'B8B52D283D5FC8A54EA6E12A1D1EAED4' count=4
2008/07/11 08:41:48| getMaxAge: 'http://127.0.0.1:8001/admin?op=ping'
2008/07/11 08:41:48| ctx: enter level 0:
'http://127.0.0.1:8001/admin?op=ping'
2008/07/11 08:41:48| storeAppend: appending 64 bytes for
'B8B52D283D5FC8A54EA6E12A1D1EAED4'
2008/07/11 08:41:48| refreshCheck: 'http://127.0.0.1:8001/admin?op=ping'
2008/07/11 08:41:48| FRESH: age 3600 < min 216000
2008/07/11 08:41:48| Staleness = -1
2008/07/11 08:41:48| refreshCheck: Matched '. 216000 100% 216000'
2008/07/11 08:41:48| refreshCheck: age = 3600
2008/07/11 08:41:48| check_time: Fri, 11 Jul 2008 07:41:48 GMT
2008/07/11 08:41:48| entry->timestamp: Fri, 11 Jul 2008 06:41:48 GMT
2008/07/11 08:41:48| storeExpireNow: 'B8B52D283D5FC8A54EA6E12A1D1EAED4'
2008/07/11 08:41:48| storeReleaseRequest: 'B8B52D283D5FC8A54EA6E12A1D1EAED4'
2008/07/11 08:41:48| storeGet: looking up 9101138CFFBF419A08EFBB418D8264D7
2008/07/11 08:41:48| storeGet: looking up 5C590DE8852729BB7654D5EFFBB29519
2008/07/11 08:41:48| ctx: exit level 0
2008/07/11 08:41:48| storeAppend: appending 63 bytes for
'B8B52D283D5FC8A54EA6E12A1D1EAED4'
2008/07/11 08:41:48| InvokeHandlers: B8B52D283D5FC8A54EA6E12A1D1EAED4
2008/07/11 08:41:48| InvokeHandlers: checking client #0
2008/07/11 08:41:48| storeClientCopy2: B8B52D283D5FC8A54EA6E12A1D1EAED4
2008/07/11 08:41:48| storeClientCopy3: Copying from memory
2008/07/11 08:41:48| storeComplete: 'B8B52D283D5FC8A54EA6E12A1D1EAED4'
2008/07/11 08:41:48| storeEntryValidLength: Checking
'B8B52D283D5FC8A54EA6E12A1D1EAED4'
2008/07/11 08:41:48| storeEntryValidLength: object_len = 127
2008/07/11 08:41:48| storeEntryValidLength: hdr_sz = 64
2008/07/11 08:41:48| storeEntryValidLength: content_length = 63
2008/07/11 08:41:48| InvokeHandlers: B8B52D283D5FC8A54EA6E12A1D1EAED4
2008/07/11 08:41:48| InvokeHandlers: checking client #0
2008/07/11 08:41:48| storeUnlockObject: key
'B8B52D283D5FC8A54EA6E12A1D1EAED4' count=3
2008/07/11 08:41:48| storePendingNClients: returning 1
2008/07/11 08:41:48| storeUnlockObject: key
'B8B52D283D5FC8A54EA6E12A1D1EAED4' count=2
2008/07/11 08:41:48| storeClientUnregister: called for
'B8B52D283D5FC8A54EA6E12A1D1EAED4'
2008/07/11 08:41:48| storePendingNClients: returning 0
2008/07/11 08:41:48| storeUnlockObject: key
'B8B52D283D5FC8A54EA6E12A1D1EAED4' count=1
2008/07/11 08:41:48| storeUnlockObject: key
'B8B52D283D5FC8A54EA6E12A1D1EAED4' count=0
2008/07/11 08:41:48| storePendingNClients: returning 0
2008/07/11 08:41:48| storeRelease: Releasing:
'B8B52D283D5FC8A54EA6E12A1D1EAED4'
2008/07/11 08:41:48| destroy_StoreEntry: destroying 0x2914f580
2008/07/11 08:41:48| ctx: enter level 0:
'http://127.0.0.1:8001/admin?op=ping'
2008/07/11 08:41:48| destroy_MemObject: destroying 0x28336100
Looks like the object is expiring, because I see the storeExpireNow
command. But I don't get exactly why it's expiring.. Well, I see
something in the log, but I do not understand what it means:
2008/07/11 08:41:48| FRESH: age 3600 < min 216000
2008/07/11 08:41:48| Staleness = -1
2008/07/11 08:41:48| refreshCheck: Matched '. 216000 100% 216000'
2008/07/11 08:41:48| refreshCheck: age = 3600
2008/07/11 08:41:48| check_time: Fri, 11 Jul 2008 07:41:48 GMT
2008/07/11 08:41:48| entry->timestamp: Fri, 11 Jul 2008 06:41:48 GMT
2008/07/11 08:41:48| storeExpireNow: '36ADE22820C2FDE4586036DE72714B3A'
--
Met vriendelijke groet,
Angelo Höngens
