Refactor debug logging (#138)

Debug logging refactored for more efficiency when
disabled and for more functionality when in use.

Specifically, the global LOG object can easily be used
from any function/method, not just from codec main loop
as it used to be.

6 files changed, 97 insertions, 92 deletions

diff --git a/CHANGES.rst b/CHANGES.rst
index 0550873..27cf40f 100644
--- a/CHANGES.rst
+++ b/CHANGES.rst
@@ -1,8 +1,11 @@
 
-Revision 0.4.5, released XX-07-2018
+Revision 0.4.5, released XX-08-2018
 -----------------------------------
 
-No changes
+- Debug logging refactored for more efficiency when disabled and
+  for more functionality when in use. Specifically, the global
+  LOG object can easily be used from any function/method, not just
+  from codec main loop as it used to be.
 
 Revision 0.4.4, released 26-07-2018
 -----------------------------------
diff --git a/pyasn1/codec/ber/decoder.py b/pyasn1/codec/ber/decoder.py
index 514e91d..6583c38 100644
--- a/pyasn1/codec/ber/decoder.py
+++ b/pyasn1/codec/ber/decoder.py
@@ -18,6 +18,8 @@ from pyasn1.type import useful
 
 __all__ = ['decode']
 
+LOG = debug.registerLoggee(__name__, flags=debug.DEBUG_DECODER)
+
 noValue = base.noValue
 
 
@@ -70,8 +72,8 @@ class ExplicitTagDecoder(AbstractSimpleDecoder):
 
         value, _ = decodeFun(head, asn1Spec, tagSet, length, **options)
 
-        if debug.logger & debug.flagDecoder:
-            debug.logger('explicit tag container carries %d octets of trailing payload (will be lost!): %s' % (
+        if LOG:
+            LOG('explicit tag container carries %d octets of trailing payload (will be lost!): %s' % (
                 len(_), debug.hexdump(_)))
 
         return value, tail
@@ -1067,21 +1069,16 @@ class Decoder(object):
                  decodeFun=None, substrateFun=None,
                  **options):
 
-        if debug.logger & debug.flagDecoder:
-            logger = debug.logger
-        else:
-            logger = None
-
-        if logger:
-            logger('decoder called at scope %s with state %d, working with up to %d octets of substrate: %s' % (debug.scope, state, len(substrate), debug.hexdump(substrate)))
+        if LOG:
+            LOG('decoder called at scope %s with state %d, working with up to %d octets of substrate: %s' % (debug.scope, state, len(substrate), debug.hexdump(substrate)))
 
         allowEoo = options.pop('allowEoo', False)
 
         # Look for end-of-octets sentinel
         if allowEoo and self.supportIndefLength:
             if substrate[:2] == self.__eooSentinel:
-                if logger:
-                    logger('end-of-octets sentinel found')
+                if LOG:
+                    LOG('end-of-octets sentinel found')
                 return eoo.endOfOctets, substrate[2:]
 
         value = noValue
@@ -1146,8 +1143,8 @@ class Decoder(object):
                 else:
                     tagSet = lastTag + tagSet
                 state = stDecodeLength
-                if logger:
-                    logger('tag decoded into %s, decoding length' % tagSet)
+                if LOG:
+                    LOG('tag decoded into %s, decoding length' % tagSet)
             if state is stDecodeLength:
                 # Decode length
                 if not substrate:
@@ -1185,8 +1182,8 @@ class Decoder(object):
                     if len(substrate) < length:
                         raise error.SubstrateUnderrunError('%d-octet short' % (length - len(substrate)))
                 state = stGetValueDecoder
-                if logger:
-                    logger('value length decoded into %d, payload substrate is: %s' % (length, debug.hexdump(length == -1 and substrate or substrate[:length])))
+                if LOG:
+                    LOG('value length decoded into %d, payload substrate is: %s' % (length, debug.hexdump(length == -1 and substrate or substrate[:length])))
             if state is stGetValueDecoder:
                 if asn1Spec is None:
                     state = stGetValueDecoderByTag
@@ -1224,8 +1221,8 @@ class Decoder(object):
                         state = stDecodeValue
                     else:
                         state = stTryAsExplicitTag
-                if logger:
-                    logger('codec %s chosen by a built-in type, decoding %s' % (concreteDecoder and concreteDecoder.__class__.__name__ or "<none>", state is stDecodeValue and 'value' or 'as explicit tag'))
+                if LOG:
+                    LOG('codec %s chosen by a built-in type, decoding %s' % (concreteDecoder and concreteDecoder.__class__.__name__ or "<none>", state is stDecodeValue and 'value' or 'as explicit tag'))
                     debug.scope.push(concreteDecoder is None and '?' or concreteDecoder.protoComponent.__class__.__name__)
             if state is stGetValueDecoderByAsn1Spec:
                 if asn1Spec.__class__ is tagmap.TagMap:
@@ -1233,19 +1230,19 @@ class Decoder(object):
                         chosenSpec = asn1Spec[tagSet]
                     except KeyError:
                         chosenSpec = None
-                    if logger:
-                        logger('candidate ASN.1 spec is a map of:')
+                    if LOG:
+                        LOG('candidate ASN.1 spec is a map of:')
                         for firstOctet, v in asn1Spec.presentTypes.items():
-                            logger('  %s -> %s' % (firstOctet, v.__class__.__name__))
+                            LOG('  %s -> %s' % (firstOctet, v.__class__.__name__))
                         if asn1Spec.skipTypes:
-                            logger('but neither of: ')
+                            LOG('but neither of: ')
                             for firstOctet, v in asn1Spec.skipTypes.items():
-                                logger('  %s -> %s' % (firstOctet, v.__class__.__name__))
-                        logger('new candidate ASN.1 spec is %s, chosen by %s' % (chosenSpec is None and '<none>' or chosenSpec.prettyPrintType(), tagSet))
+                                LOG('  %s -> %s' % (firstOctet, v.__class__.__name__))
+                        LOG('new candidate ASN.1 spec is %s, chosen by %s' % (chosenSpec is None and '<none>' or chosenSpec.prettyPrintType(), tagSet))
                 elif tagSet == asn1Spec.tagSet or tagSet in asn1Spec.tagMap:
                     chosenSpec = asn1Spec
-                    if logger:
-                        logger('candidate ASN.1 spec is %s' % asn1Spec.__class__.__name__)
+                    if LOG:
+                        LOG('candidate ASN.1 spec is %s' % asn1Spec.__class__.__name__)
                 else:
                     chosenSpec = None
 
@@ -1253,16 +1250,16 @@ class Decoder(object):
                     try:
                         # ambiguous type or just faster codec lookup
                         concreteDecoder = typeMap[chosenSpec.typeId]
-                        if logger:
-                            logger('value decoder chosen for an ambiguous type by type ID %s' % (chosenSpec.typeId,))
+                        if LOG:
+                            LOG('value decoder chosen for an ambiguous type by type ID %s' % (chosenSpec.typeId,))
                     except KeyError:
                         # use base type for codec lookup to recover untagged types
                         baseTagSet = tag.TagSet(chosenSpec.tagSet.baseTag,  chosenSpec.tagSet.baseTag)
                         try:
                             # base type or tagged subtype
                             concreteDecoder = tagMap[baseTagSet]
-                            if logger:
-                                logger('value decoder chosen by base %s' % (baseTagSet,))
+                            if LOG:
+                                LOG('value decoder chosen by base %s' % (baseTagSet,))
                         except KeyError:
                             concreteDecoder = None
                     if concreteDecoder:
@@ -1273,8 +1270,8 @@ class Decoder(object):
                 else:
                     concreteDecoder = None
                     state = stTryAsExplicitTag
-                if logger:
-                    logger('codec %s chosen by ASN.1 spec, decoding %s' % (state is stDecodeValue and concreteDecoder.__class__.__name__ or "<none>", state is stDecodeValue and 'value' or 'as explicit tag'))
+                if LOG:
+                    LOG('codec %s chosen by ASN.1 spec, decoding %s' % (state is stDecodeValue and concreteDecoder.__class__.__name__ or "<none>", state is stDecodeValue and 'value' or 'as explicit tag'))
                     debug.scope.push(chosenSpec is None and '?' or chosenSpec.__class__.__name__)
             if state is stDecodeValue:
                 if not options.get('recursiveFlag', True) and not substrateFun:  # deprecate this
@@ -1297,8 +1294,8 @@ class Decoder(object):
                         **options
                     )
 
-                if logger:
-                    logger('codec %s yields type %s, value:\n%s\n...remaining substrate is: %s' % (concreteDecoder.__class__.__name__, value.__class__.__name__, isinstance(value, base.Asn1Item) and value.prettyPrint() or value, substrate and debug.hexdump(substrate) or '<none>'))
+                if LOG:
+                    LOG('codec %s yields type %s, value:\n%s\n...remaining substrate is: %s' % (concreteDecoder.__class__.__name__, value.__class__.__name__, isinstance(value, base.Asn1Item) and value.prettyPrint() or value, substrate and debug.hexdump(substrate) or '<none>'))
 
                 state = stStop
                 break
@@ -1310,20 +1307,20 @@ class Decoder(object):
                 else:
                     concreteDecoder = None
                     state = self.defaultErrorState
-                if logger:
-                    logger('codec %s chosen, decoding %s' % (concreteDecoder and concreteDecoder.__class__.__name__ or "<none>", state is stDecodeValue and 'value' or 'as failure'))
+                if LOG:
+                    LOG('codec %s chosen, decoding %s' % (concreteDecoder and concreteDecoder.__class__.__name__ or "<none>", state is stDecodeValue and 'value' or 'as failure'))
             if state is stDumpRawValue:
                 concreteDecoder = self.defaultRawDecoder
-                if logger:
-                    logger('codec %s chosen, decoding value' % concreteDecoder.__class__.__name__)
+                if LOG:
+                    LOG('codec %s chosen, decoding value' % concreteDecoder.__class__.__name__)
                 state = stDecodeValue
             if state is stErrorCondition:
                 raise error.PyAsn1Error(
                     '%s not in asn1Spec: %r' % (tagSet, asn1Spec)
                 )
-        if logger:
+        if LOG:
             debug.scope.pop()
-            logger('decoder left scope %s, call completed' % debug.scope)
+            LOG('decoder left scope %s, call completed' % debug.scope)
         return value, substrate
 
 
diff --git a/pyasn1/codec/ber/encoder.py b/pyasn1/codec/ber/encoder.py
index f77a8a5..f213d5b 100644
--- a/pyasn1/codec/ber/encoder.py
+++ b/pyasn1/codec/ber/encoder.py
@@ -17,6 +17,8 @@ from pyasn1.type import useful
 
 __all__ = ['encode']
 
+LOG = debug.registerLoggee(__name__, flags=debug.DEBUG_ENCODER)
+
 
 class AbstractItemEncoder(object):
     supportIndefLenMode = True
@@ -620,13 +622,8 @@ class Encoder(object):
             raise error.PyAsn1Error('Value %r is not ASN.1 type instance '
                                     'and "asn1Spec" not given' % (value,))
 
-        if debug.logger & debug.flagEncoder:
-            logger = debug.logger
-        else:
-            logger = None
-
-        if logger:
-            logger('encoder called in %sdef mode, chunk size %s for '
+        if LOG:
+            LOG('encoder called in %sdef mode, chunk size %s for '
                    'type %s, value:\n%s' % (not options.get('defMode', True) and 'in' or '', options.get('maxChunkSize', 0), asn1Spec is None and value.prettyPrintType() or asn1Spec.prettyPrintType(), value))
 
         if self.fixedDefLengthMode is not None:
@@ -639,8 +636,8 @@ class Encoder(object):
         try:
             concreteEncoder = self.__typeMap[typeId]
 
-            if logger:
-                logger('using value codec %s chosen by type ID %s' % (concreteEncoder.__class__.__name__, typeId))
+            if LOG:
+                LOG('using value codec %s chosen by type ID %s' % (concreteEncoder.__class__.__name__, typeId))
 
         except KeyError:
             if asn1Spec is None:
@@ -657,13 +654,13 @@ class Encoder(object):
             except KeyError:
                 raise error.PyAsn1Error('No encoder for %r (%s)' % (value, tagSet))
 
-            if logger:
-                logger('using value codec %s chosen by tagSet %s' % (concreteEncoder.__class__.__name__, tagSet))
+            if LOG:
+                LOG('using value codec %s chosen by tagSet %s' % (concreteEncoder.__class__.__name__, tagSet))
 
         substrate = concreteEncoder.encode(value, asn1Spec, self, **options)
 
-        if logger:
-            logger('codec %s built %s octets of substrate: %s\nencoder completed' % (concreteEncoder, len(substrate), debug.hexdump(substrate)))
+        if LOG:
+            LOG('codec %s built %s octets of substrate: %s\nencoder completed' % (concreteEncoder, len(substrate), debug.hexdump(substrate)))
 
         return substrate
 
diff --git a/pyasn1/codec/native/decoder.py b/pyasn1/codec/native/decoder.py
index 78fcda6..b288dc2 100644
--- a/pyasn1/codec/native/decoder.py
+++ b/pyasn1/codec/native/decoder.py
@@ -14,6 +14,8 @@ from pyasn1.type import useful
 
 __all__ = ['decode']
 
+LOG = debug.registerLoggee(__name__, flags=debug.DEBUG_DECODER)
+
 
 class AbstractScalarDecoder(object):
     def __call__(self, pyObject, asn1Spec, decodeFun=None, **options):
@@ -136,13 +138,10 @@ class Decoder(object):
         self.__typeMap = typeMap
 
     def __call__(self, pyObject, asn1Spec, **options):
-        if debug.logger & debug.flagDecoder:
-            logger = debug.logger
-        else:
-            logger = None
-        if logger:
+
+        if LOG:
             debug.scope.push(type(pyObject).__name__)
-            logger('decoder called at scope %s, working with type %s' % (debug.scope, type(pyObject).__name__))
+            LOG('decoder called at scope %s, working with type %s' % (debug.scope, type(pyObject).__name__))
 
         if asn1Spec is None or not isinstance(asn1Spec, base.Asn1Item):
             raise error.PyAsn1Error('asn1Spec is not valid (should be an instance of an ASN.1 Item, not %s)' % asn1Spec.__class__.__name__)
@@ -159,13 +158,13 @@ class Decoder(object):
             except KeyError:
                 raise error.PyAsn1Error('Unknown ASN.1 tag %s' % asn1Spec.tagSet)
 
-        if logger:
-            logger('calling decoder %s on Python type %s <%s>' % (type(valueDecoder).__name__, type(pyObject).__name__, repr(pyObject)))
+        if LOG:
+            LOG('calling decoder %s on Python type %s <%s>' % (type(valueDecoder).__name__, type(pyObject).__name__, repr(pyObject)))
 
         value = valueDecoder(pyObject, asn1Spec, self, **options)
 
-        if logger:
-            logger('decoder %s produced ASN.1 type %s <%s>' % (type(valueDecoder).__name__, type(value).__name__, repr(value)))
+        if LOG:
+            LOG('decoder %s produced ASN.1 type %s <%s>' % (type(valueDecoder).__name__, type(value).__name__, repr(value)))
             debug.scope.pop()
 
         return value
diff --git a/pyasn1/codec/native/encoder.py b/pyasn1/codec/native/encoder.py
index 0956191..aec6bc5 100644
--- a/pyasn1/codec/native/encoder.py
+++ b/pyasn1/codec/native/encoder.py
@@ -20,6 +20,8 @@ from pyasn1.type import useful
 
 __all__ = ['encode']
 
+LOG = debug.registerLoggee(__name__, flags=debug.DEBUG_ENCODER)
+
 
 class AbstractItemEncoder(object):
     def encode(self, value, encodeFun, **options):
@@ -180,14 +182,9 @@ class Encoder(object):
         if not isinstance(value, base.Asn1Item):
             raise error.PyAsn1Error('value is not valid (should be an instance of an ASN.1 Item)')
 
-        if debug.logger & debug.flagEncoder:
-            logger = debug.logger
-        else:
-            logger = None
-
-        if logger:
+        if LOG:
             debug.scope.push(type(value).__name__)
-            logger('encoder called for type %s <%s>' % (type(value).__name__, value.prettyPrint()))
+            LOG('encoder called for type %s <%s>' % (type(value).__name__, value.prettyPrint()))
 
         tagSet = value.tagSet
 
@@ -204,13 +201,13 @@ class Encoder(object):
             except KeyError:
                 raise error.PyAsn1Error('No encoder for %s' % (value,))
 
-        if logger:
-            logger('using value codec %s chosen by %s' % (concreteEncoder.__class__.__name__, tagSet))
+        if LOG:
+            LOG('using value codec %s chosen by %s' % (concreteEncoder.__class__.__name__, tagSet))
 
         pyObject = concreteEncoder.encode(value, self, **options)
 
-        if logger:
-            logger('encoder %s produced: %s' % (type(concreteEncoder).__name__, repr(pyObject)))
+        if LOG:
+            LOG('encoder %s produced: %s' % (type(concreteEncoder).__name__, repr(pyObject)))
             debug.scope.pop()
 
         return pyObject
diff --git a/pyasn1/debug.py b/pyasn1/debug.py
index ab72fa8..f1770c1 100644
--- a/pyasn1/debug.py
+++ b/pyasn1/debug.py
@@ -5,6 +5,7 @@
 # License: http://snmplabs.com/pyasn1/license.html
 #
 import logging
+import sys
 
 from pyasn1 import __version__
 from pyasn1 import error
@@ -12,18 +13,20 @@ from pyasn1.compat.octets import octs2ints
 
 __all__ = ['Debug', 'setLogger', 'hexdump']
 
-flagNone = 0x0000
-flagEncoder = 0x0001
-flagDecoder = 0x0002
-flagAll = 0xffff
+DEBUG_NONE = 0x0000
+DEBUG_ENCODER = 0x0001
+DEBUG_DECODER = 0x0002
+DEBUG_ALL = 0xffff
 
-flagMap = {
-    'none': flagNone,
-    'encoder': flagEncoder,
-    'decoder': flagDecoder,
-    'all': flagAll
+FLAG_MAP = {
+    'none': DEBUG_NONE,
+    'encoder': DEBUG_ENCODER,
+    'decoder': DEBUG_DECODER,
+    'all': DEBUG_ALL
 }
 
+LOGGEE_MAP = {}
+
 
 class Printer(object):
     # noinspection PyShadowingNames
@@ -66,7 +69,7 @@ class Debug(object):
     defaultPrinter = Printer()
 
     def __init__(self, *flags, **options):
-        self._flags = flagNone
+        self._flags = DEBUG_NONE
 
         if 'loggerName' in options:
             # route our logs to parent logger
@@ -89,9 +92,9 @@ class Debug(object):
                 flag = flag[1:]
             try:
                 if inverse:
-                    self._flags &= ~flagMap[flag]
+                    self._flags &= ~FLAG_MAP[flag]
                 else:
-                    self._flags |= flagMap[flag]
+                    self._flags |= FLAG_MAP[flag]
             except KeyError:
                 raise error.PyAsn1Error('bad debug flag %s' % flag)
 
@@ -109,17 +112,26 @@ class Debug(object):
     def __rand__(self, flag):
         return flag & self._flags
 
-
-logger = 0
+_LOG = DEBUG_NONE
 
 
 def setLogger(userLogger):
-    global logger
+    global _LOG
 
     if userLogger:
-        logger = userLogger
+        _LOG = userLogger
     else:
-        logger = 0
+        _LOG = DEBUG_NONE
+
+    # Update registered logging clients
+    for module, (name, flags) in LOGGEE_MAP.items():
+        setattr(module, name, _LOG & flags and _LOG or DEBUG_NONE)
+
+
+def registerLoggee(module, name='LOG', flags=DEBUG_NONE):
+    LOGGEE_MAP[sys.modules[module]] = name, flags
+    setLogger(_LOG)
+    return _LOG
 
 
 def hexdump(octets):