search

faust-streaming / mode

Python AsyncIO Services
https://faust-streaming.github.io/mode/
Other
42 stars 16 forks source link

faust hijacks console output #36

Open philipmat opened 1 year ago

philipmat commented 1 year ago

Checklist

Steps to reproduce

I'm trying to use structlog inside a Faust app because I want to have JSON output. However, after Faust initialization, it seems all log messages get prefixed by [date time] [1] [WARNING].

import faust
import structlog

structlog.configure(processors=[structlog.processors.JSONRenderer()])
logger = structlog.get_logger()
logger.info("structlog configured", message="hello world")

# set up faust
app = faust.app(...)
topic = app.topic(....)

@app.topic(topic)
async def read_topic():
    logger.info("Reading from topic", topic=topic)
...

Running with `faust -l INFO --app main.app worker

Expected behavior

The first logger.info, on line 6 correctly outputs JSON:
{ "event": "structlog configured", "message": "hello world" } I expected the second logger.info inside read_topic to also output JSON on a line by itself:
{ "event": "Reading from topic", "topic": "test-topic" },

Actual behavior

Instead all logging after Faust starts get prefixed by what looks to be Faust config override, for example:
[2022-11-08 15:16:17,123] [1] [WARNING] { "event": "Reading from topic", "topic": "test-topic" }

Versions

philipmat commented 1 year ago

This doesn't seem to be log related anymore but rather faust hijacking the very console output. Even simple print statements from inside faust-controlled code cause the lines to be prefixed by [date time] [1] [WARNING], as seen in the example below:

image

wbarnha commented 1 year ago

The format of logs is a product of https://github.com/faust-streaming/mode/blob/030d69f49b9dbcc798d7547c6f324a27f1b98967/mode/utils/logging.py#L74-L76

Regarding why print statements are getting hijacked, I took a look in https://github.com/faust-streaming/mode/blob/030d69f49b9dbcc798d7547c6f324a27f1b98967/mode/worker.py#L126 and I manually set override_logging: bool = False, then the print statements worked as they typically would. I'll look into this further.

All logging is handled by mode, so I'll move this issue over there.

catermelon commented 1 year ago

I just ran into this as well. I'm happy to try and fix it.

I took a look at the history, and that flag was added in the context of https://github.com/ask/mode/issues/46. It looks like the original author wanted to always override the root logger, but this flag was added to allow users to turn that off.

Change was made here: https://github.com/faust-streaming/mode/commit/71e11f3e6769638c18881f4e5c03be773ee8da00.

I'm not sure I agree with the original logic, but just flipping the boolean from True to False would be a breaking change and I assume we don't want to do that.

The least breaking change I can think of is to add a override_override_logging flag, but other than the comedy value, I'm not sure this is a great solution.

The second least breaking way I can think of would be to change the type of override_logging to Optional[bool] and have the default be None. Then you could keep the current behavior unless loghandlers or logging_config is passed in.

Something like this, maybe: 

override_logging: Optional[bool] = None

if override_logging is None:
  override_logging = logging_config is None and loghandlers is None

It'd be annoying because you'd have to pass in some kind of config that you might not need?

What might make more sense would be to add a check for any existing root handlers and only override if there aren't any. 

if override_logging is None:
  override_logging = False if logging.root.hasHandlers() else True

I think that would also be a breaking change, though.

Let me know what you think / prefer.

philipmat commented 1 year ago

Thank you @catermelon!

I'm not sure I fully understand the implications of what you're suggesting, so I'll trust your judgement in this.

What I would expect to see happening is that Faust/mode prints/formats it's logging however it wants, but it should not interfere with the output of other loggers used in client apps. Or honestly even with print statements.

wbarnha commented 1 year ago

Thank you so much @catermelon for finding that commit!

I'm not sure I agree with the original logic, but just flipping the boolean from True to False would be a breaking change and I assume we don't want to do that.

Agreed, this change could cause a lot of undesired chaos since we're already accustomed to logging behaving like this.

Off the top of my head, I would like an option in Faust to exist so that way we can set override_logging = False. It'd be interesting to see other people's suggestions.

catermelon commented 1 year ago

Ah, okay! That would work, too. I'm happy to do that as well.

catermelon commented 1 year ago

It looks like it's already passing **kwargs so this might just be a documentation / set sane defaults issue? I'll do some testing later this afternoon.

https://github.com/faust-streaming/faust/blob/master/faust/worker.py#L260

krmcbride commented 1 year ago

I was just about to open a faust-streaming/faust PR to expose override_logging (branch: https://github.com/faust-streaming/faust/compare/master...krmcbride:faust-streaming:expose_override_logging) as @wbarnha suggested when I saw this issue linked to from https://github.com/ask/mode/issues/46. Didn't see the **kwargs, which I can try using instead.

Personally I'd like override_logging = False as a default at the Faust level -- this logger hijacking is causing us all kinds of pain and suffering.