Thanks Amos.
I fixed the channel id problem by fixing storeurl rewriter perl script but still the video/x-flv response is getting RELEASED in store.log instead of SWAPOUT. Can you please read below cache.log and suggest what is still going wrong? Now "Rewrote to" message prints the right transformed URL. After this store tries to look up for the "6B2E83D66FC215C27ECFBA432AB7B5F6" key which returns a TCP MISS for the same key lookup for 2nd and third tries as well. Then one hash entry gets inserted with another key for the same big URL with different hash key for 2nd and 3rd time as well. This new key is "04BE27CFF614A3315F5CEB008464C453". I have also pasted HTTP response header for video/x-flv content from cache.log. After this I see "Deferring starting swapping out" message in cache.log. Can you please suggest why it is not swapping out?
I am pasting below a section of squid.conf file as well. After this is the cache.log output.
----- squid.2.7.stable7 squid.conf youtube video related section starts-----
#hierarchy_stoplist cgi-bin ?
# The keyword for all youtube video files are "get_video?", "videodownload?" and "videoplayback" plus the id,
acl store_rewrite_list1 dstdomain .youtube.com .video.google.com
acl store_rewrite_list urlpath_regex \/(get_video\?|videodownload\?|videoplayback\?i|watch\?)
#acl store_rewrite_list urlpath_regex \/(get_video\?|videodownload\?|videoplayback\?|watch\?|generate_204\?|docid=)
storeurl_access allow store_rewrite_list store_rewrite_list1
storeurl_access allow all
cache allow all
storeurl_rewrite_program /orbital/current/squid/storeurl.pl
storeurl_rewrite_children 1
storeurl_rewrite_concurrency 10
#youtube's videos
#refresh_pattern -i (get_video\?|videoplayback\?|videodownload\?|watch\?|generate_204\?|docid=)$ 5259487 99999999% 5259487 ignore-no-cache override-lastmod override-expire ignore-reload negative-ttl=0
refresh_pattern -i (get_video\?|videoplayback\?|videodownload\?|watch\?)$ 5259487 99999999% 5259487 ignore-private ignore-no-cache override-lastmod override-expire ignore-reload negative-ttl=0
refresh_pattern ^ftp: 1 50% 10080
refresh_pattern ^gopher: 1 0% 1440
refresh_pattern -i \.(gif|jpg|jpeg|tif|png|ico|bmp)$ 600 400% 43200 ignore-no-cache override-expire
refresh_pattern -i \.(wma|wmv|avi|mpeg|ram|mp3|mpg|flv)$ 5259487 99999999% 5259487 override-lastmod ignore-no-cache override-expire ignore-private negative-ttl=0
refresh_pattern -i \.(cab|exe|gzip|gz|zip|rpm|bin|dat|psf|bz2)$ 5259487 99999999% 5259487 override-lastmod ignore-no-cache override-expire ignore-private negative-ttl=0
refresh_pattern -i \.(swf|css|js)$ 5259487 99999999% 5259487 override-lastmod ignore-no-cache override-expire ignore-private negative-ttl=0
refresh_pattern windowsupdate.com/.*\.(cab|exe|dll) 1 20% 1440
refresh_pattern download.microsoft.com/.*\.(cab|exe|dll) 1 20% 1440
refresh_pattern ^http:\/\/74\.125 86400 20% 86400 override-expire override-lastmod ignore-no-cache ignore-private
refresh_pattern -i \.(htm|html|shtml|asp)$ 0 0% 0
refresh_pattern . 0 20% 4320
-----squid.conf section ends-------
Here is the cache.log output.
---------output starts from cache.log---------------------
2010/11/23 09:01:30| helperHandleRead: '0http://video-srv.youtube.com.SQUIDINTERNAL/get_video?video_id=eccfa3b232c1db46
'
2010/11/23 09:01:30| helperHandleRead: end of reply found: 0http://video-srv.youtube.com.SQUIDINTERNAL/get_video?video_id=eccfa3b232c1db46
2010/11/23 09:01:30| cbdataValid: 0x8e0088
2010/11/23 09:01:30| storeurlHandleReply: {http://video-srv.youtube.com.SQUIDINTERNAL/get_video?video_id=eccfa3b232c1db46}
2010/11/23 09:01:30| cbdataValid: 0xbb50a8
2010/11/23 09:01:30| cbdataUnlock: 0xbb50a8
2010/11/23 09:01:30| clientStoreURLRewriteDone: 'http://v24.lscache6.c.youtube.com/videoplayback?ip=202.0.0.0&sparams=id%2Cexpire%2Cip%2Cipbi
ts%2Citag%2Calgorithm%2Cburst%2Cfactor&fexp=901306%2C903205&algorithm=throttle-factor&itag=34&ipbits=8&burst=40&sver=3&expire=1290531600&key=
yt1&signature=88A0880AB56535D66539DFD7D75F0706830B8E.153AEECCD614BAE74DF2807F8BF07D51DE5A4674&factor=1.25&id=eccfa3b232c1db46&' result=http:/
/video-srv.youtube.com.SQUIDINTERNAL/get_video?video_id=eccfa3b232c1db46
2010/11/23 09:01:30| Rewrote to http://video-srv.youtube.com.SQUIDINTERNAL/get_video?video_id=eccfa3b232c1db46
......
2010/11/23 09:01:30| clientInterpretRequestHeaders: REQ_NOCACHE = NOT SET
2010/11/23 09:01:30| clientInterpretRequestHeaders: REQ_CACHABLE = SET
2010/11/23 09:01:30| clientInterpretRequestHeaders: REQ_HIERARCHICAL = NOT SET
.......
2010/11/23 09:01:30| clientProcessRequest: GET 'http://v24.lscache6.c.youtube.com/videoplayback?ip=202.0.0.0&sparams=id%2Cexpire%2Cip%2Cipbit
s%2Citag%2Calgorithm%2Cburst%2Cfactor&fexp=901306%2C903205&algorithm=throttle-factor&itag=34&ipbits=8&burst=40&sver=3&expire=1290531600&key=y
t1&signature=88A0880AB56535D66539DFD7D75F0706830B8E.153AEECCD614BAE74DF2807F8BF07D51DE5A4674&factor=1.25&id=eccfa3b232c1db46&'
2010/11/23 09:01:30| 0xbb5898 lookup for 53
2010/11/23 09:01:30| storeGet: looking up 6B2E83D66FC215C27ECFBA432AB7B5F6
2010/11/23 09:01:30| clientProcessRequest2: storeGet() MISS
2010/11/23 09:01:30| clientProcessRequest: TCP_MISS for 'http://v24.lscache6.c.youtube.com/videoplayback?ip=202.0.0.0&sparams=id%2Cexpire%2Ci
p%2Cipbits%2Citag%2Calgorithm%2Cburst%2Cfactor&fexp=901306%2C903205&algorithm=throttle-factor&itag=34&ipbits=8&burst=40&sver=3&expire=1290531
600&key=yt1&signature=88A0880AB56535D66539DFD7D75F0706830B8E.153AEECCD614BAE74DF2807F8BF07D51DE5A4674&factor=1.25&id=eccfa3b232c1db46&'
2010/11/23 09:01:30| clientProcessMiss: 'GET http://v24.lscache6.c.youtube.com/videoplayback?ip=202.0.0.0&sparams=id%2Cexpire%2Cip%2Cipbits%2
Citag%2Calgorithm%2Cburst%2Cfactor&fexp=901306%2C903205&algorithm=throttle-factor&itag=34&ipbits=8&burst=40&sver=3&expire=1290531600&key=yt1&
signature=88A0880AB56535D66539DFD7D75F0706830B8E.153AEECCD614BAE74DF2807F8BF07D51DE5A4674&factor=1.25&id=eccfa3b232c1db46&'
2010/11/23 09:01:30| storeCreateEntry: 'http://v24.lscache6.c.youtube.com/videoplayback?ip=202.0.0.0&sparams=id%2Cexpire%2Cip%2Cipbits%2Citag
%2Calgorithm%2Cburst%2Cfactor&fexp=901306%2C903205&algorithm=throttle-factor&itag=34&ipbits=8&burst=40&sver=3&expire=1290531600&key=yt1&signa
ture=88A0880AB56535D66539DFD7D75F0706830B8E.153AEECCD614BAE74DF2807F8BF07D51DE5A4674&factor=1.25&id=eccfa3b232c1db46&'
2010/11/23 09:01:30| storeKeyPrivate: GET http://v24.lscache6.c.youtube.com/videoplayback?ip=202.0.0.0&sparams=id%2Cexpire%2Cip%2Cipbits%2Cit
ag%2Calgorithm%2Cburst%2Cfactor&fexp=901306%2C903205&algorithm=throttle-factor&itag=34&ipbits=8&burst=40&sver=3&expire=1290531600&key=yt1&sig
nature=88A0880AB56535D66539DFD7D75F0706830B8E.153AEECCD614BAE74DF2807F8BF07D51DE5A4674&factor=1.25&id=eccfa3b232c1db46&
2010/11/23 09:01:30| storeHashInsert: Inserting Entry 0xbb5c90 key '04BE27CFF614A3315F5CEB008464C453'
2010/11/23 09:01:30| storeLockObject: (store_client.c:122): key '04BE27CFF614A3315F5CEB008464C453' count=2
2010/11/23 09:01:30| storeClientCopy: 04BE27CFF614A3315F5CEB008464C453, seen 0, want 0, size 4096, cb 0x41db90, cbdata 0xbb50a8
2010/11/23 09:01:30| cbdataLock: 0xbb50a8
2010/11/23 09:01:30| cbdataLock: 0xbb5e88
2010/11/23 09:01:30| storeClientCopy2: 04BE27CFF614A3315F5CEB008464C453
2010/11/23 09:01:30| storeClientCopy3: Waiting for more
2010/11/23 09:01:30| cbdataUnlock: 0xbb5e88
2010/11/23 09:01:30| aclCheckFast: list: (nil)
2010/11/23 09:01:30| aclCheckFast: no matches, returning: 1
2010/11/23 09:01:30| fwdStart: 'http://v24.lscache6.c.youtube.com/videoplayback?ip=202.0.0.0&sparams=id%2Cexpire%2Cip%2Cipbits%2Citag%2Calgor
ithm%2Cburst%2Cfactor&fexp=901306%2C903205&algorithm=throttle-factor&itag=34&ipbits=8&burst=40&sver=3&expire=1290531600&key=yt1&signature=88A
0880AB56535D66539DFD7D75F0706830B8E.153AEECCD614BAE74DF2807F8BF07D51DE5A4674&factor=1.25&id=eccfa3b232c1db46&'
2010/11/23 09:01:30| storeLockObject: (forward.c:964): key '04BE27CFF614A3315F5CEB008464C453' count=3
2010/11/23 09:01:30| peerSelect: http://v24.lscache6.c.youtube.com/videoplayback?ip=202.0.0.0&sparams=id%2Cexpire%2Cip%2Cipbits%2Citag%2Calgo
rithm%2Cburst%2Cfactor&fexp=901306%2C903205&algorithm=throttle-factor&itag=34&ipbits=8&burst=40&sver=3&expire=1290531600&key=yt1&signature=88
A0880AB56535D66539DFD7D75F0706830B8E.153AEECCD614BAE74DF2807F8BF07D51DE5A4674&factor=1.25&id=eccfa3b232c1db46&
2010/11/23 09:01:30| storeLockObject: (peer_select.c:155): key '04BE27CFF614A3315F5CEB008464C453' count=4
........
2010/11/23 09:01:30| ctx: enter level 0: 'http://v24.lscache6.c.youtube.com/videoplayback?ip=202.0.0.0&sparams=id%2Cexpire%2Cip%2Cipbits%2Ci
tag%2Calgorithm%2Cburst%2Cfactor&fexp=901306%2C903205&algorithm=throttle-factor&itag=34&ipbits=8&burst=40&sver=3&expire=1290531600&key=yt1&si
gnature=88A0880AB56535D66539DFD7D75F0706830B8E.153AEECCD614BAE74DF2807F8BF07D51DE5A4674&factor=1.25&id=eccfa3b232c1db46&'
2010/11/23 09:01:30| httpProcessReplyHeader: key '04BE27CFF614A3315F5CEB008464C453'
2010/11/23 09:01:30| GOT HTTP REPLY HDR:
---------
HTTP/1.1 200 OK^M
Last-Modified: Sun, 20 Jun 2010 03:13:48 GMT^M
Content-Type: video/x-flv^M
Date: Tue, 23 Nov 2010 10:06:39 GMT^M
Expires: Tue, 23 Nov 2010 10:06:39 GMT^M
Cache-Control: private, max-age=24501^M
Accept-Ranges: bytes^M
Content-Length: 2087288^M
Connection: close^M
X-Content-Type-Options: nosniff^M
Server: gvs 1.0^M
-----------
.......
2010/11/23 09:01:30| storeSwapOut: http://v24.lscache6.c.youtube.com/videoplayback?ip=202.0.0.0&sparams=id%2Cexpire%2Cip%2Cipbits%2Citag%2Cal
gorithm%2Cburst%2Cfactor&fexp=901306%2C903205&algorithm=throttle-factor&itag=34&ipbits=8&burst=40&sver=3&expire=1290531600&key=yt1&signature=
88A0880AB56535D66539DFD7D75F0706830B8E.153AEECCD614BAE74DF2807F8BF07D51DE5A4674&factor=1.25&id=eccfa3b232c1db46&
2010/11/23 09:01:30| storeSwapOut: store_status = STORE_PENDING
2010/11/23 09:01:30| storeSwapOut: mem->inmem_lo = 0
2010/11/23 09:01:30| storeSwapOut: mem->inmem_hi = 648
2010/11/23 09:01:30| storeSwapOut: swapout.queue_offset = 0
2010/11/23 09:01:30| storeSwapOut: Deferring starting swapping out
.......
----------output ends from cache.log-----------------------
Regards,
Saurabh
-----Original Message-----
From: Amos Jeffries [mailto:squid3_at_treenet.co.nz]
Sent: Tuesday, November 23, 2010 6:45 AM
To: squid-users_at_squid-cache.org
Subject: Re: [squid-users] Caching youtube videos problem/ always getting TCP_MISS
On Mon, 22 Nov 2010 17:39:12 +0530, Saurabh Agarwal
<Saurabh.Agarwal_at_citrix.com> wrote:
> Hi All/Amos
>
> I am using squid 2.7 Stable7 and trying to cache this youtube video
> http://www.youtube.com/watch?v=7M-jsjLB20Y but I am always getting a tcp
> miss. I have done the required configuration as mentioned on
> http://wiki.squid-cache.org/ConfigExamples/DynamicContent/YouTube. After
a
> few redirects this http get request response returns the content type of
> video/x-flv.
>
>
http://v24.lscache6.c.youtube.com/videoplayback?ip=202.0.0.0&sparams=id%2Cexpire%2Cip%2Cipbits%2Citag%2Calgorithm%2Cburst%2Cfactor&fexp=901306%2C900025&algorithm=throttle-factor&itag=34&ipbits=8&burst=40&sver=3&expire=1289592000&key=yt1&signature=1E5E015856CF11DE13A253255DFA638D9084981C.D49489F758A488EF2DF2200E8DD8EFADE4F4ADF7&factor=1.25&id=eccfa3b232c1db46&
>
> From above url I can successfully extract id=eccfa3b232c1db46 field from
> this url using storeurl rewriter feature as confirmed by cache.log
below.
No. The log below shows this transformation happening on the URL, but that
the rewriter output is not correct for the channel ID portion.
> Please search for
>
http://video-srv.youtube.com.SQUIDINTERNAL/get_video?video_id=eccfa3b232c1db46
> below. When I turn on debug logs using debug level ALL,9 in squid I see
> following in cache.log file. The messages like "Rewrote to" prints the
same
> input url in the cache.logs. I think this url should be
>
http://video-srv.youtube.com.SQUIDINTERNAL/get_video?video_id=eccfa3b232c1db46
>
>
> ---------output from cache.log using debug level
> ALL,9-------------------------------
> helperHandleRead: '0
>
http://v24.lscache6.c.youtube.com/videoplayback?ip=202.0.0.0&sparams=id%2Cexpire%2Cip%2Cipbits%2Citag%2Calgorithm%2Cburst%2Cfactor&fexp=901306%2C900025&algorithm=throttle-factor&itag=34&ipbits=8&burst=40&sver=3&expire=1289592000&key=yt1&signature=1E5E015856CF11DE13A253255DFA638D9084981C.D49489F758A488EF2DF2200E8DD8EFADE4F4ADF7&factor=1.25&id=eccfa3b232c1db46&
> 10.102.79.81/client - GET - myip=10.102.79.88 myport=3128
>
http://video-srv.youtube.com.SQUIDINTERNAL/get_video?video_id=eccfa3b232c1db46
>
> '
> 2010/11/12 12:36:40| helperHandleRead: end of reply found: 0
>
http://v24.lscache6.c.youtube.com/videoplayback?ip=202.0.0.0&sparams=id%2Cexpire%2Cip%2Cipbits%2Citag%2Calgorithm%2Cburst%2Cfactor&fexp=901306%2C900025&algorithm=throttle-factor&itag=34&ipbits=8&burst=40&sver=3&expire=1289592000&key=yt1&signature=1E5E015856CF11DE13A253255DFA638D9084981C.D49489F758A488EF2DF2200E8DD8EFADE4F4ADF7&factor=1.25&id=eccfa3b232c1db46&
> 10.102.79.81/client - GET - myip=10.102.79.88 myport=3128
>
http://video-srv.youtube.com.SQUIDINTERNAL/get_video?video_id=eccfa3b232c1db46
>
This whole string appears to be what is coming back.
Correct output is just "0
http://video-srv.youtube.com.SQUIDINTERNAL/get_video?video_id=eccfa3b232c1db46"
Note the "0 " concurrency channel ID is missing from in front of the
altered URL, but the whole received line is being sent as a prefix
including the newline terminator.
<snip>
> 2010/11/12 12:36:40| Rewrote to
>
http://v24.lscache6.c.youtube.com/videoplayback?ip=202.0.0.0&sparams=id%2Cexpire%2Cip%2Cipbits%2Citag%2Calgorithm%2Cburst%2Cfactor&fexp=901306%2C900025&algorithm=throttle-factor&itag=34&ipbits=8&burst=40&sver=3&expire=1289592000&key=yt1&signature=1E5E015856CF11DE13A253255DFA638D9084981C.D49489F758A488EF2DF2200E8DD8EFADE4F4ADF7&factor=1.25&id=eccfa3b232c1db46&
> ....
Once Squid identifies the channel ID and discards the garbage trailing the
line this "rewrote to" is what Squid uses as response to the channel 0
request.
Note the absence of SQUIDINTERNAL in the domain name and the abundance of
extra parameter strings.
...
> 2010/11/12 12:36:40| cbdataUnlock: 0xafd4d8
> 2010/11/12 12:36:40| cbdataUnlock: Freeing 0xafd4d8
> 2010/11/12 12:36:40| helperHandleRead: end of reply found:
>
http://video-srv.youtube.com.SQUIDINTERNAL/get_video?video_id=eccfa3b232c1db46
>
>
> 2010/11/12 12:36:40| helperHandleRead: unexpected reply on channel -1
from
> store_rewriter #1
>
'http://video-srv.youtube.com.SQUIDINTERNAL/get_video?video_id=eccfa3b232c1db46'
This looks like the actual response is coming back on a second line
without any channel ID. This missing channel ID is the only reason your
client requests are not getting sent the wrong reply objects from cache.
What should be happening is that the rewriter pulls off the channel ID and
requested URL from the request. Then sends back the channel ID and altered
URL *only*.
Amos
Received on Tue Nov 23 2010 - 10:51:06 MST
This archive was generated by hypermail 2.2.0 : Tue Nov 23 2010 - 12:00:02 MST