This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: logging %(module)s reporting wrong modules
Type: Stage:
Components: Library (Lib) Versions:
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: mad-marty, sf-robot, vinay.sajip
Priority: normal Keywords:

Created on 2006-11-29 09:29 by mad-marty, last changed 2022-04-11 14:56 by admin. This issue is now closed.

Messages (7)
msg30711 - (view) Author: Pieter Zieschang (mad-marty) Date: 2006-11-29 09:29
I recently upgraded from python 2.4.2 to 2.4.4 
and the logging seems to be working wrong now.

I have a formatter which uses the %(module)s and %(filename)s and the point to the wrong file/module.


I have some plugins in .py files, which mainly have one class derived from threading.Thread.

Those classes logging calls will now log as 

2006-11-29 10:17:50 - threading.py - threading - INFO - ...

instead of

2006-11-29 10:17:50 - myplugin.py - myplugin - INFO - ...

msg30712 - (view) Author: Pieter Zieschang (mad-marty) Date: 2006-11-29 09:32
Forgot to add, that is is the 2.4.4 windows package used on windows xp. ;-)
msg30713 - (view) Author: Pieter Zieschang (mad-marty) Date: 2006-11-29 12:02
Checked again and found that the bug was introduced with Python 2.4.2.
Last correctly working version is python-2.4.1.msi.
msg30714 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2006-11-30 09:18
I need more information. For example (N.B. lines may wrap, please adjust if copy/pasting the code below):
#-- test.py
import module
import logging

logging.basicConfig(level=logging.DEBUG,
                    format="%(relativeCreated)-6d %(module)s %(filename)s %(lineno)d - %(message)s")

logging.getLogger("test").debug("Test starting, about to start thread...")
threads = module.start()
for t in threads:
    t.join()
logging.getLogger("test").debug("All done.")
#-- test.py ends

#-- module.py
import logging
import threading
import random
import time

class MyThread(threading.Thread):
    def run(self):
        loops = 5
        while True:
            logging.getLogger("module").debug("Running in thread: %s",
                               threading.currentThread().getName())
            time.sleep(random.random())
            loops -= 1
            if loops < 0:
                break

class MyOtherThread(threading.Thread):
    def run(self):
        loops = 5
        while True:
            logging.getLogger("module").debug("Running in thread: %s",
                               threading.currentThread().getName())
            time.sleep(random.random())
            loops -= 1
            if loops < 0:
                break

def start():
    t1 = MyThread(name="Thread One")
    t2 = MyOtherThread(name="Thread Two")
    t1.start()
    t2.start()
    return t1, t2
#-- module.py ends

When I run test, I get the following output:

15     test test.py 7 - Test starting, about to start thread...
15     module module.py 11 - Running in thread: Thread One
15     module module.py 22 - Running in thread: Thread Two
327    module module.py 11 - Running in thread: Thread One
343    module module.py 22 - Running in thread: Thread Two
655    module module.py 11 - Running in thread: Thread One
780    module module.py 22 - Running in thread: Thread Two
1000   module module.py 11 - Running in thread: Thread One
1546   module module.py 22 - Running in thread: Thread Two
1890   module module.py 11 - Running in thread: Thread One
2046   module module.py 11 - Running in thread: Thread One
2218   module module.py 22 - Running in thread: Thread Two
2562   module module.py 22 - Running in thread: Thread Two
3187   test test.py 11 - All done.

This is the expected output. Python version used:

ActivePython 2.4.3 Build 12 (ActiveState Software Inc.) based on
Python 2.4.3 (#69, Apr 11 2006, 15:32:42) [MSC v.1310 32 bit (Intel)] on win32

msg30715 - (view) Author: Pieter Zieschang (mad-marty) Date: 2006-12-02 01:09
Hi,

after some investigation, I think I found the source.

Just add 'import psyco; psyco.full()' to test.py aufer imports and you get the same problem with your example.
It seems, logging is not compatible with the way psyco creates proxy functions.
Could be that sys._getframe returns something different. - just a guess

But it works with the old logging.

Is there any other information you may want ?
msg30716 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2006-12-11 15:05
I'm not sure this should be treated as a logging bug - after all, psyco is not part of standard Python and logging is only tested as a part of standard Python. Possibly this should be logged under psyco rather than Python logging. Meanwhile, if time permits I will take a look at this.
msg30717 - (view) Author: SourceForge Robot (sf-robot) Date: 2006-12-26 03:20
This Tracker item was closed automatically by the system. It was
previously set to a Pending status, and the original submitter
did not respond within 14 days (the time period specified by
the administrator of this Tracker).
History
Date User Action Args
2022-04-11 14:56:21adminsetgithub: 44289
2006-11-29 09:29:16mad-martycreate