Logging inside Threads When Logger is Already Configured

Question

EDIT: Repo with all code (branch "daemon"). The question is regarding the code in the file linked to).

My main program configures logging like this (options have been simplified):

logging.basicConfig(level='DEBUG', filename="/some/directory/cstash.log")

Part of my application starts a daemon, for which I use the daemon package:

    with daemon.DaemonContext(
        pidfile=daemon.pidfile.PIDLockFile(self.pid_file),
        stderr=self.log_file,
        stdout=self.log_file
    ):
        self.watch_files()

where self.log_file is a file I've opened for writing.

When I start the application, I get:

--- Logging error ---
Traceback (most recent call last):
  File "/Users/afraz/.pyenv/versions/3.7.2/lib/python3.7/logging/__init__.py", line 1038, in emit
    self.flush()
  File "/Users/afraz/.pyenv/versions/3.7.2/lib/python3.7/logging/__init__.py", line 1018, in flush
    self.stream.flush()
OSError: [Errno 9] Bad file descriptor

If I switch off the logging to a file in the daemon, the logging in my main application works, and if I turn off the logging to a file in my main application, the logging in the daemon works. If I set them up to log to a file (even different files), I get the error above.

Without a [mcve](https://stackoverflow.com/help/minimal-reproducible-example) your issue is unlikely going to get any attention or solutions that will work (as there are [related threads](https://stackoverflow.com/questions/26325943/many-threads-to-write-log-file-at-same-time-in-python) that cover this issue). At the very least include the simplest application that show this behavior, because without knowing exactly how/where you opened the files, none of us will be able to tell you exactly where you might have set up the application logging wrong. — metatoaster, May 09 '20 at 23:05
Yup, fair enough. I've added a link to the code at the top of the original question. — Afraz, May 10 '20 at 12:15
It sounds like something is closing `self.log_file` while `logging` still expects it to be open and available. — AKX, May 10 '20 at 12:16
@AKX, turns out that's very likely what's happening. [This is related](https://stackoverflow.com/questions/13180720/maintaining-logging-and-or-stdout-stderr-in-python-daemon). I need to figure out how to access the root logger's filehandler, so I can add it's file descriptor to `daemon.DaemonContext.files_preserve`, but I can't see how to get a list of already configured handlers from `logging` if I've used `basicConfig` for configuration. — Afraz, May 14 '20 at 08:33
Hmm, almost there: `logger = logging.getLogger()`, means I can later call `logger.handlers[0].stream.fileno()` for the value I need in `DaemonContext`. Now however, subsequent calls to `logging.info` from the previous thread, appear to go nowhere :/ — Afraz, May 14 '20 at 08:59
I'm curious though - why would you need a separate daemon thread at all? I'd assume for an app like yours, it'd either run entirely in daemon mode (so one big loop), or as a single-shot thing? — AKX, May 14 '20 at 09:37
The daemon is actually supplementary. It's designed as a CLI tool to encrypt and upload to remote storage, but with an optional daemon to keep the added files in sync. — Afraz, May 15 '20 at 06:03

score 2 · Answer 1 · answered May 16 '20 at 16:51

After trying many things, here's what worked:

def process_wrapper():
    with self.click_context:
        self.process_queue()

def watch_wrapper():
    with self.click_context:
        self.watch_files()

with daemon.DaemonContext(
    pidfile=daemon.pidfile.PIDLockFile(self.pid_file),
    files_preserve=[logger.handlers[0].stream.fileno()],
    stderr=self.log_file,
    stdout=self.log_file
):
    logging.info("Started cstash daemon")

    while True:
        threading.Thread(target=process_wrapper).start()
        time.sleep(5)
        threading.Thread(target=watch_wrapper).start()

There were two main things wrong:

daemon.DaemonContext needs files_preserve set to the file logging handler, so it doesn't close the file once the context is switched. This is the actual solution to the original problem.
Further however, both methods needed to be in separate threads, not just one. The while True loop in the main thread was stopping the other method from running, so putting them both into separate threads means they can both run

Logging inside Threads When Logger is Already Configured

1 Answers1