fix: forkserver child processes' logs never reach ccb.log (#319)

[bygadd]

Follow-up to #319. setup_logging() runs in main.py under if __name__ == '__main__', and the forkserver start method is set right after it, so the forkserver children re-import the package without going through __main__ and never run the logging setup — their ccb.* loggers end up with no handlers. The stdconn pipe in exception_wrap relays the child's raw stdout/stderr (and the faulthandler dump on a crash), but not logging records, so the per-request embed/ingest logs from the child processes get silently dropped. On our instance ccb.log only ever showed the main pid.

This does what you were happy with in the issue: one multiprocessing.Queue plus a QueueListener in the parent bound to the real ccb handlers (single writer, so no RotatingFileHandler rotation race), and a QueueHandler installed on the child's ccb logger from inside exception_wrap. The queue is passed in as a kwarg from exec_in_proc, and it's scoped to ccb.* so it doesn't start relaying unrelated library logs.

Running this on our 5.4.0 instance now — the child records (ccb.injest, ccb.vectordb, ccb.nextwork_em, …) show up in ccb.log with the child pid, where before we only saw the main pid.

ccb.log with the patch (pid 44 is the main worker, the rest are forkserver children)

{"timestamp": "05:58:08.485", "level": "INFO", "logger": "ccb.task_fetcher", "message": "embed_sources finished for 4 source(s): 4 succeeded, 0 errored", "pid": 44}
{"timestamp": "05:58:07.716", "level": "DEBUG", "logger": "ccb.injest", "message": "db filter source results", "pid": 435237}
{"timestamp": "05:58:07.711", "level": "DEBUG", "logger": "ccb.vectordb", "message": "Embedding source mail__mail: 3105:8273303: 7 chunk(s) in 1 batch(es)", "pid": 435230}
{"timestamp": "05:58:07.711", "level": "INFO", "logger": "ccb.nextwork_em", "message": "Sending embedding request for 7 chunks of the following sizes (total: 12271):", "pid": 435230}

Developed with AI assistance and verified on a live 5.4.0 deployment.

[kyteinsky]

thanks for the PR!

there are a few issue which should be addressed though
how about adding the queue listener handler to the main app's logging config in setup_logging() so we have to do that once and it remains in the main app and does not go into the child process as intended.
the logger.py file can contain the _ensure_log_listener() and _setup_child_logging() functions so all logging stuff is there.

not related to the change but maybe we can replace the ccb logger's handers with a queue handler too so IO delays are offset but probably the pickel time is more than the IO wait?
something like: ccb_logger.handlers = [logging.handlers.QueueHandler(_log_queue)]

[kyteinsky]

there can be a race condition with the global _log_queue and _log_listener vars when multiple subprocess are started at the same time. It would be nicer to do it once at init time and cleaner to do it in logger.py file with the other logger related configuration.

[kyteinsky]

let's not assume DEBUG level. If the logger config in the main app does not accept it (has info/warning level), the data sent across the processes is wasted. It would be better to pass in the parent's log level in this function and use that.

[kyteinsky]

the logs queue is not flushed when the program exits so we might lose some of the entries, maybe atexit can be used here.
atexit.register(_log_listener.stop)

[kyteinsky]

the log level of this logger can be stored in a global var too (in logger.py) so the value can be fetched quickly from the child process to setup the logger at the level.