6

I am seeing a weird issue with SSLEngine and wondering if there is an issue with my code or SSLEngine. Here is the order in which I see things

  1. HandshakeStatus is NEED_WRAP
  2. We call SSLEngine.WRAP
  3. after, there is ZERO data written to the buffer, and SSLEngineResult.result=OK(not overflow nor underflow :( ) and HandshakeStatus is STILL NEED_WRAP

Most important question: How to debug thoroughly? How to 'see' each message somehow? I can capture the byte stream easily enough but is there some library that can parse that into SSL handshake objects?

line 298 (recording previous handshake status) to line 328(where we throw the exception with info) is the relevant code here

https://github.com/deanhiller/webpieces/blob/sslEngineFartingExample/core/core-ssl/src/main/java/org/webpieces/ssl/impl/AsyncSSLEngine3Impl.java

The stack trace was

2019-06-21 08:58:24,562 [-] [webpiecesThreadPool6] Caller+1  at org.webpieces.util.threading.SessionExecutorImpl$RunnableWithKey.run(SessionExecutorImpl.java:123)
  ERROR: Uncaught Exception
java.lang.IllegalStateException: Engine issue.  hsStatus=NEED_WRAP status=OK previous hsStatus=NEED_WRAP
    at org.webpieces.ssl.impl.AsyncSSLEngine3Impl.sendHandshakeMessageImpl(AsyncSSLEngine3Impl.java:328)
    at org.webpieces.ssl.impl.AsyncSSLEngine3Impl.sendHandshakeMessage(AsyncSSLEngine3Impl.java:286)
    at org.webpieces.ssl.impl.AsyncSSLEngine3Impl.doHandshakeWork(AsyncSSLEngine3Impl.java:133)
    at org.webpieces.ssl.impl.AsyncSSLEngine3Impl.doHandshakeLoop(AsyncSSLEngine3Impl.java:246)
    at org.webpieces.ssl.impl.AsyncSSLEngine3Impl.unwrapPacket(AsyncSSLEngine3Impl.java:210)
    at org.webpieces.ssl.impl.AsyncSSLEngine3Impl.doWork(AsyncSSLEngine3Impl.java:109)
    at org.webpieces.ssl.impl.AsyncSSLEngine3Impl.feedEncryptedPacket(AsyncSSLEngine3Impl.java:82)
    at org.webpieces.nio.impl.ssl.SslTCPChannel$SocketDataListener.incomingData(SslTCPChannel.java:175)
    at org.webpieces.nio.impl.threading.ThreadDataListener$1.run(ThreadDataListener.java:26)
    at org.webpieces.util.threading.SessionExecutorImpl$RunnableWithKey.run(SessionExecutorImpl.java:121)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:834)

any ideas? How can I really dig into this further? My preference is a library that takes bytes and spits out ssl objects representing each handshake message or decrypted packet(with any header info that comes with the original encrypted thing).

Specifically, here is the code mentioned above

        HandshakeStatus previousStatus = sslEngine.getHandshakeStatus();
    //CLOSE and all the threads that call feedPlainPacket can have contention on wrapping to encrypt and
    //must synchronize on sslEngine.wrap
    Status lastStatus;
    HandshakeStatus hsStatus;
    synchronized (wrapLock ) {

        HandshakeStatus beforeWrapHandshakeStatus = sslEngine.getHandshakeStatus();
        if (beforeWrapHandshakeStatus != HandshakeStatus.NEED_WRAP)
            throw new IllegalStateException("we should only be calling this method when hsStatus=NEED_WRAP.  hsStatus=" + beforeWrapHandshakeStatus);

        //KEEEEEP This very small.  wrap and then listener.packetEncrypted
        SSLEngineResult result = sslEngine.wrap(SslMementoImpl.EMPTY, engineToSocketData);
        lastStatus = result.getStatus();
        hsStatus = result.getHandshakeStatus();
    }

    log.trace(()->mem+"write packet pos="+engineToSocketData.position()+" lim="+
                    engineToSocketData.limit()+" status="+lastStatus+" hs="+hsStatus);

    if(lastStatus == Status.BUFFER_OVERFLOW || lastStatus == Status.BUFFER_UNDERFLOW)
        throw new RuntimeException("status not right, status="+lastStatus+" even though we sized the buffer to consume all?");

    boolean readNoData = engineToSocketData.position() == 0;
    engineToSocketData.flip();
    try {
        CompletableFuture<Void> sentMsgFuture;
        if(readNoData) {
            log.trace(() -> "ssl engine is farting. READ 0 data.  hsStatus="+hsStatus+" status="+lastStatus);

            throw new IllegalStateException("Engine issue.  hsStatus="+hsStatus+" status="+lastStatus+" previous hsStatus="+previousStatus);
            //A big hack since the Engine was not working in live testing with FireFox and it would tell us to wrap
            //and NOT output any data AND not BufferOverflow.....you have to do 1 or the other, right!
            //instead cut out of looping since there seems to be no data
            //sslEngineIsFarting = true;
            //sentMsgFuture = CompletableFuture.completedFuture(null);

thanks, Dean

Dean Hiller
  • 19,235
  • 25
  • 129
  • 212
  • Seems like you're just looking for a way to view your own log traces? – user207421 Jun 24 '19 at 04:19
  • This all looks far too complicated. If you're trying to read on behalf of the application, do an unwrap, otherwise you are doing a write so do a wrap. If when doing either, you get `NEED_WRAP`, do a `wrap()`: if you get `BUFFER_OVERFLOW` do a write and repeat the `wrap()`. Similarly if you get `NEED_UNWRAP`, do an `unwrap()`: if you get `BUFFER_UNDERFLOW` do a read and repeat the unwrap. Repeat until you have either got or sent application data, depending on which you're doing, or got an exception or a closure. I've implemented an async SSLEngine and it wasn't nearly this complex. – user207421 Jun 24 '19 at 04:40
  • I thought it was simple too until the engine would tell me to wrap and then I wrap and it does 'nothing'. (ie. the first 3 bullet points in the post are critical to read and I actually just repeated those 3 bullets) – Dean Hiller Jun 24 '19 at 18:31
  • as far as complexity, take out all the logs and all the precondition / postcondition logic and it really is doing nothing so it is quite simple. the precondition and postcondition stuff is as there is something weird going on as explained in the post. – Dean Hiller Jun 24 '19 at 18:33
  • About debug: have you tried javax.net.debug? – beat Jun 28 '19 at 11:59
  • @beat actually, I had found "-Djavax.net.debug=ssl:handshake:verbose:keymanager:trustmanager -Djava.security.debug=access:stack" soon after I posted and finally got around to trying it...very interesting. it happens when clients are sending a warning/close_notify whatever that is – Dean Hiller Jun 30 '19 at 05:28
  • oh and thanks @beat as your comment helped push me over the edge in using it. seems like truncation attacks on java are still viable....lol. – Dean Hiller Jun 30 '19 at 05:46

3 Answers3

1

Ok, more and more this seems like a jdk bug and this seems to prove it now. My log shows I was on jdk11.0.3(on a MAC)

2019-06-29 23:37:18,793 [main][] [-] Caller+1 at WEBPIECESxPACKAGE.DevelopmentServer.main(DevelopmentServer.java:32) INFO: Starting Development Server under java version=11.0.3

I used debug ssl flag settings of

-Djavax.net.debug=ssl:handshake:verbose:keymanager:trustmanager -Djava.security.debug=access:stack

I surrounded all my calls to sslEngine.wrap and sslEngine.unwrap with my own logs as well and thankfully everyone had the thread name in their logs as well.

It seems when clients send a warning of this 

javax.net.ssl|DEBUG|14|webpiecesThreadPool1|2019-06-29 23:27:14.860 
MDT|Alert.java:232|Received alert message (
"Alert": {
  "level"      : "warning",
  "description": "close_notify"
}
)

the SSLEngine tells us we need to WRAP which is correct as we need to be replying with a close_notify as well to prevent truncation attacks BUT instead the engine returns 0 bytes and tells us the state of the engine is still NEED_WRAP.

ALSO, there was ZERO ssl debug logs from java between my logs before and after the sslEngine.wrap call almost like the sslEngine farted and did nothing.

Then, I thought I would be really cool and added this as the first lines in main() method

        System.setProperty("jdk.tls.server.protocols", "TLSv1.2");
        System.setProperty("jdk.tls.client.protocols", "TLSv1.2");

but the selected version in the debug info was still TLSv1.3....grrrrrr...oh well, I give up.

shb
  • 5,957
  • 2
  • 15
  • 32
Dean Hiller
  • 19,235
  • 25
  • 129
  • 212
1

oh, even better, downgrading to 1.8.0_111 yields success

2019-06-30 00:11:54,813 [main] Caller+1  at 
WEBPIECESxPACKAGE.DevelopmentServer.main(DevelopmentServer.java:32)
 INFO: Starting Development Server under java version=1.8.0_111

webpiecesThreadPool5, READ: TLSv1.2 Alert, length = 26
webpiecesThreadPool2, RECV TLSv1.2 ALERT:  warning, close_notify
webpiecesThreadPool2, closeInboundInternal()
webpiecesThreadPool2, closeOutboundInternal()
webpiecesThreadPool5, RECV TLSv1.2 ALERT:  warning, close_notify
webpiecesThreadPool5, closeInboundInternal()
webpiecesThreadPool5, closeOutboundInternal()
webpiecesThreadPool2, SEND TLSv1.2 ALERT:  warning, description = close_notify
webpiecesThreadPool5, SEND TLSv1.2 ALERT:  warning, description = close_notify
webpiecesThreadPool2, WRITE: TLSv1.2 Alert, length = 26
webpiecesThreadPool5, WRITE: TLSv1.2 Alert, length = 26
Dean Hiller
  • 19,235
  • 25
  • 129
  • 212
1

System.setProperty("jdk.tls.server.protocols", "TLSv1.2");

System.setProperty("jdk.tls.client.protocols", "TLSv1.2");

The system property should be set before the JSSE get loaded. For example, set the property within command line. Is it the cause that the system property does not work for you?

... the SSLEngine tells us we need to WRAP which is correct as we need to be replying with a close_notify as well to prevent truncation attacks BUT instead the engine returns 0 bytes and tells us the state of the engine is still NEED_WRAP.

TLS 1.3 is using a half-close policy (See RFC 8446). When receiving the close_notify, the inbound side will be closed and the outbound side keeps open. The local side cannot receive any data, but is allowed to send more application data.

There are a few compatibility impact by the half-close policy (See JDK 11 release note, https://www.oracle.com/technetwork/java/javase/11-relnote-issues-5012449.html). The system property, "jdk.tls.acknowledgeCloseNotify", can be used as a workaround. For more details, please refer to the JDK 11 release note.

Xuelei Fan
  • 26
  • 1
  • "The system property should be set before the JSSE get loaded" On previous versions, you could set it in the JVM just fine ;) and it downgraded to 1.2 so that is weird!!! Is this a jdk11 thing only? – Dean Hiller Sep 16 '19 at 19:20
  • As for the release notes, I would expect the SSL engine to 'not' tell me to wrap then. That still seems like a jdk bug. I receive a close_notify and it tells me 'wrap, you have a msg we want you to send' but then it gives no message to send. It forced me to code for this 'peculiar' case which I guess is fine but I could not use the typical post conditions to make sure things were as they were supposed to be :(. – Dean Hiller Sep 16 '19 at 19:22
  • I guess I would prefer jdk11 not to tell me to wrap. – Dean Hiller Sep 16 '19 at 19:23
  • I should make it more clear. "The system properties, jdk.tls.server.protocols and jdk.tls.client.protocols, should be set before the JSSE get loaded". The two system properties can be set in the JVM, just before loading the JSSE context. The behavior of the two system properties is not changed in JDK 11. – Xuelei Fan Sep 19 '19 at 15:15
  • It was expected to simplify the application by using NEED_WRAP. Application only need to call wrap for application data, and don't need to worry about operations like UNWRAP. I think it works if there are application data for the wrap() method. But I also can see that if no application data for the wrap() method, it could be confusing as the wrap() did nothing. Generally, applications call wrap() with application data, but it is also legal without application data. I think I understand the concern better now. Thanks! – Xuelei Fan Sep 19 '19 at 15:32