SNMP4j over TLS stuck at "Key is writable"

AGENTPP · February 18, 2022, 12:53am

I have changed the handling of the CLOSED SSL engine status once again in the latest 2.8.9 SNAPSHOT. Now the underlying TCP connection will be closed in any case to fully reset the connection.
Maybe that helps.
Of course, you can try newer JDKs too. The SSL engine was improved a lot from 8 to 17 - I am not sure if everything has been back ported to 8.

anjali.k_m · February 28, 2022, 9:54am

Hi @AGENTPP
We are communicating with Oracle to get the fix backported but we are unsure of the rootcause.
This issue was in JKS keystore and occationally seen.
In BCFKS keystore we are frequently seeing this issue when we are establishing connection itself. Took the thread dump and noticed a dead lock.

Can you please take a look and let us know the cause.

cc: @tvikasv

AGENTPP · March 2, 2022, 9:34am

This seems to be a bug. Currently unclear why it does not occur on SNMP4J 3.x too, but that might be related to using not Hashtable but a Collections.synchronizedMap there for Snmp.pendingRequests.
I am going to provide a fix ASAP.

AGENTPP · March 2, 2022, 10:00am

This deadlock can happen only during (D)TLS contextEngineID discovery based on RFC 5343.

To fix it, in the Snmp.PendingRequest.resendRequest method the synchronized block needs to be removed like this:

protected <A extends Address> boolean resendRequest(PendingRequest<A> request, PDU response) {
    if (request.useNextPDU()) {
        request.responseReceived = false;
        pendingRequests.remove(request.key);
        PduHandle holdKeyUntilResendDone = request.key;
        request.key = null;
        handleInternalResponse(response, request.pdu, request.target.getAddress());
        try {
            sendMessage(request.pdu, request.target, request.transport, request);
        } catch (IOException e) {
            logger.error("IOException while resending request after RFC 5343 context engine ID discovery: " +
                    e.getMessage(), e);
        }
        // now the previous retry can be released
        if (logger.isDebugEnabled()) {
            logger.debug("Releasing PDU handle " + holdKeyUntilResendDone);
        }
        holdKeyUntilResendDone = null;
        return true;
    }
    return false;
}

tvikasv · March 3, 2022, 10:10am

Hi Frank ,

We don’t see the below exception when key is in writable loop .

at java.base/sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:48)
at java.base/sun.nio.ch.NioSocketImpl.tryRead(NioSocketImpl.java:261)
at java.base/sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:312)
at java.base/sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:350)
at java.base/sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:803)
at java.base/java.net.Socket$SocketInputStream.read(Socket.java:981)
at java.base/sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:478)
at java.base/sun.security.ssl.SSLSocketInputRecord.readFully(SSLSocketInputRecord.java:461)
at java.base/sun.security.ssl.SSLSocketInputRecord.decodeInputRecord(SSLSocketInputRecord.java:243)
at java.base/sun.security.ssl.SSLSocketInputRecord.decode(SSLSocketInputRecord.java:181)
at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:110)
at java.base/sun.security.ssl.SSLSocketImpl.decode(SSLSocketImpl.java:1491)
at java.base/sun.security.ssl.SSLSocketImpl.readHandshakeRecord(SSLSocketImpl.java:1397)
at java.base/sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:444)
at java.base/sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:415)

SSLSocket.close() also reads from socket after ~~JDK-8268965~~:
at java.base/sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:48)
at java.base/sun.nio.ch.NioSocketImpl.tryRead(NioSocketImpl.java:261)
at java.base/sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:312)
at java.base/sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:350)
at java.base/sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:803)
at java.base/java.net.Socket$SocketInputStream.read(Socket.java:981)
at java.base/java.io.InputStream.skip(InputStream.java:544)
at java.base/sun.security.ssl.SSLSocketInputRecord.deplete(SSLSocketInputRecord.java:504)
at java.base/sun.security.ssl.SSLSocketImpl.closeSocket(SSLSocketImpl.java:1762)
at java.base/sun.security.ssl.SSLSocketImpl.shutdown(SSLSocketImpl.java:1739)
at java.base/sun.security.ssl.SSLSocketImpl.bruteForceCloseInput(SSLSocketImpl.java:773)
at java.base/sun.security.ssl.SSLSocketImpl.duplexCloseOutput(SSLSocketImpl.java:638)
at java.base/sun.security.ssl.SSLSocketImpl.close(SSLSocketImpl.java:570)

Can you please let us know how can we justify to oracle that the looping issue is due to https://bugs.openjdk.java.net/browse/JDK-8274524 as we are not seeing ssl exception

Regards,
Vikas

AGENTPP · March 3, 2022, 10:22am

I was just guessing that the JDK bug is related to the issue you observe. I have no proof for that, except that this behavior was not observed with recent JDKs and closing connections is part of your issue.
Does not SNMP4J 2.8.9 fix your problem? It has been released today.

tvikasv · March 3, 2022, 12:17pm

Hi Frank,
We used https://snmp.app/dist/snapshot/org/snmp4j/snmp4j/2.9.0-SNAPSHOT/snmp4j-2.9.0-20220302.102246-2.jar
It has the looping issue .
Regards,
Vikas

AGENTPP · March 3, 2022, 12:20pm

Hi Vikas,
OK, then I have no further ideas.
Best regards,
Frank

anjali.k_m · March 4, 2022, 8:16am

Hi Frank,
We are thankful for the so far support.
We took java 11 openjdk-11.0.10.0.9-8 with latest snmp4j jar snmp4j-3.6.5-20220302.101842-5.jar

But we are seeing Key Is Writable issue post connections established as well.

Can you please share some pointers as how we can debug the issue on snmp4j side. As I had requested, how can we decrypt SNMP over TLS data? This might help us understand the cause. We have tried TLS decryption and was successful for HTTP over TLS but not SNMP. In your tests, how are you decrypting data for tests? Is there any other memory analyser tools or code used for decryption?

The agent side is confirming the response is sent. Java side issue pointed earlier also couldn’t be seen as we contacted Oracle. Looks like issue is irrespective of java version.

AGENTPP · March 4, 2022, 8:25am

JDK 11 is not much different in its TLS implementation than a recent JDK 8. If I remember it correctly JDK 15/16 introduced a lot of changes internally and added some debug options.

TLS decryption is the way to go. SNMP over TLS is simply TLS encrypted nothing else. That’s why I do not understand why TLS decryption would fail in your case.

Maybe you can send a larger debug log-file with the full communication starting from the connect to the Key is Writable loop to the AGENTPP support email address. Maybe we do not have identified the root cause in your case yet.

AGENTPP · March 4, 2022, 8:52am

Hi Anjali,

As you repeated that you are unable to decrypt the traffic using TSL decrypt, I thought there might be a general problem.

In the log with the key-is-writable loop above, there are also two lines beginning with “SHA-256…”.
In a TLS communication, SHA-256 must not be used! I think there is a misconfiguration of the Message Protocol. Maybe you are using version 3 (i.e., SNMP based authentication and encryption) instead of version 4 which must be used for (D)TLS.

Best regards,
Frank

anjali.k_m · March 7, 2022, 7:26am

Hi Frank,
Our configs for certificate target is
ct.setVersion(SnmpConstants.version3);
ct.setSecurityModel(SecurityModel.SECURITY_MODEL_TSM);
ct.setSecurityLevel(SecurityLevel.AUTH_PRIV);

Do you recommend to not set security level or were you referring to securityModel which is 4 in our case?

Eitheir of these (SecurityLevel =1 (NOAUTH_NOPRIV) or 3 (AUTH_PRIV), when I checked in detail in wireshark, I see there is a tab for decryptedTLS but that’s not in readable form as a SNMP packet. Am I missing something here to interpret it as SNMP?

AGENTPP · March 7, 2022, 8:02am

Version 3 for the SNMP version is correct, but in addition, the security model must be set to

        ct.setSecurityModel(SecurityModel.SECURITY_MODEL_TSM);

Thus, your initialization seems to be correct, but maybe somewhere later the object is modified, so that the USM model is being used for the communication?
Or is there a bug in the agent, sending the wrong security model in its replies?

Best regards,
Frank

tvikasv · March 19, 2022, 11:02pm

Hi Frank ,

The Write loop issue is now not observed with latest snmp4j 2.8.10 snapshot.

Thank you for the support .

Regards,
Vikas

tvikasv · April 13, 2022, 1:22pm

Hi Frank ,
We are using snmp4j2.8.10 and most of the time we don’t see the looping issue , but some times we do observe the looping .

Let us know if you need complete logs .

Message sent for SocketEntry[peerAddress=135.104.219.84/10161,socket=Socket[addr=135.104.219.84/135.104.219.84,port=10161,localport=46618],lastUse=Tue Jan 20 03:03:07 EST 1970,inNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],inAppBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],outNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],socketTimeout=null]
Dispatching inAppBuffer=java.nio.HeapByteBuffer[pos=0 lim=0 cap=32768]
Key is readable
Key is reading
Read 31 bytes from 135.104.219.84/10161
TLS inNetBuffer: java.nio.HeapByteBuffer[pos=31 lim=32768 cap=32768]
Running delegated task on SocketEntry[peerAddress=135.104.219.84/10161,socket=Socket[addr=135.104.219.84/135.104.219.84,port=10161,localport=46618],lastUse=Tue Jan 20 03:03:09 EST 1970,inNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],inAppBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],outNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],socketTimeout=null]: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 31 bytesProduced = 0
Adding operation 4 for: SocketEntry[peerAddress=135.104.219.84/10161,socket=Socket[addr=135.104.219.84/135.104.219.84,port=10161,localport=46618],lastUse=Tue Jan 20 03:03:09 EST 1970,inNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],inAppBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],outNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],socketTimeout=null]
Key is writable
Sending message with length 74 to 135.104.219.84/10161: 30:48:02:01:03:30:0f:02:02:7b:a8:02:03:00:80:00:04:01:04:02:01:04:04:00:30:30:04:0c:00:00:1d:3b:00:00:00:a1:0a:14:db:54:04:00:a5:1e:02:04:74:a3:c0:a5:02:01:00:02:01:05:30:10:30:0e:06:0a:2b:06:01:06:03:0c:01:02:01:03:05:00
Message sent for SocketEntry[peerAddress=135.104.219.84/10161,socket=Socket[addr=135.104.219.84/135.104.219.84,port=10161,localport=46618],lastUse=Tue Jan 20 03:03:09 EST 1970,inNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],inAppBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],outNetBuffer=java.nio.HeapByteBuffer[pos=31 lim=32768 cap=32768],socketTimeout=null]
Key is writable
Message sent for SocketEntry[peerAddress=135.104.219.84/10161,socket=Socket[addr=135.104.219.84/135.104.219.84,port=10161,localport=46618],lastUse=Tue Jan 20 03:03:09 EST 1970,inNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],inAppBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],outNetBuffer=java.nio.HeapByteBuffer[pos=31 lim=32768 cap=32768],socketTimeout=null]
Key is writable
Message sent for SocketEntry[peerAddress=135.104.219.84/10161,socket=Socket[addr=135.104.219.84/135.104.219.84,port=10161,localport=46618],lastUse=Tue Jan 20 03:03:09 EST 1970,inNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],inAppBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],outNetBuffer=java.nio.HeapByteBuffer[pos=31 lim=32768 cap=32768],socketTimeout=null]
Key is writable
Message sent for SocketEntry[peerAddress=135.104.219.84/10161,socket=Socket[addr=135.104.219.84/135.104.219.84,port=10161,localport=46618],lastUse=Tue Jan 20 03:03:09 EST 1970,inNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],inAppBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],outNetBuffer=java.nio.HeapByteBuffer[pos=31 lim=32768 cap=32768],socketTimeout=null]
Key is writable
Message sent for SocketEntry[peerAddress=135.104.219.84/10161,socket=Socket[addr=135.104.219.84/135.104.219.84,port=10161,localport=46618],lastUse=Tue Jan 20 03:03:09 EST 1970,inNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],inAppBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],outNetBuffer=java.nio.HeapByteBuffer[pos=31 lim=32768 cap=32768],socketTimeout=null]
Key is writable
Message sent for SocketEntry[peerAddress=135.104.219.84/10161,socket=Socket[addr=135.104.219.84/135.104.219.84,port=10161,localport=46618],lastUse=Tue Jan 20 03:03:09 EST 1970,inNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],inAppBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],outNetBuffer=java.nio.HeapByteBuffer[pos=31 lim=32768 cap=32768],socketTimeout=null]
Key is writable
Message sent for SocketEntry[peerAddress=135.104.219.84/10161,socket=Socket[addr=135.104.219.84/135.104.219.84,port=10161,localport=46618],lastUse=Tue Jan 20 03:03:09 EST 1970,inNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],inAppBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],outNetBuffer=java.nio.HeapByteBuffer[pos=31 lim=32768 cap=32768],socketTimeout=null]
Key is writable

AGENTPP · April 13, 2022, 11:13pm

The latest SNMP4J 2.8.11 SNAPSHOT contains a fix for this issue: https://snmp.app/dist/snapshot/org/snmp4j/snmp4j/3.7.0-SNAPSHOT/snmp4j-3.7.0-20220413.231210-6-distribution.zip

tvikasv · April 20, 2022, 7:50pm

Hi Frank ,
We see that there link provided for 2.8.11 is giving 404 error

https://snmp.app/dist/release/org/snmp4j/snmp4j/2.8.11/snmp4j-2.8.11-distribution.zip

AGENTPP · April 20, 2022, 11:28pm

That was an error on the download page. It has been fixed now.

tvikasv · April 21, 2022, 11:38am

Hi Frank ,

Can you please let us know the tentative time line for official availability of SNMP4j 2.8.11 ?

Regards,
Vikas

AGENTPP · April 21, 2022, 11:43am

I expect SNMP4J 2.8.11 to be released on 2022-04-26T22:00:00Z.