nginx ingress rejects HTTP POST request with a 400 code status code

Question

I'm trying to deploy EJBCA PKI in proxy mode with an ingress nginx to terminate all the SSL sessions. I was able to successfully make it works for Public/Admin web access, EJBCA Web Service and SCEP.

The last protocol I need to validate is EST and for which I need some help. First of all EST works if I remove nginx from the mix and terminate the SSL session directly on EJBCA so my EST RA and EJBCA configuration works.

When nginx terminates the SSL session with the EST RA, it complains there is something wrong with the HTTP request and send back an HTTP 400 code status. My EJBCA server doesn't receive anything.

Below is my ingress configuration for EST:

apiVersion: networking.k8s.io/v1beta1
kind: Ingress
metadata:
  name: pki-est
  annotations:
    kubernetes.io/ingress.class: "fanhe-ingress"
spec:
  tls:
  - hosts:
    - nginx-ingress-controller.ingress-nginx
    secretName: nginx-ingress-tls-ec-secret
  rules:
    - host: nginx-ingress-controller.ingress-nginx
      http:
        paths:
        - path: /.well-known/est
          backend:
           serviceName: pki-app
           servicePort: 8082

I enabled all the debugs on the ingress and below is what I see in error.log:

2020/05/18 10:06:52 [debug] 198#198: *15975 http process request line
2020/05/18 10:06:52 [debug] 198#198: *15975 http request line: "POST /.well-known/est/simpleenroll HTTP/1.1"
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'2F:/'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:1 in:'2E:.'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:2 in:'77:w'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'65:e'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'6C:l'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'6C:l'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'2D:-'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'6B:k'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'6E:n'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'6F:o'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'77:w'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'6E:n'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'2F:/'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:1 in:'65:e'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'73:s'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'74:t'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'2F:/'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:1 in:'73:s'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'69:i'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'6D:m'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'70:p'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'6C:l'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'65:e'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'65:e'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'6E:n'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'72:r'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'6F:o'
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'6C:l'
---
2020/05/18 10:06:52 [debug] 198#198: *15975 s:0 in:'6C:l'
2020/05/18 10:06:52 [debug] 198#198: *15975 http uri: "/.well-known/est/simpleenroll"
2020/05/18 10:06:52 [debug] 198#198: *15975 http args: ""
2020/05/18 10:06:52 [debug] 198#198: *15975 http exten: ""
2020/05/18 10:06:52 [debug] 198#198: *15975 http process request header line
2020/05/18 10:06:52 [debug] 198#198: *15975 http header: "User-Agent: libest 3.1.1"
2020/05/18 10:06:52 [debug] 198#198: *15975 http header: "Connection: close"
2020/05/18 10:06:52 [debug] 198#198: *15975 http header: "Host: nginx-ingress-controller.ingress-nginx:443"
2020/05/18 10:06:52 [debug] 198#198: *15975 http header: "Accept: */*"
2020/05/18 10:06:52 [debug] 198#198: *15975 http header: "Content-Type: application/pkcs10"
2020/05/18 10:06:52 [debug] 198#198: *15975 http header: "Content-Length: 366"
2020/05/18 10:06:52 [debug] 198#198: *15975 http header done
2020/05/18 10:06:52 [info] 198#198: *15975 client SSL certificate verify error: (19:self signed certificate in certificate chain) while reading client request headers, client: fd10::1:165, server: nginx-ingress-controller.ingress-nginx, request: "POST /.well-known/est/simpleenroll HTTP/1.1", host: "nginx-ingress-controller.ingress-nginx:443"
2020/05/18 10:06:52 [debug] 198#198: *15975 http finalize request: 495, "/.well-known/est/simpleenroll?" a:1, c:1
2020/05/18 10:06:52 [debug] 198#198: *15975 event timer del: 3: 947664613
2020/05/18 10:06:52 [debug] 198#198: *15975 http special response: 495, "/.well-known/est/simpleenroll?"
2020/05/18 10:06:52 [debug] 198#198: *15975 http set discard body
2020/05/18 10:06:52 [debug] 198#198: *15975 headers more header filter, uri "/.well-known/est/simpleenroll"
2020/05/18 10:06:52 [debug] 198#198: *15975 lua header filter for user lua code, uri "/.well-known/est/simpleenroll"
2020/05/18 10:06:52 [debug] 198#198: *15975 lua capture header filter, uri "/.well-known/est/simpleenroll"
2020/05/18 10:06:52 [debug] 198#198: *15975 HTTP/1.1 400 Bad Request
Server: openresty/1.15.8.1
Date: Mon, 18 May 2020 10:06:52 GMT
Content-Type: text/html
Content-Length: 221
Connection: close

2020/05/18 10:06:52 [debug] 198#198: *15975 write new buf t:1 f:0 0000558A2B30B250, pos 0000558A2B30B250, size: 158 file: 0, size: 0
2020/05/18 10:06:52 [debug] 198#198: *15975 http write filter: l:0 f:0 s:158
2020/05/18 10:06:52 [debug] 198#198: *15975 http output filter "/.well-known/est/simpleenroll?"
2020/05/18 10:06:52 [debug] 198#198: *15975 http copy filter: "/.well-known/est/simpleenroll?"
2020/05/18 10:06:52 [debug] 198#198: *15975 lua body filter for user lua code, uri "/.well-known/est/simpleenroll"
2020/05/18 10:06:52 [debug] 198#198: *15975 lua capture body filter, uri "/.well-known/est/simpleenroll"
2020/05/18 10:06:52 [debug] 198#198: *15975 http postpone filter "/.well-known/est/simpleenroll?" 0000558A2B30B438
2020/05/18 10:06:52 [debug] 198#198: *15975 write old buf t:1 f:0 0000558A2B30B250, pos 0000558A2B30B250, size: 158 file: 0, size: 0
2020/05/18 10:06:52 [debug] 198#198: *15975 write new buf t:0 f:0 0000000000000000, pos 0000558A2A15AEA0, size: 162 file: 0, size: 0
2020/05/18 10:06:52 [debug] 198#198: *15975 write new buf t:0 f:0 0000000000000000, pos 0000558A2A15BE20, size: 59 file: 0, size: 0
2020/05/18 10:06:52 [debug] 198#198: *15975 http write filter: l:1 f:0 s:379
2020/05/18 10:06:52 [debug] 198#198: *15975 http write filter limit 0
2020/05/18 10:06:52 [debug] 198#198: *15975 malloc: 0000558A2B318CC0:4096
2020/05/18 10:06:52 [debug] 198#198: *15975 SSL buf copy: 158
2020/05/18 10:06:52 [debug] 198#198: *15975 SSL buf copy: 162
2020/05/18 10:06:52 [debug] 198#198: *15975 SSL buf copy: 59
2020/05/18 10:06:52 [debug] 198#198: *15975 SSL to write: 379
2020/05/18 10:06:52 [debug] 198#198: *15975 SSL_write: 379
2020/05/18 10:06:52 [debug] 198#198: *15975 http write filter 0000000000000000
2020/05/18 10:06:52 [debug] 198#198: *15975 http copy filter: 0 "/.well-known/est/simpleenroll?"
2020/05/18 10:06:52 [debug] 198#198: *15975 http finalize request: 0, "/.well-known/est/simpleenroll?" a:1, c:1
2020/05/18 10:06:52 [debug] 198#198: *15975 event timer add: 3: 5000:947609618
2020/05/18 10:06:52 [debug] 198#198: *15975 http lingering close handler
2020/05/18 10:06:52 [debug] 198#198: *15975 SSL_read: 0
2020/05/18 10:06:52 [debug] 198#198: *15975 SSL_get_error: 6
2020/05/18 10:06:52 [debug] 198#198: *15975 peer shutdown SSL cleanly
2020/05/18 10:06:52 [debug] 198#198: *15975 lingering read: 0
2020/05/18 10:06:52 [debug] 198#198: *15975 http request count:1 blk:0
2020/05/18 10:06:52 [debug] 198#198: *15975 http close request
2020/05/18 10:06:52 [debug] 198#198: *15975 lua log handler, uri:"/.well-known/est/simpleenroll" c:0
2020/05/18 10:06:52 [debug] 198#198: *15975 http log handler
2020/05/18 10:06:52 [debug] 198#198: *15975 http map started
2020/05/18 10:06:52 [debug] 198#198: *15975 http script var: "/.well-known/est/simpleenroll"
2020/05/18 10:06:52 [debug] 198#198: *15975 http map: "/.well-known/est/simpleenroll" "1"
2020/05/18 10:06:52 [debug] 198#198: *15975 http script var: "1"
2020/05/18 10:06:52 [debug] 198#198: *15975 http map started
2020/05/18 10:06:52 [debug] 198#198: *15975 http script var: "fd10::1:165"
2020/05/18 10:06:52 [debug] 198#198: *15975 http map: "" "fd10::1:165"
2020/05/18 10:06:52 [debug] 198#198: *15975 http map started
2020/05/18 10:06:52 [debug] 198#198: *15975 http script var: "39bef9f98c79778373515fb72f84e249"
2020/05/18 10:06:52 [debug] 198#198: *15975 http map: "" "39bef9f98c79778373515fb72f84e249"
2020/05/18 10:06:52 [debug] 198#198: *15975 free: 0000558A2B30A480, unused: 7
2020/05/18 10:06:52 [debug] 198#198: *15975 free: 0000558A2B279FC0, unused: 1974
2020/05/18 10:06:52 [debug] 198#198: *15975 close http connection: 3

From those logs I don't see any obvious reason why nginx rejects the request.

I did try the same HTTP request with Postman using the exact same certificate as the est-ra and it works !!. See logs below:

2020/05/18 22:52:02 [debug] 671#671: *172624 http process request line
2020/05/18 22:52:02 [debug] 671#671: *172624 http request line: "POST /.well-known/est/simpleenroll HTTP/1.1"
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'2F:/'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:1 in:'2E:.'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:2 in:'77:w'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'65:e'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'6C:l'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'6C:l'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'2D:-'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'6B:k'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'6E:n'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'6F:o'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'77:w'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'6E:n'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'2F:/'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:1 in:'65:e'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'73:s'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'74:t'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'2F:/'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:1 in:'73:s'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'69:i'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'6D:m'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'70:p'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'6C:l'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'65:e'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'65:e'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'6E:n'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'72:r'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'6F:o'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'6C:l'
2020/05/18 22:52:02 [debug] 671#671: *172624 s:0 in:'6C:l'
2020/05/18 22:52:02 [debug] 671#671: *172624 http uri: "/.well-known/est/simpleenroll"
2020/05/18 22:52:02 [debug] 671#671: *172624 http args: ""
2020/05/18 22:52:02 [debug] 671#671: *172624 http exten: ""
2020/05/18 22:52:02 [debug] 671#671: *172624 http process request header line
2020/05/18 22:52:02 [debug] 671#671: *172624 http header: "User-Agent: libest 3.1.1"
2020/05/18 22:52:02 [debug] 671#671: *172624 http header: "Connection: close"
2020/05/18 22:52:02 [debug] 671#671: *172624 http header: "Host: nginx-ingress-controller.ingress-nginx:443"
2020/05/18 22:52:02 [debug] 671#671: *172624 http header: "Accept: */*"
2020/05/18 22:52:02 [debug] 671#671: *172624 http header: "Content-Type: application/pkcs10"
2020/05/18 22:52:02 [debug] 671#671: *172624 http header: "Authorization: Basic cmEtYXBwOkZiV241M2p3"
2020/05/18 22:52:02 [debug] 671#671: *172624 http header: "Content-Length: 280"
2020/05/18 22:52:02 [debug] 671#671: *172624 http header done
2020/05/18 22:52:02 [debug] 671#671: *172624 event timer del: 6: 993574054
2020/05/18 22:52:02 [debug] 671#671: *172624 generic phase: 0
2020/05/18 22:52:02 [debug] 671#671: *172624 rewrite phase: 1
2020/05/18 22:52:02 [debug] 671#671: *172624 rewrite phase: 2
2020/05/18 22:52:02 [debug] 671#671: *172624 http script value: "-"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script set $proxy_upstream_name
2020/05/18 22:52:02 [debug] 671#671: *172624 test location: "/"
2020/05/18 22:52:02 [debug] 671#671: *172624 test location: "ejbca/ejbcaws"
2020/05/18 22:52:02 [debug] 671#671: *172624 test location: ".well-known/est"
2020/05/18 22:52:02 [debug] 671#671: *172624 using configuration "/.well-known/est"
2020/05/18 22:52:02 [debug] 671#671: *172624 http cl:280 max:0
2020/05/18 22:52:02 [debug] 671#671: *172624 rewrite phase: 4
2020/05/18 22:52:02 [debug] 671#671: *172624 rewrite phase: 5
2020/05/18 22:52:02 [debug] 671#671: *172624 http script value: "default"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script set $namespace
2020/05/18 22:52:02 [debug] 671#671: *172624 http script value: "pki-est"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script set $ingress_name
2020/05/18 22:52:02 [debug] 671#671: *172624 http script value: "pki-app"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script set $service_name
2020/05/18 22:52:02 [debug] 671#671: *172624 http script value: "{0 8082 }"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script set $service_port
2020/05/18 22:52:02 [debug] 671#671: *172624 http script value: "/.well-known/est"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script set $location_path
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var: "https"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script value: "https"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script equal
2020/05/18 22:52:02 [debug] 671#671: *172624 http script if
2020/05/18 22:52:02 [debug] 671#671: *172624 http script value: "-1"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script set $balancer_ewma_score
2020/05/18 22:52:02 [debug] 671#671: *172624 http script value: "default-pki-app-8082"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script set $proxy_upstream_name
2020/05/18 22:52:02 [debug] 671#671: *172624 http script complex value
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var: "default-pki-app-8082"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script set $proxy_host
2020/05/18 22:52:02 [debug] 671#671: *172624 http script complex value
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var: "https"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script set $pass_access_scheme
2020/05/18 22:52:02 [debug] 671#671: *172624 http script complex value
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var: "443"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script set $pass_server_port
2020/05/18 22:52:02 [debug] 671#671: *172624 http script complex value
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var: "nginx-ingress-controller.ingress-nginx:443"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script set $best_http_host
2020/05/18 22:52:02 [debug] 671#671: *172624 http script complex value
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var: "443"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script set $pass_port
2020/05/18 22:52:02 [debug] 671#671: *172624 http script value: ""
2020/05/18 22:52:02 [debug] 671#671: *172624 http script set $proxy_alternative_upstream_name
2020/05/18 22:52:02 [debug] 671#671: *172624 rewrite phase: 6
2020/05/18 22:52:02 [debug] 671#671: *172624 lua rewrite handler, uri:"/.well-known/est/simpleenroll" c:1
2020/05/18 22:52:02 [debug] 671#671: *172624 looking up Lua code cache with key '=rewrite_by_lua(nginx.conf:1274)nhli_dbdd52ba6d647a948759533fd68b064c'
2020/05/18 22:52:02 [debug] 671#671: *172624 lua creating new thread
2020/05/18 22:52:02 [debug] 671#671: *172624 lua reset ctx
2020/05/18 22:52:02 [debug] 671#671: *172624 http cleanup add: 0000558A2B3E0AB0
2020/05/18 22:52:02 [debug] 671#671: *172624 lua run thread, top:0 c:1
2020/05/18 22:52:02 [debug] 671#671: *172624 add cleanup: 0000558A2B3348A0
2020/05/18 22:52:02 [debug] 671#671: *172624 lua resume returned 0
2020/05/18 22:52:02 [debug] 671#671: *172624 lua light thread ended normally
2020/05/18 22:52:02 [debug] 671#671: *172624 lua deleting light thread
2020/05/18 22:52:02 [debug] 671#671: *172624 post rewrite phase: 7
2020/05/18 22:52:02 [debug] 671#671: *172624 generic phase: 8
2020/05/18 22:52:02 [debug] 671#671: *172624 generic phase: 9
2020/05/18 22:52:02 [debug] 671#671: *172624 generic phase: 10
2020/05/18 22:52:02 [debug] 671#671: *172624 access phase: 11
2020/05/18 22:52:02 [debug] 671#671: *172624 access phase: 12
2020/05/18 22:52:02 [debug] 671#671: *172624 access phase: 13
2020/05/18 22:52:02 [debug] 671#671: *172624 access phase: 14
2020/05/18 22:52:02 [debug] 671#671: *172624 post access phase: 15
2020/05/18 22:52:02 [debug] 671#671: *172624 generic phase: 16
2020/05/18 22:52:02 [debug] 671#671: *172624 generic phase: 17
2020/05/18 22:52:02 [debug] 671#671: *172624 http client request body preread 280
2020/05/18 22:52:02 [debug] 671#671: *172624 http request body content length filter
2020/05/18 22:52:02 [debug] 671#671: *172624 http body new buf t:1 f:0 0000558A2B42FB5D, pos 0000558A2B42FB5D, size: 280 file: 0, size: 0
2020/05/18 22:52:02 [debug] 671#671: *172624 http init upstream, client timer: 0
2020/05/18 22:52:02 [debug] 671#671: *172624 epoll add event: fd:6 op:3 ev:80002005
2020/05/18 22:52:02 [debug] 671#671: *172624 http map started
2020/05/18 22:52:02 [debug] 671#671: *172624 http map: "" ""
2020/05/18 22:52:02 [debug] 671#671: *172624 http map started
2020/05/18 22:52:02 [debug] 671#671: *172624 posix_memalign: 0000558A2B2F54F0:4096 @16
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var: "80e3ae7c2495fcdc7ebe9b658dd579bc"
2020/05/18 22:52:02 [debug] 671#671: *172624 http map: "" "80e3ae7c2495fcdc7ebe9b658dd579bc"
2020/05/18 22:52:02 [debug] 671#671: *172624 http map started
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var: "fdff::a3d:fafb"
2020/05/18 22:52:02 [debug] 671#671: *172624 http map: "" "fdff::a3d:fafb"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script copy: "Host"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var: "nginx-ingress-controller.ingress-nginx:443"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script copy: ""
2020/05/18 22:52:02 [debug] 671#671: *172624 http script copy: "ssl-client-verify"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var: "NONE"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script copy: ""
2020/05/18 22:52:02 [debug] 671#671: *172624 http script copy: ""
2020/05/18 22:52:02 [debug] 671#671: *172624 http script copy: ""
2020/05/18 22:52:02 [debug] 671#671: *172624 http script copy: ""
2020/05/18 22:52:02 [debug] 671#671: *172624 http script copy: "X-Request-ID"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var: "80e3ae7c2495fcdc7ebe9b658dd579bc"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script copy: "X-Real-IP"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var: "fdff::a3d:fafb"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script copy: "X-Forwarded-For"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var: "fdff::a3d:fafb"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script copy: "X-Forwarded-Host"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var: "nginx-ingress-controller.ingress-nginx:443"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script copy: "X-Forwarded-Port"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var: "443"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script copy: "X-Forwarded-Proto"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var: "https"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script copy: "X-Original-URI"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var: "/.well-known/est/simpleenroll"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script copy: "X-Scheme"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var: "https"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script copy: ""
2020/05/18 22:52:02 [debug] 671#671: *172624 http script copy: "Content-Length"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script var: "280"
2020/05/18 22:52:02 [debug] 671#671: *172624 http script copy: ""
2020/05/18 22:52:02 [debug] 671#671: *172624 http proxy header: "User-Agent: libest 3.1.1"
2020/05/18 22:52:02 [debug] 671#671: *172624 http proxy header: "Accept: */*"
2020/05/18 22:52:02 [debug] 671#671: *172624 http proxy header: "Content-Type: application/pkcs10"
2020/05/18 22:52:02 [debug] 671#671: *172624 http proxy header: "Authorization: Basic cmEtYXBwOkZiV241M2p3"
2020/05/18 22:52:02 [debug] 671#671: *172624 http proxy header:
"POST /.well-known/est/simpleenroll HTTP/1.1
Host: nginx-ingress-controller.ingress-nginx:443
ssl-client-verify: NONE
X-Request-ID: 80e3ae7c2495fcdc7ebe9b658dd579bc
X-Real-IP: fdff::a3d:fafb
X-Forwarded-For: fdff::a3d:fafb
X-Forwarded-Host: nginx-ingress-controller.ingress-nginx:443
X-Forwarded-Port: 443
X-Forwarded-Proto: https
X-Original-URI: /.well-known/est/simpleenroll
X-Scheme: https
Content-Length: 280
User-Agent: libest 3.1.1
Accept: */*
Content-Type: application/pkcs10
Authorization: Basic cmEtYXBwOkZiV241M2p3

"
2020/05/18 22:52:02 [debug] 671#671: *172624 http cleanup add: 0000558A2B2F58A8
2020/05/18 22:52:02 [debug] 671#671: *172624 init keepalive peer
2020/05/18 22:52:02 [debug] 671#671: *172624 get keepalive peer
2020/05/18 22:52:02 [debug] 671#671: *172624 lua balancer peer, tries: 1
2020/05/18 22:52:02 [debug] 671#671: *172624 lua reset ctx
2020/05/18 22:52:02 [debug] 671#671: *172624 looking up Lua code cache with key 'balancer_by_luanhli_0f29762dfd828b8baa4d895affbc4b90'
2020/05/18 22:52:02 [debug] 671#671: *172624 stream socket 10
2020/05/18 22:52:02 [debug] 671#671: *172624 epoll add connection: fd:10 ev:80002005
2020/05/18 22:52:02 [debug] 671#671: *172624 connect to [fd10::1:169]:8082, fd:10 #172625
2020/05/18 22:52:02 [debug] 671#671: *172624 http upstream connect: -2
2020/05/18 22:52:02 [debug] 671#671: *172624 posix_memalign: 0000558A2B34D0A0:128 @16
2020/05/18 22:52:02 [debug] 671#671: *172624 event timer add: 10: 5000:993519304
2020/05/18 22:52:02 [debug] 671#671: *172624 http finalize request: -4, "/.well-known/est/simpleenroll?" a:1, c:2
2020/05/18 22:52:02 [debug] 671#671: *172624 http request count:2 blk:0
2020/05/18 22:52:02 [debug] 671#671: *172624 http run request: "/.well-known/est/simpleenroll?"
2020/05/18 22:52:02 [debug] 671#671: *172624 http upstream check client, write event:1, "/.well-known/est/simpleenroll"
2020/05/18 22:52:02 [debug] 671#671: *172624 http upstream request: "/.well-known/est/simpleenroll?"
2020/05/18 22:52:02 [debug] 671#671: *172624 http upstream send request handler
2020/05/18 22:52:02 [debug] 671#671: *172624 http upstream send request
2020/05/18 22:52:02 [debug] 671#671: *172624 http upstream send request body
2020/05/18 22:52:02 [debug] 671#671: *172624 chain writer buf fl:0 s:542
2020/05/18 22:52:02 [debug] 671#671: *172624 chain writer buf fl:1 s:280
2020/05/18 22:52:02 [debug] 671#671: *172624 chain writer in: 0000558A2B2F59F8
2020/05/18 22:52:02 [debug] 671#671: *172624 writev: 822 of 822
2020/05/18 22:52:02 [debug] 671#671: *172624 chain writer out: 0000000000000000
2020/05/18 22:52:02 [debug] 671#671: *172624 event timer del: 10: 993519304
2020/05/18 22:52:02 [debug] 671#671: *172624 event timer add: 10: 60000:993574308
2020/05/18 22:52:02 [debug] 671#671: *172624 http upstream request: "/.well-known/est/simpleenroll?"
2020/05/18 22:52:02 [debug] 671#671: *172624 http upstream process header
2020/05/18 22:52:02 [debug] 671#671: *172624 malloc: 0000558A2B33E000:4096
2020/05/18 22:52:02 [debug] 671#671: *172624 recv: eof:0, avail:1
2020/05/18 22:52:02 [debug] 671#671: *172624 recv: fd:10 911 of 4096
2020/05/18 22:52:02 [debug] 671#671: *172624 http proxy status 200 "200 OK"
2020/05/18 22:52:02 [debug] 671#671: *172624 http proxy header: "Connection: keep-alive"
2020/05/18 22:52:02 [debug] 671#671: *172624 http proxy header: "Content-Transfer-Encoding: base64"
2020/05/18 22:52:02 [debug] 671#671: *172624 http proxy header: "Content-Type: application/pkcs7-mime; smime-type=certs-only"
2020/05/18 22:52:02 [debug] 671#671: *172624 http proxy header: "Content-Length: 714"
2020/05/18 22:52:02 [debug] 671#671: *172624 http proxy header: "Date: Mon, 18 May 2020 22:52:02 GMT"
2020/05/18 22:52:02 [debug] 671#671: *172624 http proxy header done
2020/05/18 22:52:02 [debug] 671#671: *172624 headers more header filter, uri "/.well-known/est/simpleenroll"
2020/05/18 22:52:02 [debug] 671#671: *172624 lua header filter for user lua code, uri "/.well-known/est/simpleenroll"
2020/05/18 22:52:02 [debug] 671#671: *172624 looking up Lua code cache with key 'header_filter_by_luanhli_537482850bfc85b842f10d9c3d0521aa'
2020/05/18 22:52:02 [debug] 671#671: *172624 lua capture header filter, uri "/.well-known/est/simpleenroll"
2020/05/18 22:52:02 [debug] 671#671: *172624 HTTP/1.1 200 OK
Server: openresty/1.15.8.1
Date: Mon, 18 May 2020 22:52:02 GMT
Content-Type: application/pkcs7-mime; smime-type=certs-only
Content-Length: 714
Connection: close
Content-Transfer-Encoding: base64
Strict-Transport-Security: max-age=15724800; includeSubDomains

Any suggestion would be greatly appreciated !!.

Thanks,

Answer 1

OK I finally was able to figure it out. @Dirbaio, you were right, the issue seems related to the certificate. I realized my postman config was not correct and once I fixed it, I was able to reproduce the pb and start seeing HTTP 400 Bad request - SSL Certificate error.

I narrow it down to the following ingress configuration:

apiVersion: networking.k8s.io/v1beta1
kind: Ingress
metadata:
 name: pki-ws
 annotations:
   nginx.ingress.kubernetes.io/auth-tls-verify-client: "optional"
   nginx.ingress.kubernetes.io/auth-tls-pass-certificate-to-upstream: "true"
   nginx.ingress.kubernetes.io/auth-tls-secret: "default/managementca"
   nginx.ingress.kubernetes.io/backend-protocol: "HTTP"
   nginx.ingress.kubernetes.io/configuration-snippet: |
     proxy_set_header SSL_CLIENT_CERT $ssl_client_cert;
   kubernetes.io/ingress.class: "fanhe-ingress"
spec:
 tls:
 - hosts:
   - nginx-ingress-controller.ingress-nginx
   secretName: nginx-ingress-tls
 rules:
   - host: nginx-ingress-controller.ingress-nginx
     http:
       paths:
       - path: /ejbca/ejbcaws
         backend:
          serviceName: pki-app
          servicePort: 8082
---
apiVersion: networking.k8s.io/v1beta1
kind: Ingress
metadata:
  name: pki-est
  annotations:
    kubernetes.io/ingress.class: "fanhe-ingress"
spec:
  tls:
  - hosts:
    - nginx-ingress-controller.ingress-nginx
    secretName: nginx-ingress-tls
  rules:
    - host: nginx-ingress-controller.ingress-nginx
      http:
        paths:
        - path: /.well-known/est
          backend:
           serviceName: pki-app
           servicePort: 8082

Because both are sharing the same host, I guess both config were merged in nginx and so all the annotations applied to both path. My EST client issuing CA is different from "default/managementca" and nginx was not able to authenticate it correctly.

I fixed it by using two different hosts and one cert with multiple SANs for NGINX.

Thanks for trying to help. It was appreciated.

Answer 2

In your ingress there are a few things that I would like to comment that may be leading to the problem you have:

kubernetes.io/ingress.class: "fanhe-ingress"

This field should be filled with a pre-defined ingress.class name registered under kubernetes.io and not a name that you create.

You have to use kubernetes.io/ingress.class: "nginx" instead.

spec:
  tls:
  - hosts:
    - nginx-ingress-controller.ingress-nginx
    secretName: nginx-ingress-tls-ec-secret
  rules:
    - host: nginx-ingress-controller.ingress-nginx

hosts and host should be the domain name that you use to access your application from outside. This should be the same name as you used to create your tls certificates.

It should look like this:

spec:
 tls:
 - hosts:
   - yourwebsiteurl.com
   secretName: nginx-ingress-tls-ec-secret
 rules:
   - host: yourwebsiteurl.com

Please also double check your path, paths can contain . (dots) however this is not oftenly used.

path: /.well-known/est

It should look like this:

path: /well-known/est

Wrapping up everything, your ingress should be similar to the following.

apiVersion: networking.k8s.io/v1beta1
kind: Ingress
metadata:
 name: pki-est
 annotations:
   kubernetes.io/ingress.class: "nginx"
spec:
 tls:
 - hosts:
   - yourwebsiteurl.com
   secretName: nginx-ingress-tls-ec-secret
 rules:
   - host: yourwebsiteurl.com
     http:
       paths:
       - path: /well-known/est
         backend:
          serviceName: pki-app
          servicePort: 8082

Answer 3

This line is the reason

2020/05/18 10:06:52 [info] 198#198: *15975 client SSL certificate verify error: (19:self signed certificate in certificate chain) while reading client request headers, client: fd10::1:165, server: nginx-ingress-controller.ingress-nginx, request: "POST /.well-known/est/simpleenroll HTTP/1.1", host: "nginx-ingress-controller.ingress-nginx:443"

It seems your protocol is using TLS client certificates. It is not possible to reverse proxy connections with TLS client certificates, because the nginx-ingress doesn't have the private key to it.

You can configure nginx-ingress to use client certs with some annotations (docs) but your backend server won't be able to "see" the client certificate, so it will probably reject the request.

I'd either find a way to not use client certs (looks like EST can also use user+password?) or expose the TCP service directly.