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.
Best regards
Peter
