Troubleshooting

Http Round Trip

As proxy use netty with Zuul specific messages handling proxy might generate warnings that does not necessarily has an effect to business.

Writing response to client channel before have received the LastContent of request:

Writing response to client channel before have received the LastContent of request! uri=<URI>, method=<httpmethod>, clientip=<client>, Channel: [id: <channelID>, L:/<host> - R:/<host>], active=true, open=true, registered=true, writable=true, id=<id>, Passport: CurrentPassport {...

Solution: This message can be caused by e.g. immediate response from origin before client has send the full request (seen together with webdav requests) or even when client send a request and proxy answer immediate with a http status 502 cause origin is not reachable. To avoid the misleading messages set logger com.netflix.zuul.netty.server.ClientResponseWriter to ERROR. In case of any data loss the log level of this logger might be set back to WARN.

Received complete event while still handling the request. With reason::

Received complete event while still handling the request. With reason: CLOSE -- Channel: [id: 0xbf6efe16, L:/<host> - R:/<host>], active=true, open=true, registered=true, writable=true, id=<id>>, Passport: CurrentPassport {start_ms=1606311307942, [+0=IN_REQ_HEADERS_RECEIVED, +287805=SERVER_CH_CLOSE, +472500=NOW]}

Solution: Log messages with this very short passport were sometimes found together with network management tools which e.g. polls http ports for alive checks. To avoid the misleading messages set logger com.netflix.zuul.netty.server.ClientResponseWriter to ERROR. In case of any data loss the log level of this logger might be set back to WARN.

TLS errors

In general, TLS issues can be debugged using Java’s very detailed debug output. To enable it, the Java process needs to be started with option -Djavax.net.debug=all. Debug output is typically printed to stdout and is extremely verbose. Also it reveals plain text of requests and responses! Anyhow this is a very useful tool during integration testing. More details can be found at https://docs.oracle.com/javase/8/docs/technotes/guides/security/jsse/ReadDebug.html.

Inbound

When configuring TLS it might happen, that the keystore is not configured correctly. Sadly, not every possible error leads to a sane error-output. Most of the time the error messages mean, that no valid certificate could be found for the request. Following are two potential error messages, that mean something different than they say.

OpenSSL with SNI:

javax.net.ssl.SSLHandshakeException: error:100000b8:SSL routines:OPENSSL_internal:NO_SHARED_CIPHER

Solution: Either deactivate OpenSSL directly via zuul.ssl.openssl.allow=false in application.properties or reduce the amount of certificates to one, to disable the SNI mechanism.

No matching certificate in keystore:

io.netty.handler.codec.DecoderException: javax.net.ssl.SSLHandshakeException: no cipher suites in common

Solution: This simply means, that no certificate could be found for the requesting domain. Check your keystore and make sure that the certificate, made for the requesting client, is present.

No SNI hostname:

io.ox.proxy.server.security.SniKeyManager: No SNI hostname was found with the given SSLEngine, no alias could be determined to load certificate.

Solution: This is a known message if we have more then one alias in the keystore and a client try to connection without SNI. Make sure the client send the proper host via SNI extension or reduce alias in keystore to one.

Outbound

Outbound HTTPS connections will fail on untrusted certificates (see also Backend Pools::TLS. In that case the following will show up in logs as:

2019-11-23T14:12:42,833+0100 [Salamander-ClientToZuulWorker-0] WARN  c.n.z.filters.endpoint.ProxyEndpoint - FAILURE_LOCAL, origin = upstream, origin channel info = Channel: [id: 0xe1cb165b, L:/127.0.0.1:50142 - R:localhost/127.0.0.1:443], active=true, open=true, registered=true, writable=true, id=e1cb165b, Passport: CurrentPassport {start_ms=1574514762106, [+0=SERVER_CH_ACTIVE, +30887473=IN_REQ_HEADERS_RECEIVED, +60512380=FILTERS_INBOUND_START, +73572694=FILTERS_INBOUND_END, +654109637=ORIGIN_CH_CONNECTING, +680463025=ORIGIN_CONN_ACQUIRE_START, +680628600=IN_REQ_LAST_CONTENT_RECEIVED, +685689009=ORIGIN_CH_CONNECTED, +686688864=ORIGIN_CONN_ACQUIRE_END, +691002152=OUT_REQ_HEADERS_SENDING, +693593741=OUT_REQ_LAST_CONTENT_SENDING, +696344587=ORIGIN_CH_ACTIVE, +724605571=NOW]}
javax.net.ssl.SSLException: SSLEngine closed already
  at io.netty.handler.ssl.SslHandler.wrap(...)(Unknown Source)

Unfortunately this error message is very generic and doesn’t point to the actual root cause. To confirm, DEBUG logging can be enabled for logger com.netflix.zuul.netty.connectionpool.ConnectionPoolHandler, leading to more detailed log output.

With OpenSSL enabled:

2019-11-23T14:14:05,581+0100 [Salamander-ClientToZuulWorker-1] DEBUG i.n.h.s.ReferenceCountedOpenSslContext - verification of certificate failed
sun.security.validator.ValidatorException: PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
  at sun.security.validator.PKIXValidator.doBuild(PKIXValidator.java:397)
  at sun.security.validator.PKIXValidator.engineValidate(PKIXValidator.java:302)
  at sun.security.validator.Validator.validate(Validator.java:262)
  at sun.security.ssl.X509TrustManagerImpl.validate(X509TrustManagerImpl.java:324)
  at sun.security.ssl.X509TrustManagerImpl.checkTrusted(X509TrustManagerImpl.java:281)
  at sun.security.ssl.X509TrustManagerImpl.checkServerTrusted(X509TrustManagerImpl.java:136)
  at io.netty.handler.ssl.ReferenceCountedOpenSslClientContext$ExtendedTrustManagerVerifyCallback.verify(ReferenceCountedOpenSslClientContext.java:237)
  at io.netty.handler.ssl.ReferenceCountedOpenSslContext$AbstractCertificateVerifier.verify(ReferenceCountedOpenSslContext.java:621)
  at io.netty.internal.tcnative.SSL.readFromSSL(Native Method)
  [...]
  at java.lang.Thread.run(Thread.java:748)
Caused by: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
  at sun.security.provider.certpath.SunCertPathBuilder.build(SunCertPathBuilder.java:141)
  at sun.security.provider.certpath.SunCertPathBuilder.engineBuild(SunCertPathBuilder.java:126)
  at java.security.cert.CertPathBuilder.build(CertPathBuilder.java:280)
  at sun.security.validator.PKIXValidator.doBuild(PKIXValidator.java:392)
  ... 40 common frames omitted

With normal JRE SSL:

2019-11-23T14:15:24,995+0100 [Salamander-ClientToZuulWorker-0] DEBUG c.n.z.n.c.ConnectionPoolHandler - Exception on Origin channel for origin - upstream. Channel: [id: 0x21ce1dae, L:/127.0.0.1:50823 ! R:localhost/127.0.0.1:443], active=false, open=false, registered=true, writable=false, id=21ce1dae, Passport: CurrentPassport {start_ms=1574514924255, [+0=SERVER_CH_ACTIVE, +31071419=IN_REQ_HEADERS_RECEIVED, +62144456=FILTERS_INBOUND_START, +76851580=FILTERS_INBOUND_END, +579132125=ORIGIN_CH_CONNECTING, +604916577=ORIGIN_CONN_ACQUIRE_START, +605204297=IN_REQ_LAST_CONTENT_RECEIVED, +610441322=ORIGIN_CH_CONNECTED, +611889646=ORIGIN_CONN_ACQUIRE_END, +616052674=OUT_REQ_HEADERS_SENDING, +618740568=OUT_REQ_LAST_CONTENT_SENDING, +628692309=ORIGIN_CH_ACTIVE, +659922807=FILTERS_OUTBOUND_START, +721169337=FILTERS_OUTBOUND_END, +723031881=OUT_RESP_HEADERS_SENDING, +725671291=OUT_RESP_LAST_CONTENT_SENDING, +727932501=OUT_RESP_HEADERS_SENT, +727983756=OUT_RESP_LAST_CONTENT_SENT, +736707023=ORIGIN_CH_CLOSE, +738236144=OUT_REQ_HEADERS_ERROR_SENDING, +738657984=OUT_REQ_LAST_CONTENT_ERROR_SENDING, +738853699=ORIGIN_CH_CLOSE, +739460086=NOW]} - io.netty.handler.codec.DecoderException: javax.net.ssl.SSLHandshakeException: General SSLEngine problem
io.netty.handler.codec.DecoderException: javax.net.ssl.SSLHandshakeException: General SSLEngine problem
  at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:459)
  at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:265)
  [...]
  at java.lang.Thread.run(Thread.java:748)
Caused by: javax.net.ssl.SSLHandshakeException: General SSLEngine problem
  [...]
Caused by: sun.security.validator.ValidatorException: PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
  at sun.security.validator.PKIXValidator.doBuild(PKIXValidator.java:397)
  at sun.security.validator.PKIXValidator.engineValidate(PKIXValidator.java:302)
  at sun.security.validator.Validator.validate(Validator.java:262)
  at sun.security.ssl.X509TrustManagerImpl.validate(X509TrustManagerImpl.java:324)
  at sun.security.ssl.X509TrustManagerImpl.checkTrusted(X509TrustManagerImpl.java:281)
  at sun.security.ssl.X509TrustManagerImpl.checkServerTrusted(X509TrustManagerImpl.java:136)
  at sun.security.ssl.ClientHandshaker.serverCertificate(ClientHandshaker.java:1626)
  ... 34 common frames omitted
Caused by: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
  at sun.security.provider.certpath.SunCertPathBuilder.build(SunCertPathBuilder.java:141)
  at sun.security.provider.certpath.SunCertPathBuilder.engineBuild(SunCertPathBuilder.java:126)
  at java.security.cert.CertPathBuilder.build(CertPathBuilder.java:280)
  at sun.security.validator.PKIXValidator.doBuild(PKIXValidator.java:392)
  ... 40 common frames omitted