Intermittent java.lang.InterruptedException

nibor · January 22, 2021, 2:50pm

Hello,

I’m working with snmp4j-agent 2.6.3 on java 8.

We have a software running multi-threaded snmp requests.

As shown in the following logs, sometime we have an incorrect execution résulting in a snmp call immediately aborted and returning null response :

2021-01-21 15:49:10,729 DEBUG org.snmp4j.Snmp  - Running pending sync request with handle PduHandle[444141018] and retry count left 1
2021-01-21 15:49:10,729 DEBUG org.snmp4j.transport.DefaultUdpTransportMapping  - Sending message to <IP_ADDRESS>/161 with length 65: <MESSAGE>
2021-01-21 15:49:10,729 WARN org.snmp4j.Snmp  - java.lang.InterruptedException
2021-01-21 15:49:10,729 DEBUG org.snmp4j.transport.DefaultUdpTransportMapping  - Terminated worker task: org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
2021-01-21 15:49:10,730 DEBUG org.snmp4j.transport.DefaultUdpTransportMapping  - Interrupting worker task: org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
2021-01-21 15:49:10,730 DEBUG org.snmp4j.transport.DefaultUdpTransportMapping  - Joining worker task: org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
2021-01-21 15:49:10,730 WARN org.snmp4j.transport.DefaultUdpTransportMapping  - java.lang.InterruptedException

The timeout is set at 5seconds.

I also tried the 2.7.4 snmp4j-agent with same behaviour.

I do not succeed troubleshooting this issue, as I have not been able to reproduce it locally.

Does someone has an idea why the request is immediately aborted with this java.lang.InterruptedException ?

Thanks,

Robin.

AGENTPP · January 22, 2021, 10:45pm

Hi Robin,

It seems that you are closing the Snmp session before the request’s response has been received.
But without seeing your code, it is just guessing.

Best regards,
Frank

nibor · January 25, 2021, 11:11am

Thanks for your response,

The code is quite old spaghetti code. I need to rework it to be easily readable.

We are performing lots of multi-threaded snmp requests, 100K+ every 5 minutes. It’s running fine most of the time, but sometime (4 or 5 times per day over 288) the answer to our snmp request is null.

The issue is happening with different oids against different hosts.

We took one snmp request that was regularly failing with null response and created another program performing the same request against the same host every second. When we are hitting the null response in production program, the test program successfully get the correct response.

For each thread, a single Snmp session is used, initiallized at the begining of the thread and closed after the job is done. This is repeated given the frequency (5 minutes).
This code is synchronous and wait for the response before closing the session.

It’s weird to me that in this synchronous world sometime the snmp session will be closed while a pending request is still here.

Here is a log of snmp4j warn messages showing that we have this InterruptedException in different threads at the same timing (2021-01-21 15:49:10) :

2021-01-21 15:48:31,093 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,094 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,094 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,094 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,758 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,772 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,775 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,777 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,778 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,778 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,778 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,779 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,780 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,781 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,782 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,783 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,783 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,804 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,807 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,817 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,824 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,830 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,836 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,841 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,843 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,846 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,846 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,850 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,852 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,859 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,862 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,870 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,874 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,881 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:31,890 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:32,314 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:32,393 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:32,406 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:32,412 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:32,413 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:32,421 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:32,429 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:32,432 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:32,433 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:32,435 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:32,435 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:32,436 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:32,437 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:32,440 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,155 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,157 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,158 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,159 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,160 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,161 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,162 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,166 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,166 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,166 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,167 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,167 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,169 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,171 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,174 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,176 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,177 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,180 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,181 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,185 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,188 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,193 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,195 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,195 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,196 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,197 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,199 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,201 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,206 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,209 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,211 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:34,214 [pping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=noError, status=-1409
2021-01-21 15:48:57,212 [pping_0.0.0.0/0] WARN org.snmp4j.Snmp - Received response that cannot be matched to any outstanding request, address=10.49.66.118/161, requestID=1639162976
2021-01-21 15:49:10,278 [obeExecutor4346] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,278 [obeExecutor4343] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,278 [obeExecutor4344] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,278 [obeExecutor4347] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,279 [obeExecutor4347] WARN org.snmp4j.transport.DefaultUdpTransportMapping - java.lang.InterruptedException
2021-01-21 15:49:10,321 [obeExecutor6157] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,322 [obeExecutor5912] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,323 [obeExecutor5903] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,322 [obeExecutor5938] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,322 [obeExecutor6001] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,322 [obeExecutor6014] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,322 [obeExecutor6015] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,322 [obeExecutor6016] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,322 [obeExecutor6018] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,322 [obeExecutor6017] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,322 [obeExecutor6019] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,321 [obeExecutor6028] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,324 [obeExecutor5774] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,321 [obeExecutor6034] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,321 [obeExecutor6035] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,324 [obeExecutor6034] WARN org.snmp4j.transport.DefaultUdpTransportMapping - java.lang.InterruptedException
2021-01-21 15:49:10,321 [obeExecutor6044] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,321 [obeExecutor6047] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,321 [obeExecutor6057] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,321 [obeExecutor6079] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,321 [obeExecutor6083] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,321 [obeExecutor6086] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,321 [obeExecutor6108] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,321 [obeExecutor6129] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,321 [obeExecutor6152] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,322 [obeExecutor5910] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,326 [obeExecutor6152] WARN org.snmp4j.transport.DefaultUdpTransportMapping - java.lang.InterruptedException
2021-01-21 15:49:10,326 [obeExecutor5585] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,326 [obeExecutor5573] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,326 [obeExecutor5573] WARN org.snmp4j.transport.DefaultUdpTransportMapping - java.lang.InterruptedException
2021-01-21 15:49:10,327 [obeExecutor5429] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,328 [obeExecutor5416] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,328 [obeExecutor5382] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,328 [obeExecutor5429] WARN org.snmp4j.transport.DefaultUdpTransportMapping - java.lang.InterruptedException
2021-01-21 15:49:10,328 [obeExecutor5363] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,332 [obeExecutor5018] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,332 [obeExecutor5001] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,332 [obeExecutor5018] WARN org.snmp4j.transport.DefaultUdpTransportMapping - java.lang.InterruptedException
2021-01-21 15:49:10,344 [obeExecutor4755] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,345 [obeExecutor5416] WARN org.snmp4j.transport.DefaultUdpTransportMapping - java.lang.InterruptedException
2021-01-21 15:49:10,345 [obeExecutor5572] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,346 [obeExecutor5795] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,347 [obeExecutor5864] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,347 [obeExecutor6002] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,347 [obeExecutor6011] WARN org.snmp4j.Snmp - java.lang.InterruptedException
2021-01-21 15:49:10,391 [obeExecutor5774] WARN org.snmp4j.transport.DefaultUdpTransportMapping - java.lang.InterruptedException
2021-01-21 15:49:10,426 [obeExecutor4755] WARN org.snmp4j.transport.DefaultUdpTransportMapping - java.lang.InterruptedException
2021-01-21 15:49:10,522 [obeExecutor5382] WARN org.snmp4j.transport.DefaultUdpTransportMapping - java.lang.InterruptedException

I imagine that it is hard to guess without code, but do you have any starting point to debug this issue ? I’m not able to reproduce it locally at the moment…

Thanks, Robin.

AGENTPP · January 25, 2021, 9:56pm

First, you should change your architecture.

Creating and closing a Snmp instance continuously is a tremendous overhead. Problematic is the time a socket is being created and closed.
In your code, in addition there is a problem with the synchronization too (otherwise the exceptions won’t occur).

In any case, simply use a single Snmp instance with asynchronous request processing and use a multi-threaded message dispatcher or parallelize with other means your response processing.

Hope this helps. (It helped many other users in the past )

nibor · January 26, 2021, 6:28am

Thanks for your answer.

I will try to keep the same Snmp instance and check if its better.

Could you explain a bit what do you mean by a synchronization issue ?

AGENTPP · January 27, 2021, 10:31am

With the synchronization issue I meant the fact that you close Snmp sessions while there are outstanding requests. For me that looks like sessions are closed just after having sent the request but before the response has been received (or the request timed out).