CODEWITHSUNDEEP
pythonpython-3.xfilestdout
amkleist
amkleist

Reputation: 191

Why is sys.stdout.write called twice?

I'm trying to log all my prints to a log file (and add a timestamp before the actual message, only in the log file), but I cannot figure out why sys.stdout.write is called twice.

import sys
from datetime import datetime

class Logger(object):
    def __init__(self, filename="Default.log"):
        self.stdout = sys.stdout
        self.log = open(filename, "w")

    def write(self, message):
        self.stdout.write(message)
        time_stamp = datetime.now().strftime('%Y-%m-%d %H:%M:%S.%f')
        self.log.write(f"{time_stamp} - {message}")
        self.log.flush()
    
    def flush(self):
        pass

sys.stdout = Logger("log_file.txt")
print("Hello world !")

Output from terminal:

Hello World !

Output in log_file.txt:

2021-04-19 18:43:14.800691 - Hello world !2021-04-19 18:43:14.800735 -

What am I missing here? The write method is called again after the self.log.flush() has been called, but here message=''.

If I neglect the time_stamp variable it works like a charm, e.g calling self.log.write(message).

I could of course just check if message is empty, but I would really like to understand my problem here!

My solution

@iBug gave me the answer! I didn't know that print did work this way: one write call for the data and one write call for the end keyword which is \n as default.

My solution was to add a variable self._hidden_end to mthe Logger class that is initiated to 0 and then toggles everytime write is called to check it I should add a time stampe before writing to the log or not.

import sys
from datetime import datetime

class Logger(object):
    def __init__(self, filename="Default.log"):
        self.stdout = sys.stdout
        self.log = open(filename, "w")
        self._hidden_end = 0

    def write(self, message):
        self.stdout.write(message)
        if not self._hidden_end:
            time_stamp = datetime.now().strftime('%Y-%m-%d %H:%M:%S.%f')
            message = f"{time_stamp} - {message}"
        self._hidden_end ^= 1
        self.log.write(message)
        self.log.flush()
    
    def flush(self):
        pass

sys.stdout = Logger("log_file.txt")
print("Hello world !")

Any thoughts on my solution above are welcome! :)

Upvotes: 0

Views: 822

Answers (1)

iBug
iBug

Reputation: 37227

Your perceived results indicates that print() calls file.write twice: Once for the data and once for the "end content", which is a newline by default and can be overridden with the end keyword argument. Relevant source code lines confirm this speculation.

However, this is not something you should rely on. It's entirely implementation details, may be different for another implementation (e.g. PyPy) and may change at any time without notice, not to mention that overriding builtins is another bad practice. You should avoid this kind of practice without a compelling reason not to modify other parts of the code to use your custom logging facility.

Should you really need to do monkey-patching, it's safer to override the print() function since it has a defined, reliable interface. You can import the builtins module and assign your new print function to builtins.print, maintaining control over calls to your logging handler.

Upvotes: 1

Related Questions