sanic icon indicating copy to clipboard operation
sanic copied to clipboard

Bad error message on connection made with no request

Open Tronic opened this issue 2 years ago • 1 comments

If a connection is made and the client disconnects without saying anything (which apparently is normal behaviour with browsers), Sanic logs this:

[2021-10-16 19:43:23 +0100] - (sanic.access)[INFO][UNKNOWN]: NONE https:///*  503 75
[2021-10-16 19:43:23 +0100] [1211225] [ERROR] Connection lost before response written @ None <Request: NONE *>

The error message is very confusing because Sanic was not actually about to write a response when no request was even received. If a log message is printed, it should be correct text, and probably only on debug level. Also, the event should appear either on access log or on the normal log, but not on both, and the client IP address should be displayed instead of all those irrelevant/incorrect things it now prints.

Alternatively, we could simply not log these errors at all, which really is my preferred solution because, after all, there is nothing much to log about the client not making any request. It needs to be noted that we are not logging failing SSL handshakes either (asyncio Protocol lacks support for logging them properly), so a client could be spamming the server with connections and not make any noise on Sanic logs. Network sniffers might be better for debugging such activity.

I would prefer someone else looking into this because I am busy with a couple of other PRs.

Ping @ahopkins since we recently discussed this briefly.

Tronic avatar Oct 16 '21 18:10 Tronic

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. If this is incorrect, please respond with an update. Thank you for your contributions.

stale[bot] avatar Mar 02 '22 08:03 stale[bot]

I got the same problem.

Where my app

I deploy the sanic application on k8s. And I have deployed prometheus monitor every pod.

What My Error

And I got error log like that:

[2022-10-26 05:58:40 +0000] [9] [ERROR] Exception occurred while handling uri: 'http:///*'
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/sanic/http.py", line 126, in http1
await self.http1_request_header()
File "/usr/local/lib/python3.8/site-packages/sanic/http.py", line 188, in http1_request_header
await self._receive_more()
File "/usr/local/lib/python3.8/site-packages/sanic/server.py", line 222, in receive_more
await self._data_received.wait()
File "/usr/local/lib/python3.8/asyncio/locks.py", line 309, in wait
await fut
asyncio.exceptions.CancelledError
[2022-10-26 05:58:40 +0000] - (sanic.access)[INFO][UNKNOWN]: NONE http:///* 503 72

(I guess this request maybe from sanic self?or prometheus? or ??? Actually I have no idea.)

What my code

My sanic main code:

...
app = Sanic("APP_NAME", register=True)
...
app.run(
    debug=sanic_settings.DEBUG,
    host=sanic_settings.HOST,
    workers=sanic_settings.WORKERS,
    port=sanic_settings.PORT,
    auto_reload=True,   
)

Anybody have some answers? Thanks for your replies.

ygbingo avatar Oct 26 '22 06:10 ygbingo

Oh, and my sanic version == 21.6.2

ygbingo avatar Oct 26 '22 06:10 ygbingo

That is an old and unsupported version of Sanic. You should upgrade to a supported version: https://sanic.dev/en/org/policies.html#release-schedule

I do not remember when specifically, but we resolved this a while back.

ahopkins avatar Oct 26 '22 07:10 ahopkins