Videocache is no longer in development.
loops problem
by mustafa raji on 1 Mar 2012hi admin
there is a loop in my cache server, the access.log files show this logs
1330587634.576 0 192.168.40.1 TCP_HIT/302 973 GET http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback? - NONE/- text/html
1330587634.583 0 192.168.40.1 TCP_HIT/302 973 GET http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback? - NONE/- text/html
1330587634.589 0 192.168.40.1 TCP_HIT/302 973 GET http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback? - NONE/- text/html
1330587634.595 0 192.168.40.1 TCP_HIT/302 973 GET http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback? - NONE/- text/html
1330587634.602 0 192.168.40.1 TCP_HIT/302 973 GET http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback? - NONE/- text/html
1330587634.608 0 192.168.40.1 TCP_HIT/302 973 GET http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback? - NONE/- text/html
1330587634.615 0 192.168.40.1 TCP_HIT/302 973 GET http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback? - NONE/- text/html
1330587634.621 0 192.168.40.1 TCP_HIT/302 973 GET http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback? - NONE/- text/html
1330587634.627 0 192.168.40.1 TCP_HIT/302 973 GET http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback? - NONE/- text/html
1330587634.634 0 192.168.40.1 TCP_HIT/302 973 GET http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback? - NONE/- text/html
1330587634.640 0 192.168.40.1 TCP_HIT/302 973 GET http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback? - NONE/- text/html
1330587634.646 0 192.168.40.1 TCP_HIT/302 973 GET http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback? - NONE/- text/html
1330587634.652 0 192.168.40.1 TCP_HIT/302 973 GET http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback? - NONE/- text/html
1330587634.659 0 192.168.40.1 TCP_HIT/302 973 GET http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback? - NONE/- text/html
1330587634.665 0 192.168.40.1 TCP_HIT/302 973 GET http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback? - NONE/- text/html
1330587634.671 0 192.168.40.1 TCP_HIT/302 973 GET http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback? - NONE/- text/html
there is big number of these logs request in my access.log
scheduler.log shows
01/Mar/2012:09:05:47 1216 INFO - - VIDEOS_RECEIVED - Received 1 videos from Videocache. -
01/Mar/2012:09:20:35 1216 INFO - - VIDEOS_RECEIVED - Received 1 videos from Videocache. -
01/Mar/2012:09:20:45 1216 INFO - - VIDEOS_RECEIVED - Received 1 videos from Videocache. -
01/Mar/2012:09:21:34 1216 INFO - - VIDEOS_RECEIVED - Received 1 videos from Videocache. -
01/Mar/2012:09:21:44 1216 INFO - - VIDEOS_RECEIVED - Received 1 videos from Videocache. -
01/Mar/2012:09:21:54 1216 INFO - - VIDEOS_RECEIVED - Received 2 videos from Videocache. -
01/Mar/2012:09:30:09 1216 INFO - - VIDEOS_RECEIVED - Received 1 videos from Videocache. -
01/Mar/2012:09:30:14 1216 INFO - - VIDEOS_RECEIVED - Received 1 videos from Videocache. -
01/Mar/2012:09:30:58 1216 INFO - - VIDEOS_RECEIVED - Received 1 videos from Videocache. -
01/Mar/2012:09:31:08 1216 INFO - - VIDEOS_RECEIVED - Received 1 videos from Videocache. -
01/Mar/2012:09:34:04 1216 INFO - - VIDEOS_RECEIVED - Received 1 videos from Videocache. -
01/Mar/2012:09:34:54 1216 INFO - - VIDEOS_RECEIVED - Received 1 videos from Videocache. -
01/Mar/2012:09:36:46 1216 INFO - - VIDEOS_RECEIVED - Received 1 videos from Videocache. -
01/Mar/2012:09:40:42 1216 INFO - - VIDEOS_RECEIVED - Received 1 videos from Videocache. -
again big number of these logs in the scheduler.log file
the videocache.log shows
01/Mar/2012:10:40:34 11269 INFO 192.168.40.1 YOUTUBE CACHE_MISS 085c8ec3d220b636 Requested video was not found in cache. -
01/Mar/2012:10:40:34 11269 INFO 192.168.40.1 YOUTUBE URL_HIT 085c8ec3d220b636 http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback?sparams=algorithm%2Cburst%2Ccp%2Cfactor%2Cid%2Cip%2Cipbits%2Citag%2Csource%2Cexpire&fexp=907048%2C906358%2C910207%2C901401&algorithm=throttle-factor&itag=34&ip=95.0.0.0&burst=40&sver=3&signature=6B7BE437D02FB2301B0F063D7C96382E9FC3B711.944290978533AF59381862CE72508E9647995B29&source=youtube&expire=1330603302&key=yt1&ipbits=8&factor=1.25&cp=U0hSRVZLUV9FTENOMl9ORVVEOllaQUU5Zm83RXI4&id=085c8ec3d220b636&cm2=1 -
01/Mar/2012:10:40:34 11269 INFO 192.168.40.1 YOUTUBE CACHE_MISS 085c8ec3d220b636 Requested video was not found in cache. -
01/Mar/2012:10:40:34 11269 INFO 192.168.40.1 YOUTUBE URL_HIT 085c8ec3d220b636 http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback?sparams=algorithm%2Cburst%2Ccp%2Cfactor%2Cid%2Cip%2Cipbits%2Citag%2Csource%2Cexpire&fexp=907048%2C906358%2C910207%2C901401&algorithm=throttle-factor&itag=34&ip=95.0.0.0&burst=40&sver=3&signature=6B7BE437D02FB2301B0F063D7C96382E9FC3B711.944290978533AF59381862CE72508E9647995B29&source=youtube&expire=1330603302&key=yt1&ipbits=8&factor=1.25&cp=U0hSRVZLUV9FTENOMl9ORVVEOllaQUU5Zm83RXI4&id=085c8ec3d220b636&cm2=1 -
01/Mar/2012:10:40:34 11269 INFO 192.168.40.1 YOUTUBE CACHE_MISS 085c8ec3d220b636 Requested video was not found in cache. -
01/Mar/2012:10:40:34 11269 INFO 192.168.40.1 YOUTUBE URL_HIT 085c8ec3d220b636 http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback?sparams=algorithm%2Cburst%2Ccp%2Cfactor%2Cid%2Cip%2Cipbits%2Citag%2Csource%2Cexpire&fexp=907048%2C906358%2C910207%2C901401&algorithm=throttle-factor&itag=34&ip=95.0.0.0&burst=40&sver=3&signature=6B7BE437D02FB2301B0F063D7C96382E9FC3B711.944290978533AF59381862CE72508E9647995B29&source=youtube&expire=1330603302&key=yt1&ipbits=8&factor=1.25&cp=U0hSRVZLUV9FTENOMl9ORVVEOllaQUU5Zm83RXI4&id=085c8ec3d220b636&cm2=1 -
01/Mar/2012:10:40:34 11269 INFO 192.168.40.1 YOUTUBE CACHE_MISS 085c8ec3d220b636 Requested video was not found in cache. -
01/Mar/2012:10:40:34 11269 INFO 192.168.40.1 YOUTUBE URL_HIT 085c8ec3d220b636 http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback?sparams=algorithm%2Cburst%2Ccp%2Cfactor%2Cid%2Cip%2Cipbits%2Citag%2Csource%2Cexpire&fexp=907048%2C906358%2C910207%2C901401&algorithm=throttle-factor&itag=34&ip=95.0.0.0&burst=40&sver=3&signature=6B7BE437D02FB2301B0F063D7C96382E9FC3B711.944290978533AF59381862CE72508E9647995B29&source=youtube&expire=1330603302&key=yt1&ipbits=8&factor=1.25&cp=U0hSRVZLUV9FTENOMl9ORVVEOllaQUU5Zm83RXI4&id=085c8ec3d220b636&cm2=1 -
01/Mar/2012:10:40:34 11269 INFO 192.168.40.1 YOUTUBE CACHE_MISS 085c8ec3d220b636 Requested video was not found in cache. -
01/Mar/2012:10:40:34 11269 INFO 192.168.40.1 YOUTUBE URL_HIT 085c8ec3d220b636 http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback?sparams=algorithm%2Cburst%2Ccp%2Cfactor%2Cid%2Cip%2Cipbits%2Citag%2Csource%2Cexpire&fexp=907048%2C906358%2C910207%2C901401&algorithm=throttle-factor&itag=34&ip=95.0.0.0&burst=40&sver=3&signature=6B7BE437D02FB2301B0F063D7C96382E9FC3B711.944290978533AF59381862CE72508E9647995B29&source=youtube&expire=1330603302&key=yt1&ipbits=8&factor=1.25&cp=U0hSRVZLUV9FTENOMl9ORVVEOllaQUU5Zm83RXI4&id=085c8ec3d220b636&cm2=1 -
01/Mar/2012:10:40:34 11269 INFO 192.168.40.1 YOUTUBE CACHE_MISS 085c8ec3d220b636 Requested video was not found in cache. -
01/Mar/2012:10:40:34 11269 INFO 192.168.40.1 YOUTUBE URL_HIT 085c8ec3d220b636 http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback?sparams=algorithm%2Cburst%2Ccp%2Cfactor%2Cid%2Cip%2Cipbits%2Citag%2Csource%2Cexpire&fexp=907048%2C906358%2C910207%2C901401&algorithm=throttle-factor&itag=34&ip=95.0.0.0&burst=40&sver=3&signature=6B7BE437D02FB2301B0F063D7C96382E9FC3B711.944290978533AF59381862CE72508E9647995B29&source=youtube&expire=1330603302&key=yt1&ipbits=8&factor=1.25&cp=U0hSRVZLUV9FTENOMl9ORVVEOllaQUU5Zm83RXI4&id=085c8ec3d220b636&cm2=1 -
01/Mar/2012:10:40:34 11269 INFO 192.168.40.1 YOUTUBE CACHE_MISS 085c8ec3d220b636 Requested video was not found in cache. -
01/Mar/2012:10:40:34 11269 INFO 192.168.40.1 YOUTUBE URL_HIT 085c8ec3d220b636 http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videoplayback?sparams=algorithm%2Cburst%2Ccp%2Cfactor%2Cid%2Cip%2Cipbits%2Citag%2Csource%2Cexpire&fexp=907048%2C906358%2C910207%2C901401&algorithm=throttle-factor&itag=34&ip=95.0.0.0&burst=40&sver=3&signature=6B7BE437D02FB2301B0F063D7C96382E9FC3B711.944290978533AF59381862CE72508E9647995B29&source=youtube&expire=1330603302&key=yt1&ipbits=8&factor=1.25&cp=U0hSRVZLUV9FTENOMl9ORVVEOllaQUU5Zm83RXI4&id=085c8ec3d220b636&cm2=1 -
01/Mar/2012:10:40:34 11269 INFO 192.168.40.1 YOUTUBE CACHE_MISS 085c8ec3d220b636 Requested video was not found in cache. -
please if you notice how many request in the second, i have only 40 users and it's impossible to request these request in the same time
and the trace.log shows
return self._call_chain(*args)
File "/usr/lib/python2.7/urllib2.py", line 369, in _call_chain
result = func(*args)
File "/usr/lib/python2.7/urllib2.py", line 518, in http_error_default
raise HTTPError(req.get_full_url(), code, msg, hdrs, fp)
HTTPError: HTTP Error 404: Not Found
22/Feb/2012:16:26:37 687 192.168.40.1 YOUTUBE VIDEO_PAGE_ERR kNapZka5pY4
Traceback (most recent call last):
File "/usr/sbin/vc-scheduler", line 473, in cache_youtube_video
webpage = urllib2.urlopen(request).read()
File "/usr/lib/python2.7/urllib2.py", line 126, in urlopen
return _opener.open(url, data, timeout)
File "/usr/lib/python2.7/urllib2.py", line 397, in open
response = meth(req, response)
File "/usr/lib/python2.7/urllib2.py", line 510, in http_response
'http', request, response, code, msg, hdrs)
File "/usr/lib/python2.7/urllib2.py", line 435, in error
return self._call_chain(*args)
File "/usr/lib/python2.7/urllib2.py", line 369, in _call_chain
result = func(*args)
File "/usr/lib/python2.7/urllib2.py", line 518, in http_error_default
raise HTTPError(req.get_full_url(), code, msg, hdrs, fp)
HTTPError: HTTP Error 404: Not Found
22/Feb/2012:16:28:57 687 192.168.40.1 YOUTUBE VIDEO_PAGE_ERR kNapZka5pY4
Traceback (most recent call last):
File "/usr/sbin/vc-scheduler", line 473, in cache_youtube_video
webpage = urllib2.urlopen(request).read()
File "/usr/lib/python2.7/urllib2.py", line 126, in urlopen
return _opener.open(url, data, timeout)
File "/usr/lib/python2.7/urllib2.py", line 397, in open
response = meth(req, response)
File "/usr/lib/python2.7/urllib2.py", line 510, in http_response
'http', request, response, code, msg, hdrs)
File "/usr/lib/python2.7/urllib2.py", line 435, in error
return self._call_chain(*args)
File "/usr/lib/python2.7/urllib2.py", line 369, in _call_chain
result = func(*args)
File "/usr/lib/python2.7/urllib2.py", line 518, in http_error_default
raise HTTPError(req.get_full_url(), code, msg, hdrs, fp)
HTTPError: HTTP Error 404: Not Found
many logs like the log above
and many logs like the log below
21/Feb/2012:09:09:59 658 192.168.40.1 YOUTUBE CACHE_ERR ys263vIMC6k
Traceback (most recent call last):
File "/usr/sbin/vc-scheduler", line 424, in cache_remote_url
block = connection.read(16384)
File "/usr/lib/python2.7/socket.py", line 380, in read
data = self._sock.recv(left)
File "/usr/lib/python2.7/httplib.py", line 561, in read
s = self.fp.read(amt)
File "/usr/lib/python2.7/socket.py", line 380, in read
data = self._sock.recv(left)
timeout: timed out
21/Feb/2012:21:42:44 687 192.168.40.1 YOUTUBE CACHE_ERR wNDIs3HZd9c
Traceback (most recent call last):
File "/usr/sbin/vc-scheduler", line 424, in cache_remote_url
block = connection.read(16384)
File "/usr/lib/python2.7/socket.py", line 380, in read
data = self._sock.recv(left)
File "/usr/lib/python2.7/httplib.py", line 561, in read
s = self.fp.read(amt)
File "/usr/lib/python2.7/socket.py", line 380, in read
data = self._sock.recv(left)
timeout: timed out
21/Feb/2012:21:42:45 687 192.168.40.1 YOUTUBE CACHE_ERR ibOnTEGxEds
Traceback (most recent call last):
File "/usr/sbin/vc-scheduler", line 424, in cache_remote_url
block = connection.read(16384)
File "/usr/lib/python2.7/socket.py", line 380, in read
data = self._sock.recv(left)
File "/usr/lib/python2.7/httplib.py", line 561, in read
s = self.fp.read(amt)
File "/usr/lib/python2.7/socket.py", line 380, in read
data = self._sock.recv(left)
timeout: timed out
cache.log file contain these logs previously before i restart squid service
2012/03/01 10:15:27| Open FD READ/WRITE 175 Waiting for next request
2012/03/01 10:15:27| Open FD READ/WRITE 182 http://o-o.preferred.fra02s05.v20.lscache1.c.youtube.com/videop
2012/03/01 10:15:27| Open FD READ/WRITE 183 www.facebook.com idle connection
2012/03/01 10:15:27| Open FD READ/WRITE 184 http://www.alsabaah.com/uploads/pdf/2012/mar/2475/247500027.jpg
2012/03/01 10:15:27| Open FD READ/WRITE 188 http://o-o.preferred.fra02s05.v1.lscache6.c.youtube.com/videopl
2012/03/01 10:15:27| Open FD READ/WRITE 191 http://o-o.preferred.fra02s05.v11.lscache4.c.youtube.com/videop
2012/03/01 10:15:27| Open FD READ/WRITE 194 http://o-o.preferred.fra02s05.v1.lscache6.c.youtube.com/videopl
2012/03/01 10:15:27| Open FD READING 196 http://0-333.channel.facebook.com/ping?cb=vod
2012/03/01 10:15:27| Open FD WRITING 197 /var/squid/aufs3/01/9C/00019CB2
2012/03/01 10:15:27| Open FD READ/WRITE 199 http://o-o.preferred.fra02s05.v1.lscache6.c.youtube.com/videopl
2012/03/01 10:15:27| Open FD WRITING 200 http://0-333.channel.facebook.com/ping?cb=vod
2012/03/01 10:15:27| Open FD READ/WRITE 201 http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videop
2012/03/01 10:15:27| Open FD READ/WRITE 202 http://o-o.preferred.fra02s05.v8.lscache3.c.youtube.com/videopl
2012/03/01 10:15:27| Open FD READ/WRITE 203 http://o-o.preferred.fra02s05.v24.lscache1.c.youtube.com/videop
2012/03/01 10:15:27| Open FD READ/WRITE 205 http://o-o.preferred.fra02s05.v1.lscache6.c.youtube.com/videopl
2012/03/01 10:15:27| Open FD READ/WRITE 207 Waiting for next request
2012/03/01 10:15:27| Open FD READ/WRITE 208 http://www.asalmarble.com/fta_ehfa.jpg
2012/03/01 10:15:27| Open FD READ/WRITE 211 http://o-o.preferred.fra02s05.v11.lscache4.c.youtube.com/videop
2012/03/01 10:15:27| Open FD READ/WRITE 212 http://o-o.preferred.fra02s05.v1.lscache6.c.youtube.com/videopl
2012/03/01 10:15:27| Open FD READ/WRITE 213 http://www.ip2location.com/includes/js/controls.js
2012/03/01 10:15:27| Open FD READ/WRITE 215 http://personal.nl.avira-update.net/update/n_vdf/vbase002.vdf.g
2012/03/01 10:15:27| Open FD READ/WRITE 216 http://www.asalmarble.com/fta_lefa.jpg
2012/03/01 10:15:27| Open FD READ/WRITE 240 http://www.alsabaah.com/uploads/pdf/2012/mar/2475/247500027.jpg
2012/03/01 10:15:27| Open FD READ/WRITE 245 http://o-o.preferred.fra02s05.v1.lscache6.c.youtube.com/videopl
2012/03/01 10:15:27| Open FD READ/WRITE 265 http://o-o.preferred.fra02s05.v20.lscache1.c.youtube.com/videop
2012/03/01 10:15:27| Open FD READ/WRITE 267 http://o-o.preferred.fra02s05.v20.lscache1.c.youtube.com/videop
2012/03/01 10:15:27| Open FD READ/WRITE 269 http://o-o.preferred.fra02s05.v11.lscache4.c.youtube.com/videop
2012/03/01 10:15:27| Open FD READ/WRITE 270 http://o-o.preferred.fra02s05.v11.lscache4.c.youtube.com/videop
2012/03/01 10:15:27| Open FD READ/WRITE 276 http://o-o.preferred.fra02s05.v11.lscache4.c.youtube.com/videop
2012/03/01 10:15:27| Open FD READ/WRITE 291 Waiting for next request
please can you help me with this issue
1 Answers