diff options
author | Ilya Etingof <etingof@gmail.com> | 2018-08-03 17:06:48 +0200 |
---|---|---|
committer | GitHub <noreply@github.com> | 2018-08-03 17:06:48 +0200 |
commit | a5faeee2ebc7a13b30c2b66ac59d5ad146f04a78 (patch) | |
tree | c9bfbeb9666a14902ec9457ce749d2a534b049a7 | |
parent | e5c30776b510a88f760ca701558778b08a591e9d (diff) | |
download | pyasn1-a5faeee2ebc7a13b30c2b66ac59d5ad146f04a78.tar.gz |
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.
-rw-r--r-- | CHANGES.rst | 7 | ||||
-rw-r--r-- | pyasn1/codec/ber/decoder.py | 75 | ||||
-rw-r--r-- | pyasn1/codec/ber/encoder.py | 23 | ||||
-rw-r--r-- | pyasn1/codec/native/decoder.py | 19 | ||||
-rw-r--r-- | pyasn1/codec/native/encoder.py | 19 | ||||
-rw-r--r-- | pyasn1/debug.py | 46 |
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): |