Snmp Agent V3 throws an exception on a wrong security name

sassi67 · February 2, 2021, 7:48pm

Hallo Frank,

in my company we are using Snmp4J(-Agent) 2.6.3 for our integration tests. Everything is working fine with a Snmp V2 agent, but we have a particular case in V3 we would like to test and where getting something unexpected. In short after a while we change on the fly the access credentials to a Snmp V3 agent to test the behavior of our manager. In this case we are expecting to receive a PDU response type with an SNMP authentication error, but the agent throws an exception instead:

1164 [main] DEBUG org.snmp4j.security.USM - USM.getUser - User 'snmptest_SHA_AES256' unknown org.snmp4j.MessageException: Message processing model 3 returned error: Unknown security name 1164 [main] DEBUG org.snmp4j.security.USM - Security name not found for engineID=70:75:62:6c:69:63, securityName=73:6e:6d:70:74:65:73:74:5f:53:48:41:5f:41:45:53:32:35:36
The trick to change the credentials consists in 4 steps: unregister all the managed objects, close the server, register the managed objects again and restart:
With Snmp V2 this works fine, but Snmp V3 has this problem.
What should I check?
Thanks for your great product!
Alessandro

AGENTPP · February 2, 2021, 9:23pm

Hi Allessandro,

Unregistering and registering managed objects is not necessary nor helpful when changing authentication.

Independent from that, I guess the error is changing the engine ID too. That is why the engine ID and security name pair cannot be found. Otherwise, there is some other error in the code changing the credentials.

I can assure, that changing the keys of a SNMPv3 user works without problems at runtime.

Best regards,
Frank

sassi67 · February 4, 2021, 10:15pm

Thanks Frank, but now I suspect that the problem is unrelated to the agent restart because I’ve meanwhile implemented an unit test in which the exception is thrown when the manager uses a wrong security name
755 [DefaultUDPTransportMapping_0.0.0.0/54443] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - UDP receive buffer size for socket 0.0.0.0/54443 is set to: 65536
768 [main] DEBUG org.snmp4j.security.UsmUserTable - Adding user xxx = UsmUser[secName=xxx,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=12345678,privProtocol=1.3.6.1.4.1.4976.2.2.1.1.2,privPassphrase=12345678,localizationEngineID=null]
768 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - UDP receive buffer size for socket 0.0.0.0/0 is set to: 65536
781 [main] DEBUG org.snmp4j.security.USM - Security name not found for engineID=, securityName=73:6e:6d:70:74:65:73:74:5f:53:48:41:5f:41:45:53:32:35:36
org.snmp4j.MessageException: Message processing model 3 returned error: Unknown security name
at org.snmp4j.MessageDispatcherImpl.sendPdu(MessageDispatcherImpl.java:524)
at org.snmp4j.Snmp.sendMessage(Snmp.java:1087)
at org.snmp4j.Snmp.send(Snmp.java:981)
at org.snmp4j.Snmp.send(Snmp.java:961)
at org.snmp4j.Snmp.send(Snmp.java:926)

AGENTPP · February 4, 2021, 11:35pm

What exactly is the problem with the fact that the agent returns an error when the security name is unknown?

BTW, I suspect that the stack trace is not a command responder (agent) stack trace. That would look different. Could it be the case, that you are trying to send a RESPONSE PDU without using the required MPv3.prepareResponseMessage?

sassi67 · March 9, 2021, 11:29pm

Hi Frank!
Let me re-formulate the scenario. I have a simple working Snmp V3 agent, but there is a client which queries it providing the wrong security name. Snmp4J-Agent throws an exception, but some real devices we have in the company return an usmStatsUnknownUserNames PDU instead. I’m wondering what’s the way to force my agent to work in the same way (implement a specific CommandResponder to replace the default one passed to BaseAgent?)

AGENTPP · March 9, 2021, 11:53pm

I already wrote above, that I cannot reproduce that “SNMP4J-Agent is throwing an exception” in the case described above. And therefore I cannot provide a fix/workaround for a problem that from my point of view does not exists.
To resolve this deadlock of understanding, you could probably provide the PDU (hex-dump) that is returned from the SNMP4J-Agent to the application or/and the full debug log of the agent. The current information you provided so far, does not make sense to me and is contradicting.

sassi67 · April 5, 2021, 12:00pm

Hi Frank.
I’ve moved all the minimal relevant part of our Snmp agent implementation in a separate public repository (https://github.com/sassi67/snmp4j-agent)
In any case the log of the test which throws the exception (testSnmpV3ChangeUserNameAndRestart) is this:
0 [Test worker] INFO org.snmp4j.agent.cfg.EngineBootsCounterFile - Engine boots is: 20
3 [Test worker] INFO org.snmp4j.agent.cfg.EngineBootsCounterFile - Wrote boot counter: 21
…
274 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Registered MO [DefaultMOTable] in default context with scope DefaultMOTable[id=1.3.6.1.4.1.4976.10.1.1.1.1.2.2.1,index=org.snmp4j.agent.mo.MOTableIndex@556e12c,columns=[org.snmp4j.agent.mo.MOColumn[columnID=2,syntax=2], org.snmp4j.agent.mo.MOMutableColumn[columnID=3,syntax=2,default=1,mutableInService=true,mandatory=true], org.snmp4j.agent.mo.MOColumn[columnID=4,syntax=2], org.snmp4j.agent.mo.snmp.StorageType[columnID=5,syntax=2,default=2,mutableInService=true,mandatory=true], org.snmp4j.agent.mo.snmp.RowStatus[columnID=6,syntax=2,default=null,mutableInService=true,mandatory=true]]]
276 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Registered MO [Snmp4jCfgSecSrcAddrValidation] in default context with scope org.snmp4j.agent.mo.snmp4j.Snmp4jConfigMib$Snmp4jCfgSecSrcAddrValidation[oid=1.3.6.1.4.1.4976.10.1.1.2.1.1.1.0,access=MOAccessImpl{read|write|notify},value=2,volatile=false]
277 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Registered MO [DefaultMOTable] in default context with scope DefaultMOTable[id=1.3.6.1.4.1.4976.10.1.1.2.1.2.1.1,index=org.snmp4j.agent.mo.MOTableIndex@5cf92068,columns=[org.snmp4j.agent.mo.snmp.DisplayString[columnID=2,syntax=4,default=null,mutableInService=true,mandatory=true], org.snmp4j.agent.mo.MOColumn[columnID=4,syntax=67], org.snmp4j.agent.mo.MOColumn[columnID=5,syntax=67], org.snmp4j.agent.mo.snmp.Enumerated[columnID=6,syntax=2,default=1,mutableInService=true,mandatory=true], org.snmp4j.agent.mo.snmp.Enumerated[columnID=7,syntax=2,default=1,mutableInService=true,mandatory=true], org.snmp4j.agent.mo.snmp.StorageType[columnID=8,syntax=2,default=3,mutableInService=true,mandatory=true], org.snmp4j.agent.mo.snmp.RowStatus[columnID=9,syntax=2,default=null,mutableInService=true,mandatory=true], org.snmp4j.agent.mo.MOMutableColumn[columnID=10,syntax=4,default=default,mutableInService=true,mandatory=true]]]
277 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Registered MO [DefaultMOTable] in default context with scope DefaultMOTable[id=1.3.6.1.6.3.14.1.2.1,index=org.snmp4j.agent.mo.MOTableIndex@df9ede8,columns=[org.snmp4j.agent.mo.snmp.Enumerated[columnID=2,syntax=2,default=null,mutableInService=true,mandatory=true], org.snmp4j.agent.mo.MOMutableColumn[columnID=3,syntax=4,default=null,mutableInService=true,mandatory=true], org.snmp4j.agent.mo.MOMutableColumn[columnID=4,syntax=4,default=null,mutableInService=true,mandatory=true], org.snmp4j.agent.mo.MOMutableColumn[columnID=5,syntax=4,default=null,mutableInService=true,mandatory=true], org.snmp4j.agent.mo.MOMutableColumn[columnID=6,syntax=4,default=null,mutableInService=true,mandatory=true], org.snmp4j.agent.mo.MOMutableColumn[columnID=7,syntax=4,default=null,mutableInService=true,mandatory=true], org.snmp4j.agent.mo.snmp.StorageType[columnID=8,syntax=2,default=3,mutableInService=true,mandatory=true], org.snmp4j.agent.mo.snmp.RowStatus[columnID=9,syntax=2,default=null,mutableInService=true,mandatory=true]]]
277 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Removed registration org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.1.1.0,access=MOAccessImpl{read|notify},value=SNMP4J-Agent - Windows 10 - amd64 - 10.0,volatile=true] for org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.1.1.0,access=MOAccessImpl{read|notify},value=SNMP4J-Agent - Windows 10 - amd64 - 10.0,volatile=true] in context ‘null’ successfully
278 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Removed registration org.snmp4j.agent.mo.snmp.SNMPv2MIB$SysUpTimeImpl[oid=1.3.6.1.2.1.1.3.0,access=MOAccessImpl{read|notify},value=0:00:00.10,volatile=true] for org.snmp4j.agent.mo.snmp.SNMPv2MIB$SysUpTimeImpl[oid=1.3.6.1.2.1.1.3.0,access=MOAccessImpl{read|notify},value=0:00:00.10,volatile=true] in context ‘null’ successfully
278 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Removed registration org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.1.2.0,access=MOAccessImpl{read|notify},value=1.3.6.1.4.1.4976,volatile=true] for org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.1.2.0,access=MOAccessImpl{read|notify},value=1.3.6.1.4.1.4976,volatile=true] in context ‘null’ successfully
278 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Removed registration org.snmp4j.agent.mo.snmp.DisplayStringScalar[oid=1.3.6.1.2.1.1.4.0,access=MOAccessImpl{read|write|notify},value=,volatile=false] for org.snmp4j.agent.mo.snmp.DisplayStringScalar[oid=1.3.6.1.2.1.1.4.0,access=MOAccessImpl{read|write|notify},value=,volatile=false] in context ‘null’ successfully
278 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Removed registration org.snmp4j.agent.mo.snmp.DisplayStringScalar[oid=1.3.6.1.2.1.1.5.0,access=MOAccessImpl{read|write|notify},value=,volatile=false] for org.snmp4j.agent.mo.snmp.DisplayStringScalar[oid=1.3.6.1.2.1.1.5.0,access=MOAccessImpl{read|write|notify},value=,volatile=false] in context ‘null’ successfully
278 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Removed registration org.snmp4j.agent.mo.snmp.DisplayStringScalar[oid=1.3.6.1.2.1.1.6.0,access=MOAccessImpl{read|write|notify},value=,volatile=false] for org.snmp4j.agent.mo.snmp.DisplayStringScalar[oid=1.3.6.1.2.1.1.6.0,access=MOAccessImpl{read|write|notify},value=,volatile=false] in context ‘null’ successfully
278 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Removed registration org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.1.7.0,access=MOAccessImpl{read|notify},value=10,volatile=true] for org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.1.7.0,access=MOAccessImpl{read|notify},value=10,volatile=true] in context ‘null’ successfully
279 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Removed registration org.snmp4j.agent.mo.snmp.EnumeratedScalar[oid=1.3.6.1.2.1.11.30.0,access=MOAccessImpl{read|write|notify},value=1,volatile=false] for org.snmp4j.agent.mo.snmp.EnumeratedScalar[oid=1.3.6.1.2.1.11.30.0,access=MOAccessImpl{read|write|notify},value=1,volatile=false] in context ‘null’ successfully
279 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Removed registration org.snmp4j.agent.mo.snmp.TestAndIncr[oid=1.3.6.1.6.3.1.1.6.1.0,access=MOAccessImpl{read|write|notify},value=0,volatile=true] for org.snmp4j.agent.mo.snmp.TestAndIncr[oid=1.3.6.1.6.3.1.1.6.1.0,access=MOAccessImpl{read|write|notify},value=0,volatile=true] in context ‘null’ successfully
279 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Removed registration org.snmp4j.agent.mo.snmp.TimeStampScalar[oid=1.3.6.1.2.1.1.8.0,access=MOAccessImpl{read|notify},value=0:00:00.00,volatile=true] for org.snmp4j.agent.mo.snmp.TimeStampScalar[oid=1.3.6.1.2.1.1.8.0,access=MOAccessImpl{read|notify},value=0:00:00.00,volatile=true] in context ‘null’ successfully
279 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Removed registration org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.11.1.0,access=MOAccessImpl{read|notify},value=0,volatile=true] for org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.11.1.0,access=MOAccessImpl{read|notify},value=0,volatile=true] in context ‘null’ successfully
279 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Removed registration org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.11.3.0,access=MOAccessImpl{read|notify},value=0,volatile=true] for org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.11.3.0,access=MOAccessImpl{read|notify},value=0,volatile=true] in context ‘null’ successfully
280 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Removed registration org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.11.4.0,access=MOAccessImpl{read|notify},value=0,volatile=true] for org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.11.4.0,access=MOAccessImpl{read|notify},value=0,volatile=true] in context ‘null’ successfully
280 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Removed registration org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.11.5.0,access=MOAccessImpl{read|notify},value=0,volatile=true] for org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.11.5.0,access=MOAccessImpl{read|notify},value=0,volatile=true] in context ‘null’ successfully
280 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Removed registration org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.11.6.0,access=MOAccessImpl{read|notify},value=0,volatile=true] for org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.11.6.0,access=MOAccessImpl{read|notify},value=0,volatile=true] in context ‘null’ successfully
280 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Removed registration org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.11.31.0,access=MOAccessImpl{read|notify},value=0,volatile=true] for org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.11.31.0,access=MOAccessImpl{read|notify},value=0,volatile=true] in context ‘null’ successfully
280 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Removed registration org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.11.32.0,access=MOAccessImpl{read|notify},value=0,volatile=true] for org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.11.32.0,access=MOAccessImpl{read|notify},value=0,volatile=true] in context ‘null’ successfully
280 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Removed registration DefaultMOTable[id=1.3.6.1.2.1.1.9.1,index=org.snmp4j.agent.mo.MOTableIndex@2fe50a11,columns=[org.snmp4j.agent.mo.MOColumn[columnID=2,syntax=6], org.snmp4j.agent.mo.snmp.DisplayString[columnID=3,syntax=4,default=null,mutableInService=true,mandatory=true], org.snmp4j.agent.mo.MOColumn[columnID=4,syntax=67]]] for DefaultMOTable[id=1.3.6.1.2.1.1.9.1,index=org.snmp4j.agent.mo.MOTableIndex@2fe50a11,columns=[org.snmp4j.agent.mo.MOColumn[columnID=2,syntax=6], org.snmp4j.agent.mo.snmp.DisplayString[columnID=3,syntax=4,default=null,mutableInService=true,mandatory=true], org.snmp4j.agent.mo.MOColumn[columnID=4,syntax=67]]] in context ‘null’ successfully
280 [Test worker] INFO org.snmp4j.agent.DefaultMOServer - Registered MO [MOScalar] in default context with scope org.snmp4j.agent.mo.MOScalar[oid=1.3.6.1.2.1.1.3.0,access=MOAccessImpl{read|notify},value=1235810,volatile=false]
282 [Test worker] INFO org.snmp4j.agent.mo.snmp.NotificationOriginatorImpl - Notification 1.3.6.1.6.3.1.1.5.1 reported with [] for context
283 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - UDP receive buffer size for socket 0.0.0.0/0 is set to: 65536
286 [Test worker] DEBUG org.snmp4j.security.UsmUserTable - Adding user snmptest_SHA_AES256 = UsmUser[secName=snmptest_SHA_AES256,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=12345678,privProtocol=1.3.6.1.4.1.4976.2.2.1.1.2,privPassphrase=12345678,localizationEngineID=null]
287 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - UDP receive buffer size for socket 0.0.0.0/0 is set to: 65536
292 [Test worker] DEBUG org.snmp4j.security.USM - RFC3414 §3.1.4.b Outgoing message is not encrypted
293 [Test worker] DEBUG org.snmp4j.mp.MPv3 - Adding cache entry: StateReference[msgID=1396056,pduHandle=PduHandle[1965471201],securityEngineID=,securityModel=org.snmp4j.security.USM@ab36887,securityName=snmptest_SHA_AES256,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null]
293 [Test worker] DEBUG org.snmp4j.Snmp - Running pending sync request with handle PduHandle[1965471201] and retry count left 3
293 [Test worker] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Sending message to 127.0.0.1/61836 with length 60: 30:3a:02:01:03:30:10:02:03:15:4d:58: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
294 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Received message from /127.0.0.1/61837 with length 60: 30:3a:02:01:03:30:10:02:03:15:4d:58: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
297 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.mp.MPv3 - SNMPv3 header decoded: msgId=1396056, msgMaxSize=65535, msgFlags=04, secModel=3
298 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.USM - RFC3414 §3.2.3 Unknown engine ID:
299 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.mp.MPv3 - Adding cache entry: StateReference[msgID=1396056,pduHandle=PduHandle[1969371185],securityEngineID=,securityModel=org.snmp4j.security.USM@ab36887,securityName=,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null]
300 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.mp.MPv3 - Removed cache entry: StateReference[msgID=1396056,pduHandle=PduHandle[1969371185],securityEngineID=,securityModel=org.snmp4j.security.USM@ab36887,securityName=,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null]
300 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.USM - RFC3414 §3.1.4.b Outgoing message is not encrypted
301 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Sending message to 127.0.0.1/61837 with length 103: 30:65:02:01:03:30:10:02:03:15:4d:58:02:03:00:ff:ff:04:01:00:02:01:03:04:1d:30:1b:04:0d:80:00:13:70:01:ac:1b:60:01:94:eb:58:30:02:01:00:02:01:00:04:00:04:00:04:00:30:2f:04:0d:80:00:13:70:01:ac:1b:60:01:94:eb:58:30: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
302 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Received message from /127.0.0.1/61836 with length 103: 30:65:02:01:03:30:10:02:03:15:4d:58:02:03:00:ff:ff:04:01:00:02:01:03:04:1d:30:1b:04:0d:80:00:13:70:01:ac:1b:60:01:94:eb:58:30:02:01:00:02:01:00:04:00:04:00:04:00:30:2f:04:0d:80:00:13:70:01:ac:1b:60:01:94:eb:58:30: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
302 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.mp.MPv3 - SNMPv3 header decoded: msgId=1396056, msgMaxSize=65535, msgFlags=00, secModel=3
302 [DefaultUDPTransportMapping_0.0.0.0/0] WARN org.snmp4j.MessageDispatcherImpl - statusInfo=1.3.6.1.6.3.15.1.1.4.0 = 1, status=1410
302 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.USM - Accepting zero length security name
303 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.mp.MPv3 - Removed cache entry: StateReference[msgID=1396056,pduHandle=PduHandle[1965471201],securityEngineID=,securityModel=org.snmp4j.security.USM@ab36887,securityName=snmptest_SHA_AES256,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null]
303 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.mp.MPv3 - RFC3412 §7.2.10 - Received PDU (msgID=1396056) is a response or an internal class message. PduHandle.transactionID = 1965471201
303 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.mp.MPv3 - MPv3 finished
CommandResponderEvent[securityModel=3, securityLevel=1, maxSizeResponsePDU=65428, pduHandle=PduHandle[1965471201], stateReference=null, pdu=REPORT[{contextEngineID=80:00:13:70:01:ac:1b:60:01:94:eb:58:30, contextName=}, requestID=0, errorStatus=0, errorIndex=0, VBS[1.3.6.1.6.3.15.1.1.4.0 = 1]], messageProcessingModel=3, securityName=, processed=false, peerAddress=127.0.0.1/61836, transportMapping=org.snmp4j.transport.DefaultUdpTransportMapping@525eeadc, tmStateReference=null]
304 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.Snmp - Searching pending request with handlePduHandle[1965471201]
305 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.Snmp - Send new request after report.
305 [DefaultUDPTransportMapping_0.0.0.0/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:ac:1b:60:01:94:eb:58:30
305 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.USM - getUser(engineID=80:00:13:70:01:ac:1b:60:01:94:eb:58:30, securityName=snmptest_SHA_AES256)
321 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.AuthGeneric - SHA-1First digest: 1e:d0:e0:66:f3:cd:2f:7c:d2:98:33:ef:ba:7a:32:bb:29:2e:6f:d4
322 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.AuthGeneric - SHA-1localized key: fa:ef:a4:f0:5a:c7:2f:be:b4:45:e3:31:a7:c5:bd:94:1e:34:35:86
328 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.AuthGeneric - SHA-1First digest: 1e:d0:e0:66:f3:cd:2f:7c:d2:98:33:ef:ba:7a:32:bb:29:2e:6f:d4
328 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.AuthGeneric - SHA-1localized key: fa:ef:a4:f0:5a:c7:2f:be:b4:45:e3:31:a7:c5:bd:94:1e:34:35:86
328 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.UsmUserTable - Adding user snmptest_SHA_AES256 = UsmUser[secName=snmptest_SHA_AES256,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=fa:ef:a4:f0:5a:c7:2f:be:b4:45:e3:31:a7:c5:bd:94:1e:34:35:86,privProtocol=1.3.6.1.4.1.4976.2.2.1.1.2,privPassphrase=fa:ef:a4:f0:5a:c7:2f:be:b4:45:e3:31:a7:c5:bd:94:1e:34:35:86:05:c8:1b:01:67:de:f9:24:19:4a:de:32,localizationEngineID=80:00:13:70:01:ac:1b:60:01:94:eb:58:30]
329 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.USM - RFC3414 §3.1.4.a Outgoing message needs to be encrypted
329 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.PrivAES - initVect is 00:00:00:00:00:00:00:00:0d:8d:b0:f4:7e:26:b1:b2
394 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.PrivAES - aes encrypt: Data to encrypt 30:2f:04:0d:80:00:13:70:01:ac:1b:60:01:94:eb:58:30:04:00:a0:1c:02:04:75:26:b5:e1:02:01:00:02:01:00:30:0e:30:0c:06:08:2b:06:01:02:01:01:03:00:05:00
394 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.PrivAES - aes encrypt: used key fa:ef:a4:f0:5a:c7:2f:be:b4:45:e3:31:a7:c5:bd:94:1e:34:35:86:05:c8:1b:01:67:de:f9:24:19:4a:de:32
394 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.PrivAES - aes encrypt: created privacy_params 0d:8d:b0:f4:7e:26:b1:b2
394 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.PrivAES - aes encrypt: encrypted Data 0b:97:c6:73:ef:0d:8b:75:c0:4a:d5:73:01:1e:2e:48:0c:9c:fa:22:59:e7:51:26:0e:d5:81:4d:34:1a:a2:b4:8d:4d:7e:f3:5a:c6:89:84:3e:29:fa:3b:89:7a:c7:59:c8
395 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.mp.MPv3 - Adding cache entry: StateReference[msgID=1396057,pduHandle=PduHandle[1965471201],securityEngineID=80:00:13:70:01:ac:1b:60:01:94:eb:58:30,securityModel=org.snmp4j.security.USM@ab36887,securityName=snmptest_SHA_AES256,securityLevel=3,contextEngineID=80:00:13:70:01:ac:1b:60:01:94:eb:58:30,contextName=,retryMsgIDs=null]
395 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Sending message to 127.0.0.1/61836 with length 145: 30:81:8e:02:01:03:30:10:02:03:15:4d:59:02:03:00:ff:ff:04:01:07:02:01:03:04:44:30:42:04:0d:80:00:13:70:01:ac:1b:60:01:94:eb:58:30:02:01:00:02:01:00:04:13:73:6e:6d:70:74:65:73:74:5f:53:48:41:5f:41:45:53:32:35:36:04:0c:61:6c:19:1f:b0:7a:1d:7c:6b:55:75:b5:04:08:0d:8d:b0:f4:7e:26:b1:b2:04:31:0b:97:c6:73:ef:0d:8b:75:c0:4a:d5:73:01:1e:2e:48:0c:9c:fa:22:59:e7:51:26:0e:d5:81:4d:34:1a:a2:b4:8d:4d:7e:f3:5a:c6:89:84:3e:29:fa:3b:89:7a:c7:59:c8
395 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Received message from /127.0.0.1/61837 with length 145: 30:81:8e:02:01:03:30:10:02:03:15:4d:59:02:03:00:ff:ff:04:01:07:02:01:03:04:44:30:42:04:0d:80:00:13:70:01:ac:1b:60:01:94:eb:58:30:02:01:00:02:01:00:04:13:73:6e:6d:70:74:65:73:74:5f:53:48:41:5f:41:45:53:32:35:36:04:0c:61:6c:19:1f:b0:7a:1d:7c:6b:55:75:b5:04:08:0d:8d:b0:f4:7e:26:b1:b2:04:31:0b:97:c6:73:ef:0d:8b:75:c0:4a:d5:73:01:1e:2e:48:0c:9c:fa:22:59:e7:51:26:0e:d5:81:4d:34:1a:a2:b4:8d:4d:7e:f3:5a:c6:89:84:3e:29:fa:3b:89:7a:c7:59:c8
395 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.mp.MPv3 - SNMPv3 header decoded: msgId=1396057, msgMaxSize=65535, msgFlags=07, secModel=3
395 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.USM - getUser(engineID=80:00:13:70:01:ac:1b:60:01:94:eb:58:30, securityName=snmptest_SHA_AES256)
396 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.UsmTimeTable - CheckTime: time ok (non authoritative)
396 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.PrivAES - initVect is 00:00:00:00:00:00:00:00:0d:8d:b0:f4:7e:26:b1:b2
397 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.mp.MPv3 - RFC3412 §7.2.10 - Received PDU is NOT a response or internal class message -> unchanged PduHandle = PduHandle[1965471201]
397 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.mp.MPv3 - Adding cache entry: StateReference[msgID=1396057,pduHandle=PduHandle[1965471201],securityEngineID=80:00:13:70:01:ac:1b:60:01:94:eb:58:30,securityModel=org.snmp4j.security.USM@ab36887,securityName=snmptest_SHA_AES256,securityLevel=3,contextEngineID=80:00:13:70:01:ac:1b:60:01:94:eb:58:30,contextName=,retryMsgIDs=null]
397 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.Snmp - Fire process PDU event: CommandResponderEvent[securityModel=3, securityLevel=3, maxSizeResponsePDU=65353, pduHandle=PduHandle[1965471201], stateReference=StateReference[msgID=1396057,pduHandle=null,securityEngineID=80:00:13:70:01:ac:1b:60:01:94:eb:58:30,securityModel=org.snmp4j.security.USM@ab36887,securityName=snmptest_SHA_AES256,securityLevel=3,contextEngineID=80:00:13:70:01:ac:1b:60:01:94:eb:58:30,contextName=,retryMsgIDs=null], pdu=GET[{contextEngineID=80:00:13:70:01:ac:1b:60:01:94:eb:58:30, contextName=}, requestID=1965471201, errorStatus=0, errorIndex=0, VBS[1.3.6.1.2.1.1.3.0 = Null]], messageProcessingModel=3, securityName=snmptest_SHA_AES256, processed=false, peerAddress=127.0.0.1/61837, transportMapping=org.snmp4j.transport.DefaultUdpTransportMapping@64aaafe5, tmStateReference=null]
402 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.agent.mo.snmp.VacmMIB - Found group name ‘v3group’ for secName ‘snmptest_SHA_AES256’ and secModel 3
403 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.agent.mo.snmp.VacmMIB - Got views [DefaultMOMutableRow2PC[index=7.118.51.103.114.111.117.112.0.3.3,values=[1, fullReadView, fullWriteView, fullNotifyView, 3, 1]] for group name ‘v3group’
403 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.agent.mo.snmp.VacmMIB - Matching against access entry DefaultMOMutableRow2PC[index=7.118.51.103.114.111.117.112.0.3.3,values=[1, fullReadView, fullWriteView, fullNotifyView, 3, 1] with exactContextMatch=true, prefixMatch=false, matchSecModel=true and matchSecLevel=true
403 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.agent.mo.snmp.VacmMIB - Matching view found for group name ‘v3group’ is ‘fullReadView’
405 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.agent.request.SnmpRequest - Created subrequest 0 with scope org.snmp4j.agent.DefaultMOContextScope[context=,lowerBound=1.3.6.1.2.1.1.3.0,lowerIncluded=true,upperBound=1.3.6.1.2.1.1.3.0,upperIncluded=true] from 1.3.6.1.2.1.1.3.0 = Null
405 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.agent.request.SnmpRequest - SnmpSubRequests initialized: [org.snmp4j.agent.request.SnmpRequest$SnmpSubRequest[scope=org.snmp4j.agent.DefaultMOContextScope[context=,lowerBound=1.3.6.1.2.1.1.3.0,lowerIncluded=true,upperBound=1.3.6.1.2.1.1.3.0,upperIncluded=true],vb=1.3.6.1.2.1.1.3.0 = Null,status=RequestStatus{processed=false, phaseComplete=false, errorStatus=0},query=null,index=0,targetMO=null]]
407 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.agent.mo.snmp.VacmMIB - Access allowed for view ‘fullReadView’ by subtree for OID 1.3.6.1.2.1.1.3.0
408 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.mp.MPv3 - Removed cache entry: StateReference[msgID=1396057,pduHandle=PduHandle[1965471201],securityEngineID=80:00:13:70:01:ac:1b:60:01:94:eb:58:30,securityModel=org.snmp4j.security.USM@ab36887,securityName=snmptest_SHA_AES256,securityLevel=3,contextEngineID=80:00:13:70:01:ac:1b:60:01:94:eb:58:30,contextName=,retryMsgIDs=null]
408 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.USM - RFC3414 §3.1.4.a Outgoing message needs to be encrypted
408 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.PrivAES - initVect is 00:00:00:00:00:00:00:00:0d:8d:b0:f4:7e:26:b1:b3
408 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.PrivAES - aes encrypt: Data to encrypt 30:32:04:0d:80:00:13:70:01:ac:1b:60:01:94:eb:58:30:04:00:a2:1f:02:04:75:26:b5:e1:02:01:00:02:01:00:30:11:30:0f:06:08:2b:06:01:02:01:01:03:00:02:03:12:db:62
408 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.PrivAES - aes encrypt: used key fa:ef:a4:f0:5a:c7:2f:be:b4:45:e3:31:a7:c5:bd:94:1e:34:35:86:05:c8:1b:01:67:de:f9:24:19:4a:de:32
408 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.PrivAES - aes encrypt: created privacy_params 0d:8d:b0:f4:7e:26:b1:b3
408 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.PrivAES - aes encrypt: encrypted Data ab:6e:c0:88:a2:b8:bf:80:40:ea:ce:0b:0a:54:92:c6:3b:09:26:26:5e:83:9f:3c:7e:d0:e9:7e:68:12:81:5c:c8:43:64:4d:95:e0:e0:70:11:c5:9c:83:e3:87:0f:1f:2a:c6:b2:5b
408 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Sending message to 127.0.0.1/61837 with length 148: 30:81:91:02:01:03:30:10:02:03:15:4d:59:02:03:00:ff:ff:04:01:03:02:01:03:04:44:30:42:04:0d:80:00:13:70:01:ac:1b:60:01:94:eb:58:30:02:01:00:02:01:00:04:13:73:6e:6d:70:74:65:73:74:5f:53:48:41:5f:41:45:53:32:35:36:04:0c:85:1e:f1:e4:15:94:ae:aa:a5:da:67:fd:04:08:0d:8d:b0:f4:7e:26:b1:b3:04:34:ab:6e:c0:88:a2:b8:bf:80:40:ea:ce:0b:0a:54:92:c6:3b:09:26:26:5e:83:9f:3c:7e:d0:e9:7e:68:12:81:5c:c8:43:64:4d:95:e0:e0:70:11:c5:9c:83:e3:87:0f:1f:2a:c6:b2:5b
409 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Received message from /127.0.0.1/61836 with length 148: 30:81:91:02:01:03:30:10:02:03:15:4d:59:02:03:00:ff:ff:04:01:03:02:01:03:04:44:30:42:04:0d:80:00:13:70:01:ac:1b:60:01:94:eb:58:30:02:01:00:02:01:00:04:13:73:6e:6d:70:74:65:73:74:5f:53:48:41:5f:41:45:53:32:35:36:04:0c:85:1e:f1:e4:15:94:ae:aa:a5:da:67:fd:04:08:0d:8d:b0:f4:7e:26:b1:b3:04:34:ab:6e:c0:88:a2:b8:bf:80:40:ea:ce:0b:0a:54:92:c6:3b:09:26:26:5e:83:9f:3c:7e:d0:e9:7e:68:12:81:5c:c8:43:64:4d:95:e0:e0:70:11:c5:9c:83:e3:87:0f:1f:2a:c6:b2:5b
409 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.mp.MPv3 - SNMPv3 header decoded: msgId=1396057, msgMaxSize=65535, msgFlags=03, secModel=3
409 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.USM - getUser(engineID=80:00:13:70:01:ac:1b:60:01:94:eb:58:30, securityName=snmptest_SHA_AES256)
409 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.UsmTimeTable - CheckTime: time ok (non authoritative)
409 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.security.PrivAES - initVect is 00:00:00:00:00:00:00:00:0d:8d:b0:f4:7e:26:b1:b3
409 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.mp.MPv3 - Removed cache entry: StateReference[msgID=1396057,pduHandle=PduHandle[1965471201],securityEngineID=80:00:13:70:01:ac:1b:60:01:94:eb:58:30,securityModel=org.snmp4j.security.USM@ab36887,securityName=snmptest_SHA_AES256,securityLevel=3,contextEngineID=80:00:13:70:01:ac:1b:60:01:94:eb:58:30,contextName=,retryMsgIDs=null]
409 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.mp.MPv3 - RFC3412 §7.2.10 - Received PDU (msgID=1396057) is a response or an internal class message. PduHandle.transactionID = 1965471201
409 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.mp.MPv3 - MPv3 finished
CommandResponderEvent[securityModel=3, securityLevel=3, maxSizeResponsePDU=65353, pduHandle=PduHandle[1965471201], stateReference=null, pdu=RESPONSE[{contextEngineID=80:00:13:70:01:ac:1b:60:01:94:eb:58:30, contextName=}, requestID=1965471201, errorStatus=0, errorIndex=0, VBS[1.3.6.1.2.1.1.3.0 = 1235810]], messageProcessingModel=3, securityName=snmptest_SHA_AES256, processed=false, peerAddress=127.0.0.1/61836, transportMapping=org.snmp4j.transport.DefaultUdpTransportMapping@525eeadc, tmStateReference=null]
410 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.Snmp - Looking up pending request with handle PduHandle[1965471201]
410 [Test worker] DEBUG org.snmp4j.Snmp - Removed pending request with handle: PduHandle[1965471201]
<<<<<<< Change user name >>>>>>>>>
414 [Test worker] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Terminated worker task: org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
414 [Test worker] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Interrupting worker task: org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
414 [Test worker] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Joining worker task: org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
414 [DefaultUDPTransportMapping_0.0.0.0/0] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Worker task stopped:org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
415 [Test worker] INFO org.snmp4j.agent.cfg.EngineBootsCounterFile - Engine boots is: 21
416 [Test worker] INFO org.snmp4j.agent.cfg.EngineBootsCounterFile - Wrote boot counter: 22
422 [Test worker] DEBUG org.snmp4j.security.AuthGeneric - SHA-1First digest: 1e:d0:e0:66:f3:cd:2f:7c:d2:98:33:ef:ba:7a:32:bb:29:2e:6f:d4
422 [Test worker] DEBUG org.snmp4j.security.AuthGeneric - SHA-1localized key: fa:ef:a4:f0:5a:c7:2f:be:b4:45:e3:31:a7:c5:bd:94:1e:34:35:86
428 [Test worker] DEBUG org.snmp4j.security.AuthGeneric - SHA-1First digest: 1e:d0:e0:66:f3:cd:2f:7c:d2:98:33:ef:ba:7a:32:bb:29:2e:6f:d4
428 [Test worker] DEBUG org.snmp4j.security.AuthGeneric - SHA-1localized key: fa:ef:a4:f0:5a:c7:2f:be:b4:45:e3:31:a7:c5:bd:94:1e:34:35:86
428 [Test worker] DEBUG org.snmp4j.security.UsmUserTable - Adding user snmptest_SHA_AES256_1 = UsmUser[secName=snmptest_SHA_AES256_1,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=12345678,privProtocol=1.3.6.1.4.1.4976.2.2.1.1.2,privPassphrase=12345678,localizationEngineID=null]
432 [Test worker] INFO org.snmp4j.agent.mo.snmp.NotificationOriginatorImpl - Notification 1.3.6.1.6.3.1.1.5.1 reported with [] for context
<<<<<<< Query >>>>>>>>>
433 [DefaultUDPTransportMapping_0.0.0.0/61836] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - UDP receive buffer size for socket 0.0.0.0/61836 is set to: 65536
434 [Test worker] DEBUG org.snmp4j.security.USM - getUser(engineID=80:00:13:70:01:ac:1b:60:01:94:eb:58:30, securityName=snmptest_SHA_AES256)
434 [Test worker] DEBUG org.snmp4j.security.USM - USM.getUser - User ‘snmptest_SHA_AES256’ unknown
434 [Test worker] DEBUG org.snmp4j.security.USM - Security name not found for engineID=80:00:13:70:01:ac:1b:60:01:94:eb:58:30, securityName=73:6e:6d:70:74:65:73:74:5f:53:48:41:5f:41:45:53:32:35:36
437 [Test worker] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Terminated worker task: org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
437 [Test worker] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Interrupting worker task: org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
438 [Test worker] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Joining worker task: org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
438 [DefaultUDPTransportMapping_0.0.0.0/61836] DEBUG org.snmp4j.transport.DefaultUdpTransportMapping - Worker task stopped:org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
Thanks in advance.

AGENTPP · April 5, 2021, 1:48pm

That engine ID is only in the initial log and in the request log after the password change, but not in the log of the password change itself. Could it be, that you are using a different authoritative engine ID for the command responder after the password change than before?

Besides that, I do not see any “exception” in the log, which was your initial topic. Thus, we now do not know what your problem with the existing behaviour is now?

In addition, it is not which log is of the command sender and which belongs to the command responder?
The last log part even does not contain any send or received packets - very strange (it seems that it is from the command sender and that sender fails to send the request, because the user to be used cannot be found in the USM.