synapse.http.site - WARNING - Error processing request …: <class 'twisted.internet.error.ConnectionDone'> Connection was closed cleanly.

[jo-so]

Description

I'm seeing many warnings like these in the log, which isn't a bad case, i.e. nothing to be warned about:

2019-07-13 10:59:43,933 - synapse.http.site - 203 - WARNING - GET-295130- Error processing request <XForwardedForRequest at 0x7f98f6009550 method='GET' uri='/_matrix/client/r0/sync?filter=8&timeout=0&since=s2661503_51275966_31471_1968800_52703_4_10151_380580_8' clientproto='HTTP/1.0' site=8083>: <class 'twisted.internet.error.ConnectionDone'> Connection was closed cleanly.
2019-07-13 10:59:43,934 - synapse.access.http.8083 - 302 - INFO - GET-295130- 2a02:810a:87c0:3a11:aefd:ceff:fe3d:9e83 - 8083 - {@joerg:alea.gnuu.de} Processed request: 0.004sec/0.131sec (0.004sec, 0.004sec) (0.000sec/0.000sec/0) 364B 200! "GET /_matrix/client/r0/sync?filter=8&timeout=0&since=s2661503_51275966_31471_1968800_52703_4_10151_380580_8 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64; rv:70.0) Gecko/20100101 Firefox/70.0" [0 dbevts]

Patch: synapse-con-done.txt

Version information

• Version: 1.0.0-2
• Install method: apt install matrix-synapse
• Platform: Debian/stable

[richvdh]

It's a bad case in that the client timed out before we could send a response?

[airblag]

I have the same issue since a while. I ignored it until now, but I have the feeling that this error is taking more place since I set up multiple synchrotron workers behind nginx.
On my homeserver (a few hundred accounts), I used to see this error ~ 1k times/day.
Now my synchrotron workers are producing this warning at a rate of 1k times/5min.
I couldn't observe any side effects of it on client side.

update: just applied the proposed patch and it looks beter. I guess it will reduce the I/O load of my server a little bit

[eMPee584]

The patch looks legit, twisted.internet.error.ConnectionDone does not actually seem to be an error condition.

[richvdh]

We do see quite a lot of these. I suspect they happen whenever the client chooses not to keepalive the connection. tcpdumping shows that the response is fully sent, and the ACK received, before the FIN is received:

I still don't think the fix is just to remove the log line - for instance, we also incorrectly log that the response is not fully sent (reponse code is logged as 200!).