Null packet corrupts snmp4j CommandResponder

Hi Everyone,

I am using snpm4j to send/receive snmp traps and messages and run into a problem.
Following the tutorial implemented my class which is implementing CommandResponder
@Override
public void processPdu(CommandResponderEvent event) {
PDU pdu = event.getPDU();
log.info(“received {}”, pdu);
}

Than I am using linux command to send traps.

COMMON="-l authPriv -u user -a MD5 -A password -x DES -X password tcp:127.0.0.1:1161"
snmptrap ${COMMON} ‘’ 1.3.6.1.4.1.19406.1.2.1 1.3.6.1.4.1.19406.1.1.2.1 s ‘test’

OID is an rsyslog OID but it does not matter. What matters very much is tcp protocol.
The code logs the packets perfectly.

Until sending a null packet to the trap receiver corrupts the receiver but without any error or exception. Below nc command is netcat-openbsd on Ubuntu 20.04.2 LTS version 1.206-1ubuntu1

nc -z -v localhost 1161

After this nc command - probably has to be executed multiple times - snmptrap commands are not working anymore. No more packet log is generated. The socket is left on linux in CLOSE_WAIT and that is it. I have to restart the application completely.

Not sure whether I am missing something or not but could not find a solution to this. Besides it looks very strange that when this happens the TCP communication is done properly as I can see. So snmptrap command can send the packet and tcp ack is sent back by snmp4j. But my application does not receive anything.

If anybody could help I would appreciate it.

Hi,

The execution of the nc command will cause a parsing error on the receiver side, because an invalid SNMP packet is received then. With UDP the receiver can easily drop incorrect packets completely. With TCP there is a stream of bytes without packet delimitation on transport level.

Please check the DEBUG go of the command responder to find out what is happening in detail. Most likely the command responder closes the TCP connection but somehow, a reopening fails. The reason for that should be found in the log.

Best regards,
Frank

Hi Frank,

Based on this https://doc.snmp.app/pages/viewpage.action?pageId=27459590 I have below code part to enable debug (not 100% sure this is correct anyway):
static {
LogFactory.setLogFactory(new ConsoleLogFactory());
ConsoleLogAdapter.setDebugEnabled(true);
}

But with that code all I got in my spring boot app was:

. ____ _ __ _ _
/\ / __ _ () __ __ _ \ \ \
( ( )_
_ | '_ | '| | ’ / ` | \ \ \
\/ )| |)| | | | | || (| | ) ) ) )
’ |
| .__|| ||| |_, | / / / /
=========|
|==============|/=////
:: Spring Boot :: (v2.4.5)

2021-04-29 01:13:55.755 INFO 39928 — [ main] com.tamastarjanyi.snmp4j.Main : Starting Main using Java 11.0.11 on ttarjany-tp with PID 39928 (/home/ttarjany/IdeaProjects/snmp4j/target/classes started by ttarjany in /home/ttarjany/IdeaProjects/snmp4j)
2021-04-29 01:13:55.757 INFO 39928 — [ main] com.tamastarjanyi.snmp4j.Main : No active profile set, falling back to default profiles: default
2021-04-29 01:13:56.474 INFO 39928 — [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)
2021-04-29 01:13:56.479 INFO 39928 — [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2021-04-29 01:13:56.479 INFO 39928 — [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.45]
2021-04-29 01:13:56.513 INFO 39928 — [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2021-04-29 01:13:56.513 INFO 39928 — [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 715 ms
2021-04-29 01:13:56.548 INFO 39928 — [ main] c.t.snmp4j.SnmpTrapReceiverService : init()
2021-04-29 01:13:56.566 main DEBUG Initialized Salt to 62e27535bbfed65f.
2021-04-29 01:13:56.586 main DEBUG Adding user user = UsmUser[secName=user,authProtocol=1.3.6.1.6.3.10.1.1.2,authPassphrase=password,privProtocol=1.3.6.1.6.3.10.1.2.2,privPassphrase=password,localizationEngineID=null]
2021-04-29 01:13:56.586 INFO 39928 — [ main] c.t.snmp4j.SnmpTrapReceiverService : Listening…
2021-04-29 01:13:56.592 main INFO TCP address 0.0.0.0/1161 bound successfully
2021-04-29 01:13:56.681 INFO 39928 — [ main] o.s.s.concurrent.ThreadPoolTaskExecutor : Initializing ExecutorService ‘applicationTaskExecutor’
2021-04-29 01:13:56.802 INFO 39928 — [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ‘’
2021-04-29 01:13:56.812 INFO 39928 — [ main] com.tamastarjanyi.snmp4j.Main : Started Main in 1.371 seconds (JVM running for 1.832)
2021-04-29 01:14:07.510 DefaultTCPTransportMapping_0.0.0.0/1161 DEBUG Key is acceptable
2021-04-29 01:14:07.524 DefaultTCPTransportMapping_0.0.0.0/1161 DEBUG Adding operation 1 for: SocketEntry[peerAddress=127.0.0.1/54460,socket=Socket[addr=/127.0.0.1,port=54460,localport=1161],lastUse=Thu Jan 01 03:23:05 CET 1970,readBufferPosition=-1,socketTimeout=null]
2021-04-29 01:14:07.539 DefaultTCPTransportMapping_0.0.0.0/1161 DEBUG Firing transport state event: org.snmp4j.transport.TransportStateEvent[source=org.snmp4j.transport.DefaultTcpTransportMapping@1744a475,peerAddress=127.0.0.1/54460,newState=1,cancelled=false,causingException=null]
2021-04-29 01:14:07.539 DefaultTCPTransportMapping_0.0.0.0/1161 DEBUG Key is reading
2021-04-29 01:14:07.543 DefaultTCPTransportMapping_0.0.0.0/1161 DEBUG Reading header -1 bytes from 127.0.0.1/54460
2021-04-29 01:14:07.543 DefaultTCPTransportMapping_0.0.0.0/1161 DEBUG Socket closed remotely
2021-04-29 01:14:07.544 DefaultTCPTransportMapping_0.0.0.0/1161 DEBUG Firing transport state event: org.snmp4j.transport.TransportStateEvent[source=org.snmp4j.transport.DefaultTcpTransportMapping@1744a475,peerAddress=127.0.0.1/54460,newState=2,cancelled=false,causingException=null]
2021-04-29 01:15:07.525 Timer-0 DEBUG Scheduling 1619651827509

Ok, what SNMP4J version are you using?

Maybe you need to implement a TransportStateEvent handler in order to reopen/reinit the transport mapping?

The above log was generated with snmp4j 3.4.4 but same behaviour was observed with older versions like 3.4.3. Can you provide some info regarding this TransportStateEvent handler usage?

Have done some further in depth analysis on this issue: with SNMP4J-Agent the DefaultTcpTransportMapping works as expected in server mode.

Unfortunately there seems to be indeed an issue with SNMP4J 3.4.4 alone. I will report here when I have found the reason.

OK, this behaviour is indeed a bug (why it does not affect SNMP4J-Agent is still unclear). To fix it, remove the three occurrences of

sk.cancel();

in DefaultTcpTransportMapping.java with cancelNonServerSelectionKey(sk); add add that method to the class:

protected void cancelNonServerSelectionKey(SelectionKey sk) {
    if (!sk.isAcceptable()) {
        sk.cancel();
    }
}

As you can see from the patch, it avoids canceling the server port selection key registered for ACCEPT.

Dear Frank,

May I ask you if you plan to make an official release for this bug? As of now we have a problem to release our code based on the snmp4j library since a port scanner or some protocol fuzzer is killing our app in a second.

Thank you very much.

An official release will be available on 2021-05-09T22:00:00Z

1 Like