{"action":"created","issue":{"url":"https://api.github.com/repos/matrix-org/synapse/issues/1778","repository_url":"https://api.github.com/repos/matrix-org/synapse","labels_url":"https://api.github.com/repos/matrix-org/synapse/issues/1778/labels{/name}","comments_url":"https://api.github.com/repos/matrix-org/synapse/issues/1778/comments","events_url":"https://api.github.com/repos/matrix-org/synapse/issues/1778/events","html_url":"https://github.com/matrix-org/synapse/issues/1778","id":199396230,"number":1778,"title":"@kyrias's HS is leaking inbound FDs and filling up with CRITICAL errors","user":{"login":"ara4n","id":1294269,"avatar_url":"https://avatars.githubusercontent.com/u/1294269?v=3","gravatar_id":"","url":"https://api.github.com/users/ara4n","html_url":"https://github.com/ara4n","followers_url":"https://api.github.com/users/ara4n/followers","following_url":"https://api.github.com/users/ara4n/following{/other_user}","gists_url":"https://api.github.com/users/ara4n/gists{/gist_id}","starred_url":"https://api.github.com/users/ara4n/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/ara4n/subscriptions","organizations_url":"https://api.github.com/users/ara4n/orgs","repos_url":"https://api.github.com/users/ara4n/repos","events_url":"https://api.github.com/users/ara4n/events{/privacy}","received_events_url":"https://api.github.com/users/ara4n/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":0,"created_at":"2017-01-08T01:26:34Z","updated_at":"2017-01-08T01:42:42Z","closed_at":null,"body":"```\r\nsierra:borklogs matthew$ cat homeserver.log | grep CRITICAL -A20 | grep '^[a-zA-Z]' | grep -v Traceback | sort | uniq -c\r\n  31 AlreadyCalledError\r\n 601 IndexError: pop from empty list\r\n```\r\n\r\nSuperficially it looks like the number of 'pop from empty list' errors matches the number of leaked inbound connections.  Actual failed requests look like:\r\n\r\n```\r\n2017-01-07 13:55:10,882 - synapse.access.https.8448 - 59 - INFO - PUT-53227- 91.134.136.82 - 8448 - Received request: PUT /_matrix/federation/v1/send/1483649379640/\r\n2017-01-07 13:55:10,985 - synapse.metrics - 162 - INFO - PUT-53227- Collecting gc 0\r\n2017-01-07 13:55:11,058 - twisted - 131 - INFO - PUT-53227- Starting factory <twisted.web.client._HTTP11ClientFactory instance at 0x7f388017d8c0>\r\n2017-01-07 13:55:11,061 - twisted - 131 - INFO - PUT-53227- Starting factory <twisted.web.client._HTTP11ClientFactory instance at 0x7f3882e401b8>\r\n2017-01-07 13:55:11,063 - twisted - 131 - INFO - PUT-53227- Starting factory <twisted.web.client._HTTP11ClientFactory instance at 0x7f387faaba70>\r\n2017-01-07 13:55:11,065 - twisted - 131 - INFO - PUT-53227- Starting factory <twisted.web.client._HTTP11ClientFactory instance at 0x7f388fd86290>\r\n2017-01-07 13:55:11,068 - twisted - 131 - INFO - PUT-53227- Starting factory <twisted.web.client._HTTP11ClientFactory instance at 0x7f3889b140e0>\r\n2017-01-07 13:55:11,375 - twisted - 131 - INFO - PUT-53227- Stopping factory <twisted.web.client._HTTP11ClientFactory instance at 0x7f3882e401b8>\r\n2017-01-07 13:55:11,412 - twisted - 131 - INFO - PUT-53227- Stopping factory <twisted.web.client._HTTP11ClientFactory instance at 0x7f387faaba70>\r\n2017-01-07 13:55:11,456 - twisted - 131 - CRITICAL - PUT-53227- Unhandled error in Deferred:\r\n2017-01-07 13:55:11,457 - twisted - 131 - CRITICAL - PUT-53227- \r\n2017-01-07 13:55:11,458 - twisted - 131 - CRITICAL - PUT-53227- Unhandled error in Deferred:\r\n2017-01-07 13:55:11,458 - twisted - 131 - CRITICAL - PUT-53227- \r\n2017-01-07 13:55:11,467 - twisted - 131 - INFO - PUT-53227- Starting factory <twisted.web.client._HTTP11ClientFactory instance at 0x7f3882e401b8>\r\n2017-01-07 13:55:11,474 - twisted - 131 - INFO - PUT-53227- Starting factory <twisted.web.client._HTTP11ClientFactory instance at 0x7f387faaba70>\r\n2017-01-07 13:55:11,625 - twisted - 131 - CRITICAL - PUT-53227- Unhandled error in Deferred:\r\n2017-01-07 13:55:11,625 - twisted - 131 - CRITICAL - PUT-53227- \r\n2017-01-07 13:55:11,789 - synapse.federation.transport.server - 138 - INFO - PUT-53227- Request from kolm.io\r\n2017-01-07 13:55:11,873 - synapse.federation.transport.server - 244 - INFO - PUT-53227- Received txn 1483649379640 from kolm.io. (PDUs: 0, EDUs: 1, failures: 0)\r\n2017-01-07 13:55:12,235 - synapse.access.https.8448 - 91 - INFO - PUT-53227- 91.134.136.82 - 8448 - {kolm.io} Processed request: 1352ms (336ms, 10ms) (21ms/4) 11B 200 \"PUT /_matrix/federation/v1/send/1483649379640/ HTTP/1.1\" \"Synapse/0.18.6-rc3\"\r\n```\r\nPresumably the 'Starting factory' are bogus log contexts though..."},"comment":{"url":"https://api.github.com/repos/matrix-org/synapse/issues/comments/271123131","html_url":"https://github.com/matrix-org/synapse/issues/1778#issuecomment-271123131","issue_url":"https://api.github.com/repos/matrix-org/synapse/issues/1778","id":271123131,"user":{"login":"ara4n","id":1294269,"avatar_url":"https://avatars.githubusercontent.com/u/1294269?v=3","gravatar_id":"","url":"https://api.github.com/users/ara4n","html_url":"https://github.com/ara4n","followers_url":"https://api.github.com/users/ara4n/followers","following_url":"https://api.github.com/users/ara4n/following{/other_user}","gists_url":"https://api.github.com/users/ara4n/gists{/gist_id}","starred_url":"https://api.github.com/users/ara4n/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/ara4n/subscriptions","organizations_url":"https://api.github.com/users/ara4n/orgs","repos_url":"https://api.github.com/users/ara4n/repos","events_url":"https://api.github.com/users/ara4n/events{/privacy}","received_events_url":"https://api.github.com/users/ara4n/received_events","type":"User","site_admin":false},"created_at":"2017-01-08T01:42:42Z","updated_at":"2017-01-08T01:42:42Z","body":"The actual stack traces are:\r\n\r\n```\r\n2017-01-07 13:55:11,625 - twisted - 131 - CRITICAL - PUT-53227- Unhandled error in Deferred:\r\n2017-01-07 13:55:11,625 - twisted - 131 - CRITICAL - PUT-53227- \r\nTraceback (most recent call last):\r\n  File \"/home/synapse/twisted/src/twisted/internet/defer.py\", line 150, in maybeDeferred\r\n    result = f(*args, **kw)\r\n  File \"/home/synapse/twisted/src/twisted/internet/endpoints.py\", line 849, in iterateEndpoint\r\n    checkDone()\r\n  File \"/home/synapse/twisted/src/twisted/internet/endpoints.py\", line 839, in checkDone\r\n    winner.errback(failures.pop())\r\nIndexError: pop from empty list\r\n```\r\n\r\n@kyrias - it looks from your logs like you're on a dev version of twisted, and you're also running the develop branch of synapse.  Given the stack trace has nothing to do with synapse in it, and is instead stuff to do with iterating over twisted endpoints, my guess is that this is related to the ipv6 stuff; either a bug in the changes to synapse for ipv6, or something weird in your dev version of twisted.\r\n\r\nCan you try against non-dev twisted?"}}
{"actor":{"display_login":"ara4n"}}