VideoCache

pfSense: High CPU Load with Videocache 1.9.3.

by andylai on 27 Mar 2010

I just updated my pfSense box (1.2.2) previously running Videocache 1.9.2 to 1.9.3 (just receive from admin). After configuring the /etc/videocache.conf and /usr/local/pkg/squid.inc as running with old version 1.9.2. But this time I didn't change the /usr/share/videocache/videocache.py cause I believe admin had make the necessary modification on it.

Right after I restarted Squid, the pfSense starting to overload on its CPU. System log showing error on Squid,

Mar 27 14:02:44     php: /pkg_edit.php: Reloading Squid for configuration sync
Mar 27 14:02:49     check_reload_status: reloading filter
Mar 27 14:03:32     php: /pkg_edit.php: Reloading Squid for configuration sync
Mar 27 14:03:44     squid[6726]: The url_rewriter helpers are crashing too rapidly, need help!
Mar 27 14:03:44     kernel: pid 6726 (squid), uid 62: exited on signal 6
Mar 27 14:03:44     squid[6713]: Squid Parent: child process 6726 exited due to signal 6
Mar 27 14:03:52     squid[6713]: Squid Parent: child process 8019 started

The Videocache log starting to grow very big (over 100MB) containing same message,

2010-03-27 14:10:20,899 8020 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:10:20,912 8020 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:10:20,913 8020 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:10:20,913 8020 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:10:20,913 8020 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:10:20,914 8020 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:10:20,914 8020 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:10:20,914 8020 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:10:20,915 8020 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:10:20,915 8020 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:10:20,915 8020 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:10:20,916 8020 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:10:20,916 8020 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:10:20,917 8020 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:10:20,917 8020 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:10:20,917 8020 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,158 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,158 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,158 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,159 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,159 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,159 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,160 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,160 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,160 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,161 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,161 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,161 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,162 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,162 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,163 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,164 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,164 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,164 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,165 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,165 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,165 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,166 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,166 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,166 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,167 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,167 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,167 8022 - - RELOAD - videocache plugin was reloaded.
2010-03-27 14:12:47,168 8022 - - RELOAD - videocache plugin was reloaded.

Here I also paste,

Squid ACLs added inside /usr/local/pkg/squid.inc : http://pastebin.com/XwyvqhJu

/etc/videocache.conf : http://pastebin.com/vb8xTnXt

Note,
Because I updated the 1.9.3 on active production pfSense system so when error occur I had to temporary move back to 1.9.2 first cause it is crashing the pfSense system. But when I downgraded back to 1.9.2 (redo all configuration) the pfSense system when back normal after reboot (no more high CPU load).

10 Answers

by Kulbir Saini on 29 Mar 2010

Hi!

Please do according to this checklist
1. Determine the user who owns/runs squid process (it'll either with proxy or squid).
2. Check if /var/spool/videocache is owned by squid user.
3. Check if /var/log/videocache is owned by squid user.
4. Check if any python process is listening on port 9100.

Plus your squid.conf contains old acls. Please update them from installation page.

Please report your observations.

Thank You!

by andylai on 30 Mar 2010

While waiting for admin respond, I had configure another non production testing platform with pfSense 1.2.2 to test the VideoCache 1.9.3.

After successfully install and configure pfSense 1.2.2 with Squid 2.7.7 and tested in working condition. I started to install necessary python packages,

python26-2.6.4
py26-bsddb
py26-gdbm
py26-sqlite3
py26-tkinter

and also the critical component to run VideoCache,

py26-urlgrabber
py26-iniparse

then of course the VideoCache 1.9.3 bundle.

I had make some changes in /etc/videocache.conf like,

cache_host = 192.168.1.1
proxy = http://192.168.1.1:3128/
max_parallel_downloads = 3
video_lifetime = 90
rpc_host = 192.168.1.1

follow by editing the /usr/local/pkg/squid.inc by adding what instructed by admin from last reply (using the original alcs provided).

http://pastebin.com/nwMirhur

I link /var/spool/videocache to /usr/local/www/videocache.

Then I change owner of /var/spool/videocache, /var/log/videocache and /usr/local/www/videocache/ to proxy:proxy as Squid Owner in pfSense (FreeBSD).

# chown -R proxy:proxy /var/spool/videocache
# chown -R proxy:proxy /usr/local/www/videocache
# touch /var/log/videocache/videocache.log
# chown -R proxy:proxy /var/log/videocache/
# chmod -R 755 /var/log/videocache/

/var/log/
drwxr-xr-x 2 proxy proxy 512B Mar 29 02:18 videocache

/var/spool/
drwxr-xr-x 17 proxy proxy 512B Mar 29 02:16 videocache

This end my configuration on VideoCache in pfSense. So I reboot the pfSense for all setting to take place.

At first everything seem fine, but after a while the system starting to show high CPU load again. There is no error message in System Log, everything in pfSense seem OK and proxy service still working. I can still serf the internet with proxy enable.

Mar 29 02:37:48     php: /pkg_edit.php: Reloading Squid for configuration sync
Mar 29 02:37:59     check_reload_status: reloading filter
Mar 29 02:38:05     php: /pkg_edit.php: Reloading Squid for configuration sync

After 2 minutes I check the /var/log/videocache/ thing starting to get really wrong,

total 337860
-rwxr-xr-x  1 proxy  proxy   165M Mar 29 02:39 videocache.log.1
-rw-r-----  1 proxy  proxy   444B Mar 29 02:38 videocache.log

The videocache.log file starting to grow bigger and bigger. I think that was causing the high CPU load. I checked the content of the log file. It's all make out of this line,

2010-03-29 02:38:17,777 4955 - - RELOAD - videocache plugin was reloaded.
2010-03-29 02:38:17,779 4960 - - RELOAD - videocache plugin was reloaded.
2010-03-29 02:38:17,780 4961 - - RELOAD - videocache plugin was reloaded.
2010-03-29 02:38:17,781 4962 - - RELOAD - videocache plugin was reloaded.
2010-03-29 02:38:17,782 4963 - - RELOAD - videocache plugin was reloaded.
2010-03-29 02:38:17,783 4964 - - RELOAD - videocache plugin was reloaded.

continuing non stop. I have no idea on what's related to the above problem.

Hope to see admin reply soon. Thanks.

by andylai on 30 Mar 2010

ln -s /dev/null /var/log/videocache/videocache.log is not going to work. I just tested it. It still load the CPU to 100%.

by Kulbir Saini on 30 Mar 2010

Hi!

Thanks for the detailed report. I was helping a client with videocache yesterday. Everything was fine other than similar reload messages in videocache.log. And later it turned out that his SELinux was in Enforcing mode and it was not allowing videocache to work properly.

Can you please check your selinux settings? And if it is enabled (which is the default for most linux/unix operating systems), try disabling it and then restarting squid.

Thank You!

by andylai on 31 Mar 2010

I had open a thread at pfSense forum to ask about disabling SELinux Enforcing Mode. I am not sure how to disable it because I didn't install GRUB (add enforcing=0 behind kernel). I guest it should be adding "enforcing=0" or "selinux=0" in /boot/loader.conf. Anyway I was waiting for pfSense expert to verify that.

While waiting I was continuing testing VideoCache at my testing platform. And I had found something interesting about this problem.

1) First I boot up pfSense without adding the VideoCache ACLs into /usr/local/pkg/squid.inc (all other setting was configure properly like /etc/videocache.conf).
2) After pfSense successfully booted up. I add the ACLs into /usr/local/pkg/squid.inc. Then I refresh squid service. And WAHLA....it works (look like working).

/var/log/videocache/videocache.log

2010-03-31 10:29:59,858 3167 - - XMLRPCSERVER - Starting XMLRPCServer on port 9100.
2010-03-31 10:29:59,859 3167 - - SCHEDULEDER - Download Scheduler starting.
2010-03-31 10:29:59,859 3167 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:29:59,941 3157 - - XMLRPCSERVER - Starting XMLRPCServer on port 9100.
2010-03-31 10:29:59,942 3157 - - SCHEDULEDER - Download Scheduler starting.
2010-03-31 10:29:59,942 3157 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:00,206 3163 - - XMLRPCSERVER - Starting XMLRPCServer on port 9100.
2010-03-31 10:30:00,207 3163 - - SCHEDULEDER - Download Scheduler starting.
2010-03-31 10:30:00,208 3163 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:00,462 3158 - - SCHEDULEDER - Download Scheduler starting.
2010-03-31 10:30:00,463 3158 - - XMLRPCSERVER - Starting XMLRPCServer on port 9100.
2010-03-31 10:30:00,463 3158 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:02,927 3161 - - XMLRPCSERVER - Starting XMLRPCServer on port 9100.
2010-03-31 10:30:02,927 3161 - - SCHEDULEDER - Download Scheduler starting.
2010-03-31 10:30:02,927 3161 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:03,782 3166 - - XMLRPCSERVER - Starting XMLRPCServer on port 9100.
2010-03-31 10:30:03,783 3166 - - SCHEDULEDER - Download Scheduler starting.
2010-03-31 10:30:03,783 3166 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,055 3168 - - XMLRPCSERVER - Starting XMLRPCServer on port 9100.
2010-03-31 10:30:04,056 3168 - - SCHEDULEDER - Download Scheduler starting.
2010-03-31 10:30:04,056 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,066 3168 - - RELOAD - videocache plugin was reloaded.
.........
......... same RELOAD message (85 lines)
.........
2010-03-31 10:30:04,150 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,150 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,151 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,151 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,151 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,151 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,151 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,152 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,152 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,152 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,152 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,152 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,153 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,153 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,153 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,153 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,153 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,153 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,154 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,154 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,154 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,154 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,154 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,155 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,155 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,155 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,155 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,155 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,156 3168 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:04,928 3165 - - XMLRPCSERVER - Starting XMLRPCServer on port 9100.
2010-03-31 10:30:04,928 3165 - - SCHEDULEDER - Download Scheduler starting.
2010-03-31 10:30:04,928 3165 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:05,589 3164 - - XMLRPCSERVER - Starting XMLRPCServer on port 9100.
2010-03-31 10:30:05,589 3164 - - SCHEDULEDER - Download Scheduler starting.
2010-03-31 10:30:05,590 3164 - - RELOAD - videocache plugin was reloaded.
2010-03-31 10:30:05,762 3195 - - XMLRPCSERVER - Starting XMLRPCServer on port 9100.
2010-03-31 10:30:05,763 3195 - - SCHEDULEDER - Download Scheduler starting.

Altought is still contain lot of noisy stack print but it eventually stop. And it didn't overload the CPU anymore.

3) So I test play some Youtube video and the log show,

(Downloading Video)
2010-03-31 09:29:44,621 6538 192.168.1.201 - REQUEST - http://www.youtube.com/get_video?video_id=xm01KrsO8KY&t=vjVQa1PpcFM25ICe02xhMhVOVRp4N7_OH_9zrBNY-aY=&el=detailpage&ps=&fmt=34&asv=2&noflv=1
2010-03-31 09:29:44,621 6538 192.168.1.201 xm01KrsO8KY URL_HIT YOUTUBE http://www.youtube.com/get_video?video_id=xm01KrsO8KY&t=vjVQa1PpcFM25ICe02xhMhVOVRp4N7_OH_9zrBNY-aY=&el=detailpage&ps=&fmt=34&asv=2&noflv=1
2010-03-31 09:29:44,621 6538 192.168.1.201 xm01KrsO8KY CACHE_MISS YOUTUBE Requested video was not found in cache.
2010-03-31 09:29:44,630 6538 192.168.1.201 xm01KrsO8KY NEW_URL YOUTUBE http://www.youtube.com/get_video?video_id=xm01KrsO8KY&t=vjVQa1PpcFM25ICe02xhMhVOVRp4N7_OH_9zrBNY-aY=&el=detailpage&ps=&fmt=34&asv=2&noflv=1
2010-03-31 09:29:46,908 6538 192.168.1.201 xm01KrsO8KY SCHEDULED YOUTUBE Video scheduled for download.
2010-03-31 09:29:46,931 6538 192.168.1.1 - REQUEST - http://www.youtube.com/get_video?video_id=xm01KrsO8KY&t=vjVQa1PpcFM25ICe02xhMhVOVRp4N7_OH_9zrBNY-aY=&el=detailpage&ps=&fmt=34&asv=2
2010-03-31 09:29:46,931 6538 192.168.1.1 xm01KrsO8KY URL_HIT YOUTUBE http://www.youtube.com/get_video?video_id=xm01KrsO8KY&t=vjVQa1PpcFM25ICe02xhMhVOVRp4N7_OH_9zrBNY-aY=&el=detailpage&ps=&fmt=34&asv=2
2010-03-31 09:29:46,932 6538 192.168.1.1 xm01KrsO8KY CACHE_MISS YOUTUBE Requested video was not found in cache.
2010-03-31 09:29:46,936 6538 192.168.1.1 xm01KrsO8KY NEW_URL YOUTUBE http://www.youtube.com/get_video?video_id=xm01KrsO8KY&t=vjVQa1PpcFM25ICe02xhMhVOVRp4N7_OH_9zrBNY-aY=&el=detailpage&ps=&fmt=34&asv=2
2010-03-31 09:34:35,897 10272 192.168.1.201 xm01KrsO8KY DOWNLOAD YOUTUBE 12567290 Video was downloaded and cached.

(Serving Video)
2010-03-31 10:34:11,149 3195 192.168.1.201 - REQUEST - http://www.youtube.com/get_video?video_id=xm01KrsO8KY&t=vjVQa1PpcFOK5au1XUKtRp26okU6tOFSQsQYlllONvM=&el=detailpage&ps=&fmt=34&asv=2&noflv=1
2010-03-31 10:34:11,151 3195 192.168.1.201 xm01KrsO8KY URL_HIT YOUTUBE http://www.youtube.com/get_video?video_id=xm01KrsO8KY&t=vjVQa1PpcFOK5au1XUKtRp26okU6tOFSQsQYlllONvM=&el=detailpage&ps=&fmt=34&asv=2&noflv=1
2010-03-31 10:34:11,186 3195 192.168.1.201 xm01KrsO8KY CACHE_HIT YOUTUBE Video was served from cache.
2010-03-31 10:34:11,186 3195 192.168.1.201 xm01KrsO8KY NEW_URL YOUTUBE 303:http://192.168.1.1/videocache/youtube/xm01KrsO8KY?video_id=xm01KrsO8KY&t=vjVQa1PpcFOK5au1XUKtRp26okU6tOFSQsQYlllONvM=&el=detailpage&ps=&fmt=34&asv=2&noflv=1

Everthing seem fine.

4) Then I record down the python process while the system was still alright.

USER     PID %CPU %MEM   VSZ   RSS  TT  STAT STARTED      TIME COMMAND
proxy   1966  0.0  0.7 18428 10804  ??  I     9:14AM   0:01.71 (squid) -D (squi
proxy   6538  0.0  0.6 11228  8884  ??  I     9:21AM   0:00.26 (python) /usr/sh
proxy   7574  0.0  0.6 10844  8672  ??  I     9:22AM   0:00.13 (python) /usr/sh
proxy   7575  0.0  0.6 10844  8672  ??  I     9:22AM   0:00.13 (python) /usr/sh
proxy   7576  0.0  0.6 10844  8672  ??  I     9:22AM   0:00.13 (python) /usr/sh
proxy   7577  0.0  0.6 10844  8672  ??  I     9:22AM   0:00.13 (python) /usr/sh
proxy   7578  0.0  0.6 10844  8672  ??  I     9:22AM   0:00.13 (python) /usr/sh
proxy   7579  0.0  0.6 10844  8672  ??  I     9:22AM   0:00.13 (python) /usr/sh
proxy   7580  0.0  0.6 10844  8672  ??  I     9:22AM   0:00.13 (python) /usr/sh
proxy   7581  0.0  0.6 10844  8672  ??  I     9:22AM   0:00.13 (python) /usr/sh
proxy   7582  0.0  0.6 10844  8672  ??  I     9:22AM   0:00.13 (python) /usr/sh
proxy   7583  0.0  0.6 10844  8672  ??  I     9:22AM   0:00.13 (python) /usr/sh

5) Then I reboot the pfSense with the ACLs in /usr/local/pkg/squid.inc
6) The system immediately start to "BERSERK". CPU overload at 100% and /var/log/videocache/videocache.log starting to pile up again.

total 189248
-rw-r-----  1 proxy  proxy    92M Mar 31 09:46 videocache.log.1
-rw-r-----  1 proxy  proxy     0B Mar 31 09:42 videocache.log

7) Then I try record the python process again. This time thing look very difference while the system was BERSERKING.

USER     PID %CPU %MEM   VSZ   RSS  TT  STAT STARTED      TIME COMMAND
proxy   2007  0.0  0.7 17404 10168  ??  I     9:40AM   0:00.10 (squid) -D (squi
proxy   2014  6.5  0.6 11228  8776  ??  R     9:40AM   0:09.14 (python) /usr/sh
proxy   1873  6.4  0.6 11228  8772  ??  R     9:40AM   0:08.64 (python) /usr/sh
proxy   1886  5.6  0.6 11228  8756  ??  R     9:40AM   0:08.79 (python) /usr/sh
proxy   2009  5.6  0.6 11228  8776  ??  R     9:40AM   0:08.56 (python) /usr/sh
proxy   2019  5.6  0.6 11228  8776  ??  R     9:40AM   0:08.68 (python) /usr/sh
proxy   1890  5.3  0.6 11228  8756  ??  R     9:40AM   0:08.69 (python) /usr/sh
proxy   2017  5.3  0.6 11228  8764  ??  R     9:40AM   0:08.80 (python) /usr/sh
proxy   2011  4.9  0.6 11228  8776  ??  R     9:40AM   0:09.02 (python) /usr/sh
proxy   1893  4.6  0.6 11228  8768  ??  R     9:40AM   0:08.36 (python) /usr/sh
proxy   2016  4.6  0.6 11228  8776  ??  R     9:40AM   0:08.37 (python) /usr/sh
proxy   1869  4.5  0.6 11228  8768  ??  R     9:40AM   0:08.44 (python) /usr/sh
proxy   1891  4.5  0.6 11228  8756  ??  R     9:40AM   0:08.39 (python) /usr/sh
proxy   1892  4.5  0.6 11228  8760  ??  R     9:40AM   0:08.40 (python) /usr/sh
proxy   2013  4.5  0.6 11228  8780  ??  R     9:40AM   0:08.25 (python) /usr/sh
proxy   2020  4.4  0.6 11228  8776  ??  R     9:40AM   0:08.25 (python) /usr/sh
proxy   2018  4.3  0.6 11228  8776  ??  R     9:40AM   0:08.42 (python) /usr/sh
proxy   1872  4.2  0.6 11228  8760  ??  R     9:40AM   0:07.40 (python) /usr/sh
proxy   1888  4.2  0.6 11228  8824  ??  R     9:40AM   0:07.72 (python) /usr/sh
proxy   2010  4.0  0.6 11228  8764  ??  R     9:40AM   0:08.10 (python) /usr/sh
proxy   1880  3.6  0.6 11228  8756  ??  R     9:40AM   0:08.08 (python) /usr/sh

it seem like python process grow in double compare to while the system was alright. And it is taking up %CPU.

8) It make me think that VideoCache is actually double loaded if the system reboot. That's when I noticed pfSense actually had Squid exit and start back again everytime when pfSense is starting even there is no VideoCache enable.

Mar 31 10:37:59     php: : Reloading Squid for configuration sync
Mar 31 10:38:00     last message repeated 6 times
Mar 31 10:38:00     squid[1862]: Squid Parent: child process 1864 started
Mar 31 10:38:00     check_reload_status: check_reload_status is starting
Mar 31 10:38:05     Squid_Alarm[1957]: Squid has exited. Reconfiguring filter.
Mar 31 10:38:05     Squid_Alarm[1959]: Attempting restart...
Mar 31 10:38:05     squid[1966]: Squid Parent: child process 1969 started
Mar 31 10:38:08     Squid_Alarm[1976]: Reconfiguring filter...
Mar 31 10:38:09     Squid_Alarm[2505]: Squid has resumed. Reconfiguring filter.
Mar 31 12:06:33     php: /pkg_edit.php: Reloading Squid for configuration sync
Mar 31 12:06:35     php: /pkg_edit.php: Reloading Squid for configuration sync
Mar 31 12:06:37     check_reload_status: reloading filter

9) Anyway I was thinking to keep on testing in my testing platform by not adding the ACLs into /usr/local/pkg/squid.inc. It sound ridiculous to put into a production system cause it will BERSERK if the system were to reboot. I will wait for pfSense Team to give result on disabling the "enforcing mode"

by andylai on 31 Mar 2010

Now assume that I continue this temporary by adding in the ACLs after the system start and VideoCache should had been working.

I had try let VideoCache download some Youtube video.

/var/spool/videocache/youtube/

total 157536
-rw-r--r--  1 proxy  proxy    12M Mar 31 10:34 xm01KrsO8KY
-rw-r--r--  1 proxy  proxy    11M Mar 31 09:23 29NXaLxMIoY
-rw-r--r--  1 proxy  proxy    30M Mar 31 09:22 Bh2mE6K7y1g
-rw-r--r--  1 proxy  proxy    12M Mar 31 04:01 DDjIBG5RBo8
-rw-r--r--  1 proxy  proxy    12M Mar 31 03:58 HK15Fwho6Ys

Then I play it back again on the same PC after clearing and restart Mozilla. It (same Youtube video) actually re-download again and not getting it from the cache. Altought the videocache.log show the video is served from cache.

/var/log/videocache/videocache.log

(download video)
2010-03-31 09:29:44,621 6538 192.168.1.201 - REQUEST - http://www.youtube.com/get_video?video_id=xm01KrsO8KY&t=vjVQa1PpcFM25ICe02xhMhVOVRp4N7_OH_9zrBNY-aY=&el=detailpage&ps=&fmt=34&asv=2&noflv=1
2010-03-31 09:29:44,621 6538 192.168.1.201 xm01KrsO8KY URL_HIT YOUTUBE http://www.youtube.com/get_video?video_id=xm01KrsO8KY&t=vjVQa1PpcFM25ICe02xhMhVOVRp4N7_OH_9zrBNY-aY=&el=detailpage&ps=&fmt=34&asv=2&noflv=1
2010-03-31 09:29:44,621 6538 192.168.1.201 xm01KrsO8KY CACHE_MISS YOUTUBE Requested video was not found in cache.
2010-03-31 09:29:44,630 6538 192.168.1.201 xm01KrsO8KY NEW_URL YOUTUBE http://www.youtube.com/get_video?video_id=xm01KrsO8KY&t=vjVQa1PpcFM25ICe02xhMhVOVRp4N7_OH_9zrBNY-aY=&el=detailpage&ps=&fmt=34&asv=2&noflv=1
2010-03-31 09:29:46,908 6538 192.168.1.201 xm01KrsO8KY SCHEDULED YOUTUBE Video scheduled for download.
2010-03-31 09:29:46,931 6538 192.168.1.1 - REQUEST - http://www.youtube.com/get_video?video_id=xm01KrsO8KY&t=vjVQa1PpcFM25ICe02xhMhVOVRp4N7_OH_9zrBNY-aY=&el=detailpage&ps=&fmt=34&asv=2
2010-03-31 09:29:46,931 6538 192.168.1.1 xm01KrsO8KY URL_HIT YOUTUBE http://www.youtube.com/get_video?video_id=xm01KrsO8KY&t=vjVQa1PpcFM25ICe02xhMhVOVRp4N7_OH_9zrBNY-aY=&el=detailpage&ps=&fmt=34&asv=2
2010-03-31 09:29:46,932 6538 192.168.1.1 xm01KrsO8KY CACHE_MISS YOUTUBE Requested video was not found in cache.
2010-03-31 09:29:46,936 6538 192.168.1.1 xm01KrsO8KY NEW_URL YOUTUBE http://www.youtube.com/get_video?video_id=xm01KrsO8KY&t=vjVQa1PpcFM25ICe02xhMhVOVRp4N7_OH_9zrBNY-aY=&el=detailpage&ps=&fmt=34&asv=2
2010-03-31 09:34:35,897 10272 192.168.1.201 xm01KrsO8KY DOWNLOAD YOUTUBE 12567290 Video was downloaded and cached.

(serving video)
2010-03-31 10:34:11,149 3195 192.168.1.201 - REQUEST - http://www.youtube.com/get_video?video_id=xm01KrsO8KY&t=vjVQa1PpcFOK5au1XUKtRp26okU6tOFSQsQYlllONvM=&el=detailpage&ps=&fmt=34&asv=2&noflv=1
2010-03-31 10:34:11,151 3195 192.168.1.201 xm01KrsO8KY URL_HIT YOUTUBE http://www.youtube.com/get_video?video_id=xm01KrsO8KY&t=vjVQa1PpcFOK5au1XUKtRp26okU6tOFSQsQYlllONvM=&el=detailpage&ps=&fmt=34&asv=2&noflv=1
2010-03-31 10:34:11,186 3195 192.168.1.201 xm01KrsO8KY CACHE_HIT YOUTUBE Video was served from cache.
2010-03-31 10:34:11,186 3195 192.168.1.201 xm01KrsO8KY NEW_URL YOUTUBE 303:http://192.168.1.1/videocache/youtube/xm01KrsO8KY?video_id=xm01KrsO8KY&t=vjVQa1PpcFOK5au1XUKtRp26okU6tOFSQsQYlllONvM=&el=detailpage&ps=&fmt=34&asv=2&noflv=1

(serving video)
2010-03-31 09:22:38,946 6538 192.168.1.201 - REQUEST - http://www.youtube.com/get_video?fmt=34&asv=3&video_id=Bh2mE6K7y1g&el=detailpage&t=vjVQa1PpcFMJiU5dGDiOq9_ivPXrZQ9stb4IteNCTZ8=&noflv=1
2010-03-31 09:22:38,947 6538 192.168.1.201 Bh2mE6K7y1g URL_HIT YOUTUBE http://www.youtube.com/get_video?fmt=34&asv=3&video_id=Bh2mE6K7y1g&el=detailpage&t=vjVQa1PpcFMJiU5dGDiOq9_ivPXrZQ9stb4IteNCTZ8=&noflv=1
2010-03-31 09:22:38,948 6538 192.168.1.201 Bh2mE6K7y1g CACHE_HIT YOUTUBE Video was served from cache.
2010-03-31 09:22:38,948 6538 192.168.1.201 Bh2mE6K7y1g NEW_URL YOUTUBE 303:http://192.168.1.1/videocache/youtube/Bh2mE6K7y1g?fmt=34&asv=3&video_id=Bh2mE6K7y1g&el=detailpage&t=vjVQa1PpcFMJiU5dGDiOq9_ivPXrZQ9stb4IteNCTZ8=&noflv=1

(serving video)
2010-03-31 09:23:59,777 6538 192.168.1.201 - REQUEST - http://www.youtube.com/get_video?asv=3&fmt=34&el=detailpage&noflv=1&t=vjVQa1PpcFP25XR4uTrxvNzIb9y2fOiBDHY_tit4MSY=&video_id=29NXaLxMIoY
2010-03-31 09:23:59,778 6538 192.168.1.201 29NXaLxMIoY URL_HIT YOUTUBE http://www.youtube.com/get_video?asv=3&fmt=34&el=detailpage&noflv=1&t=vjVQa1PpcFP25XR4uTrxvNzIb9y2fOiBDHY_tit4MSY=&video_id=29NXaLxMIoY
2010-03-31 09:23:59,778 6538 192.168.1.201 29NXaLxMIoY CACHE_HIT YOUTUBE Video was served from cache.
2010-03-31 09:23:59,778 6538 192.168.1.201 29NXaLxMIoY NEW_URL YOUTUBE 303:http://192.168.1.1/videocache/youtube/29NXaLxMIoY?asv=3&fmt=34&el=detailpage&noflv=1&t=vjVQa1PpcFP25XR4uTrxvNzIb9y2fOiBDHY_tit4MSY=&video_id=29NXaLxMIoY

Funny!!!!! I was wondering where's the video served to?

by andylai on 31 Mar 2010

oppssss.....pfSense admin return my thread saying that's is no SELinux support in Freebsd.

http://forum.pfsense.org/index.php/topic,23965.0.html

T.T

by Kulbir Saini on 2 Apr 2010

Hi!

It must be a pfsense specific problem because I myself have it working on CentOS 5.4 and Fedora and other are also using it on other platforms. Please let me know if you are in for live support kind of thing where we can debug the problem together.

Thank You!

by andylai on 3 Apr 2010

I think it's pfSense specific problem also. Consider seeing all VideoCache users already start caching with the new 1.9.3. bundle.

I try to search for VideoCache user at pfSense forum but there were not much pfSense user using VideoCache and most of them who did haven't got any luck.

For pfSense base system I'll going to give up on VideoCache and switch to Lusca. I temporary was not good enough to configure a Fedora or other Linux OS. I just start using Linux base system not long ago (newbie). I started to use pfSense bacause it didn't need to much knowledge on Linux in order to use it.

Maybe I'll wait for some other pfSense user who was more knowledgeable to fix those errors.

Thanks for all the help. Thank you very much.

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