Do not store incomplete USM keys and improve USM debugging

This adds details debugging on USM initial configuration process
and runtime USM user cloning.

Besides that, this patch eliminates storing of incomplete
USM keys (in case when master/localized keys are configured
directly).

On top of that, this commit fixes a bug in USM configuration
which did not allow the same user names to be added under
different security names.

4 files changed, 172 insertions, 38 deletions

diff --git a/CHANGES.txt b/CHANGES.txt
index 88460094..e486cc16 100644
--- a/CHANGES.txt
+++ b/CHANGES.txt
@@ -3,6 +3,9 @@ Revision 4.4.11, released 2019-08-XX
 ------------------------------------
 
 - Added SNMPv3 USM master and localized keys support to LCD configuration
+- Improved initial and runtime USM debugging
+- Fixed a bug in USM configuration which did not allow the same user names
+  to be added under different security names
 
 Revision 4.4.10, released 2019-07-29
 ------------------------------------
diff --git a/pysnmp/entity/config.py b/pysnmp/entity/config.py
index 9087c00f..5c5b5c8b 100644
--- a/pysnmp/entity/config.py
+++ b/pysnmp/entity/config.py
@@ -14,6 +14,7 @@ from pysnmp.proto.secmod.eso.priv import des3, aes192, aes256
 from pysnmp.proto import rfc1902
 from pysnmp.proto import rfc1905
 from pysnmp import error
+from pysnmp import debug
 
 # A shortcut to popular constants
 
@@ -91,13 +92,15 @@ def addV1System(snmpEngine, communityIndex, communityName,
     if contextName is None:
         contextName = null
 
+    securityName = securityName is not None and securityName or communityIndex
+
     snmpEngine.msgAndPduDsp.mibInstrumController.writeVars(
         ((snmpCommunityEntry.name + (8,) + tblIdx, 'destroy'),)
     )
     snmpEngine.msgAndPduDsp.mibInstrumController.writeVars(
         ((snmpCommunityEntry.name + (1,) + tblIdx, communityIndex),
          (snmpCommunityEntry.name + (2,) + tblIdx, communityName),
-         (snmpCommunityEntry.name + (3,) + tblIdx, securityName is not None and securityName or communityIndex),
+         (snmpCommunityEntry.name + (3,) + tblIdx, securityName),
          (snmpCommunityEntry.name + (4,) + tblIdx, contextEngineId),
          (snmpCommunityEntry.name + (5,) + tblIdx, contextName),
          (snmpCommunityEntry.name + (6,) + tblIdx, transportTag),
@@ -105,6 +108,13 @@ def addV1System(snmpEngine, communityIndex, communityName,
          (snmpCommunityEntry.name + (8,) + tblIdx, 'createAndGo'))
     )
 
+    debug.logger & debug.flagSM and debug.logger(
+        'addV1System: added new table entry '
+        'communityIndex "%s" communityName "%s" securityName "%s" '
+        'contextEngineId "%s" contextName "%s" transportTag '
+        '"%s"' % (communityIndex, communityName, securityName,
+                  contextEngineId, contextName, transportTag))
+
 
 def delV1System(snmpEngine, communityIndex):
     (snmpCommunityEntry, tblIdx,
@@ -113,6 +123,10 @@ def delV1System(snmpEngine, communityIndex):
         ((snmpCommunityEntry.name + (8,) + tblIdx, 'destroy'),)
     )
 
+    debug.logger & debug.flagSM and debug.logger(
+        'delV1System: deleted table entry by communityIndex '
+        '"%s"' % (communityIndex,))
+
 
 def __cookV3UserInfo(snmpEngine, securityName, securityEngineId):
     mibBuilder = snmpEngine.msgAndPduDsp.mibInstrumController.mibBuilder
@@ -120,17 +134,17 @@ def __cookV3UserInfo(snmpEngine, securityName, securityEngineId):
     snmpEngineID, = mibBuilder.importSymbols('__SNMP-FRAMEWORK-MIB', 'snmpEngineID')
 
     if securityEngineId is None:
-        snmpEngineID = snmpEngineID.syntax
+        securityEngineId = snmpEngineID.syntax
     else:
-        snmpEngineID = snmpEngineID.syntax.clone(securityEngineId)
+        securityEngineId = snmpEngineID.syntax.clone(securityEngineId)
 
     usmUserEntry, = mibBuilder.importSymbols('SNMP-USER-BASED-SM-MIB', 'usmUserEntry')
-    tblIdx1 = usmUserEntry.getInstIdFromIndices(snmpEngineID, securityName)
+    tblIdx1 = usmUserEntry.getInstIdFromIndices(securityEngineId, securityName)
 
     pysnmpUsmSecretEntry, = mibBuilder.importSymbols('PYSNMP-USM-MIB', 'pysnmpUsmSecretEntry')
     tblIdx2 = pysnmpUsmSecretEntry.getInstIdFromIndices(securityName)
 
-    return snmpEngineID, usmUserEntry, tblIdx1, pysnmpUsmSecretEntry, tblIdx2
+    return securityEngineId, usmUserEntry, tblIdx1, pysnmpUsmSecretEntry, tblIdx2
 
 
 def addV3User(snmpEngine, userName,
@@ -142,15 +156,18 @@ def addV3User(snmpEngine, userName,
               privKeyType=usmKeyTypePassphrase,
               # deprecated parameter
               contextEngineId=None):
+
     mibBuilder = snmpEngine.msgAndPduDsp.mibInstrumController.mibBuilder
 
     if securityName is None:
         securityName = userName
+
     if securityEngineId is None:  # backward compatibility
         securityEngineId = contextEngineId
 
-    (snmpEngineID, usmUserEntry, tblIdx1,
-     pysnmpUsmSecretEntry, tblIdx2) = __cookV3UserInfo(snmpEngine, userName, securityEngineId)
+    (securityEngineId, usmUserEntry, tblIdx1,
+     pysnmpUsmSecretEntry, tblIdx2) = __cookV3UserInfo(
+        snmpEngine, securityName, securityEngineId)
 
     # Load augmenting table before creating new row in base one
     pysnmpUsmKeyEntry, = mibBuilder.importSymbols('PYSNMP-USM-MIB', 'pysnmpUsmKeyEntry')
@@ -182,54 +199,93 @@ def addV3User(snmpEngine, userName,
 
     # Localize authentication key unless given
 
-    masterAuthKey = localAuthKey = authKey
+    masterAuthKey = localAuthKey = authKey = rfc1902.OctetString(authKey or null)
 
-    if authKeyType < usmKeyTypeMaster:  # master key is not given
+    if authKeyType < usmKeyTypeMaster:  # pass phrase is given
         masterAuthKey = authServices[authProtocol].hashPassphrase(
             authKey or null
         )
 
-    if authKeyType < usmKeyTypeLocalized:  # localized key is not given
+    if authKeyType < usmKeyTypeLocalized:  # pass phrase or master key is given
         localAuthKey = authServices[authProtocol].localizeKey(
-            masterAuthKey, snmpEngineID
+            masterAuthKey, securityEngineId
         )
 
     # Localize privacy key unless given
 
-    masterPrivKey = localPrivKey = privKey
-
     privKeyType = pysnmpUsmKeyType.syntax.clone(privKeyType)
 
-    if privKeyType < usmKeyTypeMaster:  # master key is not given
+    masterPrivKey = localPrivKey = privKey = rfc1902.OctetString(privKey or null)
+
+    if privKeyType < usmKeyTypeMaster:  # pass phrase is given
         masterPrivKey = privServices[privProtocol].hashPassphrase(
             authProtocol, privKey or null
         )
 
-    if privKeyType < usmKeyTypeLocalized:  # localized key is not given
+    if privKeyType < usmKeyTypeLocalized:  # pass phrase or master key is given
         localPrivKey = privServices[privProtocol].localizeKey(
-            authProtocol, masterPrivKey, snmpEngineID
+            authProtocol, masterPrivKey, securityEngineId
         )
 
-    # Commit master and localized keys
+    # Commit only the keys we have
+
     snmpEngine.msgAndPduDsp.mibInstrumController.writeVars(
-        ((pysnmpUsmKeyEntry.name + (1,) + tblIdx1, localAuthKey),
-         (pysnmpUsmKeyEntry.name + (2,) + tblIdx1, localPrivKey),
-         (pysnmpUsmKeyEntry.name + (3,) + tblIdx1, masterAuthKey),
-         (pysnmpUsmKeyEntry.name + (4,) + tblIdx1, masterPrivKey))
+        ((pysnmpUsmKeyEntry.name + (1,) + tblIdx1, localAuthKey),)
     )
 
     snmpEngine.msgAndPduDsp.mibInstrumController.writeVars(
+        ((pysnmpUsmKeyEntry.name + (2,) + tblIdx1, localPrivKey),)
+    )
+
+    if authKeyType < usmKeyTypeLocalized:
+        snmpEngine.msgAndPduDsp.mibInstrumController.writeVars(
+            ((pysnmpUsmKeyEntry.name + (3,) + tblIdx1, masterAuthKey),)
+        )
+
+    if privKeyType < usmKeyTypeLocalized:
+        snmpEngine.msgAndPduDsp.mibInstrumController.writeVars(
+            ((pysnmpUsmKeyEntry.name + (4,) + tblIdx1, masterPrivKey),)
+        )
+
+    snmpEngine.msgAndPduDsp.mibInstrumController.writeVars(
         ((pysnmpUsmSecretEntry.name + (4,) + tblIdx2, 'destroy'),)
     )
 
-    # Commit plain-text pass-phrases
+    # Commit plain-text pass-phrases if we have them
+
     snmpEngine.msgAndPduDsp.mibInstrumController.writeVars(
-        ((pysnmpUsmSecretEntry.name + (1,) + tblIdx2, userName),
-         (pysnmpUsmSecretEntry.name + (2,) + tblIdx2, authKey),
-         (pysnmpUsmSecretEntry.name + (3,) + tblIdx2, privKey),
-         (pysnmpUsmSecretEntry.name + (4,) + tblIdx2, 'createAndGo'))
+        ((pysnmpUsmSecretEntry.name + (4,) + tblIdx2, 'createAndGo'),)
     )
 
+    if authKeyType < usmKeyTypeMaster:
+        snmpEngine.msgAndPduDsp.mibInstrumController.writeVars(
+            ((pysnmpUsmSecretEntry.name + (1,) + tblIdx2, userName),
+             (pysnmpUsmSecretEntry.name + (2,) + tblIdx2, authKey))
+        )
+
+    if privKeyType < usmKeyTypeMaster:
+        snmpEngine.msgAndPduDsp.mibInstrumController.writeVars(
+            ((pysnmpUsmSecretEntry.name + (1,) + tblIdx2, userName),
+             (pysnmpUsmSecretEntry.name + (3,) + tblIdx2, privKey))
+        )
+
+    debug.logger & debug.flagSM and debug.logger(
+        'addV3User: added new table entries '
+        'userName "%s" securityName "%s" authProtocol %s '
+        'privProtocol %s localAuthKey "%s" localPrivKey "%s" '
+        'masterAuthKey "%s" masterPrivKey "%s" authKey "%s" '
+        'privKey "%s" by index securityName "%s" securityEngineId '
+        '"%s"' % (
+            userName, securityName, authProtocol, privProtocol,
+            localAuthKey.prettyPrint(),
+            localPrivKey.prettyPrint(),
+            masterAuthKey.prettyPrint(),
+            masterPrivKey.prettyPrint(),
+            authKey.prettyPrint(),
+            privKey.prettyPrint(),
+            securityName,
+            securityEngineId and securityEngineId.prettyPrint()))
+
 
 def delV3User(snmpEngine,
               userName,
@@ -238,21 +294,31 @@ def delV3User(snmpEngine,
               contextEngineId=None):
     if securityEngineId is None:  # backward compatibility
         securityEngineId = contextEngineId
-    (snmpEngineID, usmUserEntry, tblIdx1, pysnmpUsmSecretEntry,
+    (securityEngineId, usmUserEntry, tblIdx1, pysnmpUsmSecretEntry,
      tblIdx2) = __cookV3UserInfo(snmpEngine, userName, securityEngineId)
+
     snmpEngine.msgAndPduDsp.mibInstrumController.writeVars(
         ((usmUserEntry.name + (13,) + tblIdx1, 'destroy'),)
     )
+
     snmpEngine.msgAndPduDsp.mibInstrumController.writeVars(
         ((pysnmpUsmSecretEntry.name + (4,) + tblIdx2, 'destroy'),)
     )
 
+    debug.logger & debug.flagSM and debug.logger(
+        'delV3User: deleted table entries by index '
+        'userName "%s" securityEngineId '
+        '"%s"' % (
+            userName,
+            securityEngineId.prettyPrint()))
+
     # Drop all derived rows
     varBinds = initialVarBinds = (
         (usmUserEntry.name + (1,), None),  # usmUserEngineID
         (usmUserEntry.name + (2,), None),  # usmUserName
         (usmUserEntry.name + (4,), None)  # usmUserCloneFrom
     )
+
     while varBinds:
         varBinds = snmpEngine.msgAndPduDsp.mibInstrumController.readNextVars(
             varBinds
diff --git a/pysnmp/proto/secmod/rfc3414/localkey.py b/pysnmp/proto/secmod/rfc3414/localkey.py
index 651722e4..95d1deb0 100644
--- a/pysnmp/proto/secmod/rfc3414/localkey.py
+++ b/pysnmp/proto/secmod/rfc3414/localkey.py
@@ -37,7 +37,8 @@ def hashPassphrase(passphrase, hashFunc):
             )
             mark = e - ringBufferLen
         count += 1
-    return hasher.digest()
+    digest = hasher.digest()
+    return univ.OctetString(digest)
 
 
 def passwordToKey(passphrase, snmpEngineId, hashFunc):
@@ -47,7 +48,8 @@ def passwordToKey(passphrase, snmpEngineId, hashFunc):
 def localizeKey(passKey, snmpEngineId, hashFunc):
     passKey = univ.OctetString(passKey).asOctets()
     # noinspection PyDeprecation,PyCallingNonCallable
-    return hashFunc(passKey + snmpEngineId.asOctets() + passKey).digest()
+    digest = hashFunc(passKey + snmpEngineId.asOctets() + passKey).digest()
+    return univ.OctetString(digest)
 
 
 # RFC3414: A.2.1
diff --git a/pysnmp/proto/secmod/rfc3414/service.py b/pysnmp/proto/secmod/rfc3414/service.py
index 545ed874..4ef7d748 100644
--- a/pysnmp/proto/secmod/rfc3414/service.py
+++ b/pysnmp/proto/secmod/rfc3414/service.py
@@ -250,8 +250,27 @@ class SnmpUSMSecurityModel(AbstractSecurityModel):
                 usmUserPrivKeyLocalized = cachedSecurityData['usmUserPrivKeyLocalized']
             else:
                 usmUserPrivKeyLocalized = None
+
             securityEngineID = snmpEngineID
-            debug.logger & debug.flagSM and debug.logger('__generateRequestOrResponseMsg: user info read from cache')
+
+            debug.logger & debug.flagSM and debug.logger(
+                '__generateRequestOrResponseMsg: using cached USM user entry '
+                'usmUserName "%s" '
+                'usmUserSecurityName "%s" '
+                'usmUserAuthProtocol "%s" '
+                'usmUserAuthKeyLocalized "%s" '
+                'usmUserPrivProtocol "%s" '
+                'usmUserPrivKeyLocalized "%s" for '
+                'securityEngineID "%s" and  securityName "%s" found by '
+                'securityStateReference "%s" ' % (
+                    usmUserName, usmUserSecurityName,
+                    usmUserAuthProtocol,
+                    usmUserAuthKeyLocalized.prettyPrint(),
+                    usmUserPrivProtocol,
+                    usmUserPrivKeyLocalized.prettyPrint(),
+                    securityEngineID.prettyPrint(),
+                    securityName, securityStateReference))
+
         elif securityName:
             # 3.1.1b
             try:
@@ -262,7 +281,23 @@ class SnmpUSMSecurityModel(AbstractSecurityModel):
                     securityEngineID,
                     self.__sec2usr(snmpEngine, securityName, securityEngineID)
                 )
-                debug.logger & debug.flagSM and debug.logger('__generateRequestOrResponseMsg: read user info')
+
+                debug.logger & debug.flagSM and debug.logger(
+                    '__generateRequestOrResponseMsg: found USM user entry '
+                    'usmUserName "%s" '
+                    'usmUserSecurityName "%s" '
+                    'usmUserAuthProtocol "%s" '
+                    'usmUserAuthKeyLocalized "%s" '
+                    'usmUserPrivProtocol "%s" '
+                    'usmUserPrivKeyLocalized "%s" by '
+                    'securityEngineID "%s" and  securityName "%s"' % (
+                        usmUserName, usmUserSecurityName,
+                        usmUserAuthProtocol,
+                        usmUserAuthKeyLocalized.prettyPrint(),
+                        usmUserPrivProtocol,
+                        usmUserPrivKeyLocalized.prettyPrint(),
+                        securityEngineID.prettyPrint(),
+                        securityName))
 
             except NoSuchInstanceError:
                 pysnmpUsmDiscovery, = mibBuilder.importSymbols('__PYSNMP-USM-MIB', 'pysnmpUsmDiscovery')
@@ -278,7 +313,28 @@ class SnmpUSMSecurityModel(AbstractSecurityModel):
                             self.__sec2usr(snmpEngine, securityName)
                         )
 
+                        debug.logger & debug.flagSM and debug.logger(
+                            '__generateRequestOrResponseMsg: cloned USM user entry '
+                            'usmUserName "%s" '
+                            'usmUserSecurityName "%s" '
+                            'usmUserAuthProtocol "%s" '
+                            'usmUserAuthKeyLocalized "%s" '
+                            'usmUserPrivProtocol "%s" '
+                            'usmUserPrivKeyLocalized "%s" for '
+                            'securityEngineID "%s" and  securityName "%s"' % (
+                                usmUserName, usmUserSecurityName,
+                                usmUserAuthProtocol,
+                                usmUserAuthKeyLocalized.prettyPrint(),
+                                usmUserPrivProtocol,
+                                usmUserPrivKeyLocalized.prettyPrint(),
+                                securityEngineID.prettyPrint(), securityName))
+
                     except NoSuchInstanceError:
+                        debug.logger & debug.flagSM and debug.logger(
+                            '__generateRequestOrResponseMsg: failed to clone '
+                            'USM user for securityEngineID "%s" securityName '
+                            '"%s"' % (securityEngineID, securityName))
+
                         reportUnknownName = True
 
                 if reportUnknownName:
@@ -286,8 +342,6 @@ class SnmpUSMSecurityModel(AbstractSecurityModel):
                         errorIndication=errind.unknownSecurityName
                     )
 
-                debug.logger & debug.flagSM and debug.logger('__generateRequestOrResponseMsg: clone user info')
-
             except PyAsn1Error:
                 debug.logger & debug.flagSM and debug.logger(
                     '__generateRequestOrResponseMsg: %s' % (sys.exc_info()[1],))
@@ -296,18 +350,27 @@ class SnmpUSMSecurityModel(AbstractSecurityModel):
                 raise error.StatusInformation(
                     errorIndication=errind.invalidMsg
                 )
+
         else:
             # empty username used for engineID discovery
             usmUserName = usmUserSecurityName = null
             usmUserAuthProtocol = noauth.NoAuth.serviceID
             usmUserPrivProtocol = nopriv.NoPriv.serviceID
             usmUserAuthKeyLocalized = usmUserPrivKeyLocalized = None
-            debug.logger & debug.flagSM and debug.logger('__generateRequestOrResponseMsg: use empty USM data')
 
-        # noinspection PyUnboundLocalVariable
-        debug.logger & debug.flagSM and debug.logger(
-            '__generateRequestOrResponseMsg: local usmUserName %r usmUserSecurityName %r usmUserAuthProtocol %s usmUserPrivProtocol %s securityEngineID %r securityName %r' % (
-                usmUserName, usmUserSecurityName, usmUserAuthProtocol, usmUserPrivProtocol, securityEngineID, securityName))
+            debug.logger & debug.flagSM and debug.logger(
+                '__generateRequestOrResponseMsg: using blank USM info '
+                'usmUserName "%s" '
+                'usmUserSecurityName "%s" '
+                'usmUserAuthProtocol "%s" '
+                'usmUserAuthKeyLocalized "%s" '
+                'usmUserPrivProtocol "%s" '
+                'usmUserPrivKeyLocalized "%s" for '
+                'securityEngineID "%s" and  securityName "%s"' % (
+                    usmUserName, usmUserSecurityName,
+                    usmUserAuthProtocol, usmUserAuthKeyLocalized,
+                    usmUserPrivProtocol, usmUserPrivKeyLocalized,
+                    securityEngineID.prettyPrint(), securityName))
 
         msg = globalData