Proxy server not responding to clients

nouman_younis@yahoo.com · 11-15-2010, 01:44 AM

I have deployed proxy server in my office about a month ago. I have about 7-8 client accessing it through port 3128. After some days of deployment, my server started creating problems. Some clients were not able to access proxy while other clients were accessing it. The error message which I found in cache.log was:

Code:

WARNING: Closing client 192.168.2.99 connection due to lifetime timeout

In this way it was disconnecting clients randomly. The problem resolves when I restart proxy server but after some time it again start creating similar problem.

Im sending my cache.log file

Code:

Last login: Mon Nov 15 12:37:29 2010 from 192.168.2.2
[root@localhost ~]# cat /var/log/squid/cache.log
2010/11/15 08:11:49| storeDirWriteCleanLogs: Starting...
2010/11/15 08:11:49|   Finished.  Wrote 57740 entries.
2010/11/15 08:11:49|   Took 0.0 seconds (4476316.0 entries/sec).
2010/11/15 08:11:49| logfileRotate: /var/log/squid/store.log
2010/11/15 08:11:49| logfileRotate: /var/log/squid/access.log
2010/11/15 08:22:11| Preparing for shutdown after 2338 requests
2010/11/15 08:22:11| Waiting 30 seconds for active connections to finish
2010/11/15 08:22:11| FD 12 Closing HTTP connection
2010/11/15 08:22:42| Shutting down...
2010/11/15 08:22:42| FD 13 Closing ICP connection
2010/11/15 08:22:42| WARNING: Closing client 192.168.2.150 connection due to lifetime timeout
2010/11/15 08:22:42|    http://download.microsoft.com/downlo...a/dotnetfx.exe
2010/11/15 08:22:42| WARNING: Closing client 192.168.2.150 connection due to lifetime timeout
2010/11/15 08:22:42|    http://download.bitdefender.com/wind...i2009/bdts.msi
2010/11/15 08:22:42| Closing unlinkd pipe on FD 10
2010/11/15 08:22:42| storeDirWriteCleanLogs: Starting...
2010/11/15 08:22:42|   Finished.  Wrote 57868 entries.
2010/11/15 08:22:42|   Took 0.0 seconds (3365396.9 entries/sec).
CPU Usage: 0.832 seconds = 0.304 user + 0.528 sys
Maximum Resident Size: 0 KB
Page faults with physical i/o: 1
Memory usage for squid via mallinfo():
        total space in arena:   11208 KB
        Ordinary blocks:        10798 KB     92 blks
        Small blocks:               0 KB      6 blks
        Holding blocks:           244 KB      1 blks
        Free Small blocks:          0 KB
        Free Ordinary blocks:     409 KB
        Total in use:           11042 KB 96%
        Total free:               409 KB 4%
2010/11/15 08:22:42| Squid Cache (Version 2.6.STABLE6): Exiting normally.
2010/11/15 08:25:00| Starting Squid Cache version 2.6.STABLE6 for i686-redhat-linux-gnu...
2010/11/15 08:25:00| Process ID 2700
2010/11/15 08:25:00| With 1024 file descriptors available
2010/11/15 08:25:00| Using epoll for the IO loop
2010/11/15 08:25:00| DNS Socket created at 0.0.0.0, port 32768, FD 5
2010/11/15 08:25:00| Adding domain localdomain from /etc/resolv.conf
2010/11/15 08:25:00| Adding nameserver 203.99.163.240 from /etc/resolv.conf
2010/11/15 08:25:00| User-Agent logging is disabled.
2010/11/15 08:25:00| Referer logging is disabled.
2010/11/15 08:25:00| Unlinkd pipe opened on FD 10
2010/11/15 08:25:00| Swap maxSize 2048000 KB, estimated 157538 objects
2010/11/15 08:25:00| Target number of buckets: 7876
2010/11/15 08:25:00| Using 8192 Store buckets
2010/11/15 08:25:00| Max Mem  size: 8192 KB
2010/11/15 08:25:00| Max Swap size: 2048000 KB
2010/11/15 08:25:00| Local cache digest enabled; rebuild/rewrite every 3600/3600 sec
2010/11/15 08:25:00| Rebuilding storage in /var/spool/squid (CLEAN)
2010/11/15 08:25:00| Using Least Load store dir selection
2010/11/15 08:25:00| Set Current Directory to /var/spool/squid
2010/11/15 08:25:00| Loaded Icons.
2010/11/15 08:25:02| Accepting proxy HTTP connections at 0.0.0.0, port 3128, FD 12.
2010/11/15 08:25:02| Accepting ICP messages at 0.0.0.0, port 3130, FD 13.
2010/11/15 08:25:02| WCCP Disabled.
2010/11/15 08:25:02| Ready to serve requests.
2010/11/15 08:25:02| Store rebuilding is  7.1% complete
2010/11/15 08:25:03| Done reading /var/spool/squid swaplog (57868 entries)
2010/11/15 08:25:03| Finished rebuilding storage from disk.
2010/11/15 08:25:03|     57868 Entries scanned
2010/11/15 08:25:03|         0 Invalid entries.
2010/11/15 08:25:03|         0 With invalid flags.
2010/11/15 08:25:03|     57868 Objects loaded.
2010/11/15 08:25:03|         0 Objects expired.
2010/11/15 08:25:03|         0 Objects cancelled.
2010/11/15 08:25:03|         0 Duplicate URLs purged.
2010/11/15 08:25:03|         0 Swapfile clashes avoided.
2010/11/15 08:25:03|   Took 2.5 seconds (22805.1 objects/sec).
2010/11/15 08:25:03| Beginning Validation Procedure
2010/11/15 08:25:03|   Completed Validation Procedure
2010/11/15 08:25:03|   Validated 57868 Entries
2010/11/15 08:25:03|   store_swap_size = 1060120k
2010/11/15 08:25:03| storeLateRelease: released 0 objects
2010/11/15 08:25:09| comm_udp_sendto: FD 5, 203.99.163.240, port 53: (101) Network is unreachable
2010/11/15 08:25:09| idnsSendQuery: FD 5: sendto: (101) Network is unreachable
2010/11/15 10:05:48| sslReadClient: FD 43: read failure: (110) Connection timed out
2010/11/15 10:33:16| Preparing for shutdown after 6908 requests
2010/11/15 10:33:16| Waiting 30 seconds for active connections to finish
2010/11/15 10:33:16| FD 12 Closing HTTP connection
2010/11/15 10:33:47| Shutting down...
2010/11/15 10:33:47| FD 13 Closing ICP connection
2010/11/15 10:33:47| WARNING: Closing client 192.168.2.99 connection due to lifetime timeout
2010/11/15 10:33:47|    http://v5.lscache3.c.youtube.com/vid...0894531a1e38f4
2010/11/15 10:33:47| WARNING: Closing client 192.168.2.4 connection due to lifetime timeout
2010/11/15 10:33:47|    http://195.190.13.150/source/search.php
2010/11/15 10:33:47| WARNING: Closing client 192.168.2.99 connection due to lifetime timeout
2010/11/15 10:33:47|    http://fsb.movshare.net/dl/40785a3d9...7gat776pfs.flv
2010/11/15 10:33:47| Closing unlinkd pipe on FD 10
2010/11/15 10:33:47| storeDirWriteCleanLogs: Starting...
2010/11/15 10:33:47|   Finished.  Wrote 59428 entries.
2010/11/15 10:33:47|   Took 0.0 seconds (4359768.2 entries/sec).
CPU Usage: 0.908 seconds = 0.312 user + 0.596 sys
Maximum Resident Size: 0 KB
Page faults with physical i/o: 1
Memory usage for squid via mallinfo():
        total space in arena:   27164 KB
        Ordinary blocks:        18307 KB    150 blks
        Small blocks:               0 KB      6 blks
        Holding blocks:           244 KB      1 blks
        Free Small blocks:          0 KB
        Free Ordinary blocks:    8856 KB
        Total in use:           18551 KB 68%
        Total free:              8856 KB 32%
2010/11/15 10:33:47| Squid Cache (Version 2.6.STABLE6): Exiting normally.
2010/11/15 10:33:48| Starting Squid Cache version 2.6.STABLE6 for i686-redhat-linux-gnu...
2010/11/15 10:33:48| Process ID 3807
2010/11/15 10:33:48| With 1024 file descriptors available
2010/11/15 10:33:48| Using epoll for the IO loop
2010/11/15 10:33:48| DNS Socket created at 0.0.0.0, port 32771, FD 5
2010/11/15 10:33:48| Adding domain localdomain from /etc/resolv.conf
2010/11/15 10:33:48| Adding nameserver 203.99.163.240 from /etc/resolv.conf
2010/11/15 10:33:48| User-Agent logging is disabled.
2010/11/15 10:33:48| Referer logging is disabled.
2010/11/15 10:33:48| Unlinkd pipe opened on FD 10
2010/11/15 10:33:48| Swap maxSize 2048000 KB, estimated 157538 objects
2010/11/15 10:33:48| Target number of buckets: 7876
2010/11/15 10:33:48| Using 8192 Store buckets
2010/11/15 10:33:48| Max Mem  size: 8192 KB
2010/11/15 10:33:48| Max Swap size: 2048000 KB
2010/11/15 10:33:48| Local cache digest enabled; rebuild/rewrite every 3600/3600 sec
2010/11/15 10:33:48| Rebuilding storage in /var/spool/squid (CLEAN)
2010/11/15 10:33:48| Using Least Load store dir selection
2010/11/15 10:33:48| Set Current Directory to /var/spool/squid
2010/11/15 10:33:48| Loaded Icons.
2010/11/15 10:33:48| Accepting proxy HTTP connections at 0.0.0.0, port 3128, FD 12.
2010/11/15 10:33:48| Accepting ICP messages at 0.0.0.0, port 3130, FD 13.
2010/11/15 10:33:48| WCCP Disabled.
2010/11/15 10:33:48| Ready to serve requests.
2010/11/15 10:33:48| Store rebuilding is  6.9% complete
2010/11/15 10:33:49| Done reading /var/spool/squid swaplog (59428 entries)
2010/11/15 10:33:49| Finished rebuilding storage from disk.
2010/11/15 10:33:49|     59428 Entries scanned
2010/11/15 10:33:49|         0 Invalid entries.
2010/11/15 10:33:49|         0 With invalid flags.
2010/11/15 10:33:49|     59428 Objects loaded.
2010/11/15 10:33:49|         0 Objects expired.
2010/11/15 10:33:49|         0 Objects cancelled.
2010/11/15 10:33:49|         0 Duplicate URLs purged.
2010/11/15 10:33:49|         0 Swapfile clashes avoided.
2010/11/15 10:33:49|   Took 0.9 seconds (67166.0 objects/sec).
2010/11/15 10:33:49| Beginning Validation Procedure
2010/11/15 10:33:49|   Completed Validation Procedure
2010/11/15 10:33:49|   Validated 59428 Entries
2010/11/15 10:33:49|   store_swap_size = 1082536k
2010/11/15 10:33:49| storeLateRelease: released 0 objects
2010/11/15 10:40:47| Preparing for shutdown after 604 requests
2010/11/15 10:40:47| Waiting 30 seconds for active connections to finish
2010/11/15 10:40:47| FD 12 Closing HTTP connection
2010/11/15 10:41:18| Shutting down...
2010/11/15 10:41:18| FD 13 Closing ICP connection
2010/11/15 10:41:18| WARNING: Closing client 192.168.2.99 connection due to lifetime timeout
2010/11/15 10:41:18|    http://w02.movshare.net/dl/b25d8a01a...j07f27atz4.flv
2010/11/15 10:41:18| Closing unlinkd pipe on FD 10
2010/11/15 10:41:18| storeDirWriteCleanLogs: Starting...
2010/11/15 10:41:18|   Finished.  Wrote 59754 entries.
2010/11/15 10:41:18|   Took 0.0 seconds (3367371.1 entries/sec).
CPU Usage: 0.680 seconds = 0.164 user + 0.516 sys
Maximum Resident Size: 0 KB
Page faults with physical i/o: 0
Memory usage for squid via mallinfo():
        total space in arena:   10472 KB
        Ordinary blocks:         9970 KB     46 blks
        Small blocks:               0 KB      6 blks
        Holding blocks:           244 KB      1 blks
        Free Small blocks:          0 KB
        Free Ordinary blocks:     501 KB
        Total in use:           10214 KB 95%
        Total free:               501 KB 5%
2010/11/15 10:41:18| Squid Cache (Version 2.6.STABLE6): Exiting normally.
2010/11/15 10:43:58| Starting Squid Cache version 2.6.STABLE6 for i686-redhat-linux-gnu...
2010/11/15 10:43:58| Process ID 2700
2010/11/15 10:43:58| With 1024 file descriptors available
2010/11/15 10:43:58| Using epoll for the IO loop
2010/11/15 10:43:58| DNS Socket created at 0.0.0.0, port 32768, FD 5
2010/11/15 10:43:58| Adding domain localdomain from /etc/resolv.conf
2010/11/15 10:43:58| Adding nameserver 203.99.163.240 from /etc/resolv.conf
2010/11/15 10:43:58| User-Agent logging is disabled.
2010/11/15 10:43:58| Referer logging is disabled.
2010/11/15 10:43:58| Unlinkd pipe opened on FD 10
2010/11/15 10:43:58| Swap maxSize 2048000 KB, estimated 157538 objects
2010/11/15 10:43:58| Target number of buckets: 7876
2010/11/15 10:43:58| Using 8192 Store buckets
2010/11/15 10:43:58| Max Mem  size: 8192 KB
2010/11/15 10:43:58| Max Swap size: 2048000 KB
2010/11/15 10:43:58| Local cache digest enabled; rebuild/rewrite every 3600/3600 sec
2010/11/15 10:43:58| Rebuilding storage in /var/spool/squid (CLEAN)
2010/11/15 10:43:58| Using Least Load store dir selection
2010/11/15 10:43:58| Set Current Directory to /var/spool/squid
2010/11/15 10:43:58| Loaded Icons.
2010/11/15 10:44:00| Accepting proxy HTTP connections at 0.0.0.0, port 3128, FD 12.
2010/11/15 10:44:00| Accepting ICP messages at 0.0.0.0, port 3130, FD 13.
2010/11/15 10:44:00| WCCP Disabled.
2010/11/15 10:44:00| Ready to serve requests.
2010/11/15 10:44:00| Store rebuilding is  6.9% complete
2010/11/15 10:44:00| Done reading /var/spool/squid swaplog (59754 entries)
2010/11/15 10:44:00| Finished rebuilding storage from disk.
2010/11/15 10:44:00|     59754 Entries scanned
2010/11/15 10:44:00|         0 Invalid entries.
2010/11/15 10:44:00|         0 With invalid flags.
2010/11/15 10:44:00|     59754 Objects loaded.
2010/11/15 10:44:00|         0 Objects expired.
2010/11/15 10:44:00|         0 Objects cancelled.
2010/11/15 10:44:00|         0 Duplicate URLs purged.
2010/11/15 10:44:00|         0 Swapfile clashes avoided.
2010/11/15 10:44:00|   Took 2.6 seconds (22961.3 objects/sec).
2010/11/15 10:44:00| Beginning Validation Procedure
2010/11/15 10:44:00|   Completed Validation Procedure
2010/11/15 10:44:00|   Validated 59754 Entries
2010/11/15 10:44:00|   store_swap_size = 1086580k
2010/11/15 10:44:01| storeLateRelease: released 0 objects
2010/11/15 10:44:07| comm_udp_sendto: FD 5, 203.99.163.240, port 53: (101) Network is unreachable
2010/11/15 10:44:07| idnsSendQuery: FD 5: sendto: (101) Network is unreachable
2010/11/15 12:03:49| Preparing for shutdown after 6764 requests
2010/11/15 12:03:49| Waiting 30 seconds for active connections to finish
2010/11/15 12:03:49| FD 12 Closing HTTP connection
2010/11/15 12:04:20| Shutting down...
2010/11/15 12:04:20| FD 13 Closing ICP connection
2010/11/15 12:04:20| WARNING: Closing client 192.168.2.150 connection due to lifetime timeout
2010/11/15 12:04:20|    http://download.microsoft.com/downlo...es/mpam-fe.exe
2010/11/15 12:04:20| WARNING: Closing client 192.168.2.99 connection due to lifetime timeout
2010/11/15 12:04:20|    http://fsd.movshare.net/dl/3f080cc66...7gat776pfs.flv
2010/11/15 12:04:20| WARNING: Closing client 192.168.2.99 connection due to lifetime timeout
2010/11/15 12:04:20|    http://v5.lscache3.c.youtube.com/vid...0894531a1e38f4
2010/11/15 12:04:20| WARNING: Closing client 192.168.2.60 connection due to lifetime timeout
2010/11/15 12:04:20|    http://v12.lscache7.c.youtube.com/vi...5&begin=321778
2010/11/15 12:04:20| WARNING: Closing client 192.168.2.60 connection due to lifetime timeout
2010/11/15 12:04:20|    http://v12.lscache7.c.youtube.com/vi...2a1bb36064465&
2010/11/15 12:04:20| Closing unlinkd pipe on FD 10
2010/11/15 12:04:20| storeDirWriteCleanLogs: Starting...
2010/11/15 12:04:20|   Finished.  Wrote 61206 entries.
2010/11/15 12:04:20|   Took 0.0 seconds (4388785.3 entries/sec).
CPU Usage: 0.912 seconds = 0.332 user + 0.580 sys
Maximum Resident Size: 0 KB
Page faults with physical i/o: 1
Memory usage for squid via mallinfo():
        total space in arena:   16620 KB
        Ordinary blocks:        16220 KB    101 blks
        Small blocks:               0 KB      5 blks
        Holding blocks:           244 KB      1 blks
        Free Small blocks:          0 KB
        Free Ordinary blocks:     400 KB
        Total in use:           16464 KB 98%
        Total free:               400 KB 2%
2010/11/15 12:04:20| Squid Cache (Version 2.6.STABLE6): Exiting normally.
2010/11/15 12:05:30| Starting Squid Cache version 2.6.STABLE6 for i686-redhat-linux-gnu...
2010/11/15 12:05:30| Process ID 3749
2010/11/15 12:05:30| With 1024 file descriptors available
2010/11/15 12:05:30| Using epoll for the IO loop
2010/11/15 12:05:30| DNS Socket created at 0.0.0.0, port 32771, FD 5
2010/11/15 12:05:30| Adding domain localdomain from /etc/resolv.conf
2010/11/15 12:05:30| Adding nameserver 203.99.163.240 from /etc/resolv.conf
2010/11/15 12:05:30| User-Agent logging is disabled.
2010/11/15 12:05:30| Referer logging is disabled.
2010/11/15 12:05:30| Unlinkd pipe opened on FD 10
2010/11/15 12:05:30| Swap maxSize 2048000 KB, estimated 157538 objects
2010/11/15 12:05:30| Target number of buckets: 7876
2010/11/15 12:05:30| Using 8192 Store buckets
2010/11/15 12:05:30| Max Mem  size: 8192 KB
2010/11/15 12:05:30| Max Swap size: 2048000 KB
2010/11/15 12:05:30| Local cache digest enabled; rebuild/rewrite every 3600/3600 sec
2010/11/15 12:05:30| Rebuilding storage in /var/spool/squid (DIRTY)
2010/11/15 12:05:30| Using Least Load store dir selection
2010/11/15 12:05:30| Set Current Directory to /var/spool/squid
2010/11/15 12:05:30| Loaded Icons.
2010/11/15 12:05:30| Accepting proxy HTTP connections at 0.0.0.0, port 3128, FD 11.
2010/11/15 12:05:30| Accepting ICP messages at 0.0.0.0, port 3130, FD 12.
2010/11/15 12:05:30| WCCP Disabled.
2010/11/15 12:05:30| Ready to serve requests.
2010/11/15 12:05:30| Done scanning /var/spool/squid (0 entries)
2010/11/15 12:05:30| Finished rebuilding storage from disk.
2010/11/15 12:05:30|         0 Entries scanned
2010/11/15 12:05:30|         0 Invalid entries.
2010/11/15 12:05:30|         0 With invalid flags.
2010/11/15 12:05:30|         0 Objects loaded.
2010/11/15 12:05:30|         0 Objects expired.
2010/11/15 12:05:30|         0 Objects cancelled.
2010/11/15 12:05:30|         0 Duplicate URLs purged.
2010/11/15 12:05:30|         0 Swapfile clashes avoided.
2010/11/15 12:05:30|   Took 0.3 seconds (   0.0 objects/sec).
2010/11/15 12:05:30| Beginning Validation Procedure
2010/11/15 12:05:30|   Completed Validation Procedure
2010/11/15 12:05:30|   Validated 0 Entries
2010/11/15 12:05:30|   store_swap_size = 0k
2010/11/15 12:05:31| storeLateRelease: released 0 objects

barriehie · 11-15-2010, 05:30 PM

There are many timeout variables in squid.conf. Have you looked at any of those?

nouman_younis@yahoo.com · 11-15-2010, 09:13 PM

Quote:

Originally Posted by barriehie

There are many timeout variables in squid.conf. Have you looked at any of those?

Can you please elaborate those timeout variables and which variables I have to edit in order to make proxy work normal. Btw I am using RHEL5.

barriehie · 11-16-2010, 10:42 AM

Quote:

Originally Posted by nouman_younis@yahoo.com

Can you please elaborate those timeout variables and which variables I have to edit in order to make proxy work normal. Btw I am using RHEL5.

This should yield the .conf file tags that have to do with the timeout variables:

Code:

cat ./squid.conf | gawk '{ if($0~/^#  TAG: .*timeout.*$/) { print $0 } }'

I'm running squid 2.6 Stable 18 and in my setup I ended up with:

Code:

# dead_peer_timeout 10 seconds
# forward_timeout 4 minutes
# connect_timeout 1 minute
# peer_connect_timeout 30 seconds
# read_timeout 15 minutes
# request_timeout 5 minutes
# persistent_request_timeout 2 minutes
# pconn_timeout 1 minute
# ident_timeout 10 seconds
# Also see "pconn_timeout" in the TIMEOUTS section
# icp_query_timeout 0
# maximum_icp_query_timeout 2000
# mcast_icp_query_timeout 2000
# dns_timeout 2 minutes

Note: I ran this on a copy of squid.conf in a temp. directory.