Do not store incomplete USM keys and improve debug

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.

5 files changed, 166 insertions, 39 deletions

diff --git a/CHANGES.txt b/CHANGES.txt
index e5ad5a84..0813d057 100644
--- a/CHANGES.txt
+++ b/CHANGES.txt
@@ -103,6 +103,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 ea6ca00b..bba225de 100644
--- a/pysnmp/entity/config.py
+++ b/pysnmp/entity/config.py
@@ -22,6 +22,7 @@ from pysnmp.proto.secmod.eso.priv import des3
 from pysnmp.proto import rfc1902
 from pysnmp.proto import rfc1905
 from pysnmp import error
+from pysnmp import debug
 
 # A shortcut to popular constants
 
@@ -110,6 +111,8 @@ def addV1System(snmpEngine, communityIndex, communityName,
     if contextName is None:
         contextName = null
 
+    securityName = securityName is not None and securityName or communityIndex
+
     snmpEngine.msgAndPduDsp.mibInstrumController.writeMibObjects(
         (snmpCommunityEntry.name + (8,) + tblIdx, 'destroy'),
         snmpEngine=snmpEngine
@@ -118,9 +121,7 @@ def addV1System(snmpEngine, communityIndex, communityName,
     snmpEngine.msgAndPduDsp.mibInstrumController.writeMibObjects(
         (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),
@@ -129,6 +130,13 @@ def addV1System(snmpEngine, communityIndex, communityName,
         snmpEngine=snmpEngine
     )
 
+    debug.logger & debug.FLAG_SM 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,
@@ -139,6 +147,10 @@ def delV1System(snmpEngine, communityIndex):
         snmpEngine=snmpEngine
     )
 
+    debug.logger & debug.FLAG_SM and debug.logger(
+        'delV1System: deleted table entry by communityIndex '
+        '"%s"' % (communityIndex,))
+
 
 def __cookV3UserInfo(snmpEngine, securityName, securityEngineId):
     mibBuilder = snmpEngine.msgAndPduDsp.mibInstrumController.mibBuilder
@@ -147,22 +159,22 @@ def __cookV3UserInfo(snmpEngine, securityName, securityEngineId):
         '__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,
@@ -172,14 +184,15 @@ def addV3User(snmpEngine, userName,
               securityName=None,
               authKeyType=USM_KEY_TYPE_PASSPHRASE,
               privKeyType=USM_KEY_TYPE_PASSPHRASE):
+
     mibBuilder = snmpEngine.msgAndPduDsp.mibInstrumController.mibBuilder
 
     if securityName is None:
         securityName = userName
 
-    (snmpEngineID, usmUserEntry, tblIdx1,
+    (securityEngineId, usmUserEntry, tblIdx1,
      pysnmpUsmSecretEntry, tblIdx2) = __cookV3UserInfo(
-        snmpEngine, userName, securityEngineId)
+        snmpEngine, securityName, securityEngineId)
 
     # Load augmenting table before creating new row in base one
     pysnmpUsmKeyEntry, = mibBuilder.importSymbols(
@@ -217,6 +230,8 @@ def addV3User(snmpEngine, userName,
 
     # Localize authentication key unless given
 
+    authKey = authKey and rfc1902.OctetString(authKey)
+
     masterAuthKey = localAuthKey = authKey
 
     if authKeyType < USM_KEY_TYPE_MASTER:  # master key is not given
@@ -226,15 +241,17 @@ def addV3User(snmpEngine, userName,
 
     if authKeyType < USM_KEY_TYPE_LOCALIZED:  # localized key is not given
         localAuthKey = AUTH_SERVICES[authProtocol].localizeKey(
-            masterAuthKey, snmpEngineID
+            masterAuthKey, securityEngineId
         )
 
     # Localize privacy key unless given
 
-    masterPrivKey = localPrivKey = privKey
-
     privKeyType = pysnmpUsmKeyType.syntax.clone(privKeyType)
 
+    privKey = privKey and rfc1902.OctetString(privKey)
+
+    masterPrivKey = localPrivKey = privKey
+
     if privKeyType < USM_KEY_TYPE_MASTER:  # master key is not given
         masterPrivKey = PRIV_SERVICES[privProtocol].hashPassphrase(
             authProtocol, privKey or null
@@ -242,37 +259,81 @@ def addV3User(snmpEngine, userName,
 
     if privKeyType < USM_KEY_TYPE_LOCALIZED:  # localized key is not given
         localPrivKey = PRIV_SERVICES[privProtocol].localizeKey(
-            authProtocol, masterPrivKey, snmpEngineID
+            authProtocol, masterPrivKey, securityEngineId
         )
 
-    # Commit master and localized keys
+    # Commit only the keys we have
+
     snmpEngine.msgAndPduDsp.mibInstrumController.writeMibObjects(
         (pysnmpUsmKeyEntry.name + (1,) + tblIdx1, localAuthKey),
+         snmpEngine=snmpEngine
+    )
+
+    snmpEngine.msgAndPduDsp.mibInstrumController.writeMibObjects(
         (pysnmpUsmKeyEntry.name + (2,) + tblIdx1, localPrivKey),
-        (pysnmpUsmKeyEntry.name + (3,) + tblIdx1, masterAuthKey),
-        (pysnmpUsmKeyEntry.name + (4,) + tblIdx1, masterPrivKey),
-        snmpEngine=snmpEngine
+        snmpEngine = snmpEngine
     )
 
+    if authKeyType < USM_KEY_TYPE_LOCALIZED:
+        snmpEngine.msgAndPduDsp.mibInstrumController.writeMibObjects(
+            (pysnmpUsmKeyEntry.name + (3,) + tblIdx1, masterAuthKey),
+             snmpEngine=snmpEngine
+        )
+
+    if privKeyType < USM_KEY_TYPE_LOCALIZED:
+        snmpEngine.msgAndPduDsp.mibInstrumController.writeMibObjects(
+            (pysnmpUsmKeyEntry.name + (4,) + tblIdx1, masterPrivKey),
+            snmpEngine=snmpEngine
+        )
+
     snmpEngine.msgAndPduDsp.mibInstrumController.writeMibObjects(
         (pysnmpUsmSecretEntry.name + (4,) + tblIdx2, 'destroy'),
-        snmpEngine=snmpEngine
+         snmpEngine=snmpEngine
     )
 
-    # Commit plain-text pass-phrases
+    # Commit plain-text pass-phrases if we have them
+
     snmpEngine.msgAndPduDsp.mibInstrumController.writeMibObjects(
-        (pysnmpUsmSecretEntry.name + (1,) + tblIdx2, userName),
-        (pysnmpUsmSecretEntry.name + (2,) + tblIdx2, authKey),
-        (pysnmpUsmSecretEntry.name + (3,) + tblIdx2, privKey),
         (pysnmpUsmSecretEntry.name + (4,) + tblIdx2, 'createAndGo'),
         snmpEngine=snmpEngine
     )
 
+    if authKeyType < USM_KEY_TYPE_MASTER:
+        snmpEngine.msgAndPduDsp.mibInstrumController.writeMibObjects(
+            (pysnmpUsmSecretEntry.name + (1,) + tblIdx2, userName),
+            (pysnmpUsmSecretEntry.name + (2,) + tblIdx2, authKey),
+            snmpEngine=snmpEngine
+        )
+
+    if privKeyType < USM_KEY_TYPE_MASTER:
+        snmpEngine.msgAndPduDsp.mibInstrumController.writeMibObjects(
+            (pysnmpUsmSecretEntry.name + (1,) + tblIdx2, userName),
+            (pysnmpUsmSecretEntry.name + (3,) + tblIdx2, privKey),
+            snmpEngine=snmpEngine
+        )
+
+    debug.logger & debug.FLAG_SM 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 and localAuthKey.prettyPrint(),
+            localPrivKey and localPrivKey.prettyPrint(),
+            masterAuthKey and masterAuthKey.prettyPrint(),
+            masterPrivKey and masterPrivKey.prettyPrint(),
+            authKey and authKey.prettyPrint(),
+            privKey and privKey.prettyPrint(),
+            securityName,
+            securityEngineId and securityEngineId.prettyPrint()))
+
 
 def delV3User(snmpEngine,
               userName,
               securityEngineId=None):
-    (snmpEngineID, usmUserEntry, tblIdx1, pysnmpUsmSecretEntry,
+    (securityEngineId, usmUserEntry, tblIdx1, pysnmpUsmSecretEntry,
      tblIdx2) = __cookV3UserInfo(snmpEngine, userName, securityEngineId)
 
     snmpEngine.msgAndPduDsp.mibInstrumController.writeMibObjects(
@@ -285,6 +346,13 @@ def delV3User(snmpEngine,
         snmpEngine=snmpEngine
     )
 
+    debug.logger & debug.FLAG_SM and debug.logger(
+        'delV3User: deleted table entries by index '
+        'userName "%s" securityEngineId '
+        '"%s"' % (
+            userName,
+            securityEngineId.prettyPrint()))
+
     # Drop all derived rows
 
     def _cbFun(varBinds, **context):
diff --git a/pysnmp/proto/secmod/rfc3414/localkey.py b/pysnmp/proto/secmod/rfc3414/localkey.py
index bc4faa91..61ce5ff9 100644
--- a/pysnmp/proto/secmod/rfc3414/localkey.py
+++ b/pysnmp/proto/secmod/rfc3414/localkey.py
@@ -36,8 +36,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):
@@ -49,7 +49,8 @@ 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 0a8f54e5..f20df861 100644
--- a/pysnmp/proto/secmod/rfc3414/service.py
+++ b/pysnmp/proto/secmod/rfc3414/service.py
@@ -344,7 +344,22 @@ class SnmpUSMSecurityModel(AbstractSecurityModel):
             securityEngineID = snmpEngineID
 
             debug.logger & debug.FLAG_SM and debug.logger(
-                '__generateRequestOrResponseMsg: user info read from cache')
+                '__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 and usmUserAuthKeyLocalized.prettyPrint(),
+                    usmUserPrivProtocol,
+                    usmUserPrivKeyLocalized and usmUserPrivKeyLocalized.prettyPrint(),
+                    securityEngineID.prettyPrint(),
+                    securityName, securityStateReference))
 
         elif securityName:
             # 3.1.1b
@@ -356,8 +371,23 @@ class SnmpUSMSecurityModel(AbstractSecurityModel):
                     securityEngineID,
                     self._sec2usr(snmpEngine, securityName, securityEngineID)
                 )
+
                 debug.logger & debug.FLAG_SM and debug.logger(
-                    '__generateRequestOrResponseMsg: read user info')
+                    '__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(
@@ -375,7 +405,28 @@ class SnmpUSMSecurityModel(AbstractSecurityModel):
                             self._sec2usr(snmpEngine, securityName)
                         )
 
+                        debug.logger & debug.FLAG_SM 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.FLAG_SM and debug.logger(
+                            '__generateRequestOrResponseMsg: failed to clone '
+                            'USM user for securityEngineID "%s" securityName '
+                            '"%s"' % (securityEngineID, securityName))
+
                         reportUnknownName = True
 
                 if reportUnknownName:
@@ -404,16 +455,18 @@ class SnmpUSMSecurityModel(AbstractSecurityModel):
             usmUserAuthKeyLocalized = usmUserPrivKeyLocalized = None
 
             debug.logger & debug.FLAG_SM and debug.logger(
-                '__generateRequestOrResponseMsg: use empty USM data')
-
-        # noinspection PyUnboundLocalVariable
-        debug.logger & debug.FLAG_SM and debug.logger(
-            '__generateRequestOrResponseMsg: local usmUserName %r '
-            'usmUserSecurityName %r usmUserAuthProtocol %s '
-            'usmUserPrivProtocol %s securityEngineID %r '
-            'securityName %r' % (
-                usmUserName, usmUserSecurityName, usmUserAuthProtocol,
-                usmUserPrivProtocol, securityEngineID, securityName))
+                '__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
 
diff --git a/pysnmp/smi/builder.py b/pysnmp/smi/builder.py
index da03764d..0a3a6a1c 100644
--- a/pysnmp/smi/builder.py
+++ b/pysnmp/smi/builder.py
@@ -100,8 +100,10 @@ class __AbstractMibSource(object):
 
         for pycSfx in BYTECODE_SUFFIXES:
 
+            pycFile = f + pycSfx
+
             try:
-                pycData, pycPath = self._getData(f + pycSfx, 'rb')
+                pycData, pycPath = self._getData(pycFile, 'rb')
 
             except IOError as exc:
                 if ENOENT == -1 or exc.errno == ENOENT: