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

Luis Miguel Silva luismiguelferreirasilva at gmail.com
Mon Feb 16 08:30:31 UTC 2015 

Figured out the problem (I had another squid on the network that was
intercepting my requests)...sorry about that!

Luis

On Sun, Feb 15, 2015 at 11:26 PM, Luis Miguel Silva <
luismiguelferreirasilva at gmail.com> wrote:

> 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/20150216/9e175a87/attachment-0001.html>

More information about the squid-users mailing list