faust hijacks console output

[philipmat]

Checklist

• I have included information about relevant versions
• I have verified that the issue persists when using the master branch of Faust.

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

• Python version: pypy 3.9, python 3.10
• Faust version: 0.9.4
• Operating system: Docker pypy:3.9-7.3.9 image - Linux 5.15.49-linuxkit aarch64 GNU/Linux
• Kafka version: 7.1.1
• RocksDB version (if applicable)

[philipmat]

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:

[wbarnha]

The format of logs is a product of

mode/mode/utils/logging.py

Lines 74 to 76 in 030d69f

	DEFAULT_FORMAT: str = """
	[%(asctime)s] [%(process)s] [%(levelname)s]: %(message)s %(extra)s
	""".strip()

Regarding why print statements are getting hijacked, I took a look in

mode/mode/worker.py

Line 126 in 030d69f

override_logging: bool = True,

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]

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 ask#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: 71e11f3.

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]

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]

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]

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

[catermelon]

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]

I was just about to open a faust-streaming/faust PR to expose override_logging (branch: faust-streaming/faust@master...krmcbride:faust-streaming:expose_override_logging) as @wbarnha suggested when I saw this issue linked to from ask#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.