Re: Squid 5.7 + bump ERR_READ_ERROR|WITH_SERVER

[Alex Rousskov <rousskov@xxxxxxxxxxxxxxxxxxxxxxx>]

On 10/17/22 05:55, David Touzeau wrote:

> After few days production, it seems you are right, there is some DNS issues.
>
> That is strange because in v4 on the same server, we have no issue.
>
> Maybe a coincidence and the fact that v4 is less sensitive to DNS errors

I would rather not speculate regarding such vague terms as DNS error 
sensitivity of a Squid version. If you find a way to reproduce the 
problem and/or collect more logs, we should be able to get to the bottom 
of this. It is possible that we need to fix some Squid v5 bugs here...

Alex.


> Le 13/10/2022 à 19:41, Alex Rousskov a écrit :
> > On 10/13/22 03:05, David Touzeau wrote:
> > > I have pushed more previous data here:
> > >
> > > http://articatech.net/tmpf/cache.log.txt
> >
> > As I suspected, a Squid worker (kid3) found no destinations that can 
> > be used to forward this request:
> >
> > > peer_select.cc(479) resolveSelected: PeerSelector43309 found all 0 
> > > destinations for categories.articatech.net:443
> >
> > > FwdState.cc(209) stopAndDestroy: for path selection found no paths
> >
> > > FwdState.cc(492) fail: ERR_READ_ERROR "Bad Gateway"
> >
> >
> > There were no destinations because Squid cache had a no-IPs DNS entry 
> > for the above domain:
> >
> > > ipcache.cc(647) ipcache_nbgethostbyname_: ... HIT for 
> > > 'categories.articatech.net'
> >
> > > ipcache.cc(231) finalCallback: ... lookup_err=No DNS records
> >
> >
> >
> > AFAICT, the shared logs start _after_ the corresponding DNS cache 
> > entry was created (or lost its IPs), so I cannot tell what actually 
> > happened back then.
> >
> > Later, the expired(?) no-IPs DNS cache entry is purged, and Squid is 
> > able to resolve the same host name:
> >
> > > ipcache.cc(532) addGood: categories.articatech.net #1 217.182.193.199
> >
> >
> > And similar transactions start to succeed from this point.
> >
> >
> > If you can share more/earlier logs, I may be able to tell what caused 
> > the 'No DNS records' problem.
> >
> >
> > HTH,
> >
> > Alex.
> > P.S. Please compress debugging logs when sharing.
> >
> >
> > > Le 13/10/2022 à 00:16, Alex Rousskov a écrit :
> > > > On 10/12/22 17:58, David Touzeau wrote:
> > > >
> > > > > We have put it in debug mode :
> > > >
> > > > Unfortunately, this log starts at GET request processing _after_ 
> > > > CONNECT request processing has already encountered and saved the 
> > > > error. Thus, I cannot tell you why that error was encountered. I 
> > > > need to see the lines before the lines you have shared. If you still 
> > > > have the log file, searching for AFC90000000000002632000003000000 
> > > > (above the already shared lines) might help you find where the error 
> > > > message was created.
> > > >
> > > > HTH,
> > > >
> > > > Alex.
> > > >
> > > >
> > > > > you can see :
> > > > >
> > > > >
> > > > > "2022/10/12 22:29:49.476 kid3| 4,3| Error.cc(22) update: recent: 
> > > > > ERR_READ_ERROR/WITH_SERVER"
> > > > >
> > > > > As without ssl-bump, there is no issue.
> > > > >
> > > > > the full log can be downloaded here 
> > > > > http://articatech.net/tmpf/cache.log.txt*
> > > > > *
> > > > >
> > > > > }
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(85) assign: assigning 
> > > > > SBuf15905084 from SBuf15905303
> > > > > 2022/10/12 22:29:49.475 kid3| 11,2| client_side.cc(1357) 
> > > > > parseHttpRequest: HTTP Client conn214046 local=192.168.1.190:3128 
> > > > > remote=192.168.1.13:62858 FD 21 flags=1
> > > > > 2022/10/12 22:29:49.475 kid3| 11,2| client_side.cc(1361) 
> > > > > parseHttpRequest: HTTP Client REQUEST:
> > > > > ---------
> > > > > GET /fw.ping.php?_=1665576594826 HTTP/1.1
> > > > > Host: categories.articatech.net
> > > > > User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:105.0) 
> > > > > Gecko/20100101 Firefox/105.0
> > > > > Accept: */*
> > > > > Accept-Language: fr,fr-FR;q=0.8,en-US;q=0.5,en;q=0.3
> > > > > Accept-Encoding: gzip, deflate, br
> > > > > Referer: https://categories.articatech.net/index
> > > > > X-Requested-With: XMLHttpRequest
> > > > > Connection: keep-alive
> > > > > Cookie: _ga=GA1.2.1172828951.1642984448; 
> > > > > PHPSESSID=28871210b5b031a7b034981e9704a4ac
> > > > > Sec-Fetch-Dest: empty
> > > > > Sec-Fetch-Mode: cors
> > > > > Sec-Fetch-Site: same-origin
> > > > >
> > > > >
> > > > > ----------
> > > > > 2022/10/12 22:29:49.475 kid3| 33,3| client_side.cc(1393) 
> > > > > parseHttpRequest: complete request received. prefix_sz = 542, 
> > > > > request-line-size=43, mime-header-size=499, mime header block:
> > > > > Host: categories.articatech.net
> > > > > User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:105.0) 
> > > > > Gecko/20100101 Firefox/105.0
> > > > > Accept: */*
> > > > > Accept-Language: fr,fr-FR;q=0.8,en-US;q=0.5,en;q=0.3
> > > > > Accept-Encoding: gzip, deflate, br
> > > > > Referer: https://categories.articatech.net/index
> > > > > X-Requested-With: XMLHttpRequest
> > > > > Connection: keep-alive
> > > > > Cookie: _ga=GA1.2.1172828951.1642984448; 
> > > > > PHPSESSID=28871210b5b031a7b034981e9704a4ac
> > > > > Sec-Fetch-Dest: empty
> > > > > Sec-Fetch-Mode: cors
> > > > > Sec-Fetch-Site: same-origin
> > > > >
> > > > >
> > > > > ----------
> > > > > 2022/10/12 22:29:49.475 kid3| 93,5| AsyncJob.cc(34) AsyncJob: 
> > > > > AsyncJob constructed, this=0x56260e3814b8 type=ClientHttpRequest 
> > > > > [job199106]
> > > > > 2022/10/12 22:29:49.475 kid3| 1,5| CodeContext.cc(60) Entering: ALE 
> > > > > w/o master
> > > > > 2022/10/12 22:29:49.475 kid3| 87,3| clientStream.cc(140) 
> > > > > clientStreamInsertHead: clientStreamInsertHead: Inserted node 
> > > > > 0x56260e6d26f8 with data 0x56260e0fa280 after head
> > > > > 2022/10/12 22:29:49.475 kid3| 33,5| client_side.cc(1413) 
> > > > > parseHttpRequest: Prepare absolute URL from
> > > > > 2022/10/12 22:29:49.475 kid3| 25,5| Parser.cc(228) 
> > > > > getHostHeaderField: looking for Host
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(763) findFirstNotOf: 
> > > > > first not of characterset non-LF in id SBuf15905340
> > > > > 2022/10/12 22:29:49.475 kid3| 24,5| Tokenizer.cc(27) consume: 
> > > > > consuming 32 bytes
> > > > > 2022/10/12 22:29:49.475 kid3| 24,5| Tokenizer.cc(27) consume: 
> > > > > consuming 1 bytes
> > > > > 2022/10/12 22:29:49.475 kid3| 25,5| Parser.cc(249) 
> > > > > getHostHeaderField: checking Host: categories.articatech.net
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(763) findFirstNotOf: 
> > > > > first not of characterset WSP in id SBuf15905345
> > > > > 2022/10/12 22:29:49.475 kid3| 24,5| Tokenizer.cc(27) consume: 
> > > > > consuming 1 bytes
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(85) assign: assigning 
> > > > > SBuf15905339 from SBuf15905345
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(763) findFirstNotOf: 
> > > > > first not of characterset host in id SBuf15905339
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(771) findFirstNotOf: 
> > > > > not found
> > > > > 2022/10/12 22:29:49.475 kid3| 25,5| Parser.cc(267) 
> > > > > getHostHeaderField: returning categories.articatech.net
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(85) assign: assigning 
> > > > > SBuf15905347 from SBuf183
> > > > > 2022/10/12 22:29:49.475 kid3| 33,5| client_side.cc(1294) 
> > > > > prepareTlsSwitchingURL: TLS switching host rewrite: 
> > > > > https://categories.articatech.net/fw.ping.php?_=1665576594826
> > > > > 2022/10/12 22:29:49.475 kid3| 33,5| client_side.cc(1981) 
> > > > > clientParseRequests: conn214046 local=192.168.1.190:3128 
> > > > > remote=192.168.1.13:62858 FD 21 flags=1: done parsing a request
> > > > > 2022/10/12 22:29:49.475 kid3| 5,4| AsyncCall.cc(30) AsyncCall: The 
> > > > > AsyncCall ConnStateData::lifetimeTimeout constructed, 
> > > > > this=0x56260e5afd50 [call1972958]
> > > > > 2022/10/12 22:29:49.475 kid3| 5,3| comm.cc(571) commSetConnTimeout: 
> > > > > conn214046 local=192.168.1.190:3128 remote=192.168.1.13:62858 FD 21 
> > > > > flags=1 timeout 86400
> > > > > 2022/10/12 22:29:49.475 kid3| 55,7| HttpHeader.cc(194) clean: 
> > > > > cleaning hdr: 0x56260e392c18 owner: 3
> > > > > 2022/10/12 22:29:49.475 kid3| 55,7| HttpHeader.cc(194) clean: 
> > > > > cleaning hdr: 0x56260e392c18 owner: 3
> > > > > 2022/10/12 22:29:49.475 kid3| 33,3| client_side.cc(1806) add: 
> > > > > 0x56260e0f9210*3 to 0/1
> > > > > 2022/10/12 22:29:49.475 kid3| 33,3| Pipeline.cc(24) add: Pipeline 
> > > > > 0x56260e6cd470 add request 2 0x56260e0f9210*4
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905349
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 61 for SBuf15905349
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905349 new store capacity: 128
> > > > > 2022/10/12 22:29:49.475 kid3| 55,7| HttpHeader.cc(155) HttpHeader: 
> > > > > init-ing hdr: 0x56260e4038f8 owner: 2
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(763) findFirstNotOf: 
> > > > > first not of characterset special in id SBuf15905363
> > > > > 2022/10/12 22:29:49.475 kid3| 24,5| Tokenizer.cc(27) consume: 
> > > > > consuming 5 bytes
> > > > > 2022/10/12 22:29:49.475 kid3| 24,5| Tokenizer.cc(27) consume: 
> > > > > consuming 1 bytes
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(85) assign: assigning 
> > > > > SBuf15905367 from SBuf183
> > > > > 2022/10/12 22:29:49.475 kid3| 24,5| Tokenizer.cc(27) consume: 
> > > > > consuming 2 bytes
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 1 for SBuf15905371
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(167) rawSpace: 
> > > > > SBuf15905371 not growing
> > > > > 2022/10/12 22:29:49.475 kid3| 23,3| Uri.cc(441) parse: Split URL 
> > > > > 'https://categories.articatech.net/fw.ping.php?_=1665576594826' 
> > > > > into proto='https', host='categories.articatech.net', port='443', 
> > > > > path='/fw.ping.php?_=1665576594826'
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(85) assign: assigning 
> > > > > SBuf15905351 from SBuf15905361
> > > > > 2022/10/12 22:29:49.475 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905353 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905353
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 28 for SBuf15905353
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905353 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 14,3| Address.cc(389) lookupHostIP: 
> > > > > Given Non-IP 'categories.articatech.net': Name or service not known
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905373
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 0 for SBuf15905373
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(167) rawSpace: 
> > > > > SBuf15905373 not growing
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(85) assign: assigning 
> > > > > SBuf15905352 from SBuf15905373
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(85) assign: assigning 
> > > > > SBuf15905350 from SBuf15905305
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 1 for SBuf15905374
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(167) rawSpace: 
> > > > > SBuf15905374 not growing
> > > > > 2022/10/12 22:29:49.475 kid3| 55,7| HttpHeader.cc(390) parse: 
> > > > > parsing hdr: (0x56260e4038f8)
> > > > > Host: categories.articatech.net
> > > > > User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:105.0) 
> > > > > Gecko/20100101 Firefox/105.0
> > > > > Accept: */*
> > > > > Accept-Language: fr,fr-FR;q=0.8,en-US;q=0.5,en;q=0.3
> > > > > Accept-Encoding: gzip, deflate, br
> > > > > Referer: https://categories.articatech.net/index
> > > > > X-Requested-With: XMLHttpRequest
> > > > > Connection: keep-alive
> > > > > Cookie: _ga=GA1.2.1172828951.1642984448; 
> > > > > PHPSESSID=28871210b5b031a7b034981e9704a4ac
> > > > > Sec-Fetch-Dest: empty
> > > > > Sec-Fetch-Mode: cors
> > > > > Sec-Fetch-Site: same-origin
> > > > >
> > > > > 2022/10/12 22:29:49.475 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905375 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905375
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 4 for SBuf15905375
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905375 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905376 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905376
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 4 for SBuf15905376
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905376 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e4038f8 adding entry: Host[30] at 0
> > > > > 2022/10/12 22:29:49.475 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905377 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905377
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 10 for SBuf15905377
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905377 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905378 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905378
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 10 for SBuf15905378
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905378 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e4038f8 adding entry: User-Agent[67] at 1
> > > > > 2022/10/12 22:29:49.475 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905379 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905379
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 6 for SBuf15905379
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905379 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905380 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905380
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 6 for SBuf15905380
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905380 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e4038f8 adding entry: Accept[0] at 2
> > > > > 2022/10/12 22:29:49.475 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905381 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905381
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 15 for SBuf15905381
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905381 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905382 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905382
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 15 for SBuf15905382
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905382 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e4038f8 adding entry: Accept-Language[3] at 3
> > > > > 2022/10/12 22:29:49.475 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905383 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905383
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 15 for SBuf15905383
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905383 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905384 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905384
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 15 for SBuf15905384
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905384 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e4038f8 adding entry: Accept-Encoding[2] at 4
> > > > > 2022/10/12 22:29:49.475 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905385 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905385
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 7 for SBuf15905385
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905385 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905386 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905386
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 7 for SBuf15905386
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905386 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e4038f8 adding entry: Referer[54] at 5
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905387
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 16 for SBuf15905387
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905387 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(85) assign: assigning 
> > > > > SBuf15905388 from SBuf15905387
> > > > > 2022/10/12 22:29:49.475 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e4038f8 adding entry: Other:[87] at 6
> > > > > 2022/10/12 22:29:49.475 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905389 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905389
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 10 for SBuf15905389
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905389 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905390 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905390
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 10 for SBuf15905390
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905390 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e4038f8 adding entry: Connection[12] at 7
> > > > > 2022/10/12 22:29:49.475 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905391 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905391
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 6 for SBuf15905391
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905391 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905392 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905392
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 6 for SBuf15905392
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905392 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e4038f8 adding entry: Cookie[22] at 8
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905393
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 14 for SBuf15905393
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905393 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(85) assign: assigning 
> > > > > SBuf15905394 from SBuf15905393
> > > > > 2022/10/12 22:29:49.475 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e4038f8 adding entry: Other:[87] at 9
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905395
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 14 for SBuf15905395
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905395 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(85) assign: assigning 
> > > > > SBuf15905396 from SBuf15905395
> > > > > 2022/10/12 22:29:49.475 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e4038f8 adding entry: Other:[87] at 10
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905397
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 14 for SBuf15905397
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905397 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(85) assign: assigning 
> > > > > SBuf15905398 from SBuf15905397
> > > > > 2022/10/12 22:29:49.475 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e4038f8 adding entry: Other:[87] at 11
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905355
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 25 for SBuf15905355
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905355 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(85) assign: assigning 
> > > > > SBuf15905354 from SBuf15905355
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 6 for SBuf15905355
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(167) rawSpace: 
> > > > > SBuf15905355 not growing
> > > > > 2022/10/12 22:29:49.475 kid3| 33,5| Http1Server.cc(193) 
> > > > > buildHttpRequest: normalize 1 Host header using 
> > > > > categories.articatech.net
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 1 for SBuf15905399
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905399 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905401 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905401
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 4 for SBuf15905401
> > > > > 2022/10/12 22:29:49.475 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905401 new store capacity: 40
> > > > > 2022/10/12 22:29:49.475 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e4038f8 adding entry: Host[30] at 12
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905356 new store capacity: 16384
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 5 for SBuf15905356
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(167) rawSpace: 
> > > > > SBuf15905356 not growing
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905356
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 1 for SBuf15905356
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(167) rawSpace: 
> > > > > SBuf15905356 not growing
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905356
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 2 for SBuf15905356
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(167) rawSpace: 
> > > > > SBuf15905356 not growing
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 25 for SBuf15905356
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(167) rawSpace: 
> > > > > SBuf15905356 not growing
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 28 for SBuf15905356
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(167) rawSpace: 
> > > > > SBuf15905356 not growing
> > > > > 2022/10/12 22:29:49.476 kid3| 33,3| client_side.cc(699) 
> > > > > clientSetKeepaliveFlag: http_ver = HTTP/1.1
> > > > > 2022/10/12 22:29:49.476 kid3| 33,3| client_side.cc(700) 
> > > > > clientSetKeepaliveFlag: method = GET
> > > > > 2022/10/12 22:29:49.476 kid3| 55,6| HttpHeader.cc(850) getList: 
> > > > > 0x56260e4038f8: joined for id Connection[12]: 0x7ffc7248c400
> > > > > 2022/10/12 22:29:49.476 kid3| 33,4| client_side.cc(1510) 
> > > > > quitAfterError: Will close after error: conn214046 
> > > > > local=192.168.1.190:3128 remote=192.168.1.13:62858 FD 21 flags=1
> > > > > 2022/10/12 22:29:49.476 kid3| 33,5| client_side.cc(1531) 
> > > > > serveDelayedError: Responding with delated error for 
> > > > > https://categories.articatech.net/fw.ping.php?_=1665576594826
> > > > > 2022/10/12 22:29:49.476 kid3| 20,3| store.cc(443) lock: 
> > > > > clientReplyContext::setReplyToStoreEntry locked key 
> > > > > AFC90000000000002632000003000000 e:=sp2XIV/0x56260e1b8290*2
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Checklist.cc(70) preCheck: 
> > > > > 0x7ffc7248c000 checking fast rules
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Checklist.cc(343) fastCheck: 
> > > > > aclCheckFast: list: 0x56260c88d7a8
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > delay_access
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Checklist.cc(398) bannedAction: 
> > > > > Action 'ALLOWED/0' is not banned
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > delay_access#1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > Group2
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| DomainData.cc(110) match: 
> > > > > aclMatchDomainList: checking 'categories.articatech.net'
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| DomainData.cc(115) match: 
> > > > > aclMatchDomainList: 'categories.articatech.net' NOT found
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > Group2 = 0
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > delay_access#1 = 0
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Checklist.cc(398) bannedAction: 
> > > > > Action 'DENIED/0' is not banned
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > delay_access#2
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking all
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Ip.cc(538) match: aclIpMatchIp: 
> > > > > '192.168.1.13:62858' found
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > all = 1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > delay_access#2 = 1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > delay_access = 1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Checklist.cc(63) markFinished: 
> > > > > 0x7ffc7248c000 answer DENIED for match
> > > > > 2022/10/12 22:29:49.476 kid3| 28,4| FilledChecklist.cc(67) 
> > > > > ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7ffc7248c000
> > > > > 2022/10/12 22:29:49.476 kid3| 28,4| Checklist.cc(197) 
> > > > > ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x7ffc7248c000
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Checklist.cc(70) preCheck: 
> > > > > 0x7ffc7248c000 checking fast rules
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Checklist.cc(343) fastCheck: 
> > > > > aclCheckFast: list: 0x56260c8c46a8
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > delay_access
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Checklist.cc(398) bannedAction: 
> > > > > Action 'ALLOWED/0' is not banned
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > delay_access#1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > Group2
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| DomainData.cc(110) match: 
> > > > > aclMatchDomainList: checking 'categories.articatech.net'
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| DomainData.cc(115) match: 
> > > > > aclMatchDomainList: 'categories.articatech.net' NOT found
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > Group2 = 0
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > delay_access#1 = 0
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Checklist.cc(398) bannedAction: 
> > > > > Action 'DENIED/0' is not banned
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > delay_access#2
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking all
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Ip.cc(538) match: aclIpMatchIp: 
> > > > > '192.168.1.13:62858' found
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > all = 1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > delay_access#2 = 1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > delay_access = 1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Checklist.cc(63) markFinished: 
> > > > > 0x7ffc7248c000 answer DENIED for match
> > > > > 2022/10/12 22:29:49.476 kid3| 28,4| FilledChecklist.cc(67) 
> > > > > ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7ffc7248c000
> > > > > 2022/10/12 22:29:49.476 kid3| 28,4| Checklist.cc(197) 
> > > > > ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x7ffc7248c000
> > > > > *2022/10/12 22:29:49.476 kid3| 4,3| Error.cc(22) update: recent: 
> > > > > ERR_READ_ERROR/WITH_SERVER*
> > > > > 2022/10/12 22:29:49.476 kid3| 33,5| Stream.cc(117) pullData: 0 
> > > > > written 0 into conn214046 local=192.168.1.190:3128 
> > > > > remote=192.168.1.13:62858 FD 21 flags=1
> > > > > 2022/10/12 22:29:49.476 kid3| 33,5| Stream.cc(141) 
> > > > > getNextRangeOffset: range: 0; http offset 0; reply 0
> > > > > 2022/10/12 22:29:49.476 kid3| 87,3| clientStream.cc(180) 
> > > > > clientStreamRead: clientStreamRead: Calling 1 with cbdata 
> > > > > 0x56260e0d2ba8 from node 0x56260e6d26f8
> > > > > 2022/10/12 22:29:49.476 kid3| 90,3| store_client.cc(246) copy: 
> > > > > store_client::copy: AFC90000000000002632000003000000, from 0, for 
> > > > > length 4096, cb 1, cbdata 0x56260e0d1ad8
> > > > > 2022/10/12 22:29:49.476 kid3| 20,3| store.cc(443) lock: 
> > > > > store_client::copy locked key AFC90000000000002632000003000000 
> > > > > e:=sp2XIV/0x56260e1b8290*3
> > > > > 2022/10/12 22:29:49.476 kid3| 90,3| store_client.cc(338) 
> > > > > storeClientCopy2: storeClientCopy2: AFC90000000000002632000003000000
> > > > > 2022/10/12 22:29:49.476 kid3| 33,5| store_client.cc(368) doCopy: 
> > > > > store_client::doCopy: co: 0, hi: 506665
> > > > > 2022/10/12 22:29:49.476 kid3| 90,3| store_client.cc(472) 
> > > > > scheduleMemRead: store_client::doCopy: Copying normal from memory
> > > > > 2022/10/12 22:29:49.476 kid3| 19,6| stmem.cc(230) copy: memCopy: 
> > > > > 0x56260db339f8 [0,4096)
> > > > > 2022/10/12 22:29:49.476 kid3| 88,5| client_side_reply.cc(2213) 
> > > > > sendMoreData: conn214046 local=192.168.1.190:3128 
> > > > > remote=192.168.1.13:62858 FD 21 flags=1 
> > > > > 'categories.articatech.net:443' out.offset=0
> > > > > 2022/10/12 22:29:49.476 kid3| 88,5| client_side_reply.cc(2241) 
> > > > > sendMoreData: clientReplyContext::sendMoreData: 
> > > > > https://categories.articatech.net/fw.ping.php?_=1665576594826, 4096 
> > > > > bytes (4096 new bytes)
> > > > > 2022/10/12 22:29:49.476 kid3| 55,7| HttpHeader.cc(155) HttpHeader: 
> > > > > init-ing hdr: 0x56260e392c18 owner: 3
> > > > > 2022/10/12 22:29:49.476 kid3| 55,7| HttpHeader.cc(243) append: 
> > > > > appending hdr: 0x56260e392c18 += 0x56260db7a728
> > > > > 2022/10/12 22:29:49.476 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905409 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905409
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 6 for SBuf15905409
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905409 new store capacity: 40
> > > > > 2022/10/12 22:29:49.476 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e392c18 adding entry: Server[57] at 0
> > > > > 2022/10/12 22:29:49.476 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905410 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905410
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 12 for SBuf15905410
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905410 new store capacity: 40
> > > > > 2022/10/12 22:29:49.476 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e392c18 adding entry: Mime-Version[43] at 1
> > > > > 2022/10/12 22:29:49.476 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905411 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905411
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 4 for SBuf15905411
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905411 new store capacity: 40
> > > > > 2022/10/12 22:29:49.476 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e392c18 adding entry: Date[24] at 2
> > > > > 2022/10/12 22:29:49.476 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905412 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905412
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 12 for SBuf15905412
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905412 new store capacity: 40
> > > > > 2022/10/12 22:29:49.476 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e392c18 adding entry: Content-Type[21] at 3
> > > > > 2022/10/12 22:29:49.476 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905413 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905413
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 14 for SBuf15905413
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905413 new store capacity: 40
> > > > > 2022/10/12 22:29:49.476 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e392c18 adding entry: Content-Length[17] at 4
> > > > > 2022/10/12 22:29:49.476 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905414 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905414
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 13 for SBuf15905414
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905414 new store capacity: 40
> > > > > 2022/10/12 22:29:49.476 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e392c18 adding entry: X-Squid-Error[76] at 5
> > > > > 2022/10/12 22:29:49.476 kid3| 66,7| HttpHeaderTools.cc(156) 
> > > > > httpHeaderParseOffset: offset 506470 parsed as 506470
> > > > > 2022/10/12 22:29:49.476 kid3| 66,7| HttpHeaderTools.cc(156) 
> > > > > httpHeaderParseOffset: offset 506470 parsed as 506470
> > > > > 2022/10/12 22:29:49.476 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905416 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905416
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 7 for SBuf15905416
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905416 new store capacity: 40
> > > > > 2022/10/12 22:29:49.476 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e392c18 adding entry: X-Cache[72] at 6
> > > > > 2022/10/12 22:29:49.476 kid3| 33,2| client_side_reply.cc(1585) 
> > > > > buildReplyHeader: clientBuildReplyHeader: Connection Keep-Alive not 
> > > > > requested by admin or client
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 16 for SBuf15905417
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905417 new store capacity: 40
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 96 for SBuf15905417
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| MemBlob.cc(130) syncSize: 0 was: 0
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905417 new store capacity: 128
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(85) assign: assigning 
> > > > > SBuf15905418 from SBuf15905417
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 1 for SBuf15905418
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(167) rawSpace: 
> > > > > SBuf15905418 not growing
> > > > > 2022/10/12 22:29:49.476 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905420 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905420
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 3 for SBuf15905420
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905420 new store capacity: 40
> > > > > 2022/10/12 22:29:49.476 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e392c18 adding entry: Via[69] at 7
> > > > > 2022/10/12 22:29:49.476 kid3| 24,6| SBuf.cc(99) assign: 
> > > > > SBuf15905422 from c-string, n=4294967295)
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(209) append: from 
> > > > > c-string to id SBuf15905422
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(160) rawSpace: 
> > > > > reserving 10 for SBuf15905422
> > > > > 2022/10/12 22:29:49.476 kid3| 24,7| SBuf.cc(866) reAlloc: 
> > > > > SBuf15905422 new store capacity: 40
> > > > > 2022/10/12 22:29:49.476 kid3| 55,7| HttpHeader.cc(786) addEntry: 
> > > > > 0x56260e392c18 adding entry: Connection[12] at 8
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Checklist.cc(70) preCheck: 
> > > > > 0x7ffc7248bb70 checking fast rules
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Checklist.cc(343) fastCheck: 
> > > > > aclCheckFast: list: 0x56260c8adf68
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > http_header_access Server
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Checklist.cc(398) bannedAction: 
> > > > > Action 'DENIED/0' is not banned
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > http_header_access Server#1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking all
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Ip.cc(538) match: aclIpMatchIp: 
> > > > > '192.168.1.13:62858' found
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > all = 1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > http_header_access Server#1 = 1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > http_header_access Server = 1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Checklist.cc(63) markFinished: 
> > > > > 0x7ffc7248bb70 answer DENIED for match
> > > > > 2022/10/12 22:29:49.476 kid3| 66,7| HttpHeaderTools.cc(308) 
> > > > > httpHdrMangle: checklist denied, we have no replacement. Pass
> > > > > 2022/10/12 22:29:49.476 kid3| 28,4| FilledChecklist.cc(67) 
> > > > > ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7ffc7248bb70
> > > > > 2022/10/12 22:29:49.476 kid3| 28,4| Checklist.cc(197) 
> > > > > ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x7ffc7248bb70
> > > > > 2022/10/12 22:29:49.476 kid3| 66,7| HttpHeaderTools.cc(286) 
> > > > > httpHdrMangle: couldn't find mangler or access list. Allowing
> > > > > 2022/10/12 22:29:49.476 kid3| 66,7| HttpHeaderTools.cc(286) 
> > > > > httpHdrMangle: couldn't find mangler or access list. Allowing
> > > > > 2022/10/12 22:29:49.476 kid3| 66,7| HttpHeaderTools.cc(286) 
> > > > > httpHdrMangle: couldn't find mangler or access list. Allowing
> > > > > 2022/10/12 22:29:49.476 kid3| 66,7| HttpHeaderTools.cc(286) 
> > > > > httpHdrMangle: couldn't find mangler or access list. Allowing
> > > > > 2022/10/12 22:29:49.476 kid3| 66,7| HttpHeaderTools.cc(286) 
> > > > > httpHdrMangle: couldn't find mangler or access list. Allowing
> > > > > 2022/10/12 22:29:49.476 kid3| 66,7| HttpHeaderTools.cc(286) 
> > > > > httpHdrMangle: couldn't find mangler or access list. Allowing
> > > > > 2022/10/12 22:29:49.476 kid3| 66,7| HttpHeaderTools.cc(286) 
> > > > > httpHdrMangle: couldn't find mangler or access list. Allowing
> > > > > 2022/10/12 22:29:49.476 kid3| 66,7| HttpHeaderTools.cc(286) 
> > > > > httpHdrMangle: couldn't find mangler or access list. Allowing
> > > > > 2022/10/12 22:29:49.476 kid3| 55,7| HttpHeader.cc(769) refreshMask: 
> > > > > refreshing the mask in hdr 0x56260e392c18
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Checklist.cc(70) preCheck: 
> > > > > 0x7ffc7248bcb0 checking fast rules
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Checklist.cc(343) fastCheck: 
> > > > > aclCheckFast: list: 0x56260c88d7a8
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > delay_access
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Checklist.cc(398) bannedAction: 
> > > > > Action 'ALLOWED/0' is not banned
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > delay_access#1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > Group2
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| DomainData.cc(110) match: 
> > > > > aclMatchDomainList: checking 'categories.articatech.net'
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| DomainData.cc(115) match: 
> > > > > aclMatchDomainList: 'categories.articatech.net' NOT found
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > Group2 = 0
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > delay_access#1 = 0
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Checklist.cc(398) bannedAction: 
> > > > > Action 'DENIED/0' is not banned
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > delay_access#2
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking all
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Ip.cc(538) match: aclIpMatchIp: 
> > > > > '192.168.1.13:62858' found
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > all = 1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > delay_access#2 = 1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > delay_access = 1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Checklist.cc(63) markFinished: 
> > > > > 0x7ffc7248bcb0 answer DENIED for match
> > > > > 2022/10/12 22:29:49.476 kid3| 28,4| FilledChecklist.cc(67) 
> > > > > ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7ffc7248bcb0
> > > > > 2022/10/12 22:29:49.476 kid3| 28,4| Checklist.cc(197) 
> > > > > ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x7ffc7248bcb0
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Checklist.cc(70) preCheck: 
> > > > > 0x7ffc7248bcb0 checking fast rules
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Checklist.cc(343) fastCheck: 
> > > > > aclCheckFast: list: 0x56260c8c46a8
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > delay_access
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Checklist.cc(398) bannedAction: 
> > > > > Action 'ALLOWED/0' is not banned
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > delay_access#1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > Group2
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| DomainData.cc(110) match: 
> > > > > aclMatchDomainList: checking 'categories.articatech.net'
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| DomainData.cc(115) match: 
> > > > > aclMatchDomainList: 'categories.articatech.net' NOT found
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > Group2 = 0
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > delay_access#1 = 0
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Checklist.cc(398) bannedAction: 
> > > > > Action 'DENIED/0' is not banned
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > delay_access#2
> > > > > 2022/10/12 22:29:49.476 kid3| 28,5| Acl.cc(124) matches: checking all
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Ip.cc(538) match: aclIpMatchIp: 
> > > > > '192.168.1.13:62858' found
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > all = 1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > delay_access#2 = 1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > delay_access = 1
> > > > > 2022/10/12 22:29:49.476 kid3| 28,3| Checklist.cc(63) markFinished: 
> > > > > 0x7ffc7248bcb0 answer DENIED for match
> > > > > 2022/10/12 22:29:49.476 kid3| 28,4| FilledChecklist.cc(67) 
> > > > > ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7ffc7248bcb0
> > > > > 2022/10/12 22:29:49.477 kid3| 28,4| Checklist.cc(197) 
> > > > > ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x7ffc7248bcb0
> > > > > 2022/10/12 22:29:49.477 kid3| 28,3| Checklist.cc(70) preCheck: 
> > > > > 0x7ffc7248bc10 checking fast ACLs
> > > > > 2022/10/12 22:29:49.477 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > reply_body_max_size -1
> > > > > 2022/10/12 22:29:49.477 kid3| 28,5| Acl.cc(124) matches: checking 
> > > > > (reply_body_max_size -1 line)
> > > > > 2022/10/12 22:29:49.477 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > (reply_body_max_size -1 line) = 1
> > > > > 2022/10/12 22:29:49.477 kid3| 28,3| Acl.cc(151) matches: checked: 
> > > > > reply_body_max_size -1 = 1
> > > > > 2022/10/12 22:29:49.477 kid3| 28,3| Checklist.cc(63) markFinished: 
> > > > > 0x7ffc7248bc10 answer ALLOWED for match
> > > > > 2022/10/12 22:29:49.477 kid3| 58,4| HttpReply.cc(564) 
> > > > > calcMaxBodySize: bodySizeMax=-1
> > > > > 2022/10/12 22:29:49.477 kid3| 28,4| FilledChecklist.cc(67) 
> > > > > ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7ffc7248bc10
> > > > > 2022/10/12 22:29:49.477 kid3| 28,4| Checklist.cc(197) 
> > > > > ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x7ffc7248bc10
> > > > > 2022/10/12 22:29:49.477 kid3| 58,7| HttpReply.cc(528) 
> > > > > expectedBodyTooLarge: bodySizeMax=-1
> > > > > 2022/10/12 22:29:49.477 kid3| 88,2| client_side_reply.cc(2090) 
> > > > > processReplyAccessResult: The reply for GET 
> > > > > https://categories.articatech.net/fw.ping.php?_=1665576594826 is 
> > > > > ALLOWED, because it matched (reply_body_max_size -1 line)
> > > > > 2022/10/12 22:29:49.477 kid3| 20,3| store.cc(443) lock: 
> > > > > ClientHttpRequest::loggingEntry locked key 
> > > > > AFC90000000000002632000003000000 e:=sp2XIV/0x56260e1b8290*4
> > > > > 2022/10/12 22:29:49.477 kid3| 88,3| client_side_reply.cc(2128) 
> > > > > processReplyAccessResult: clientReplyContext::sendMoreData: 
> > > > > Appending 3901 bytes after 195 bytes of headers
> > > > > 2022/10/12 22:29:49.477 kid3| 87,3| clientStream.cc(158) 
> > > > > clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 
> > > > > 0x56260e0fa280 from node 0x56260e5c0ab8
> > > > > 2022/10/12 22:29:49.477 kid3| 33,3| Pipeline.cc(35) front: Pipeline 
> > > > > 0x56260e6cd470 front 0x56260e0f9210*4
> > > > > 2022/10/12 22:29:49.477 kid3| 33,3| Pipeline.cc(35) front: Pipeline 
> > > > > 0x56260e6cd470 front 0x56260e0f9210*4
> > > > > 2022/10/12 22:29:49.477 kid3| 55,7| HttpHeader.cc(589) packInto: 
> > > > > 0x56260e392c18 into 0x56260e26ebe8
> > > > > 2022/10/12 22:29:49.477 kid3| 11,2| Stream.cc(279) 
> > > > > sendStartOfMessage: HTTP Client conn214046 local=192.168.1.190:3128 
> > > > > remote=192.168.1.13:62858 FD 21 flags=1
> > > > > 2022/10/12 22:29:49.477 kid3| 11,2| Stream.cc(280) 
> > > > > sendStartOfMessage: HTTP Client REPLY:
> > > > > ---------
> > > > > HTTP/1.1 502 Bad Gateway
> > > > > Mime-Version: 1.0
> > > > > Date: Wed, 12 Oct 2022 20:29:49 GMT
> > > > > Content-Type: text/html;charset=utf-8
> > > > > Content-Length: 506470
> > > > > X-Squid-Error: ERR_READ_ERROR 0
> > > > > X-Cache: MISS from proxy-190.articatech.int
> > > > > Via: 1.1 789aaa51-a1eb-eb48-639b-000070877aed (squid)
> > > > > Connection: close
> > > > >
> > > > >
> > > > > Le 12/10/2022 à 20:00, Alex Rousskov a écrit :
> > > > > > On 10/12/22 12:45, David Touzeau wrote:
> > > > > > > Hi
> > > > > > >
> > > > > > > We using squid 5.7 after adding ssl-bump we have sometimes 
> > > > > > > several 502 error  with extended error ERR_READ_ERROR|WITH_SERVER
> > > > > > >
> > > > > > > 1665589818.831     11 192.168.1.13 NONE_NONE/502 192616 OPTIONS 
> > > > > > > https://www2.deepl.com/jsonrpc?method=LMT_split_text - 
> > > > > > > HIER_NONE/-:- text/html mac="68:54:5a:94:e7:56" - 
> > > > > > > exterr="ERR_READ_ERROR|WITH_SERVER"
> > > > > > > 1665589839.288     11 192.168.1.13 NONE_NONE/502 506759 POST 
> > > > > > > https://pollserver.lastpass.com/poll_server.php - HIER_NONE/-:- 
> > > > > > > text/html mac="68:54:5a:94:e7:56" - 
> > > > > > > exterr="ERR_READ_ERROR|WITH_SERVER"
> > > > > > > 1665589719.879     44 192.168.1.13 NONE_NONE/502 506954 GET 
> > > > > > > https://contile.services.mozilla.com/v1/tiles - HIER_NONE/-:- 
> > > > > > > text/html mac="68:54:5a:94:e7:56" - 
> > > > > > > exterr="ERR_READ_ERROR|WITH_SERVER"
> > > > > >
> > > > > > > What does it means.
> > > > > >
> > > > > > 502 with ERR_READ_ERROR|WITH_SERVER may mean several things 
> > > > > > (unfortunately). Given HIER_NONE, I would suspect that Squid could 
> > > > > > not find a valid destination for the request. There is a similar 
> > > > > > recent squid-users thread at 
> > > > > > http://lists.squid-cache.org/pipermail/squid-users/2022-October/025289.html 
> > > > > >
> > > > > >
> > > > > >
> > > > > > > how can we fix it ?
> > > > > >
> > > > > > The first step is to identify what causes these errors.
> > > > > >
> > > > > > Can you reproduce this problem at will? Perhaps by trying going to 
> > > > > > https://dnslabeldoesnotexist.com mentioned at the above thread? If 
> > > > > > you can, consider sharing (a pointer to) a compressed debugging 
> > > > > > cache.log from a test box that does not expose any internal 
> > > > > > secrets, as detailed at 
> > > > > > https://wiki.squid-cache.org/SquidFaq/BugReporting#Debugging_a_single_transaction 


_______________________________________________
squid-users mailing list
squid-users@xxxxxxxxxxxxxxxxxxxxx
http://lists.squid-cache.org/listinfo/squid-users