Merge ~pappacena/turnip:paginated-check-refs-permissions into turnip:master

[Thiago F. Pappacena]

Adding better error reporting and paginating the requests to check_ref_permissions on hooks, to avoid connection timeout when a user git pushes dozens of refs at once.

Ideally, when a user pushes a lot of branches at once, we should parallelize (in a thread pool executor, for example) the permissions checks in batches (instead of checking one batch after another).

But such change would require a bit more refactoring to create different sockets, so this goes in a future MP.

[Thiago F. Pappacena (pappacena)]

This branch uses mock package for python 2. So, it depends on https://code.launchpad.net/~pappacena/turnip/+git/turnip-dependencies/+merge/384592.

[Colin Watson (cjwatson)]

(Please attach bugs to your merge proposals where appropriate; it's handy to have things interlinked. The method described in https://help.launchpad.net/Code/Git#Linking_to_bugs is easiest, but you can also link bugs from the merge proposal web UI after the fact.)

I'm not convinced that this is solving the right problem here. My instinct is that checking a couple of thousand refs shouldn't cause a timeout on the appserver side. Now, my instinct could be wrong, but if so we ought to be able to find an OOPS corresponding to the timeout; but when I went hunting for Andy's problem on 2020-05-26, I could find the push attempt (which took over half an hour), but it looked as though the checkRefPermissions request never made it as far as the appserver. That suggests that the problem is a somewhat different one.

So, I had a look at how the netstring protocol is implemented between turnip.pack.hooks.hook and turnip.pack.hookrpc. I found two separate problems:

 * netstring_send calls sock.send, but it doesn't handle the case of short sends. sock.send is perfectly entitled to send fewer bytes than you asked it to send, and in that case it expects you to call it again to attempt delivery of the remaining data. This could account for the problem all by itself: we'd see the described symptoms if sock.send only sent part of the netstring and then hookrpc waited forever (or at least until a timeout somewhere) waiting to read the rest of it.

 * hookrpc uses twisted.protocols.basic.NetstringReceiver, which imposes a maximum length of 99999 on netstrings. I think we should consider either removing this limit entirely (perhaps by overriding _checkStringSize) or setting it to something a couple of orders of magnitude larger. Our netstring receiver isn't on a significant security boundary, and we've already read the full list of ref paths into memory anyway by the time we get to this point. 99999 bytes may well not be enough for the JSON encoding of 2000 ref paths.

I also spotted one problem in the implementation of GitRepository.checkRefPermissions in Launchpad: it doesn't preload grantees of GitGranteeType.PERSON, so if there are many matching rules with grants for different teams of which the user is a member, it will incur on the order of one query per relevant grantee. This is bounded above by the number of teams of which the user is a member, so it's unlikely to be a timeout-level problem in practice, but it might be worth cleaning up.

I have a strong suspicion that just fixing the two netstring-related bugs will solve the problem without needing to do any complicated pagination, and I think we should try that first. If we do need to resort to pagination, then the page size can almost certainly be very much larger: I'd start at more like 250 than 25, and I wouldn't be surprised if we could go quite a bit higher still. With larger page sizes, there'll be many fewer round trips involved, and there should be no need to resort to the considerable extra complexity of parallel checks.

review: Needs Information

[Thiago F. Pappacena (pappacena)]

Hi, cjwatson.

- I'll check both problems you've mentioned on netstring, and open separated MPs for that. I didn't spot those problems when checking, and thanks for pointing that out.

- GitRepository.checkRefPermissions would be my next step, to see query count and other common performance problems. I'll check that too.

- I was planning to adjust the page size after benchmarking a bit better. Yesterday night I've run some quick tests locally, and already realized that 25 was way too small (before your comment, I had already pushed a change to make it 100). The problem is that the reported bug was trying to push 2.000 branches.

- The pagination and parallelization was actually not that complicated. Apart from the changes on where we do the socket creation, make it run in parallel was a change of about 15 lines of code, for example. But I agree that most of our problems are probably somewhere else.

[Colin Watson (cjwatson)]

It's true that it's not a completely unreasonable amount of complexity. But if we can avoid it in favour of a couple of more surgical and relatively simple changes, then I'd like to try those first. :-)

Unmerged commits

472112b... by Thiago F. Pappacena on 2020-05-27

Fixing comment

545ac8a... by Thiago F. Pappacena on 2020-05-27

Merge branch 'paginated-check-refs-permissions' of git+ssh://git.launchpad.net/~pappacena/turnip into paginated-check-refs-permissions

cfa68f9... by Thiago F. Pappacena on 2020-05-27

Paginating check_ref_permissions RPC calls to avoid timeouts

44036eb... by Thiago F. Pappacena on 2020-05-27

Paginating check_ref_permissions RPC calls to avoid timeouts

diff --git a/requirements.txt b/requirements.txt
index a298c0a..cb86dfe 100644
--- a/requirements.txt
+++ b/requirements.txt
@@ -26,6 +26,7 @@ linecache2==1.0.0
 m2r==0.1.14
 mccabe==0.3
 mistune==0.8.3
+mock==3.0.5
 Paste==2.0.2
 PasteDeploy==2.1.0
 pbr==5.4.4
diff --git a/setup.py b/setup.py
index cd8f4fb..b5821f7 100755
--- a/setup.py
+++ b/setup.py
@@ -34,6 +34,7 @@ test_requires = [
     'docutils',
     'fixtures',
     'flake8',
+    'mock',
     'testtools',
     'webtest',
     ]
diff --git a/turnip/pack/hooks/hook.py b/turnip/pack/hooks/hook.py
index e135395..2969e21 100755
--- a/turnip/pack/hooks/hook.py
+++ b/turnip/pack/hooks/hook.py
@@ -113,14 +113,20 @@ def netstring_recv(sock):
     c = sock.recv(1)
     lengthstr = b''
     while c != b':':
-        assert c.isdigit()
+        if not c.isdigit():
+            raise ValueError(
+                "Invalid response: %s" % (six.ensure_text(c + sock.recv(256))))
         lengthstr += c
         c = sock.recv(1)
     length = int(lengthstr)
     s = bytearray()
     while len(s) < length:
         s += sock.recv(length - len(s))
-    assert sock.recv(1) == b','
+    ending = sock.recv(1)
+    if ending != b',':
+        raise ValueError(
+            "Length error for message '%s': ending='%s'" %
+            (six.ensure_text(bytes(s)), six.ensure_text(ending)))
     return bytes(s)
 
 
@@ -135,14 +141,24 @@ def rpc_invoke(sock, method, args):
     return res['result']
 
 
-def check_ref_permissions(sock, rpc_key, ref_paths):
+def split_list(lst, n):
+    """Splits the given list into chunks of size n."""
+    lst = list(lst)
+    return [lst[i:i + n] for i in range(0, len(lst), n)]
+
+
+def check_ref_permissions(sock, rpc_key, ref_paths, page_size=100):
     ref_paths = [base64.b64encode(path).decode('UTF-8') for path in ref_paths]
-    rule_lines = rpc_invoke(
-        sock, 'check_ref_permissions',
-        {'key': rpc_key, 'paths': ref_paths})
-    return {
-        base64.b64decode(path.encode('UTF-8')): permissions
-        for path, permissions in rule_lines.items()}
+    permissions = {}
+    # Paginate the rpc calls to avoid timeouts.
+    for ref_paths_chunk in split_list(ref_paths, page_size):
+        rule_lines = rpc_invoke(
+            sock, 'check_ref_permissions',
+            {'key': rpc_key, 'paths': ref_paths_chunk})
+        permissions.update({
+            base64.b64decode(path.encode('UTF-8')): permissions
+            for path, permissions in rule_lines.items()})
+    return permissions
 
 
 def send_mp_url(received_line):
diff --git a/turnip/pack/tests/test_hooks.py b/turnip/pack/tests/test_hooks.py
index 449b9f9..b383d6b 100644
--- a/turnip/pack/tests/test_hooks.py
+++ b/turnip/pack/tests/test_hooks.py
@@ -17,7 +17,12 @@ from fixtures import (
     MonkeyPatch,
     TempDir,
     )
+try:
+    from unittest import mock
+except ImportError:
+    import mock
 import pygit2
+import six
 from testtools import TestCase
 from testtools.deferredruntest import AsynchronousDeferredRunTest
 from twisted.internet import (
@@ -29,6 +34,7 @@ from twisted.internet import (
 from turnip.pack import hookrpc
 from turnip.pack.helpers import ensure_hooks
 from turnip.pack.hooks import hook
+from turnip.pack.hooks.hook import split_list, check_ref_permissions
 
 
 class HookProcessProtocol(protocol.ProcessProtocol):
@@ -108,15 +114,21 @@ class TestNetstringRecv(TestCase):
 
     def test_nondigit(self):
         sock = MockSocket([b'zzz:abc,'])
-        self.assertRaises(AssertionError, hook.netstring_recv, sock)
+        self.assertRaisesRegex(
+            ValueError, "Invalid response: zzz:abc,",
+            hook.netstring_recv, sock)
 
     def test_short(self):
         sock = MockSocket([b'4:abc,'])
-        self.assertRaises(AssertionError, hook.netstring_recv, sock)
+        self.assertRaisesRegex(
+            ValueError, "Length error for message 'abc,': ending=''",
+            hook.netstring_recv, sock)
 
     def test_unterminated(self):
         sock = MockSocket([b'4:abcd'])
-        self.assertRaises(AssertionError, hook.netstring_recv, sock)
+        self.assertRaisesRegex(
+            ValueError, "Length error for message 'abcd': ending=''",
+            hook.netstring_recv, sock)
 
     def test_split_data(self):
         sock = MockSocket([b'12:abcd', b'efgh', b'ijkl,'])
@@ -446,3 +458,38 @@ class TestDeterminePermissions(TestCase):
         output = hook.determine_permissions_outcome(
             pygit2.GIT_OID_HEX_ZERO, 'ref', {'ref': ['force_push']})
         self.assertEqual(b"You do not have permission to create ref.", output)
+
+
+class TestSplitRefPathsCalls(TestCase):
+    def test_split_list(self):
+        self.assertEqual(
+            split_list(range(10), 3), [[0, 1, 2], [3, 4, 5], [6, 7, 8], [9]])
+
+    @mock.patch('turnip.pack.hooks.hook.rpc_invoke')
+    def test_rcp_calls_are_paginated(self, rpc_invoke):
+        encode = lambda x: six.ensure_text(base64.b64encode(x))
+        rpc_invoke.side_effect = [
+            {encode(b'master'): [], encode(b'develop'): []},
+            {encode(b'head'): []}
+        ]
+        sock = mock.Mock()
+        # Call it with page size = 2
+        result = check_ref_permissions(
+            sock, "rpc-key", [b"master", b"develop", b"head"], 2)
+
+        # The final result should have been joined into.
+        self.assertEqual(
+            result, {b"master": [], b"develop": [], b"head": []})
+
+        # Check that it called correctly the rpc_invoke method.
+        self.assertEqual(rpc_invoke.call_args_list, [
+            mock.call(
+                sock, 'check_ref_permissions', {
+                    'key': 'rpc-key', 'paths': [
+                        encode(b"master"), encode(b"develop")]
+                }),
+            mock.call(
+                sock, 'check_ref_permissions', {
+                    'key': 'rpc-key', 'paths': [encode(b"head")]
+                }),
+        ])