VideoCache

loops problem

by mustafa raji on 1 Mar 2012

hi 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

by Kulbir Saini on 2 Mar 2012

Hi Mustafa,

It's difficult to say anything without having a look at your videocache.conf and squid.conf. Please send them in mail.

Thank You!

You need to sign in. Please sign in to add answer to this question.