Benutzerdefinierte Logger mit Zeitstempel in Python

Question

Ich habe viel Code auf ein Projekt mit print-Anweisungen und wollte schnell eine schmutzige Logger dieser Druckanweisungen machen und entschied sich für die benutzerdefinierte Route gehen. Ich habe es geschafft, einen Logger zusammenzustellen, der sowohl auf das Terminal als auch auf eine Datei druckt (mit Hilfe dieser Seite), aber jetzt möchte ich jeder Aussage einen einfachen Zeitstempel hinzufügen, und ich stoße auf ein komisches Problem.

Hier ist meine Protokollierungsklasse.

class Logger(object): 
    def __init__(self, stream): 
     self.terminal = stream 
     self.log = open("test.log", 'a') 

    def write(self, message): 
     self.terminal.flush() 
     self.terminal.write(self.stamp() + message) 
     self.log.write(self.stamp() + message) 

    def stamp(self): 
     d = datetime.today() 
     string = d.strftime("[%H:%M:%S] ") 
     return string 

Beachten Sie die Stempelmethode, die ich dann versuche, in der Schreibmethode zu verwenden.

Wenn die folgenden zwei Zeilen laufen bekomme ich einen unerwarteten Ausgang:

sys.stdout = Logger(sys.stdout) 
print("Hello World!") 

Ausgang:

[11:10:47] Hello World![11:10:47] 

Das, was die Ausgabe sieht auch in der Log-Datei, aber ich sehe keinen Grund, warum Die Zeichenfolge, die ich hinzufüge, hängt an das Ende an. Kann mir hier jemand helfen?

UPDATE Siehe Antwort unten. Zur schnelleren Bezugnahme wird das Problem jedoch generell mit "print()" behoben. Ersetzen Sie es nach dem Zuweisen der Variablen durch sys.stdout.write.

Verwenden Sie auch "Logging" für langfristige/größere Projekte auf Anhieb.

Answer 1

Es ruft die Methode .write() Ihres Streams zweimal auf, weil in Cpython print die Stream-Methode .write() zweimal aufruft. Das erste Mal ist mit dem Objekt und das zweite Mal schreibt es ein Newline-Zeichen. Zum Beispiel sehen line 138 in the pprint module in cpython v3.5.2

def pprint(self, object): 
    self._format(object, self._stream, 0, 0, {}, 0) 
    self._stream.write("\n") # <- write() called again! 

können Sie diese testen:

>>> from my_logger import Logger # my_logger.py has your Logger class 
>>> import sys 
>>> sys.stdout = Logger(stream=sys.stdout) 
>>> sys.stdout.write('hi\n') 
[14:05:32] hi 

Sie können print(<blah>) überall in Ihrem Code ersetzen sed verwenden.

$ for mymodule in *.py; do 
> sed -i -E "s/print\((.+)\)/LOGGER.debug(\1)/" $mymodule 
> done 

Auschecken Python's Logging builtin module. Es hat ziemlich umfassende Protokollierung einschließlich der Aufnahme eines Zeitstempels in allen Nachrichtenformat.

import logging 
FORMAT = '%(asctime)-15s %(message)s' 
DATEFMT = '%Y-%m-%d %H:%M:%S' 
logging.basicConfig(format=FORMAT, datefmt=DATEFMT) 
logger = logging.getLogger(__name__) 
logger.setLevel(logging.DEBUG) 

logger.debug('message: %s', 'message') 

Diese Ausgänge 2016-07-29 11:44:20 message: message zu stdout. Es gibt auch Handler, um die Ausgabe an Dateien zu senden. Es gibt eine basic tutorial, eine advanced tutorial und eine cookbook of common logging recipes.

Es gibt ein Beispiel für die Verwendung von simultaneous file and console loggers im Kochbuch.

import logging 

LOGGER = logging.getLogger(__name__) # get logger named for this module 
LOGGER.setLevel(logging.DEBUG) # set logger level to debug 

# create formatter 
LOG_DATEFMT = '%Y-%m-%d %H:%M:%S' 
LOG_FORMAT = ('\n[%(levelname)s/%(name)s:%(lineno)d] %(asctime)s ' + 
       '(%(processName)s/%(threadName)s)\n> %(message)s') 
FORMATTER = logging.Formatter(LOG_FORMAT, datefmt=LOG_DATEFMT) 

CH = logging.StreamHandler() # create console handler 
CH.setLevel(logging.DEBUG) # set handler level to debug 
CH.setFormatter(FORMATTER) # add formatter to ch 
LOGGER.addHandler(CH) # add console handler to logger 

FH = logging.FileHandler('myapp.log') # create file handler 
FH.setLevel(logging.DEBUG) # set handler level to debug 
FH.setFormatter(FORMATTER) # add formatter to fh 
LOGGER.addHandler(FH) # add file handler to logger 

LOGGER.debug('test: %s', 'hi') 

Diese Ausgänge:

[DEBUG/__main__:22] 2016-07-29 12:20:45 (MainProcess/MainThread) 
> test: hi 

sowohl Konsole und Datei gleichzeitig myapp.log.

Answer 2

Wahrscheinlich müssen Sie den Zeilenumbruch verwenden.

class Logger(object): 
    def __init__(self, stream): 
     self.terminal = stream 
     self.log = open("test.log", 'a') 

    def write(self, message): 
     self.terminal.flush() 
     self.terminal.write(self.stamp() + message + "\n") 
     self.log.write(self.stamp() + message + "\n") 

    def stamp(self): 
     d = datetime.today() 
     string = d.strftime("[%H:%M:%S] ") 
     return string 

Wie auch immer, die Verwendung von integrierten Logging-Modul wird besser sein.