[SNMP4J] Not in time window Error Using TestAgent
Frank Fock
fock at agentpp.com
Fri Mar 31 00:06:01 CEST 2006
Hi Jesse,
If you are using SNMP4J SnmpRequest with the TestAgent,
it is likely that both use the same engine ID which
causes these problems. Please make sure that both
use different engine IDs.
Best regards,
Frank
Prusi, Jesse R wrote:
> I am using SnmpRequest to send a SNMPv3 message to the TestAgent. I am
> using the following arguments for SnmpRequest:
>
> -a SHA -A maplesyrup -u TEST -x DES -X maplesyrup -v 3 -r 0 -d DEBUG -p
> GET 127.0.0.1/9361 1.3.6.1.2.1.1.6.0
>
> The TestAgent receives the message and reports "Not in time window".
> What does this mean? What am I missing in the SNMPv3 setup?
>
> I've attached the logs for SnmpRequest and TestAgent.
>
> Thanks,
> Jesse
>
>
>
>
> ------------------------------------------------------------------------
>
> 0 [main] INFO org.snmp4j.agent.BaseAgent - Engine boots is: 9
> 10 [main] INFO org.snmp4j.agent.BaseAgent - Wrote boot counter: 10
> 60 [main] DEBUG org.snmp4j.security.Salt - Initialized Salt to e6667b4c3cc51e7e.
> 200 [main] DEBUG org.snmp4j.security.AuthGeneric - SHA-1First digest: 85:84:4e:de:31:ec:6a:d2:30:00:21:be:c1:98:e3:e9:f9:05:42:89
> 200 [main] DEBUG org.snmp4j.security.AuthGeneric - SHA-1localized key: 24:49:16:56:f8:f1:9e:37:43:30:95:df:dd:67:63:36:95:2f:85:d7
> 260 [main] DEBUG org.snmp4j.security.AuthGeneric - SHA-1First digest: 8a:be:fa:f6:ee:86:6a:49:70:c9:df:de:80:be:86:b3:23:3c:71:63
> 310 [main] DEBUG org.snmp4j.security.AuthGeneric - SHA-1localized key: 3c:bb:6a:03:2b:d1:a9:80:d7:b6:3c:a6:75:fb:98:1a:5d:8e:d3:df
> 310 [main] DEBUG org.snmp4j.security.UsmUserTable - Adding user SHADES = UsmUser[secName=SHADES,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=SHADESAuthPassword,privProtocol=1.3.6.1.6.3.10.1.2.2,privPassphrase=SHADESPrivPassword,localizationEngineID=null]
> 410 [main] DEBUG org.snmp4j.security.AuthGeneric - SHA-1First digest: 9f:b5:cc:03:81:49:7b:37:93:52:89:39:ff:78:8d:5d:79:14:52:11
> 410 [main] DEBUG org.snmp4j.security.AuthGeneric - SHA-1localized key: 93:ed:ac:53:a3:58:38:0b:4a:f5:b0:fe:70:f3:66:ee:b6:3f:3f:12
> 480 [main] DEBUG org.snmp4j.security.AuthGeneric - SHA-1First digest: 9f:b5:cc:03:81:49:7b:37:93:52:89:39:ff:78:8d:5d:79:14:52:11
> 480 [main] DEBUG org.snmp4j.security.AuthGeneric - SHA-1localized key: 93:ed:ac:53:a3:58:38:0b:4a:f5:b0:fe:70:f3:66:ee:b6:3f:3f:12
> 500 [main] DEBUG org.snmp4j.security.UsmUserTable - Adding user TEST = UsmUser[secName=TEST,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=maplesyrup,privProtocol=1.3.6.1.6.3.10.1.2.2,privPassphrase=maplesyrup,localizationEngineID=null]
> 570 [main] DEBUG org.snmp4j.security.AuthGeneric - SHA-1First digest: df:9b:a9:07:99:14:5b:29:18:9e:88:67:46:19:6d:5c:62:50:19:f1
> 570 [main] DEBUG org.snmp4j.security.AuthGeneric - SHA-1localized key: a5:26:b1:38:fe:23:53:27:c8:35:1a:34:33:7b:97:d4:5c:65:1f:02
> 570 [main] DEBUG org.snmp4j.security.UsmUserTable - Adding user SHA = UsmUser[secName=SHA,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=SHAAuthPassword,privProtocol=null,privPassphrase=null,localizationEngineID=null]
> 580 [main] INFO org.snmp4j.agent.mo.snmp.NotificationOriginatorImpl - Notification 1.3.6.1.6.3.1.1.5.1 issued with []
> 580 [main] DEBUG org.snmp4j.agent.mo.snmp.VacmMIB - VACM access requested for context=, securityName=public, securityModel=2, securityLevel=1, viewType=0, OID=1.3.6.1.6.3.1.1.5.1
> 580 [main] DEBUG org.snmp4j.agent.mo.snmp.VacmMIB - Matching view found for group name 'v1v2group' is 'fullNotifyView'
> 580 [main] DEBUG org.snmp4j.agent.mo.snmp.VacmMIB - Access allowed for view 'fullNotifyView' by subtree 1.3 for OID 1.3.6.1.6.3.1.1.5.1
> 590 [main] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Sending message to 127.0.0.1/162 with length 69: 30:43:02:01:01:04:06:70:75:62:6c:69:63:a7:36:02:04:5f:a9:07:52:02:01:00:02:01:00:30:28:30:0d:06:08:2b:06:01:02:01:01:03:00:43:01:32:30:17:06:0a:2b:06:01:06:03:01:01:04:01:00:06:09:2b:06:01:06:03:01:01:05:01
> 590 [main] INFO org.snmp4j.agent.mo.snmp.NotificationOriginatorImpl - Sent notification TRAP[requestID=1604912978, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.1.2.1.1.3.0 = 0:00:00.50; 1.3.6.1.6.3.1.1.4.1.0 = 1.3.6.1.6.3.1.1.5.1]] to CommunityTarget[address=127.0.0.1/162, version=1, timeout=2000, retries=1, community=public]
> 600 [main] ERROR org.snmp4j.agent.BaseAgent - java.io.FileNotFoundException: SNMP4JTestAgentConfig.cfg (The system cannot find the file specified)
> 600 [DefaultUDPTransportMapping_127.0.0.1/9361] INFO org.snmp4j.transport.DefaultUdpTransportMapping - UDP receive buffer size for socket 127.0.0.1/9361 is set to: 8192
> 233208 [DefaultUDPTransportMapping_127.0.0.1/9361] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Received message from /127.0.0.1/1640 with length 61: 30:3b:02:01:03:30:11:02:04:16:05:66:f4:02:03:00:ff:ff:04:01:04:02:01:03:04:10:30:0e:04:00:02:01:00:02:01:00:04:00:04:00:04:00:30:11:04:00:04:00:a0:0b:02:01:00:02:01:00:02:01:00:30:00
> 233218 [DefaultUDPTransportMapping_127.0.0.1/9361] DEBUG org.snmp4j.mp.MPv3 - SNMPv3 header decoded: msgId=369452788, msgMaxSize=65535, msgFlags=04, secModel=3
> 233218 [DefaultUDPTransportMapping_127.0.0.1/9361] DEBUG org.snmp4j.security.USM - RFC3414 §3.2.3 Unknown engine ID:
> 233218 [DefaultUDPTransportMapping_127.0.0.1/9361] DEBUG org.snmp4j.mp.MPv3 - Adding cache entry: StateReference[msgID=369452788,pduHandle=PduHandle[1604912979],securityEngineID=[B at 2f1921,securityModel=org.snmp4j.security.USM at 1adc30,securityName=[B at 16df84b,securityLevel=1,contextEngineID=[B at c832d2,contextName=[B at 1808199]
> 233268 [DefaultUDPTransportMapping_127.0.0.1/9361] DEBUG org.snmp4j.mp.MPv3 - Removed cache entry: StateReference[msgID=369452788,pduHandle=PduHandle[1604912979],securityEngineID=[B at 2f1921,securityModel=org.snmp4j.security.USM at 1adc30,securityName=[B at 16df84b,securityLevel=1,contextEngineID=[B at c832d2,contextName=[B at 1808199]
> 233268 [DefaultUDPTransportMapping_127.0.0.1/9361] DEBUG org.snmp4j.security.USM - RFC3414 §3.1.4.b Outgoing message is not encrypted
> 233268 [DefaultUDPTransportMapping_127.0.0.1/9361] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Sending message to 127.0.0.1/1640 with length 87: 30:55:02:01:03:30:11:02:04:16:05:66:f4:02:03:00:ff:ff:04:01:00:02:01:03:04:19:30:17:04:09:80:00:13:70:01:81:da:6a:58:02:01:00:02:01:00:04:00: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:01
> 233328 [DefaultUDPTransportMapping_127.0.0.1/9361] WARN org.snmp4j.MessageDispatcherImpl - 1.3.6.1.6.3.15.1.1.4.0 = 1
> 233888 [DefaultUDPTransportMapping_127.0.0.1/9361] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Received message from /127.0.0.1/1640 with length 125: 30:7b:02:01:03:30:11:02:04:16:05:66:f5:02:03:00:ff:ff:04:01:07:02:01:03:04:31:30:2f:04:09:80:00:13:70:01:81:da:6a:58:02:01:00:02:01:00:04:04:54:45:53:54:04:0c:73:7f:c7:40:cd:86:f4:7f:a4:ff:3c:15:04:08:00:00:00:00:4a:4c:1f:49:04:30:2e:be:17:97:1e:82:f2:0c:10:7e:0e:c1:6f:3a:0e:7a:32:7b:c2:02:e8:94:77:a5:c2:20:44:eb:8c:d5:bd:ec:3b:b8:b8:80:6a:22:87:6b:d6:ad:67:63:ab:9a:7c:d1
> 233958 [DefaultUDPTransportMapping_127.0.0.1/9361] DEBUG org.snmp4j.mp.MPv3 - SNMPv3 header decoded: msgId=369452789, msgMaxSize=65535, msgFlags=07, secModel=3
> 233958 [DefaultUDPTransportMapping_127.0.0.1/9361] DEBUG org.snmp4j.security.USM - getUser(engineID=80:00:13:70:01:81:da:6a:58, securityName=TEST)
> 233958 [DefaultUDPTransportMapping_127.0.0.1/9361] DEBUG org.snmp4j.security.UsmTimeTable - CheckTime: received message outside time window (authorative):engineBoots differ
> 233958 [DefaultUDPTransportMapping_127.0.0.1/9361] DEBUG org.snmp4j.security.USM - RFC3414 §3.2.7.a Not in time window; engineID='80:00:13:70:01:81:da:6a:58', engineBoots=0, engineTime=0
> 233958 [DefaultUDPTransportMapping_127.0.0.1/9361] DEBUG org.snmp4j.mp.MPv3 - Adding cache entry: StateReference[msgID=369452789,pduHandle=PduHandle[1604912980],securityEngineID=[B at 1ff7a1e,securityModel=org.snmp4j.security.USM at 1adc30,securityName=[B at 1aa57fb,securityLevel=3,contextEngineID=[B at 763f5d,contextName=[B at 13a317a]
> 233958 [DefaultUDPTransportMapping_127.0.0.1/9361] DEBUG org.snmp4j.mp.MPv3 - Removed cache entry: StateReference[msgID=369452789,pduHandle=PduHandle[1604912980],securityEngineID=[B at 1ff7a1e,securityModel=org.snmp4j.security.USM at 1adc30,securityName=[B at 1aa57fb,securityLevel=3,contextEngineID=[B at 763f5d,contextName=[B at 13a317a]
> 233978 [DefaultUDPTransportMapping_127.0.0.1/9361] DEBUG org.snmp4j.security.USM - RFC3414 §3.1.4.b Outgoing message is not encrypted
> 233978 [DefaultUDPTransportMapping_127.0.0.1/9361] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Sending message to 127.0.0.1/1640 with length 104: 30:66:02:01:03:30:11:02:04:16:05:66:f5:02:03:00:ff:ff:04:01:01:02:01:03:04:2a:30:28:04:09:80:00:13:70:01:81:da:6a:58:02:01:0a:02:02:00:e9:04:04:54:45:53:54:04:0c:bf:fe:55:f3:e8:55:fa:83:98:06:3e:26: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:01
> 233978 [DefaultUDPTransportMapping_127.0.0.1/9361] WARN org.snmp4j.MessageDispatcherImpl - 1.3.6.1.6.3.15.1.1.2.0 = 1
>
>
> ------------------------------------------------------------------------
>
> 0 [main] DEBUG org.snmp4j.security.Salt - Initialized Salt to ce4eb2794a4c1f49.
> 20 [main] DEBUG org.snmp4j.security.UsmUserTable - Adding user TEST = UsmUser[secName=TEST,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=maplesyrup,privProtocol=1.3.6.1.6.3.10.1.2.2,privPassphrase=maplesyrup,localizationEngineID=null]
> 30 [DefaultUDPTransportMapping_129.218.106.88/0] INFO org.snmp4j.transport.DefaultUdpTransportMapping - UDP receive buffer size for socket 129.218.106.88/0 is set to: 8192
> 30 [main] DEBUG org.snmp4j.security.USM - RFC3414 §3.1.4.b Outgoing message is not encrypted
> 30 [main] DEBUG org.snmp4j.mp.MPv3 - Adding cache entry: StateReference[msgID=369452788,pduHandle=PduHandle[327515159],securityEngineID=[B at 922804,securityModel=org.snmp4j.security.USM at 1815859,securityName=[B at cf40f5,securityLevel=1,contextEngineID=[B at b1c260,contextName=[B at 503429]
> 30 [main] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Sending message to 127.0.0.1/9361 with length 61: 30:3b:02:01:03:30:11:02:04:16:05:66:f4:02:03:00:ff:ff:04:01:04:02:01:03:04:10:30:0e:04:00:02:01:00:02:01:00:04:00:04:00:04:00:30:11:04:00:04:00:a0:0b:02:01:00:02:01:00:02:01:00:30:00
> 40 [main] DEBUG org.snmp4j.Snmp - New pending request with handle PduHandle[327515159]
> 150 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Received message from /127.0.0.1/9361 with length 87: 30:55:02:01:03:30:11:02:04:16:05:66:f4:02:03:00:ff:ff:04:01:00:02:01:03:04:19:30:17:04:09:80:00:13:70:01:81:da:6a:58:02:01:00:02:01:00:04:00: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:01
> 150 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.mp.MPv3 - SNMPv3 header decoded: msgId=369452788, msgMaxSize=65535, msgFlags=00, secModel=3
> 210 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.security.USM - Accepting zero length security name
> 210 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.mp.MPv3 - Removed cache entry: StateReference[msgID=369452788,pduHandle=PduHandle[327515159],securityEngineID=[B at 922804,securityModel=org.snmp4j.security.USM at 1815859,securityName=[B at cf40f5,securityLevel=1,contextEngineID=[B at b1c260,contextName=[B at 503429]
> 210 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.mp.MPv3 - RFC3412 §7.2.10 - Received PDU (msgID=369452788) is a response or an internal class message. PduHandle.transactionID = 327515159
> 210 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.mp.MPv3 - MPv3 finished
> 210 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.Snmp - Searching pending request with handlePduHandle[327515159]
> 210 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.Snmp - Send new request after report.
> 210 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.mp.MPv3 - Context engine ID of scoped PDU is empty! Setting it to authoritative engine ID: 80:00:13:70:01:81:da:6a:58
> 210 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.security.USM - getUser(engineID=80:00:13:70:01:81:da:6a:58, securityName=TEST)
> 340 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.security.AuthGeneric - SHA-1First digest: 9f:b5:cc:03:81:49:7b:37:93:52:89:39:ff:78:8d:5d:79:14:52:11
> 340 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.security.AuthGeneric - SHA-1localized key: 93:ed:ac:53:a3:58:38:0b:4a:f5:b0:fe:70:f3:66:ee:b6:3f:3f:12
> 410 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.security.AuthGeneric - SHA-1First digest: 9f:b5:cc:03:81:49:7b:37:93:52:89:39:ff:78:8d:5d:79:14:52:11
> 410 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.security.AuthGeneric - SHA-1localized key: 93:ed:ac:53:a3:58:38:0b:4a:f5:b0:fe:70:f3:66:ee:b6:3f:3f:12
> 410 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.security.UsmUserTable - Adding user TEST = UsmUser[secName=TEST,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=null,privProtocol=1.3.6.1.6.3.10.1.2.2,privPassphrase=null,localizationEngineID=80:00:13:70:01:81:da:6a:58]
> 410 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.security.USM - RFC3414 §3.1.4.a Outgoing message needs to be encrypted
> 410 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.security.PrivDES - Preparing decrypt_params.
> 410 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.security.PrivDES - Preparing iv for encryption.
> 710 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.security.PrivDES - Using padding.
> 710 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.security.PrivDES - Encryption finished.
> 710 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.mp.MPv3 - Adding cache entry: StateReference[msgID=369452789,pduHandle=PduHandle[327515159],securityEngineID=[B at 1c9a690,securityModel=org.snmp4j.security.USM at 1815859,securityName=[B at cf40f5,securityLevel=3,contextEngineID=[B at 1d6776d,contextName=[B at 13ad085]
> 710 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Sending message to 127.0.0.1/9361 with length 125: 30:7b:02:01:03:30:11:02:04:16:05:66:f5:02:03:00:ff:ff:04:01:07:02:01:03:04:31:30:2f:04:09:80:00:13:70:01:81:da:6a:58:02:01:00:02:01:00:04:04:54:45:53:54:04:0c:73:7f:c7:40:cd:86:f4:7f:a4:ff:3c:15:04:08:00:00:00:00:4a:4c:1f:49:04:30:2e:be:17:97:1e:82:f2:0c:10:7e:0e:c1:6f:3a:0e:7a:32:7b:c2:02:e8:94:77:a5:c2:20:44:eb:8c:d5:bd:ec:3b:b8:b8:80:6a:22:87:6b:d6:ad:67:63:ab:9a:7c:d1
> 800 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Received message from /127.0.0.1/9361 with length 104: 30:66:02:01:03:30:11:02:04:16:05:66:f5:02:03:00:ff:ff:04:01:01:02:01:03:04:2a:30:28:04:09:80:00:13:70:01:81:da:6a:58:02:01:0a:02:02:00:e9:04:04:54:45:53:54:04:0c:bf:fe:55:f3:e8:55:fa:83:98:06:3e:26: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:01
> 800 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.mp.MPv3 - SNMPv3 header decoded: msgId=369452789, msgMaxSize=65535, msgFlags=01, secModel=3
> 800 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.security.USM - getUser(engineID=80:00:13:70:01:81:da:6a:58, securityName=TEST)
> 800 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.security.UsmTimeTable - CheckTime: received message outside time window (authorative):engineBoots differ
> 800 [DefaultUDPTransportMapping_129.218.106.88/0] DEBUG org.snmp4j.security.USM - RFC3414 §3.2.7.a Not in time window; engineID='80:00:13:70:01:81:da:6a:58', engineBoots=10, engineTime=233
> 800 [DefaultUDPTransportMapping_129.218.106.88/0] WARN org.snmp4j.MessageDispatcherImpl - 1.3.6.1.6.3.15.1.1.2.0 = 1
> 1040 [Thread-0] DEBUG org.snmp4j.Snmp - Request timed out: 327515159
> 1070 [main] DEBUG org.snmp4j.Snmp - Removed pending request with handle: PduHandle[327515159]
> Received response after 1050 millis
> Request timed out.
>
>
> ------------------------------------------------------------------------
>
> _______________________________________________
> 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
More information about the SNMP4J
mailing list