[squid-users] Squid 5.7 + bump ERR_READ_ERROR|WITH_SERVER
Alex Rousskov
rousskov at measurement-factory.com
Mon Oct 17 13:41:42 UTC 2022
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
More information about the squid-users
mailing list