[squid-users] Squid stopped logging to access.log

Mon Feb 16 06:26:37 UTC 2015

Dear all,

As I was playing around with Squid and e-cap, I decided to shutdown squid,
clear the cache and the log files.

Now, when I start it, it seems to create both the access.log and cache.log
files, but it only writes to the cache.log file:
root at appliance:/var/log/squid3# ls -al
total 16
drwxr-xr-x  2 proxy proxy 4096 Feb 15 23:12 .
drwxr-xr-x 11 root  root  4096 Feb 15 06:25 ..
-rw-r--r--  1 proxy proxy    0 Feb 15 23:12 access.log
-rw-r--r--  1 proxy proxy 8046 Feb 15 23:13 cache.log
root at appliance:/var/log/squid3#

As far as I know, I've reverted ALL my changes to a known working state
(e.g. disabled e-cap altogether, the debug_options and the
request_header_access directives I had turned on earlier today), but I just
can't get squid to write to access.log.

Here's what I'm getting (this time with debug_options ALL, 2 , so we can
see a little more info on what is going on):

root at appliance:/var/log/squid3# rm *
root at appliance:/var/log/squid3# /etc/init.d/squid3 start
[ ok ] Starting Squid HTTP Proxy 3.x: squid3.
root at appliance:/var/log/squid3# ls -l
total 12
-rw-r----- 1 proxy proxy    0 Feb 15 23:25 access.log
-rw-r----- 1 proxy proxy 9002 Feb 15 23:25 cache.log
root at appliance:/var/log/squid3# cat cache.log
2015/02/15 23:25:39.890| main.cc(1424) SquidMain: Doing post-config
initialization

2015/02/15 23:25:39.890| main.cc(1426) SquidMain: running
RegisteredRunner::finalizeConfig
2015/02/15 23:25:39.891| main.cc(1427) SquidMain: running
RegisteredRunner::claimMemoryNeeds
2015/02/15 23:25:39.891| main.cc(1428) SquidMain: running
RegisteredRunner::useConfig
2015/02/15 23:25:39.930 kid1| main.cc(1424) SquidMain: Doing post-config
initialization

2015/02/15 23:25:39.930 kid1| main.cc(1426) SquidMain: running
RegisteredRunner::finalizeConfig
2015/02/15 23:25:39.930 kid1| main.cc(1427) SquidMain: running
RegisteredRunner::claimMemoryNeeds
2015/02/15 23:25:39.930 kid1| main.cc(1428) SquidMain: running
RegisteredRunner::useConfig
2015/02/15 23:25:39.930 kid1| Current Directory is /
2015/02/15 23:25:39.930 kid1| Starting Squid Cache version 3.5.1 for
x86_64-unknown-linux-gnu...
2015/02/15 23:25:39.930 kid1| Service Name: squid
2015/02/15 23:25:39.930 kid1| Process ID 11312
2015/02/15 23:25:39.930 kid1| Process Roles: worker
2015/02/15 23:25:39.930 kid1| With 65535 file descriptors available
2015/02/15 23:25:39.930 kid1| Initializing IP Cache...
2015/02/15 23:25:39.941 kid1| dns_internal.cc(1529) dnsInit: idnsInit:
attempt open DNS socket to: [::]
2015/02/15 23:25:39.941 kid1| dns_internal.cc(1538) dnsInit: idnsInit:
attempt open DNS socket to: 0.0.0.0
2015/02/15 23:25:39.941 kid1| DNS Socket created at [::], FD 6
2015/02/15 23:25:39.941 kid1| DNS Socket created at 0.0.0.0, FD 7
2015/02/15 23:25:39.941 kid1| Adding nameserver 8.8.8.8 from squid.conf
2015/02/15 23:25:39.941 kid1| helperOpenServers: Starting 5/5 'ssl_crtd'
processes
2015/02/15 23:25:39.963 kid1| Format.cc(64) parse: got definition '%>a/%>A
%un %>rm myip=%la myport=%lp'
2015/02/15 23:25:39.963 kid1| Format.cc(64) parse: got definition '%>a/%>A
%un %>rm myip=%la myport=%lp'
2015/02/15 23:25:39.963 kid1| Logfile: opening log
daemon:/var/log/squid3/access.log
2015/02/15 23:25:39.963 kid1| Logfile Daemon: opening log
/var/log/squid3/access.log
2015/02/15 23:25:40 kid1| Unlinkd pipe opened on FD 25
2015/02/15 23:25:40.227 kid1| store_digest.cc(490) storeDigestCalcCap:
storeDigestCalcCap: have: 0, want 161319 entries; limits: [1, 161319]
2015/02/15 23:25:40.227 kid1| CacheDigest.cc(49) cacheDigestInit:
cacheDigestInit: capacity: 161319 entries, bpe: 5; size: 100825 bytes
2015/02/15 23:25:40.227 kid1| Local cache digest enabled; rebuild/rewrite
every 3600/3600 sec
2015/02/15 23:25:40.227 kid1| Store logging disabled
2015/02/15 23:25:40.227 kid1| Swap maxSize 2097152 + 1048576 KB, estimated
241979 objects
2015/02/15 23:25:40.227 kid1| Target number of buckets: 12098
2015/02/15 23:25:40.227 kid1| Using 16384 Store buckets
2015/02/15 23:25:40.227 kid1| Max Mem  size: 1048576 KB
2015/02/15 23:25:40.227 kid1| Max Swap size: 2097152 KB
2015/02/15 23:25:40.228 kid1| ufs/UFSSwapLogParser.cc(96)
GetUFSSwapLogParser: Swap file version: 2
2015/02/15 23:25:40.228 kid1| Rebuilding storage in /var/spool/squid3
(clean log)
2015/02/15 23:25:40.228 kid1| Using Least Load store dir selection
2015/02/15 23:25:40.228 kid1| Current Directory is /
2015/02/15 23:25:40.228 kid1| Finished loading MIME types and icons.
2015/02/15 23:25:40.259 kid1| wccp.cc(112) wccpConnectionOpen: WCCPv1
disabled.
2015/02/15 23:25:40.259 kid1| wccp2.cc(960) wccp2ConnectionOpen: WCCPv2
Disabled. No IPv4 Router(s) configured.
2015/02/15 23:25:40.259 kid1| AsyncCall.cc(26) AsyncCall: The AsyncCall
clientListenerConnectionOpened constructed, this=0x30a4470 [call20]
2015/02/15 23:25:40.259 kid1| AsyncCall.cc(93) ScheduleCall:
StartListening.cc(59) will call
clientListenerConnectionOpened(local=[::]:3128 remote=[::] FD 28 flags=9,
err=0, HTTP Socket port=0x30a44d0) [call20]
2015/02/15 23:25:40.259 kid1| AsyncCall.cc(26) AsyncCall: The AsyncCall
clientListenerConnectionOpened constructed, this=0x30a47f0 [call22]
2015/02/15 23:25:40.260 kid1| AsyncCall.cc(93) ScheduleCall:
StartListening.cc(59) will call
clientListenerConnectionOpened(local=[::]:3129 remote=[::] FD 29 flags=41,
err=0, HTTP Socket port=0x30a4850) [call22]
2015/02/15 23:25:40.260 kid1| AsyncCall.cc(26) AsyncCall: The AsyncCall
clientListenerConnectionOpened constructed, this=0x30a4980 [call24]
2015/02/15 23:25:40.260 kid1| AsyncCall.cc(93) ScheduleCall:
StartListening.cc(59) will call
clientListenerConnectionOpened(local=[::]:3130 remote=[::] FD 30 flags=41,
err=0, HTTPS Socket port=0x30a49e0) [call24]
2015/02/15 23:25:40.260 kid1| HTCP Disabled.
2015/02/15 23:25:40.260 kid1| Squid plugin modules loaded: 0
2015/02/15 23:25:40.260 kid1| Adaptation support is on
2015/02/15 23:25:40.260 kid1| Config.cc(211) FinalizeEach: Initialized 1
message adaptation services
2015/02/15 23:25:40.260 kid1| Config.cc(211) FinalizeEach: Initialized 0
message adaptation service groups
2015/02/15 23:25:40.260 kid1| Config.cc(211) FinalizeEach: Initialized 1
message adaptation access rules
2015/02/15 23:25:40.260 kid1| AsyncCallQueue.cc(55) fireNext: entering
clientListenerConnectionOpened(local=[::]:3128 remote=[::] FD 28 flags=9,
err=0, HTTP Socket port=0x30a44d0)
2015/02/15 23:25:40.260 kid1| AsyncCall.cc(38) make: make call
clientListenerConnectionOpened [call20]
2015/02/15 23:25:40.260 kid1| Accepting HTTP Socket connections at
local=[::]:3128 remote=[::] FD 28 flags=9
2015/02/15 23:25:40.260 kid1| AsyncCallQueue.cc(57) fireNext: leaving
clientListenerConnectionOpened(local=[::]:3128 remote=[::] FD 28 flags=9,
err=0, HTTP Socket port=0x30a44d0)
2015/02/15 23:25:40.260 kid1| AsyncCallQueue.cc(55) fireNext: entering
clientListenerConnectionOpened(local=[::]:3129 remote=[::] FD 29 flags=41,
err=0, HTTP Socket port=0x30a4850)
2015/02/15 23:25:40.260 kid1| AsyncCall.cc(38) make: make call
clientListenerConnectionOpened [call22]
2015/02/15 23:25:40.260 kid1| Accepting NAT intercepted HTTP Socket
connections at local=[::]:3129 remote=[::] FD 29 flags=41
2015/02/15 23:25:40.260 kid1| AsyncCallQueue.cc(57) fireNext: leaving
clientListenerConnectionOpened(local=[::]:3129 remote=[::] FD 29 flags=41,
err=0, HTTP Socket port=0x30a4850)
2015/02/15 23:25:40.261 kid1| AsyncCallQueue.cc(55) fireNext: entering
clientListenerConnectionOpened(local=[::]:3130 remote=[::] FD 30 flags=41,
err=0, HTTPS Socket port=0x30a49e0)
2015/02/15 23:25:40.261 kid1| AsyncCall.cc(38) make: make call
clientListenerConnectionOpened [call24]
2015/02/15 23:25:40.261 kid1| Accepting NAT intercepted SSL bumped HTTPS
Socket connections at local=[::]:3130 remote=[::] FD 30 flags=41
2015/02/15 23:25:40.261 kid1| AsyncCallQueue.cc(57) fireNext: leaving
clientListenerConnectionOpened(local=[::]:3130 remote=[::] FD 30 flags=41,
err=0, HTTPS Socket port=0x30a49e0)
2015/02/15 23:25:40.261 kid1| Done reading /var/spool/squid3 swaplog (0
entries)
2015/02/15 23:25:40.261 kid1| Store rebuilding is 0.00% complete
2015/02/15 23:25:40.261 kid1| Finished rebuilding storage from disk.
2015/02/15 23:25:40.261 kid1|         0 Entries scanned
2015/02/15 23:25:40.261 kid1|         0 Invalid entries.
2015/02/15 23:25:40.261 kid1|         0 With invalid flags.
2015/02/15 23:25:40.261 kid1|         0 Objects loaded.
2015/02/15 23:25:40.261 kid1|         0 Objects expired.
2015/02/15 23:25:40.261 kid1|         0 Objects cancelled.
2015/02/15 23:25:40.261 kid1|         0 Duplicate URLs purged.
2015/02/15 23:25:40.261 kid1|         0 Swapfile clashes avoided.
2015/02/15 23:25:40.261 kid1|   Took 0.03 seconds (  0.00 objects/sec).
2015/02/15 23:25:40.261 kid1| Beginning Validation Procedure
2015/02/15 23:25:40.261 kid1| disk.cc(503) xrename: xrename: renaming
/var/spool/squid3/swap.state.new to /var/spool/squid3/swap.state
2015/02/15 23:25:40.261 kid1| store_rebuild.cc(96) storeCleanup: Seen: 51
entries
2015/02/15 23:25:40.261 kid1|   Completed Validation Procedure
2015/02/15 23:25:40.261 kid1|   Validated 0 Entries
2015/02/15 23:25:40.261 kid1|   store_swap_size = 0.00 KB
2015/02/15 23:25:40.261 kid1| store_digest.cc(283) storeDigestRebuildStart:
storeDigestRebuildStart: rebuild #1
2015/02/15 23:25:40.261 kid1| store_digest.cc(490) storeDigestCalcCap:
storeDigestCalcCap: have: 51, want 51 entries; limits: [1, 161319]
2015/02/15 23:25:40.261 kid1| store_digest.cc(512) storeDigestResize:
storeDigestResize: 161319 -> 51; change: 161268 (100%)
2015/02/15 23:25:40.261 kid1| store_digest.cc(519) storeDigestResize:
storeDigestResize: big change, resizing.
2015/02/15 23:25:40.262 kid1| CacheDigest.cc(49) cacheDigestInit:
cacheDigestInit: capacity: 51 entries, bpe: 5; size: 32 bytes
2015/02/15 23:25:40.262 kid1| store_digest.cc(363) storeDigestRewriteStart:
storeDigestRewrite: start rewrite #1
2015/02/15 23:25:40.262 kid1| store_digest.cc(377) storeDigestRewriteStart:
storeDigestRewriteStart: waiting for rebuild to finish.
2015/02/15 23:25:40.262 kid1| store_digest.cc(317)
storeDigestRebuildFinish: storeDigestRebuildFinish: done.
2015/02/15 23:25:40.262 kid1| store_digest.cc(418)
storeDigestRewriteFinish: storeDigestRewriteFinish: digest expires at
1424071540 (+3600)
2015/02/15 23:25:41 kid1| storeLateRelease: released 0 objects
root at appliance:/var/log/squid3# cat cache.log  | grep -i access
2015/02/15 23:25:39.963 kid1| Logfile: opening log
daemon:/var/log/squid3/access.log
2015/02/15 23:25:39.963 kid1| Logfile Daemon: opening log
/var/log/squid3/access.log
2015/02/15 23:25:40.260 kid1| Config.cc(211) FinalizeEach: Initialized 1
message adaptation access rules
root at appliance:/var/log/squid3# ls -al
total 20
drwxr-xr-x  2 proxy proxy 4096 Feb 15 23:25 .
drwxr-xr-x 11 root  root  4096 Feb 15 06:25 ..
-rw-r-----  1 proxy proxy    0 Feb 15 23:25 access.log
-rw-r-----  1 proxy proxy 9065 Feb 15 23:25 cache.log
root at appliance:/var/log/squid3#

Everything seems to be working fine, and traffic IS being routed through
squid. Its just that nothing gets logged to access.log...

Any idea on what might be causing this?

Thank you,
Luis
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20150215/05effc1e/attachment-0001.html>