asyncio docs should call out that network logging is a no-no

[gvanrossum]

BPO	20847
Nosy	@vstinner, @merwok, @socketpair, @1st1, @Mariatta

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = 'https://github.com/vstinner'
closed_at = None
created_at = <Date 2014-03-03.20:12:20.295>
labels = ['type-feature', 'docs', 'expert-asyncio']
title = 'asyncio docs should call out that network logging is a no-no'
updated_at = <Date 2016-11-02.21:28:11.952>
user = 'https://github.com/gvanrossum'

bugs.python.org fields:

activity = <Date 2016-11-02.21:28:11.952>
actor = 'Mariatta'
assignee = 'vstinner'
closed = False
closed_date = None
closer = None
components = ['Documentation', 'asyncio']
creation = <Date 2014-03-03.20:12:20.295>
creator = 'gvanrossum'
dependencies = []
files = []
hgrepos = []
issue_num = 20847
keywords = ['patch']
message_count = 7.0
messages = ['212664', '212666', '212671', '212689', '279181', '279184', '279371']
nosy_count = 6.0
nosy_names = ['vstinner', 'eric.araujo', 'socketpair', 'yselivanov', 'Winterflower', 'Mariatta']
pr_nums = []
priority = 'normal'
resolution = None
stage = 'needs patch'
status = 'open'
superseder = None
type = 'enhancement'
url = 'https://bugs.python.org/issue20847'
versions = ['Python 3.4']

[gvanrossum]

The asyncio package uses the logging module. We should remind users that they should always configure their logs to go to a file on the local filesystem -- using any kind of network logging will block the event loop.

[1st1]

Can we instead re-engineer asyncio logging to have logger calls in a separate thread?

I.e. logger is a proxy object, that puts logging calls in a queue, and there would be another thread to block on the queue and do the actual logging. This way it won't really matter how logging is configured.

[gvanrossum]

If you really need network logging you should be able to configure a handler that puts things in a queue whose other end is serviced by an asyncio task. There should be no need to mess with the type of the logger object. Anyway, in 3.4 it is what it is. :-)

[1st1]

If you really need network logging you should be able to configure a handler that puts things in a queue whose other end is serviced by an asyncio task. There should be no need to mess with the type of the logger object.

It's something that is easy to misconfigure. Having [logger+queue+logging thread] combination mitigates the risk a bit, but yeah, at the cost of increased complexity...

Anyway, in 3.4 it is what it is. :-)

Right.

[Mariatta]

Hi,
I added to asyncio logging doc that the log file should point to a file on local filesystem.
Please review. Thanks :)

[vstinner]

+Logs for :mod:`asyncio` module should always point to a file on the local
+filesystem. Using any kind of network logging will block the event loop.

Well... even writing to a local file can block :-/

By "network", what about the local UNIX socket used by syslog?

I guess that the safest option would be a new asyncio library running
all logs functions to a thread, or maybe using loop.run_in_executor().

[socketpair]

Typical network logging is using syslog UDP. Sending UDP is never block.

[kumaraditya303]

As of #65046 (comment), is this fixed or still work left todo ? This is the oldest asyncio open.

[gvanrossum]

@Mariatta I can't find any page about asyncio or logging that has the phrase "should always point to a file on the local filesystem". You never mentioned a PR. Do you recall whether that was landed, and in which file?

[merwok]

The change was attached as a patch: https://bugs.python.org/file45182/issue20847.patch

diff -r 4b6e6a77e501 Doc/library/asyncio-dev.rst
--- a/Doc/library/asyncio-dev.rst	Sat Oct 22 03:21:55 2016 +0000
+++ b/Doc/library/asyncio-dev.rst	Fri Oct 21 22:23:14 2016 -0700
@@ -169,6 +169,8 @@
 
    logging.getLogger('asyncio').setLevel(logging.WARNING)
 
+Logs for :mod:`asyncio` module should always point to a file on the local
+filesystem.  Using any kind of network logging will block the event loop.
 
 .. _asyncio-coroutine-not-scheduled:
 

[gvanrossum]

Whoops! @kumaraditya303 Do you want to create a patch? We can add Co-Authored-By: Mariatta for credit.

[kumaraditya303]

See #97559. Local files can also block so it should not be done in same thread so it isn't 100% correct.

[gvanrossum]

Hm, I think we should reopen this because I was too fast in merging the PR. @merwok had some reasonable concerns.

[merwok]

To keep the discussion here, here is the change committed:

Network logging can block the event loop. It is recommended to use
a separate thread for handling logs or use non-blocking IO.

My remark:

It’s not immediately clear what one should use: after all, we are in the async I/O docs!
Is there a section in the os module or another part of the stdlib that explains how to do non-asyncio non-blocking I/O?

Guido:

I doubt we have something more specific than "use threads or write to disk" -- and while writing to disk is technically not perfect, it's generally considered good enough for asyncio (we've been told that there are async APIs for writing to disk on some platforms, and IIRC there are 3rd party packages that wrap them, but the benefits are at best marginal, and the code isn't portable.

Also, I think the warning is about configuring a logger that uses network I/O rather than about how user code should do their own logging. The point is that asyncio itself sometimes calls the logging module and the user should avoid messing that up by accidentally configuring a network-using logger.

User code can just use the run_in_executor API to do the logging from a thread, but we don't want to do that for asyncio's own logging.

[merwok]

I doubt we have something more specific than "use threads or write to disk"

OK, then it’s enough that the doc mention a thread without needed a link to the threading module!

Also, I think the warning is about configuring a logger that uses network I/O

Ah true, the doc page is logging-dev, not regular user tutorial.

rather than about how user code should do their own logging. [...]
the user should avoid messing that up by accidentally configuring a network-using logger

Now I am confused: this doc is not for users (python developers using logging, not someone writing a logging handler, although there can be overlap), but users should heed the warning?

(Maybe it’s just me — I’ll wait to see if kumaraditya303 understands your meaning better than I!)

[gvanrossum]

(Maybe it’s just me — I’ll wait to see if kumaraditya303 understands your meaning better than I!)

Do I understand my own meaning? I'm not sure. :-(

This page is a separate section of the asyncio library docs titled "Developing with asyncio" and appears to be guidance for users who are learning to use asyncio, focusing on common things you might do out of habit that aren't a good idea. So I think this doc is for users. And the paragraph added is in a section titled "Logging" which (until this PR) just shows how to adjust the logging level for the logger used by asyncio itself.

From this perspective I think the only questionable part is the recommendation to use non-blocking I/O, which would lead people to believe they should write a logger that uses the event loop, which is likely to lead to more confusion when asyncio is logging things. (Especially since sometimes the logging happens from code run in another thread, like getaddrinfo.)

And yes, it is terse and vague, like some other advice in this section.

[merwok]

@vsajip could you look at the PR and say if the new line of info is good enough?

[vsajip]

Well, it's probably too brief to be useful to all users. IMO it would be more useful to more people to have a logging cookbook recipe showing how to do logging from async code without blocking the event loop, and then referring to that recipe in this bit. I'm not sure my asyncio-fu is good enough to cover everything - I tend to use gevent to get async benefits with threading semantics - but I don't mind having a go if someone offers to review it 🙂

[gvanrossum]

I'll happily review it. I'm not sure what we should suggest though. Logging to a file should be fine, but if you really want network logging, you cannot use the asyncio loop at all, since some asyncio logging is called from inside loop internals when the loop is not necessarily in a usable, consistent state.

So the alternative would be to have a separate helper thread that runs the network logging, and have the logger used by asyncio just put the processed log record in a queue that is read by the helper thread -- and hope that the helper thread can keep up.

This seems rather advanced material for the document we're discussing -- maybe it should just state "don't configure network logging for the asyncio logger". Or maybe the recipe could be in the logging cookbook and the asyncio-dev text can link to that.

[vsajip]

There's already a recipe in the logging cookbook under the section Dealing with handlers that block. It uses a QueueListener, which already listens and dispatches received log events on a separate thread. It seems to me that this could be used together with a QueueHandler for logging from async code. Now configuring handlers is normally the preserve of an application rather than a library, whether it's sync or async - would it be enough to suggest that any application which uses any async code always configures a QueueHandler / QueueListener combination? I'm happy to update that cookbook recipe to add a note highlighting that the approach could be used from async code.

[vsajip]

Proposed additional note:

Although the earlier discussion wasn’t specifically talking about async code,
but rather about slow logging handlers, it should be noted that when logging
from async code, network and even file handlers could lead to problems (blocking
the event loop) because some logging is done from asyncio internals. It might be
best if any async code is used in an application to use the above approach for
logging, so that any blocking code runs only in the QueueListener thread. 

[gvanrossum]

Yeah, adding that note to tha cookbook recipe seems like a good start. I agree that asyncio itself shouldn't mess with this (and the default logging goes to stderr IIRC, which seems fine).

We should then also link to the cookbook recipe from the asyncio docs where this started (and maybe remove the "or use non-blocking I/O" part).