Add more debug logging to *ER codecsadd-more-debug-logging

More debug logging added to BER family of codecs to
ease encoding problems troubleshooting.

Also:

* code layout made a bit more sparse
* potential bug in open type decoding in indefinite mode
  fixed

3 files changed, 361 insertions, 44 deletions

diff --git a/CHANGES.rst b/CHANGES.rst
index 27cf40f..e9a8de5 100644
--- a/CHANGES.rst
+++ b/CHANGES.rst
@@ -6,6 +6,8 @@ Revision 0.4.5, released XX-08-2018
   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.
+- More debug logging added to BER family of codecs to ease encoding
+  problems troubleshooting.
 
 Revision 0.4.4, released 26-07-2018
 -----------------------------------
diff --git a/pyasn1/codec/ber/decoder.py b/pyasn1/codec/ber/decoder.py
index 6583c38..4527fd1 100644
--- a/pyasn1/codec/ber/decoder.py
+++ b/pyasn1/codec/ber/decoder.py
@@ -73,8 +73,8 @@ class ExplicitTagDecoder(AbstractSimpleDecoder):
         value, _ = decodeFun(head, asn1Spec, tagSet, length, **options)
 
         if LOG:
-            LOG('explicit tag container carries %d octets of trailing payload (will be lost!): %s' % (
-                len(_), debug.hexdump(_)))
+            LOG('explicit tag container carries %d octets of trailing payload '
+                '(will be lost!): %s' % (len(_), debug.hexdump(_)))
 
         return value, tail
 
@@ -126,7 +126,8 @@ class BooleanDecoder(IntegerDecoder):
     protoComponent = univ.Boolean(0)
 
     def _createComponent(self, asn1Spec, tagSet, value, **options):
-        return IntegerDecoder._createComponent(self, asn1Spec, tagSet, value and 1 or 0, **options)
+        return IntegerDecoder._createComponent(
+            self, asn1Spec, tagSet, value and 1 or 0, **options)
 
 
 class BitStringDecoder(AbstractSimpleDecoder):
@@ -140,8 +141,8 @@ class BitStringDecoder(AbstractSimpleDecoder):
         head, tail = substrate[:length], substrate[length:]
 
         if substrateFun:
-            return substrateFun(self._createComponent(asn1Spec, tagSet, noValue, **options),
-                                substrate, length)
+            return substrateFun(self._createComponent(
+                asn1Spec, tagSet, noValue, **options), substrate, length)
 
         if not head:
             raise error.PyAsn1Error('Empty BIT STRING substrate')
@@ -154,12 +155,17 @@ class BitStringDecoder(AbstractSimpleDecoder):
                     'Trailing bits overflow %s' % trailingBits
                 )
 
-            value = self.protoComponent.fromOctetString(head[1:], internalFormat=True, padding=trailingBits)
+            value = self.protoComponent.fromOctetString(
+                head[1:], internalFormat=True, padding=trailingBits)
 
             return self._createComponent(asn1Spec, tagSet, value, **options), tail
 
         if not self.supportConstructedForm:
-            raise error.PyAsn1Error('Constructed encoding form prohibited at %s' % self.__class__.__name__)
+            raise error.PyAsn1Error('Constructed encoding form prohibited '
+                                    'at %s' % self.__class__.__name__)
+
+        if LOG:
+            LOG('assembling constructed serialization')
 
         # All inner fragments are of the same type, treat them as octet string
         substrateFun = self.substrateCollector
@@ -240,6 +246,9 @@ class OctetStringDecoder(AbstractSimpleDecoder):
         if not self.supportConstructedForm:
             raise error.PyAsn1Error('Constructed encoding form prohibited at %s' % self.__class__.__name__)
 
+        if LOG:
+            LOG('assembling constructed serialization')
+
         # All inner fragments are of the same type, treat them as octet string
         substrateFun = self.substrateCollector
 
@@ -273,7 +282,9 @@ class OctetStringDecoder(AbstractSimpleDecoder):
                                              allowEoo=True, **options)
             if component is eoo.endOfOctets:
                 break
+
             header += component
+
         else:
             raise error.SubstrateUnderrunError(
                 'No EOO seen before substrate ends'
@@ -380,59 +391,90 @@ class RealDecoder(AbstractSimpleDecoder):
         if fo & 0x80:  # binary encoding
             if not head:
                 raise error.PyAsn1Error("Incomplete floating-point value")
+
+            if LOG:
+                LOG('decoding binary encoded REAL')
+
             n = (fo & 0x03) + 1
+
             if n == 4:
                 n = oct2int(head[0])
                 head = head[1:]
+
             eo, head = head[:n], head[n:]
+
             if not eo or not head:
                 raise error.PyAsn1Error('Real exponent screwed')
+
             e = oct2int(eo[0]) & 0x80 and -1 or 0
+
             while eo:  # exponent
                 e <<= 8
                 e |= oct2int(eo[0])
                 eo = eo[1:]
+
             b = fo >> 4 & 0x03  # base bits
+
             if b > 2:
                 raise error.PyAsn1Error('Illegal Real base')
+
             if b == 1:  # encbase = 8
                 e *= 3
+
             elif b == 2:  # encbase = 16
                 e *= 4
             p = 0
+
             while head:  # value
                 p <<= 8
                 p |= oct2int(head[0])
                 head = head[1:]
+
             if fo & 0x40:  # sign bit
                 p = -p
+
             sf = fo >> 2 & 0x03  # scale bits
             p *= 2 ** sf
             value = (p, 2, e)
+
         elif fo & 0x40:  # infinite value
+            if LOG:
+                LOG('decoding infinite REAL')
+
             value = fo & 0x01 and '-inf' or 'inf'
+
         elif fo & 0xc0 == 0:  # character encoding
             if not head:
                 raise error.PyAsn1Error("Incomplete floating-point value")
+
+            if LOG:
+                LOG('decoding character encoded REAL')
+
             try:
                 if fo & 0x3 == 0x1:  # NR1
                     value = (int(head), 10, 0)
+
                 elif fo & 0x3 == 0x2:  # NR2
                     value = float(head)
+
                 elif fo & 0x3 == 0x3:  # NR3
                     value = float(head)
+
                 else:
                     raise error.SubstrateUnderrunError(
                         'Unknown NR (tag %s)' % fo
                     )
+
             except ValueError:
                 raise error.SubstrateUnderrunError(
                     'Bad character Real syntax'
                 )
+
         else:
             raise error.SubstrateUnderrunError(
                 'Unknown encoding (tag %s)' % fo
             )
+
         return self._createComponent(asn1Spec, tagSet, value, **options), tail
 
 
@@ -453,10 +495,12 @@ class UniversalConstructedTypeDecoder(AbstractConstructedDecoder):
     def _decodeComponents(self, substrate, tagSet=None, decodeFun=None, **options):
         components = []
         componentTypes = set()
+
         while substrate:
             component, substrate = decodeFun(substrate, **options)
             if component is eoo.endOfOctets:
                 break
+
             components.append(component)
             componentTypes.add(component.tagSet)
 
@@ -466,6 +510,7 @@ class UniversalConstructedTypeDecoder(AbstractConstructedDecoder):
         # * otherwise -> likely SEQUENCE OF/SET OF
         if len(componentTypes) > 1:
             protoComponent = self.protoRecordComponent
+
         else:
             protoComponent = self.protoSequenceComponent
 
@@ -475,6 +520,10 @@ class UniversalConstructedTypeDecoder(AbstractConstructedDecoder):
             tagSet=tag.TagSet(protoComponent.tagSet.baseTag, *tagSet.superTags)
         )
 
+        if LOG:
+            LOG('guessed %r container type (pass `asn1Spec` to guide the '
+                'decoder)' % asn1Object)
+
         for idx, component in enumerate(components):
             asn1Object.setComponentByPosition(
                 idx, component,
@@ -496,8 +545,10 @@ class UniversalConstructedTypeDecoder(AbstractConstructedDecoder):
         if substrateFun is not None:
             if asn1Spec is not None:
                 asn1Object = asn1Spec.clone()
+
             elif self.protoComponent is not None:
                 asn1Object = self.protoComponent.clone(tagSet=tagSet)
+
             else:
                 asn1Object = self.protoRecordComponent, self.protoSequenceComponent
 
@@ -507,8 +558,12 @@ class UniversalConstructedTypeDecoder(AbstractConstructedDecoder):
             asn1Object, trailing = self._decodeComponents(
                 head, tagSet=tagSet, decodeFun=decodeFun, **options
             )
+
             if trailing:
-                raise error.PyAsn1Error('Unused trailing %d octets encountered' % len(trailing))
+                if LOG:
+                    LOG('Unused trailing %d octets encountered: %s' % (
+                        len(trailing), debug.hexdump(trailing)))
+
             return asn1Object, tail
 
         asn1Object = asn1Spec.clone()
@@ -520,21 +575,31 @@ class UniversalConstructedTypeDecoder(AbstractConstructedDecoder):
             isSetType = asn1Spec.typeId == univ.Set.typeId
             isDeterministic = not isSetType and not namedTypes.hasOptionalOrDefault
 
+            if LOG:
+                LOG('decoding %sdeterministic %s type %r chosen by type ID' % (
+                    not isDeterministic and 'non-' or '', isSetType and 'SET' or '',
+                    asn1Spec))
+
             seenIndices = set()
             idx = 0
             while head:
                 if not namedTypes:
                     componentType = None
+
                 elif isSetType:
                     componentType = namedTypes.tagMapUnique
+
                 else:
                     try:
                         if isDeterministic:
                             componentType = namedTypes[idx].asn1Object
+
                         elif namedTypes[idx].isOptional or namedTypes[idx].isDefaulted:
                             componentType = namedTypes.getTagMapNearPosition(idx)
+
                         else:
                             componentType = namedTypes[idx].asn1Object
+
                     except IndexError:
                         raise error.PyAsn1Error(
                             'Excessive components decoded at %r' % (asn1Spec,)
@@ -545,6 +610,7 @@ class UniversalConstructedTypeDecoder(AbstractConstructedDecoder):
                 if not isDeterministic and namedTypes:
                     if isSetType:
                         idx = namedTypes.getPositionByType(component.effectiveTagSet)
+
                     elif namedTypes[idx].isOptional or namedTypes[idx].isDefaulted:
                         idx = namedTypes.getPositionNearType(component.effectiveTagSet, idx)
 
@@ -557,14 +623,22 @@ class UniversalConstructedTypeDecoder(AbstractConstructedDecoder):
                 seenIndices.add(idx)
                 idx += 1
 
+            if LOG:
+                LOG('seen component indices %s' % seenIndices)
+
             if namedTypes:
                 if not namedTypes.requiredComponents.issubset(seenIndices):
-                    raise error.PyAsn1Error('ASN.1 object %s has uninitialized components' % asn1Object.__class__.__name__)
+                    raise error.PyAsn1Error(
+                        'ASN.1 object %s has uninitialized '
+                        'components' % asn1Object.__class__.__name__)
 
                 if  namedTypes.hasOpenTypes:
 
                     openTypes = options.get('openTypes', {})
 
+                    if LOG:
+                        LOG('using open types map: %r' % openTypes)
+
                     if openTypes or options.get('decodeOpenTypes', False):
 
                         for idx, namedType in enumerate(namedTypes.namedTypes):
@@ -587,8 +661,15 @@ class UniversalConstructedTypeDecoder(AbstractConstructedDecoder):
                                     openType = namedType.openType[governingValue]
 
                                 except KeyError:
+                                    if LOG:
+                                        LOG('failed to resolve open type by governing '
+                                            'value %r' % (governingValue,))
                                     continue
 
+                            if LOG:
+                                LOG('resolved open type %r by governing '
+                                    'value %r' % (openType, governingValue))
+
                             component, rest = decodeFun(
                                 asn1Object.getComponentByPosition(idx).asOctets(),
                                 asn1Spec=openType
@@ -604,6 +685,9 @@ class UniversalConstructedTypeDecoder(AbstractConstructedDecoder):
 
             componentType = asn1Spec.componentType
 
+            if LOG:
+                LOG('decoding type %r chosen by given `asn1Spec`' % componentType)
+
             idx = 0
 
             while head:
@@ -613,6 +697,7 @@ class UniversalConstructedTypeDecoder(AbstractConstructedDecoder):
                     verifyConstraints=False,
                     matchTags=False, matchConstraints=False
                 )
+
                 idx += 1
 
         return asn1Object, tail
@@ -627,8 +712,10 @@ class UniversalConstructedTypeDecoder(AbstractConstructedDecoder):
         if substrateFun is not None:
             if asn1Spec is not None:
                 asn1Object = asn1Spec.clone()
+
             elif self.protoComponent is not None:
                 asn1Object = self.protoComponent.clone(tagSet=tagSet)
+
             else:
                 asn1Object = self.protoRecordComponent, self.protoSequenceComponent
 
@@ -648,21 +735,31 @@ class UniversalConstructedTypeDecoder(AbstractConstructedDecoder):
             isSetType = asn1Object.typeId == univ.Set.typeId
             isDeterministic = not isSetType and not namedTypes.hasOptionalOrDefault
 
+            if LOG:
+                LOG('decoding %sdeterministic %s type %r chosen by type ID' % (
+                    not isDeterministic and 'non-' or '', isSetType and 'SET' or '',
+                    asn1Spec))
+
             seenIndices = set()
             idx = 0
             while substrate:
                 if len(namedTypes) <= idx:
                     asn1Spec = None
+
                 elif isSetType:
                     asn1Spec = namedTypes.tagMapUnique
+
                 else:
                     try:
                         if isDeterministic:
                             asn1Spec = namedTypes[idx].asn1Object
+
                         elif namedTypes[idx].isOptional or namedTypes[idx].isDefaulted:
                             asn1Spec = namedTypes.getTagMapNearPosition(idx)
+
                         else:
                             asn1Spec = namedTypes[idx].asn1Object
+
                     except IndexError:
                         raise error.PyAsn1Error(
                             'Excessive components decoded at %r' % (asn1Object,)
@@ -692,13 +789,19 @@ class UniversalConstructedTypeDecoder(AbstractConstructedDecoder):
                     'No EOO seen before substrate ends'
                 )
 
+            if LOG:
+                LOG('seen component indices %s' % seenIndices)
+
             if namedTypes:
                 if not namedTypes.requiredComponents.issubset(seenIndices):
                     raise error.PyAsn1Error('ASN.1 object %s has uninitialized components' % asn1Object.__class__.__name__)
 
                 if  namedTypes.hasOpenTypes:
 
-                    openTypes = options.get('openTypes', None)
+                    openTypes = options.get('openTypes', {})
+
+                    if LOG:
+                        LOG('using open types map: %r' % openTypes)
 
                     if openTypes or options.get('decodeOpenTypes', False):
 
@@ -722,8 +825,15 @@ class UniversalConstructedTypeDecoder(AbstractConstructedDecoder):
                                     openType = namedType.openType[governingValue]
 
                                 except KeyError:
+                                    if LOG:
+                                        LOG('failed to resolve open type by governing '
+                                            'value %r' % (governingValue,))
                                     continue
 
+                            if LOG:
+                                LOG('resolved open type %r by governing '
+                                    'value %r' % (openType, governingValue))
+
                             component, rest = decodeFun(
                                 asn1Object.getComponentByPosition(idx).asOctets(),
                                 asn1Spec=openType, allowEoo=True
@@ -740,6 +850,9 @@ class UniversalConstructedTypeDecoder(AbstractConstructedDecoder):
 
             componentType = asn1Spec.componentType
 
+            if LOG:
+                LOG('decoding type %r chosen by given `asn1Spec`' % componentType)
+
             idx = 0
 
             while substrate:
@@ -753,7 +866,9 @@ class UniversalConstructedTypeDecoder(AbstractConstructedDecoder):
                     verifyConstraints=False,
                     matchTags=False, matchConstraints=False
                 )
+
                 idx += 1
+
             else:
                 raise error.SubstrateUnderrunError(
                     'No EOO seen before substrate ends'
@@ -800,18 +915,25 @@ class ChoiceDecoder(AbstractConstructedDecoder):
 
         if asn1Spec is None:
             asn1Object = self.protoComponent.clone(tagSet=tagSet)
+
         else:
             asn1Object = asn1Spec.clone()
 
         if substrateFun:
             return substrateFun(asn1Object, substrate, length)
 
-        if asn1Object.tagSet == tagSet:  # explicitly tagged Choice
+        if asn1Object.tagSet == tagSet:
+            if LOG:
+                LOG('decoding %s as explicitly tagged CHOICE' % (tagSet,))
+
             component, head = decodeFun(
                 head, asn1Object.componentTagMap, **options
             )
 
         else:
+            if LOG:
+                LOG('decoding %s as untagged CHOICE' % (tagSet,))
+
             component, head = decodeFun(
                 head, asn1Object.componentTagMap,
                 tagSet, length, state, **options
@@ -819,6 +941,9 @@ class ChoiceDecoder(AbstractConstructedDecoder):
 
         effectiveTagSet = component.effectiveTagSet
 
+        if LOG:
+            LOG('decoded component %s, effective tag set %s' % (component, effectiveTagSet))
+
         asn1Object.setComponentByType(
             effectiveTagSet, component,
             verifyConstraints=False,
@@ -840,18 +965,26 @@ class ChoiceDecoder(AbstractConstructedDecoder):
         if substrateFun:
             return substrateFun(asn1Object, substrate, length)
 
-        if asn1Object.tagSet == tagSet:  # explicitly tagged Choice
+        if asn1Object.tagSet == tagSet:
+            if LOG:
+                LOG('decoding %s as explicitly tagged CHOICE' % (tagSet,))
+
             component, substrate = decodeFun(
                 substrate, asn1Object.componentType.tagMapUnique, **options
             )
+
             # eat up EOO marker
             eooMarker, substrate = decodeFun(
                 substrate, allowEoo=True, **options
             )
+
             if eooMarker is not eoo.endOfOctets:
                 raise error.PyAsn1Error('No EOO seen before substrate ends')
 
         else:
+            if LOG:
+                LOG('decoding %s as untagged CHOICE' % (tagSet,))
+
             component, substrate = decodeFun(
                 substrate, asn1Object.componentType.tagMapUnique,
                 tagSet, length, state, **options
@@ -859,6 +992,9 @@ class ChoiceDecoder(AbstractConstructedDecoder):
 
         effectiveTagSet = component.effectiveTagSet
 
+        if LOG:
+            LOG('decoded component %s, effective tag set %s' % (component, effectiveTagSet))
+
         asn1Object.setComponentByType(
             effectiveTagSet, component,
             verifyConstraints=False,
@@ -883,6 +1019,9 @@ class AnyDecoder(AbstractSimpleDecoder):
             length += len(fullSubstrate) - len(substrate)
             substrate = fullSubstrate
 
+            if LOG:
+                LOG('decoding as untagged ANY, substrate %s' % debug.hexdump(substrate))
+
         if substrateFun:
             return substrateFun(self._createComponent(asn1Spec, tagSet, noValue, **options),
                                 substrate, length)
@@ -898,12 +1037,19 @@ class AnyDecoder(AbstractSimpleDecoder):
         if asn1Spec is not None and tagSet == asn1Spec.tagSet:
             # tagged Any type -- consume header substrate
             header = null
+
+            if LOG:
+                LOG('decoding as tagged ANY')
+
         else:
             fullSubstrate = options['fullSubstrate']
 
             # untagged Any, recover header substrate
             header = fullSubstrate[:-len(substrate)]
 
+            if LOG:
+                LOG('decoding as untagged ANY, header substrate %s' % debug.hexdump(header))
+
         # Any components do not inherit initial tag
         asn1Spec = self.protoComponent
 
@@ -911,6 +1057,9 @@ class AnyDecoder(AbstractSimpleDecoder):
             asn1Object = self._createComponent(asn1Spec, tagSet, noValue, **options)
             return substrateFun(asn1Object, header + substrate, length + len(header))
 
+        if LOG:
+            LOG('assembling constructed serialization')
+
         # All inner fragments are of the same type, treat them as octet string
         substrateFun = self.substrateCollector
 
@@ -920,13 +1069,17 @@ class AnyDecoder(AbstractSimpleDecoder):
                                              allowEoo=True, **options)
             if component is eoo.endOfOctets:
                 break
+
             header += component
+
         else:
             raise error.SubstrateUnderrunError(
                 'No EOO seen before substrate ends'
             )
+
         if substrateFun:
             return header, substrate
+
         else:
             return self._createComponent(asn1Spec, tagSet, header, **options), substrate
 
@@ -1091,26 +1244,32 @@ class Decoder(object):
         fullSubstrate = substrate
 
         while state is not stStop:
+
             if state is stDecodeTag:
                 if not substrate:
                     raise error.SubstrateUnderrunError(
                         'Short octet stream on tag decoding'
                     )
+
                 # Decode tag
                 isShortTag = True
                 firstOctet = substrate[0]
                 substrate = substrate[1:]
+
                 try:
                     lastTag = tagCache[firstOctet]
+
                 except KeyError:
                     integerTag = oct2int(firstOctet)
                     tagClass = integerTag & 0xC0
                     tagFormat = integerTag & 0x20
                     tagId = integerTag & 0x1F
+
                     if tagId == 0x1F:
                         isShortTag = False
                         lengthOctetIdx = 0
                         tagId = 0
+
                         try:
                             while True:
                                 integerTag = oct2int(substrate[lengthOctetIdx])
@@ -1119,42 +1278,55 @@ class Decoder(object):
                                 tagId |= (integerTag & 0x7F)
                                 if not integerTag & 0x80:
                                     break
+
                             substrate = substrate[lengthOctetIdx:]
+
                         except IndexError:
                             raise error.SubstrateUnderrunError(
                                 'Short octet stream on long tag decoding'
                             )
+
                     lastTag = tag.Tag(
                         tagClass=tagClass, tagFormat=tagFormat, tagId=tagId
                     )
+
                     if isShortTag:
                         # cache short tags
                         tagCache[firstOctet] = lastTag
+
                 if tagSet is None:
                     if isShortTag:
                         try:
                             tagSet = tagSetCache[firstOctet]
+
                         except KeyError:
                             # base tag not recovered
                             tagSet = tag.TagSet((), lastTag)
                             tagSetCache[firstOctet] = tagSet
                     else:
                         tagSet = tag.TagSet((), lastTag)
+
                 else:
                     tagSet = lastTag + tagSet
+
                 state = stDecodeLength
+
                 if LOG:
                     LOG('tag decoded into %s, decoding length' % tagSet)
+
             if state is stDecodeLength:
                 # Decode length
                 if not substrate:
                     raise error.SubstrateUnderrunError(
                         'Short octet stream on length decoding'
                     )
+
                 firstOctet = oct2int(substrate[0])
+
                 if firstOctet < 128:
                     size = 1
                     length = firstOctet
+
                 elif firstOctet > 128:
                     size = firstOctet & 0x7F
                     # encoded in size bytes
@@ -1165,28 +1337,36 @@ class Decoder(object):
                         raise error.SubstrateUnderrunError(
                             '%s<%s at %s' % (size, len(encodedLength), tagSet)
                         )
+
                     length = 0
                     for lengthOctet in encodedLength:
                         length <<= 8
                         length |= lengthOctet
                     size += 1
+
                 else:
                     size = 1
                     length = -1
 
                 substrate = substrate[size:]
+
                 if length == -1:
                     if not self.supportIndefLength:
                         raise error.PyAsn1Error('Indefinite length encoding not supported by this codec')
+
                 else:
                     if len(substrate) < length:
                         raise error.SubstrateUnderrunError('%d-octet short' % (length - len(substrate)))
+
                 state = stGetValueDecoder
+
                 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
+
                 else:
                     state = stGetValueDecoderByAsn1Spec
             #
@@ -1208,41 +1388,55 @@ class Decoder(object):
             if state is stGetValueDecoderByTag:
                 try:
                     concreteDecoder = tagMap[tagSet]
+
                 except KeyError:
                     concreteDecoder = None
+
                 if concreteDecoder:
                     state = stDecodeValue
+
                 else:
                     try:
                         concreteDecoder = tagMap[tagSet[:1]]
+
                     except KeyError:
                         concreteDecoder = None
+
                     if concreteDecoder:
                         state = stDecodeValue
                     else:
                         state = stTryAsExplicitTag
+
                 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:
                     try:
                         chosenSpec = asn1Spec[tagSet]
+
                     except KeyError:
                         chosenSpec = None
+
                     if LOG:
                         LOG('candidate ASN.1 spec is a map of:')
+
                         for firstOctet, v in asn1Spec.presentTypes.items():
                             LOG('  %s -> %s' % (firstOctet, v.__class__.__name__))
+
                         if asn1Spec.skipTypes:
                             LOG('but neither of: ')
                             for firstOctet, v in asn1Spec.skipTypes.items():
                                 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 LOG:
                         LOG('candidate ASN.1 spec is %s' % asn1Spec.__class__.__name__)
+
                 else:
                     chosenSpec = None
 
@@ -1250,29 +1444,38 @@ class Decoder(object):
                     try:
                         # ambiguous type or just faster codec lookup
                         concreteDecoder = typeMap[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 LOG:
                                 LOG('value decoder chosen by base %s' % (baseTagSet,))
+
                         except KeyError:
                             concreteDecoder = None
+
                     if concreteDecoder:
                         asn1Spec = chosenSpec
                         state = stDecodeValue
+
                     else:
                         state = stTryAsExplicitTag
+
                 else:
                     concreteDecoder = None
                     state = stTryAsExplicitTag
+
                 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
                     substrateFun = lambda a, b, c: (a, b[:c])
@@ -1286,6 +1489,7 @@ class Decoder(object):
                         self, substrateFun,
                         **options
                     )
+
                 else:
                     value, substrate = concreteDecoder.valueDecoder(
                         substrate, asn1Spec,
@@ -1299,28 +1503,37 @@ class Decoder(object):
 
                 state = stStop
                 break
+
             if state is stTryAsExplicitTag:
                 if tagSet and tagSet[0].tagFormat == tag.tagFormatConstructed and tagSet[0].tagClass != tag.tagClassUniversal:
                     # Assume explicit tagging
                     concreteDecoder = explicitTagDecoder
                     state = stDecodeValue
+
                 else:
                     concreteDecoder = None
                     state = self.defaultErrorState
+
                 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 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 LOG:
             debug.scope.pop()
             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 f213d5b..142e167 100644
--- a/pyasn1/codec/ber/encoder.py
+++ b/pyasn1/codec/ber/encoder.py
@@ -33,29 +33,39 @@ class AbstractItemEncoder(object):
         encodedTag = tagClass | tagFormat
         if isConstructed:
             encodedTag |= tag.tagFormatConstructed
+
         if tagId < 31:
             return encodedTag | tagId,
+
         else:
             substrate = tagId & 0x7f,
+
             tagId >>= 7
+
             while tagId:
                 substrate = (0x80 | (tagId & 0x7f),) + substrate
                 tagId >>= 7
+
             return (encodedTag | 0x1F,) + substrate
 
     def encodeLength(self, length, defMode):
         if not defMode and self.supportIndefLenMode:
             return (0x80,)
+
         if length < 0x80:
             return length,
+
         else:
             substrate = ()
             while length:
                 substrate = (length & 0xff,) + substrate
                 length >>= 8
+
             substrateLen = len(substrate)
+
             if substrateLen > 126:
                 raise error.PyAsn1Error('Length octets overflow (%d)' % substrateLen)
+
             return (0x80 | substrateLen,) + substrate
 
     def encodeValue(self, value, asn1Spec, encodeFun, **options):
@@ -87,16 +97,32 @@ class AbstractItemEncoder(object):
                     value, asn1Spec, encodeFun, **options
                 )
 
+                if LOG:
+                    LOG('encoded %svalue %s into %s' % (
+                        isConstructed and 'constructed ' or '', value, substrate
+                    ))
+
                 if not substrate and isConstructed and options.get('ifNotEmpty', False):
                     return substrate
 
-                # primitive form implies definite mode
                 if not isConstructed:
                     defModeOverride = True
 
+                    if LOG:
+                        LOG('overridden encoding mode into definitive for primitive type')
+
             header = self.encodeTag(singleTag, isConstructed)
+
+            if LOG:
+                LOG('encoded %stag %s into %s' % (isConstructed and 'constructed ' or '',
+                                                  singleTag, debug.hexdump(header)))
+
             header += self.encodeLength(len(substrate), defModeOverride)
 
+            if LOG:
+                LOG('encoded %s octets (tag + payload) into %s' % (
+                    len(substrate), debug.hexdump(header)))
+
             if isOctets:
                 substrate = ints2octs(header) + substrate
 
@@ -133,6 +159,11 @@ class IntegerEncoder(AbstractItemEncoder):
 
     def encodeValue(self, value, asn1Spec, encodeFun, **options):
         if value == 0:
+            if LOG:
+                LOG('encoding %spayload for zero INTEGER' % (
+                    self.supportCompactZero and 'no ' or ''
+                ))
+
             # de-facto way to encode zero
             if self.supportCompactZero:
                 return (), False, False
@@ -159,11 +190,15 @@ class BitStringEncoder(AbstractItemEncoder):
             substrate = alignedValue.asOctets()
             return int2oct(len(substrate) * 8 - valueLength) + substrate, False, True
 
+        if LOG:
+            LOG('encoding into up to %s-octet chunks' % maxChunkSize)
+
         baseTag = value.tagSet.baseTag
 
         # strip off explicit tags
         if baseTag:
             tagSet = tag.TagSet(baseTag, baseTag)
+
         else:
             tagSet = tag.TagSet()
 
@@ -197,44 +232,47 @@ class OctetStringEncoder(AbstractItemEncoder):
         if not maxChunkSize or len(substrate) <= maxChunkSize:
             return substrate, False, True
 
-        else:
+        if LOG:
+            LOG('encoding into up to %s-octet chunks' % maxChunkSize)
 
-            # strip off explicit tags for inner chunks
+        # strip off explicit tags for inner chunks
 
-            if asn1Spec is None:
-                baseTag = value.tagSet.baseTag
+        if asn1Spec is None:
+            baseTag = value.tagSet.baseTag
 
-                # strip off explicit tags
-                if baseTag:
-                    tagSet = tag.TagSet(baseTag, baseTag)
-                else:
-                    tagSet = tag.TagSet()
+            # strip off explicit tags
+            if baseTag:
+                tagSet = tag.TagSet(baseTag, baseTag)
 
-                asn1Spec = value.clone(tagSet=tagSet)
+            else:
+                tagSet = tag.TagSet()
+
+            asn1Spec = value.clone(tagSet=tagSet)
 
-            elif not isOctetsType(value):
-                baseTag = asn1Spec.tagSet.baseTag
+        elif not isOctetsType(value):
+            baseTag = asn1Spec.tagSet.baseTag
 
-                # strip off explicit tags
-                if baseTag:
-                    tagSet = tag.TagSet(baseTag, baseTag)
-                else:
-                    tagSet = tag.TagSet()
+            # strip off explicit tags
+            if baseTag:
+                tagSet = tag.TagSet(baseTag, baseTag)
+
+            else:
+                tagSet = tag.TagSet()
 
-                asn1Spec = asn1Spec.clone(tagSet=tagSet)
+            asn1Spec = asn1Spec.clone(tagSet=tagSet)
 
-            pos = 0
-            substrate = null
+        pos = 0
+        substrate = null
 
-            while True:
-                chunk = value[pos:pos + maxChunkSize]
-                if not chunk:
-                    break
+        while True:
+            chunk = value[pos:pos + maxChunkSize]
+            if not chunk:
+                break
 
-                substrate += encodeFun(chunk, asn1Spec, **options)
-                pos += maxChunkSize
+            substrate += encodeFun(chunk, asn1Spec, **options)
+            pos += maxChunkSize
 
-            return substrate, True, True
+        return substrate, True, True
 
 
 class NullEncoder(AbstractItemEncoder):
@@ -270,8 +308,10 @@ class ObjectIdentifierEncoder(AbstractItemEncoder):
                 oid = (second + 80,) + oid[2:]
             else:
                 raise error.PyAsn1Error('Impossible first/second arcs at %s' % (value,))
+
         elif first == 2:
             oid = (second + 80,) + oid[2:]
+
         else:
             raise error.PyAsn1Error('Impossible first/second arcs at %s' % (value,))
 
@@ -282,15 +322,19 @@ class ObjectIdentifierEncoder(AbstractItemEncoder):
             if 0 <= subOid <= 127:
                 # Optimize for the common case
                 octets += (subOid,)
+
             elif subOid > 127:
                 # Pack large Sub-Object IDs
                 res = (subOid & 0x7f,)
                 subOid >>= 7
+
                 while subOid:
                     res = (0x80 | (subOid & 0x7f),) + res
                     subOid >>= 7
+
                 # Add packed Sub-Object ID to resulted Object ID
                 octets += res
+
             else:
                 raise error.PyAsn1Error('Negative OID arc %s at %s' % (subOid, value))
 
@@ -306,12 +350,16 @@ class RealEncoder(AbstractItemEncoder):
         ms, es = 1, 1
         if m < 0:
             ms = -1  # mantissa sign
+
         if e < 0:
             es = -1  # exponent sign
+
         m *= ms
+
         if encbase == 8:
             m *= 2 ** (abs(e) % 3 * es)
             e = abs(e) // 3 * es
+
         elif encbase == 16:
             m *= 2 ** (abs(e) % 4 * es)
             e = abs(e) // 4 * es
@@ -322,6 +370,7 @@ class RealEncoder(AbstractItemEncoder):
                 e -= 1
                 continue
             break
+
         return ms, int(m), encbase, e
 
     def _chooseEncBase(self, value):
@@ -329,23 +378,32 @@ class RealEncoder(AbstractItemEncoder):
         encBase = [2, 8, 16]
         if value.binEncBase in encBase:
             return self._dropFloatingPoint(m, value.binEncBase, e)
+
         elif self.binEncBase in encBase:
             return self._dropFloatingPoint(m, self.binEncBase, e)
-        # auto choosing base 2/8/16 
+
+        # auto choosing base 2/8/16
         mantissa = [m, m, m]
         exponent = [e, e, e]
         sign = 1
         encbase = 2
         e = float('inf')
+
         for i in range(3):
             (sign,
              mantissa[i],
              encBase[i],
              exponent[i]) = self._dropFloatingPoint(mantissa[i], encBase[i], exponent[i])
+
             if abs(exponent[i]) < abs(e) or (abs(exponent[i]) == abs(e) and mantissa[i] < m):
                 e = exponent[i]
                 m = int(mantissa[i])
                 encbase = encBase[i]
+
+        if LOG:
+            LOG('automatically chosen REAL encoding base %s, sign %s, mantissa %s, '
+                'exponent %s' % (encbase, sign, m, e))
+
         return sign, m, encbase, e
 
     def encodeValue(self, value, asn1Spec, encodeFun, **options):
@@ -354,69 +412,98 @@ class RealEncoder(AbstractItemEncoder):
 
         if value.isPlusInf:
             return (0x40,), False, False
+
         if value.isMinusInf:
             return (0x41,), False, False
+
         m, b, e = value
+
         if not m:
             return null, False, True
+
         if b == 10:
+            if LOG:
+                LOG('encoding REAL into character form')
+
             return str2octs('\x03%dE%s%d' % (m, e == 0 and '+' or '', e)), False, True
+
         elif b == 2:
             fo = 0x80  # binary encoding
             ms, m, encbase, e = self._chooseEncBase(value)
+
             if ms < 0:  # mantissa sign
                 fo |= 0x40  # sign bit
+
             # exponent & mantissa normalization
             if encbase == 2:
                 while m & 0x1 == 0:
                     m >>= 1
                     e += 1
+
             elif encbase == 8:
                 while m & 0x7 == 0:
                     m >>= 3
                     e += 1
                 fo |= 0x10
+
             else:  # encbase = 16
                 while m & 0xf == 0:
                     m >>= 4
                     e += 1
                 fo |= 0x20
+
             sf = 0  # scale factor
+
             while m & 0x1 == 0:
                 m >>= 1
                 sf += 1
+
             if sf > 3:
                 raise error.PyAsn1Error('Scale factor overflow')  # bug if raised
+
             fo |= sf << 2
             eo = null
             if e == 0 or e == -1:
                 eo = int2oct(e & 0xff)
+
             else:
                 while e not in (0, -1):
                     eo = int2oct(e & 0xff) + eo
                     e >>= 8
+
                 if e == 0 and eo and oct2int(eo[0]) & 0x80:
                     eo = int2oct(0) + eo
+
                 if e == -1 and eo and not (oct2int(eo[0]) & 0x80):
                     eo = int2oct(0xff) + eo
+
             n = len(eo)
             if n > 0xff:
                 raise error.PyAsn1Error('Real exponent overflow')
+
             if n == 1:
                 pass
+
             elif n == 2:
                 fo |= 1
+
             elif n == 3:
                 fo |= 2
+
             else:
                 fo |= 3
                 eo = int2oct(n & 0xff) + eo
+
             po = null
+
             while m:
                 po = int2oct(m & 0xff) + po
                 m >>= 8
+
             substrate = int2oct(fo) + eo + po
+
             return substrate, False, True
+
         else:
             raise error.PyAsn1Error('Prohibited Real base %s' % b)
 
@@ -441,10 +528,14 @@ class SequenceEncoder(AbstractItemEncoder):
                     namedType = namedTypes[idx]
 
                     if namedType.isOptional and not component.isValue:
-                            continue
+                        if LOG:
+                            LOG('not encoding OPTIONAL component %r' % (namedType,))
+                        continue
 
                     if namedType.isDefaulted and component == namedType.asn1Object:
-                            continue
+                        if LOG:
+                            LOG('not encoding DEFAULT component %r' % (namedType,))
+                        continue
 
                     if self.omitEmptyOptionals:
                         options.update(ifNotEmpty=namedType.isOptional)
@@ -457,6 +548,9 @@ class SequenceEncoder(AbstractItemEncoder):
                     if wrapType.tagSet and not wrapType.isSameTypeWith(component):
                         chunk = encodeFun(chunk, wrapType, **options)
 
+                        if LOG:
+                            LOG('wrapped open type with wrap type %r' % (wrapType,))
+
                 substrate += chunk
 
         else:
@@ -467,12 +561,17 @@ class SequenceEncoder(AbstractItemEncoder):
                     component = value[namedType.name]
 
                 except KeyError:
-                    raise error.PyAsn1Error('Component name "%s" not found in %r' % (namedType.name, value))
+                    raise error.PyAsn1Error('Component name "%s" not found in %r' % (
+                        namedType.name, value))
 
                 if namedType.isOptional and namedType.name not in value:
+                    if LOG:
+                        LOG('not encoding OPTIONAL component %r' % (namedType,))
                     continue
 
                 if namedType.isDefaulted and component == namedType.asn1Object:
+                    if LOG:
+                        LOG('not encoding DEFAULT component %r' % (namedType,))
                     continue
 
                 if self.omitEmptyOptionals:
@@ -486,6 +585,9 @@ class SequenceEncoder(AbstractItemEncoder):
                     if wrapType.tagSet and not wrapType.isSameTypeWith(component):
                         chunk = encodeFun(chunk, wrapType, **options)
 
+                        if LOG:
+                            LOG('wrapped open type with wrap type %r' % (wrapType,))
+
                 substrate += chunk
 
         return substrate, True, True