Re: problems with squid 3.5.17

[Michael Tremer <michael.tremer@ipfire.org>]

[-- Attachment #1: Type: text/plain, Size: 9988 bytes --]

The async-io switch does not seem to be supported since squid 3.2 and after any
more and should not change anything at all.

-Michael

On Fri, 2016-04-29 at 18:01 +0100, Michael Tremer wrote:
> Hi,
> 
> thanks for looking into that. I tried to contact you today to ask for a status
> update about this.
> 
> I have not been able to get in touch with any of the other people that had
> proxy
> woes so I guess we are on our own. On one hand this makes me want to give this
> a
> very low priority. On the other hand I think we should target Core Update 103
> with this. The update should actually not be that severe.
> 
> On Fri, 2016-04-29 at 18:14 +0200, Matthias Fischer wrote:
> > 
> > Hi,
> > 
> > As always: "I'd like to have a problem" - perhaps somone else here has
> > some clues or better ideas:
> > 
> > I had not much luck during my tests with 'squid 3.5.17'.
> > 
> > In the last week I tested several compilations with the following
> > modifications compared with '3.4.14'. Configuration included 'squid
> > 3.5.17', squidguard 1.5-beta', 'squidclamav 5.11' and 'privoxy 3.0.24'.
> > 
> > I changed and tested with various configure-options:
> > 
> > 'squid':
> > ipv6 disabled / enabled
> > enable-async-io=8 / 16 / 32
> I had a look what the IPv6 switch actually changes. And that is not really
> much.
> Essentially nothing. It just probes if the system supports IPv6 and if not it
> disables it internally.
> 
> http://git.ipfire.org/?p=thirdparty%2Fsquid.git&a=search&h=refs%2Fheads%2Ftrun
> k&st=grep&s=USE_IPV6
> 
> I think we can as well enable this.
> 
> > 
> > 
> > 'privoxy':
> > ipv6-support enabled / disabled
> > 
> > After installing each new 'squid' version I deleted 'swap.state' and
> > the whole cache dir structure - that means, everything below
> > '/var/log/cache/' - and let 'squid' rebuild everything from scratch with
> > 'squid -z'.
> > No problems with that.
> > 
> > At first, 'squid' always seemed to run fine, 'squid.conf' and 'squid -k
> > parse' showed no problems. Ok, without 'ipv6' I got a warning during
> > start, but this seemed to have no further effect.
> > 
> > But after a few hours - sometimes it took a day - errors came up in the
> > logs.
> > These didn't noticably showed up during browsing. I had to search for
> > them in the logs.
> > 
> > One error that ALWAYS occured - 'squid' tried to load a file from cache
> > that wasn't there. In this case, 'squid' logged 'No such file or directory'.
> > Furthermore 'swapin MD5 mismatches' came up. It looked like 'swap.state'
> > had been corrupted(?).
> I guess it might be a good idea to wipe the cache when changing anything here.
> Although none of these issues should happen and I have no idea what you are
> trying to tell me here ;) Is this a big issue or just updating woes?
> 
> Should we merge 3.5.x for next and then see what this gets us?
> 
> > 
> > 2016/04/25 04:41:09 kid1| WARNING: 1 swapin MD5 mismatches
> > 2016/04/25 04:41:09 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 04:41:09 kid1| 	/var/log/cache/00/00/00000008
> > 2016/04/25 04:41:09 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 04:41:09 kid1| 	/var/log/cache/00/00/00000009
> > 2016/04/25 04:41:09 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 04:41:09 kid1| 	/var/log/cache/00/00/0000000A
> > 2016/04/25 04:41:09 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 04:41:09 kid1| 	/var/log/cache/00/00/0000000B
> > 2016/04/25 04:41:10 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 04:41:10 kid1| 	/var/log/cache/00/00/0000000C
> > 2016/04/25 04:41:10 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 04:41:10 kid1| 	/var/log/cache/00/00/0000000D
> > 2016/04/25 04:41:10 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 04:41:10 kid1| 	/var/log/cache/00/00/0000000E
> > ...
> > 
> > ...
> > 2016/04/25 05:17:21 kid1| Starting new redirector helpers...
> > 2016/04/25 05:17:21 kid1| helperOpenServers: Starting 1/30
> > 'redirect_wrapper' processes
> > 2016/04/25 05:17:21 kid1| Starting new redirector helpers...
> > 2016/04/25 05:17:21 kid1| helperOpenServers: Starting 1/30
> > 'redirect_wrapper' processes
> > 2016/04/25 05:17:45 kid1| WARNING: 1 swapin MD5 mismatches
> > 2016/04/25 14:05:08 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:08 kid1| 	/var/log/cache/00/00/00000073
> > 2016/04/25 14:05:08 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:08 kid1| 	/var/log/cache/00/00/00000075
> > 2016/04/25 14:05:09 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:09 kid1| 	/var/log/cache/00/00/00000008
> > 2016/04/25 14:05:09 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:09 kid1| 	/var/log/cache/00/00/00000009
> > 2016/04/25 14:05:09 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:09 kid1| 	/var/log/cache/00/00/0000000A
> > 2016/04/25 14:05:09 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:09 kid1| 	/var/log/cache/00/00/0000000B
> > 2016/04/25 14:05:09 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:09 kid1| 	/var/log/cache/00/00/0000000C
> > 2016/04/25 14:05:09 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:09 kid1| 	/var/log/cache/00/00/0000000D
> > 2016/04/25 14:05:09 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:09 kid1| 	/var/log/cache/00/00/0000000E
> > 2016/04/25 14:05:09 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:09 kid1| 	/var/log/cache/00/00/0000000F
> > 2016/04/25 14:05:09 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:09 kid1| 	/var/log/cache/00/00/00000010
> > 2016/04/25 14:05:09 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:09 kid1| 	/var/log/cache/00/00/00000011
> > 2016/04/25 14:05:10 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:10 kid1| 	/var/log/cache/00/00/00000012
> > 2016/04/25 14:05:10 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:10 kid1| 	/var/log/cache/00/00/00000013
> > 2016/04/25 14:05:10 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:10 kid1| 	/var/log/cache/00/00/00000085
> > 2016/04/25 14:05:10 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:10 kid1| 	/var/log/cache/00/00/00000087
> > 2016/04/25 14:05:10 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:10 kid1| 	/var/log/cache/00/07/00000766
> > 2016/04/25 14:05:10 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:10 kid1| 	/var/log/cache/00/07/00000767
> > 2016/04/25 14:05:11 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:11 kid1| 	/var/log/cache/00/00/00000014
> > 2016/04/25 14:05:11 kid1| DiskThreadsDiskFile::openDone: (2) No such
> > file or directory
> > 2016/04/25 14:05:11 kid1| 	/var/log/cache/00/00/00000015
> > 2016/04/25 14:10:16 kid1| Starting new redirector helpers...
> > ...
> > 
> > With the last '3.5.17', 'squid' reported a totally wrong
> > 'store_swap_size' plus some weird queue errors:
> > 
> > ...
> > 2016/04/26 01:27:44 kid1| Beginning Validation Procedure
> > 2016/04/26 01:27:44 kid1|   Completed Validation Procedure
> > 2016/04/26 01:27:44 kid1|   Validated 9126 Entries
> > 2016/04/26 01:27:44 kid1|   store_swap_size = 2226220.00 KB <--- Wrong
> > size! WHY!? System was nearly IDLE!
> > 2016/04/26 01:27:44 kid1| storeLateRelease: released 0 objects
> > 2016/04/26 01:27:45 kid1| squidaio_queue_request: Async request queue
> > growing uncontrollably!
> > 2016/04/26 01:27:45 kid1| squidaio_queue_request: Syncing pending I/O
> > operations.. (blocking)
> > 2016/04/26 01:27:45 kid1| squidaio_queue_request: Synced
> > 2016/04/26 01:27:45 kid1| squidaio_queue_request: Async request queue
> > growing uncontrollably!
> > 2016/04/26 01:27:45 kid1| squidaio_queue_request: Syncing pending I/O
> > operations.. (blocking)
> > 2016/04/26 01:27:45 kid1| squidaio_queue_request: Synced
> > ...
> > 
> > Even during restart, 'cache_log' reports a wrong 'store_swap_size':
> > 
> > ...
> > 2016/04/29 17:16:33 kid1| Beginning Validation Procedure
> > 2016/04/29 17:16:33 kid1| Completed Validation Procedure
> > 2016/04/29 17:16:33 kid1| Validated 3541 Entries
> > 2016/04/29 17:16:33 kid1| store_swap_size = 389420.00 KB <----!
> > ...
> > 
> > But in reality its only 117351 KB! 'squid' was ALWAYS started with
> > ...
> > cache_mem 32 MB
> > cache_dir aufs /var/log/cache 128 16 256
> > ...
> > 
> > So what!?
> > 
> > At this point, I'm giving up (again), to think things over and to ask if
> > anyone got an idea.
> > 
> > During building everythings OK, but it looks like I can't get that
> > version to work without errors.
> > 
> > Test versions are available here:
> > http://people.ipfire.org/~mfischer/squid/3.5.17
> > 
> > The same configuration is running right now with '3.4.14' (ipv6 disabled
> > / enable-async-io=16).
> > No errors in the logs, reported 'store_swap_size' is OK, no problems.
> > 
> > Any ideas?
> > 
> > Best,
> > Matthias
> -Michael

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 819 bytes --]