Haproxy logs - Termination state PR- -

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 :slight_smile:

Sorry, english is not my first language.
Thanks!

Hi,

We are seeing a similar but not idential error in our logs. We get a and 500 http response code instead. We are currently running with the latest (2.4.3) official haproxy alpine based container image.

So far we have only seen this error on frontends where we are enforcing client certificate validation.

Neither stdout/stderr output nor stats show errors command show any additional information so it is pretty hard to get an understanding about why the request is beeing blocked by HAProxy. We would really appreciate tutorials/guides on how to debug this on a lower level.

show info output:

Name: HAProxy
Version: 2.4.3-4dd5a5a
Release_date: 2021/08/17
Nbthread: 4
Nbproc: 1
Process_num: 1
Pid: 49
Uptime: 0d 0h03m18s
Uptime_sec: 198
Memmax_MB: 0
PoolAlloc_MB: 0
PoolUsed_MB: 0
PoolFailed: 0
Ulimit-n: 20241
Maxsock: 20241
Maxconn: 10000
Hard_maxconn: 10000
CurrConns: 16
CumConns: 15323
CumReq: 316
MaxSslConns: 0
CurrSslConns: 25
CumSslConns: 2472
Maxpipes: 0
PipesUsed: 0
PipesFree: 0
ConnRate: 0
ConnRateLimit: 0
MaxConnRate: 5
SessRate: 0
SessRateLimit: 0
MaxSessRate: 5
SslRate: 1
SslRateLimit: 0
MaxSslRate: 3
SslFrontendKeyRate: 1
SslFrontendMaxKeyRate: 3
SslFrontendSessionReuse_pct: 0
SslBackendKeyRate: 6
SslBackendMaxKeyRate: 16
SslCacheLookups: 33
SslCacheMisses: 32
CompressBpsIn: 0
CompressBpsOut: 0
CompressBpsRateLim: 0
Tasks: 288
Run_queue: 0
Idle_pct: 99
node: 5120cbdc4a9a
Stopping: 0
Jobs: 39
Unstoppable Jobs: 1
Listeners: 10
ActivePeers: 0
ConnectedPeers: 0
DroppedLogs: 0
BusyPolling: 0
FailedResolutions: 0
TotalBytesOut: 3794152
TotalSplicdedBytesOut: 0
BytesOutRate: 10464
DebugCommandsIssued: 0
CumRecvLogs: 0
Build info: 2.4.3-4dd5a5a
Memmax_bytes: 0
PoolAlloc_bytes: 464288
PoolUsed_bytes: 464288
Start_time_sec: 1629735904
Tainted: 0