[SNMP4J] strange problem

[Peirong Feng (pefeng)]

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