Hi, I’m using Haproxy 2.2 and I’m observing some strange pattern in Haproxy logs:
Aug 20, 2021 @ 09:29:06.595 <134>Aug 20 12:29:06 haproxy[211]: 1.2.3.4:56929 [20/Aug/2021:12:29:06.595] www-https~ www-https/ -1/-1/-1/-1/0 0 0 - - PR– 5697/5652/0/0/0 0/0 “<BADREQ>”
Aug 20, 2021 @ 09:29:05.948 <134>Aug 20 12:29:05 haproxy[211]: 1.2.3.4:26229 [20/Aug/2021:12:29:05.950] www-https~ www-https/ -1/-1/-1/-1/0 0 0 - - PR– 5697/5652/0/0/0 0/0 “<BADREQ>”
Aug 20, 2021 @ 09:29:05.213 <134>Aug 20 12:29:05 haproxy[211]: 11.2.3.4:22895 [20/Aug/2021:12:29:05.215] www-https~ www-https/ -1/-1/-1/-1/0 0 0 - - PR– 5691/5646/0/0/0 0/0 “<BADREQ>”
Aug 20, 2021 @ 09:29:03.283 <134>Aug 20 12:29:03 haproxy[211]: 1.2.3.4:26837 [20/Aug/2021:12:29:03.282] www-https~ www-https/ -1/-1/-1/-1/0 0 0 - - PR– 5684/5639/0/0/0 0/0 “<BADREQ>”
Aug 20, 2021 @ 09:29:02.391 <134>Aug 20 12:29:02 haproxy[211]: 1.2.3.4:62325 [20/Aug/2021:12:29:02.391] www-https~ www-https/ -1/-1/-1/-1/0 0 0 - - PR– 5689/5644/0/0/0 0/0 “<BADREQ>”
The first interesting point is that at the end of each line we have “<BADREQ>”, but the status code returned is 0, does anyone know what that means?
The second point is the termination state that each line has, looking in the documentation:
On the first character:
P : the session was prematurely aborted by the proxy, because of a
connection limit enforcement, because a DENY filter was matched,
because of a security check which detected and blocked a dangerous
error in server response which might have caused information leak
(e.g. cacheable cookie).
On the second character:
R : the proxy was waiting for a complete, valid REQUEST from the client
(HTTP mode only). Nothing was sent to any server.
So I’m trying to understand what this logs actually means. Tried to find if this error is some connection limit, so I runned “show info” and got:
Version: 2.2.14-a07ac36
Release_date: 2021/04/29
Nbthread: 16
Nbproc: 1
Process_num: 1
Pid: 211
Uptime: 0d 9h25m53s
Uptime_sec: 33953
Memmax_MB: 0
PoolAlloc_MB: 43
PoolUsed_MB: 35
PoolFailed: 0
Ulimit-n: 1000000
Maxsock: 200204
Maxconn: 100000
Hard_maxconn: 100000
CurrConns: 5993
CumConns: 669024
CumReq: 1026019
MaxSslConns: 0
CurrSslConns: 5942
CumSslConns: 249378
Maxpipes: 0
PipesUsed: 0
PipesFree: 0
ConnRate: 41
ConnRateLimit: 0
MaxConnRate: 70
SessRate: 41
SessRateLimit: 0
MaxSessRate: 70
SslRate: 41
SslRateLimit: 0
MaxSslRate: 62
SslFrontendKeyRate: 9
SslFrontendMaxKeyRate: 24
SslFrontendSessionReuse_pct: 78
SslBackendKeyRate: 0
SslBackendMaxKeyRate: 0
SslCacheLookups: 387
SslCacheMisses: 116
CompressBpsIn: 0
CompressBpsOut: 0
CompressBpsRateLim: 0
Tasks: 15378
Run_queue: 1
Idle_pct: 98
node: 3f0274d68f82
Stopping: 0
Jobs: 6001
Unstoppable Jobs: 0
Listeners: 7
ActivePeers: 0
ConnectedPeers: 0
DroppedLogs: 85
BusyPolling: 0
FailedResolutions: 0
TotalBytesOut: 14189641212
BytesOutRate: 5402528
DebugCommandsIssued: 0
Build info: 2.2.14-a07ac36
If I understood it well it says that we are not even close to connection limit. Trying to find if it was some denied request, I collected Haproxy status and got this:
So the last hypotheses from the documentation is “because of a security check which detected and blocked a dangerous error in server response which might have caused information leak”, but I didn’t quite understand this one… Am I missing something? Has anyone experienced this? Some help or tips for debug are welcome
Sorry, english is not my first language.
Thanks!