[squid-users] Bug: Missing MemObject::storeId value

Heiler Bemerguy heiler.bemerguy at cinbesa.com.br
Tue May 31 16:36:00 UTC 2016


This is the parent proxy of another one (10.1.10.101).

It was receiveing requests like these:

1464665138.326      0 10.1.10.101 UDP_MISS/000 72 ICP_QUERY 
http://img.olx.com.br/thumbs/51/517630000636766.jpg - HIER_NONE/- -
1464665138.331      0 10.1.10.101 UDP_MISS/000 72 ICP_QUERY 
http://img.olx.com.br/thumbs/51/515630006195751.jpg - HIER_NONE/- -
1464665138.400     68 10.1.10.101 TCP_MISS/200 2439 GET 
http://img.olx.com.br/thumbs/51/515630006195751.jpg - 
HIER_DIRECT/54.192.57.169 image/jpeg
1464665138.404     86 10.1.10.101 TCP_MISS/200 2221 GET 
http://img.olx.com.br/thumbs/51/518630004436306.jpg - 
HIER_DIRECT/54.192.57.169 image/jpeg


-- 
Best Regards,

Heiler Bemerguy
Network Manager - CINBESA
55 91 98151-4894/3184-1751


Em 31/05/2016 13:23, Yuri Voinov escreveu:
>
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA256
>
> This proxy uses as peer for downstreams?
>
>
> 31.05.2016 21:09, Heiler Bemerguy пишет:
> > > > I disabled ICP requests to it and these "Bug: Missing 
> MemObject::storeId value" messages stopped... any thoughts? > > Known 
> bug? > > -- > Best Regards, > > Heiler Bemerguy > Network Manager - 
> CINBESA > 55 91 98151-4894/3184-1751 > > > Em 31/05/2016 11:49, Yuri 
> escreveu: >> >> Hm. Seems related. The objects not the same in memory 
> yet. >> >> >> 31.05.2016 20:45, Heiler Bemerguy пишет: >>> >>> >>> Yep 
> I know it should/would vanish all those "Vary objects" messages.. but 
> what are these other "Bug: Missing MemObject::storeId value" ?? I 
> thought it was related... >>> >>> 2016/05/31 11:43:27.594 kid2| 
> clientProcessHit: URL mismatch, '[unknown_URI]' != 
> 'http://www.agenciabelem.com.br/Resize/CreateThumbnail?path=/multimidiaSGN/galeria/69379/69379_213524.jpg&maxHeight=61&maxWidth=91' 
> >>> 2016/05/31 11:43:28.492 kid2| clientProcessHit: URL mismatch, 
> '[unknown_URI]' != 
> 'http://www.agenciabelem.com.br/Resize/CreateThumbnail?path=/MultimidiaSGN/galeria/69395/69395_213686.jpg&maxHeight=225&maxWidth=136' 
> >>> 2016/05/31 11:43:46 kid1| Bug: Missing MemObject::storeId value 
> >>> 2016/05/31 11:43:46 kid1| mem_hdr: 0x3efe990 nodes.start() 
> 0x19b79ef0 >>> 2016/05/31 11:43:46 kid1| mem_hdr: 0x3efe990 
> nodes.finish() 0x19b79ef0 >>> 2016/05/31 11:43:46 kid1| 
> MemObject->start_ping: 0.000000 >>> 2016/05/31 11:43:46 kid1| 
> MemObject->inmem_hi: 193 >>> 2016/05/31 11:43:46 kid1| 
> MemObject->inmem_lo: 0 >>> 2016/05/31 11:43:46 kid1| 
> MemObject->nclients: 0 >>> 2016/05/31 11:43:46 kid1| MemObject->reply: 
> 0x45656e0 >>> 2016/05/31 11:43:46 kid1| MemObject->request: 0 >>> 
> 2016/05/31 11:43:46 kid1| MemObject->logUri: >>> 2016/05/31 11:43:46 
> kid1| MemObject->storeId: >>> 2016/05/31 11:43:46.569 kid2| 
> clientProcessHit: URL mismatch, '[unknown_URI]' != 
> 'http://captive.apple.com/hotspot-detect.html' >>> 2016/05/31 11:43:52 
> kid2| Bug: Missing MemObject::storeId value >>> 2016/05/31 11:43:52 
> kid2| mem_hdr: 0x24eafe0 nodes.start() 0x7cac320 >>> 2016/05/31 
> 11:43:52 kid2| mem_hdr: 0x24eafe0 nodes.finish() 0x5385350 >>> 
> 2016/05/31 11:43:52 kid2| MemObject->start_ping: 0.000000 >>> 
> 2016/05/31 11:43:52 kid2| MemObject->inmem_hi: 10455 >>> 2016/05/31 
> 11:43:52 kid2| MemObject->inmem_lo: 0 >>> 2016/05/31 11:43:52 kid2| 
> MemObject->nclients: 0 >>> 2016/05/31 11:43:52 kid2| MemObject->reply: 
> 0x2970910 >>> 2016/05/31 11:43:52 kid2| MemObject->request: 0 >>> 
> 2016/05/31 11:43:52 kid2| MemObject->logUri: >>> 2016/05/31 11:43:52 
> kid2| MemObject->storeId: >>> 2016/05/31 11:43:52.364 kid2| 
> clientProcessHit: URL mismatch, '[unknown_URI]' != 
> 'http://cdn-00-default.nativex.com/asset/d4c6dac2-76fd-4f91-9254-9708b603f097.css' 
> >>> 2016/05/31 11:43:52.364 kid2| Bug: Missing MemObject::storeId 
> value >>> 2016/05/31 11:43:52.364 kid2| mem_hdr: 0x264c000 
> nodes.start() 0x311ee90 >>> 2016/05/31 11:43:52.364 kid2| mem_hdr: 
> 0x264c000 nodes.finish() 0x6e46250 >>> 2016/05/31 11:43:52.364 kid2| 
> MemObject->start_ping: 0.000000 >>> 2016/05/31 11:43:52.364 kid2| 
> MemObject->inmem_hi: 12244 >>> 2016/05/31 11:43:52.364 kid2| 
> MemObject->inmem_lo: 0 >>> 2016/05/31 11:43:52.364 kid2| 
> MemObject->nclients: 0 >>> 2016/05/31 11:43:52.364 kid2| 
> MemObject->reply: 0x2233a30 >>> 2016/05/31 11:43:52.364 kid2| 
> MemObject->request: 0 >>> 2016/05/31 11:43:52.364 kid2| 
> MemObject->logUri: >>> 2016/05/31 11:43:52.364 kid2| 
> MemObject->storeId: >>> 2016/05/31 11:43:52.390 kid2| 
> clientProcessHit: URL mismatch, '[unknown_URI]' != 
> 'http://cdn-00-default.nativex.com/asset/7b4133df-f0c8-4f2d-8532-2dcf6915577b.js' 
> >>> 2016/05/31 11:43:52 kid3| Bug: Missing MemObject::storeId value 
> >>> 2016/05/31 11:43:52 kid3| mem_hdr: 0x2ac67f0 nodes.start() 
> 0x3f5d410 >>> 2016/05/31 11:43:52 kid3| mem_hdr: 0x2ac67f0 
> nodes.finish() 0x1c71fc0 >>> 2016/05/31 11:43:52 kid3| 
> MemObject->start_ping: 0.000000 >>> 2016/05/31 11:43:52 kid3| 
> MemObject->inmem_hi: 95355 >>> 2016/05/31 11:43:52 kid3| 
> MemObject->inmem_lo: 0 >>> 2016/05/31 11:43:52 kid3| 
> MemObject->nclients: 0 >>> 2016/05/31 11:43:52 kid3| MemObject->reply: 
> 0x2972cc0 >>> 2016/05/31 11:43:52 kid3| MemObject->request: 0 >>> 
> 2016/05/31 11:43:52 kid3| MemObject->logUri: >>> 2016/05/31 11:43:52 
> kid3| MemObject->storeId: >>> >>> -- >>> Best Regards, >>> >>> Heiler 
> Bemerguy >>> Network Manager - CINBESA >>> 55 91 98151-4894/3184-1751 
> >>> >>> Em 31/05/2016 11:39, Yuri escreveu: >>>> >>>> Bad test. 
> Problem is with swapped onto disk objects exactly. So, when we disable 
> cache_dirs, problem is gone. >>>> >>>> >>>> 31.05.2016 20:36, Heiler 
> Bemerguy пишет: >>>>> >>>>> >>>>> Just did a test here. >>>>> >>>>> 
> Disabled every cache_dir and fully restarted squid 3.5.19 >>>>> >>>>> 
> No more "vary object loop", but these continues: >>>>> >>>>> 
> 2016/05/31 11:35:13 kid2| Bug: Missing MemObject::storeId value >>>>> 
> 2016/05/31 11:35:13 kid2| mem_hdr: 0x3177f40 nodes.start() 0x7370880 
> >>>>> 2016/05/31 11:35:13 kid2| mem_hdr: 0x3177f40 nodes.finish() 
> 0x7370880 >>>>> 2016/05/31 11:35:13 kid2| MemObject->start_ping: 
> 0.000000 >>>>> 2016/05/31 11:35:13 kid2| MemObject->inmem_hi: 2224 
> >>>>> 2016/05/31 11:35:13 kid2| MemObject->inmem_lo: 0 >>>>> 
> 2016/05/31 11:35:13 kid2| MemObject->nclients: 0 >>>>> 2016/05/31 
> 11:35:13 kid2| MemObject->reply: 0x29711e0 >>>>> 2016/05/31 11:35:13 
> kid2| MemObject->request: 0 >>>>> 2016/05/31 11:35:13 kid2| 
> MemObject->logUri: >>>>> 2016/05/31 11:35:13 kid2| MemObject->storeId: 
> >>>>> 2016/05/31 11:35:14 kid1| Bug: Missing MemObject::storeId value 
> >>>>> 2016/05/31 11:35:14 kid1| mem_hdr: 0x3e0d990 nodes.start() 
> 0x1ca70540 >>>>> 2016/05/31 11:35:14 kid1| mem_hdr: 0x3e0d990 
> nodes.finish() 0x1ca70540 >>>>> 2016/05/31 11:35:14 kid1| 
> MemObject->start_ping: 0.000000 >>>>> 2016/05/31 11:35:14 kid1| 
> MemObject->inmem_hi: 193 >>>>> 2016/05/31 11:35:14 kid1| 
> MemObject->inmem_lo: 0 >>>>> 2016/05/31 11:35:14 kid1| 
> MemObject->nclients: 0 >>>>> 2016/05/31 11:35:14 kid1| 
> MemObject->reply: 0x45656e0 >>>>> 2016/05/31 11:35:14 kid1| 
> MemObject->request: 0 >>>>> 2016/05/31 11:35:14 kid1| 
> MemObject->logUri: >>>>> 2016/05/31 11:35:14 kid1| MemObject->storeId: 
> >>>>> 2016/05/31 11:35:14.418 kid1| clientProcessHit: URL mismatch, 
> '[unknown_URI]' != 'http://captive.apple.com/hotspot-detect.html' 
> >>>>> 2016/05/31 11:35:14 kid2| Bug: Missing MemObject::storeId value 
> >>>>> 2016/05/31 11:35:14 kid2| mem_hdr: 0x336b090 nodes.start() 
> 0x2b136d0 >>>>> 2016/05/31 11:35:14 kid2| mem_hdr: 0x336b090 
> nodes.finish() 0x82709c0 >>>>> 2016/05/31 11:35:14 kid2| 
> MemObject->start_ping: 0.000000 >>>>> 2016/05/31 11:35:14 kid2| 
> MemObject->inmem_hi: 4573 >>>>> 2016/05/31 11:35:14 kid2| 
> MemObject->inmem_lo: 0 >>>>> 2016/05/31 11:35:14 kid2| 
> MemObject->nclients: 0 >>>>> 2016/05/31 11:35:14 kid2| 
> MemObject->reply: 0x26bdf50 >>>>> 2016/05/31 11:35:14 kid2| 
> MemObject->request: 0 >>>>> 2016/05/31 11:35:14 kid2| 
> MemObject->logUri: >>>>> 2016/05/31 11:35:14 kid2| MemObject->storeId: 
> >>>>> >>>>> >>>>> -- >>>>> Best Regards, >>>>> >>>>> Heiler Bemerguy 
> >>>>> Network Manager - CINBESA >>>>> 55 91 98151-4894/3184-1751 >>>>> 
> >>>>> Em 31/05/2016 11:14, Yuri escreveu: >>>>>> Without 
> collapsed_forwarding seems ok: >>>>>> >>>>>> 
> https://i1.someimage.com/E8pM9tu.png >>>>>> >>>>>> no warnings/errors 
> in cache.log. >>>>>> >>>>>> Seems Heiler right. >>>>>> >>>>>> 
> 31.05.2016 19:33, joe пишет: >>>>>>> load this link on both browser 
> chrome  and firefox >>>>>>> 'http://js.statig.com.br/pub/adtags.js' 
> >>>>>>> keep clicking reload  on both browser  and look at your 
> cache.log >>>>>>> with or without collapsed_forwarding >>>>>>> >>>>>>> 
> >>>>>>> Heiler Bemerguy wrote >>>>>>>> Yeah, I know. This kind of 
> stuff only appeared after enabling >>>>>>>> collapsed_forwarding, I 
> think. Now it's off again.. but I didn't wipe >>>>>>>> the cache too, 
> so I don't know..... >>>>>>>> >>>>>>>> 2016/05/31 10:50:24 kid2| 
> varyEvaluateMatch: Oops. Not a Vary match on >>>>>>>> second attempt, 
> 'http://js.statig.com.br/pub/adtags.js' >>>>>>>> 
> 'accept-encoding="gzip,%20deflate"' >>>>>>>> 2016/05/31 10:50:24 kid2| 
> clientProcessHit: Vary object loop! >>>>>>>> 2016/05/31 10:50:25 kid2| 
> Bug: Missing MemObject::storeId value >>>>>>>> 2016/05/31 10:50:25 
> kid2| mem_hdr: 0x20573e10 nodes.start() 0x117e4ce0 >>>>>>>> 2016/05/31 
> 10:50:25 kid2| mem_hdr: 0x20573e10 nodes.finish() 0x117e4ce0 >>>>>>>> 
> 2016/05/31 10:50:25 kid2| MemObject->start_ping: 0.000000 >>>>>>>> 
> 2016/05/31 10:50:25 kid2| MemObject->inmem_hi: 2155 >>>>>>>> 
> 2016/05/31 10:50:25 kid2| MemObject->inmem_lo: 0 >>>>>>>> 2016/05/31 
> 10:50:25 kid2| MemObject->nclients: 0 >>>>>>>> 2016/05/31 10:50:25 
> kid2| MemObject->reply: 0x7db9ce0 >>>>>>>> 2016/05/31 10:50:25 kid2| 
> MemObject->request: 0 >>>>>>>> 2016/05/31 10:50:25 kid2| 
> MemObject->logUri: >>>>>>>> 2016/05/31 10:50:25 kid2| 
> MemObject->storeId: >>>>>>>> >>>>>>>> >>>>>>>> -- >>>>>>>> Best 
> Regards, >>>>>>>> >>>>>>>> Heiler Bemerguy >>>>>>>> Network Manager - 
> CINBESA >>>>>>>> 55 91 98151-4894/3184-1751 >>>>>>>> >>>>>>>> >>>>>>>> 
> Em 31/05/2016 10:34, Yuri escreveu: >>>>>>>>> This is too expensive 
> action. Cold out cache will decrease hit-ratio >>>>>>>>> for weeks. 
> >>>>>>>>> >>>>>>>>> >>>>>>>>> Also, I suggest force reloading objects 
> must overwrite stale cached, no? >>>>>>>>> >>>>>>>>> >>>>>>>>> 
> 31.05.2016 19:32, Heiler Bemerguy пишет: >>>>>>>>>> >>>>>>>>>> I swear 
> this bug was only rarely triggered without >>>>>>>>>> 
> collapsed_forwarding enabled... but I think you'll have to wipe your 
> >>>>>>>>>> cache to really test it... >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> 
> >>>>>>>>>> -- >>>>>>>>>> Heiler Bemerguy - (91) 98151-4894 >>>>>>>>>> 
> Assessor Técnico - CINBESA (91) 3184-1751 >>>>>>>>>> >>>>>>>>>> Em 
> 31/05/2016 08:00, Yuri escreveu: >>>>>>>>>>> Heh, >>>>>>>>>>> 
> >>>>>>>>>>> the issue occurs also with disabled collapsed_forwarding: 
> >>>>>>>>>>> >>>>>>>>>>> 2016/05/31 16:58:12 kid1| varyEvaluateMatch: 
> Oops. Not a Vary match >>>>>>>>>>> on second attempt, >>>>>>>>>>> 
> 'https://ru.wikipedia.org/w/load.php?debug=false&lang=ru&modules=jquery.accessKeyLabel%2Cclient%7Cmediawiki.RegExp%2Cnotify%2Cutil%7Cmediawiki.legacy.wikibits&skin=vector&version=b5e9abd3b463' 
> >>>>>>>>>>> 'accept-encoding="gzip,%20deflate,%20sdch,%20br"' 
> >>>>>>>>>>> 2016/05/31 16:58:12 kid1| clientProcessHit: Vary object 
> loop! >>>>>>>>>>> 2016/05/31 16:58:12 kid1| Error negotiating SSL on 
> FD 260: >>>>>>>>>>> error:14090086:SSL 
> routines:SSL3_GET_SERVER_CERTIFICATE:certificate >>>>>>>>>>> verify 
> failed (1/-1/0) >>>>>>>>>>> 2016/05/31 16:58:12 kid1| 
> varyEvaluateMatch: Oops. Not a Vary match >>>>>>>>>>> on second 
> attempt, >>>>>>>>>>> 
> 'https://ru.wikipedia.org/w/index.php?title=MediaWiki:Secure.js&action=raw&ctype=text/javascript' 
> >>>>>>>>>>> 'accept-encoding="gzip,%20deflate,%20sdch,%20br", 
> >>>>>>>>>>> 
> cookie="WMF-Last-Access%3D31-May-2016%3B%20GeoIP%3DKZ%3A02%3AAlmaty%3A43.26%3A76.93%3Av4", 
> >>>>>>>>>>> authorization' >>>>>>>>>>> 2016/05/31 16:58:12 kid1| 
> clientProcessHit: Vary object loop! >>>>>>>>>>> 2016/05/31 16:58:12 
> kid1| varyEvaluateMatch: Oops. Not a Vary match >>>>>>>>>>> on second 
> attempt, >>>>>>>>>>> 
> 'https://ru.wikipedia.org/w/index.php?title=MediaWiki:Osm.js&action=raw&ctype=text/javascript' 
> >>>>>>>>>>> 'accept-encoding="gzip,%20deflate,%20sdch,%20br", 
> >>>>>>>>>>> 
> cookie="WMF-Last-Access%3D31-May-2016%3B%20GeoIP%3DKZ%3A02%3AAlmaty%3A43.26%3A76.93%3Av4", 
> >>>>>>>>>>> authorization' >>>>>>>>>>> 2016/05/31 16:58:12 kid1| 
> clientProcessHit: Vary object loop! >>>>>>>>>>> 2016/05/31 16:58:13 
> kid1| varyEvaluateMatch: Oops. Not a Vary match >>>>>>>>>>> on second 
> attempt, >>>>>>>>>>> 
> 'https://ru.wikipedia.org/w/index.php?title=MediaWiki:Sidebar-related.js&action=raw&ctype=text/javascript' 
> >>>>>>>>>>> 'accept-encoding="gzip,%20deflate,%20sdch,%20br", 
> >>>>>>>>>>> 
> cookie="WMF-Last-Access%3D31-May-2016%3B%20GeoIP%3DKZ%3A02%3AAlmaty%3A43.26%3A76.93%3Av4", 
> >>>>>>>>>>> authorization' >>>>>>>>>>> 2016/05/31 16:58:13 kid1| 
> clientProcessHit: Vary object loop! >>>>>>>>>>> 2016/05/31 16:58:13 
> kid1| varyEvaluateMatch: Oops. Not a Vary match >>>>>>>>>>> on second 
> attempt, >>>>>>>>>>> 
> 'https://ru.wikipedia.org/w/index.php?title=MediaWiki:Wikibugs.js&action=raw&ctype=text/javascript' 
> >>>>>>>>>>> 'accept-encoding="gzip,%20deflate,%20sdch,%20br", 
> >>>>>>>>>>> 
> cookie="WMF-Last-Access%3D31-May-2016%3B%20GeoIP%3DKZ%3A02%3AAlmaty%3A43.26%3A76.93%3Av4", 
> >>>>>>>>>>> authorization' >>>>>>>>>>> 2016/05/31 16:58:13 kid1| 
> clientProcessHit: Vary object loop! >>>>>>>>>>> 2016/05/31 16:58:13 
> kid1| varyEvaluateMatch: Oops. Not a Vary match >>>>>>>>>>> on second 
> attempt, >>>>>>>>>>> 
> 'https://ru.wikipedia.org/w/index.php?title=MediaWiki:Interwiki-links.js&action=raw&ctype=text/javascript' 
> >>>>>>>>>>> 'accept-encoding="gzip,%20deflate,%20sdch,%20br", 
> >>>>>>>>>>> 
> cookie="WMF-Last-Access%3D31-May-2016%3B%20GeoIP%3DKZ%3A02%3AAlmaty%3A43.26%3A76.93%3Av4", 
> >>>>>>>>>>> authorization' >>>>>>>>>>> 2016/05/31 16:58:13 kid1| 
> clientProcessHit: Vary object loop! >>>>>>>>>>> 2016/05/31 16:58:13 
> kid1| varyEvaluateMatch: Oops. Not a Vary match >>>>>>>>>>> on second 
> attempt, >>>>>>>>>>> 
> 'https://meta.wikimedia.org/w/index.php?title=MediaWiki:Wikiminiatlas.js&action=raw&ctype=text/javascript' 
> >>>>>>>>>>> 'accept-encoding="gzip,%20deflate,%20sdch,%20br", cookie, 
> >>>>>>>>>>> authorization' >>>>>>>>>>> >>>>>>>>>>> 3.5.19 >>>>>>>>>>> 
> >>>>>>>>>>> >>> >>> >>> >>> 
> _______________________________________________ >>> squid-users 
> mailing list >>> squid-users at lists.squid-cache.org >>> 
> http://lists.squid-cache.org/listinfo/squid-users >> >> >> >> 
> _______________________________________________ >> squid-users mailing 
> list >> squid-users at lists.squid-cache.org >> 
> http://lists.squid-cache.org/listinfo/squid-users > > > > 
> _______________________________________________ > squid-users mailing 
> list > squid-users at lists.squid-cache.org > 
> http://lists.squid-cache.org/listinfo/squid-users
>
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG v2
>
> iQEcBAEBCAAGBQJXTbqXAAoJENNXIZxhPexGBUkH/28v8MSQP+ud24DsiMnOcOYW
> 1+/bz42zvnVgGBo092Th7i3ZZObCKmZ3St7wuWQPgFbVP3qoyEZYKumvK+P5+78w
> YfuOWge8SG1yVwmPbQ8ge0Oq4/I19HcapFZXnHzEqN8/TbOtm04iTaaPiiKinsnq
> KLpb0t9kdrTQgMZudjoDCg5y3kwGkYAMl39pAotFe2GgrBLWrP14/WTbrbmiT88a
> bBD2rCjM9H2168q26AzKR/+u85gLvF6YYtN4xLn2/ahwmwu7Ak8hsJko+PeTxIeA
> ae3g27/a/cQdch3GtjuDcMl8pmEk8U8rKRcHmQ63i1la3n+08FPjJcYJ2UzWAbM=
> =VcAB
> -----END PGP SIGNATURE-----
>
>
>
> _______________________________________________
> squid-users mailing list
> squid-users at lists.squid-cache.org
> http://lists.squid-cache.org/listinfo/squid-users

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20160531/bdf61d53/attachment-0001.html>


More information about the squid-users mailing list