Python Logging - Nachricht nicht in Kind

Question

Ich habe einige Schwierigkeiten mit Python Logging. Ich habe zwei Dateien, main.py und mymodule.py. Im Allgemeinen wird main.py ausgeführt, und es importiert mymodule.py und verwendet einige Funktionen von dort. Aber manchmal werde ich mymodule.py direkt ausführen.

Ich habe versucht, es so zu machen, dass die Protokollierung nur an einem Ort konfiguriert ist, aber etwas scheint falsch.

Hier ist der Code.

# main.py 
import logging 
import mymodule 

logger = logging.getLogger(__name__) 

def setup_logging(): 
    # only cofnigure logger if script is main module 
    # configuring logger in multiple places is bad 
    # only top-level module should configure logger 
    if not len(logger.handlers): 
     logger.setLevel(logging.DEBUG) 
     # create console handler with a higher log level 
     ch = logging.StreamHandler() 
     ch.setLevel(logging.DEBUG) 
     formatter = logging.Formatter('%(levelname)s: %(asctime)s %(funcName)s(%(lineno)d) -- %(message)s', datefmt = '%Y-%m-%d %H:%M:%S') 
     ch.setFormatter(formatter) 
     logger.addHandler(ch) 

if __name__ == '__main__': 
    setup_logging() 
    logger.info('calling mymodule.myfunc()') 
    mymodule.myfunc() 

und das importierte Modul:

# mymodule.py 
import logging 

logger = logging.getLogger(__name__) 

def myfunc(): 
    msg = 'myfunc is being called' 
    logger.info(msg) 
    print('done with myfunc') 


if __name__ == '__main__': 
    # only cofnigure logger if script is main module 
    # configuring logger in multiple places is bad 
    # only top-level module should configure logger 
    if not len(logger.handlers): 
     logger.setLevel(logging.DEBUG) 
     # create console handler with a higher log level 
     ch = logging.StreamHandler() 
     ch.setLevel(logging.DEBUG) 
     formatter = logging.Formatter('%(levelname)s: %(asctime)s %(funcName)s(%(lineno)d) -- %(message)s', datefmt = '%Y-%m-%d %H:%M:%S') 
     ch.setFormatter(formatter) 
     logger.addHandler(ch) 
    logger.info('myfunc was executed directly') 
    myfunc() 

Wenn ich den Code ausführen, sehe ich diese Ausgabe:

$>python main.py 
INFO: 2016-07-14 18:13:04 <module>(22) -- calling mymodule.myfunc() 
done with myfunc 

Aber ich erwarte, dass dies sehen:

$>python main.py 
INFO: 2016-07-14 18:13:04 <module>(22) -- calling mymodule.myfunc() 
INFO: 2016-07-14 18:15:09 myfunc(8) -- myfunc is being called 
done with myfunc 

Jeder hat Irgendeine Idee warum der zweite logging.info Aufruf nicht auf dem Bildschirm gedruckt wird? Danke im Voraus!

Answer 1

Logger existieren in einer Hierarchie, mit einem Root-Logger (abgerufen mit logging.getLogger(), keine Argumente) an der Spitze. Jeder Logger erbt die Konfiguration von seinem übergeordneten Server, wobei jede Konfiguration auf dem Logger selbst die geerbte Konfiguration außer Kraft setzt. In diesem Fall konfigurieren Sie niemals den Root-Logger, sondern nur den modulspezifischen Logger in main.py. Daher ist der modulspezifische Logger in mymodule.py niemals konfiguriert.

Die einfachste Lösung ist wahrscheinlich logging.basicConfig in main.py verwenden Optionen festlegen, die Sie von alle Loggern geteilt werden sollen.

Answer 2

Chepner ist korrekt. Ich habe mich in dieses Problem vertieft. Das Problem ist einfach in Ihrem Haupt-Skript

16 log = logging.getLogger() # use this form to initialize the root logger 
17 #log = logging.getLogger(__name__) # never use this one 

Wenn Sie Linie 17 benutzen, dann importiert Python-Modulen werden keine Log-Meldungen

In Sie

import logging 
logger = logging.getLogger() 
logger.debug("You will not see this message if you use line 17 in main") 

Hoffnung dieser Eintrag submodule.py kann jemandem helfen, der bei diesem Problem stecken geblieben ist.