CODEWITHSUNDEEP
pythonlogging
Bo Milanovich
Bo Milanovich

Reputation: 8201

How to properly log errors/info with Python?

I'm building a GUI program that has several a GUI (main) module and 4 different QThread modules. I want to be able to properly log unhandled exceptions and other various information that I specify. So I decided to use the python's built-in logging module.

This is what I configured it as:

logging.basicConfig(filename="ubc.log", 
                    format='%(asctime)-6s: %(name)s - %(levelname)s - %(module)s - %(funcName)s - %(lineno)d - %(message)s', 
                    level=logging.DEBUG)

Per this config, I wanted the logging module to tell me exactly what line an error/information occurred on, in which module, what function did it take place in, etc. However, this is what I get in the log (when I do logging.info("text")):

2011-12-22 16:06:02,072: root - INFO - logging - info - 1592 - Calling load blog names function, tabWidget index is 0

Needless to say, most of this information is of no use to me. Line number is definitely not 1592, function name is not info, and module is not logging.

To reiterate, what I want is this: when I say logging.info("log this"), I want this to appear in the log:

2011-12-22 16:06:02,072: root - INFO - WorkerThread1.py - upload_function(self, email, param) - line number 131 - log this

Is something like this possible, and if so, how?

EDIT: Per request, I'm adding more code:

class UI(QMainWindow, ui_ui.Ui_MainWindow):

    def __init__(self, parent=None):
        super(BlogCreator, self).__init__(parent)
        self.setupUi(self)
        self.tabWidget.setCurrentIndex(0)

        logging.info("Prda!")

The logging.info("Prda!") is on line 414 of the GUI.py file. As you can see, this message should be written every time the software starts (this is the setupUi). And it is written, but here is what is being written:

2011-12-22 16:53:04,209: root - INFO - logging - info - 1592 - Prda!

EDIT #2 Upon further examination, it seems that it is PyInstaller that somehow screws things up. Running the software directly through the interpreter produces desired results; after the program has been compiled into EXE file, the aforementioned occurs.

Upvotes: 2

Views: 1072

Answers (3)

gecco
gecco

Reputation: 18870

I was not able to reproduce your problem. This post contains a very simple example. Please give it a try and tell us if you succeed to get a correct result or not:

myModule.py:

import logging
logging.basicConfig(filename="myLogFile.log", \
    format='%(asctime)-6s: %(name)s - %(levelname)s - %(module)s - %(funcName)s - %(lineno)d - %(message)s', \
    level=logging.DEBUG)

def myFct():
    logging.info("info at module.function level")

logging.info("info at module level")
myFct()

After execution, my log file contains:

2011-12-23 10:35:09,743: root - INFO - myModule - <module> - 11 - info at module level
2011-12-23 10:35:09,743: root - INFO - myModule - myFct - 9 - info at module.class.function level

Upvotes: 1

Stan
Stan

Reputation: 8976

Maybe the traceback module is what you are looking for :

import sys, traceback

try:
    my_function()
except Exception:
    exc_type, exc_value, exc_traceback = sys.exc_info()
    msg = u"\n".join(traceback.format_tb(exc_traceback))
    logging.error(msg)

Upvotes: 0

lbolla
lbolla

Reputation: 5411

Can you post a full snippet? If I do what you just said, I get a proper log. I'll post my script here (named stackoverflow_8613924.py), for comparison:

import logging

logging.basicConfig(filename=None, format='%(asctime)-6s: %(name)s - %(levelname)s - %(module)s - %(funcName)s - %(lineno)d - %(message)s', level=logging.DEBUG)

def fname():
    logging.info('hello world')

fname()

Executing it gives me:

$ python stackoverflow_8613924.py 
2011-12-23 09:05:35,678: root - INFO - stackoverflow_8613924 - fname - 6 - hello world

Upvotes: 3

Related Questions