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

[Scott Lehman]

My apologies - I think I solved it.  I didn't synchronize around the
creation of the shared Snmp and DefaultUdpTransportMapping instances - duh
:(

After thinking about my statement about seeing two listen threads, I
realized that I must have been doing something wrong and creating two of
them.
Sorry for wasting bandwidth!

Scott

On 6/18/07, Scott Lehman <guitguy69 at gmail.com> wrote:
>
> 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
>
>
>