Python logging working on Windows but not Mac OS

Question

# Logging
cur_flname = os.path.splitext(os.path.basename(__file__))[0]
LOG_FILENAME = constants.log_dir + os.sep + 'Log_' + cur_flname + '.txt'
util.make_dir_if_missing(constants.log_dir)
logging.basicConfig(filename=LOG_FILENAME, level=logging.INFO, filemode='w',
                    format='%(asctime)s %(levelname)s %(module)s - %(funcName)s: %(message)s',
                    datefmt="%m-%d %H:%M")  # Logging levels are DEBUG, INFO, WARNING, ERROR, and CRITICAL
# Output to screen
logger = logging.getLogger(cur_flname)
logger.addHandler(logging.StreamHandler())

I use the code above to create a logger that I can use in my module to print messages to screen as well simultaneously to a text file.

On Windows, the messages get output to both file and screen. However, on Mac OS X 10.9.5, they only get output to file. I am using Python 2.7.

Any ideas on how to fix this?

Answer 1

From your question it is clear, you have no problem with creating logger name, log file name and with logging to a file, so I will keep this part simplified to keep my code succinct.

First thing: To me your solution seems correct as logging.StreamHandler shall send output to sys.stderr by default. You might have some code around (not shown in your question), which is modifying sys.stderr, or you are running your code on OSX in such a way, that output to stderr is not shown (but is really output).

Solution with logging

Put following code into with_logging.py:

import logging
import sys

logformat = "%(asctime)s %(levelname)s %(module)s - %(funcName)s: %(message)s"
datefmt = "%m-%d %H:%M"

logging.basicConfig(filename="app.log", level=logging.INFO, filemode="w",
                    format=logformat, datefmt=datefmt)

stream_handler = logging.StreamHandler(sys.stderr)
stream_handler.setFormatter(logging.Formatter(fmt=logformat, datefmt=datefmt))

logger = logging.getLogger("app")
logger.addHandler(stream_handler)

logger.info("information")
logger.warning("warning")


def fun():
    logger.info(" fun inf")
    logger.warning("fun warn")

if __name__ == "__main__":
    fun()

Run it: $ python with_logging.py and you shall see expected log records (properly formatted) in log file app.log and on stderr too.

Note, if you do not see it on stderr, something is hiding your stderr output. To see something, change in StreamHandler the stream to sys.stdout.

Solution with logbook

logbook is python package providing alternative logging means. I am showing it here to show main difference to stdlib logging: with logbook the use and configuration seems simpler to me.

Previous solution rewritten to with_logbook.py

import logbook
import sys

logformat = ("{record.time:%m-%d %H:%M} {record.level_name} {record.module} - "
             "{record.func_name}: {record.message}")
kwargs = {"level": logbook.INFO, "format_string": logformat, "bubble": True}

logbook.StreamHandler(sys.stderr, **kwargs).push_application()
logbook.FileHandler("app.log", **kwargs).push_application()

logger = logbook.Logger("app")

logger.info("information")
logger.warning("warning")


def fun():
    logger.info(" fun inf")
    logger.warning("fun warn")

if __name__ == "__main__":
    fun()

The main difference is, that you do not have to attach handlers to loggers, your loggers simply emit some log records.

These records will be handled by handlers, if they are put in place. One method is to create a handler and call push_application() on it. This will put the handler into stack of handlers in use.

As before, we need two handlers, one for the file, another for stderr.

If you run this script $ python with_logbook.py, you shall see exactly the same results as with logging.

Separate logging setup from module code: short_logbook.py

With stdlib logging I reall do not like the introductory dances to make the logger work. I want simply emit some log records and want to do that as simply as possible.

Following example is modification of previous one. Instead of setting up logging on very beginning of the module, I do it just before the code is run - inside the if __name__ == "__main__" (you may do the same on any other place).

For practical reasons, I separated the module and calling code to two files:

File funmodule.py

from logbook import Logger

log = Logger(__name__)

log.info("information")
log.warning("warning")


def fun():
    log.info(" fun inf")
    log.warning("fun warn")

You can notice, that there are really only two lines of code related to making logging available.

Then, create the calling code, put into short_logbook.py:

import sys
import logbook

if __name__ == "__main__":
    logformat = ("{record.time:%m-%d %H:%M} {record.level_name} {record.module}"
                 "- {record.func_name}: {record.message}")
    kwargs = {"level": logbook.INFO, "format_string": logformat, "bubble": True}

    logbook.StreamHandler(sys.stderr, **kwargs).push_application()
    logbook.FileHandler("app.log", **kwargs).push_application()

    from funmodule import fun
    fun()

Running the code you will see it working the same way as before, only logger name will be funmodule.

Note, that I did the from funmodule import fun after the logging was set up. If I did it on the top if the short_logbook.py file, the first two log records from funmodule.py would not be seen as they happen during module import.

EDIT: added another logging solution to have fair comparison

One more stdlib logging solution

Trying to have fair comparison of logbook and logging I rewrote final logbook example to logging.

funmodule_logging.py looks like:

import logging

log = logging.getLogger(__name__)

log.info("information")
log.warning("warning")


def fun():
    log.info(" fun inf")
    log.warning("fun warn")
    log.error("no fun at all")

and short_logging.py looks as follows:

import sys
import logging

if __name__ == "__main__":
    logformat = "%(asctime)s %(levelname)s %(module)s - %(funcName)s: %(message)s"
    datefmt = "%m-%d %H:%M"

    logging.basicConfig(filename="app.log", level=logging.INFO, filemode="w",
                        format=logformat, datefmt=datefmt)

    stream_handler = logging.StreamHandler(sys.stderr)
    stream_handler.setFormatter(logging.Formatter(fmt=logformat, datefmt=datefmt))

    logger = logging.getLogger("funmodule_logging")
    logger.addHandler(stream_handler)

    from funmodule_logging import fun
    fun()

Functionality is very similar.

I still strugle with logging. stdlib logging is not easy to grasp, but it is in stdlib and offers some nice things like logging.config.dictConfig allowing to configure logging by a dictionary. logbook was much simpler to start with, but is a bit slower at the moment and lacks the dictConfig. Anyway, these differences are not relevant to your question.