Custom JSON logger and duplicate log messages

[wangjinbei]

Hi, when I use https://kdeldycke.github.io/click-extra/logging.html#custom-logger

My terminal outputs two logs, is there a problem where I am processing?
My intention: to format all log content in json format so that I can analyze and notify using the log collector .

Also what can I do to define the Load configuration matching foo.ini in json format as well?

demo.py:

import logging

from click import pass_context
from click_extra import extra_command, extra_basic_config, verbosity_option

extra_basic_config(
    logger_name="app_logger",
    format='{{"time": "{asctime}", "name": "{name}", "level": "{levelname}", "msg": "{message}"}}',
    force=True,
    level=logging.INFO,
)


@extra_command
@pass_context
@verbosity_option(default_logger="app_logger",)
def cli(config):
    logging.getLogger("app_logger").info("This is an info message from the root logger.")

output:

Load configuration matching foo.ini
{"time": "2024-06-18 10:35:50,018", "name": "app_logger", "level": "info", "msg": "This is an info message from the root logger."}
info: This is an info message from the root logger.

[kdeldycke]

I can reproduce your case with the latest Click Extra (v4.11.7), so nothing's wrong on your side. It seems that the duplicate log has always been there since I introduced unittests with the documentation in v4.3.0: ec4243c#diff-1a5e57d66b08bec5a71860d67f06912a004f03368c36910099d4ffae12970c7dR230-R231

And as you can see it is how that's being documented at https://kdeldycke.github.io/click-extra/logging.html#custom-logger

As for the Load configuration matching message, it seems there is a chicken and egg problem involved, as per the comments in the source code:

click-extra/click_extra/config.py

Lines 394 to 397 in e495e3b

	if explicit_conf:
	# We have can't simply use logger.info() here as the defaults have not been
	# loaded yet and the logger is stuck to its default WARNING level.
	echo(message, err=True)

Still, your use-case of producing JSON for all logs is interesting. Let me dive into that. Maybe it's just a matter of setting up the right configuration.

[kdeldycke]

The issue regarding the duplicate message has been documented at:

click-extra/docs/logging.md

Lines 338 to 375 in 5ea95cf

	.. attention::
	If the debug message of our custom logger is printed in the example above as expected, you can right away notice an issue: it is **displayed twice**.
	Because of a custom name, ``app_logger`` is created as a sub-logger of the ``root`` logger. And as such, its `messages are propagated to its parent <https://docs.python.org/3/library/logging.html#logging.Logger.propagate>`_ by default.
	To fix this issue, you have to explicitely disable the propagation of messages of ``app_logger`` to ``root``:
	.. click:example::
	import logging
	from click import command, echo
	from click_extra import extra_basic_config, verbosity_option
	my_logger = extra_basic_config(
	logger_name="app_logger",
	format="{levelname} | {name} | {message}",
	)
	my_logger.propagate = False
	@command
	@verbosity_option(default_logger="app_logger")
	def awesome_app():
	echo("Awesome App started")
	logger = logging.getLogger("app_logger")
	logger.debug("Awesome App has started.")
	Which get rids of the duplicate messages:
	.. click:run::
	from textwrap import dedent
	result = invoke(awesome_app, args=["--verbosity", "DEBUG"])
	assert dedent("""\
	\x1b[34mdebug\x1b[0m: Set <Logger app_logger (DEBUG)> to DEBUG.
	Awesome App started
	\x1b[34mdebug\x1b[0m | app_logger | Awesome App has started.
	\x1b[34mdebug\x1b[0m: Reset <Logger app_logger (DEBUG)> to WARNING.
	"""
	) in result.output

Tl;Dr: you need to logging.getLogger("app_logger").propagate = False.

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.