Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

FCGI calls return 500 with "IH" Stream State #2568

Closed
git001 opened this issue May 16, 2024 · 17 comments
Closed

FCGI calls return 500 with "IH" Stream State #2568

git001 opened this issue May 16, 2024 · 17 comments
Labels
status: fixed This issue is a now-fixed bug. type: bug This issue describes a bug.

Comments

@git001
Copy link
Contributor

git001 commented May 16, 2024

Detailed Description of the Problem

I have a strange behavior with HAProxy and FCGI PHP App.

When I call any URL from the php app HAProxy returns randomly a 500, after a refresh of the same page returns the HAProxy 200.

10.128.2.35:39684 [16/May/2024:14:54:26.229] craft-cms fcgi-servers/craftcms1 0/0/0/-1/1138 500 15416 - - IH-- 2/2/0/0/0 0/0 "GET /craftcms/admin/settings HTTP/1.1"

10.131.0.26:46546 [16/May/2024:14:56:01.870] craft-cms fcgi-servers/craftcms1 0/0/0/1511/1514 200 113460 - - ---- 2/2/0/0/0 0/0 "GET /craftcms/admin/settings HTTP/1.1"

I have added the fcgi trace

global
  log stdout format raw daemon debug

  pidfile     /data/haproxy/run/haproxy.pid
  # maxconn  auto config from hap
  # nbthread auto config from hap

  master-worker

  #tune.comp.maxlevel 5

  expose-experimental-directives
  trace fcgi sink stdout
  trace fcgi verbosity advanced
  trace fcgi event any
  trace fcgi start now

    # turn on stats unix socket
  stats socket /data/haproxy/run/stats mode 660 level admin expose-fd listeners

and got this outputs for error and success case.

Error Case

0000002b:craft-cms.accept(0009)=002d from [10.131.0.26:56214] ALPN=<none>
0000002b:craft-cms.clireq[002d:ffffffff]: GET /craftcms/cpresources/970470f8/Dashboard.js?v=1715869192 HTTP/1.1
0000002b:craft-cms.clihdr[002d:ffffffff]: x-forwarded-proto: https
0000002b:craft-cms.clihdr[002d:ffffffff]: x-forwarded-port: 443
0000002b:craft-cms.clihdr[002d:ffffffff]: x-forwarded-for: 10.153.102.220, 10.153.102.220, 10.153.249.4, 217.149.228.18:51604
0000002b:craft-cms.clihdr[002d:ffffffff]: x-original-url: /craftcms/cpresources/970470f8/Dashboard.js?v=1715869192
0000002b:craft-cms.clihdr[002d:ffffffff]: x-appgw-trace-id: 547f7ec1baff51f3cebfd9591f8047de
0000002b:craft-cms.clihdr[002d:ffffffff]: x-original-host: $DOMAIN
0000002b:craft-cms.clihdr[002d:ffffffff]: pragma: no-cache
0000002b:craft-cms.clihdr[002d:ffffffff]: cache-control: no-cache
0000002b:craft-cms.clihdr[002d:ffffffff]: sec-ch-ua: "Chromium";v="124", "Google Chrome";v="124", "Not-A.Brand";v="99"
0000002b:craft-cms.clihdr[002d:ffffffff]: sec-ch-ua-mobile: ?0
0000002b:craft-cms.clihdr[002d:ffffffff]: user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36
0000002b:craft-cms.clihdr[002d:ffffffff]: sec-ch-ua-platform: "Windows"
0000002b:craft-cms.clihdr[002d:ffffffff]: accept: */*
0000002b:craft-cms.clihdr[002d:ffffffff]: sec-fetch-site: same-origin
0000002b:craft-cms.clihdr[002d:ffffffff]: sec-fetch-mode: no-cors
0000002b:craft-cms.clihdr[002d:ffffffff]: sec-fetch-dest: script
0000002b:craft-cms.clihdr[002d:ffffffff]: referer: https://$DOMAIN/craftcms/admin/dashboard
0000002b:craft-cms.clihdr[002d:ffffffff]: accept-encoding: gzip, deflate, br, zstd
0000002b:craft-cms.clihdr[002d:ffffffff]: accept-language: de-DE,de;q=0.9
0000002b:craft-cms.clihdr[002d:ffffffff]: cookie: idsrv.sessionCORS=3c28502c9d019ddfd3fdd9935f995f96; idsrv.session=3c28502c9d019ddfd3fdd9935f995f96; $CUST-ns-azure=7c02a3dcac290dde3b937f4e7c8b3379a24f7f76e94ef2af9563d149fce18fdcad0013f0; 3de564f513c74f77a6c49a102a6c07a9_username=70cd51e1e7ce06bbbce9dc32e850074a444cb2fdedc90141c598783508564360a%3A2%3A%7Bi%3A0%3Bs%3A41%3A%223de564f513c74f77a6c49a102a6c07a9_username%22%3Bi%3A1%3Bs%3A5%3A%22admin%22%3B%7D; 3de564f513c74f77a6c49a102a6c07a9_license_shun=dba5e213895f2cf57f6335e38e2c15f95b283cc89a8040ed055ff9e70220d205a%3A2%3A%7Bi%3A0%3Bs%3A45%3A%223de564f513c74f77a6c49a102a6c07a9_license_shun%22%3Bi%3A1%3Bs%3A93%3A%22%7B%22hash%22%3A%2225a61645c2ff0af72e388e25582dd2ef%22%2C%22timestamp%22%3A%222024-05-16T08%3A17%3A27-07%3A00%22%2C%22count%22%3A1%7D%22%3B%7D; CraftSessionId=aaab656109a913e2808e006ce9a7cb6d; 3de564f513c74f77a6c49a102a6c07a9_identity=62db8f6481d9c1263b4652d4fb592b9187c2cc01a2debbc6bdcc6125ead2b2d7a%3A2%3A%7Bi%3A0%3Bs%3A41%3A%223de564f513c74f77a6c49a102a6c07a9_identity%22%3Bi%3A1%3Bs%3A159%3A%22%5B1%2C%22%5B%5C%222ONltZEkKbkXuYMiTUU9BuuhXhtKKbPnOuGNvVKZnWIeGhOIySr6n_AjCRZRgH0Iaj-SMYSWisVfOmcJB7rFkgQX2Z1WwIHBqBr1%5C%22%2Cnull%2C%5C%22a16ddaab909d2cf27fce353f26dd2ff2%5C%22%5D%22%2C3600%5D%22%3B%7D; CRAFT_CSRF_TOKEN=cda2fc094e55f24cfe00de6636fec2804ec4d360e631caf387ca8b444089c5a2a%3A2%3A%7Bi%3A0%3Bs%3A16%3A%22CRAFT_CSRF_TOKEN%22%3Bi%3A1%3Bs%3A147%3A%227XAfKLzpnEyiobtHKkOxaQ26fUt--iDSTDm0pPcy%7Cadc1e7e7d35f32269ebe51c37470088ba2df48da93b045695361ac75824fb0967XAfKLzpnEyiobtHKkOxaQ26fUt--iDSTDm0pPcy%7C1%22%3B%7D
0000002b:craft-cms.clihdr[002d:ffffffff]: x-orig-addr: 10.153.102.220
0000002b:craft-cms.clihdr[002d:ffffffff]: x-forwarded-host: $DOMAIN
0000002b:craft-cms.clihdr[002d:ffffffff]: x-forwarded-server: $DOMAIN
0000002b:craft-cms.clihdr[002d:ffffffff]: host: craftcms.apps.arodev02.westeurope.aroapp.io:443
0000002b:craft-cms.clihdr[002d:ffffffff]: forwarded: for=10.196.9.5;host=craftcms.apps.arodev02.westeurope.aroapp.io:443;proto=https
[07|fcgi|1|x_fcgi.c:4006] sending FCGI PARAMS record [rsp:MSG_RPBEFORE] - "GET /index.php/craftcms/cpresources/970470f8/Dashboard.js?v=1715869192 HTTP/1.1" - fconn=0x7f5037c13f00(RDH,0x00001000) fstrm=0x7f5037c55300(3,OPN,0x00000300)
[07|fcgi|1|x_fcgi.c:1795] FCGI request fully xferred [rsp:MSG_RPBEFORE] - fconn=0x7f5037c13f00(RDH,0x00001000) fstrm=0x7f5037c55300(3,OPN,0x00000306)
[07|fcgi|1|x_fcgi.c:3382] rcvd H1 response headers [rsp:MSG_DATA] - "HTTP/1.1 200 OK" - fconn=0x7f5037c13f00(RDD,0x00001000) fstrm=0x7f5037c55300(3,OPN,0x00000306)
0000002b:fcgi-servers.srvrep[002d:002a]: HTTP/1.1 200 OK
0000002b:fcgi-servers.srvhdr[002d:002a]: cache-control: no-store
0000002b:fcgi-servers.srvhdr[002d:002a]: pragma: public
0000002b:fcgi-servers.srvhdr[002d:002a]: accept-ranges: bytes
0000002b:fcgi-servers.srvhdr[002d:002a]: expires: 0
0000002b:fcgi-servers.srvhdr[002d:002a]: content-disposition: inline; filename="Dashboard.js"
0000002b:fcgi-servers.srvhdr[002d:002a]: content-type: text/javascript;charset=UTF-8
0000002b:fcgi-servers.srvhdr[002d:002a]: content-length: 16938
0000002b:fcgi-servers.srvhdr[002d:002a]: set-cookie: 3de564f513c74f77a6c49a102a6c07a9_identity=62db8f6481d9c1263b4652d4fb592b9187c2cc01a2debbc6bdcc6125ead2b2d7a%3A2%3A%7Bi%3A0%3Bs%3A41%3A%223de564f513c74f77a6c49a102a6c07a9_identity%22%3Bi%3A1%3Bs%3A159%3A%22%5B1%2C%22%5B%5C%222ONltZEkKbkXuYMiTUU9BuuhXhtKKbPnOuGNvVKZnWIeGhOIySr6n_AjCRZRgH0Iaj-SMYSWisVfOmcJB7rFkgQX2Z1WwIHBqBr1%5C%22%2Cnull%2C%5C%22a16ddaab909d2cf27fce353f26dd2ff2%5C%22%5D%22%2C3600%5D%22%3B%7D; expires=Thu, 16 May 2024 20:00:24 GMT; Max-Age=3600; path=/; secure; HttpOnly
0000002b:fcgi-servers.srvcls[002d:002a]
0000002b:fcgi-servers.clicls[002d:002a]
0000002b:fcgi-servers.closed[002d:002a]
10.131.0.26:56214 [16/May/2024:19:00:23.649] craft-cms fcgi-servers/craftcms1 0/0/0/-1/454 500 15432 - - IH-- 6/6/5/5/0 0/0 "GET /craftcms/cpresources/970470f8/Dashboard.js?v=1715869192 HTTP/1.1"

Success case

00000031:craft-cms.accept(0009)=002d from [10.131.0.26:56214] ALPN=<none>
00000031:craft-cms.clireq[002d:ffffffff]: GET /craftcms/cpresources/60c8e6a7/selectize.js.map HTTP/1.1
00000031:craft-cms.clihdr[002d:ffffffff]: x-forwarded-proto: https
00000031:craft-cms.clihdr[002d:ffffffff]: x-forwarded-port: 443
00000031:craft-cms.clihdr[002d:ffffffff]: x-forwarded-for: 10.153.102.220, 10.153.102.220, 10.153.249.4, 217.149.228.18:51656
00000031:craft-cms.clihdr[002d:ffffffff]: x-original-url: /craftcms/cpresources/60c8e6a7/selectize.js.map
00000031:craft-cms.clihdr[002d:ffffffff]: x-appgw-trace-id: e6bb50dd1b0ee043378d72bcdca9c38e
00000031:craft-cms.clihdr[002d:ffffffff]: x-original-host: $DOMAIN
00000031:craft-cms.clihdr[002d:ffffffff]: pragma: no-cache
00000031:craft-cms.clihdr[002d:ffffffff]: cache-control: no-cache
00000031:craft-cms.clihdr[002d:ffffffff]: sec-fetch-site: same-origin
00000031:craft-cms.clihdr[002d:ffffffff]: sec-fetch-mode: no-cors
00000031:craft-cms.clihdr[002d:ffffffff]: sec-fetch-dest: empty
00000031:craft-cms.clihdr[002d:ffffffff]: user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36
00000031:craft-cms.clihdr[002d:ffffffff]: accept-encoding: gzip, deflate, br, zstd
00000031:craft-cms.clihdr[002d:ffffffff]: accept-language: de-DE,de;q=0.9
00000031:craft-cms.clihdr[002d:ffffffff]: cookie: idsrv.sessionCORS=3c28502c9d019ddfd3fdd9935f995f96; idsrv.session=3c28502c9d019ddfd3fdd9935f995f96; $CUST-ns-azure=7c02a3dcac290dde3b937f4e7c8b3379a24f7f76e94ef2af9563d149fce18fdcad0013f0; 3de564f513c74f77a6c49a102a6c07a9_username=70cd51e1e7ce06bbbce9dc32e850074a444cb2fdedc90141c598783508564360a%3A2%3A%7Bi%3A0%3Bs%3A41%3A%223de564f513c74f77a6c49a102a6c07a9_username%22%3Bi%3A1%3Bs%3A5%3A%22admin%22%3B%7D; 3de564f513c74f77a6c49a102a6c07a9_license_shun=dba5e213895f2cf57f6335e38e2c15f95b283cc89a8040ed055ff9e70220d205a%3A2%3A%7Bi%3A0%3Bs%3A45%3A%223de564f513c74f77a6c49a102a6c07a9_license_shun%22%3Bi%3A1%3Bs%3A93%3A%22%7B%22hash%22%3A%2225a61645c2ff0af72e388e25582dd2ef%22%2C%22timestamp%22%3A%222024-05-16T08%3A17%3A27-07%3A00%22%2C%22count%22%3A1%7D%22%3B%7D; CraftSessionId=aaab656109a913e2808e006ce9a7cb6d; 3de564f513c74f77a6c49a102a6c07a9_identity=62db8f6481d9c1263b4652d4fb592b9187c2cc01a2debbc6bdcc6125ead2b2d7a%3A2%3A%7Bi%3A0%3Bs%3A41%3A%223de564f513c74f77a6c49a102a6c07a9_identity%22%3Bi%3A1%3Bs%3A159%3A%22%5B1%2C%22%5B%5C%222ONltZEkKbkXuYMiTUU9BuuhXhtKKbPnOuGNvVKZnWIeGhOIySr6n_AjCRZRgH0Iaj-SMYSWisVfOmcJB7rFkgQX2Z1WwIHBqBr1%5C%22%2Cnull%2C%5C%22a16ddaab909d2cf27fce353f26dd2ff2%5C%22%5D%22%2C3600%5D%22%3B%7D; CRAFT_CSRF_TOKEN=cda2fc094e55f24cfe00de6636fec2804ec4d360e631caf387ca8b444089c5a2a%3A2%3A%7Bi%3A0%3Bs%3A16%3A%22CRAFT_CSRF_TOKEN%22%3Bi%3A1%3Bs%3A147%3A%227XAfKLzpnEyiobtHKkOxaQ26fUt--iDSTDm0pPcy%7Cadc1e7e7d35f32269ebe51c37470088ba2df48da93b045695361ac75824fb0967XAfKLzpnEyiobtHKkOxaQ26fUt--iDSTDm0pPcy%7C1%22%3B%7D
00000031:craft-cms.clihdr[002d:ffffffff]: x-orig-addr: 10.153.102.220
00000031:craft-cms.clihdr[002d:ffffffff]: x-forwarded-host: $DOMAIN
00000031:craft-cms.clihdr[002d:ffffffff]: x-forwarded-server: $DOMAIN
00000031:craft-cms.clihdr[002d:ffffffff]: host: craftcms.apps.arodev02.westeurope.aroapp.io:443
00000031:craft-cms.clihdr[002d:ffffffff]: forwarded: for=10.196.9.5;host=craftcms.apps.arodev02.westeurope.aroapp.io:443;proto=https
[07|fcgi|1|x_fcgi.c:4006] sending FCGI PARAMS record [rsp:MSG_RPBEFORE] - "GET /index.php/craftcms/cpresources/60c8e6a7/selectize.js.map HTTP/1.1" - fconn=0x7f5037c13f00(RDH,0x00001000) fstrm=0x7f5037c55300(1,OPN,0x00000300)
[07|fcgi|1|x_fcgi.c:1795] FCGI request fully xferred [rsp:MSG_RPBEFORE] - fconn=0x7f5037c13f00(RDH,0x00001000) fstrm=0x7f5037c55300(1,OPN,0x00000306)
[07|fcgi|1|x_fcgi.c:3382] rcvd H1 response headers [rsp:MSG_DATA] - "HTTP/1.1 200 OK" - fconn=0x7f5037c13f00(RDD,0x00001000) fstrm=0x7f5037c55300(1,OPN,0x00000306)
00000031:fcgi-servers.srvrep[002d:002a]: HTTP/1.1 200 OK
00000031:fcgi-servers.srvhdr[002d:002a]: cache-control: no-store
00000031:fcgi-servers.srvhdr[002d:002a]: pragma: public
00000031:fcgi-servers.srvhdr[002d:002a]: accept-ranges: bytes
00000031:fcgi-servers.srvhdr[002d:002a]: expires: 0
00000031:fcgi-servers.srvhdr[002d:002a]: content-disposition: inline; filename="selectize.js.map"
00000031:fcgi-servers.srvhdr[002d:002a]: content-type: application/octet-stream
00000031:fcgi-servers.srvhdr[002d:002a]: content-length: 190176
00000031:fcgi-servers.srvhdr[002d:002a]: set-cookie: 3de564f513c74f77a6c49a102a6c07a9_identity=62db8f6481d9c1263b4652d4fb592b9187c2cc01a2debbc6bdcc6125ead2b2d7a%3A2%3A%7Bi%3A0%3Bs%3A41%3A%223de564f513c74f77a6c49a102a6c07a9_identity%22%3Bi%3A1%3Bs%3A159%3A%22%5B1%2C%22%5B%5C%222ONltZEkKbkXuYMiTUU9BuuhXhtKKbPnOuGNvVKZnWIeGhOIySr6n_AjCRZRgH0Iaj-SMYSWisVfOmcJB7rFkgQX2Z1WwIHBqBr1%5C%22%2Cnull%2C%5C%22a16ddaab909d2cf27fce353f26dd2ff2%5C%22%5D%22%2C3600%5D%22%3B%7D; expires=Thu, 16 May 2024 20:00:24 GMT; Max-Age=3600; path=/; secure; HttpOnly
[07|fcgi|1|x_fcgi.c:3423] H1 response fully rcvd [rsp:MSG_DONE] - fconn=0x7f5037c13f00(RDH,0x00001000) fstrm=0x7f5037c55300(1,OPN,0x00000306)
[07|fcgi|1|x_fcgi.c:3423] H1 response fully rcvd [rsp:MSG_DONE] - fconn=0x7f5037c13f00(RDH,0x00001000) fstrm=0x7f5037c55300(1,OPN,0x00000306)
00000031:fcgi-servers.srvcls[002d:002a]
00000031:fcgi-servers.clicls[002d:002a]
00000031:fcgi-servers.closed[002d:002a]
10.131.0.26:56214 [16/May/2024:19:00:24.225] craft-cms fcgi-servers/craftcms1 0/0/1/388/393 200 190877 - - ---- 6/6/4/4/0 0/0 "GET /craftcms/cpresources/60c8e6a7/selectize.js.map HTTP/1.1"

Expected Behavior

No 500 internal errors.

Steps to Reproduce the Behavior

  1. Create real php-fpm application
  2. Create haproxy setup
  3. make some requests
    Sorry that this is quite vague but that's how I have run haproxy with fcgi backend

Do you have any idea what may have caused this?

I assume that something in the connection pooling and fd handling course some misbehavior because in the error case are these lines missing.

[07|fcgi|1|x_fcgi.c:3423] H1 response fully rcvd [rsp:MSG_DONE] - fconn=0x7f5037c13f00(RDH,0x00001000) fstrm=0x7f5037c55300(1,OPN,0x00000306)
[07|fcgi|1|x_fcgi.c:3423] H1 response fully rcvd [rsp:MSG_DONE] - fconn=0x7f5037c13f00(RDH,0x00001000) fstrm=0x7f5037c55300(1,OPN,0x00000306)

Do you have an idea how to solve the issue?

Sorry no

What is your configuration?

cat /data/haproxy/etc/haproxy.cfg
# copy from
# https://raw.githubusercontent.com/haproxytech/haproxy-docker-ubuntu/main/2.9/haproxy.cfg

#---------------------------------------------------------------------
# Example configuration for a possible web application.  See the
# full configuration options online.
#
#   https://www.haproxy.org/download/2.9/doc/configuration.txt
#   https://cbonte.github.io/haproxy-dconv/2.9/configuration.html
#
#---------------------------------------------------------------------

#---------------------------------------------------------------------
# Global settings
#---------------------------------------------------------------------
global
  log stdout format raw daemon debug

  pidfile     /data/haproxy/run/haproxy.pid
  # maxconn  auto config from hap
  # nbthread auto config from hap

  master-worker

  #tune.comp.maxlevel 5

  expose-experimental-directives
  trace fcgi sink stdout
  trace fcgi verbosity advanced
  trace fcgi event any
  trace fcgi start now

    # turn on stats unix socket
  stats socket /data/haproxy/run/stats mode 660 level admin expose-fd listeners

resolvers kube-dns
  nameserver dns1 dns-default.openshift-dns.svc.cluster.local:53
  accepted_payload_size 4096
  resolve_retries       3
  timeout resolve       1s
  timeout retry         1s
  hold other           30s
  hold refused         30s
  hold nx              30s
  hold timeout         30s
  hold valid           10s
  hold obsolete        30s

#---------------------------------------------------------------------
# common defaults that all the 'listen' and 'backend' sections will
# use if not designated in their block
#---------------------------------------------------------------------
defaults
    mode                    http
    balance                 leastconn
    log                     global
    option                  httplog
    option                  dontlognull
    option                  log-health-checks
    option                  forwardfor       except 10.196.106.108/32
    option                  redispatch
    retries                 3
    timeout http-request    10s
    timeout queue           30s
    timeout connect         10s
    timeout client          30s
    timeout server          30s
    timeout http-keep-alive 10s
    timeout check           10s
    #maxconn                 3000

#---------------------------------------------------------------------
# main frontend which proxys to the backends
#---------------------------------------------------------------------
frontend craft-cms
  bind *:8080

  tcp-request inspect-delay 5s
  tcp-request content accept if HTTP

  # default check url from appgateway
  monitor-uri /health

  # https://www.haproxy.com/blog/introduction-to-haproxy-maps
  # Real client IP comes from AZ Frontdoor in X-Azure-Clientip header
  #acl is-denied-ip req.hdr(X-Azure-Clientip) -m ip -f /data/haproxy/etc/denied-ip.map
  #acl is-allowed-ip req.hdr(X-Azure-Clientip) -m ip -f /data/haproxy/etc/allowed-ip.map
  #header-request deny if is-denied-ip !is-allowed-ip

  # https://www.haproxy.com/blog/load-balancing-php-fpm-with-haproxy-and-fastcgi
  # fix CVE-2019-11043
  http-request deny if { path_sub -i %0a %0d }

  # Mitigate CVE-2023-40225 (Proxy forwards malformed empty Content-Length headers)
  http-request deny if { hdr_len(content-length) 0 }

  # Strip off Proxy headers to prevent HTTpoxy (https://httpoxy.org/)
  http-request del-header Proxy

  # DNS labels are case insensitive (RFC 4343), we need to convert the hostname into lowercase
  # before matching, or any requests containing uppercase characters will never match.
  http-request set-header Host %[req.hdr(Host),lower]

  acl exist-php-ext path_sub -i .php
  acl fpm-status path /fpm-status

  # http-request set-path %[path] if { path /pinf.php }
  http-request set-path /index.php%[path] if !exist-php-ext !fpm-status !{ path_end .php }

  # http-request set-var(txn.myPath)  path
  # http-request set-var(txn.myQuery) query
  # http-response set-header X-My-Header-Path  %[var(txn.myPath)]
  # http-response set-header X-My-Header-Query %[var(txn.myQuery)]

  # https://www.haproxy.com/blog/haproxy-and-http-strict-transport-security-hsts
  # max-age is mandatory
  # 16000000 seconds is a bit more than 6 months
  http-response set-header Strict-Transport-Security "max-age=16000000; includeSubDomains; preload;"

  default_backend fcgi-servers

listen stats
  bind *:1936

  # Health check monitoring uri.
  monitor-uri /healthz

  # provide prometheus endpoint
  http-request use-service prometheus-exporter if { path /metrics }

  # Add your custom health check monitoring failure condition here.
  # monitor fail if <condition>
  stats enable
  stats uri /
#  stats hide-version
#  stats realm Haproxy\ Statistics
#  stats auth statsuser:statspass

backend fcgi-servers

  option httpchk
  http-check connect proto fcgi
  http-check send meth GET uri /fpm-ping

  #http-response wait-for-body time 2s

  # Get from cache / put in cache
  ## http-request cache-use fcgi-cache
  ## http-response cache-store fcgi-cache
  ## http-response set-header X-Cache-Status HIT if !{ srv_id -m found }
  ## http-response set-header X-Cache-Status MISS if { srv_id -m found }

  # filter compression
  # compression algo-res gzip
  # compression type-res application/javascript application/octet-stream text/css text/javascript application/json text/plan text/html

  use-fcgi-app php-fpm

  # https://www.haproxy.com/blog/circuit-breaking-haproxy
  server-template craftcms 10 "${CRAFT_SERVICE}.${NAMESPACE}.svc.cluster.local":9000 proto fcgi check resolvers kube-dns init-addr none observe layer7  error-limit 5  on-error mark-down inter 10s  rise 30  slowstart 40s

fcgi-app php-fpm
    log-stderr global
    #option keep-conn
    #option mpxs-conns
    #option max-reqs 10

    docroot /app/web
    index index.php
    path-info ^(/.+\.php)(/.*)?$


### Output of `haproxy -vv`

```plain
HAProxy version 2.9.7-5742051 2024/04/05 - https://haproxy.org/
Status: stable branch - will stop receiving fixes around Q1 2025.
Known bugs: http://www.haproxy.org/bugs/bugs-2.9.7.html
Running on: Linux 5.14.0-284.64.1.el9_2.x86_64 #1 SMP PREEMPT_DYNAMIC Mon Apr 22 13:25:11 EDT 2024 x86_64
Build options :
  TARGET  = linux-glibc
  CPU     = generic
  CC      = cc
  CFLAGS  = -O2 -g -Wall -Wextra -Wundef -Wdeclaration-after-statement -Wfatal-errors -Wtype-limits -Wshift-negative-value -Wshift-overflow=2 -Wduplicated-cond -Wnull-dereference -fwrapv -Wno-address-of-packed-member -Wno-unused-label -Wno-sign-compare -Wno-unused-parameter -Wno-clobbered -Wno-missing-field-initializers -Wno-cast-function-type -Wno-string-plus-int -Wno-atomic-alignment
  OPTIONS = USE_PTHREAD_EMULATION=1 USE_LINUX_TPROXY=1 USE_GETADDRINFO=1 USE_OPENSSL=1 USE_LUA=1 USE_SLZ=1 USE_TFO=1 USE_QUIC=1 USE_PROMEX=1 USE_PCRE2=1 USE_PCRE2_JIT=1 USE_QUIC_OPENSSL_COMPAT=1
  DEBUG   = -DDEBUG_STRICT -DDEBUG_MEMORY_POOLS

Feature list : -51DEGREES +ACCEPT4 +BACKTRACE -CLOSEFROM +CPU_AFFINITY +CRYPT_H -DEVICEATLAS +DL -ENGINE +EPOLL -EVPORTS +GETADDRINFO -KQUEUE -LIBATOMIC +LIBCRYPT +LINUX_CAP +LINUX_SPLICE +LINUX_TPROXY +LUA +MATH -MEMORY_PROFILING +NETFILTER +NS -OBSOLETE_LINKER +OPENSSL -OPENSSL_AWSLC -OPENSSL_WOLFSSL -OT -PCRE +PCRE2 +PCRE2_JIT -PCRE_JIT +POLL +PRCTL -PROCCTL +PROMEX +PTHREAD_EMULATION +QUIC +QUIC_OPENSSL_COMPAT +RT +SHM_OPEN +SLZ +SSL -STATIC_PCRE -STATIC_PCRE2 -SYSTEMD +TFO +THREAD +THREAD_DUMP +TPROXY -WURFL -ZLIB

Default settings :
  bufsize = 16384, maxrewrite = 1024, maxpollevents = 200

Built with multi-threading support (MAX_TGROUPS=16, MAX_THREADS=256, default=8).
Built with OpenSSL version : OpenSSL 3.0.2 15 Mar 2022
Running on OpenSSL version : OpenSSL 3.0.2 15 Mar 2022
OpenSSL library supports TLS extensions : yes
OpenSSL library supports SNI : yes
OpenSSL library supports : TLSv1.0 TLSv1.1 TLSv1.2 TLSv1.3
OpenSSL providers loaded : default
Built with Lua version : Lua 5.4.4
Built with the Prometheus exporter as a service
Built with network namespace support.
Built with libslz for stateless compression.
Compression algorithms supported : identity("identity"), deflate("deflate"), raw-deflate("deflate"), gzip("gzip")
Built with transparent proxy support using: IP_TRANSPARENT IPV6_TRANSPARENT IP_FREEBIND
Built with PCRE2 version : 10.39 2021-10-29
PCRE2 library supports JIT : yes
Encrypted password support via crypt(3): yes
Built with gcc compiler version 11.4.0

Available polling systems :
      epoll : pref=300,  test result OK
       poll : pref=200,  test result OK
     select : pref=150,  test result OK
Total: 3 (3 usable), will use epoll.

Available multiplexer protocols :
(protocols marked as <default> cannot be specified using 'proto' keyword)
       quic : mode=HTTP  side=FE     mux=QUIC  flags=HTX|NO_UPG|FRAMED
         h2 : mode=HTTP  side=FE|BE  mux=H2    flags=HTX|HOL_RISK|NO_UPG
       fcgi : mode=HTTP  side=BE     mux=FCGI  flags=HTX|HOL_RISK|NO_UPG
  <default> : mode=HTTP  side=FE|BE  mux=H1    flags=HTX
         h1 : mode=HTTP  side=FE|BE  mux=H1    flags=HTX|NO_UPG
  <default> : mode=TCP   side=FE|BE  mux=PASS  flags=
       none : mode=TCP   side=FE|BE  mux=PASS  flags=NO_UPG

Available services : prometheus-exporter
Available filters :
        [BWLIM] bwlim-in
        [BWLIM] bwlim-out
        [CACHE] cache
        [COMP] compression
        [FCGI] fcgi-app
        [SPOE] spoe
        [TRACE] trace


### Last Outputs and Backtraces

_No response_

### Additional Information

_No response_
@git001 git001 added status: needs-triage This issue needs to be triaged. type: bug This issue describes a bug. labels May 16, 2024
@git001
Copy link
Contributor Author

git001 commented May 16, 2024

I have played with tune.bufsize and with tune.bufsize 8192 occur the error very often, with tune.bufsize 32768 not that much.

The size value at 500 is near the buffer size 31800 and 7240.
Maybe this helps to find the root cause.

The "funny" thing is that the 500 error always hit the 07|fcgi , but this could be something just happen.

I have also seen, from the trace output , that the problem could be in this function, but this could hide some other root cause.

static size_t fcgi_strm_parse_response(struct fcgi_strm *fstrm, struct buffer *buf, size_t count)

@git001
Copy link
Contributor Author

git001 commented May 16, 2024

The Problem exist also in 3.0-dev11

HAProxy version 3.0-dev11-7217a9e 2024/05/10 - https://haproxy.org/
Status: development branch - not safe for use in production.
Known bugs: https://github.com/haproxy/haproxy/issues?q=is:issue+is:open
Running on: Linux 5.14.0-284.64.1.el9_2.x86_64 #1 SMP PREEMPT_DYNAMIC Mon Apr 22 13:25:11 EDT 2024 x86_64
Build options :
  TARGET  = linux-glibc
  CC      = cc
  CFLAGS  = -O2 -g -fwrapv
  OPTIONS = USE_PTHREAD_EMULATION=1 USE_LINUX_TPROXY=1 USE_GETADDRINFO=1 USE_OPENSSL=1 USE_LUA=1 USE_SLZ=1 USE_TFO=1 USE_QUIC=1 USE_PROMEX=1 USE_PCRE2=1 USE_PCRE2_JIT=1 USE_QUIC_OPENSSL_COMPAT=1
  DEBUG   =

Feature list : -51DEGREES +ACCEPT4 +BACKTRACE -CLOSEFROM +CPU_AFFINITY +CRYPT_H -DEVICEATLAS +DL -ENGINE +EPOLL -EVPORTS +GETADDRINFO -KQUEUE -LIBATOMIC +LIBCRYPT +LINUX_CAP +LINUX_SPLICE +LINUX_TPROXY +LUA +MATH -MEMORY_PROFILING +NETFILTER +NS -OBSOLETE_LINKER +OPENSSL -OPENSSL_AWSLC -OPENSSL_WOLFSSL -OT -PCRE +PCRE2 +PCRE2_JIT -PCRE_JIT +POLL +PRCTL -PROCCTL +PROMEX +PTHREAD_EMULATION +QUIC +QUIC_OPENSSL_COMPAT +RT +SHM_OPEN +SLZ +SSL -STATIC_PCRE -STATIC_PCRE2 +SYSTEMD +TFO +THREAD +THREAD_DUMP +TPROXY -WURFL -ZLIB

Default settings :
  bufsize = 16384, maxrewrite = 1024, maxpollevents = 200

Built with multi-threading support (MAX_TGROUPS=16, MAX_THREADS=256, default=8).
Built with OpenSSL version : OpenSSL 3.0.2 15 Mar 2022
Running on OpenSSL version : OpenSSL 3.0.2 15 Mar 2022
OpenSSL library supports TLS extensions : yes
OpenSSL library supports SNI : yes
OpenSSL library supports : TLSv1.0 TLSv1.1 TLSv1.2 TLSv1.3
OpenSSL providers loaded : default
Built with Lua version : Lua 5.4.4
Built with the Prometheus exporter as a service
Built with network namespace support.
Built with libslz for stateless compression.
Compression algorithms supported : identity("identity"), deflate("deflate"), raw-deflate("deflate"), gzip("gzip")
Built with transparent proxy support using: IP_TRANSPARENT IPV6_TRANSPARENT IP_FREEBIND
Built with PCRE2 version : 10.39 2021-10-29
PCRE2 library supports JIT : yes
Encrypted password support via crypt(3): yes
Built with gcc compiler version 11.4.0

Available polling systems :
      epoll : pref=300,  test result OK
       poll : pref=200,  test result OK
     select : pref=150,  test result OK
Total: 3 (3 usable), will use epoll.

Available multiplexer protocols :
(protocols marked as <default> cannot be specified using 'proto' keyword)
       quic : mode=HTTP  side=FE     mux=QUIC  flags=HTX|NO_UPG|FRAMED
         h2 : mode=HTTP  side=FE|BE  mux=H2    flags=HTX|HOL_RISK|NO_UPG
       fcgi : mode=HTTP  side=BE     mux=FCGI  flags=HTX|HOL_RISK|NO_UPG
  <default> : mode=HTTP  side=FE|BE  mux=H1    flags=HTX
         h1 : mode=HTTP  side=FE|BE  mux=H1    flags=HTX|NO_UPG
  <default> : mode=TCP   side=FE|BE  mux=PASS  flags=
       none : mode=TCP   side=FE|BE  mux=PASS  flags=NO_UPG

Available services : prometheus-exporter
Available filters :
        [BWLIM] bwlim-in
        [BWLIM] bwlim-out
        [CACHE] cache
        [COMP] compression
        [FCGI] fcgi-app
        [SPOE] spoe
        [TRACE] trace

@capflam
Copy link
Member

capflam commented May 17, 2024

Thanks for report. Could you try with more traces by update your trace directives in your global section:

    expose-experimental-directives
    trace fcgi sink stdout
    trace fcgi level developer
    trace fcgi verbosity complete
    trace fcgi start now

@git001
Copy link
Contributor Author

git001 commented May 17, 2024

I have created the tace.
Can I send you the file directly via mail so that you have all information's?

@capflam
Copy link
Member

capflam commented May 17, 2024

Of course! Go ahead.

@git001
Copy link
Contributor Author

git001 commented May 17, 2024

Thanks. you should have it now 😃

@capflam
Copy link
Member

capflam commented May 17, 2024

Just to let you know. I've checked your traces and it seems the internal error is reported by an HTTP analyzer and not the FCGI multiplexer. I must investigate because it seems strange.

@capflam capflam added status: reviewed This issue was reviewed. A fix is required. and removed status: needs-triage This issue needs to be triaged. labels May 17, 2024
@git001
Copy link
Contributor Author

git001 commented May 17, 2024

Do you need more traces?

@capflam
Copy link
Member

capflam commented May 17, 2024

No, for now, I need more time 😄

@capflam
Copy link
Member

capflam commented May 21, 2024

Looking at your config, I don't know how it is possible, But I suspect an error during the response analysis. Could you add last_rule_file and last_rule_line sample in your logs ? This will help to know the last evaluated rule.

@git001
Copy link
Contributor Author

git001 commented May 21, 2024

Thank you for the update.

I have added this lines to the config and send the traces to you.

global
  log stdout format raw daemon debug

  pidfile     /data/haproxy/run/haproxy.pid
  # maxconn  auto config from hap
  # nbthread auto config from hap

  master-worker

  #tune.comp.maxlevel 5
  #tune.bufsize 32768
  tune.bufsize 8192

  # expose-experimental-directives
  # trace fcgi sink stdout
  # trace fcgi level developer
  # trace fcgi verbosity complete
  # trace fcgi event any
  # trace fcgi start now

  expose-experimental-directives
  trace fcgi sink stdout
  trace fcgi level developer
  trace fcgi verbosity complete
  trace fcgi start now 
#
  trace h1 sink stdout
  trace h1 level developer
  trace h1 verbosity complete
  trace h1 start now


    # turn on stats unix socket
  stats socket /data/haproxy/run/stats mode 660 level admin expose-fd listeners

resolvers kube-dns
  nameserver dns1 dns-default.openshift-dns.svc.cluster.local:53
  accepted_payload_size 4096
  resolve_retries       3
  timeout resolve       1s
  timeout retry         1s
  hold other           30s
  hold refused         30s
  hold nx              30s
  hold timeout         30s
  hold valid           10s
  hold obsolete        30s

defaults
    mode                    http
    balance                 leastconn
    log                     global
    log-format "${HAPROXY_HTTP_LOG_FMT} lr=%[last_rule_file]:%[last_rule_line]"
#    option                  httplog
    option                  dontlognull
    option                  log-health-checks
    option                  forwardfor       except 10.196.106.108/32
    option                  redispatch
    retries                 3
    timeout http-request    10s
    timeout queue           30s
    timeout connect         10s
    timeout client          30s
    timeout server          30s
    timeout http-keep-alive 10s
    timeout check           10s
    #maxconn                 3000

frontend craft-cms
...

@capflam
Copy link
Member

capflam commented May 21, 2024

Thanks. I checked the code more carefully and its seems there is a regression on the termination state reported in logs. The offending commit is 0fd2551. Internal errors are always reported, even when another reason was already set. In this case, I guess it is a rewrite error. So, you get IH-- in logs instead of PH--.

You config update will dump the failing rule. Another way is to check wrew in the stats. And if I'm right, the workaround is to increase tune.maxrewrite global parameter. However, There are not so much rewrites on the response in your config snippet. So it may be something else.

@git001
Copy link
Contributor Author

git001 commented May 21, 2024

Okay, What value should I put for tune.maxrewrite ?

Have you seen this comment about tune.bufsize ?
#2568 (comment)

@capflam
Copy link
Member

capflam commented May 21, 2024

The reserve in the buffer (set via tune.maxrewrite) is by default 1024, independently on the buffer size. If it is really the root cause, you should check all rules rewriting the response to set an appropriate value. It really depends on your config.

@git001
Copy link
Contributor Author

git001 commented May 21, 2024

What's the right socket command to get wrew

echo 'show stat' | socat stdio /data/haproxy/run/stats|egrep wrew
# pxname,svname,qcur,qmax,scur,smax,slim,stot,bin,bout,dreq,dresp,ereq,econ,eresp,wretr,wredis,status,weight,act,bck,chkfail,chkdown,lastchg,downtime,qlimit,pid,iid,sid,throttle,lbtot,tracked,type,rate,rate_lim,rate_max,check_status,check_code,check_duration,hrsp_1xx,hrsp_2xx,hrsp_3xx,hrsp_4xx,hrsp_5xx,hrsp_other,hanafail,req_rate,req_rate_max,req_tot,cli_abrt,srv_abrt,comp_in,comp_out,comp_byp,comp_rsp,lastsess,last_chk,last_agt,qtime,ctime,rtime,ttime,agent_status,agent_code,agent_duration,check_desc,agent_desc,check_rise,check_fall,check_health,agent_rise,agent_fall,agent_health,addr,cookie,mode,algo,conn_rate,conn_rate_max,conn_tot,intercepted,dcon,dses,wrew,connect,reuse,cache_lookups,cache_hits,srv_icur,src_ilim,qtime_max,ctime_max,rtime_max,ttime_max,eint,idle_conn_cur,safe_conn_cur,used_conn_cur,need_conn_est,uweight,agg_server_status,agg_server_check_status,agg_check_status,srid,sess_other,h1sess,h2sess,h3sess,req_other,h1req,h2req,h3req,proto,-,ssl_sess,ssl_reused_sess,ssl_failed_handshake,quic_rxbuf_full,quic_dropped_pkt,quic_dropped_pkt_bufoverrun,quic_dropped_parsing_pkt,quic_socket_full,quic_sendto_err,quic_sendto_err_unknwn,quic_sent_pkt,quic_lost_pkt,quic_too_short_dgram,quic_retry_sent,quic_retry_validated,quic_retry_error,quic_half_open_conn,quic_hdshk_fail,quic_stless_rst_sent,quic_conn_migration_done,quic_transp_err_no_error,quic_transp_err_internal_error,quic_transp_err_connection_refused,quic_transp_err_flow_control_error,quic_transp_err_stream_limit_error,quic_transp_err_stream_state_error,quic_transp_err_final_size_error,quic_transp_err_frame_encoding_error,quic_transp_err_transport_parameter_error,quic_transp_err_connection_id_limit,quic_transp_err_protocol_violation_error,quic_transp_err_invalid_token,quic_transp_err_application_error,quic_transp_err_crypto_buffer_exceeded,quic_transp_err_key_update_error,quic_transp_err_aead_limit_reached,quic_transp_err_no_viable_path,quic_transp_err_crypto_error,quic_transp_err_unknown_error,quic_data_blocked,quic_stream_data_blocked,quic_streams_blocked_bidi,quic_streams_blocked_uni,h3_data,h3_headers,h3_cancel_push,h3_push_promise,h3_max_push_id,h3_goaway,h3_settings,h3_no_error,h3_general_protocol_error,h3_internal_error,h3_stream_creation_error,h3_closed_critical_stream,h3_frame_unexpected,h3_frame_error,h3_excessive_load,h3_id_error,h3_settings_error,h3_missing_settings,h3_request_rejected,h3_request_cancelled,h3_request_incomplete,h3_message_error,h3_connect_error,h3_version_fallback,pack_decompression_failed,qpack_encoder_stream_error,qpack_decoder_stream_error,h2_headers_rcvd,h2_data_rcvd,h2_settings_rcvd,h2_rst_stream_rcvd,h2_goaway_rcvd,h2_detected_conn_protocol_errors,h2_detected_strm_protocol_errors,h2_rst_stream_resp,h2_goaway_resp,h2_open_connections,h2_backend_open_streams,h2_total_connections,h2_backend_total_streams,h1_open_connections,h1_open_streams,h1_total_connections,h1_total_streams,h1_bytes_in,h1_bytes_out,h1_spliced_bytes_in,h1_spliced_bytes_out,

Could the problem be the "long" http-response set-header Content-Security-Policy ...?

@git001
Copy link
Contributor Author

git001 commented May 21, 2024

Thank you @capflam . I have now increased the tune.maxrewrite to 2048 and now no more IH-- in the logs.
Thank you for your patience and time.

@git001 git001 closed this as completed May 21, 2024
@capflam
Copy link
Member

capflam commented May 21, 2024

No problem. I will fix the termination state issue. Thanks !

@capflam capflam removed the status: reviewed This issue was reviewed. A fix is required. label May 21, 2024
haproxy-mirror pushed a commit that referenced this issue May 22, 2024
…rnal error

When internal error is reported from an HTTP analyzer, we must take care to
not set the stream termination condition if it was already set. For
instance, it happens when a message rewrite fails. In this case
SF_ERR_PXCOND is set by the rule. The HTTP analyzer must not crush it with
SF_ERR_INTERNAL.

The regression was introduced with the commit 0fd2551 ("MEDIUM: http-ana:
Set termination state before returning haproxy response").

The bug was discovered working in the issue #2568. It must be backported to
2.9.
@capflam capflam added the status: fixed This issue is a now-fixed bug. label May 22, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
status: fixed This issue is a now-fixed bug. type: bug This issue describes a bug.
Projects
None yet
Development

No branches or pull requests

2 participants