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:[email protected]] Sent: Tuesday, November 23, 2010 6:45 AM To: [email protected] Subject: Re: [squid-users] Caching youtube videos problem/ always getting TCP_MISS On Mon, 22 Nov 2010 17:39:12 +0530, Saurabh Agarwal <[email protected]> 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
