[SNMP4J] ProxyForwarder - Drops the response

Senthil Muniswamy senthil.muniswamy at gmail.com
Fri Jun 23 00:16:32 CEST 2006


Frank,

Seems like the response received from the Target address is processed only
after the timeout period, eventually the response gets dropped as the
pending request has been removed. Any idea?

456865 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.transport.DefaultUdpTransportMapping  - Received message from
BEL1-101230/172.16.15.114/1867 with length 64:
30:3e:02:01:03:30:0d:02:01:02:02:02:20:00:04:01:04:02:01:03:04:17:30:15:04:00:02:01:00:02:01:00:04:07:69:6e:69:74:69:61:6c:04:00:04:00:30:11:04:00:04:00:a0:0b:02:01:01:02:01:00:02:01:00:30:00
456865 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.mp.MPv3  - SNMPv3 header decoded: msgId=2, msgMaxSize=8192,
msgFlags=04, secModel=3
456865 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.USM  - RFC3414 §3.2.3 Unknown engine ID:
456865 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.mp.MPv3  - Adding cache entry:
StateReference[msgID=2,pduHandle=PduHandle[954968313],securityEngineID=,securityModel=
org.snmp4j.security.USM at 131c89c
,securityName=initial,securityLevel=1,contextEngineID=,contextName=]
456865 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.mp.MPv3  - Removed cache entry:
StateReference[msgID=2,pduHandle=PduHandle[954968313],securityEngineID=,securityModel=
org.snmp4j.security.USM at 131c89c
,securityName=initial,securityLevel=1,contextEngineID=,contextName=]
456865 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.USM  - RFC3414 §3.1.4.b Outgoing message is not
encrypted
456865 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.transport.DefaultUdpTransportMapping  - Sending message to
172.16.15.114/1867 with length 94:
30:5c:02:01:03:30:0e:02:01:02:02:03:00:ff:ff:04:01:00:02:01:03:04:23:30:21:04:0c:80:00:13:70:04:74:65:73:74:69:6e:67:02:01:00:02:01:00:04:07:69:6e:69:74:69:61:6c:04:00:04:00:30:22:04:00:04:00:a8:1c:02:01:00:02:01:00:02:01:00:30:11:30:0f:06:0a:2b:06:01:06:03:0f:01:01:04:00:41:01:0b
456865 [DefaultUDPTransportMapping_172.16.15.114/1161] WARN
org.snmp4j.MessageDispatcherImpl  - 1.3.6.1.6.3.15.1.1.4.0 = 11
456975 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.transport.DefaultUdpTransportMapping  - Received message from
BEL1-101230/172.16.15.114/1867 with length 99:
30:61:02:01:03:30:0d:02:01:04:02:02:20:00:04:01:05:02:01:03:04:2e:30:2c:04:0c:80:00:13:70:04:74:65:73:74:69:6e:67:02:01:00:02:01:00:04:06:53:48:41:44:45:53:04:0c:ab:6a:ec:a5:f9:1b:22:34:8a:46:be:04:04:00:30:1d:04:0c:80:00:13:70:04:74:65:73:74:69:6e:67:04:00:a0:0b:02:01:03:02:01:00:02:01:00:30:00
456975 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.mp.MPv3  - SNMPv3 header decoded: msgId=4, msgMaxSize=8192,
msgFlags=05, secModel=3
456975 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.USM  -
getUser(engineID=80:00:13:70:04:74:65:73:74:69:6e:67, securityName=SHADES)
456975 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.UsmTimeTable  - CheckTime: received message outside time
window (authorative):engineBoots differ
456975 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.USM  - RFC3414 §3.2.7.a Not in time window;
engineID='80:00:13:70:04:74:65:73:74:69:6e:67', engineBoots=0, engineTime=0
456975 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.mp.MPv3  - Adding cache entry:
StateReference[msgID=4,pduHandle=PduHandle[954968314],securityEngineID=80:00:13:70:04:74:65:73:74:69:6e:67,securityModel=
org.snmp4j.security.USM at 131c89c
,securityName=SHADES,securityLevel=2,contextEngineID=,contextName=]
456975 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.mp.MPv3  - Removed cache entry:
StateReference[msgID=4,pduHandle=PduHandle[954968314],securityEngineID=80:00:13:70:04:74:65:73:74:69:6e:67,securityModel=
org.snmp4j.security.USM at 131c89c
,securityName=SHADES,securityLevel=2,contextEngineID=,contextName=]
456975 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.USM  - RFC3414 §3.1.4.b Outgoing message is not
encrypted
456975 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.transport.DefaultUdpTransportMapping  - Sending message to
172.16.15.114/1867 with length 106:
30:68:02:01:03:30:0e:02:01:04:02:03:00:ff:ff:04:01:01:02:01:03:04:2f:30:2d:04:0c:80:00:13:70:04:74:65:73:74:69:6e:67:02:01:5e:02:02:01:c8:04:06:53:48:41:44:45:53:04:0c:ab:c5:72:b7:4a:42:1c:ae:fe:99:6c:37:04:00:30:22:04:00:04:00:a8:1c:02:01:00:02:01:00:02:01:00:30:11:30:0f:06:0a:2b:06:01:06:03:0f:01:01:02:00:41:01:0b
456975 [DefaultUDPTransportMapping_172.16.15.114/1161] WARN
org.snmp4j.MessageDispatcherImpl  - 1.3.6.1.6.3.15.1.1.2.0 = 11
457365 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.transport.DefaultUdpTransportMapping  - Received message from
BEL1-101230/172.16.15.114/1867 with length 127:
30:7d:02:01:03:30:0d:02:01:06:02:02:20:00:04:01:07:02:01:03:04:37:30:35:04:0c:80:00:13:70:04:74:65:73:74:69:6e:67:02:01:5e:02:02:01:c8:04:06:53:48:41:44:45:53:04:0c:c7:33:ad:42:4d:3e:a0:9a:54:c2:75:05:04:08:08:5b:86:69:d1:b9:be:f0:04:30:44:c6:7b:94:a0:3f:a4:47:57:43:f4:42:2e:f7:69:00:79:c6:74:f1:be:c2:a7:64:8d:cc:8b:29:5e:f2:ea:cb:9c:c0:81:bb:91:62:1c:17:11:ad:81:7b:f3:63:d6:53
457365 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.mp.MPv3  - SNMPv3 header decoded: msgId=6, msgMaxSize=8192,
msgFlags=07, secModel=3
457365 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.USM  -
getUser(engineID=80:00:13:70:04:74:65:73:74:69:6e:67, securityName=SHADES)
457365 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.UsmTimeTable  - CheckTime: time ok (authorative)
457365 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.mp.MPv3  - RFC3412 §7.2.10 - Received PDU is NOT a response or
internal class message -> PduHandle := NONE
457365 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.mp.MPv3  - Adding cache entry:
StateReference[msgID=6,pduHandle=PduHandle[-2147483648],securityEngineID=80:00:13:70:04:74:65:73:74:69:6e:67,securityModel=
org.snmp4j.security.USM at 131c89c
,securityName=SHADES,securityLevel=3,contextEngineID=80:00:13:70:01:ac:10:0f:72,contextName=]
457365 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG org.snmp4j.Snmp
- Fire process PDU event: CommandResponderEvent[transportMapping=
org.snmp4j.transport.DefaultUdpTransportMapping at 49cf9fpeerAddress=
172.16.15.114/1867, processed=false, pdu=[GET[reqestID=5, errorStatus=0,
errorIndex=0, VBS[1.3.6.1.2.1.1.1.0 = Null]]], securityName=SHADES,
securityModel=3, securityLevel=3]
457365 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.agent.CommandProcessor  - Processsing proxy request with proxy
forwarder org.snmp4j.agent.mo.snmp.ProxyForwarderImpl at 5c7734
457365 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.agent.mo.snmp.ProxyForwarderImpl  - Checking possible match for
in parameter: v31
457365 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.agent.mo.snmp.ProxyForwarderImpl  - Matching request
CommandResponderEvent[transportMapping=
org.snmp4j.transport.DefaultUdpTransportMapping at 49cf9fpeerAddress=
172.16.15.114/1867, processed=false, pdu=[GET[reqestID=5, errorStatus=0,
errorIndex=0, VBS[1.3.6.1.2.1.1.1.0 = Null]]], securityName=SHADES,
securityModel=3, securityLevel=3]  with mpModel=3, secModel=3, secLevel=3,
secName=SHADES
457365 [DefaultUDPTransportMapping_172.16.15.114/1161] INFO
org.snmp4j.agent.mo.snmp.ProxyForwarderImpl  - Forwarding proxy request
org.snmp4j.agent.ProxyForwardRequest
[contextEngineID=80:00:13:70:01:ac:10:0f:72,context=,proxyType=1,commandEvent=CommandResponderEvent[transportMapping=
org.snmp4j.transport.DefaultUdpTransportMapping at 49cf9fpeerAddress=
172.16.15.114/1867, processed=false, pdu=[GET[reqestID=5, errorStatus=0,
errorIndex=0, VBS[1.3.6.1.2.1.1.1.0 = Null]]], securityName=SHADES,
securityModel=3, securityLevel=3]] to org.snmp4j.UserTarget[address=
172.16.15.114/161, version=3, timeout=5000, retries=0]
457365 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.USM  - getUser(engineID=80:00:13:70:01:ac:10:0f:72,
securityName=SHADES)
457365 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.USM  - RFC3414 §3.1.4.a Outgoing message needs to be
encrypted
457365 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.PrivDES  - Preparing decrypt_params.
457365 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.PrivDES  - Preparing iv for encryption.
457365 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.PrivDES  - Using padding.
457365 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.PrivDES  - Encryption finished.
457381 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.mp.MPv3  - Adding cache entry:
StateReference[msgID=827499190,pduHandle=PduHandle[5],securityEngineID=80:00:13:70:01:ac:10:0f:72,securityModel=
org.snmp4j.security.USM at 131c89c
,securityName=SHADES,securityLevel=3,contextEngineID=80:00:13:70:01:ac:10:0f:72,contextName=]
457381 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.transport.DefaultUdpTransportMapping  - Sending message to
172.16.15.114/161 with length 128:
30:7e:02:01:03:30:11:02:04:31:52:a2:b6:02:03:00:ff:ff:04:01:07:02:01:03:04:34:30:32:04:09:80:00:13:70:01:ac:10:0f:72:02:01:08:02:02:06:c2:04:06:53:48:41:44:45:53:04:0c:89:e0:65:22:79:3c:2b:ae:30:b7:72:0c:04:08:00:00:00:08:e2:d1:8b:c4:04:30:d8:3b:d7:86:22:0c:38:58:74:0d:0c:45:80:9a:9a:40:80:89:f1:72:95:85:5b:d2:bb:1b:84:ca:90:b2:9e:1e:a5:d6:f3:c1:94:cf:97:47:8f:c8:f3:00:ea:3f:2a:44
457381 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG org.snmp4j.Snmp
- New pending request with handle PduHandle[5]
462381 [Timer-0] DEBUG org.snmp4j.Snmp  - Request timed out: 5

462381 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG org.snmp4j.Snmp
- Removed pending request with handle: PduHandle[5]
462381 [DefaultUDPTransportMapping_172.16.15.114/1161] INFO
org.snmp4j.agent.mo.snmp.ProxyForwarderImpl  - Received proxy response from
null is null
462381 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.mp.MPv3  - Removed cache entry:
StateReference[msgID=6,pduHandle=PduHandle[-2147483648],securityEngineID=80:00:13:70:04:74:65:73:74:69:6e:67,securityModel=
org.snmp4j.security.USM at 131c89c
,securityName=SHADES,securityLevel=3,contextEngineID=80:00:13:70:01:ac:10:0f:72,contextName=]
462381 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.USM  - RFC3414 §3.1.4.a Outgoing message needs to be
encrypted
462381 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.PrivDES  - Preparing decrypt_params.
462381 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.PrivDES  - Preparing iv for encryption.
462381 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.PrivDES  - Using padding.
462381 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.PrivDES  - Encryption finished.
462381 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.transport.DefaultUdpTransportMapping  - Sending message to
172.16.15.114/1867 with length 112:
30:6e:02:01:03:30:0e:02:01:06:02:03:00:ff:ff:04:01:03:02:01:03:04:37:30:35:04:0c:80:00:13:70:04:74:65:73:74:69:6e:67:02:01:5e:02:02:01:ce:04:06:53:48:41:44:45:53:04:0c:12:2d:38:31:bf:de:b7:e5:9e:1b:ea:80:04:08:00:00:00:5e:e2:d1:8b:c5:04:20:ad:ff:b2:26:ae:c6:29:14:5b:cf:37:af:d5:79:e4:70:42:69:89:74:18:e7:17:3d:b4:17:b0:90:ec:c7:c6:88
462381 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.transport.DefaultUdpTransportMapping  - Received message from
BEL1-101230/172.16.15.114/161 with length 161:
30:81:9e:02:01:03:30:11:02:04:31:52:a2:b6:02:03:00:ff:ff:04:01:03:02:01:03:04:34:30:32:04:09:80:00:13:70:01:ac:10:0f:72:02:01:08:02:02:06:c6:04:06:53:48:41:44:45:53:04:0c:ae:91:79:ad:55:31:3e:72:b1:9b:99:b4:04:08:00:00:00:08:3d:60:a2:aa:04:50:9b:f5:4f:9e:dd:73:95:42:c2:94:17:4c:ad:d1:53:7a:df:ca:2e:7e:03:33:f9:23:a0:6c:d6:ad:7d:b3:dc:e1:6d:e3:e3:04:16:03:86:87:4d:8b:e1:be:8e:21:b6:cf:c0:4b:c8:6a:41:90:24:25:20:52:82:5a:74:12:e6:b0:86:d0:3a:6b:5d:bd:ce:14:5d:72:d9:37:f2:0d:e0:ab
462381 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.mp.MPv3  - SNMPv3 header decoded: msgId=827499190,
msgMaxSize=65535, msgFlags=03, secModel=3
462381 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.USM  - getUser(engineID=80:00:13:70:01:ac:10:0f:72,
securityName=SHADES)
462381 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.security.UsmTimeTable  - CheckTime: time ok (non authorative)
462381 [DefaultUDPTransportMapping_172.16.15.114/1161] DEBUG
org.snmp4j.mp.MPv3  - RFC3412 §7.2.10 - Received PDU (msgID=827499190) is a
response or internal class message, but cached information for the msgID
could not be found
462381 [DefaultUDPTransportMapping_172.16.15.114/1161] WARN
org.snmp4j.MessageDispatcherImpl  - noError

Thanks,
Senthil



More information about the SNMP4J mailing list