Can't find the source of exception

Question

I'm trying to find the cause of a crash in of our python scripts.

The main structure is this:

def main()
    try:
      dostuff
    except Exception as ex:
      import traceback
      tb = traceback.format_exc()
      import platform
      node = platform.node()
      sendMail([DEBUG_EMAIL], "Alarm exception on %s" % node, str(tb), [])

I get this stacktrace in our main error handling, not in an error email which I'm supposed to.

Traceback (most recent call last):
  File "/usr/lib/python2.6/logging/__init__.py", line 799, in emit
    stream.write(fs % msg.encode("UTF-8"))
UnicodeDecodeError: 'ascii' codec can't decode byte 0xc3 in position 66: ordinal not in range(128)

From what I see all of the write-calls to logger are inside the try-block, but since it's not caught and handled in my email sending exception block it seems I've missed something. I've checked and the sendMail function doesn't use the logging module at all. So the exception shouldn't originate in my except-block.

I tried adding

sys.tracebacklimit = 10

at the top of the file see where the exception originates but that didn't affect anything. And now I'm out of ideas on how to find where the problem originates.

The script runs once every hour and only crashes about once per week, which makes me assume that it's something related to the input data, but that's only handled by dostuff().

UPDATE:

I've figured out why I only get one row of the stacktrace. Inside the emit() I found this.

        try:
            ... doing stuff, something goes boom with encoding...
        except UnicodeError:
            stream.write(fs % msg.encode("UTF-8")) Here it goes Boom again
        self.flush()
    except (KeyboardInterrupt, SystemExit):
        raise
    except:
        self.handleError(record) Which means it ends up here

And the relevant part of the handleError function looks like this:

 ei = sys.exc_info()
 try:
     traceback.print_exception(ei[0], ei[1], ei[2], None, sys.stderr)

Which only prints the last part of the stacktrace.

Answer 1

Basically your problem is twofold

1. One log stream does not accept 8-bit strings with extended characters, and throws UnicodeError
2. There is a silly bug in logging module which make it lose the original traceback

The exact cause of the exception is this:

>>> 'ä'.encode('UTF-8')
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
UnicodeDecodeError: 'ascii' codec can't decode byte 0xc3 in position 0: ordinal not in range(128)

But this exception is not the real problem. This is the part of the 2.6 logging code; the 799 is the last line of the block. The last line is the one causing the problems. Basically something logs a message in a 8-bit byte string, UTF-8 encoded, containing Latin-1 extended letters; but the stream does not like that, and throws an UnicodeError within the try block;

try:
    if (isinstance(msg, unicode) and
        getattr(stream, 'encoding', None)):

        # .... the string is NOT an unicode instance, so ignored
        # for brevity
    else:
        # this line throws the original exception 
        # fs is a bytestring "%s\n", and msg is a bytestring
        # with extended letters, most probably Latin 1.
        # stream.write spits out an UnicodeError on these values
        stream.write(fs % msg)
except UnicodeError:
    # now we get a useless exception report from this code
    stream.write(fs % msg.encode("UTF-8"))

So to debug this you'd want to set up a breakpoint on the aforementioned line 799, and try all loggers if they accept the following string:

logging.getLogger(name).critical('Testing logger: ä')

If you hit line 799 then get the backtrace of the exception, it can shed some light on what is happening...