MessageLoggerMiddleware sometimes fails to return and hangs

[euri10]

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.

[florimondmanca]

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 😄)

[euri10]

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,

uvicorn/uvicorn/protocols/websockets/wsproto_impl.py

Lines 208 to 226 in 9dc5a43

	async def run_asgi(self):
	try:
	result = await self.app(self.scope, self.receive, self.send)
	except BaseException as exc:
	msg = "Exception in ASGI application\n"
	self.logger.error(msg, exc_info=exc)
	if not self.handshake_complete:
	self.send_500_response()
	self.transport.close()
	else:
	if not self.handshake_complete:
	msg = "ASGI callable returned without completing handshake."
	self.logger.error(msg)
	self.send_500_response()
	self.transport.close()
	elif result is not None:
	msg = "ASGI callable should return None, but returned '%s'."
	self.logger.error(msg, result)
	self.transport.close()

[euri10]

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.