[squid-users] Caching youtube videos problem/ always getting TCP_MISS from Saurabh Agarwal on 2010-11-22 (squid-users)

From: Saurabh Agarwal <Saurabh.Agarwal_at_citrix.com>
Date: Mon, 22 Nov 2010 17:39:12 +0530

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. 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

2010/11/12 12:36:40| clientProcessRequest: GET '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&'
2010/11/12 12:36:40| 0xb31898 lookup for 53
2010/11/12 12:36:40| storeGet: looking up FF870BC29D7518B45A387BDAC9FF66CD
2010/11/12 12:36:40| clientProcessRequest2: storeGet() MISS
2010/11/12 12:36:40| clientProcessRequest: TCP_MISS for '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&'
2010/11/12 12:36:40| clientProcessMiss: 'GET 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&'
2010/11/12 12:36:40| storeCreateEntry: '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&'

.....
2010/11/12 12:36:40| storeKeyPrivate: GET 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&
2010/11/12 12:36:40| storeHashInsert: Inserting Entry 0xb32320 key 'DE829298A169F5E6BC0EE12D3AC5F613'
2010/11/12 12:36:40| storeLockObject: (store_client.c:122): key 'DE829298A169F5E6BC0EE12D3AC5F613' count=2
2010/11/12 12:36:40| storeClientCopy: DE829298A169F5E6BC0EE12D3AC5F613, seen 0, want 0, size 4096, cb 0x41db90, cbdata 0xb310a8
2010/11/12 12:36:40| cbdataLock: 0xb310a8
2010/11/12 12:36:40| cbdataLock: 0xb2f668
2010/11/12 12:36:40| storeClientCopy2: DE829298A169F5E6BC0EE12D3AC5F613
2010/11/12 12:36:40| storeClientCopy3: Waiting for more
2010/11/12 12:36:40| cbdataUnlock: 0xb2f668
2010/11/12 12:36:40| aclCheckFast: list: (nil)
2010/11/12 12:36:40| aclCheckFast: no matches, returning: 1
2010/11/12 12:36:40| fwdStart: '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&'
2010/11/12 12:36:40| storeLockObject: (forward.c:964): key 'DE829298A169F5E6BC0EE12D3AC5F613' count=3
2010/11/12 12:36:40| peerSelect: 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&
2010/11/12 12:36:40| storeLockObject: (peer_select.c:155): key 'DE829298A169F5E6BC0EE12D3AC5F613' count=4
2010/11/12 12:36:40| cbdataLock: 0xb326b8
2010/11/12 12:36:40| peerSelectFoo: 'GET v24.lscache6.c.youtube.com'
2010/11/12 12:36:40| peerCheckNetdbDirect: MY RTT = 0 msec
2010/11/12 12:36:40| peerCheckNetdbDirect: minimum_direct_rtt = 0 msec
2010/11/12 12:36:40| peerCheckNetdbDirect: MY hops = 0
2010/11/12 12:36:40| peerCheckNetdbDirect: minimum_direct_hops = 0
2010/11/12 12:36:40| whichPeer: from 0.0.0.0 port 0
2010/11/12 12:36:40| peerSelectFoo: direct = DIRECT_MAYBE
2010/11/12 12:36:40| peerSelectIcpPing: 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&
2010/11/12 12:36:40| peerAddFwdServer: adding DIRECT DIRECT
2010/11/12 12:36:40| peerSelectCallback: 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&
2010/11/12 12:36:40| cbdataValid: 0xb326b8
.....
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'
2010/11/12 12:36:40| comm_select: timeout 134
2010/11/12 12:36:40| do_comm_select: 1 fds ready
2010/11/12 12:36:40| comm_call_handlers(): got fd=27 read_event=0 write_event=4 F->read_handler=(nil) F->write_handler=0x42adb0
2010/11/12 12:36:40| comm_remove_close_handler: FD 27, handler=0x429bd0, data=0xaf9008
2010/11/12 12:36:40| cbdataUnlock: 0xaf9008
2010/11/12 12:36:40| commSetTimeout: FD 27 timeout -1
2010/11/12 12:36:40| commConnectFree: FD 27
2010/11/12 12:36:40| cbdataFree: 0xaf9008
2010/11/12 12:36:40| cbdataFree: Freeing 0xaf9008

---------output ends from cache.log using debug level ALL,9-------------------------------

Regards,
Saurabh
Received on Mon Nov 22 2010 - 12:09:25 MST

This archive was generated by hypermail 2.2.0 : Tue Nov 23 2010 - 12:00:02 MST