Connection closed by redis server

[nritsche]

This bug has appeared only once so far: redis seems to be closing the connection:

Oct 22 06:43:13 csBfs cocod[25394]: DEBUG:aioredis:Cancelling waiter (<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fa1310abbb8>()] created
Oct 22 06:43:13 csBfs cocod[25394]: [2019-10-22 06:43:13 -0700] [25413] [ERROR] Exception occurred while handling uri: 'http://localhost:54323/gps-ti
Oct 22 06:43:13 csBfs cocod[25394]: Traceback (most recent call last):
Oct 22 06:43:13 csBfs cocod[25394]: File "/usr/local/lib/python3.6/site-packages/sanic/app.py", line 942, in handle_request
Oct 22 06:43:13 csBfs cocod[25394]: response = await response
Oct 22 06:43:13 csBfs cocod[25394]: File "/usr/lib64/python3.6/asyncio/coroutines.py", line 129, in throw
Oct 22 06:43:13 csBfs cocod[25394]: return self.gen.throw(type, value, traceback)
Oct 22 06:43:13 csBfs cocod[25394]: File "/usr/local/lib/python3.6/site-packages/coco/master.py", line 430, in external_endpoint
Oct 22 06:43:13 csBfs cocod[25394]: request.query_string,
Oct 22 06:43:13 csBfs cocod[25394]: File "/usr/lib64/python3.6/asyncio/coroutines.py", line 129, in throw
Oct 22 06:43:13 csBfs cocod[25394]: return self.gen.throw(type, value, traceback)
Oct 22 06:43:13 csBfs cocod[25394]: File "/usr/local/lib/python3.6/site-packages/aioredis/util.py", line 48, in wait_ok
Oct 22 06:43:13 csBfs cocod[25394]: res = await fut
Oct 22 06:43:13 csBfs cocod[25394]: aioredis.errors.ConnectionClosedError: Reader at end of file
Oct 22 06:43:13 csBfs cocod[25394]: ERROR:sanic.root:Exception occurred while handling uri: 'http://localhost:54323/gps-time'
Oct 22 06:43:13 csBfs cocod[25394]: Traceback (most recent call last):
Oct 22 06:43:13 csBfs cocod[25394]: File "/usr/local/lib/python3.6/site-packages/sanic/app.py", line 942, in handle_request
Oct 22 06:43:13 csBfs cocod[25394]: response = await response
Oct 22 06:43:13 csBfs cocod[25394]: File "/usr/lib64/python3.6/asyncio/coroutines.py", line 129, in throw
Oct 22 06:43:13 csBfs cocod[25394]: return self.gen.throw(type, value, traceback)
Oct 22 06:43:13 csBfs cocod[25394]: File "/usr/local/lib/python3.6/site-packages/coco/master.py", line 430, in external_endpoint
Oct 22 06:43:13 csBfs cocod[25394]: request.query_string,
Oct 22 06:43:13 csBfs cocod[25394]: File "/usr/lib64/python3.6/asyncio/coroutines.py", line 129, in throw
Oct 22 06:43:13 csBfs cocod[25394]: return self.gen.throw(type, value, traceback)
Oct 22 06:43:13 csBfs cocod[25394]: File "/usr/local/lib/python3.6/site-packages/aioredis/util.py", line 48, in wait_ok
Oct 22 06:43:13 csBfs cocod[25394]: res = await fut
Oct 22 06:43:13 csBfs cocod[25394]: aioredis.errors.ConnectionClosedError: Reader at end of file
Oct 22 06:43:13 csBfs cocod[25394]: [2019-10-22 06:43:13 -0700] - (sanic.access)[INFO][127.0.0.1:34630]: GET http://localhost:54323/gps-time  500 303
Oct 22 06:43:13 csBfs cocod[25394]: INFO:sanic.access:
Oct 22 06:43:13 csBfs cocod[25394]: [2019-10-22 06:43:13 -0700] [25400] [ERROR] [coco.scheduler] Scheduler failed calling gps-time: (500, message='In
Oct 22 06:43:13 csBfs cocod[25394]: ERROR:coco.scheduler:Scheduler failed calling gps-time: (500, message='Internal Server Error'). Has coco's sanic

According to the redis documentation this happens when the client is not responding for a timeout that is set to 300 (seconds) in our configuration.

The redis log gives no hints about this:

1056:M 22 Oct 2019 06:42:54.094 * 10 changes in 300 seconds. Saving...
1056:M 22 Oct 2019 06:42:54.094 * Background saving started by pid 29362
29362:C 22 Oct 2019 06:42:54.135 * DB saved on disk
29362:C 22 Oct 2019 06:42:54.136 * RDB: 0 MB of memory used by copy-on-write
1056:M 22 Oct 2019 06:42:54.195 * Background saving terminated with success
1056:M 22 Oct 2019 06:57:55.094 * 1 changes in 900 seconds. Saving...

[nritsche]

Also see #203

[nritsche]

Maybe we had fixed this for a while by setting timeout to 0 in /etc/redis.conf, (as suggested in django/daphne#262). Now the timeout is set to 300 and it will need a redis restart to change that.