Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Any plan to add taskName logging attribute as CallsiteParameter #693

Open
PrieJos opened this issue Jan 20, 2025 · 3 comments
Open

Any plan to add taskName logging attribute as CallsiteParameter #693

PrieJos opened this issue Jan 20, 2025 · 3 comments

Comments

@PrieJos
Copy link

PrieJos commented Jan 20, 2025

Hello,

As of Python 3.12, the standard library logging added a new attribute taskName (see here). Is there any plan to add this attribute as well to structlog at some point?

Thanks
Jose M. Prieto

@hynek
Copy link
Owner

hynek commented Jan 25, 2025

Not immediately, but open to PRs. Shouldn't be too difficult, but my focus is elsewhere right now.

@PrieJos
Copy link
Author

PrieJos commented Jan 29, 2025

Not immediately, but open to PRs. Shouldn't be too difficult, but my focus is elsewhere right now.

Thanks. I’ll try to come out with a proposal.

Cheers
José M. Prieto

PrieJos added a commit to PrieJos/structlog that referenced this issue Feb 1, 2025
PrieJos added a commit to PrieJos/structlog that referenced this issue Feb 1, 2025
@PrieJos
Copy link
Author

PrieJos commented Feb 1, 2025

Hi,

I have come out with this PR 698 which add a new member TASK_NAME to the enumeration CallsiteParameter and the respective handlers to the CallsiteParameterAdder processor so that a mew field task_name is added to the event dict upon processing. The compute of this new field is quite easy and looks like this (this helper function is added to the module structlog._utils):

def get_taskname() -> Optional[str]:
    """
    Get the current asynchronous task if applicable.

    Returns:
        Optional[str]: asynchronous task name.
    """
    task_name = None
    with suppress(Exception):
        task = asyncio.current_task()
        if task:
            task_name = task.get_name()
    return task_name

So task_name will become None if no event loop is running or whatever the asyncio.Task.get_name() method returns otherwise.

I also added into the PR a few test cases which are all passed.

However, what I noticed was that it doesn't work as expected when running async. I wrote the attach small Python script a.py that you can execute sync (w/ option --sync) or async (no options or --async). The idea of such a script is to compare the callsite information as displayed by structlog and the standard logging module.

a.zip

If executed synchronously, then no issues. Callsite parameters are equal on both sides:

🟢 python a.py --sync
~~~ Synchrnous Mode ~~~
2025-02-01T21:36:31 [info     ] structlog -> Start of async task (sleep: 0.40) filename=a.py func_name=routine lineno=95 module=a process=407380 process_name=n/a task_name=None thread_name=MainThread
2025-02-01T21:36:31 [info     ] structlog -> End of async task filename=a.py func_name=routine lineno=100 module=a process=407380 process_name=n/a task_name=None thread_name=MainThread
2025-02-01T21:36:31 INFO 407380 MainProcess a a.py:routine:93 MainThread None logging -> Start of async task (sleep: 0.78)
2025-02-01T21:36:32 INFO 407380 MainProcess a a.py:routine:98 MainThread None logging -> End of async task

The differences can be seen if executed asynchrnously:

🟢 python tmp/a.py --async
~~~ Asynchrnous Mode ~~~
2025-02-01T21:36:55 [info     ] structlog -> Start of async task (sleep: 0.55) filename=a.py func_name=aroutine lineno=66 module=a process=407651 process_name=n/a task_name=None thread_name=asyncio_0
2025-02-01T21:36:55 [info     ] structlog -> End of async task filename=a.py func_name=aroutine lineno=74 module=a process=407651 process_name=n/a task_name=None thread_name=asyncio_0
2025-02-01T21:36:55 INFO 407651 MainProcess a a.py:aroutine:64 MainThread AsyncRoutine logging -> Start of async task (sleep: 0.63)
2025-02-01T21:36:56 INFO 407651 MainProcess a a.py:aroutine:72 MainThread AsyncRoutine logging -> End of async task
  • The callsite parameter TASK_NAME I added isn't working the same. While logging shows the right task name AsyncRoutine, structlog shows None.
  • However, neither the callsite parameters PROCESS_NAME nor THREAD_NAME aren't working either. logging shows them as MainProcess and MainThread resp., while structlog shows them as n/a and asyncio_0 which are not correct by the way.

As far as I could see, the reason I think is the way structlog calls out the async version of the logger method ainfo, awarning, etc. They are eventually proxied to the respective sync versions and executed in another thread using asyncio.get_running_loop().run_in_executor by the corresponding bound logger. That explains the difference in the output respect the standard logging module. To see this visually, see the attached structlog.png that shows the call stack on a breakpoint on structlog._utils.get_taskname when executing the test tests/processors/test_processors.py::TestCallsiteParameterAdder::test_async[BoundLogger-ainfo].

Image

So, in short, assuming my analysis is right, there way to add "task name" as another callsite parameter is not feasible. Indeed, neither the "process name" nor "thread name" seems to work. Do you have any other suggestion/idea how it can be added (if any)?

Thanks!

PS: Sorry for the long post.

Cheers,
Jose M. Prieto

PrieJos added a commit to PrieJos/structlog that referenced this issue Feb 3, 2025
PrieJos added a commit to PrieJos/structlog that referenced this issue Feb 3, 2025
PrieJos added a commit to PrieJos/structlog that referenced this issue Feb 26, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants