Snmp4j 2.8 Encryption error for Triumph-Adler 3206ci printer

Hi all,

There is an issue in snm4j 2.8.0 (I didn’t try 3.1 because we not wiling to move to java 9+), we get Encryption error when trying to get snmp data from Triumph-Adler 3206ci printer using snmpv3 with both privacy and encryption. The printer can be reached by other snmp clients like Paessler SNMP Tester using the same snmp v3 parameters.

Can this issue be fixed in version 2.8, or is it already fixed in 3.1?

Bellow is the snmp4j log to help you debug it:

Blockquote
Jan 16, 2020 2:40:55 PM com.ibm.infoprint.snmp.test.TestGetAllV2 setupLog
INFO:

***** SNMP4J LOG INITIALIZED *****
VERSION: 2.8.0

Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: Initialized Salt to be3ef89a7681eb8f.
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: UDP receive buffer size for socket 0.0.0.0/0 is set to: 65536
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3414 §3.1.4.b Outgoing message is not encrypted
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: Adding cache entry: StateReference[msgID=150208089,pduHandle=PduHandle[1603161604],securityEngineID=,securityModel=org.snmp4j.security.USM@674e2e92,securityName=,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null]
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: Running pending sync request with handle PduHandle[1603161604] and retry count left 0
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: Sending message to 172.21.14.173/161 with length 61: 30:3b:02:01:03:30:11:02:04:08:f3:fe:59: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
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: Received message from /172.21.14.173/161 with length 107: 30:69:02:01:03:30:11:02:04:08:f3:fe:59:02:03:00:ff:e3:04:01:00:02:01:03:04:1f:30:1d:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:02:01:01:02:03:3b:6c:a5:04:00:04:00:04:00:30:30:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:04:00:a8:1d:02:01:00:02:01:00:02:01:00:30:12:30:10:06:0a:2b:06:01:06:03:0f:01:01:04:00:41:02:37:0c
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: SNMPv3 header decoded: msgId=150208089, msgMaxSize=65507, msgFlags=00, secModel=3
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: Accepting zero length security name
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed cache entry: StateReference[msgID=150208089,pduHandle=null,securityEngineID=,securityModel=org.snmp4j.security.USM@674e2e92,securityName=,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null]
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3412 §7.2.10 - Received PDU (msgID=150208089) is a response or an internal class message. PduHandle.transactionID = 1603161604
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: MPv3 finished
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: Searching pending request with handlePduHandle[1603161604]
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed pending request with handle: PduHandle[1603161604]
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1First digest: 6b:22:35:cb:01:77:75:b4:c5:16:48:d7:11:f3:d3:59:aa:a9:ec:3b
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1localized key: 42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1First digest: 6b:22:35:cb:01:77:75:b4:c5:16:48:d7:11:f3:d3:59:aa:a9:ec:3b
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1localized key: 42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: Adding user 37:62:66:75:50:56:44:6e:4d:3f:00 = UsmUser[secName=37:62:66:75:50:56:44:6e:4d:3f:00,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52,privProtocol=1.3.6.1.4.1.4976.2.2.1.1.2,privPassphrase=42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52:1e:e6:a8:f1:fa:a0:d3:9a:2b:1f:d2:da,localizationEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25]
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: Context engine ID of scoped PDU is empty! Setting it to authoritative engine ID: 80:00:05:43:80:52:89:16:56:5d:e4:fb:25
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: getUser(engineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25, securityName=37:62:66:75:50:56:44:6e:4d:3f:00)
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3414 §3.1.4.a Outgoing message needs to be encrypted
Jan 16, 2020 2:40:56 PM org.snmp4j.log.JavaLogAdapter log
FINE: initVect is 00:00:00:01:00:3b:6c:a5:be:3e:f8:9a:76:81:eb:8f
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
SEVERE: Encrypt Exception java.security.InvalidKeyException: Illegal key size
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: Encryption error
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3414 §3.1.4.b Outgoing message is not encrypted
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: Adding cache entry: StateReference[msgID=150208091,pduHandle=PduHandle[1603161607],securityEngineID=,securityModel=org.snmp4j.security.USM@674e2e92,securityName=,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null]
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: Running pending sync request with handle PduHandle[1603161607] and retry count left 0
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: Sending message to 172.21.14.173/161 with length 61: 30:3b:02:01:03:30:11:02:04:08:f3:fe:5b: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
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: Received message from /172.21.14.173/161 with length 107: 30:69:02:01:03:30:11:02:04:08:f3:fe:5b:02:03:00:ff:e3:04:01:00:02:01:03:04:1f:30:1d:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:02:01:01:02:03:3b:6c:a5:04:00:04:00:04:00:30:30:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:04:00:a8:1d:02:01:00:02:01:00:02:01:00:30:12:30:10:06:0a:2b:06:01:06:03:0f:01:01:04:00:41:02:37:0d
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: SNMPv3 header decoded: msgId=150208091, msgMaxSize=65507, msgFlags=00, secModel=3
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: Accepting zero length security name
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed cache entry: StateReference[msgID=150208091,pduHandle=null,securityEngineID=,securityModel=org.snmp4j.security.USM@674e2e92,securityName=,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null]
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3412 §7.2.10 - Received PDU (msgID=150208091) is a response or an internal class message. PduHandle.transactionID = 1603161607
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: MPv3 finished
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: Searching pending request with handlePduHandle[1603161607]
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed pending request with handle: PduHandle[1603161607]
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1First digest: 6b:22:35:cb:01:77:75:b4:c5:16:48:d7:11:f3:d3:59:aa:a9:ec:3b
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1localized key: 42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1First digest: 6b:22:35:cb:01:77:75:b4:c5:16:48:d7:11:f3:d3:59:aa:a9:ec:3b
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1localized key: 42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: Adding user 37:62:66:75:50:56:44:6e:4d:3f:00 = UsmUser[secName=37:62:66:75:50:56:44:6e:4d:3f:00,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52,privProtocol=1.3.6.1.4.1.4976.2.2.1.1.2,privPassphrase=42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52:1e:e6:a8:f1:fa:a0:d3:9a:2b:1f:d2:da,localizationEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25]
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: Context engine ID of scoped PDU is empty! Setting it to authoritative engine ID: 80:00:05:43:80:52:89:16:56:5d:e4:fb:25
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: getUser(engineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25, securityName=37:62:66:75:50:56:44:6e:4d:3f:00)
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3414 §3.1.4.a Outgoing message needs to be encrypted
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: initVect is 00:00:00:01:00:3b:6c:a5:be:3e:f8:9a:76:81:eb:90
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
SEVERE: Encrypt Exception java.security.InvalidKeyException: Illegal key size
Jan 16, 2020 2:40:57 PM org.snmp4j.log.JavaLogAdapter log
FINE: Encryption error
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Terminated worker task: org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Interrupting worker task: org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Joining worker task: org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Worker task stopped:org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3414 §3.1.4.b Outgoing message is not encrypted
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Adding cache entry: StateReference[msgID=58471,pduHandle=PduHandle[687523168],securityEngineID=,securityModel=org.snmp4j.security.USM@6559dab8,securityName=,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null]
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Running pending sync request with handle PduHandle[687523168] and retry count left 0
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Sending message to 172.21.14.173/161 with length 60: 30:3a:02:01:03:30:10:02:03:00:e4:67: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
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: UDP receive buffer size for socket 0.0.0.0/0 is set to: 65536
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Received message from /172.21.14.173/161 with length 106: 30:68:02:01:03:30:10:02:03:00:e4:67:02:03:00:ff:e3:04:01:00:02:01:03:04:1f:30:1d:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:02:01:01:02:03:3b:6e:33:04:00:04:00:04:00:30:30:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:04:00:a8:1d:02:01:00:02:01:00:02:01:00:30:12:30:10:06:0a:2b:06:01:06:03:0f:01:01:04:00:41:02:37:0e
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: SNMPv3 header decoded: msgId=58471, msgMaxSize=65507, msgFlags=00, secModel=3
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Accepting zero length security name
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed cache entry: StateReference[msgID=58471,pduHandle=null,securityEngineID=,securityModel=org.snmp4j.security.USM@6559dab8,securityName=,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null]
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3412 §7.2.10 - Received PDU (msgID=58471) is a response or an internal class message. PduHandle.transactionID = 687523168
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: MPv3 finished
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Searching pending request with handlePduHandle[687523168]
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed pending request with handle: PduHandle[687523168]
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1First digest: 6b:22:35:cb:01:77:75:b4:c5:16:48:d7:11:f3:d3:59:aa:a9:ec:3b
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1localized key: 42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1First digest: 6b:22:35:cb:01:77:75:b4:c5:16:48:d7:11:f3:d3:59:aa:a9:ec:3b
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1localized key: 42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Adding user read = UsmUser[secName=read,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52,privProtocol=1.3.6.1.4.1.4976.2.2.1.1.2,privPassphrase=42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52:1e:e6:a8:f1:fa:a0:d3:9a:2b:1f:d2:da,localizationEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25]
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Context engine ID of scoped PDU is empty! Setting it to authoritative engine ID: 80:00:05:43:80:52:89:16:56:5d:e4:fb:25
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: getUser(engineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25, securityName=read)
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3414 §3.1.4.a Outgoing message needs to be encrypted
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: initVect is 00:00:00:01:00:3b:6e:33:be:3e:f8:9a:76:81:eb:91
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
SEVERE: Encrypt Exception java.security.InvalidKeyException: Illegal key size
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Encryption error
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3414 §3.1.4.b Outgoing message is not encrypted
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Adding cache entry: StateReference[msgID=58473,pduHandle=PduHandle[687523171],securityEngineID=,securityModel=org.snmp4j.security.USM@6559dab8,securityName=,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null]
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Running pending sync request with handle PduHandle[687523171] and retry count left 0
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Sending message to 172.21.14.173/161 with length 60: 30:3a:02:01:03:30:10:02:03:00:e4:69: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
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Received message from /172.21.14.173/161 with length 106: 30:68:02:01:03:30:10:02:03:00:e4:69:02:03:00:ff:e3:04:01:00:02:01:03:04:1f:30:1d:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:02:01:01:02:03:3b:6e:33:04:00:04:00:04:00:30:30:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:04:00:a8:1d:02:01:00:02:01:00:02:01:00:30:12:30:10:06:0a:2b:06:01:06:03:0f:01:01:04:00:41:02:37:0f
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: SNMPv3 header decoded: msgId=58473, msgMaxSize=65507, msgFlags=00, secModel=3
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Accepting zero length security name
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed cache entry: StateReference[msgID=58473,pduHandle=null,securityEngineID=,securityModel=org.snmp4j.security.USM@6559dab8,securityName=,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null]
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3412 §7.2.10 - Received PDU (msgID=58473) is a response or an internal class message. PduHandle.transactionID = 687523171
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: MPv3 finished
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Searching pending request with handlePduHandle[687523171]
Jan 16, 2020 2:47:34 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed pending request with handle: PduHandle[687523171]
Jan 16, 2020 2:47:35 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1First digest: 6b:22:35:cb:01:77:75:b4:c5:16:48:d7:11:f3:d3:59:aa:a9:ec:3b
Jan 16, 2020 2:47:35 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1localized key: 42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52
Jan 16, 2020 2:47:35 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1First digest: 6b:22:35:cb:01:77:75:b4:c5:16:48:d7:11:f3:d3:59:aa:a9:ec:3b
Jan 16, 2020 2:47:35 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1localized key: 42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52
Jan 16, 2020 2:47:35 PM org.snmp4j.log.JavaLogAdapter log
FINE: Adding user read = UsmUser[secName=read,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52,privProtocol=1.3.6.1.4.1.4976.2.2.1.1.2,privPassphrase=42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52:1e:e6:a8:f1:fa:a0:d3:9a:2b:1f:d2:da,localizationEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25]
Jan 16, 2020 2:47:35 PM org.snmp4j.log.JavaLogAdapter log
FINE: Context engine ID of scoped PDU is empty! Setting it to authoritative engine ID: 80:00:05:43:80:52:89:16:56:5d:e4:fb:25
Jan 16, 2020 2:47:35 PM org.snmp4j.log.JavaLogAdapter log
FINE: getUser(engineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25, securityName=read)
Jan 16, 2020 2:47:35 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3414 §3.1.4.a Outgoing message needs to be encrypted
Jan 16, 2020 2:47:35 PM org.snmp4j.log.JavaLogAdapter log
FINE: initVect is 00:00:00:01:00:3b:6e:33:be:3e:f8:9a:76:81:eb:92
Jan 16, 2020 2:47:35 PM org.snmp4j.log.JavaLogAdapter log
SEVERE: Encrypt Exception java.security.InvalidKeyException: Illegal key size
Jan 16, 2020 2:47:35 PM org.snmp4j.log.JavaLogAdapter log
FINE: Encryption error
Jan 16, 2020 2:48:01 PM org.snmp4j.log.JavaLogAdapter log
FINE: Terminated worker task: org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
Jan 16, 2020 2:48:01 PM org.snmp4j.log.JavaLogAdapter log
FINE: Interrupting worker task: org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
Jan 16, 2020 2:48:01 PM org.snmp4j.log.JavaLogAdapter log
FINE: Joining worker task: org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread
Jan 16, 2020 2:48:01 PM org.snmp4j.log.JavaLogAdapter log
FINE: Worker task stopped:org.snmp4j.transport.DefaultUdpTransportMapping$ListenThread

It is not a bug in SNMP4J! It is an error in your usage/configuration. You cannot use SHA-1 authentication with a AES256-With-3DES-Key-Extension privacy protocol because the SHA-1 key is too short for AES256. I doubt that this configuration would work with any other standard conforming SNMP API or tool.

Why are you using AES256 instead of the standard AES128? And why the special (Cisco like) 3DES key extension?

With such a weak authentication protocol (SHA-1) in use you will not gain any additional security but waste a lot of CPU cycles (and CO2).

Hi Frank,

Many thanks for your input and quick response.

Since our client’s printer snmpv3 configuration page shows just AES, he got confused and tried with all 3 AES protocols (128, 192 and 256). He claims no one worked, including AES-128. I ask him to recreate the problem using just with AES-128 and collect snmp4j logs, after I will come back to you with those logs.

Have a nice day
Piri

Hi Frank,

Here are the snmp4j log, with right snmpv3 parameters (SHA and AES-128), for the situation when the printer in question cannot be reached by snmp4j. But the same printer can be reached with Paessler SNMP tester, using the same snmpv3 parameters.

Jan 23, 2020 12:15:43 PM com.ibm.infoprint.snmp.test.TestGetAllV2 setupLog
INFO:

***** SNMP4J LOG INITIALIZED *****
VERSION: 2.8.0

Jan 23, 2020 12:16:08 PM org.snmp4j.log.JavaLogAdapter log
FINE: Initialized Salt to 57d706432e4b86f2.
Jan 23, 2020 12:16:08 PM org.snmp4j.log.JavaLogAdapter log
FINE: UDP receive buffer size for socket 0.0.0.0/0 is set to: 65536
Jan 23, 2020 12:16:08 PM org.snmp4j.log.JavaLogAdapter log
FINE: Running pending sync request with handle PduHandle[1240369123] and retry count left 1
Jan 23, 2020 12:16:08 PM org.snmp4j.log.JavaLogAdapter log
FINE: Running pending sync request with handle PduHandle[1240369124] and retry count left 1
Jan 23, 2020 12:16:08 PM org.snmp4j.log.JavaLogAdapter log
FINE: Sending message to 172.21.14.173/161 with length 43: 30:29:02:01:00:04:06:70:75:62:6c:69:63:a0:1c:02:04:49:ee:87:e3:02:01:00:02:01:00:30:0e:30:0c:06:08:2b:06:01:02:01:01:01:00:05:00
Jan 23, 2020 12:16:08 PM org.snmp4j.log.JavaLogAdapter log
FINE: Sending message to 172.21.14.173/161 with length 43: 30:29:02:01:00:04:06:70:75:62:6c:69:63:a0:1c:02:04:49:ee:87:e4:02:01:00:02:01:00:30:0e:30:0c:06:08:2b:06:01:02:01:01:01:00:05:00
Jan 23, 2020 12:16:10 PM org.snmp4j.log.JavaLogAdapter log
FINE: Running pending sync request with handle PduHandle[1240369123] and retry count left 0
Jan 23, 2020 12:16:10 PM org.snmp4j.log.JavaLogAdapter log
FINE: Sending message to 172.21.14.173/161 with length 43: 30:29:02:01:00:04:06:70:75:62:6c:69:63:a0:1c:02:04:49:ee:87:e3:02:01:00:02:01:00:30:0e:30:0c:06:08:2b:06:01:02:01:01:01:00:05:00
Jan 23, 2020 12:16:10 PM org.snmp4j.log.JavaLogAdapter log
FINE: Running pending sync request with handle PduHandle[1240369124] and retry count left 0
Jan 23, 2020 12:16:10 PM org.snmp4j.log.JavaLogAdapter log
FINE: Sending message to 172.21.14.173/161 with length 43: 30:29:02:01:00:04:06:70:75:62:6c:69:63:a0:1c:02:04:49:ee:87:e4:02:01:00:02:01:00:30:0e:30:0c:06:08:2b:06:01:02:01:01:01:00:05:00
Jan 23, 2020 12:16:12 PM org.snmp4j.log.JavaLogAdapter log
FINE: Request timed out: 1240369123
Jan 23, 2020 12:16:12 PM org.snmp4j.log.JavaLogAdapter log
FINE: Request timed out: 1240369124
Jan 23, 2020 12:16:12 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed pending request with handle: PduHandle[1240369124]
Jan 23, 2020 12:16:12 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed pending request with handle: PduHandle[1240369123]
Jan 23, 2020 12:16:12 PM org.snmp4j.log.JavaLogAdapter log
FINE: Running pending sync request with handle PduHandle[1240369125] and retry count left 1
Jan 23, 2020 12:16:12 PM org.snmp4j.log.JavaLogAdapter log
FINE: Running pending sync request with handle PduHandle[1240369126] and retry count left 1
Jan 23, 2020 12:16:12 PM org.snmp4j.log.JavaLogAdapter log
FINE: Sending message to 172.21.14.173/161 with length 43: 30:29:02:01:00:04:06:70:75:62:6c:69:63:a0:1c:02:04:49:ee:87:e5:02:01:00:02:01:00:30:0e:30:0c:06:08:2b:06:01:02:01:01:01:00:05:00
Jan 23, 2020 12:16:12 PM org.snmp4j.log.JavaLogAdapter log
FINE: Sending message to 172.21.14.173/161 with length 43: 30:29:02:01:00:04:06:70:75:62:6c:69:63:a0:1c:02:04:49:ee:87:e6:02:01:00:02:01:00:30:0e:30:0c:06:08:2b:06:01:02:01:01:01:00:05:00
Jan 23, 2020 12:16:14 PM org.snmp4j.log.JavaLogAdapter log
FINE: Running pending sync request with handle PduHandle[1240369125] and retry count left 0
Jan 23, 2020 12:16:14 PM org.snmp4j.log.JavaLogAdapter log
FINE: Sending message to 172.21.14.173/161 with length 43: 30:29:02:01:00:04:06:70:75:62:6c:69:63:a0:1c:02:04:49:ee:87:e5:02:01:00:02:01:00:30:0e:30:0c:06:08:2b:06:01:02:01:01:01:00:05:00
Jan 23, 2020 12:16:14 PM org.snmp4j.log.JavaLogAdapter log
FINE: Running pending sync request with handle PduHandle[1240369126] and retry count left 0
Jan 23, 2020 12:16:14 PM org.snmp4j.log.JavaLogAdapter log
FINE: Sending message to 172.21.14.173/161 with length 43: 30:29:02:01:00:04:06:70:75:62:6c:69:63:a0:1c:02:04:49:ee:87:e6:02:01:00:02:01:00:30:0e:30:0c:06:08:2b:06:01:02:01:01:01:00:05:00
Jan 23, 2020 12:16:16 PM org.snmp4j.log.JavaLogAdapter log
FINE: Request timed out: 1240369125
Jan 23, 2020 12:16:16 PM org.snmp4j.log.JavaLogAdapter log
FINE: Request timed out: 1240369126
Jan 23, 2020 12:16:16 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed pending request with handle: PduHandle[1240369126]
Jan 23, 2020 12:16:16 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed pending request with handle: PduHandle[1240369125]
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3414 §3.1.4.b Outgoing message is not encrypted
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: Adding cache entry: StateReference[msgID=131835109,pduHandle=PduHandle[1240369127],securityEngineID=,securityModel=org.snmp4j.security.USM@73f36ef9,securityName=,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null]
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: Running pending sync request with handle PduHandle[1240369127] and retry count left 0
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: Sending message to 172.21.14.173/161 with length 61: 30:3b:02:01:03:30:11:02:04:07:db:a4:e5: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
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: Received message from /172.21.14.173/161 with length 107: 30:69:02:01:03:30:11:02:04:07:db:a4:e5:02:03:00:ff:e3:04:01:00:02:01:03:04:1f:30:1d:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:02:01:01:02:03:44:85:dc:04:00:04:00:04:00:30:30:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:04:00:a8:1d:02:01:00:02:01:00:02:01:00:30:12:30:10:06:0a:2b:06:01:06:03:0f:01:01:04:00:41:02:42:2a
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: SNMPv3 header decoded: msgId=131835109, msgMaxSize=65507, msgFlags=00, secModel=3
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: Accepting zero length security name
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed cache entry: StateReference[msgID=131835109,pduHandle=null,securityEngineID=,securityModel=org.snmp4j.security.USM@73f36ef9,securityName=,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null]
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3412 §7.2.10 - Received PDU (msgID=131835109) is a response or an internal class message. PduHandle.transactionID = 1240369127
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: MPv3 finished
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: Searching pending request with handlePduHandle[1240369127]
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed pending request with handle: PduHandle[1240369127]
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1First digest: 6b:22:35:cb:01:77:75:b4:c5:16:48:d7:11:f3:d3:59:aa:a9:ec:3b
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1localized key: 42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1First digest: 6b:22:35:cb:01:77:75:b4:c5:16:48:d7:11:f3:d3:59:aa:a9:ec:3b
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1localized key: 42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: Adding user read = UsmUser[secName=read,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52,privProtocol=1.3.6.1.6.3.10.1.2.4,privPassphrase=42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef,localizationEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25]
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: Context engine ID of scoped PDU is empty! Setting it to authoritative engine ID: 80:00:05:43:80:52:89:16:56:5d:e4:fb:25
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: getUser(engineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25, securityName=read)
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3414 §3.1.4.a Outgoing message needs to be encrypted
Jan 23, 2020 12:19:00 PM org.snmp4j.log.JavaLogAdapter log
FINE: initVect is 00:00:00:01:00:44:85:dc:57:d7:06:43:2e:4b:86:f2
Jan 23, 2020 12:19:01 PM org.snmp4j.log.JavaLogAdapter log
FINE: aes encrypt: Data to encrypt 30:2f:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:04:00:a0:1c:02:04:49:ee:87:e9:02:01:00:02:01:00:30:0e:30:0c:06:08:2b:06:01:02:01:01:01:00:05:00
Jan 23, 2020 12:19:01 PM org.snmp4j.log.JavaLogAdapter log
FINE: aes encrypt: used key 42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef
Jan 23, 2020 12:19:01 PM org.snmp4j.log.JavaLogAdapter log
FINE: aes encrypt: created privacy_params 57:d7:06:43:2e:4b:86:f2
Jan 23, 2020 12:19:01 PM org.snmp4j.log.JavaLogAdapter log
FINE: aes encrypt: encrypted Data a5:01:88:5f:62:c2:c7:2f:ae:87:8e:14:9e:0d:e0:9e:78:5e:5c:d4:e6:fb:85:55:80:66:3f:ab:df:76:46:65:1a:5b:7f:a5:cd:b5:80:a1:e6:a2:11:94:de:64:bf:43:23
Jan 23, 2020 12:19:01 PM org.snmp4j.log.JavaLogAdapter log
FINE: Adding cache entry: StateReference[msgID=131835110,pduHandle=PduHandle[1240369129],securityEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25,securityModel=org.snmp4j.security.USM@73f36ef9,securityName=read,securityLevel=3,contextEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25,contextName=,retryMsgIDs=null]
Jan 23, 2020 12:19:01 PM org.snmp4j.log.JavaLogAdapter log
FINE: Running pending sync request with handle PduHandle[1240369129] and retry count left 1
Jan 23, 2020 12:19:01 PM org.snmp4j.log.JavaLogAdapter log
FINE: Sending message to 172.21.14.173/161 with length 133: 30:81:82:02:01:03:30:11:02:04:07:db:a4:e6:02:03:00:ff:ff:04:01:07:02:01:03:04:37:30:35:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:02:01:01:02:03:44:85:dc:04:04:72:65:61:64:04:0c:13:9d:01:f4:25:86:80:97:c6:74:2c:a4:04:08:57:d7:06:43:2e:4b:86:f2:04:31:a5:01:88:5f:62:c2:c7:2f:ae:87:8e:14:9e:0d:e0:9e:78:5e:5c:d4:e6:fb:85:55:80:66:3f:ab:df:76:46:65:1a:5b:7f:a5:cd:b5:80:a1:e6:a2:11:94:de:64:bf:43:23
Jan 23, 2020 12:19:01 PM org.snmp4j.log.JavaLogAdapter log
FINE: Received message from /172.21.14.173/161 with length 110: 30:6c:02:01:03:30:11:02:04:07:db:a4:e6:02:03:00:ff:e3:04:01:00:02:01:03:04:23:30:21:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:02:01:01:02:03:44:85:dd:04:04:72:65:61:64:04:00:04:00:30:2f:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25: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:05:00:41:01:53
Jan 23, 2020 12:19:01 PM org.snmp4j.log.JavaLogAdapter log
FINE: SNMPv3 header decoded: msgId=131835110, msgMaxSize=65507, msgFlags=00, secModel=3
Jan 23, 2020 12:19:01 PM org.snmp4j.log.JavaLogAdapter log
FINE: getUser(engineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25, securityName=read)
Jan 23, 2020 12:19:01 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed cache entry: StateReference[msgID=131835110,pduHandle=null,securityEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25,securityModel=org.snmp4j.security.USM@73f36ef9,securityName=read,securityLevel=3,contextEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25,contextName=,retryMsgIDs=null]
Jan 23, 2020 12:19:01 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3412 §7.2.10 - Received PDU (msgID=131835110) is a response or an internal class message. PduHandle.transactionID = 1240369129
Jan 23, 2020 12:19:01 PM org.snmp4j.log.JavaLogAdapter log
FINE: MPv3 finished
Jan 23, 2020 12:19:01 PM org.snmp4j.log.JavaLogAdapter log
FINE: Searching pending request with handlePduHandle[1240369129]
Jan 23, 2020 12:19:01 PM org.snmp4j.log.JavaLogAdapter log
WARNING: RFC3412 §7.2.11.b:Received REPORT PDU with security level noAuthNoPriv from ‘CommandResponderEvent[securityModel=3, securityLevel=1, maxSizeResponsePDU=65400, pduHandle=PduHandle[1240369129], stateReference=null, pdu=REPORT[{contextEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25, contextName=}, requestID=0, errorStatus=0, errorIndex=0, VBS[1.3.6.1.6.3.15.1.1.5.0 = 83]], messageProcessingModel=3, securityName=read, processed=true, peerAddress=172.21.14.173/161, transportMapping=org.snmp4j.transport.DefaultUdpTransportMapping@3cbb1afb, tmStateReference=null]’. Ignoring it, because report strategy is set to standard
Jan 23, 2020 12:19:03 PM org.snmp4j.log.JavaLogAdapter log
FINE: getUser(engineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25, securityName=read)
Jan 23, 2020 12:19:03 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3414 §3.1.4.a Outgoing message needs to be encrypted
Jan 23, 2020 12:19:03 PM org.snmp4j.log.JavaLogAdapter log
FINE: initVect is 00:00:00:01:00:44:85:df:57:d7:06:43:2e:4b:86:f3
Jan 23, 2020 12:19:03 PM org.snmp4j.log.JavaLogAdapter log
FINE: aes encrypt: Data to encrypt 30:2f:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:04:00:a0:1c:02:04:49:ee:87:e9:02:01:00:02:01:00:30:0e:30:0c:06:08:2b:06:01:02:01:01:01:00:05:00
Jan 23, 2020 12:19:03 PM org.snmp4j.log.JavaLogAdapter log
FINE: aes encrypt: used key 42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef
Jan 23, 2020 12:19:03 PM org.snmp4j.log.JavaLogAdapter log
FINE: aes encrypt: created privacy_params 57:d7:06:43:2e:4b:86:f3
Jan 23, 2020 12:19:03 PM org.snmp4j.log.JavaLogAdapter log
FINE: aes encrypt: encrypted Data d1:c9:6b:14:9d:6d:25:07:8d:f2:dd:79:19:fd:ea:d3:0c:0f:f5:c0:07:e3:58:36:19:24:dc:bc:3f:7d:0d:9b:90:8b:5d:f6:f4:45:08:81:00:8a:47:22:34:e9:3e:c1:36
Jan 23, 2020 12:19:03 PM org.snmp4j.log.JavaLogAdapter log
FINE: Adding cache entry: StateReference[msgID=131835111,pduHandle=PduHandle[1240369129],securityEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25,securityModel=org.snmp4j.security.USM@73f36ef9,securityName=read,securityLevel=3,contextEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25,contextName=,retryMsgIDs=null]
Jan 23, 2020 12:19:03 PM org.snmp4j.log.JavaLogAdapter log
FINE: Running pending sync request with handle PduHandle[1240369129] and retry count left 0
Jan 23, 2020 12:19:03 PM org.snmp4j.log.JavaLogAdapter log
FINE: Sending message to 172.21.14.173/161 with length 133: 30:81:82:02:01:03:30:11:02:04:07:db:a4:e7:02:03:00:ff:ff:04:01:07:02:01:03:04:37:30:35:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:02:01:01:02:03:44:85:df:04:04:72:65:61:64:04:0c:93:85:b1:48:68:3c:ff:e7:e5:52:f3:52:04:08:57:d7:06:43:2e:4b:86:f3:04:31:d1:c9:6b:14:9d:6d:25:07:8d:f2:dd:79:19:fd:ea:d3:0c:0f:f5:c0:07:e3:58:36:19:24:dc:bc:3f:7d:0d:9b:90:8b:5d:f6:f4:45:08:81:00:8a:47:22:34:e9:3e:c1:36
Jan 23, 2020 12:19:03 PM org.snmp4j.log.JavaLogAdapter log
FINE: Received message from /172.21.14.173/161 with length 110: 30:6c:02:01:03:30:11:02:04:07:db:a4:e7:02:03:00:ff:e3:04:01:00:02:01:03:04:23:30:21:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:02:01:01:02:03:44:85:df:04:04:72:65:61:64:04:00:04:00:30:2f:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25: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:05:00:41:01:54
Jan 23, 2020 12:19:03 PM org.snmp4j.log.JavaLogAdapter log
FINE: SNMPv3 header decoded: msgId=131835111, msgMaxSize=65507, msgFlags=00, secModel=3
Jan 23, 2020 12:19:03 PM org.snmp4j.log.JavaLogAdapter log
FINE: getUser(engineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25, securityName=read)
Jan 23, 2020 12:19:03 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed cache entry: StateReference[msgID=131835111,pduHandle=null,securityEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25,securityModel=org.snmp4j.security.USM@73f36ef9,securityName=read,securityLevel=3,contextEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25,contextName=,retryMsgIDs=null]
Jan 23, 2020 12:19:03 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3412 §7.2.10 - Received PDU (msgID=131835111) is a response or an internal class message. PduHandle.transactionID = 1240369129
Jan 23, 2020 12:19:03 PM org.snmp4j.log.JavaLogAdapter log
FINE: MPv3 finished
Jan 23, 2020 12:19:03 PM org.snmp4j.log.JavaLogAdapter log
FINE: Searching pending request with handlePduHandle[1240369129]
Jan 23, 2020 12:19:03 PM org.snmp4j.log.JavaLogAdapter log
WARNING: RFC3412 §7.2.11.b:Received REPORT PDU with security level noAuthNoPriv from ‘CommandResponderEvent[securityModel=3, securityLevel=1, maxSizeResponsePDU=65400, pduHandle=PduHandle[1240369129], stateReference=null, pdu=REPORT[{contextEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25, contextName=}, requestID=0, errorStatus=0, errorIndex=0, VBS[1.3.6.1.6.3.15.1.1.5.0 = 84]], messageProcessingModel=3, securityName=read, processed=true, peerAddress=172.21.14.173/161, transportMapping=org.snmp4j.transport.DefaultUdpTransportMapping@3cbb1afb, tmStateReference=null]’. Ignoring it, because report strategy is set to standard
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed pending request with handle: PduHandle[1240369129]
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3414 §3.1.4.b Outgoing message is not encrypted
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: Adding cache entry: StateReference[msgID=131835112,pduHandle=PduHandle[1240369132],securityEngineID=,securityModel=org.snmp4j.security.USM@73f36ef9,securityName=,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null]
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: Running pending sync request with handle PduHandle[1240369132] and retry count left 0
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: Sending message to 172.21.14.173/161 with length 61: 30:3b:02:01:03:30:11:02:04:07:db:a4:e8: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
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: Received message from /172.21.14.173/161 with length 107: 30:69:02:01:03:30:11:02:04:07:db:a4:e8:02:03:00:ff:e3:04:01:00:02:01:03:04:1f:30:1d:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:02:01:01:02:03:44:85:e1:04:00:04:00:04:00:30:30:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:04:00:a8:1d:02:01:00:02:01:00:02:01:00:30:12:30:10:06:0a:2b:06:01:06:03:0f:01:01:04:00:41:02:42:2b
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: SNMPv3 header decoded: msgId=131835112, msgMaxSize=65507, msgFlags=00, secModel=3
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: Accepting zero length security name
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed cache entry: StateReference[msgID=131835112,pduHandle=null,securityEngineID=,securityModel=org.snmp4j.security.USM@73f36ef9,securityName=,securityLevel=1,contextEngineID=,contextName=,retryMsgIDs=null]
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3412 §7.2.10 - Received PDU (msgID=131835112) is a response or an internal class message. PduHandle.transactionID = 1240369132
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: MPv3 finished
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: Searching pending request with handlePduHandle[1240369132]
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed pending request with handle: PduHandle[1240369132]
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1First digest: 6b:22:35:cb:01:77:75:b4:c5:16:48:d7:11:f3:d3:59:aa:a9:ec:3b
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1localized key: 42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1First digest: 6b:22:35:cb:01:77:75:b4:c5:16:48:d7:11:f3:d3:59:aa:a9:ec:3b
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: SHA-1localized key: 42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: Adding user read = UsmUser[secName=read,authProtocol=1.3.6.1.6.3.10.1.1.3,authPassphrase=42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef:8c:14:38:52,privProtocol=1.3.6.1.6.3.10.1.2.4,privPassphrase=42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef,localizationEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25]
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: Context engine ID of scoped PDU is empty! Setting it to authoritative engine ID: 80:00:05:43:80:52:89:16:56:5d:e4:fb:25
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: getUser(engineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25, securityName=read)
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3414 §3.1.4.a Outgoing message needs to be encrypted
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: initVect is 00:00:00:01:00:44:85:e1:57:d7:06:43:2e:4b:86:f4
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: aes encrypt: Data to encrypt 30:2f:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:04:00:a0:1c:02:04:49:ee:87:ee:02:01:00:02:01:00:30:0e:30:0c:06:08:2b:06:01:02:01:01:01:00:05:00
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: aes encrypt: used key 42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: aes encrypt: created privacy_params 57:d7:06:43:2e:4b:86:f4
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: aes encrypt: encrypted Data cb:bb:35:a9:d9:e6:b1:e5:fd:bb:06:da:d7:af:72:2e:f6:48:d3:75:54:cc:ad:8c:08:76:ff:49:0d:8c:ba:72:8e:03:b5:df:96:f1:b6:21:4d:4b:aa:67:bf:ad:78:b9:59
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: Adding cache entry: StateReference[msgID=131835113,pduHandle=PduHandle[1240369134],securityEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25,securityModel=org.snmp4j.security.USM@73f36ef9,securityName=read,securityLevel=3,contextEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25,contextName=,retryMsgIDs=null]
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: Running pending sync request with handle PduHandle[1240369134] and retry count left 1
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: Sending message to 172.21.14.173/161 with length 133: 30:81:82:02:01:03:30:11:02:04:07:db:a4:e9:02:03:00:ff:ff:04:01:07:02:01:03:04:37:30:35:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:02:01:01:02:03:44:85:e1:04:04:72:65:61:64:04:0c:50:29:e1:18:2f:c9:04:ba:56:8a:07:01:04:08:57:d7:06:43:2e:4b:86:f4:04:31:cb:bb:35:a9:d9:e6:b1:e5:fd:bb:06:da:d7:af:72:2e:f6:48:d3:75:54:cc:ad:8c:08:76:ff:49:0d:8c:ba:72:8e:03:b5:df:96:f1:b6:21:4d:4b:aa:67:bf:ad:78:b9:59
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: Received message from /172.21.14.173/161 with length 110: 30:6c:02:01:03:30:11:02:04:07:db:a4:e9:02:03:00:ff:e3:04:01:00:02:01:03:04:23:30:21:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:02:01:01:02:03:44:85:e1:04:04:72:65:61:64:04:00:04:00:30:2f:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25: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:05:00:41:01:55
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: SNMPv3 header decoded: msgId=131835113, msgMaxSize=65507, msgFlags=00, secModel=3
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: getUser(engineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25, securityName=read)
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed cache entry: StateReference[msgID=131835113,pduHandle=null,securityEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25,securityModel=org.snmp4j.security.USM@73f36ef9,securityName=read,securityLevel=3,contextEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25,contextName=,retryMsgIDs=null]
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3412 §7.2.10 - Received PDU (msgID=131835113) is a response or an internal class message. PduHandle.transactionID = 1240369134
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: MPv3 finished
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
FINE: Searching pending request with handlePduHandle[1240369134]
Jan 23, 2020 12:19:05 PM org.snmp4j.log.JavaLogAdapter log
WARNING: RFC3412 §7.2.11.b:Received REPORT PDU with security level noAuthNoPriv from ‘CommandResponderEvent[securityModel=3, securityLevel=1, maxSizeResponsePDU=65400, pduHandle=PduHandle[1240369134], stateReference=null, pdu=REPORT[{contextEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25, contextName=}, requestID=0, errorStatus=0, errorIndex=0, VBS[1.3.6.1.6.3.15.1.1.5.0 = 85]], messageProcessingModel=3, securityName=read, processed=true, peerAddress=172.21.14.173/161, transportMapping=org.snmp4j.transport.DefaultUdpTransportMapping@3cbb1afb, tmStateReference=null]’. Ignoring it, because report strategy is set to standard
Jan 23, 2020 12:19:07 PM org.snmp4j.log.JavaLogAdapter log
FINE: getUser(engineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25, securityName=read)
Jan 23, 2020 12:19:07 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3414 §3.1.4.a Outgoing message needs to be encrypted
Jan 23, 2020 12:19:07 PM org.snmp4j.log.JavaLogAdapter log
FINE: initVect is 00:00:00:01:00:44:85:e3:57:d7:06:43:2e:4b:86:f5
Jan 23, 2020 12:19:07 PM org.snmp4j.log.JavaLogAdapter log
FINE: aes encrypt: Data to encrypt 30:2f:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:04:00:a0:1c:02:04:49:ee:87:ee:02:01:00:02:01:00:30:0e:30:0c:06:08:2b:06:01:02:01:01:01:00:05:00
Jan 23, 2020 12:19:07 PM org.snmp4j.log.JavaLogAdapter log
FINE: aes encrypt: used key 42:cc:cc:aa:63:da:00:1e:00:90:b3:10:aa:75:b3:ef
Jan 23, 2020 12:19:07 PM org.snmp4j.log.JavaLogAdapter log
FINE: aes encrypt: created privacy_params 57:d7:06:43:2e:4b:86:f5
Jan 23, 2020 12:19:07 PM org.snmp4j.log.JavaLogAdapter log
FINE: aes encrypt: encrypted Data 16:dc:8d:f9:ff:d0:26:29:bd:3d:6e:7d:f0:d5:d0:60:97:e8:2d:3d:fe:8d:08:05:87:57:4e:b5:bc:e6:fb:b3:21:41:df:b4:41:2a:7b:d6:bf:4d:ee:80:ce:0d:a6:db:eb
Jan 23, 2020 12:19:07 PM org.snmp4j.log.JavaLogAdapter log
FINE: Adding cache entry: StateReference[msgID=131835114,pduHandle=PduHandle[1240369134],securityEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25,securityModel=org.snmp4j.security.USM@73f36ef9,securityName=read,securityLevel=3,contextEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25,contextName=,retryMsgIDs=null]
Jan 23, 2020 12:19:07 PM org.snmp4j.log.JavaLogAdapter log
FINE: Running pending sync request with handle PduHandle[1240369134] and retry count left 0
Jan 23, 2020 12:19:07 PM org.snmp4j.log.JavaLogAdapter log
FINE: Sending message to 172.21.14.173/161 with length 133: 30:81:82:02:01:03:30:11:02:04:07:db:a4:ea:02:03:00:ff:ff:04:01:07:02:01:03:04:37:30:35:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:02:01:01:02:03:44:85:e3:04:04:72:65:61:64:04:0c:1e:98:e9:f0:31:c6:dc:d8:32:47:2f:92:04:08:57:d7:06:43:2e:4b:86:f5:04:31:16:dc:8d:f9:ff:d0:26:29:bd:3d:6e:7d:f0:d5:d0:60:97:e8:2d:3d:fe:8d:08:05:87:57:4e:b5:bc:e6:fb:b3:21:41:df:b4:41:2a:7b:d6:bf:4d:ee:80:ce:0d:a6:db:eb
Jan 23, 2020 12:19:07 PM org.snmp4j.log.JavaLogAdapter log
FINE: Received message from /172.21.14.173/161 with length 110: 30:6c:02:01:03:30:11:02:04:07:db:a4:ea:02:03:00:ff:e3:04:01:00:02:01:03:04:23:30:21:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25:02:01:01:02:03:44:85:e3:04:04:72:65:61:64:04:00:04:00:30:2f:04:0d:80:00:05:43:80:52:89:16:56:5d:e4:fb:25: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:05:00:41:01:56
Jan 23, 2020 12:19:07 PM org.snmp4j.log.JavaLogAdapter log
FINE: SNMPv3 header decoded: msgId=131835114, msgMaxSize=65507, msgFlags=00, secModel=3
Jan 23, 2020 12:19:07 PM org.snmp4j.log.JavaLogAdapter log
FINE: getUser(engineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25, securityName=read)
Jan 23, 2020 12:19:07 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed cache entry: StateReference[msgID=131835114,pduHandle=null,securityEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25,securityModel=org.snmp4j.security.USM@73f36ef9,securityName=read,securityLevel=3,contextEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25,contextName=,retryMsgIDs=null]
Jan 23, 2020 12:19:07 PM org.snmp4j.log.JavaLogAdapter log
FINE: RFC3412 §7.2.10 - Received PDU (msgID=131835114) is a response or an internal class message. PduHandle.transactionID = 1240369134
Jan 23, 2020 12:19:07 PM org.snmp4j.log.JavaLogAdapter log
FINE: MPv3 finished
Jan 23, 2020 12:19:07 PM org.snmp4j.log.JavaLogAdapter log
FINE: Searching pending request with handlePduHandle[1240369134]
Jan 23, 2020 12:19:07 PM org.snmp4j.log.JavaLogAdapter log
WARNING: RFC3412 §7.2.11.b:Received REPORT PDU with security level noAuthNoPriv from ‘CommandResponderEvent[securityModel=3, securityLevel=1, maxSizeResponsePDU=65400, pduHandle=PduHandle[1240369134], stateReference=null, pdu=REPORT[{contextEngineID=80:00:05:43:80:52:89:16:56:5d:e4:fb:25, contextName=}, requestID=0, errorStatus=0, errorIndex=0, VBS[1.3.6.1.6.3.15.1.1.5.0 = 86]], messageProcessingModel=3, securityName=read, processed=true, peerAddress=172.21.14.173/161, transportMapping=org.snmp4j.transport.DefaultUdpTransportMapping@3cbb1afb, tmStateReference=null]’. Ignoring it, because report strategy is set to standard
Jan 23, 2020 12:19:09 PM org.snmp4j.log.JavaLogAdapter log
FINE: Request timed out: 1240369134
Jan 23, 2020 12:19:09 PM org.snmp4j.log.JavaLogAdapter log
FINE: Removed pending request with handle: PduHandle[1240369134]

Thanks and best regards
Piri

Hi Piri,

The REPORT from the printer returns “wrongDigest”, which means that the authentication key is wrong.

Best regards,
Frank

Hi Frank,

It seams it’s a matter of the length of the authentication and privacy key, if they have 10 chars long snmp4j doesn’t work. I set both passwords with the following string: ‘abCDe12345’ and snmp4j wasn’t able to communicate. When I set them with ‘abCD12345’ or ‘abCD1234?’ or ‘abcd1234’ it worked well. Of course Paesler SNMP Tester worked when authentication and privacy passwords were set with ‘abCDe12345’. Is there a reason why this is happening?

Thanks and best regards
Piri

Hi Piri,

I guess that the Paessler tool and the printer are using only the first 8 bytes of the passphrase to create a key with their passwordToKey function. That would be a bug if it is true. SNMP4J uses (as required by the SNMPv3 standard) all bytes of the passphrase.

The SNMP4J code to convert a password to a key is as follows:

    public byte[] passwordToKey(OctetString passwordString, byte[] engineID) {

    MessageDigest md = getDigestObject();

    byte[] digest;
    ByteBuffer buf = ByteBuffer.allocate(HMAC_BUFFER_SIZE);
    int password_index = 0;
    int count = 0;
    byte[] password = passwordString.getValue();

    /* Use while loop until we've done 1 Megabyte */
    while (count < HMAC_BUFFER_SIZE) {
        for (int i = 0; i < hmacBlockSize; ++i) {
            /* Take the next octet of the password, wrapping */
            /* to the beginning of the password as necessary.*/
            buf.put(password[password_index++ % password.length]);
        }
        count += hmacBlockSize;
    }
    buf.flip();
    md.update(buf);
    digest = md.digest();
    if (logger.isDebugEnabled()) {
        logger.debug(protoName + "First digest: " + new OctetString(digest).toHexString());
    }

    /*****************************************************/
    /* Now localize the key with the engine_id and pass  */
    /* through MD to produce final key                   */
    /*****************************************************/
    md.reset();
    md.update(digest);
    md.update(engineID);
    md.update(digest);
    digest = md.digest();
    if (logger.isDebugEnabled()) {
        logger.debug(protoName + "localized key: " + new OctetString(digest).toHexString());
    }

    return digest;
}

You might check yourself if you suspect the error there? I would be very surprised.
Maybe you can directly use keys instead of passwords on the printer configuration to mitigate the issue?

Best regards,
Frank