[SNMP4J] Problem going multi-threaded - responses don't match outstanding requests

[Scott Lehman]

Hi All,
I've been using snmp4j for a few months to talk to a number of agents in the
context of a single thread (works great!), but I'm having problems using
multiple threads to perform actions on the network devices in parallel.

I'm trying to use a single shared Snmp instance with a
DefaultUdpTransportMapping.  I have an ExecutorService thread pool that
performs get/sets using synchronous calls on the shared Snmp instance.  With
a thread pool size of 1, things are fine, but with anything higher,
responses always timeout.

The timeout is 3 seconds and the response arrives well within that.  I've
tried setting retries to 0 as well.  The only way I've been able to get it
to work with multiple threads going is to create separate Snmp and
TransportMapping instances for each agent which I'm trying to avoid.

Do I need to do something else when sharing an Snmp instance across threads?
 I've observed a number of DefaultUdpTransportMapping$ListenThreads equal to
the number of threads in my pool - is that correct behavior?

Some log output from runs with 1 and 2 threads are below.  The OS is Windows
XP.

Thanks,

Scott


Here's logging from the single thread run:

[2007-06-18T13:02:58.250-0700] [INFO ]
[DefaultUDPTransportMapping_10.1.1.99/0] [Log4jLogAdapter:info:?] UDP
receive buffer size for socket 10.1.1.99/0 is set to: 8192
[2007-06-18T13:02:58.453-0700] [DEBUG] [pool-3-thread-1]
[Log4jLogAdapter:debug:?] Running pending sync request with handle
PduHandle[1930684020] and retry count left 2
[2007-06-18T13:02:58.453-0700] [DEBUG] [pool-3-thread-1]
[Log4jLogAdapter:debug:?] Sending message to 10.1.1.101/161 with length 48:
30:2e:02:01:00:04:07:70:72:69:76:61:74:65:a0:20:02:04:73:13:e6:74:02:01:00:02:01:00:30:12:30:10:06:0c:2b:06:01:04:01:94:78:01:01:01:01:00:05:00
[2007-06-18T13:02:58.468-0700] [DEBUG]
[DefaultUDPTransportMapping_10.1.1.99/0] [Log4jLogAdapter:debug:?] Received
message from /10.1.1.101/161 with length 52:
30:32:02:01:00:04:07:70:72:69:76:61:74:65:a2:24:02:04:73:13:e6:74:02:01:00:02:01:00:30:16:30:14:06:0c:2b:06:01:04:01:94:78:01:01:01:01:00:02:04:00:00:00:02
[2007-06-18T13:02:58.468-0700] [DEBUG]
[DefaultUDPTransportMapping_10.1.1.99/0] [Log4jLogAdapter:debug:?] Looking
up pending request with handle PduHandle[1930684020]
[2007-06-18T13:02:58.468-0700] [DEBUG] [pool-3-thread-1]
[Log4jLogAdapter:debug:?] Removed pending request with handle:
PduHandle[1930684020]




And from another run with two threads in the pool:

[2007-06-18T12:56:45.053-0700] [INFO ]
[DefaultUDPTransportMapping_10.1.1.99/0] [Log4jLogAdapter:info:?] UDP
receive buffer size for socket 10.1.1.99/0 is set to: 8192
[2007-06-18T12:56:45.053-0700] [INFO ]
[DefaultUDPTransportMapping_10.1.1.99/0] [Log4jLogAdapter:info:?] UDP
receive buffer size for socket 10.1.1.99/0 is set to: 8192
[2007-06-18T12:56:45.115-0700] [DEBUG] [pool-3-thread-2]
[Log4jLogAdapter:debug:?] Running pending sync request with handle
PduHandle[1251976792] and retry count left 2
[2007-06-18T12:56:45.115-0700] [DEBUG] [pool-3-thread-2]
[Log4jLogAdapter:debug:?] Sending message to 10.1.1.101/161 with length 48:
30:2e:02:01:00:04:07:70:72:69:76:61:74:65:a0:20:02:04:4a:9f:a6:58:02:01:00:02:01:00:30:12:30:10:06:0c:2b:06:01:04:01:94:78:01:01:01:01:00:05:00
[2007-06-18T12:56:45.115-0700] [DEBUG]
[DefaultUDPTransportMapping_10.1.1.99/0] [Log4jLogAdapter:debug:?] Received
message from /10.1.1.101/161 with length 52:
30:32:02:01:00:04:07:70:72:69:76:61:74:65:a2:24:02:04:4a:9f:a6:58:02:01:00:02:01:00:30:16:30:14:06:0c:2b:06:01:04:01:94:78:01:01:01:01:00:02:04:00:00:00:02
[2007-06-18T12:56:45.131-0700] [DEBUG]
[DefaultUDPTransportMapping_10.1.1.99/0] [Log4jLogAdapter:debug:?] Looking
up pending request with handle PduHandle[1251976792]
[2007-06-18T12:56:45.131-0700] [WARN ]
[DefaultUDPTransportMapping_10.1.1.99/0] [Log4jLogAdapter:warn:?] Received
response that cannot be matched to any outstanding request, address=
10.1.1.101/161, requestID=1251976792
[2007-06-18T12:56:45.131-0700] [WARN ]
[DefaultUDPTransportMapping_10.1.1.99/0] [Log4jLogAdapter:warn:?] Received
response that cannot be matched to any outstanding request, address=
10.1.1.101/161, requestID=1251976792
[2007-06-18T12:56:45.131-0700] [ERROR]
[DefaultUDPTransportMapping_10.1.1.99/0] [Log4jLogAdapter:error:?]
java.io.IOException: Unexpected end of input stream at position 52