[SNMP4J] strange problem

Wed Mar 11 21:33:48 CET 2009

Hi Peirong,

The timeout occurs because you send a sync
request from a async callback. BTW, using
the MultiThreadedMessageDispatcher would
not help here.

Just, use an async call within the callback
instead.

Best regards,
Frank

Peirong Feng (pefeng) wrote:
> Hi Frank,
> 
> The library is the latest one 1.9.3b. The second snmp4j call is in the
> callback, but the callback will call " PDU req = event.getRequest();
> PDU resp = event.getResponse();  ((Snmp)event.getSource()).cancel(req,
> this);" first. 
> 
> Is the timeout error caused by the fact that the second call is inside
> the callback and I'm reusing the Snmp and Target objects?
> 
> Peirong
> 
> -----Original Message-----
> From: Frank Fock [mailto:fock at agentpp.com] 
> Sent: Saturday, March 07, 2009 1:24 AM
> To: Peirong Feng (pefeng)
> Cc: snmp4j at agentpp.org
> Subject: Re: [SNMP4J] strange problem
> 
> Hi,
> 
> What version of SNMP4J are you using?
> What is your question?
> Does your async callback routine return
> immediately?
> 
> Best regards,
> Frank
> 
> Peirong Feng (pefeng) wrote:
>> Hi there,
>>
>> My program reads from switch with an asynchronous call followed with
>> sychronous call. The async call went fine but the sync call timed out,
>> and then snmp4j lib reports the reply from switch. The tcpdump shows
>> that the reply came back immediately. I'm reusing the target object
> and
>> snmp object here.
>>
>> Attached is the tcpdump packet trace and the log I got:
>>
>> ------FIRST ASYNC CALL
>> 2009-03-06 19:52:29.336 -0430 INFO
>> org.snmp4j.transport.DefaultUdpTransportMapping    - UDP receive
> buffer
>> size for socket 10.201.2.16/0 is set to: 56320
>> 2009-03-06 19:52:29.388 -0430 DEBUG org.snmp4j.Snmp
>> - Running pending async request with handle PduHandle[665093246] and
>> retry count left 1
>> 2009-03-06 19:52:29.388 -0430 DEBUG
>> org.snmp4j.transport.DefaultUdpTransportMapping    - Sending message
> to
>> 10.201.15.5/161 with length 104:
>>
> 30:66:02:01:01:04:07:6e:74:5f:72:65:61:64:a0:58:02:04:27:a4:84:7e:02:01:
> 00:02:01:00:30:4a:30:0f:06:0b:2b:06:01:02:01:1f:01:01:01:01:02:05:00:30:
> 11:06:0d:2b:06:01:04:01:91:60:01:03:03:01:07:02:05:00:30:11:06:0d:2b:06:
> 01:04:01:91:60:01:03:03:01:03:02:05:00:30:11:06:0d:2b:06:01:04:01:91:60:
>> 01:03:03:01:04:02:05:00
>> 2009-03-06 19:52:29.395 -0430 DEBUG
>> org.snmp4j.transport.DefaultUdpTransportMapping    - Received message
>> from /10.201.15.5/161 with length 132:
>>
> 30:81:81:02:01:01:04:07:6e:74:5f:72:65:61:64:a2:73:02:04:27:a4:84:7e:02:
> 01:00:02:01:00:30:65:30:25:06:0b:2b:06:01:02:01:1f:01:01:01:01:02:04:16:
> 69:66:63:32:20:28:53:6c:6f:74:3a:20:31:20:50:6f:72:74:3a:20:32:29:30:13:
> 06:0d:2b:06:01:04:01:91:60:01:03:03:01:07:02:02:02:00:97:30:13:06:0d:2b:
> 06:01:04:01:91:60:01:03:03:01:03:02:04:02:00:97:30:12:06:0d:2b:06:01:04:
>> 01:91:60:01:03:03:01:04:02:02:01:01
>> 2009-03-06 19:52:29.396 -0430 DEBUG org.snmp4j.Snmp
>> - Looking up pending request with handle PduHandle[665093246]
>> 2009-03-06 19:52:29.396 -0430 DEBUG org.snmp4j.Snmp
>> - Cancelling pending request with handle PduHandle[665093246]
>>
>> ------SECOND SYNC CALL
>> 2009-03-06 19:52:29.397 -0430 DEBUG org.snmp4j.Snmp
>> - Running pending sync request with handle PduHandle[665093248] and
>> retry count left 1
>> 2009-03-06 19:52:29.397 -0430 DEBUG
>> org.snmp4j.transport.DefaultUdpTransportMapping    - Sending message
> to
>> 10.201.15.5/161 with length 50:
>>
> 30:30:02:01:01:04:07:6e:74:5f:72:65:61:64:a0:22:02:04:27:a4:84:80:02:01:
> 00:02:01:00:30:14:30:12:06:0e:2b:06:01:04:01:91:60:01:03:02:01:0b:81:17:
>> 05:00
>> ------SECOND SYNC CALL RETRY (5 seconds later)
>> 2009-03-06 19:52:34.398 -0430 DEBUG org.snmp4j.Snmp
>> - Running pending sync request with handle PduHandle[665093248] and
>> retry count left 0
>> 2009-03-06 19:52:34.398 -0430 DEBUG
>> org.snmp4j.transport.DefaultUdpTransportMapping    - Sending message
> to
>> 10.201.15.5/161 with length 50:
>>
> 30:30:02:01:01:04:07:6e:74:5f:72:65:61:64:a0:22:02:04:27:a4:84:80:02:01:
> 00:02:01:00:30:14:30:12:06:0e:2b:06:01:04:01:91:60:01:03:02:01:0b:81:17:
>> 05:00
>> ------SECOND SYNC CALL TIMED OUT (another 5 seconds later)
>> 2009-03-06 19:52:39.400 -0430 DEBUG org.snmp4j.Snmp
>> - Request timed out: 665093248
>> 2009-03-06 19:52:39.400 -0430 DEBUG org.snmp4j.Snmp
>> - Removed pending request with handle: PduHandle[665093248]
>> ------SECOND SYNC CALL RESPONSES (which should be received earlier)
>> 2009-03-06 19:52:39.401 -0430 DEBUG
>> org.snmp4j.transport.DefaultUdpTransportMapping    - Received message
>> from /10.201.15.5/161 with length 114:
>>
> 30:70:02:01:01:04:07:6e:74:5f:72:65:61:64:a2:62:02:04:27:a4:84:80:02:01:
> 00:02:01:00:30:54:30:52:06:0e:2b:06:01:04:01:91:60:01:03:02:01:0b:81:17:
> 04:40:20:00:00:80:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:
> 00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:
>> 00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00
>> 2009-03-06 19:52:39.401 -0430 DEBUG org.snmp4j.Snmp
>> - Looking up pending request with handle PduHandle[665093248]
>> 2009-03-06 19:52:39.401 -0430 WARN  org.snmp4j.Snmp
>> - Received response that cannot be matched to any outstanding request,
>> address=10.201.15.5/161, requestID=665093248
>> 2009-03-06 19:52:39.401 -0430 WARN  org.snmp4j.Snmp
>> - Received response that cannot be matched to any outstanding request,
>> address=10.201.15.5/161, requestID=665093248
>> 2009-03-06 19:52:39.401 -0430 DEBUG
>> org.snmp4j.transport.DefaultUdpTransportMapping    - Received message
>> from /10.201.15.5/161 with length 114:
>>
> 30:70:02:01:01:04:07:6e:74:5f:72:65:61:64:a2:62:02:04:27:a4:84:80:02:01:
> 00:02:01:00:30:54:30:52:06:0e:2b:06:01:04:01:91:60:01:03:02:01:0b:81:17:
> 04:40:20:00:00:80:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:
> 00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:
>> 00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00
>> 2009-03-06 19:52:39.402 -0430 DEBUG org.snmp4j.Snmp
>> - Looking up pending request with handle PduHandle[665093248]
>> 2009-03-06 19:52:39.402 -0430 WARN  org.snmp4j.Snmp
>> - Received response that cannot be matched to any outstanding request,
>> address=10.201.15.5/161, requestID=665093248
>> 2009-03-06 19:52:39.402 -0430 WARN  org.snmp4j.Snmp
>> - Received response that cannot be matched to any outstanding request,
>> address=10.201.15.5/161, requestID=665093248
>>
>> Peirong
>>
>>
>>
> ------------------------------------------------------------------------
>> _______________________________________________
>> SNMP4J mailing list
>> SNMP4J at agentpp.org
>> http://lists.agentpp.org/mailman/listinfo/snmp4j
> 

-- 
AGENT++
http://www.agentpp.com
http://www.mibexplorer.com
http://www.mibdesigner.com