SNMPv3 TSM TLS 1.3 TCP tmStateReference=null for traps
When receiving several traps at the “same time” some traps are not dispatched :
Dispatching message canceled due to security issue: statusInfo=noError status=1602,tmStateReference=null {}
When the issue occur dispatchMessage is called from processQueues
and checkTransportStateReference is never called therefore tmStateReference is NULL.
For working one dispatchMessage is called from readMessage which call checkTransportStateReference.
It only seems to appear for TLS 1.3 (I’m unable to reproduce it with TLS 1.2)
and when several traps are received
snmp4j version : 3.9.0
JRE : OpenJDK Runtime Environment Temurin-21.0.6+7
Log example :
Handshake....
INFO [TLSTM_0.0.0.0/10162] com.efr.nms.snmpmanager.transport.TLSTM:info:87 - Handshake status = NEED_UNWRAP {}
DEBUG [TLSTM_0.0.0.0/10162] com.efr.nms.snmpmanager.transport.TLSTM:debug:59 - NEED_UNWRAP processing with inNetBuffer=java.nio.HeapByteBuffer[pos=858 lim=32768 cap=32768] {}
DEBUG [TLSTM_0.0.0.0/10162] com.efr.nms.snmpmanager.transport.TLSTM:debug:59 - Running delegated task on SocketEntry[peerAddress=172.31.0.9/40648,socketChannel=java.nio.channels.SocketChannel[connected local=/172.31.0.5:10162 remote=bpl_simu-headend_1-1.efrnms_ip6_net/172.31.0.9:40648],lastUse=Sun Jan 04 15:00:39 GMT 1970,inNetBuffer=java.nio.HeapByteBuffer[pos=757 lim=32768 cap=32768],inAppBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],outAppBuffer=null,outNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],socketTimeout=null]: Status = OK HandshakeStatus = NEED_TASK
bytesConsumed = 101 bytesProduced = 0 {}
DEBUG [TLSTM_0.0.0.0/10162] com.efr.nms.snmpmanager.transport.TLSTM:debug:59 - Running delegated task... {}
INFO [TLSTM_0.0.0.0/10162] com.efr.nms.snmpmanager.transport.TLSTM:info:87 - Handshake status = NEED_UNWRAP {}
DEBUG [TLSTM_0.0.0.0/10162] com.efr.nms.snmpmanager.transport.TLSTM:debug:59 - NEED_UNWRAP processing with inNetBuffer=java.nio.HeapByteBuffer[pos=757 lim=32768 cap=32768] {}
DEBUG [TLSTM_0.0.0.0/10162] jdk.event.security:log:-1 - TLSHandshake: bpl_simu-headend_1-1.efrnms_ip6_net:40648, TLSv1.3, TLS_AES_128_GCM_SHA256, 2751604593 {}
DEBUG [TLSTM_0.0.0.0/10162] com.efr.nms.snmpmanager.transport.TLSTM:debug:59 - Running delegated task on SocketEntry[peerAddress=172.31.0.9/40648,socketChannel=java.nio.channels.SocketChannel[connected local=/172.31.0.5:10162 remote=bpl_simu-headend_1-1.efrnms_ip6_net/172.31.0.9:40648],lastUse=Sun Jan 04 15:00:39 GMT 1970,inNetBuffer=java.nio.HeapByteBuffer[pos=699 lim=32768 cap=32768],inAppBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],outAppBuffer=null,outNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],socketTimeout=null]: Status = OK HandshakeStatus = NEED_WRAP
bytesConsumed = 58 bytesProduced = 0 {}
DEBUG [TLSTM_0.0.0.0/10162] com.efr.nms.snmpmanager.transport.TLSTM:debug:59 - TLS outNetBuffer = java.nio.HeapByteBuffer[pos=0 lim=4134 cap=32768] {}
DEBUG [TLSTM_0.0.0.0/10162] com.efr.nms.snmpmanager.transport.TLSTM:debug:59 - Running delegated task on SocketEntry[peerAddress=172.31.0.9/40648,socketChannel=java.nio.channels.SocketChannel[connected local=/172.31.0.5:10162 remote=bpl_simu-headend_1-1.efrnms_ip6_net/172.31.0.9:40648],lastUse=Sun Jan 04 15:00:39 GMT 1970,inNetBuffer=java.nio.HeapByteBuffer[pos=699 lim=32768 cap=32768],inAppBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],outAppBuffer=null,outNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],socketTimeout=null]: Status = OK HandshakeStatus = FINISHED
bytesConsumed = 0 bytesProduced = 4134 sequenceNumber = 0 {}
DEBUG [TLSTM_0.0.0.0/10162] com.efr.nms.snmpmanager.transport.TLSTM:debug:59 - TLS handshake finished {}
DEBUG [TLSTM_0.0.0.0/10162] com.efr.nms.snmpmanager.transport.TLSTM:debug:59 - TLS inNetBuffer = java.nio.HeapByteBuffer[pos=0 lim=699 cap=32768] {}
DEBUG [TLSTM_0.0.0.0/10162] com.efr.nms.snmpmanager.transport.TLSTM:debug:59 - Running delegated task on SocketEntry[peerAddress=172.31.0.9/40648,socketChannel=java.nio.channels.SocketChannel[connected local=/172.31.0.5:10162 remote=bpl_simu-headend_1-1.efrnms_ip6_net/172.31.0.9:40648],lastUse=Sun Jan 04 15:00:39 GMT 1970,inNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],inAppBuffer=java.nio.HeapByteBuffer[pos=677 lim=32768 cap=32768],outAppBuffer=null,outNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],socketTimeout=null]: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 699 bytesProduced = 677 {}
DEBUG [TLSTM_0.0.0.0/10162] com.efr.nms.snmpmanager.transport.TLSTM:debug:59 - Dispatching inAppBuffer=java.nio.HeapByteBuffer[pos=0 lim=677 cap=32768] {}
DEBUG [TLSTM_0.0.0.0/10162] com.efr.nms.snmpmanager.transport.TLSTM:debug:59 - Received message from 172.31.0.9/40648 with length 677: 30:82:02:a1:02:01:03:30:11:02:04:27:37:3d:86:02:03:00:ff:e3:04:01:03:02:01:04:04:00:30:82:02:85:04:11:80:00:1f:88:80:6b:56:44:3e:75:50:bc:67:00:00:00:00:04:00:a7:82:02:6c:02:04:71:0b:2d:6e:02:01:00:02:01:00:30:82:02:5c:30:10:06:08:2b:06:01:02:01:01:03:00:43:04:01:dd:f7:4b:30:20:06:0a:2b:06:01:06:03:01:01:04:01:00:06:12:2b:06:01:04:01:83:c3:66:83:4d:00:81:10:02:01:01:01:00:30:1d:06:13:2b:06:01:04:01:83:c3:66:83:4d:00:81:10:03:01:02:01:01:00:04:06:00:17:41:15:00:00:30:25:06:11:2b:06:01:04:01:83:c3:66:83:4d:00:81:10:06:01:02:00:04:10:45:45:46:52:30:30:31:37:34:31:31:35:30:30:30:30:30:18:06:13:2b:06:01:04:01:83:c3:66:83:4d:00:81:10:02:01:01:02:01:00:42:01:0c:30:19:06:11:2b:06:01:04:01:83:c3:66:83:4d:00:81:10:07:04:01:00:04:04:ac:1f:00:09:30:25:06:11:2b:06:01:04:01:83:c3:66:83:4d:00:81:10:07:04:02:00:04:10:fd:00:de:ad:be:ef:ca:fe:fa:ce:ab:ba:ba:ba:00:70:30:18:06:13:2b:06:01:04:01:83:c3:66:83:4d:00:81:10:03:01:02:02:01:00:42:01:08:30:1a:06:13:2b:06:01:04:01:83:c3:66:83:4d:00:81:10:03:01:02:02:02:00:42:03:00:bf:27:30:1a:06:13:2b:06:01:04:01:83:c3:66:83:4d:00:81:10:03:01:02:02:03:00:42:03:00:83:c0:30:19:06:13:2b:06:01:04:01:83:c3:66:83:4d:00:81:10:03:01:02:02:04:00:04:02:45:55:30:1d:06:13:2b:06:01:04:01:83:c3:66:83:4d:00:81:10:03:01:02:02:05:00:04:06:00:17:41:15:00:00:30:19:06:11:2b:06:01:04:01:83:c3:66:83:4d:00:81:10:06:01:05:00:04:04:45:45:46:52:30:19:06:11:2b:06:01:04:01:83:c3:66:83:4d:00:81:10:06:01:06:00:04:04:45:45:46:52:30:1f:06:11:2b:06:01:04:01:83:c3:66:83:4d:00:81:10:06:01:07:00:04:0a:53:47:43:2d:42:50:4c:2d:48:45:30:2e:06:11:2b:06:01:04:01:83:c3:66:83:4d:00:81:10:04:01:01:00:04:19:53:47:43:2d:42:50:4c:2d:48:45:2d:30:31:5f:76:31:2e:30:2e:30:5f:50:52:4f:44:30:22:06:11:2b:06:01:04:01:83:c3:66:83:4d:00:81:10:06:01:08:00:04:0d:73:69:6d:75:20:68:61:72:64:77:61:72:65:30:17:06:12:2b:06:01:04:01:83:c3:66:83:4d:00:81:10:0d:01:01:01:00:42:01:00:30:18:06:12:2b:06:01:04:01:83:c3:66:83:4d:00:81:10:0d:01:01:02:00:42:02:27:b1:30:1a:06:12:2b:06:01:04:01:83:c3:66:83:4d:00:81:10:0d:01:01:03:00:04:04:20:00:00:00 {}
DEBUG [TLSTM_0.0.0.0/10162] org.snmp4j.transport.AbstractTransportServerThread:debug:59 - Key is readable {}
DEBUG [TLSTM_0.0.0.0/10162] org.snmp4j.transport.AbstractTransportServerThread:debug:59 - Key is reading {}
DEBUG [TLSTM_0.0.0.0/10162] com.efr.nms.snmpmanager.transport.TLSTM:debug:59 - Read 24 bytes from 172.31.0.9/40648 {}
DEBUG [DispatcherPool.0] org.snmp4j.mp.MPv3:debug:59 - SNMPv3 header decoded: msgId=657931654, msgMaxSize=65507, msgFlags=03, secModel=4 {}
DEBUG [TLSTM_0.0.0.0/10162] com.efr.nms.snmpmanager.transport.TLSTM:debug:59 - TLS inNetBuffer: java.nio.HeapByteBuffer[pos=24 lim=32768 cap=32768] {}
DEBUG [DispatcherPool.0] org.snmp4j.mp.MPv3:debug:59 - PduHandle for messageID 657931654 not found in MPv3.Cache {}
DEBUG [TLSTM_0.0.0.0/10162] com.efr.nms.snmpmanager.transport.TLSTM:debug:59 - Running delegated task on SocketEntry[peerAddress=172.31.0.9/40648,socketChannel=java.nio.channels.SocketChannel[connected local=/172.31.0.5:10162 remote=bpl_simu-headend_1-1.efrnms_ip6_net/172.31.0.9:40648],lastUse=Sun Jan 04 15:00:39 GMT 1970,inNetBuffer=java.nio.HeapByteBuffer[pos=24 lim=24 cap=32768],inAppBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],outAppBuffer=null,outNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],socketTimeout=null]: Status = CLOSED HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 24 bytesProduced = 0 {}
DEBUG [TLSTM_0.0.0.0/10162] org.snmp4j.transport.AbstractSocketEntry:debug:59 - Removed operation(s) [READ] for: SocketEntry[peerAddress=172.31.0.9/40648,socketChannel=java.nio.channels.SocketChannel[connected local=/172.31.0.5:10162 remote=bpl_simu-headend_1-1.efrnms_ip6_net/172.31.0.9:40648],lastUse=Sun Jan 04 15:00:39 GMT 1970,inNetBuffer=java.nio.HeapByteBuffer[pos=24 lim=24 cap=32768],inAppBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],outAppBuffer=null,outNetBuffer=java.nio.HeapByteBuffer[pos=0 lim=32768 cap=32768],socketTimeout=null] {}
INFO [TLSTM_0.0.0.0/10162] com.efr.nms.snmpmanager.transport.TLSTM:info:87 - TLS connection to 172.31.0.9/40648 is closed {}
DEBUG [TLSTM_0.0.0.0/10162] org.snmp4j.transport.AbstractTransportMapping:debug:59 - Firing transport state event: org.snmp4j.transport.TransportStateEvent[[source=com.efr.nms.snmpmanager.transport.TLSTM@7c840fe3,peerAddress=172.31.0.9/40648,newState=4,cancelled=false,causingException=null](mailto:source=com.efr.nms.snmpmanager.transport.TLSTM@7c840fe3,peerAddress=172.31.0.9/40648,newState=4,cancelled=false,causingException=null)] {}
INFO [DispatcherPool.0] org.snmp4j.MessageDispatcherImpl:info:87 - Dispatching message canceled due to security issue: statusInfo=noError, status=1602,tmStateReference=null {}