Python logging module kicking up KeyErrors?

Question

I'm using the logging module across various functions, and it's kicking up an error stack that looks like this:

KeyError: 'level'                                                                                                     x
Traceback (most recent call last):                                                                                    x
  File "/usr/lib64/python2.6/logging/__init__.py", line 776, in emit                                                  x
    msg = self.format(record)                                                                                         x
  File "/usr/lib64/python2.6/logging/__init__.py", line 654, in format                                                x
    return fmt.format(record)                                                                                         x
  File "/usr/lib64/python2.6/logging/__init__.py", line 439, in format                                                x
    s = self._fmt % record.__dict__                                                                                   x
KeyError: 'level'                                                                                                     x
Traceback (most recent call last):                                                                                    x
  File "/usr/lib64/python2.6/logging/__init__.py", line 776, in emit                                                  x
    msg = self.format(record)                                                                                         x
  File "/usr/lib64/python2.6/logging/__init__.py", line 654, in format                                                x
    return fmt.format(record)                                                                                         x
  File "/usr/lib64/python2.6/logging/__init__.py", line 439, in format                                                x
    s = self._fmt % record.__dict__                                                                                   x
KeyError: 'level'                                                                                                     x
Traceback (most recent call last):                                                                                    x
  File "/usr/lib64/python2.6/logging/__init__.py", line 776, in emit                                                  x
    msg = self.format(record)                                                                                         x
  File "/usr/lib64/python2.6/logging/__init__.py", line 654, in format                                                x
    return fmt.format(record)                                                                                         x
  File "/usr/lib64/python2.6/logging/__init__.py", line 439, in format                                                x
    s = self._fmt % record.__dict__                                                                                   x
KeyError: 'level'                                                                                                     x
Traceback (most recent call last):                                                                                    x
  File "/usr/lib64/python2.6/logging/__init__.py", line 776, in emit                                                  x
    msg = self.format(record)                                                                                         x
  File "/usr/lib64/python2.6/logging/__init__.py", line 654, in format                                                x
    return fmt.format(record)                                                                                         x
  File "/usr/lib64/python2.6/logging/__init__.py", line 439, in format                                                x
    s = self._fmt % record.__dict__                                                                                   x
KeyError: 'level' 

I'm struggling to figure out why. Here is my code:

from csv import reader, writer
import logging
from sys import argv
from types import IntType, FloatType


def main():
    logging.basicConfig(level=logging.INFO, format='[%(level)s] - %(message)s')
    # logging.disable(logging.CRITICAL)

    # Files
    infile = argv[1]
    header_file = argv[2]
    transact_file = argv[3]

    start_process(infile)


def start_process(infile):
    """Create a csv reader and parse it into two lists."""

    with open(infile, 'r') as inf:
        logging.info('Infile name: {0}'.format(inf))
        csv_reader = reader(inf, quotechar='"')
        parse_headers(csv_reader)


def parse_headers(reader_obj):
    """Separate header files ("H", "S") from transaction files."""

    headers = []
    transactions = []

    for row in reader_obj:
        row_type = row[0]
        logging.info('Row type is: {0}'.format(row_type))
        if row_type == 'H':
            logging.info('Row added to header list.')
            headers.append(row)
            if row_type == 'S':
                if row not in headers:
                    headers.append(row)
        else:
            logging.info('Row added to transaction list.')
            transactions.append(row)

    logging.info('Header list contains: {0}'.format('\n'.join([str(header) for header
        in headers])))
    logging.info('Transaction list contains: {0}'.format(
        '\n'.join([str(trans) for trans in transactions])))

    recon_totals(headers, transactions)


def recon_totals(header_list, transact_list):
    """Reconcile the check total amount and document count."""

    # Client totals
    client_doc_count = int(header_list[0][6])     
    client_check_tot = float(header_list[0][7])

    # Double check variable typing for reconciliation totals.
    logging.info('Document count is: {0}'.format(client_doc_count))
    doc_var_type = type(client_doc_count)
    assert doc_var_type is IntType, 'Doc Count is not an integer: {0}'.format(
        doc_var_type) 
    logging.info('Check Total is: {0}'.format(client_check_tot))
    check_var_type = type(client_check_tot)
    assert check_var_type is FloatType, 'Check tot is not a float: {0}'.format(
        check_var_type)

    # RRD totals
    rrd_doc_count = 0
    rrd_check_tot = 0.0

    for transact in transact_list:
        row_type = transact[0]
        logging.info('Transaction type is: {0}'.format(row_type))

        if row_type == 'P':
            rrd_doc_count += 1
            trans_chk_amt = float(transact[12])
            trans_chk_type = type(trans_chk_amt)
            assert trans_chk_type is FloatType, 'Transaction Check Total is '\
                                                'not a float: {0}'.format(
                                                    trans_chk_type)
            rrd_check_tot += trans_chk_amt

    # Reconcile totals
    if (client_doc_count, client_check_tot) == (rrd_doc_count, rrd_check_tot):
        write_files()
    else:
        raise ValueError('Recon totals do not match! Client: {0} {1} '
                         'RRD {2} {3}'.format(client_doc_count,
                                              client_check_tot,
                                              rrd_doc_count,
                                              rrd_check_tot))


def write_files(header_file, transact_file, header_data, transact_data):
    pass


if __name__ == '__main__':
    main()

As a side note, is it bad practice to call one function from another in a chain like I'm doing? Should I be doing this as separate processes? I was going to create a class that handles it all, but then I decided there was not real benefit.

Answer 1

Your format string format='[%(level)s] - %(message)s' needs to be: format='%(levelname)s - %(message)s'

Answer 2

level isn't one of the standard LogRecord attributes, so when you use it in the logging format:

logging.basicConfig(level=logging.INFO, format='[%(level)s] - %(message)s')

the formatter can't find level and throws an exception. Perhaps you meant levelname or levelno?