MessageLoggerMiddleware sometimes fails to return and hangs#967
Closed
euri10 wants to merge 3 commits intoKludex:masterfrom
Closed
MessageLoggerMiddleware sometimes fails to return and hangs#967euri10 wants to merge 3 commits intoKludex:masterfrom
euri10 wants to merge 3 commits intoKludex:masterfrom
Conversation
euri10
changed the title
euri10
added a commit
to euri10/uvicorn
that referenced
this pull request
Feb 24, 2021
| self.logger.trace(log_text, prefix, task_counter, logged_scope) | ||
| try: | ||
| await self.app(scope, inner_receive, inner_send) | ||
| r = await self.app(scope, inner_receive, inner_send) |
Contributor
There was a problem hiding this comment.
I think ASGI apps aren't meant to return anything? This is equivalent to storing None and returning it in the else branch, which was already the case since Python functions return None by default.
Is the hang due to something else in the logger middleware? (Note that I didn't try to reproduce, reviewing from my phone 😄)
Contributor
Author
There was a problem hiding this comment.
ok so asgi apps arent meant to return anything, I didn't know that.
I may have mis-diagnosed the issue, not sure, the thing is that if you run this specific test, it hangs for wsprotocol
this hangs forever:
pytest 'tests/protocols/test_websocket.py::test_asgi_return_value[WSProtocol]'
and it fails for websockets protocol:
pytest 'tests/protocols/test_websocket.py::test_asgi_return_value[WebSocketProtocol]'
> assert exc_info.value.code == 1006
E AssertionError: assert 1000 == 1006
E + where 1000 = ConnectionClosedOK('code = 1000 (OK), no reason').code
E + where ConnectionClosedOK('code = 1000 (OK), no reason') = <ExceptionInfo ConnectionClosedOK('code = 1000 (OK), no reason') tblen=4>.value
tests/protocols/test_websocket.py:375: AssertionError
It hangs in wsproto_impl.py in run_asgi after you end up with a None result from the await self.app.... It seems to block after, not sure why or where,
Contributor
Author
There was a problem hiding this comment.
well after playing with this I'm going to close it, I cant find a reproducible real-life example where it does that, so now I'm not sure it's not a "test-only" issue.
euri10
added a commit
that referenced
this pull request
Jun 1, 2021
* Magically turn warnings into errors ! * Close that socket * Close those loops * Is it because of lifespan was not explicitely set to off ? * Closing loop explicitely, maybe consider switching to a context manager ? * trigger GitHub actions * Close the transport when connection is lost * Close the transport when connection is lost works locally Adds some trace logs * Close the transport when connection is lost works locally Adds some trace logs * Fixed bug in message_logger.py, doesnt return Added trace logger in ws test that fails * trace log on failing wds test in ci, cant get it locally * Hard to know which test doesnt close and make the CI fail * Test order in protocols * Rewrite protocols http with context manager * Lint * rename order counts and still a bug * WOOT ? * Minimized diff, I moved tests around * Minimized diff, ws test should stay the same * Minimized diff, httptools debug stuff ermoved * Removing trace logs from diff * Reduce diff again, we take care of that bug in #967 * Removed pytest.mark.asyncio * Fix lifespan close loop post merge master * Fix websockets 9 deprecation warning
Kludex
pushed a commit
that referenced
this pull request
Nov 17, 2021
* Magically turn warnings into errors ! * Close that socket * Close those loops * Is it because of lifespan was not explicitely set to off ? * Closing loop explicitely, maybe consider switching to a context manager ? * trigger GitHub actions * Close the transport when connection is lost * Close the transport when connection is lost works locally Adds some trace logs * Close the transport when connection is lost works locally Adds some trace logs * Fixed bug in message_logger.py, doesnt return Added trace logger in ws test that fails * trace log on failing wds test in ci, cant get it locally * Hard to know which test doesnt close and make the CI fail * Test order in protocols * Rewrite protocols http with context manager * Lint * rename order counts and still a bug * WOOT ? * Minimized diff, I moved tests around * Minimized diff, ws test should stay the same * Minimized diff, httptools debug stuff ermoved * Removing trace logs from diff * Reduce diff again, we take care of that bug in #967 * Removed pytest.mark.asyncio * Fix lifespan close loop post merge master * Fix websockets 9 deprecation warning
Kludex
pushed a commit
to sephioh/uvicorn
that referenced
this pull request
Oct 29, 2022
* Magically turn warnings into errors ! * Close that socket * Close those loops * Is it because of lifespan was not explicitely set to off ? * Closing loop explicitely, maybe consider switching to a context manager ? * trigger GitHub actions * Close the transport when connection is lost * Close the transport when connection is lost works locally Adds some trace logs * Close the transport when connection is lost works locally Adds some trace logs * Fixed bug in message_logger.py, doesnt return Added trace logger in ws test that fails * trace log on failing wds test in ci, cant get it locally * Hard to know which test doesnt close and make the CI fail * Test order in protocols * Rewrite protocols http with context manager * Lint * rename order counts and still a bug * WOOT ? * Minimized diff, I moved tests around * Minimized diff, ws test should stay the same * Minimized diff, httptools debug stuff ermoved * Removing trace logs from diff * Reduce diff again, we take care of that bug in Kludex#967 * Removed pytest.mark.asyncio * Fix lifespan close loop post merge master * Fix websockets 9 deprecation warning
cr313
added a commit
to cr313/py-project-uvicorn
that referenced
this pull request
Apr 19, 2024
* Magically turn warnings into errors ! * Close that socket * Close those loops * Is it because of lifespan was not explicitely set to off ? * Closing loop explicitely, maybe consider switching to a context manager ? * trigger GitHub actions * Close the transport when connection is lost * Close the transport when connection is lost works locally Adds some trace logs * Close the transport when connection is lost works locally Adds some trace logs * Fixed bug in message_logger.py, doesnt return Added trace logger in ws test that fails * trace log on failing wds test in ci, cant get it locally * Hard to know which test doesnt close and make the CI fail * Test order in protocols * Rewrite protocols http with context manager * Lint * rename order counts and still a bug * WOOT ? * Minimized diff, I moved tests around * Minimized diff, ws test should stay the same * Minimized diff, httptools debug stuff ermoved * Removing trace logs from diff * Reduce diff again, we take care of that bug in Kludex/uvicorn#967 * Removed pytest.mark.asyncio * Fix lifespan close loop post merge master * Fix websockets 9 deprecation warning
Kludex
pushed a commit
to Kludex/jik
that referenced
this pull request
Aug 14, 2024
* Magically turn warnings into errors ! * Close that socket * Close those loops * Is it because of lifespan was not explicitely set to off ? * Closing loop explicitely, maybe consider switching to a context manager ? * trigger GitHub actions * Close the transport when connection is lost * Close the transport when connection is lost works locally Adds some trace logs * Close the transport when connection is lost works locally Adds some trace logs * Fixed bug in message_logger.py, doesnt return Added trace logger in ws test that fails * trace log on failing wds test in ci, cant get it locally * Hard to know which test doesnt close and make the CI fail * Test order in protocols * Rewrite protocols http with context manager * Lint * rename order counts and still a bug * WOOT ? * Minimized diff, I moved tests around * Minimized diff, ws test should stay the same * Minimized diff, httptools debug stuff ermoved * Removing trace logs from diff * Reduce diff again, we take care of that bug in Kludex/uvicorn#967 * Removed pytest.mark.asyncio * Fix lifespan close loop post merge master * Fix websockets 9 deprecation warning
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
I discovered that accidentally playing rough with the test suite on trying to fix stuff for #929
The 1st commit of this PR demonstrate the issue, if you just add
log_level="trace"in the config in that test it hangs forever, for good reason since the middleware never returns.