[ python-Bugs-1605110 ] logging %(module)s reporting wrong modules

[SourceForge.net]

Bugs item #1605110, was opened at 2006-11-29 09:29
Message generated for change (Comment added) made by vsajip
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=105470&aid=1605110&group_id=5470

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: Python Library
Group: None
>Status: Pending
>Resolution: Invalid
Priority: 5
Private: No
Submitted By: Pieter Zieschang (mad-marty)
Assigned to: Vinay Sajip (vsajip)
Summary: logging %(module)s reporting wrong modules

Initial Comment:
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 - ...



----------------------------------------------------------------------

>Comment By: Vinay Sajip (vsajip)
Date: 2006-12-11 15:05

Message:
Logged In: YES 
user_id=308438
Originator: NO

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.

----------------------------------------------------------------------

Comment By: Pieter Zieschang (mad-marty)
Date: 2006-12-02 01:09

Message:
Logged In: YES 
user_id=1269426
Originator: YES

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 ?

----------------------------------------------------------------------

Comment By: Vinay Sajip (vsajip)
Date: 2006-11-30 09:18

Message:
Logged In: YES 
user_id=308438
Originator: NO

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



----------------------------------------------------------------------

Comment By: Pieter Zieschang (mad-marty)
Date: 2006-11-29 12:02

Message:
Logged In: YES 
user_id=1269426
Originator: YES

Checked again and found that the bug was introduced with Python 2.4.2.
Last correctly working version is python-2.4.1.msi.

----------------------------------------------------------------------

Comment By: Pieter Zieschang (mad-marty)
Date: 2006-11-29 09:32

Message:
Logged In: YES 
user_id=1269426
Originator: YES

Forgot to add, that is is the 2.4.4 windows package used on windows xp.
;-)

----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=105470&aid=1605110&group_id=5470