Mark,
> Am 23.06.2017 um 17:32 schrieb Mark Thomas <ma...@apache.org>: > > On 23/06/17 16:02, l...@kreuser.name wrote: >> Mark, >>> >>> Am 23.06.2017 um 15:17 schrieb Mark Thomas <ma...@apache.org>: >>> >>> On 13/06/17 11:57, Mark Thomas wrote: >>>> On 13/06/17 10:13, Kreuser, Peter wrote: >>>>> Mark, >>>>> >>>>>> On 09/06/17 16:02, Kreuser, Peter wrote: >>>>>>> Hi all, >>>>>>> >>>>>>> Sorry for the long text. I hope somebody can help me track down the >>>>>>> problem I'm facing with Tomcat (8.5.15), tcnative (1.2.12), openssl >>>>>>> (1.1.0e) and HTTP/2. JVM is zulu-8.21.0.1 (1.8.0_131-b11) >>>>>> >>>>>> No need to apologise. There was enough information in this report for me >>>>>> to be 95% sure of what was going on before I tested things locally. >>>>>> >>>>>> <snip/> >>>>>> >>>>>>> Would be nice if somebody here could tell me if that is a bug or if I >>>>>>> have some misconfiguration. >>>>>> >>>>>> It is a bug. >>>>>> >>>>>> The short explanation is that with NIO2, the style of the API (async >>>>>> read/write with CompletionHandlers) means that a TLS connection can get >>>>>> closed down (by a CompletionHandler) before the access log entry is >>>>>> written. This leads to passing a NULL reference to some native code >>>>>> which - unsurprisingly - falls over (Tomcat is meant to make sure it >>>>>> doesn't pass NULL references). >>>>>> >>>>>> There is an easy fix but the side-effect is that sometimes the cipher >>>>>> suite name won't appear in the access log. Depending on timing on your >>>>>> system that could be very frequent to almost never. I'd roughly expect >>>>>> it to happen as frequently as the crashes. >>>>>> >>>>>> The harder fix is to note that we want the info and to ensure we cache >>>>>> it before the TLS connection is closed down. In theory, we could do this >>>>>> in the access log but it means parsing the request attribute config. >>>>>> Performance wise, there will be an impact on users since the lookup to >>>>>> populate the cache will occur during request processing rather than >>>>>> afterwards. However, overall throughput should be unaffected. >>>>>> >>>>>> An alternative fix is for the application to trigger the caching of the >>>>>> TLS info by requesting one of the TLD attributes. >>>>>> >>>>>> Switching to NIO should also fix this. Note, I would not expect NIO and >>>>>> NIO2 to be much different performance wise. >>>>>> >>>>>> Would the easy fix be sufficient? >>>>>> >>>>>> Mark >>>>> >>>>> For a start the easy fix would be sufficient. Apparently this is only a >>>>> real problem when I call the site via curl, as it does not happen in the >>>>> various browsers (at least not on every call). >>>>> >>>>> We should at least make users aware that certain information can be >>>>> missing in the accesslog and the cause of it (in the AccessLogValve >>>>> documentation?). And are there any other implications of the >>>>> asynchronicity? I guess the behavior of NIO2 and HTTP/2 processing is not >>>>> obvious? >>>>> >>>>> Your alternative fix would be to copy the attributes during request >>>>> processing (in a filter) and then log them from the filter request >>>>> attributes instead of the predefined ssl attributes? Correct? >>>>> >>>>> Thank you for your support and the bug fix ;-)! Have you filed the bug >>>>> internally or should I? >>>> >>>> I need to look into this some more first. Remy's comments suggest that >>>> my first analysis might have been wrong. >>> >>> I've been looking into this this afternoon. Rémy has made some changes >>> to trunk and 8.5.x that prevent the crash. >>> >>> It does appear that a timing issue is involved. I'm still looking into >>> the details. >>> >>> At the moment, the SSL_NULL_WITH_NULL_NULL cipher suite is recorded >>> rather than the crash when the TLS information is not available when the >>> access log needs it. >>> >>> Rémy's changes are in the 9.0.x and 8.5.x releases being voted on at the >>> moment. >>> >>> Mark >>> >>> --------------------------------------------------------------------- >> >> That seems to help. I get >> >> 192.168.1.10 - - [23/Jun/2017:16:53:22 +0200] 'GET / HTTP/2.0' 200 16 5 8843 >> '-' 'curl/7.54.0' - SSL_NULL_WITH_NULL_NULL >> >> plus on the console: >> >> 23-Jun-2017 16:53:22.045 WARNING [https-openssl-nio2-8843-exec-3] >> org.apache.coyote.AbstractProcessor.populateSslRequestAttributes Exception >> getting SSL attributes >> java.lang.IllegalStateException: SSL session ID not available >> at >> org.apache.tomcat.util.net.openssl.OpenSSLEngine$OpenSSLSession.getId(OpenSSLEngine.java:1047) >> at >> org.apache.tomcat.util.net.jsse.JSSESupport.getSessionId(JSSESupport.java:156) >> at >> org.apache.coyote.AbstractProcessor.populateSslRequestAttributes(AbstractProcessor.java:608) >> at >> org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:361) >> at org.apache.coyote.Request.action(Request.java:426) >> at org.apache.catalina.connector.Request.getAttribute(Request.java:903) >> at >> org.apache.catalina.valves.AbstractAccessLogValve$RequestAttributeElement.addElement(AbstractAccessLogValve.java:1439) >> at >> org.apache.catalina.valves.AbstractAccessLogValve.log(AbstractAccessLogValve.java:653) >> at >> org.apache.catalina.core.AccessLogAdapter.log(AccessLogAdapter.java:48) >> at >> org.apache.catalina.core.ContainerBase.logAccess(ContainerBase.java:1065) >> at >> org.apache.catalina.core.ContainerBase.logAccess(ContainerBase.java:1072) >> at >> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:401) >> at >> org.apache.coyote.http2.StreamProcessor.service(StreamProcessor.java:245) >> at >> org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) >> at >> org.apache.coyote.http2.StreamProcessor.process(StreamProcessor.java:65) >> at org.apache.coyote.http2.StreamRunnable.run(StreamRunnable.java:35) >> at >> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) >> at >> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) >> at >> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) >> at java.lang.Thread.run(Thread.java:748) >> >> However I still see a timing problem, as it is not always happening. Maybe 5 >> out of 7 are NULL. If I send more requests immediately after each other NULL >> is more frequent. > > Thanks for the confirmation. The important thing is that the crashes > have stopped. Note I'm fairly certain this is issue only affects NIO2 > with OpenSSL for TLS. > > I'm currently looking at a way to pre-populate the TLS info if the > AccessLogValve requires this to avoid the error messages and the NULL > cipher suite entries. > > Mark > I agree with that - no more crashes is key! Thanks. Have a great weekend. Peter --------------------------------------------------------------------- To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
