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